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
--- 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.