diff --git a/testing/mochitest/runrobocop.py b/testing/mochitest/runrobocop.py index 6ac308fd59f7..1d555fd88d6d 100644 --- a/testing/mochitest/runrobocop.py +++ b/testing/mochitest/runrobocop.py @@ -42,7 +42,7 @@ class RobocopTestRunner(MochitestDesktop): """ Simple one-time initialization. """ - MochitestDesktop.__init__(self, options.flavor, options) + MochitestDesktop.__init__(self, options) self.auto = automation self.dm = devmgr diff --git a/testing/mochitest/runtests.py b/testing/mochitest/runtests.py index 53118353b40e..be875ab056ce 100644 --- a/testing/mochitest/runtests.py +++ b/testing/mochitest/runtests.py @@ -155,10 +155,8 @@ class MessageLogger(object): 'chrome://mochitests/content/browser/', 'chrome://mochitests/content/chrome/'] - def __init__(self, logger, buffering=True, structured=True): + def __init__(self, logger, buffering=True): self.logger = logger - self.structured = structured - self.gecko_id = 'GECKO' # Even if buffering is enabled, we only want to buffer messages between # TEST-START/TEST-END. So it is off to begin, but will be enabled after @@ -172,12 +170,11 @@ class MessageLogger(object): # Failures reporting, after the end of the tests execution self.errors = [] - def validate(self, obj): - """Tests whether the given object is a valid structured message + def valid_message(self, obj): + """True if the given object is a valid structured message (only does a superficial validation)""" - if not (isinstance(obj, dict) and 'action' in obj and obj[ - 'action'] in MessageLogger.VALID_ACTIONS): - raise ValueError + return isinstance(obj, dict) and 'action' in obj and obj[ + 'action'] in MessageLogger.VALID_ACTIONS def _fix_test_name(self, message): """Normalize a logged test path to match the relative path from the sourcedir. @@ -207,21 +204,18 @@ class MessageLogger(object): continue try: message = json.loads(fragment) - self.validate(message) - except ValueError: - if self.structured: - message = dict( - action='process_output', - process=self.gecko_id, - data=fragment, - ) - else: + if not self.valid_message(message): message = dict( action='log', level='info', message=fragment, - ) - + unstructured=True) + except ValueError: + message = dict( + action='log', + level='info', + message=fragment, + unstructured=True) self._fix_test_name(message) self._fix_message_format(message) messages.append(message) @@ -238,6 +232,11 @@ class MessageLogger(object): self.buffering = False return + unstructured = False + if 'unstructured' in message: + unstructured = True + message.pop('unstructured') + # Error detection also supports "raw" errors (in log messages) because some tests # manually dump 'TEST-UNEXPECTED-FAIL'. if ('expected' in message or (message['action'] == 'log' and message[ @@ -259,12 +258,15 @@ class MessageLogger(object): # Logging the error message self.logger.log_raw(message) - # Determine if message should be buffered - elif self.buffering and self.structured and message['action'] in self.BUFFERED_ACTIONS: - self.buffered_messages.append(message) - # Otherwise log the message directly - else: + # If we don't do any buffering, or the tests haven't started, or the message was + # unstructured, it is directly logged. + elif any([not self.buffering, + unstructured, + message['action'] not in self.BUFFERED_ACTIONS]): self.logger.log_raw(message) + else: + # Buffering the message + self.buffered_messages.append(message) # If a test ended, we clean the buffer if message['action'] == 'test_end': @@ -791,9 +793,8 @@ class MochitestDesktop(object): # TODO: replace this with 'runtests.py' or 'mochitest' or the like test_name = 'automation.py' - def __init__(self, flavor, logger_options, quiet=False): + def __init__(self, logger_options, quiet=False): self.update_mozinfo() - self.flavor = flavor self.server = None self.wsserver = None self.websocketProcessBridge = None @@ -819,12 +820,7 @@ class MochitestDesktop(object): }) MochitestDesktop.log = self.log - # Jetpack flavors still don't use the structured logger. We need to process their output - # slightly differently. - structured = not self.flavor.startswith('jetpack') - self.message_logger = MessageLogger( - logger=self.log, buffering=quiet, structured=structured) - + self.message_logger = MessageLogger(logger=self.log, buffering=quiet) # Max time in seconds to wait for server startup before tests will fail -- if # this seems big, it's mostly for debug machines where cold startup # (particularly after a build) takes forever. @@ -2081,10 +2077,7 @@ toolbar#nav-bar { outputTimeout=timeout) proc = runner.process_handler self.log.info("runtests.py | Application pid: %d" % proc.pid) - - gecko_id = "GECKO(%d)" % proc.pid - self.log.process_start(gecko_id) - self.message_logger.gecko_id = gecko_id + self.log.process_start("Main app process") # start marionette and kick off the tests marionette_args = marionette_args or {} @@ -2750,7 +2743,7 @@ def run_test_harness(parser, options): key: value for key, value in vars(options).iteritems() if key.startswith('log') or key == 'valgrind'} - runner = MochitestDesktop(options.flavor, logger_options, quiet=options.quiet) + runner = MochitestDesktop(logger_options, quiet=options.quiet) options.runByDir = False diff --git a/testing/mochitest/runtestsremote.py b/testing/mochitest/runtestsremote.py index 72e65e4eebb8..51ed683f72d9 100644 --- a/testing/mochitest/runtestsremote.py +++ b/testing/mochitest/runtestsremote.py @@ -29,7 +29,7 @@ class MochiRemote(MochitestDesktop): logMessages = [] def __init__(self, automation, devmgr, options): - MochitestDesktop.__init__(self, options.flavor, options) + MochitestDesktop.__init__(self, options) self._automation = automation self._dm = devmgr diff --git a/testing/mozbase/mozlog/mozlog/formatters/machformatter.py b/testing/mozbase/mozlog/mozlog/formatters/machformatter.py index 0988eb92f313..e7e1cafdcea6 100644 --- a/testing/mozbase/mozlog/mozlog/formatters/machformatter.py +++ b/testing/mozbase/mozlog/mozlog/formatters/machformatter.py @@ -322,15 +322,11 @@ class MachFormatter(base.BaseFormatter): def process_output(self, data): rv = [] - pid = data['process'] - if pid.isdigit(): - pid = 'pid:%s' % pid - if "command" in data and data["process"] not in self._known_pids: self._known_pids.add(data["process"]) - rv.append('(%s) Full command: %s' % (pid, data["command"])) + rv.append('(pid:%s) Full command: %s' % (data["process"], data["command"])) - rv.append('(%s) "%s"' % (pid, data["data"])) + rv.append('(pid:%s) "%s"' % (data["process"], data["data"])) return "\n".join(rv) def crash(self, data): diff --git a/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py b/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py index 4bebb647bc6a..ada8fd494d6e 100644 --- a/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py +++ b/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py @@ -72,10 +72,7 @@ class TbplFormatter(BaseFormatter): @output_subtests def process_output(self, data): - pid = data['process'] - if pid.isdigit(): - pid = 'PID %s' % pid - return "%s | %s\n" % (pid, data['data']) + return "PROCESS | %(process)s | %(data)s\n" % data @output_subtests def process_start(self, data): diff --git a/testing/mozharness/mozharness/mozilla/structuredlog.py b/testing/mozharness/mozharness/mozilla/structuredlog.py index ec4865c765b4..d87c5ebdc361 100644 --- a/testing/mozharness/mozharness/mozilla/structuredlog.py +++ b/testing/mozharness/mozharness/mozilla/structuredlog.py @@ -47,10 +47,15 @@ class StructuredOutputParser(OutputParser): "from the MozbaseMixin to ensure that mozlog is available.") return mozlog - def _handle_unstructured_output(self, line, log_output=True): - self.log_output = log_output + def _handle_unstructured_output(self, line): + if self.strict: + self.critical(("Test harness output was not a valid structured log message: " + "\n%s") % line) + self.update_levels(TBPL_FAILURE, log.CRITICAL) + return super(StructuredOutputParser, self).parse_single_line(line) + def parse_single_line(self, line): """Parses a line of log output from the child process and passes it to mozlog to update the overall status of the run. @@ -69,22 +74,12 @@ class StructuredOutputParser(OutputParser): pass if data is None: - if self.strict: - self.critical(("Test harness output was not a valid structured log message: " - "\n%s") % line) - self.update_levels(TBPL_FAILURE, log.CRITICAL) - else: - self._handle_unstructured_output(line) + self._handle_unstructured_output(line) return self.handler(data) action = data["action"] - if action == "process_output": - # Run process output through the error lists, but make sure the super parser - # doesn't print them to stdout (they should go through the log formatter). - self._handle_unstructured_output(data['data'], log_output=False) - if action == "log": level = getattr(log, data["level"].upper())