commit 1724f9573c8b4bd7eebb587bdd39f30cda70c58a
author Dan Shi <dshi@google.com> Thu May 26 09:45:43 2016 -0700
committer chrome-bot <chrome-bot@chromium.org> Sat May 28 02:11:12 2016 -0700
tree 7241f61b262a22d00706b4aa6f6a2b1f5b830fb9
parent 023aae3b8fa2fc477b96a168d054d549e62fe0b3

Change logging formatter to include thread name in testbed provision.

When provisioning duts connected to testbed, change logging formatter to include
thread name. This is to help logs from each provision runs have the dut's
serial, which is set as the thread name.

BUG=b:28848023
TEST=local run, sample log:
dshi1.mtv/results/1046-debug_user/100.96.51.111/debug/autoserv.DEBUG

Change-Id: I02c9641951ef0b7db336466cc97fac72a7f68365
Reviewed-on: https://chromium-review.googlesource.com/347511
Commit-Ready: Dan Shi <dshi@google.com>
Tested-by: Dan Shi <dshi@google.com>
Reviewed-by: Kevin Cheng <kevcheng@chromium.org>

client/common_lib/logging_config.py

diff --git a/client/common_lib/logging_config.py b/client/common_lib/logging_config.py
index afbae57..711587e 100644
--- a/client/common_lib/logging_config.py
+++ b/client/common_lib/logging_config.py
@@ -48,9 +48,12 @@
 
     FILE_FORMAT = ('%(asctime)s.%(msecs)03d %(levelname)-5.5s|%(module)18.18s:'
                    '%(lineno)4.4d| %(message)s')
+    FILE_FORMAT_WITH_THREADNAME = (
+            '%(asctime)s.%(msecs)03d %(levelname)-5.5s|%(module)18.18s:'
+            '%(lineno)4.4d| %(threadName)10.10s| %(message)s')
+    DATE_FORMAT = '%m/%d %H:%M:%S'
 
-    file_formatter = logging.Formatter(fmt=FILE_FORMAT,
-                                       datefmt='%m/%d %H:%M:%S')
+    file_formatter = logging.Formatter(fmt=FILE_FORMAT, datefmt=DATE_FORMAT)
 
     CONSOLE_FORMAT = '%(asctime)s %(levelname)-5.5s| %(message)s'
 
@@ -156,3 +159,19 @@
 
     def configure_logging(self, **kwargs):
         pass
+
+
+def add_threadname_in_log():
+    """Change logging formatter to include thread name.
+
+    This is to help logs from each thread runs to include its thread name.
+    """
+    log = logging.getLogger()
+    for handler in logging.getLogger().handlers:
+        if isinstance(handler, logging.FileHandler):
+            log.removeHandler(handler)
+            handler.setFormatter(logging.Formatter(
+                    LoggingConfig.FILE_FORMAT_WITH_THREADNAME,
+                    LoggingConfig.DATE_FORMAT))
+            log.addHandler(handler)
+    logging.debug('Logging handler\'s format updated with thread name.')

server/hosts/testbed.py

diff --git a/server/hosts/testbed.py b/server/hosts/testbed.py
index 6c7db57..59e8f40 100644
--- a/server/hosts/testbed.py
+++ b/server/hosts/testbed.py
@@ -6,11 +6,13 @@
 
 import logging
 import re
+import threading
 from multiprocessing import pool
 
 import common
 
 from autotest_lib.client.common_lib import error
+from autotest_lib.client.common_lib import logging_config
 from autotest_lib.server.cros.dynamic_suite import constants
 from autotest_lib.server.cros.dynamic_suite import frontend_wrappers
 from autotest_lib.server import autoserv_parser
@@ -191,6 +193,9 @@
         host = inputs['host']
         build_url = inputs['build_url']
 
+        # Set the thread name with the serial so logging for installing
+        # different devices can have different thread name.
+        threading.current_thread().name = host.adb_serial
         logging.info('Starting installing device %s:%s from build url %s',
                      host.hostname, host.adb_serial, build_url)
         host.machine_install(build_url=build_url)
@@ -281,6 +286,11 @@
         images = self._parse_image(self._parser.options.image)
         host_attributes = {}
 
+        # Change logging formatter to include thread name. This is to help logs
+        # from each provision runs have the dut's serial, which is set as the
+        # thread name.
+        logging_config.add_threadname_in_log()
+
         arguments = []
         for serial, build in self.locate_devices(images).iteritems():
             logging.info('Installing build %s on DUT with serial %s.', build,