1 :mod:`mozlog` --- Structured logging for test output
2 ===============================================================
4 :py:mod:`mozlog` is a library designed for logging the
5 execution and results of test harnesses. The internal data model is a
6 stream of JSON-compatible objects, with one object per log entry. The
7 default output format is line-based, with one JSON object serialized
10 :py:mod:`mozlog` is *not* based on the stdlib logging
11 module, although it shares several concepts with it.
13 One notable difference between this module and the standard logging
14 module is the way that loggers are created. The structured logging
15 module does not require that loggers with a specific name are
16 singleton objects accessed through a factory function. Instead the
17 ``StructuredLogger`` constructor may be used directly. However all
18 loggers with the same name share the same internal state (the "Borg"
19 pattern). In particular the list of handler functions is the same for
20 all loggers with the same name.
22 Typically, you would only instantiate one logger object per
23 program. Two convenience methods are provided to set and get the
24 default logger in the program.
26 Logging is threadsafe, with access to handlers protected by a
27 ``threading.Lock``. However it is `not` process-safe. This means that
28 applications using multiple processes, e.g. via the
29 ``multiprocessing`` module, should arrange for all logging to happen in
35 Structured loggers produce messages in a simple format designed to be
36 compatible with the JSON data model. Each message is a single object,
37 with the type of message indicated by the ``action`` key. It is
38 intended that the set of ``action`` values be closed; where there are
39 use cases for additional values they should be integrated into this
40 module rather than extended in an ad-hoc way. The set of keys present
41 on on all messages is:
44 The type of the message (string).
47 The timestamp of the message in ms since the epoch (int).
50 The name of the thread emitting the message (string).
53 The pid of the process creating the message (int).
56 Name of the logger creating the message (string).
58 For each ``action`` there are is a further set of specific fields
59 describing the details of the event that caused the message to be
63 Emitted when the testsuite starts running.
66 A dict of test ids keyed by group. Groups are any logical grouping
67 of tests, for example a manifest, directory or tag. For convenience,
68 a list of test ids can be used instead. In this case all tests will
69 automatically be placed in the 'default' group name. Test ids can
70 either be strings or lists of strings (an example of the latter is
71 reftests where the id has the form [test_url, ref_type, ref_url]).
72 Test ids are assumed to be unique within a given testsuite. In cases
73 where the test list is not known upfront an empty dict or list may
77 An optional string to identify the suite by.
80 An optional dictionary describing the properties of the
81 build and test environment. This contains the information provided
82 by :doc:`mozinfo <mozinfo>`, plus a boolean ``debug`` field indicating
83 whether the build under test is a debug build.
86 Emitted when the testsuite is finished and no more results will be produced.
89 Emitted when a test is being started.
92 A unique id for the test (string or list of strings).
95 Optional path to the test relative to some base (typically the root of the
96 source tree). Mainly used when ``test`` id is not a path (string).
99 Emitted for a test which has subtests to record the result of a
103 The same unique id for the test as in the ``test_start`` message.
106 Name of the subtest (string).
109 Result of the test (string enum; ``PASS``, ``FAIL``,
110 ``PRECONDITION_FAILED``, ``TIMEOUT``, ``NOTRUN``)
113 Expected result of the test. Omitted if the expected result is the
114 same as the actual result (string enum, same as ``status``).
116 ``known_intermittent``
117 A list of known intermittent statuses for that test. Omitted if there are
118 no intermittent statuses expected. (items in the list are string enum, same as ``status``)
121 Emitted to give the result of a test with no subtests, or the status
122 of the overall file when there are subtests.
125 The same unique id for the test as in the ``test_start`` message.
128 Either result of the test (if there are no subtests) in which case
129 (string enum ``PASS``, ``FAIL``, ``PRECONDITION_FAILED``,
130 ``TIMEOUT``, ``CRASH``, ``ASSERT``, , ``SKIP``) or the status of
131 the overall file where there are subtests (string enum ``OK``,
132 ``PRECONDITION_FAILED``, ``ERROR``, ``TIMEOUT``, ``CRASH``,
133 ``ASSERT``, ``SKIP``).
136 The expected status, or omitted if the expected status matches the
137 actual status (string enum, same as ``status``).
139 ``known_intermittent``
140 A list of known intermittent statuses for that test. Omitted if there are
141 no intermittent statuses expected. (items in the list are string enum, same as ``status``)
144 Output from a managed subprocess.
147 pid of the subprocess.
150 Command used to launch the subprocess.
153 Data output by the subprocess.
156 General human-readable logging message, used to debug the harnesses
157 themselves rather than to provide input to other tools.
160 Level of the log message (string enum ``CRITICAL``, ``ERROR``,
161 ``WARNING``, ``INFO``, ``DEBUG``).
164 Text of the log message.
167 This is a special action that can only be logged once per logger state.
168 It is sent when calling :meth:`StructuredLogger.shutdown` or implicitly
169 when exiting the context manager.
174 When used for testsuites, the following structured logging messages must be emitted:
176 * One ``suite_start`` message before any ``test_*`` messages
178 * One ``test_start`` message per test that is run
180 * One ``test_status`` message per subtest that is run. This might be
181 zero if the test type doesn't have the notion of subtests.
183 * One ``test_end`` message per test that is run, after the
184 ``test_start`` and any ``test_status`` messages for that same test.
186 * One ``suite_end`` message after all ``test_*`` messages have been
189 The above mandatory events may be interspersed with ``process_output``
190 and ``log`` events, as required.
195 The purpose of subtests is to deal with situations where a single test
196 produces more than one result, and the exact details of the number of
197 results is not known ahead of time. For example consider a test
198 harness that loads JavaScript-based tests in a browser. Each url
199 loaded would be a single test, with corresponding ``test_start`` and
200 ``test_end`` messages. If there can be more than one JS-defined test
201 on a page, however, it it useful to track the results of those tests
202 separately. Therefore each of those tests is a subtest, and one
203 ``test_status`` message must be generated for each subtest result.
205 Subtests must have a name that is unique within their parent test.
207 Whether or not a test has subtests changes the meaning of the
208 ``status`` property on the test itself. When the test does not have
209 any subtests, this property is the actual test result such as ``PASS``
210 or ``FAIL`` . When a test does have subtests, the test itself does not
211 have a result as-such; it isn't meaningful to describe it as having a
212 ``PASS`` result, especially if the subtests did not all pass. Instead
213 this property is used to hold information about whether the test ran
214 without error. If no errors were detected the test must be given the
215 status ``OK``. Otherwise the test may get the status ``ERROR`` (for
216 e.g. uncaught JS exceptions), ``TIMEOUT`` (if no results were reported
217 in the allowed time) or ``CRASH`` (if the test caused the process
218 under test to crash).
220 StructuredLogger Objects
221 ------------------------
223 .. automodule:: mozlog.structuredlog
224 :members: set_default_logger, get_default_logger, LoggerShutdownError
226 .. autoclass:: StructuredLogger
227 :members: add_handler, remove_handler, handlers, suite_start,
228 suite_end, test_start, test_status, test_end,
229 process_output, critical, error, warning, info, debug,
232 .. autoclass:: StructuredLogFileLike
238 Since :func:`mozlog.structuredlog.get_default_logger` return None when
239 the default logger is not initialized, it is not possible to directly
240 use it at the module level.
242 With ProxyLogger, it is possible to write the following code: ::
244 from mozlog import get_proxy_logger
246 LOG = get_proxy_logger('component_name')
250 LOG.info('logging with a module level object')
255 mozlog still needs to be initialized before the first call occurs
256 to a ProxyLogger instance, for example with
257 :func:`mozlog.commandline.setup_logging`.
259 .. automodule:: mozlog.proxy
260 :members: get_proxy_logger, ProxyLogger
265 A handler is a callable that is called for each log message produced
266 and is responsible for handling the processing of that
267 message. The typical example of this is a ``StreamHandler`` which takes
268 a log message, invokes a formatter which converts the log to a string,
269 and writes it to a file.
271 .. automodule:: mozlog.handlers
273 .. autoclass:: BaseHandler
276 .. autoclass:: StreamHandler
279 .. autoclass:: LogLevelFilter
282 .. autoclass:: BufferHandler
288 Formatters are callables that take a log message, and return either a
289 string representation of that message, or ``None`` if that message
290 should not appear in the output. This allows formatters to both
291 exclude certain items and create internal buffers of the output so
292 that, for example, a single string might be returned for a
293 ``test_end`` message indicating the overall result of the test,
294 including data provided in the ``test_status`` messages.
296 Formatter modules are written so that they can take raw input on stdin
297 and write formatted output on stdout. This allows the formatters to be
298 invoked as part of a command line for post-processing raw log files.
300 .. automodule:: mozlog.formatters.base
302 .. autoclass:: BaseFormatter
305 .. automodule:: mozlog.formatters.unittest
307 .. autoclass:: UnittestFormatter
310 .. automodule:: mozlog.formatters.xunit
312 .. autoclass:: XUnitFormatter
315 .. automodule:: mozlog.formatters.html
317 .. autoclass:: HTMLFormatter
320 .. automodule:: mozlog.formatters.machformatter
322 .. autoclass:: MachFormatter
325 .. automodule:: mozlog.formatters.tbplformatter
327 .. autoclass:: TbplFormatter
333 The ``mozlog.reader`` module provides utilities for working
334 with structured log files.
336 .. automodule:: mozlog.reader
339 Integration with argparse
340 -------------------------
342 The `mozlog.commandline` module provides integration with the `argparse`
343 module to provide uniform logging-related command line arguments to programs
344 using `mozlog`. Each known formatter gets a command line argument of the form
345 ``--log-{name}``, which takes the name of a file to log to with that format,
346 or ``-`` to indicate stdout.
348 .. automodule:: mozlog.commandline
356 from mozlog import structuredlog
357 from mozlog import handlers, formatters
358 logger = structuredlog.StructuredLogger("my-test-suite")
359 logger.add_handler(handlers.StreamHandler(sys.stdout,
360 formatters.JSONFormatter()))
361 logger.suite_start(["test-id-1"])
362 logger.test_start("test-id-1")
363 logger.info("This is a message with action='LOG' and level='INFO'")
364 logger.test_status("test-id-1", "subtest-1", "PASS")
365 logger.test_end("test-id-1", "OK")
368 Log with a context manager::
370 from mozlog.structuredlog import StructuredLogger
371 from mozlog.handlers import StreamHandler
372 from mozlog.formatters import JSONFormatter
374 with StructuredLogger("my-test-suite") as logger:
375 logger.add_handler(StreamHandler(sys.stdout,
377 logger.info("This is an info message")
379 Populate an ``argparse.ArgumentParser`` with logging options, and
380 create a logger based on the value of those options, defaulting to
381 JSON output on stdout if nothing else is supplied::
384 from mozlog import commandline
386 parser = argparse.ArgumentParser()
387 # Here one would populate the parser with other options
388 commandline.add_logging_group(parser)
390 args = parser.parse_args()
391 logger = commandline.setup_logging("testsuite-name", args, {"raw": sys.stdout})
393 Count the number of tests that timed out in a testsuite::
395 from mozlog import reader
399 def handle_test_end(data):
401 if data["status"] == "TIMEOUT":
404 reader.each_log(reader.read("my_test_run.log"),
405 {"test_end": handle_test_end})
409 More Complete Example
410 ---------------------
412 This example shows a complete toy testharness set up to used
413 structured logging. It is available as `structured_example.py <_static/structured_example.py>`_:
415 .. literalinclude:: _static/structured_example.py
417 Each global function with a name starting
418 ``test_`` represents a test. A passing test returns without
419 throwing. A failing test throws a :py:class:`TestAssertion` exception
420 via the :py:func:`assert_equals` function. Throwing anything else is
421 considered an error in the test. There is also a :py:func:`expected`
422 decorator that is used to annotate tests that are expected to do
423 something other than pass.
425 The main entry point to the test runner is via that :py:func:`main`
426 function. This is responsible for parsing command line
427 arguments, and initiating the test run. Although the test harness
428 itself does not provide any command line arguments, the
429 :py:class:`ArgumentParser` object is populated by
430 :py:meth:`commandline.add_logging_group`, which provides a generic
431 set of structured logging arguments appropriate to all tools producing
434 The values of these command line arguments are used to create a
435 :py:class:`mozlog.StructuredLogger` object populated with the
436 specified handlers and formatters in
437 :py:func:`commandline.setup_logging`. The third argument to this
438 function is the default arguments to use. In this case the default
439 is to output raw (i.e. JSON-formatted) logs to stdout.
441 The main test harness is provided by the :py:class:`TestRunner`
442 class. This class is responsible for scheduling all the tests and
443 logging all the results. It is passed the :py:obj:`logger` object
444 created from the command line arguments. The :py:meth:`run` method
445 starts the test run. Before the run is started it logs a
446 ``suite_start`` message containing the id of each test that will run,
447 and after the testrun is done it logs a ``suite_end`` message.
449 Individual tests are run in the :py:meth:`run_test` method. For each
450 test this logs a ``test_start`` message. It then runs the test and
451 logs a ``test_end`` message containing the test name, status, expected
452 status, and any informational message about the reason for the
453 result. In this test harness there are no subtests, so the
454 ``test_end`` message has the status of the test and there are no
455 ``test_status`` messages.
460 When run without providing any command line options, the raw
461 structured log messages are sent to stdout::
463 $ python structured_example.py
465 {"source": "structured-example", "tests": ["test_that_has_an_error", "test_that_fails", "test_expected_fail", "test_that_passes"], "thread": "MainThread", "time": 1401446682787, "action": "suite_start", "pid": 18456}
466 {"source": "structured-example", "thread": "MainThread", "time": 1401446682787, "action": "log", "message": "Running tests", "level": "INFO", "pid": 18456}
467 {"source": "structured-example", "test": "test_that_has_an_error", "thread": "MainThread", "time": 1401446682787, "action": "test_start", "pid": 18456}
468 {"status": "ERROR", "thread": "MainThread", "pid": 18456, "source": "structured-example", "test": "test_that_has_an_error", "time": 1401446682788, "action": "test_end", "message": "Traceback (most recent call last):\n File \"structured_example.py\", line 61, in run_test\n func()\n File \"structured_example.py\", line 31, in test_that_has_an_error\n assert_equals(2, 1 + \"1\")\nTypeError: unsupported operand type(s) for +: 'int' and 'str'\n", "expected": "PASS"}
469 {"source": "structured-example", "test": "test_that_fails", "thread": "MainThread", "time": 1401446682788, "action": "test_start", "pid": 18456}
470 {"status": "FAIL", "thread": "MainThread", "pid": 18456, "source": "structured-example", "test": "test_that_fails", "time": 1401446682788, "action": "test_end", "message": "1 not equal to 2", "expected": "PASS"}
471 {"source": "structured-example", "test": "test_expected_fail", "thread": "MainThread", "time": 1401446682788, "action": "test_start", "pid": 18456}
472 {"status": "FAIL", "thread": "MainThread", "pid": 18456, "source": "structured-example", "test": "test_expected_fail", "time": 1401446682788, "action": "test_end", "message": "4 not equal to 5"}
473 {"source": "structured-example", "test": "test_that_passes", "thread": "MainThread", "time": 1401446682788, "action": "test_start", "pid": 18456}
474 {"status": "PASS", "source": "structured-example", "test": "test_that_passes", "thread": "MainThread", "time": 1401446682789, "action": "test_end", "pid": 18456}
475 {"source": "structured-example", "test": "test_with_known_intermittent", "thread": "MainThread", "time": 1401446682789, "action": "test_start", "pid": 18456}
476 {"status": "FAIL", thread": "MainThread", "pid": 18456, "source": "structured-example", "test": "test_with_known_intermittent", "time": 1401446682790, "action": "test_end", "expected": "PASS", "known_intermittent": ["FAIL", "TIMEOUT"]}
477 {"action": "suite_end", "source": "structured-example", "pid": 18456, "thread": "MainThread", "time": 1401446682790}
479 The structured logging module provides a number of command line
482 $ python structured_example.py --help
484 usage: structured_example.py [-h] [--log-unittest LOG_UNITTEST]
485 [--log-raw LOG_RAW] [--log-html LOG_HTML]
486 [--log-xunit LOG_XUNIT]
487 [--log-mach LOG_MACH]
490 -h, --help show this help message and exit
493 Options for logging output. Each option represents a possible logging
494 format and takes a filename to write that format to, or '-' to write to
497 --log-unittest LOG_UNITTEST
498 Unittest style output
499 --log-raw LOG_RAW Raw structured log messages
500 --log-html LOG_HTML HTML report
501 --log-xunit LOG_XUNIT
503 --log-mach LOG_MACH Human-readable output
505 In order to get human-readable output on stdout and the structured log
506 data to go to the file ``structured.log``, we would run::
508 $ python structured_example.py --log-mach=- --log-raw=structured.log
510 0:00.00 SUITE_START: MainThread 4
511 0:01.00 LOG: MainThread INFO Running tests
512 0:01.00 TEST_START: MainThread test_that_has_an_error
513 0:01.00 TEST_END: MainThread Harness status ERROR, expected PASS. Subtests passed 0/0. Unexpected 1
514 0:01.00 TEST_START: MainThread test_that_fails
515 0:01.00 TEST_END: MainThread Harness status FAIL, expected PASS. Subtests passed 0/0. Unexpected 1
516 0:01.00 TEST_START: MainThread test_expected_fail
517 0:02.00 TEST_END: MainThread Harness status FAIL. Subtests passed 0/0. Unexpected 0
518 0:02.00 TEST_START: MainThread test_that_passes
519 0:02.00 TEST_END: MainThread Harness status PASS. Subtests passed 0/0. Unexpected 0
520 0:02.00 SUITE_END: MainThread