Bug 1045525 - Convert automationutils python logging to log through mozlog.structured.;r=ahal

build/automationutils.py

@@ -31,9 +31,23 @@ __all__ = [
   'systemMemory',
   'environment',
   'dumpScreen',
-  "ShutdownLeaks"
+  "ShutdownLeaks",
+  "setAutomationLog",
   ]
 
+log = logging.getLogger()
+def resetGlobalLog():
+  while log.handlers:
+    log.removeHandler(log.handlers[0])
+  handler = logging.StreamHandler(sys.stdout)
+  log.setLevel(logging.INFO)
+  log.addHandler(handler)
+resetGlobalLog()
+
+def setAutomationLog(alt_logger):
+  global log
+  log = alt_logger
+
 # Map of debugging programs to information about them, like default arguments
 # and whether or not they are interactive.
 DEBUGGER_INFO = {
@@ -144,8 +158,6 @@ class ZipFileReader(object):
     for name in self._zipfile.namelist():
       self._extractname(name, path)
 
-log = logging.getLogger()
-
 def isURL(thing):
   """Return True if |thing| looks like a URL."""
   # We want to download URLs like http://... but not Windows paths like c:\...
@@ -500,9 +512,9 @@ def environment(xrePath, env=None, crashreporter=True, debugger=False, dmdPath=N
       llvmsym = os.path.join(xrePath, "llvm-symbolizer")
       if os.path.isfile(llvmsym):
         env["ASAN_SYMBOLIZER_PATH"] = llvmsym
-        log.info("INFO | runtests.py | ASan using symbolizer at %s", llvmsym)
+        log.info("INFO | runtests.py | ASan using symbolizer at %s" % llvmsym)
       else:
-        log.info("TEST-UNEXPECTED-FAIL | runtests.py | Failed to find ASan symbolizer at %s", llvmsym)
+        log.info("TEST-UNEXPECTED-FAIL | runtests.py | Failed to find ASan symbolizer at %s" % llvmsym)
 
       totalMemory = systemMemory()
 
@@ -535,7 +547,7 @@ def environment(xrePath, env=None, crashreporter=True, debugger=False, dmdPath=N
         env['ASAN_OPTIONS'] = ':'.join(asanOptions)
 
     except OSError,err:
-      log.info("Failed determine available memory, disabling ASan low-memory configuration: %s", err.strerror)
+      log.info("Failed determine available memory, disabling ASan low-memory configuration: %s" % err.strerror)
     except:
       log.info("Failed determine available memory, disabling ASan low-memory configuration")
     else:
@@ -571,7 +583,7 @@ def dumpScreen(utilityPath):
     returncode = subprocess.call(utility + [imgfilename])
     printstatus(returncode, utilityname)
   except OSError, err:
-    log.info("Failed to start %s for screenshot: %s",
+    log.info("Failed to start %s for screenshot: %s" %
              utility[0], err.strerror)
     return
 

testing/mochitest/runtests.py

@@ -32,7 +32,20 @@ import urllib2
 import zipfile
 import bisection
 
-from automationutils import environment, getDebuggerInfo, isURL, KeyValueParseError, parseKeyValue, processLeakLog, dumpScreen, ShutdownLeaks, printstatus, LSANLeaks
+from automationutils import (
+    environment,
+    getDebuggerInfo,
+    isURL,
+    KeyValueParseError,
+    parseKeyValue,
+    processLeakLog,
+    dumpScreen,
+    ShutdownLeaks,
+    printstatus,
+    LSANLeaks,
+    setAutomationLog,
+)
+
 from datetime import datetime
 from manifestparser import TestManifest
 from mochitest_options import MochitestOptions
@@ -40,25 +53,12 @@ from mozprofile import Profile, Preferences
 from mozprofile.permissions import ServerLocations
 from urllib import quote_plus as encodeURIComponent
 from mozlog.structured.formatters import TbplFormatter
-from mozlog.structured.commandline import add_logging_group, setup_logging
-from mozlog.structured.handlers import StreamHandler
+from mozlog.structured import commandline
 
 # This should use the `which` module already in tree, but it is
 # not yet present in the mozharness environment
 from mozrunner.utils import findInPath as which
 
-
-# Necessary to set up the global logger in automationutils.py
-import logging
-log = logging.getLogger()
-def resetGlobalLog():
-   while log.handlers:
-       log.removeHandler(log.handlers[0])
-   handler = logging.StreamHandler(sys.stdout)
-   log.setLevel(logging.INFO)
-   log.addHandler(handler)
-resetGlobalLog()
-
 ###########################
 # Option for NSPR logging #
 ###########################
@@ -75,16 +75,29 @@ NSPR_LOG_MODULES = ""
 
 ### output processing
 class MochitestFormatter(TbplFormatter):
+    """
+    The purpose of this class is to maintain compatibility with legacy users.
+    Mozharness' summary parser expects the count prefix, and others expect python
+    logging to contain a line prefix picked up by TBPL (bug 1043420).
+    Those directly logging "TEST-UNEXPECTED" require no prefix to log output
+    in order to turn a build orange (bug 1044206).
+
+    Once updates are propagated to Mozharness, this class may be removed.
+    """
     log_num = 0
 
     def __init__(self):
         super(MochitestFormatter, self).__init__()
 
     def __call__(self, data):
-        tbpl_output = super(MochitestFormatter, self).__call__(data)
+        output = super(MochitestFormatter, self).__call__(data)
         log_level = data.get('level', 'info').upper()
-        output = '%d %s %s' % (MochitestFormatter.log_num, log_level, tbpl_output)
-        MochitestFormatter.log_num += 1
+
+        if 'js_source' in data or log_level == 'ERROR':
+            data.pop('js_source', None)
+            output = '%d %s %s' % (MochitestFormatter.log_num, log_level, output)
+            MochitestFormatter.log_num += 1
+
         return output
 
 ### output processing
@@ -409,7 +422,7 @@ class MochitestUtilsMixin(object):
   TEST_PATH = "tests"
   CHROME_PATH = "redirect.html"
   urlOpts = []
-  structured_logger = None
+  log = None
 
   def __init__(self, logger_options):
     self.update_mozinfo()
@@ -417,20 +430,19 @@ class MochitestUtilsMixin(object):
     self.wsserver = None
     self.sslTunnel = None
     self._locations = None
-    # Structured logger
-    if self.structured_logger is None:
-        self.structured_logger = setup_logging('mochitest', logger_options, {})
-        # Add the tbpl logger if no handler is logging to stdout, to display formatted logs by default
-        has_stdout_logger = any(h.stream == sys.stdout for h in self.structured_logger.handlers)
-        if not has_stdout_logger:
-            handler = StreamHandler(sys.stdout, MochitestFormatter())
-            self.structured_logger.add_handler(handler)
-        MochitestUtilsMixin.structured_logger = self.structured_logger
 
-    self.message_logger = MessageLogger(logger=self.structured_logger)
+    if self.log is None:
+      commandline.log_formatters["tbpl"]  = (MochitestFormatter,
+                                             "Mochitest specific tbpl formatter")
+      self.log = commandline.setup_logging("mochitest",
+                                           logger_options,
+                                           {
+                                              "tbpl": sys.stdout
+                                           })
+      MochitestUtilsMixin.log = self.log
+      setAutomationLog(self.log)
 
-    # self.log should also be structured_logger, but to avoid regressions like bug 1044206 we're now logging with the stdlib's logger
-    self.log = log
+    self.message_logger = MessageLogger(logger=self.log)
 
   def update_mozinfo(self):
     """walk up directories to find mozinfo.json update the info"""
@@ -1206,7 +1218,7 @@ class Mochitest(MochitestUtilsMixin):
       if gmp_path is not None:
           browserEnv["MOZ_GMP_PATH"] = gmp_path
     except EnvironmentError:
-      log.error('Could not find path to gmp-fake plugin!')
+      self.log.error('Could not find path to gmp-fake plugin!')
       return None
 
     if options.fatalAssertions:
@@ -2063,7 +2075,7 @@ class Mochitest(MochitestUtilsMixin):
 def main():
   # parse command line options
   parser = MochitestOptions()
-  add_logging_group(parser)
+  commandline.add_logging_group(parser)
   options, args = parser.parse_args()
   if options is None:
     # parsing error

testing/mochitest/runtestsremote.py

@@ -606,8 +606,7 @@ def main():
     mochitest = MochiRemote(auto, dm, options)
 
     log = mochitest.log
-    structured_logger = mochitest.structured_logger
-    message_logger.logger = mochitest.structured_logger
+    message_logger.logger = log
     mochitest.message_logger = message_logger
 
     if (options == None):
@@ -706,7 +705,7 @@ def main():
 
             active_tests.append(test)
 
-        structured_logger.suite_start([t['name'] for t in active_tests])
+        log.suite_start([t['name'] for t in active_tests])
 
         for test in active_tests:
             # When running in a loop, we need to create a fresh profile for each cycle

testing/mochitest/tests/SimpleTest/TestRunner.js

@@ -243,6 +243,10 @@ function StructuredLogger(name) {
         var allData = {action: action,
                        time: new Date().getTime(),
                        thread: "",
+                       // This is a directive to python to format these messages
+                       // for compatibility with mozharness. This can be removed
+                       // with the MochitestFormatter (see bug 1045525).
+                       js_source: "TestRunner",
                        pid: null,
                        source: this.name};