Bug 1419826 - [mozlog] Implement StructuredLogger.shutdown(), r?jgraham draft
authorAndrew Halberstadt <ahalberstadt@mozilla.com>
Wed, 22 Nov 2017 23:10:39 -0500
changeset 704278 2da67cd13d315e00e3fe729e0d1760830d160e71
parent 704277 2d9f120a7529834c8d14f8fe6cae9e555b7f1f88
child 742060 7f4f7c25f7cdecbf685fa9e9792b2d89aea20a31
push id91140
push userahalberstadt@mozilla.com
push dateTue, 28 Nov 2017 14:50:04 +0000
reviewersjgraham
bugs1419826
milestone59.0a1
Bug 1419826 - [mozlog] Implement StructuredLogger.shutdown(), r?jgraham Calling shutdown() causes two things to happen: 1) A 'shutdown' action is implicitly logged so handlers/formatters can do things on log shutdown. 2) Further attempts to use the logger raises a LoggerShutdownError. The shutdown() method is also implicitly called when exiting the context manager. MozReview-Commit-ID: LLNojVoCBZY
testing/mozbase/docs/mozlog.rst
testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
testing/mozbase/mozlog/mozlog/structuredlog.py
testing/mozbase/mozlog/tests/test_structured.py
--- a/testing/mozbase/docs/mozlog.rst
+++ b/testing/mozbase/docs/mozlog.rst
@@ -149,16 +149,21 @@ emitted:
 
   ``level``
     Level of the log message (string enum ``CRITICAL``, ``ERROR``,
     ``WARNING``, ``INFO``, ``DEBUG``).
 
   ``message``
     Text of the log message.
 
+``shutdown``
+  This is a special action that can only be logged once per logger state.
+  It is sent when calling :meth:`StructuredLogger.shutdown` or implicitly
+  when exiting the context manager.
+
 Testsuite Protocol
 ------------------
 
 When used for testsuites, the following structured logging messages must be emitted:
 
  * One ``suite_start`` message before any ``test_*`` messages
 
  * One ``test_start`` message per test that is run
@@ -202,22 +207,23 @@ status ``OK``. Otherwise the test may ge
 e.g. uncaught JS exceptions), ``TIMEOUT`` (if no results were reported
 in the allowed time) or ``CRASH`` (if the test caused the process
 under test to crash).
 
 StructuredLogger Objects
 ------------------------
 
 .. automodule:: mozlog.structuredlog
-  :members: set_default_logger, get_default_logger
+  :members: set_default_logger, get_default_logger, LoggerShutdownError
 
 .. autoclass:: StructuredLogger
    :members: add_handler, remove_handler, handlers, suite_start,
              suite_end, test_start, test_status, test_end,
-             process_output, critical, error, warning, info, debug
+             process_output, critical, error, warning, info, debug,
+             shutdown
 
 .. autoclass:: StructuredLogFileLike
   :members:
 
 ProxyLogger Objects
 -------------------
 
 Since :func:`mozlog.structuredlog.get_default_logger` return None when
@@ -345,16 +351,26 @@ Log to stdout::
                                               formatters.JSONFormatter()))
     logger.suite_start(["test-id-1"])
     logger.test_start("test-id-1")
     logger.info("This is a message with action='LOG' and level='INFO'")
     logger.test_status("test-id-1", "subtest-1", "PASS")
     logger.test_end("test-id-1", "OK")
     logger.suite_end()
 
+Log with a context manager::
+
+    from mozlog.structuredlog import StructuredLogger
+    from mozlog.handlers import StreamHandler
+    from mozlog.formatters import JSONFormatter
+
+    with StructuredLogger("my-test-suite") as logger:
+        logger.add_handler(StreamHandler(sys.stdout,
+                                         JSONFormatter()))
+        logger.info("This is an info message")
 
 Populate an ``argparse.ArgumentParser`` with logging options, and
 create a logger based on the value of those options, defaulting to
 JSON output on stdout if nothing else is supplied::
 
    import argparse
    from mozlog import commandline
 
--- a/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
+++ b/testing/mozbase/mozlog/mozlog/formatters/tbplformatter.py
@@ -40,19 +40,16 @@ class TbplFormatter(BaseFormatter):
     @compact.setter
     def compact(self, value):
         self._compact = value
         if value:
             self.buffer = deque([], 10)
         else:
             self.buffer = None
 
-    def __call__(self, data):
-        return getattr(self, data["action"])(data)
-
     def _format_subtests(self, component, subtract_context=False):
         count = self.subtests_count
         if subtract_context:
             count -= len(self.buffer)
         self.subtests_count = 0
         return self._log({"level": "INFO",
                           "message": "." * count,
                           "component": component})
