Bug 1526445 - [mochitest] Don't ever enable log buffering if it was initially disabled, r=gbrown
authorAndrew Halberstadt <ahalberstadt@mozilla.com>
Wed, 11 Mar 2020 03:11:47 +0000
changeset 518190 3a7bf80352e455b2cd53dda9698a0e7eb5ed0b8f
parent 518189 1313df275548899d287430ee34551a7bb398f6ed
child 518191 b2e47ad97d590e015bf5a44af9645b6ebe8ed71b
push id37206
push useraciure@mozilla.com
push dateThu, 12 Mar 2020 03:57:49 +0000
treeherdermozilla-central@4fd5c458be4c [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersgbrown
bugs1526445
milestone76.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1526445 - [mochitest] Don't ever enable log buffering if it was initially disabled, r=gbrown Differential Revision: https://phabricator.services.mozilla.com/D66284
testing/mochitest/runtests.py
testing/mochitest/tests/python/python.ini
testing/mochitest/tests/python/test_message_logger.py
--- a/testing/mochitest/runtests.py
+++ b/testing/mochitest/runtests.py
@@ -167,19 +167,22 @@ class MessageLogger(object):
     def __init__(self, logger, buffering=True, structured=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
         # a TEST-START comes in.
-        self.buffering = False
+        self._buffering = False
         self.restore_buffering = buffering
 
+        # Guard to ensure we never buffer if this value was initially `False`
+        self._buffering_initially_enabled = buffering
+
         # Message buffering
         self.buffered_messages = []
 
     def validate(self, obj):
         """Tests whether 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):
@@ -240,16 +243,26 @@ class MessageLogger(object):
 
             self._fix_subtest_name(message)
             self._fix_test_name(message)
             self._fix_message_format(message)
             messages.append(message)
 
         return messages
 
+    @property
+    def buffering(self):
+        if not self._buffering_initially_enabled:
+            return False
+        return self._buffering
+
+    @buffering.setter
+    def buffering(self, val):
+        self._buffering = val
+
     def process_message(self, message):
         """Processes a structured message. Takes into account buffering, errors, ..."""
         # Activation/deactivating message buffering from the JS side
         if message['action'] == 'buffering_on':
             self.buffering = True
             return
         if message['action'] == 'buffering_off':
             self.buffering = False
--- a/testing/mochitest/tests/python/python.ini
+++ b/testing/mochitest/tests/python/python.ini
@@ -1,8 +1,9 @@
 [DEFAULT]
 subsuite = mochitest
 skip-if = python == 3
 
 [test_basic_mochitest_plain.py]
 sequential = true
+[test_build_profile.py]
 [test_get_active_tests.py]
-[test_build_profile.py]
+[test_message_logger.py]
new file mode 100644
--- /dev/null
+++ b/testing/mochitest/tests/python/test_message_logger.py
@@ -0,0 +1,146 @@
+# Any copyright is dedicated to the Public Domain.
+# http://creativecommons.org/publicdomain/zero/1.0/
+
+from __future__ import absolute_import, print_function
+
+import json
+import time
+import types
+from StringIO import StringIO
+
+import mozunit
+import pytest
+from conftest import setup_args
+from mozlog.formatters import JSONFormatter
+from mozlog.handlers.base import StreamHandler
+from mozlog.structuredlog import StructuredLogger
+from six import string_types
+
+
+@pytest.fixture
+def logger():
+    logger = StructuredLogger('mochitest_message_logger')
+
+    buf = StringIO()
+    handler = StreamHandler(buf, JSONFormatter())
+    logger.add_handler(handler)
+    return logger
+
+
+@pytest.fixture
+def get_message_logger(setup_test_harness, logger):
+    setup_test_harness(*setup_args)
+    runtests = pytest.importorskip('runtests')
+
+    def fake_message(self, action, **extra):
+        message = {
+            'action': action,
+            'time': time.time(),
+        }
+        if action in ('test_start', 'test_end', 'test_status'):
+            message['test'] = 'test_foo.html'
+
+            if action == 'test_end':
+                message['status'] = 'PASS'
+                message['expected'] = 'PASS'
+
+            elif action == 'test_status':
+                message['subtest'] = 'bar'
+                message['status'] = 'PASS'
+
+        elif action == 'log':
+            message['level'] = 'INFO'
+            message['message'] = 'foobar'
+
+        message.update(**extra)
+        return self.process_message(message)
+
+    def inner(**kwargs):
+        ml = runtests.MessageLogger(logger, **kwargs)
+
+        # Create a convenience function for faking incoming log messages.
+        ml.fake_message = types.MethodType(fake_message, ml)
+        return ml
+
+    return inner
+
+
+@pytest.fixture
+def assert_actions(logger):
+    buf = logger.handlers[0].stream
+
+    def inner(expected):
+        if isinstance(expected, string_types):
+            expected = [expected]
+
+        lines = buf.getvalue().splitlines()
+        actions = [json.loads(l)['action'] for l in lines]
+        assert actions == expected
+        buf.truncate(0)
+
+    return inner
+
+
+def test_buffering_on(get_message_logger, assert_actions):
+    ml = get_message_logger(buffering=True)
+
+    # no buffering initially (outside of test)
+    ml.fake_message('log')
+    assert_actions(['log'])
+
+    # inside a test buffering is enabled, only 'test_start' logged
+    ml.fake_message('test_start')
+    ml.fake_message('test_status')
+    ml.fake_message('log')
+    assert_actions(['test_start'])
+
+    # buffering turned off manually within a test
+    ml.fake_message('buffering_off')
+    ml.fake_message('test_status')
+    ml.fake_message('log')
+    assert_actions(['test_status', 'log'])
+
+    # buffering turned back on again
+    ml.fake_message('buffering_on')
+    ml.fake_message('test_status')
+    ml.fake_message('log')
+    assert_actions([])
+
+    # test end, it failed! All previsouly buffered messages are now logged.
+    ml.fake_message('test_end', status='FAIL')
+    assert_actions([
+        'log',          # "Buffered messages logged"
+        'test_status',
+        'log',
+        'test_status',
+        'log',
+        'log',          # "Buffered messages finished"
+        'test_end',
+    ])
+
+
+def test_buffering_off(get_message_logger, assert_actions):
+    ml = get_message_logger(buffering=False)
+
+    ml.fake_message('test_start')
+    assert_actions(['test_start'])
+
+    # messages logged no matter what the state
+    ml.fake_message('test_status')
+    ml.fake_message('buffering_off')
+    ml.fake_message('log')
+    assert_actions(['test_status', 'log'])
+
+    # even after a 'buffering_on' action
+    ml.fake_message('buffering_on')
+    ml.fake_message('test_status')
+    ml.fake_message('log')
+    assert_actions(['test_status', 'log'])
+
+    # no buffer to empty on test fail
+    ml.fake_message('test_end', status='FAIL')
+    assert_actions(['test_end'])
+
+
+if __name__ == '__main__':
+    mozunit.main()