Merge lp:~le-chi-thu/lava-dispatcher/improve-logging-2 into lp:lava-dispatcher

[Le Chi Thu]

make it easier to follow the flow and outcome of actions

[Yongqin Liu (liuyq0307)]

the logging level has been set in lava-dispatcher/lava-dispatch with the default value specified in lava-dispatcher.conf.
is it necessary that we change that to use the value specified in job file, and delete the _set_logging_level method?

review: Approve

[Zygmunt Krynicki (zyga)]

Hi ChiThu

59 - rc = session.run('lava-test help', response="list-test", timeout=60)
60 + rc = session.run('lava-test -h', response="list-test", timeout=60)

I understand this is not related to logging

294 + def _set_logging_level(self):
295 + # set logging level is optional
296 + try:
297 + logging.root.setLevel(self.logging_level)
298 + except :
299 + pass

I understand the intent was to ignore missing entries in the job file (and in that case accessing self.logging_level would raise KeyError). I think this is somewhat confusing and I'd suggest wrapping that inside the def logging_level(self) property method. To users of this class this should be a normal property, not something that may raise an unexpected KeyError. In addition, I think we should validate the values of logging level that are passed. Instead of using raw integers that few users will understand (is 0 more verbose than 100?) I would just use the standard set of logging.XXX names {DEBUG, INFO, WARNING, ERROR, CRITICAL}.

I can show you how to make code like that elegant and how to validate the input quickly.

[Le Chi Thu (le-chi-thu)]

wait merging util I have updated according to the discussion below.

<zyga> ChiThu: so for that isuse: I was suggesting to use foo.set_logging_level("info") instead of 0 or 100 or whatever in between
<zyga> ChiThu: you can convert a string to an integer (for logging) using...
<zyga> ChiThu: try logging.getLevelName("INFO")
<zyga> ChiThu: then I was hoping that we actually validate the dispatcher job file
<zyga> ChiThu: a simple schema could check if the log level is in the valid set ("INFO", "DEBUG", etc)
<zyga> ChiThu: for doing that I could point you to json-schema-validator documentation
<zyga> ChiThu: and to json-document documentation (for better tutorial-like approach)
* antipov (~antipov@gateway/tor-sasl/antipov) has joined #linaro
<plars> zyga, ChiThu: Adding a schema for the dispatcher would also go a long way toward documenting the dispatcher
<ChiThu> zyga, yes, good idea about schema for dispatcher

[Paul Larson (pwlars)]

I don't think adding a schema and validator should be part of this merge, though I do thing we should do it. I'll add a blueprint for it as I think it would improve reliability and documentation in the dispatcher. Is that something you'd like to work on ChiThu?

[Le Chi Thu (le-chi-thu)]

I can update the log_level to string and let the let schema and validator feature be in an other patch.

[Paul Larson (pwlars)]

You may want to take a look at logging._checklevel, should simplify this so that it can take either a string, or numerical argument

[lp:~le-chi-thu/lava-dispatcher/improve-logging-2]

206. By Le Chi Thu <email address hidden> <email address hidden> on 2012-02-07

Use string as logging level

207. By Le Chi Thu <email address hidden> <email address hidden> on 2012-02-07

Synched with trunk

[Le Chi Thu (le-chi-thu)]

Updated according to the comments.
* Use string as logging level.
* Removed not logging related changes
* Sync with trunk

review: Needs Resubmitting

[Zygmunt Krynicki (zyga)]

ChiThu: resubmit == submit another proposal I think

=== 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-02-07 19:21:18 +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:21:18 +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 19:21:18 +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:21:18 +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-02-07 19:21:18 +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:21:18 +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:21:18 +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)