From 4e55351ae1a62e05a4f0d5ddb5b498283f6233a3 Mon Sep 17 00:00:00 2001 From: Chris Manchester Date: Fri, 29 Aug 2014 10:37:17 -0400 Subject: [PATCH] Bug 1045525 - Convert automationutils python logging to log through mozlog.structured.;r=ahal --- build/automationutils.py | 26 +++++-- testing/mochitest/runtests.py | 78 +++++++++++-------- testing/mochitest/runtestsremote.py | 5 +- .../mochitest/tests/SimpleTest/TestRunner.js | 4 + 4 files changed, 70 insertions(+), 43 deletions(-) diff --git a/build/automationutils.py b/build/automationutils.py index a00d141335f..4228c2e3dd3 100644 --- a/build/automationutils.py +++ b/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 diff --git a/testing/mochitest/runtests.py b/testing/mochitest/runtests.py index aa854676157..0f7e83e5a1c 100644 --- a/testing/mochitest/runtests.py +++ b/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 diff --git a/testing/mochitest/runtestsremote.py b/testing/mochitest/runtestsremote.py index 3c431971444..1bcbcd75ae2 100644 --- a/testing/mochitest/runtestsremote.py +++ b/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 diff --git a/testing/mochitest/tests/SimpleTest/TestRunner.js b/testing/mochitest/tests/SimpleTest/TestRunner.js index 2064eef31d2..3bb580cdfe0 100644 --- a/testing/mochitest/tests/SimpleTest/TestRunner.js +++ b/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};