Bug 1344346 - [mozlog] Add 'main' key to the process_start action, r?jgraham draft
authorAndrew Halberstadt <ahalberstadt@mozilla.com>
Fri, 03 Mar 2017 16:25:23 -0500
changeset 494062 7be44abff6541afb888eb90d5487f98c9328d0f2
parent 493226 a793136c90bc5d32f2c82aa7dea4bc300c4f1836
child 494063 5776110269336c54f7fc4a67ff97bae315dd66ab
push id47921
push userahalberstadt@mozilla.com
push dateMon, 06 Mar 2017 14:42:00 +0000
reviewersjgraham
bugs1344346
milestone54.0a1
Bug 1344346 - [mozlog] Add 'main' key to the process_start action, r?jgraham We ran into a situation where we want to format 'main' process output differently from a subprocess' output. This simple key allows formatters to distinguish. MozReview-Commit-ID: 2MJIidhTxBR
testing/mozbase/mozlog/mozlog/formatters/machformatter.py
testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
testing/mozbase/mozlog/mozlog/logtypes.py
testing/mozbase/mozlog/mozlog/structuredlog.py
testing/mozbase/mozlog/tests/test_structured.py
--- a/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
+++ b/testing/mozbase/mozlog/mozlog/formatters/machformatter.py
@@ -46,16 +46,17 @@ class MachFormatter(base.BaseFormatter):
         self.write_interval = write_interval
         self.write_times = write_times
         self.status_buffer = {}
         self.has_unexpected = {}
         self.last_time = None
         self.terminal = terminal
         self.verbose = False
         self._known_pids = set()
+        self._main_pids = set()
 
         self.summary_values = {"tests": 0,
                                "subtests": 0,
                                "assertion_counts": 0,
                                "expected": 0,
                                "unexpected": defaultdict(int),
                                "skipped": 0}
         self.summary_unexpected = []
@@ -315,18 +316,20 @@ class MachFormatter(base.BaseFormatter):
         if "expected" in data:
             self.summary_values["unexpected"][data["status"]] += 1
         elif data["status"] == "SKIP":
             self.summary_values["skipped"] += 1
         else:
             self.summary_values["expected"] += 1
 
     def process_output(self, data):
+        if data['process'] in self._main_pids:
+            return "%s\n" % data["data"]
+
         rv = []
-
         if "command" in data and data["process"] not in self._known_pids:
             self._known_pids.add(data["process"])
             rv.append('(pid:%s) Full command: %s' % (data["process"], data["command"]))
 
         rv.append('(pid:%s) "%s"' % (data["process"], data["data"]))
         return "\n".join(rv)
 
     def crash(self, data):
@@ -358,16 +361,19 @@ class MachFormatter(base.BaseFormatter):
 
         rv = "\n".join(rv)
         if not rv[-1] == "\n":
             rv += "\n"
 
         return rv
 
     def process_start(self, data):
+        if data.get('main'):
+            self._main_pids.add(data['process'])
+
         rv = "Started process `%s`" % data['process']
         desc = data.get('command')
         if desc:
             rv = '%s (%s)' % (rv, desc)
         return rv
 
     def process_exit(self, data):
         return "%s: %s" % (data['process'], strstatus(data['exitcode']))