--- a/testing/mozbase/mozlog/mozlog/structuredlog.py
+++ b/testing/mozbase/mozlog/mozlog/structuredlog.py
@@ -105,26 +105,31 @@ log_levels = dict((k.upper(), v) for v, 
 lint_levels = ["ERROR", "WARNING"]
 
 
 def log_actions():
     """Returns the set of actions implemented by mozlog."""
     return set(convertor_registry.keys())
 
 
+class LoggerShutdownError(Exception):
+    """Raised when attempting to log after logger.shutdown() has been called."""
+
+
 class LoggerState(object):
 
     def __init__(self):
         self.reset()
 
     def reset(self):
         self.handlers = []
         self.running_tests = set()
         self.suite_started = False
         self.component_states = {}
+        self.has_shutdown = False
 
 
 class ComponentState(object):
 
     def __init__(self):
         self.filter_ = None
 
 
@@ -222,16 +227,19 @@ class StructuredLogger(object):
     def _log_data(self, action, data=None):
         if data is None:
             data = {}
 
         log_data = self._make_log_data(action, data)
         self._handle_log(log_data)
 
     def _handle_log(self, data):
+        if self._state.has_shutdown:
+            raise LoggerShutdownError("{} action received after shutdown.".format(data['action']))
+
         with self._lock:
             if self.component_filter:
                 data = self.component_filter(data)
                 if data is None:
                     return
 
             for handler in self.handlers:
                 try:
@@ -450,16 +458,35 @@ class StructuredLogger(object):
         """Log count of assertions produced when running a test.
 
         :param count: - Number of assertions produced
         :param min_expected: - Minimum expected number of assertions
         :param max_expected: - Maximum expected number of assertions
         """
         self._log_data("assertion_count", data)
 
+    @log_action()
+    def shutdown(self, data):
+        """Shutdown the logger.
+
+        This logs a 'shutdown' action after which any further attempts to use
+        the logger will raise a :exc:`LoggerShutdownError`.
+
+        This is also called implicitly from the destructor or
+        when exiting the context manager.
+        """
+        self._log_data('shutdown', data)
+        self._state.has_shutdown = True
+
+    def __enter__(self):
+        return self
+
+    def __exit__(self, exc, val, tb):
+        self.shutdown()
+
 
 def _log_func(level_name):
     @log_action(Unicode("message"),
                 Any("exc_info", default=False))
     def log(self, data):
         exc_info = data.pop("exc_info", None)
         if exc_info:
             if not isinstance(exc_info, tuple):
--- a/testing/mozbase/mozlog/tests/test_structured.py
+++ b/testing/mozbase/mozlog/tests/test_structured.py
@@ -392,16 +392,55 @@ class TestStructuredLog(BaseStructuredTe
                                 "message": "line 3"})
 
         file_like.write("line 4\r\n")
 
         self.assert_log_equals({"action": "log",
                                 "level": "INFO",
                                 "message": "line 4"})
 
+    def test_shutdown(self):
+        # explicit shutdown
+        log = structuredlog.StructuredLogger("test 1")
+        log.add_handler(self.handler)
+        log.info("line 1")
+        self.assert_log_equals({"action": "log",
+                                "level": "INFO",
+                                "message": "line 1",
+                                "source": "test 1"})
+        log.shutdown()
+        self.assert_log_equals({"action": "shutdown", "source": "test 1"})
+        with self.assertRaises(structuredlog.LoggerShutdownError):
+            log.info("bad log")
+        with self.assertRaises(structuredlog.LoggerShutdownError):
+            log.log_raw({"action": "log", "level": "info", "message": "bad log"})
+
+        # shutdown still applies to new instances
+        del log
+        log = structuredlog.StructuredLogger("test 1")
+        with self.assertRaises(structuredlog.LoggerShutdownError):
+            log.info("bad log")
+
+        # context manager shutdown
+        with structuredlog.StructuredLogger("test 2") as log:
+            log.add_handler(self.handler)
+            log.info("line 2")
+            self.assert_log_equals({"action": "log",
+                                    "level": "INFO",
+                                    "message": "line 2",
+                                    "source": "test 2"})
+        self.assert_log_equals({"action": "shutdown", "source": "test 2"})
+
+        # shutdown prevents logging across instances
+        log1 = structuredlog.StructuredLogger("test 3")
+        log2 = structuredlog.StructuredLogger("test 3", component="bar")
+        log1.shutdown()
+        with self.assertRaises(structuredlog.LoggerShutdownError):
+            log2.info("line 3")
+
 
 class TestTypeConversions(BaseStructuredTest):
 
     def test_raw(self):
         self.logger.log_raw({"action": "suite_start",
                              "tests": [1],
                              "time": "1234"})
         self.assert_log_equals({"action": "suite_start",