testing/mozbase/docs/mozlog_structured.rst

Thu, 22 Jan 2015 13:21:57 +0100

author
Michael Schloh von Bennewitz <michael@schloh.com>
date
Thu, 22 Jan 2015 13:21:57 +0100
branch
TOR_BUG_9701
changeset 15
b8a032363ba2
permissions
-rw-r--r--

Incorporate requested changes from Mozilla in review:
https://bugzilla.mozilla.org/show_bug.cgi?id=1123480#c6

     1 :mod:`mozlog.structured` --- Structured logging for test output
     2 ===============================================================
     4 ``mozlog.structured`` is a library designed for logging the execution
     5 and results of test harnesses. The canonical output format is JSON,
     6 with one line of JSON per log entry. It is *not* based on the stdlib
     7 logging module, although it shares several concepts with this module.
     9 One notable difference between this module and the standard logging
    10 module is the way that loggers are created. The structured logging
    11 module does not require that loggers with a specific name are
    12 singleton objects accessed through a factory function. Instead the
    13 ``StructuredLogger`` constructor may be used directly. However all
    14 loggers with the same name share the same internal state (the "Borg"
    15 pattern). In particular the list of handlers functions is the same for
    16 all loggers with the same name.
    18 Logging is threadsafe, with access to handlers protected by a
    19 ``threading.Lock``. However it is `not` process-safe. This means that
    20 applications using multiple processes, e.g. via the
    21 ``multiprocessing`` module, should arrange for all logging to happen in
    22 a single process.
    24 Data Format
    25 -----------
    27 Structured loggers produce messages in a simple format designed to be
    28 compatible with the JSON data model. Each message is a single object,
    29 with the type of message indicated by the ``action`` key. It is
    30 intended that the set of ``action`` values be closed; where there are
    31 use cases for additional values they should be integrated into this
    32 module rather than extended in an ad-hoc way. The set of keys present
    33 on on all messages is:
    35 ``action``
    36   The type of the message (string).
    38 ``time``
    39   The timestamp of the message in ms since the epoch (int).
    41 ``thread``
    42   The name of the thread emitting the message (string).
    44 ``pid``
    45   The pid of the process creating the message (int).
    47 ``source``
    48   Name of the logger creating the message (string).
    50 For each ``action`` there are is a further set of specific fields
    51 describing the details of the event that caused the message to be
    52 emitted:
    54 ``suite_start``
    55   Emitted when the testsuite starts running.
    57   ``tests``
    58     A list of test_ids (list).
    60   ``run_info``
    61     An optional dictionary describing the properties of the
    62     build and test environment. This contains the information provided
    63     by :doc:`mozinfo <mozinfo>`, plus a boolean ``debug`` field indicating
    64     whether the build under test is a debug build.
    66 ``suite_end``
    67   Emitted when the testsuite is finished and no more results will be produced.
    69 ``test_start``
    70   Emitted when a test is being started.
    72   ``test``
    73     A unique id for the test (string or list of strings).
    75 ``test_status``
    76   Emitted for a test which has subtests to record the result of a
    77   single subtest
    79   ``test``
    80     The same unique id for the test as in the ``test_start`` message.
    82   ``subtest``
    83     Name of the subtest (string).
    85   ``status``
    86     Result of the test (string enum; ``PASS``, ``FAIL``, ``TIMEOUT``,
    87     ``NOTRUN``)
    89   ``expected``
    90     Expected result of the test. Omitted if the expected result is the
    91     same as the actual result (string enum, same as ``status``).
    93 ``test_end``
    94   Emitted to give the result of a test with no subtests, or the status
    95   of the overall file when there are subtests.
    97   ``test``
    98     The same unique id for the test as in the ``test_start`` message.
   100   ``status``
   101     Either result of the test (if there are no subtests) in which case
   102     (string enum ``PASS``, ``FAIL``, ``TIMEOUT``, ``CRASH``,
   103     ``ASSERT``, ``SKIP``) or the status of the overall file where
   104     there are subtests (string enum ``OK``, ``ERROR``, ``TIMEOUT``,
   105     ``CRASH``, ``ASSERT``, ``SKIP``).
   107   ``expected``
   108     The expected status, or emitted if the expected status matches the
   109     actual status (string enum, same as ``status``).
   111 ``process_output``
   112   Output from a managed subprocess.
   114   ``process``
   115   pid of the subprocess.
   117   ``command``
   118   Command used to launch the subprocess.
   120   ``data``
   121   Data output by the subprocess.
   123 ``log``
   124   General human-readable logging message, used to debug the harnesses
   125   themselves rather than to provide input to other tools.
   127   ``level``
   128     Level of the log message (string enum ``CRITICAL``, ``ERROR``,
   129     ``WARNING``, ``INFO``, ``DEBUG``).
   131   ``message``
   132     Text of the log message.
   134 StructuredLogger Objects
   135 ------------------------
   137 .. automodule:: mozlog.structured.structuredlog
   139 .. autoclass:: StructuredLogger
   140    :members: add_handler, remove_handler, handlers, suite_start,
   141              suite_end, test_start, test_status, test_end,
   142              process_output, critical, error, warning, info, debug
   144 .. autoclass:: StructuredLogFileLike
   145   :members:
   147 Handlers
   148 --------
   150 A handler is a callable that is called for each log message produced
   151 and is responsible for handling the processing of that
   152 message. The typical example of this is a ``StreamHandler`` which takes
   153 a log message, invokes a formatter which converts the log to a string,
   154 and writes it to a file.
   156 .. automodule:: mozlog.structured.handlers
   158 .. autoclass:: StreamHandler
   159   :members:
   161 .. autoclass:: LogLevelFilter
   162   :members:
   164 Formatters
   165 ----------
   167 Formatters are callables that take a log message, and return either a
   168 string representation of that message, or ``None`` if that message
   169 should not appear in the output. This allows formatters to both
   170 exclude certain items and create internal buffers of the output so
   171 that, for example, a single string might be returned for a
   172 ``test_end`` message indicating the overall result of the test,
   173 including data provided in the ``test_status`` messages.
   175 Formatter modules are written so that they can take raw input on stdin
   176 and write formatted output on stdout. This allows the formatters to be
   177 invoked as part of a command line for post-processing raw log files.
   179 .. automodule:: mozlog.structured.formatters.base
   181 .. autoclass:: BaseFormatter
   182   :members:
   184 .. automodule:: mozlog.structured.formatters.unittest
   186 .. autoclass:: UnittestFormatter
   187   :members:
   189 .. automodule:: mozlog.structured.formatters.xunit
   191 .. autoclass:: XUnitFormatter
   192   :members:
   194 .. automodule:: mozlog.structured.formatters.html
   196 .. autoclass:: HTMLFormatter
   197   :members:
   199 .. automodule:: mozlog.structured.formatters.machformatter
   201 .. autoclass:: MachFormatter
   202   :members:
   204 .. autoclass:: MachTerminalFormatter
   205   :members:
   207 Processing Log Files
   208 --------------------
   210 The ``mozlog.structured.reader`` module provides utilities for working
   211 with structured log files.
   213 .. automodule:: mozlog.structured.reader
   214   :members:
   216 Integration with argparse
   217 -------------------------
   219 The `mozlog.structured.commandline` module provides integration with
   220 the `argparse` module to provide uniform logging-related command line
   221 arguments to programs using `mozlog.structured`. Each known formatter
   222 gets a command line argument of the form ``--log-{name}``, which takes
   223 the name of a file to log to with that format of `-` to indicate stdout.
   225 .. automodule:: mozlog.structured.commandline
   226   :members:
   228 Examples
   229 --------
   231 Log to stdout::
   233     from mozlog.structured import structuredlog
   234     from mozlog.structured import handlers, formatters
   235     logger = structuredlog.StructuredLogger("my-test-suite")
   236     logger.add_handler(handlers.StreamHandler(sys.stdout,
   237                                               formatters.JSONFormatter()))
   238     logger.suite_start(["test-id-1"])
   239     logger.test_start("test-id-1")
   240     logger.info("This is a message with action='LOG' and level='INFO'")
   241     logger.test_status("test-id-1", "subtest-1", "PASS")
   242     logger.test_end("test-id-1", "OK")
   243     logger.suite_end()
   246 Populate an ``argparse.ArgumentParser`` with logging options, and
   247 create a logger based on the value of those options, defaulting to
   248 JSON output on stdout if nothing else is supplied::
   250    import argparse
   251    from mozlog.structured import commandline
   253    parser = argparse.ArgumentParser()
   254    # Here one would populate the parser with other options
   255    commandline.add_logging_group(parser)
   257    args = parser.parse_args()
   258    logger = commandline.setup_logging("testsuite-name", args, {"raw": sys.stdout})
   260 Count the number of tests that timed out in a testsuite::
   262    from mozlog.structured import reader
   264    count = 0;
   266    def handle_test_end(data):
   267        global count
   268        if data["status"] == "TIMEOUT":
   269            count += 1
   271    reader.each_log(reader.read("my_test_run.log"),
   272                    {"test_end": handle_test_end})
   274    print count

mercurial