--- a/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
+++ b/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
@@ -25,16 +25,17 @@ class TbplFormatter(BaseFormatter):
     hand-parsing this format.
     """
     def __init__(self, compact=False):
         self.suite_start_time = None
         self.test_start_times = {}
         self.buffer = None
         self.compact = compact
         self.subtests_count = 0
+        self._main_pids = set()
 
     @property
     def compact(self):
         return self._compact
 
     @compact.setter
     def compact(self, value):
         self._compact = value
@@ -67,20 +68,25 @@ class TbplFormatter(BaseFormatter):
 
         if "stack" in data:
             message += "\n%s" % data["stack"]
 
         return "%s\n" % message
 
     @output_subtests
     def process_output(self, data):
+        if data['process'] in self._main_pids:
+            return "%s\n" % data['data']
         return "PROCESS | %(process)s | %(data)s\n" % data
 
     @output_subtests
     def process_start(self, data):
+        if data.get('main'):
+            self._main_pids.add(data['process'])
+
         msg = "TEST-INFO | started process %s" % data['process']
         if 'command' in data:
             msg = '%s (%s)' % (msg, data['command'])
         return msg + '\n'
 
     @output_subtests
     def process_exit(self, data):
         return "TEST-INFO | %s: %s\n" % (data['process'],
--- a/testing/mozbase/mozlog/mozlog/logtypes.py
+++ b/testing/mozbase/mozlog/mozlog/logtypes.py
@@ -229,16 +229,22 @@ class TestList(DataType):
 
 
 class Int(DataType):
 
     def convert(self, data):
         return int(data)
 
 
+class Bool(DataType):
+
+    def convert(self, data):
+        return bool(data)
+
+
 class Any(DataType):
 
     def convert(self, data):
         return data
 
 
 class Tuple(ContainerType):
 
--- a/testing/mozbase/mozlog/mozlog/structuredlog.py
+++ b/testing/mozbase/mozlog/mozlog/structuredlog.py
@@ -6,18 +6,31 @@ from __future__ import unicode_literals
 
 from multiprocessing import current_process
 from threading import current_thread, Lock
 import json
 import sys
 import time
 import traceback
 
-from logtypes import Unicode, TestId, TestList, Status, SubStatus, Dict, List, Int, Any, Tuple
-from logtypes import log_action, convertor_registry
+from logtypes import (
+    convertor_registry,
+    log_action,
+    Any,
+    Bool,
+    Dict,
+    Int,
+    List,
+    Status,
+    SubStatus,
+    TestId,
+    TestList,
+    Tuple,
+    Unicode,
+)
 
 """Structured Logging for recording test results.
 
 Allowed actions, and subfields:
   suite_start
       tests  - List of test names
 
   suite_end
@@ -397,24 +410,27 @@ class StructuredLogger(object):
         self._log_data("crash", data)
 
     @log_action(Unicode("primary", default=None),
                 List(Unicode, "secondary", default=None))
     def valgrind_error(self, data):
         self._log_data("valgrind_error", data)
 
     @log_action(Unicode("process"),
-                Unicode("command", default=None, optional=True))
+                Unicode("command", default=None, optional=True),
+                Bool("main", default=False, optional=True))
     def process_start(self, data):
         """Log start event of a process.
 
         :param process: A unique identifier for the process producing the
                         output (typically the pid)
         :param command: A string representing the full command line used to
                         start the process.
+        :param main: A boolean declaring whether this is the main application
+                     process or not (default False).
         """
         self._log_data("process_start", data)
 
     @log_action(Unicode("process"),
                 Int("exitcode"),
                 Unicode("command", default=None, optional=True))
     def process_exit(self, data):
         """Log exit event of a process.
--- a/testing/mozbase/mozlog/tests/test_structured.py
+++ b/testing/mozbase/mozlog/tests/test_structured.py
@@ -653,16 +653,25 @@ class TestTBPLFormatter(FormatterTest):
         self.logger.test_end("test1", "OK")
         self.logger.suite_end()
 
         # This sequence should not produce blanklines
         for line in self.loglines:
             self.assertNotEqual("", line, "No blank line should be present in: %s" %
                                 self.loglines)
 
+    def test_main_process_output(self):
+        self.logger.process_start(1234, main=True)
+        self.logger.process_output(1234, "This line should not start with PROCESS")
+        self.assertFalse(self.loglines[1].startswith('PROCESS'))
+
+        self.logger.process_start(5678)
+        self.logger.process_output(5678, "This line should start with PROCESS")
+        self.assertTrue(self.loglines[3].startswith('PROCESS'))
+
     def test_process_exit(self):
         self.logger.process_exit(1234, 0)
         self.assertIn('TEST-INFO | 1234: exit 0', self.loglines)
 
     @unittest.skipUnless(os.name == 'posix', 'posix only')
     def test_process_exit_with_sig(self):
         # subprocess return code is negative when process
         # has been killed by signal on posix.