From patchwork Tue Feb 7 20:43:10 2012 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Zygmunt Krynicki X-Patchwork-Id: 6689 Return-Path: X-Original-To: patchwork@peony.canonical.com Delivered-To: patchwork@peony.canonical.com Received: from fiordland.canonical.com (fiordland.canonical.com [91.189.94.145]) by peony.canonical.com (Postfix) with ESMTP id 390B323E01 for ; Tue, 7 Feb 2012 20:43:14 +0000 (UTC) Received: from mail-iy0-f180.google.com (mail-iy0-f180.google.com [209.85.210.180]) by fiordland.canonical.com (Postfix) with ESMTP id D3B58A1877B for ; Tue, 7 Feb 2012 20:43:13 +0000 (UTC) Received: by iabz7 with SMTP id z7so14314116iab.11 for ; Tue, 07 Feb 2012 12:43:13 -0800 (PST) Received: by 10.50.156.133 with SMTP id we5mr16600515igb.12.1328647393315; Tue, 07 Feb 2012 12:43:13 -0800 (PST) X-Forwarded-To: linaro-patchwork@canonical.com X-Forwarded-For: patch@linaro.org linaro-patchwork@canonical.com Delivered-To: patches@linaro.org Received: by 10.231.169.210 with SMTP id a18cs136127ibz; Tue, 7 Feb 2012 12:43:12 -0800 (PST) Received: by 10.180.97.196 with SMTP id ec4mr35444813wib.11.1328647391419; Tue, 07 Feb 2012 12:43:11 -0800 (PST) Received: from indium.canonical.com (indium.canonical.com. [91.189.90.7]) by mx.google.com with ESMTPS id y19si14047465weq.139.2012.02.07.12.43.10 (version=TLSv1/SSLv3 cipher=OTHER); Tue, 07 Feb 2012 12:43:11 -0800 (PST) Received-SPF: pass (google.com: best guess record for domain of bounces@canonical.com designates 91.189.90.7 as permitted sender) client-ip=91.189.90.7; Authentication-Results: mx.google.com; spf=pass (google.com: best guess record for domain of bounces@canonical.com designates 91.189.90.7 as permitted sender) smtp.mail=bounces@canonical.com Received: from ackee.canonical.com ([91.189.89.26]) by indium.canonical.com with esmtp (Exim 4.71 #1 (Debian)) id 1Rursc-0006iU-Lj for ; Tue, 07 Feb 2012 20:43:10 +0000 Received: from ackee.canonical.com (localhost [127.0.0.1]) by ackee.canonical.com (Postfix) with ESMTP id 96ECDE0028 for ; Tue, 7 Feb 2012 20:43:10 +0000 (UTC) MIME-Version: 1.0 X-Launchpad-Project: lava-dispatcher X-Launchpad-Branch: ~linaro-validation/lava-dispatcher/trunk X-Launchpad-Message-Rationale: Subscriber X-Launchpad-Branch-Revision-Number: 221 X-Launchpad-Notification-Type: branch-revision To: Linaro Patch Tracker From: noreply@launchpad.net Subject: [Branch ~linaro-validation/lava-dispatcher/trunk] Rev 221: Improve dispatcher logging (fixes 921527) Message-Id: <20120207204310.2987.69803.launchpad@ackee.canonical.com> Date: Tue, 07 Feb 2012 20:43:10 -0000 Reply-To: noreply@launchpad.net Sender: bounces@canonical.com Errors-To: bounces@canonical.com Precedence: bulk X-Generated-By: Launchpad (canonical.com); Revision="14747"; Instance="launchpad-lazr.conf" X-Launchpad-Hash: eb953cd7047cabc196c161dd6560b76ee3d4cd21 X-Gm-Message-State: ALoCoQm1qIr/C6zpNub0uTU4qEpFNW/dpHXCBZv4Lt/pipJc2JFK2xx8BMlYsBQyJsurSAT7NIJ1 Merge authors: Le Chi Thu le.chi.thu@linaro.org Related merge proposals: https://code.launchpad.net/~le-chi-thu/lava-dispatcher/improve-logging-2/+merge/90253 proposed by: Le Chi Thu (le-chi-thu) review: Resubmit - Le Chi Thu (le-chi-thu) review: Approve - Yongqin Liu (liuyq0307) https://code.launchpad.net/~le-chi-thu/lava-dispatcher/improve-logging/+merge/76548 proposed by: Le Chi Thu (le-chi-thu) review: Approve - Paul Larson (pwlars) ------------------------------------------------------------ revno: 221 [merge] committer: Zygmunt Krynicki branch nick: trunk timestamp: Tue 2012-02-07 21:30:14 +0100 message: Improve dispatcher logging (fixes 921527) modified: lava_dispatcher/actions/boot_control.py lava_dispatcher/actions/launch_control.py lava_dispatcher/client/base.py lava_dispatcher/client/master.py lava_dispatcher/connection.py lava_dispatcher/job.py lava_dispatcher/utils.py --- lp:lava-dispatcher https://code.launchpad.net/~linaro-validation/lava-dispatcher/trunk You are subscribed to branch lp:lava-dispatcher. To unsubscribe from this branch go to https://code.launchpad.net/~linaro-validation/lava-dispatcher/trunk/+edit-subscription === modified file 'lava_dispatcher/actions/boot_control.py' --- lava_dispatcher/actions/boot_control.py 2011-11-24 03:00:54 +0000 +++ lava_dispatcher/actions/boot_control.py 2012-01-26 10:20:09 +0000 @@ -43,7 +43,6 @@ client = self.client status = 'pass' try: - logging.info("Boot Linaro image") client.boot_linaro_image() except: logging.exception("boot_linaro_image failed") @@ -58,5 +57,4 @@ """ def run(self): client = self.client - logging.info("Boot master image") client.boot_master_image() === modified file 'lava_dispatcher/actions/launch_control.py' --- lava_dispatcher/actions/launch_control.py 2012-02-02 01:56:11 +0000 +++ lava_dispatcher/actions/launch_control.py 2012-02-07 19:16:17 +0000 @@ -62,8 +62,9 @@ json_bundle = json.dumps(main_bundle) job_name = self.context.job_data.get('job_name', "LAVA Results") try: - print >> self.context.oob_file, 'dashboard-put-result:', \ - dashboard.put_ex(json_bundle, job_name, stream) + result = dashboard.put_ex(json_bundle, job_name, stream) + print >> self.context.oob_file, 'dashboard-put-result:', result + logging.info("Dashboard : %s" %result) except xmlrpclib.Fault, err: logging.warning("xmlrpclib.Fault occurred") logging.warning("Fault code: %d" % err.faultCode) @@ -176,6 +177,6 @@ logging.warn("The url seems not RPC2 or xml-rpc endpoints, please make sure it's a valid one!!!") dashboard = srv.dashboard - logging.info("server RPC endpoint URL: %s" % server) + logging.debug("server RPC endpoint URL: %s" % server) return dashboard === modified file 'lava_dispatcher/client/base.py' --- lava_dispatcher/client/base.py 2012-02-07 18:42:14 +0000 +++ lava_dispatcher/client/base.py 2012-02-07 20:30:14 +0000 @@ -374,7 +374,6 @@ timeout=timeout) if match_id == 1: raise OperationFailed - logging.info("System is in test image now") def deploy_linaro(self, hwpack, rootfs, kernel_matrix=None, use_cache=True, rootfstype='ext3'): raise NotImplementedError(self.deploy_linaro) @@ -386,6 +385,8 @@ """ Reboot the system to the test image """ + logging.info("Boot the test image") + self.proc._boot(self.boot_cmds) self.in_test_shell(300) # set PS1 to include return value of last command @@ -395,6 +396,8 @@ self.proc.sendline('export PS1="$PS1 [rc=$(echo \$?)]: "') self.proc.expect(self.tester_str, timeout=10) + logging.info("System is in test image now") + def get_seriallog(self): return self.sio.getvalue() === modified file 'lava_dispatcher/client/master.py' --- lava_dispatcher/client/master.py 2012-01-27 03:23:09 +0000 +++ lava_dispatcher/client/master.py 2012-02-07 19:16:17 +0000 @@ -121,7 +121,7 @@ session.run('umount /mnt/lava/boot') def _recreate_uInitrd(session): - logging.info("Recreate uInitrd") + logging.debug("Recreate uInitrd") # Original android sdcard partition layout by l-a-m-c sys_part_org = session._client.device_option("sys_part_android_org") cache_part_org = session._client.device_option("cache_part_android_org") @@ -245,9 +245,8 @@ self.run( cmd, [pattern1, pexpect.EOF, pexpect.TIMEOUT], timeout=5) if self.match_id == 0: - logging.info("\nmatching pattern is %s" % self.match_id) ip = self.match.group(1) - logging.info("Master IP is %s" % ip) + logging.debug("Master image IP is %s" % ip) return ip return None @@ -269,9 +268,11 @@ boot_tgz, root_tgz = self._generate_tarballs( hwpack, rootfs, kernel_matrix, use_cache) except: + logging.error("Deployment tarballs preparation failed") tb = traceback.format_exc() self.sio.write(tb) raise CriticalError("Deployment tarballs preparation failed") + logging.info("Booting master image") try: self.boot_master_image() @@ -288,6 +289,7 @@ try: session.wait_network_up() except: + logging.error("Unable to reach LAVA server, check network") tb = traceback.format_exc() self.sio.write(tb) raise CriticalError("Unable to reach LAVA server, check network") @@ -296,6 +298,7 @@ _deploy_linaro_rootfs(session, root_url) _deploy_linaro_bootfs(session, boot_url) except: + logging.error("Deployment failed") tb = traceback.format_exc() self.sio.write(tb) raise CriticalError("Deployment failed") @@ -317,6 +320,7 @@ try: session.wait_network_up() except: + logging.error("Unable to reach LAVA server, check network") tb = traceback.format_exc() self.sio.write(tb) raise CriticalError("Unable to reach LAVA server, check network") @@ -325,6 +329,7 @@ boot_tbz2, system_tbz2, data_tbz2, pkg_tbz2 = \ self._download_tarballs(boot, system, data, pkg, use_cache) except: + logging.error("Unable to download artifacts for deployment") tb = traceback.format_exc() self.sio.write(tb) raise CriticalError("Unable to download artifacts for deployment") @@ -353,6 +358,7 @@ # _purge_linaro_android_sdcard(session) _deploy_linaro_android_data(session, data_url) except: + logging.error("Android deployment failed") tb = traceback.format_exc() self.sio.write(tb) raise CriticalError("Android deployment failed") @@ -400,6 +406,7 @@ """ reboot the system, and check that we are in a master shell """ + logging.info("Boot the system master image") self.proc.soft_reboot() try: self.proc.expect("Starting kernel") @@ -410,6 +417,7 @@ self._in_master_shell(300) self.proc.sendline('export PS1="$PS1 [rc=$(echo \$?)]: "') self.proc.expect(self.master_str, timeout=10, lava_no_logging=1) + logging.info("System is in master image now") def _format_testpartition(self, session, fstype): logging.info("Format testboot and testrootfs partitions") @@ -434,6 +442,7 @@ _extract_partition(image_file, self.boot_part, boot_tgz) _extract_partition(image_file, self.root_part, root_tgz) except: + logging.error("Failed to generate tarballs") shutil.rmtree(tarball_dir) tb = traceback.format_exc() self.sio.write(tb) @@ -553,8 +562,7 @@ [self.master_str, pexpect.TIMEOUT], timeout=timeout, lava_no_logging=1) if match_id == 1: raise OperationFailed - logging.info("System is in master image now") - + @contextlib.contextmanager def _master_session(self): """A session that can be used to run commands in the master image. === modified file 'lava_dispatcher/connection.py' --- lava_dispatcher/connection.py 2012-01-12 23:08:03 +0000 +++ lava_dispatcher/connection.py 2012-01-26 10:20:09 +0000 @@ -82,13 +82,13 @@ self.sendline("") def soft_reboot(self): + logging.info("Perform soft reboot the system") cmd = self.device_option("soft_boot_cmd") if cmd != "": self.sendline(cmd) else: self.sendline("reboot") # set soft reboot timeout 120s, or do a hard reset - logging.info("Rebooting the system") id = self.expect( ['Restarting system.', 'The system is going down for reboot NOW', 'Will now restart', pexpect.TIMEOUT], timeout=120) === modified file 'lava_dispatcher/job.py' --- lava_dispatcher/job.py 2012-02-02 11:01:31 +0000 +++ lava_dispatcher/job.py 2012-02-07 19:16:17 +0000 @@ -67,6 +67,9 @@ 'type': 'integer', 'optional': False, }, + 'logging_level': { + 'optional': True, + }, }, } @@ -85,6 +88,13 @@ return self.job_data['target'] @property + def logging_level(self): + try: + return self.job_data['logging_level'] + except : + return None + + @property def image_type(self): return self.job_data.get('image_type') @@ -101,6 +111,7 @@ def run(self): self.validate() + self._set_logging_level() lava_commands = get_all_cmds() if self.job_data['actions'][-1]['command'].startswith("submit_results"): @@ -119,6 +130,7 @@ try: for cmd in self.job_data['actions']: params = cmd.get('parameters', {}) + logging.info("[ACTION-B] Command %s is started with parameters %s." % (cmd['command'],params)) metadata = cmd.get('metadata', {}) self.context.test_data.add_metadata(metadata) action = lava_commands[cmd['command']](self.context) @@ -135,8 +147,8 @@ status = 'pass' finally: err_msg = "" - logging.info("Action %s finished." % cmd['command']) if status == 'fail': + logging.warning("[ACTION-E] %s is finished with error (%s)." %(cmd['command'], err)) err_msg = "Lava failed at action %s with error: %s\n" %\ (cmd['command'], unicode(str(err), 'ascii', 'replace')) if cmd['command'] == 'lava_test_run': @@ -146,6 +158,7 @@ # output to both serial log and logfile self.context.client.sio.write(err_msg) else: + logging.info("[ACTION-E] %s is finished successfully." %cmd['command']) err_msg = "" self.context.test_data.add_result( action.test_name(**params), status, err_msg) @@ -159,3 +172,21 @@ action = lava_commands[submit_results['command']]( self.context) action.run(**params) + + def _set_logging_level(self): + # set logging level is optional + level = self.logging_level + # CRITICAL, ERROR, WARNING, INFO or DEBUG + if level: + if level == 'DEBUG': + logging.root.setLevel(logging.DEBUG) + elif level == 'INFO': + logging.root.setLevel(logging.INFO) + elif level == 'WARNING': + logging.root.setLevel(logging.WARNING) + elif level == 'ERROR': + logging.root.setLevel(logging.ERROR) + elif level == 'CRITICAL': + logging.root.setLevel(logging.CRITICAL) + else: + logging.warning("Unknown logging level in the job '%s'. Allow level are : CRITICAL, ERROR, WARNING, INFO or DEBUG" %level) === modified file 'lava_dispatcher/utils.py' --- lava_dispatcher/utils.py 2012-01-26 10:11:27 +0000 +++ lava_dispatcher/utils.py 2012-02-07 19:16:17 +0000 @@ -55,9 +55,9 @@ if err.errno == errno.EXDEV: shutil.copy(cache_loc, file_location) if err.errno == errno.EEXIST: - logging.info("Cached copy of %s already exists" % url) + logging.debug("Cached copy of %s already exists" % url) else: - logging.exception("os.link failed") + logging.exception("os.link '%s' with '%s' failed"%(cache_loc,file_location)) else: file_location = download(url, path) try: @@ -70,7 +70,7 @@ if err.errno == errno.EXDEV: shutil.copy(file_location, cache_loc) if err.errno == errno.EEXIST: - logging.info("Cached copy of %s already exists" % url) + logging.debug("Cached copy of %s already exists" % url) else: logging.exception("os.link failed") return file_location @@ -90,6 +90,6 @@ return map(strip_newlines, list(splitter)) def logging_system(cmd): - logging.info('executing %r'%cmd) + logging.debug("Executing on host : '%r'"%cmd) return os.system(cmd)