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
--- 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",