Bug 1367745 - Make sure 'process_output' messages are logged at the proper mozharness level, r?jgraham draft
authorAndrew Halberstadt <ahalberstadt@mozilla.com>
Tue, 23 May 2017 09:05:57 -0400
changeset 585331 0fd6c88ec7d2b783a236bc3003d5de47f63bbec9
parent 585328 bce03a8eac301bcd9408b22333b1a67c3eaed057
child 630708 77fd9b1bc59ae954ccd93d6fbd3bad9315b50f1e
push id61095
push userahalberstadt@mozilla.com
push dateFri, 26 May 2017 20:22:42 +0000
reviewersjgraham
bugs1367745
milestone55.0a1
Bug 1367745 - Make sure 'process_output' messages are logged at the proper mozharness level, r?jgraham In addition to saving the log level of 'process_output' messages, this will also start passing 'log' messages through the error lists. This means mozharness will start using 'log' errors when determining the tbpl_status and worst_log_level. MozReview-Commit-ID: CZnH6aI1Wo0
testing/mozharness/mozharness/base/log.py
testing/mozharness/mozharness/mozilla/structuredlog.py
--- a/testing/mozharness/mozharness/base/log.py
+++ b/testing/mozharness/mozharness/base/log.py
@@ -291,16 +291,20 @@ class OutputParser(LogMixin):
         self.worst_log_level = INFO
 
     def parse_single_line(self, line):
         """ parse a console output line and check if it matches one in `error_list`,
         if so then log it according to `log_output`.
 
         Args:
             line (str): command line output to parse.
+
+        Returns:
+            If the line hits a match in the error_list, the new log level the line was
+            (or should be) logged at is returned. Otherwise, returns None.
         """
         for error_check in self.error_list:
             # TODO buffer for context_lines.
             match = False
             if 'substr' in error_check:
                 if error_check['substr'] in line:
                     match = True
             elif 'regex' in error_check:
@@ -320,20 +324,20 @@ class OutputParser(LogMixin):
                     else:
                         self.log(message, level=log_level)
                 if log_level in (ERROR, CRITICAL, FATAL):
                     self.num_errors += 1
                 if log_level == WARNING:
                     self.num_warnings += 1
                 self.worst_log_level = self.worst_level(log_level,
                                                         self.worst_log_level)
-                break
-        else:
-            if self.log_output:
-                self.info(' %s' % line)
+                return log_level
+
+        if self.log_output:
+            self.info(' %s' % line)
 
     def add_lines(self, output):
         """ process a string or list of strings, decode them to utf-8,strip
         them of any trailing whitespaces and parse them using `parse_single_line`
 
         strings consisting only of whitespaces are ignored.
 
         Args:
--- a/testing/mozharness/mozharness/mozilla/structuredlog.py
+++ b/testing/mozharness/mozharness/mozilla/structuredlog.py
@@ -44,17 +44,17 @@ class StructuredOutputParser(OutputParse
             import mozlog
         except ImportError:
             self.fatal("A script class using structured logging must inherit "
                        "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
-        super(StructuredOutputParser, self).parse_single_line(line)
+        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.
         Re-emits the logged line in human-readable format.
         """
         level = INFO
         tbpl_level = TBPL_SUCCESS
@@ -75,23 +75,29 @@ class StructuredOutputParser(OutputParse
                 self.update_levels(TBPL_FAILURE, log.CRITICAL)
             else:
                 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 in ('log', 'process_output'):
+            if action == 'log':
+                message = data['message']
+                level = getattr(log, data['level'].upper())
+            else:
+                message = data['data']
 
-        if action == "log":
-            level = getattr(log, data["level"].upper())
+            # Run log and process_output actions through the error lists, but make sure
+            # the super parser doesn't print them to stdout (they should go through the
+            # log formatter).
+            error_level = self._handle_unstructured_output(message, log_output=False)
+            if error_level is not None:
+                level = self.worst_level(error_level, level)
 
         log_data = self.formatter(data)
         if log_data is not None:
             self.log(log_data, level=level)
             self.update_levels(tbpl_level, level)
 
     def evaluate_parser(self, return_code, success_codes=None):
         success_codes = success_codes or [0]