Bug 1671422 - [mozlog] Add group durations to errorsummary.log, r=marco

Durations are measured in ms, and are computed by subtracting the timestamp of
the first 'test_start' action from the last 'test_end' for each manifest.

Differential Revision: https://phabricator.services.mozilla.com/D94178

.flake8

@@ -108,6 +108,7 @@ per-file-ignores =
     testing/marionette/**/__init__.py: F401
     testing/mochitest/tests/python/conftest.py: F811
     testing/mozbase/manifestparser/tests/test_filters.py: E731
+    testing/mozbase/mozlog/tests/test_formatters.py: E501
     testing/mozharness/configs/*: E124, E127, E128, E131, E231, E261, E265, E266, E501, W391
 
     # These paths contain Python-2 only syntax which cause errors since flake8

testing/mozbase/mozlog/mozlog/formatters/errorsummary.py

@@ -6,6 +6,7 @@
 from __future__ import absolute_import
 
 import json
+from collections import defaultdict
 
 from .base import BaseFormatter
 
@@ -13,8 +14,12 @@ from .base import BaseFormatter
 class ErrorSummaryFormatter(BaseFormatter):
 
     def __init__(self):
-        self.groups = {}
-        self.group_results = {}
+        self.test_to_group = {}
+        self.groups = defaultdict(lambda: {
+            "status": None,
+            "start": None,
+            "end": None,
+        })
         self.line_count = 0
 
     def __call__(self, data):
@@ -30,7 +35,7 @@ class ErrorSummaryFormatter(BaseFormatter):
     def _output_test(self, test, subtest, item):
         data = {"test": test,
                 "subtest": subtest,
-                "group": self.groups.get(test, ''),
+                "group": self.test_to_group.get(test, ''),
                 "status": item["status"],
                 "expected": item["expected"],
                 "message": item.get("message"),
@@ -38,44 +43,60 @@ class ErrorSummaryFormatter(BaseFormatter):
                 "known_intermittent": item.get("known_intermittent", [])}
         return self._output("test_result", data)
 
-    def _update_results(self, item):
-        group = self.groups.get(item["test"], None)
-        if group is None:
-            return
+    def _update_group_result(self, group, item):
+        ginfo = self.groups[group]
 
         if item["status"] == "SKIP":
-            if group not in self.group_results:
-                self.group_results[group] = "SKIP"
+            if ginfo["status"] is None:
+                ginfo["status"] = "SKIP"
         elif (
             "expected" not in item
             or item["status"] == item["expected"]
             or item["status"] in item.get("known_intermittent", [])
         ):
-            if group not in self.group_results or self.group_results[group] == "SKIP":
-                self.group_results[group] = "OK"
+            if ginfo["status"] in (None, "SKIP"):
+                ginfo["status"] = "OK"
         else:
-            self.group_results[group] = "ERROR"
+            ginfo["status"] = "ERROR"
 
     def suite_start(self, item):
-        self.groups = {v: k for k in item["tests"] for v in item["tests"][k]}
+        self.test_to_group = {v: k for k in item["tests"] for v in item["tests"][k]}
         return self._output("test_groups", {"groups": list(item["tests"].keys())})
 
     def suite_end(self, data):
         return "".join(
-            self._output("group_result", {"group": group, "status": status})
-            for group, status in self.group_results.items()
+            self._output("group_result", {
+                "group": group,
+                "status": info["status"],
+                "duration": info["end"] - info["start"],
+            })
+            for group, info in self.groups.items()
         )
 
+    def test_start(self, item):
+        group = self.test_to_group.get(item["test"], None)
+        if group and self.groups[group]["start"] is None:
+            self.groups[group]["start"] = item["time"]
+
     def test_status(self, item):
-        self._update_results(item)
+        group = self.test_to_group.get(item["test"], None)
+        if group:
+            self._update_group_result(group, item)
+
         if "expected" not in item:
             return
+
         return self._output_test(item["test"], item["subtest"], item)
 
     def test_end(self, item):
-        self._update_results(item)
+        group = self.test_to_group.get(item["test"], None)
+        if group:
+            self._update_group_result(group, item)
+            self.groups[group]["end"] = item["time"]
+
         if "expected" not in item:
             return
+
         return self._output_test(item["test"], None, item)
 
     def log(self, item):

testing/mozbase/mozlog/tests/test_formatters.py

@@ -6,9 +6,11 @@
 
 from __future__ import absolute_import, print_function, unicode_literals
 
-import unittest
+import json
 import os
 import signal
+import time
+import unittest
 import xml.etree.ElementTree as ET
 from textwrap import dedent
 
@@ -22,12 +24,14 @@ from mozlog.formatters import (
     TbplFormatter,
     HTMLFormatter,
     XUnitFormatter,
-    GroupingFormatter
+    GroupingFormatter,
+    ErrorSummaryFormatter,
 )
 from mozlog.handlers import StreamHandler
 
 formatters = {
     'mach': MachFormatter,
+    'errorsummary': ErrorSummaryFormatter,
 }
 
 FORMATS = {
@@ -248,6 +252,15 @@ FORMATS = {
             OK
             """).lstrip('\n')),
     ],
+
+    'ERRORSUMMARY': [
+        ('errorsummary', {}, dedent("""
+            {"groups": ["manifestA", "manifestB"], "action": "test_groups", "line": 0}
+            {"test": "test_baz", "subtest": null, "group": "manifestA", "status": "PASS", "expected": "FAIL", "message": null, "stack": null, "known_intermittent": [], "action": "test_result", "line": 8}
+            {"group": "manifestA", "status": "ERROR", "duration": 70, "action": "group_result", "line": 9}
+            {"group": "manifestB", "status": "OK", "duration": 10, "action": "group_result", "line": 9}
+            """).lstrip('\n')),
+    ]
 }
 
 
@@ -270,13 +283,25 @@ def timestamp(monkeypatch):
     monkeypatch.setattr(MachFormatter, '_time', fake_time)
 
 
+@pytest.fixture
+def get_logger():
+    # Ensure a new state instance is created for each test function.
+    StructuredLogger._logger_states = {}
+
+    def inner(name, **fmt_args):
+        buf = StringIO()
+        fmt = formatters[name](**fmt_args)
+        logger = StructuredLogger('test_logger')
+        logger.add_handler(StreamHandler(buf, fmt))
+        return logger
+
+    return inner
+
+
 @pytest.mark.parametrize("name,opts,expected", FORMATS['PASS'],
                          ids=ids('PASS'))
-def test_pass(name, opts, expected):
-    buf = StringIO()
-    fmt = formatters[name](**opts)
-    logger = StructuredLogger('test_logger')
-    logger.add_handler(StreamHandler(buf, fmt))
+def test_pass(get_logger, name, opts, expected):
+    logger = get_logger(name, **opts)
 
     logger.suite_start(['test_foo', 'test_bar', 'test_baz'])
     logger.test_start('test_foo')
@@ -288,6 +313,7 @@ def test_pass(name, opts, expected):
     logger.test_end('test_baz', 'FAIL', 'FAIL', 'expected 0 got 1')
     logger.suite_end()
 
+    buf = logger.handlers[0].stream
     result = buf.getvalue()
     print("Dumping result for copy/paste:")
     print(result)
@@ -296,16 +322,13 @@ def test_pass(name, opts, expected):
 
 @pytest.mark.parametrize("name,opts,expected", FORMATS['FAIL'],
                          ids=ids('FAIL'))
-def test_fail(name, opts, expected):
+def test_fail(get_logger, name, opts, expected):
     stack = """
     SimpleTest.is@SimpleTest/SimpleTest.js:312:5
     @caps/tests/mochitest/test_bug246699.html:53:1
 """.strip('\n')
 
-    buf = StringIO()
-    fmt = formatters[name](**opts)
-    logger = StructuredLogger('test_logger')
-    logger.add_handler(StreamHandler(buf, fmt))
+    logger = get_logger(name, **opts)
 
     logger.suite_start(['test_foo', 'test_bar', 'test_baz'])
     logger.test_start('test_foo')
@@ -318,6 +341,7 @@ def test_fail(name, opts, expected):
     logger.test_end('test_baz', 'PASS', 'FAIL')
     logger.suite_end()
 
+    buf = logger.handlers[0].stream
     result = buf.getvalue()
     print("Dumping result for copy/paste:")
     print(result)
@@ -326,11 +350,8 @@ def test_fail(name, opts, expected):
 
 @pytest.mark.parametrize("name,opts,expected", FORMATS['PRECONDITION_FAILED'],
                          ids=ids('PRECONDITION_FAILED'))
-def test_precondition_failed(name, opts, expected):
-    buf = StringIO()
-    fmt = formatters[name](**opts)
-    logger = StructuredLogger('test_logger')
-    logger.add_handler(StreamHandler(buf, fmt))
+def test_precondition_failed(get_logger, name, opts, expected):
+    logger = get_logger(name, **opts)
 
     logger.suite_start(['test_foo', 'test_bar'])
     logger.test_start('test_foo')
@@ -341,6 +362,7 @@ def test_precondition_failed(name, opts, expected):
     logger.test_end('test_bar', 'OK')
     logger.suite_end()
 
+    buf = logger.handlers[0].stream
     result = buf.getvalue()
     print("Dumping result for copy/paste:")
     print(result)
@@ -349,11 +371,8 @@ def test_precondition_failed(name, opts, expected):
 
 @pytest.mark.parametrize("name,opts,expected", FORMATS['KNOWN-INTERMITTENT'],
                          ids=ids('KNOWN-INTERMITTENT'))
-def test_known_intermittent(name, opts, expected):
-    buf = StringIO()
-    fmt = formatters[name](**opts)
-    logger = StructuredLogger('test_logger')
-    logger.add_handler(StreamHandler(buf, fmt))
+def test_known_intermittent(get_logger, name, opts, expected):
+    logger = get_logger(name, **opts)
 
     logger.suite_start(['test_foo', 'test_bar', 'test_baz'])
     logger.test_start('test_foo')
@@ -367,12 +386,54 @@ def test_known_intermittent(name, opts, expected):
                     known_intermittent=['PASS'])
     logger.suite_end()
 
+    buf = logger.handlers[0].stream
     result = buf.getvalue()
     print("Dumping result for copy/paste:")
     print(result)
     assert result == expected
 
 
+@pytest.mark.parametrize("name,opts,expected", FORMATS['ERRORSUMMARY'],
+                         ids=ids('ERRORSUMMARY'))
+def test_errorsummary(monkeypatch, get_logger, name, opts, expected):
+
+    ts = {'ts': 0}  # need to use dict since 'nonlocal' doesn't exist on PY2
+
+    def fake_time():
+        ts['ts'] += 0.01
+        return ts['ts']
+
+    monkeypatch.setattr(time, 'time', fake_time)
+    logger = get_logger(name, **opts)
+
+    logger.suite_start({
+        'manifestA': ['test_foo', 'test_bar', 'test_baz'],
+        'manifestB': ['test_something'],
+    })
+    logger.test_start('test_foo')
+    logger.test_end('test_foo', 'SKIP')
+    logger.test_start('test_bar')
+    logger.test_end('test_bar', 'OK')
+    logger.test_start('test_something')
+    logger.test_end('test_something', 'OK')
+    logger.test_start('test_baz')
+    logger.test_end('test_baz', 'PASS', 'FAIL')
+    logger.suite_end()
+
+    buf = logger.handlers[0].stream
+    result = buf.getvalue()
+    print("Dumping result for copy/paste:")
+    print(result)
+
+    expected = expected.split("\n")
+    for i, line in enumerate(result.split("\n")):
+        if not line:
+            continue
+
+        data = json.loads(line)
+        assert data == json.loads(expected[i])
+
+
 class FormatterTest(unittest.TestCase):
 
     def setUp(self):