michael@0: :mod:`mozlog.structured` --- Structured logging for test output
michael@0: ===============================================================
michael@0: 
michael@0: ``mozlog.structured`` is a library designed for logging the execution
michael@0: and results of test harnesses. The canonical output format is JSON,
michael@0: with one line of JSON per log entry. It is *not* based on the stdlib
michael@0: logging module, although it shares several concepts with this module.
michael@0: 
michael@0: One notable difference between this module and the standard logging
michael@0: module is the way that loggers are created. The structured logging
michael@0: module does not require that loggers with a specific name are
michael@0: singleton objects accessed through a factory function. Instead the
michael@0: ``StructuredLogger`` constructor may be used directly. However all
michael@0: loggers with the same name share the same internal state (the "Borg"
michael@0: pattern). In particular the list of handlers functions is the same for
michael@0: all loggers with the same name.
michael@0: 
michael@0: Logging is threadsafe, with access to handlers protected by a
michael@0: ``threading.Lock``. However it is `not` process-safe. This means that
michael@0: applications using multiple processes, e.g. via the
michael@0: ``multiprocessing`` module, should arrange for all logging to happen in
michael@0: a single process.
michael@0: 
michael@0: Data Format
michael@0: -----------
michael@0: 
michael@0: Structured loggers produce messages in a simple format designed to be
michael@0: compatible with the JSON data model. Each message is a single object,
michael@0: with the type of message indicated by the ``action`` key. It is
michael@0: intended that the set of ``action`` values be closed; where there are
michael@0: use cases for additional values they should be integrated into this
michael@0: module rather than extended in an ad-hoc way. The set of keys present
michael@0: on on all messages is:
michael@0: 
michael@0: ``action``
michael@0:   The type of the message (string).
michael@0: 
michael@0: ``time``
michael@0:   The timestamp of the message in ms since the epoch (int).
michael@0: 
michael@0: ``thread``
michael@0:   The name of the thread emitting the message (string).
michael@0: 
michael@0: ``pid``
michael@0:   The pid of the process creating the message (int).
michael@0: 
michael@0: ``source``
michael@0:   Name of the logger creating the message (string).
michael@0: 
michael@0: For each ``action`` there are is a further set of specific fields
michael@0: describing the details of the event that caused the message to be
michael@0: emitted:
michael@0: 
michael@0: ``suite_start``
michael@0:   Emitted when the testsuite starts running.
michael@0: 
michael@0:   ``tests``
michael@0:     A list of test_ids (list).
michael@0: 
michael@0:   ``run_info``
michael@0:     An optional dictionary describing the properties of the
michael@0:     build and test environment. This contains the information provided
michael@0:     by :doc:`mozinfo <mozinfo>`, plus a boolean ``debug`` field indicating
michael@0:     whether the build under test is a debug build.
michael@0: 
michael@0: ``suite_end``
michael@0:   Emitted when the testsuite is finished and no more results will be produced.
michael@0: 
michael@0: ``test_start``
michael@0:   Emitted when a test is being started.
michael@0: 
michael@0:   ``test``
michael@0:     A unique id for the test (string or list of strings).
michael@0: 
michael@0: ``test_status``
michael@0:   Emitted for a test which has subtests to record the result of a
michael@0:   single subtest
michael@0: 
michael@0:   ``test``
michael@0:     The same unique id for the test as in the ``test_start`` message.
michael@0: 
michael@0:   ``subtest``
michael@0:     Name of the subtest (string).
michael@0: 
michael@0:   ``status``
michael@0:     Result of the test (string enum; ``PASS``, ``FAIL``, ``TIMEOUT``,
michael@0:     ``NOTRUN``)
michael@0: 
michael@0:   ``expected``
michael@0:     Expected result of the test. Omitted if the expected result is the
michael@0:     same as the actual result (string enum, same as ``status``).
michael@0: 
michael@0: ``test_end``
michael@0:   Emitted to give the result of a test with no subtests, or the status
michael@0:   of the overall file when there are subtests.
michael@0: 
michael@0:   ``test``
michael@0:     The same unique id for the test as in the ``test_start`` message.
michael@0: 
michael@0:   ``status``
michael@0:     Either result of the test (if there are no subtests) in which case
michael@0:     (string enum ``PASS``, ``FAIL``, ``TIMEOUT``, ``CRASH``,
michael@0:     ``ASSERT``, ``SKIP``) or the status of the overall file where
michael@0:     there are subtests (string enum ``OK``, ``ERROR``, ``TIMEOUT``,
michael@0:     ``CRASH``, ``ASSERT``, ``SKIP``).
michael@0: 
michael@0:   ``expected``
michael@0:     The expected status, or emitted if the expected status matches the
michael@0:     actual status (string enum, same as ``status``).
michael@0: 
michael@0: ``process_output``
michael@0:   Output from a managed subprocess.
michael@0: 
michael@0:   ``process``
michael@0:   pid of the subprocess.
michael@0: 
michael@0:   ``command``
michael@0:   Command used to launch the subprocess.
michael@0: 
michael@0:   ``data``
michael@0:   Data output by the subprocess.
michael@0: 
michael@0: ``log``
michael@0:   General human-readable logging message, used to debug the harnesses
michael@0:   themselves rather than to provide input to other tools.
michael@0: 
michael@0:   ``level``
michael@0:     Level of the log message (string enum ``CRITICAL``, ``ERROR``,
michael@0:     ``WARNING``, ``INFO``, ``DEBUG``).
michael@0: 
michael@0:   ``message``
michael@0:     Text of the log message.
michael@0: 
michael@0: StructuredLogger Objects
michael@0: ------------------------
michael@0: 
michael@0: .. automodule:: mozlog.structured.structuredlog
michael@0: 
michael@0: .. autoclass:: StructuredLogger
michael@0:    :members: add_handler, remove_handler, handlers, suite_start,
michael@0:              suite_end, test_start, test_status, test_end,
michael@0:              process_output, critical, error, warning, info, debug
michael@0: 
michael@0: .. autoclass:: StructuredLogFileLike
michael@0:   :members:
michael@0: 
michael@0: Handlers
michael@0: --------
michael@0: 
michael@0: A handler is a callable that is called for each log message produced
michael@0: and is responsible for handling the processing of that
michael@0: message. The typical example of this is a ``StreamHandler`` which takes
michael@0: a log message, invokes a formatter which converts the log to a string,
michael@0: and writes it to a file.
michael@0: 
michael@0: .. automodule:: mozlog.structured.handlers
michael@0: 
michael@0: .. autoclass:: StreamHandler
michael@0:   :members:
michael@0: 
michael@0: .. autoclass:: LogLevelFilter
michael@0:   :members:
michael@0: 
michael@0: Formatters
michael@0: ----------
michael@0: 
michael@0: Formatters are callables that take a log message, and return either a
michael@0: string representation of that message, or ``None`` if that message
michael@0: should not appear in the output. This allows formatters to both
michael@0: exclude certain items and create internal buffers of the output so
michael@0: that, for example, a single string might be returned for a
michael@0: ``test_end`` message indicating the overall result of the test,
michael@0: including data provided in the ``test_status`` messages.
michael@0: 
michael@0: Formatter modules are written so that they can take raw input on stdin
michael@0: and write formatted output on stdout. This allows the formatters to be
michael@0: invoked as part of a command line for post-processing raw log files.
michael@0: 
michael@0: .. automodule:: mozlog.structured.formatters.base
michael@0: 
michael@0: .. autoclass:: BaseFormatter
michael@0:   :members:
michael@0: 
michael@0: .. automodule:: mozlog.structured.formatters.unittest
michael@0: 
michael@0: .. autoclass:: UnittestFormatter
michael@0:   :members:
michael@0: 
michael@0: .. automodule:: mozlog.structured.formatters.xunit
michael@0: 
michael@0: .. autoclass:: XUnitFormatter
michael@0:   :members:
michael@0: 
michael@0: .. automodule:: mozlog.structured.formatters.html
michael@0: 
michael@0: .. autoclass:: HTMLFormatter
michael@0:   :members:
michael@0: 
michael@0: .. automodule:: mozlog.structured.formatters.machformatter
michael@0: 
michael@0: .. autoclass:: MachFormatter
michael@0:   :members:
michael@0: 
michael@0: .. autoclass:: MachTerminalFormatter
michael@0:   :members:
michael@0: 
michael@0: Processing Log Files
michael@0: --------------------
michael@0: 
michael@0: The ``mozlog.structured.reader`` module provides utilities for working
michael@0: with structured log files.
michael@0: 
michael@0: .. automodule:: mozlog.structured.reader
michael@0:   :members:
michael@0: 
michael@0: Integration with argparse
michael@0: -------------------------
michael@0: 
michael@0: The `mozlog.structured.commandline` module provides integration with
michael@0: the `argparse` module to provide uniform logging-related command line
michael@0: arguments to programs using `mozlog.structured`. Each known formatter
michael@0: gets a command line argument of the form ``--log-{name}``, which takes
michael@0: the name of a file to log to with that format of `-` to indicate stdout.
michael@0: 
michael@0: .. automodule:: mozlog.structured.commandline
michael@0:   :members:
michael@0: 
michael@0: Examples
michael@0: --------
michael@0: 
michael@0: Log to stdout::
michael@0: 
michael@0:     from mozlog.structured import structuredlog
michael@0:     from mozlog.structured import handlers, formatters
michael@0:     logger = structuredlog.StructuredLogger("my-test-suite")
michael@0:     logger.add_handler(handlers.StreamHandler(sys.stdout,
michael@0:                                               formatters.JSONFormatter()))
michael@0:     logger.suite_start(["test-id-1"])
michael@0:     logger.test_start("test-id-1")
michael@0:     logger.info("This is a message with action='LOG' and level='INFO'")
michael@0:     logger.test_status("test-id-1", "subtest-1", "PASS")
michael@0:     logger.test_end("test-id-1", "OK")
michael@0:     logger.suite_end()
michael@0: 
michael@0: 
michael@0: Populate an ``argparse.ArgumentParser`` with logging options, and
michael@0: create a logger based on the value of those options, defaulting to
michael@0: JSON output on stdout if nothing else is supplied::
michael@0: 
michael@0:    import argparse
michael@0:    from mozlog.structured import commandline
michael@0: 
michael@0:    parser = argparse.ArgumentParser()
michael@0:    # Here one would populate the parser with other options
michael@0:    commandline.add_logging_group(parser)
michael@0: 
michael@0:    args = parser.parse_args()
michael@0:    logger = commandline.setup_logging("testsuite-name", args, {"raw": sys.stdout})
michael@0: 
michael@0: Count the number of tests that timed out in a testsuite::
michael@0: 
michael@0:    from mozlog.structured import reader
michael@0: 
michael@0:    count = 0;
michael@0: 
michael@0:    def handle_test_end(data):
michael@0:        global count
michael@0:        if data["status"] == "TIMEOUT":
michael@0:            count += 1
michael@0: 
michael@0:    reader.each_log(reader.read("my_test_run.log"),
michael@0:                    {"test_end": handle_test_end})
michael@0: 
michael@0:    print count