1.1 --- /dev/null Thu Jan 01 00:00:00 1970 +0000
1.2 +++ b/testing/mozbase/docs/mozlog_structured.rst Wed Dec 31 06:09:35 2014 +0100
1.3 @@ -0,0 +1,274 @@
1.4 +:mod:`mozlog.structured` --- Structured logging for test output
1.5 +===============================================================
1.6 +
1.7 +``mozlog.structured`` is a library designed for logging the execution
1.8 +and results of test harnesses. The canonical output format is JSON,
1.9 +with one line of JSON per log entry. It is *not* based on the stdlib
1.10 +logging module, although it shares several concepts with this module.
1.11 +
1.12 +One notable difference between this module and the standard logging
1.13 +module is the way that loggers are created. The structured logging
1.14 +module does not require that loggers with a specific name are
1.15 +singleton objects accessed through a factory function. Instead the
1.16 +``StructuredLogger`` constructor may be used directly. However all
1.17 +loggers with the same name share the same internal state (the "Borg"
1.18 +pattern). In particular the list of handlers functions is the same for
1.19 +all loggers with the same name.
1.20 +
1.21 +Logging is threadsafe, with access to handlers protected by a
1.22 +``threading.Lock``. However it is `not` process-safe. This means that
1.23 +applications using multiple processes, e.g. via the
1.24 +``multiprocessing`` module, should arrange for all logging to happen in
1.25 +a single process.
1.26 +
1.27 +Data Format
1.28 +-----------
1.29 +
1.30 +Structured loggers produce messages in a simple format designed to be
1.31 +compatible with the JSON data model. Each message is a single object,
1.32 +with the type of message indicated by the ``action`` key. It is
1.33 +intended that the set of ``action`` values be closed; where there are
1.34 +use cases for additional values they should be integrated into this
1.35 +module rather than extended in an ad-hoc way. The set of keys present
1.36 +on on all messages is:
1.37 +
1.38 +``action``
1.39 + The type of the message (string).
1.40 +
1.41 +``time``
1.42 + The timestamp of the message in ms since the epoch (int).
1.43 +
1.44 +``thread``
1.45 + The name of the thread emitting the message (string).
1.46 +
1.47 +``pid``
1.48 + The pid of the process creating the message (int).
1.49 +
1.50 +``source``
1.51 + Name of the logger creating the message (string).
1.52 +
1.53 +For each ``action`` there are is a further set of specific fields
1.54 +describing the details of the event that caused the message to be
1.55 +emitted:
1.56 +
1.57 +``suite_start``
1.58 + Emitted when the testsuite starts running.
1.59 +
1.60 + ``tests``
1.61 + A list of test_ids (list).
1.62 +
1.63 + ``run_info``
1.64 + An optional dictionary describing the properties of the
1.65 + build and test environment. This contains the information provided
1.66 + by :doc:`mozinfo <mozinfo>`, plus a boolean ``debug`` field indicating
1.67 + whether the build under test is a debug build.
1.68 +
1.69 +``suite_end``
1.70 + Emitted when the testsuite is finished and no more results will be produced.
1.71 +
1.72 +``test_start``
1.73 + Emitted when a test is being started.
1.74 +
1.75 + ``test``
1.76 + A unique id for the test (string or list of strings).
1.77 +
1.78 +``test_status``
1.79 + Emitted for a test which has subtests to record the result of a
1.80 + single subtest
1.81 +
1.82 + ``test``
1.83 + The same unique id for the test as in the ``test_start`` message.
1.84 +
1.85 + ``subtest``
1.86 + Name of the subtest (string).
1.87 +
1.88 + ``status``
1.89 + Result of the test (string enum; ``PASS``, ``FAIL``, ``TIMEOUT``,
1.90 + ``NOTRUN``)
1.91 +
1.92 + ``expected``
1.93 + Expected result of the test. Omitted if the expected result is the
1.94 + same as the actual result (string enum, same as ``status``).
1.95 +
1.96 +``test_end``
1.97 + Emitted to give the result of a test with no subtests, or the status
1.98 + of the overall file when there are subtests.
1.99 +
1.100 + ``test``
1.101 + The same unique id for the test as in the ``test_start`` message.
1.102 +
1.103 + ``status``
1.104 + Either result of the test (if there are no subtests) in which case
1.105 + (string enum ``PASS``, ``FAIL``, ``TIMEOUT``, ``CRASH``,
1.106 + ``ASSERT``, ``SKIP``) or the status of the overall file where
1.107 + there are subtests (string enum ``OK``, ``ERROR``, ``TIMEOUT``,
1.108 + ``CRASH``, ``ASSERT``, ``SKIP``).
1.109 +
1.110 + ``expected``
1.111 + The expected status, or emitted if the expected status matches the
1.112 + actual status (string enum, same as ``status``).
1.113 +
1.114 +``process_output``
1.115 + Output from a managed subprocess.
1.116 +
1.117 + ``process``
1.118 + pid of the subprocess.
1.119 +
1.120 + ``command``
1.121 + Command used to launch the subprocess.
1.122 +
1.123 + ``data``
1.124 + Data output by the subprocess.
1.125 +
1.126 +``log``
1.127 + General human-readable logging message, used to debug the harnesses
1.128 + themselves rather than to provide input to other tools.
1.129 +
1.130 + ``level``
1.131 + Level of the log message (string enum ``CRITICAL``, ``ERROR``,
1.132 + ``WARNING``, ``INFO``, ``DEBUG``).
1.133 +
1.134 + ``message``
1.135 + Text of the log message.
1.136 +
1.137 +StructuredLogger Objects
1.138 +------------------------
1.139 +
1.140 +.. automodule:: mozlog.structured.structuredlog
1.141 +
1.142 +.. autoclass:: StructuredLogger
1.143 + :members: add_handler, remove_handler, handlers, suite_start,
1.144 + suite_end, test_start, test_status, test_end,
1.145 + process_output, critical, error, warning, info, debug
1.146 +
1.147 +.. autoclass:: StructuredLogFileLike
1.148 + :members:
1.149 +
1.150 +Handlers
1.151 +--------
1.152 +
1.153 +A handler is a callable that is called for each log message produced
1.154 +and is responsible for handling the processing of that
1.155 +message. The typical example of this is a ``StreamHandler`` which takes
1.156 +a log message, invokes a formatter which converts the log to a string,
1.157 +and writes it to a file.
1.158 +
1.159 +.. automodule:: mozlog.structured.handlers
1.160 +
1.161 +.. autoclass:: StreamHandler
1.162 + :members:
1.163 +
1.164 +.. autoclass:: LogLevelFilter
1.165 + :members:
1.166 +
1.167 +Formatters
1.168 +----------
1.169 +
1.170 +Formatters are callables that take a log message, and return either a
1.171 +string representation of that message, or ``None`` if that message
1.172 +should not appear in the output. This allows formatters to both
1.173 +exclude certain items and create internal buffers of the output so
1.174 +that, for example, a single string might be returned for a
1.175 +``test_end`` message indicating the overall result of the test,
1.176 +including data provided in the ``test_status`` messages.
1.177 +
1.178 +Formatter modules are written so that they can take raw input on stdin
1.179 +and write formatted output on stdout. This allows the formatters to be
1.180 +invoked as part of a command line for post-processing raw log files.
1.181 +
1.182 +.. automodule:: mozlog.structured.formatters.base
1.183 +
1.184 +.. autoclass:: BaseFormatter
1.185 + :members:
1.186 +
1.187 +.. automodule:: mozlog.structured.formatters.unittest
1.188 +
1.189 +.. autoclass:: UnittestFormatter
1.190 + :members:
1.191 +
1.192 +.. automodule:: mozlog.structured.formatters.xunit
1.193 +
1.194 +.. autoclass:: XUnitFormatter
1.195 + :members:
1.196 +
1.197 +.. automodule:: mozlog.structured.formatters.html
1.198 +
1.199 +.. autoclass:: HTMLFormatter
1.200 + :members:
1.201 +
1.202 +.. automodule:: mozlog.structured.formatters.machformatter
1.203 +
1.204 +.. autoclass:: MachFormatter
1.205 + :members:
1.206 +
1.207 +.. autoclass:: MachTerminalFormatter
1.208 + :members:
1.209 +
1.210 +Processing Log Files
1.211 +--------------------
1.212 +
1.213 +The ``mozlog.structured.reader`` module provides utilities for working
1.214 +with structured log files.
1.215 +
1.216 +.. automodule:: mozlog.structured.reader
1.217 + :members:
1.218 +
1.219 +Integration with argparse
1.220 +-------------------------
1.221 +
1.222 +The `mozlog.structured.commandline` module provides integration with
1.223 +the `argparse` module to provide uniform logging-related command line
1.224 +arguments to programs using `mozlog.structured`. Each known formatter
1.225 +gets a command line argument of the form ``--log-{name}``, which takes
1.226 +the name of a file to log to with that format of `-` to indicate stdout.
1.227 +
1.228 +.. automodule:: mozlog.structured.commandline
1.229 + :members:
1.230 +
1.231 +Examples
1.232 +--------
1.233 +
1.234 +Log to stdout::
1.235 +
1.236 + from mozlog.structured import structuredlog
1.237 + from mozlog.structured import handlers, formatters
1.238 + logger = structuredlog.StructuredLogger("my-test-suite")
1.239 + logger.add_handler(handlers.StreamHandler(sys.stdout,
1.240 + formatters.JSONFormatter()))
1.241 + logger.suite_start(["test-id-1"])
1.242 + logger.test_start("test-id-1")
1.243 + logger.info("This is a message with action='LOG' and level='INFO'")
1.244 + logger.test_status("test-id-1", "subtest-1", "PASS")
1.245 + logger.test_end("test-id-1", "OK")
1.246 + logger.suite_end()
1.247 +
1.248 +
1.249 +Populate an ``argparse.ArgumentParser`` with logging options, and
1.250 +create a logger based on the value of those options, defaulting to
1.251 +JSON output on stdout if nothing else is supplied::
1.252 +
1.253 + import argparse
1.254 + from mozlog.structured import commandline
1.255 +
1.256 + parser = argparse.ArgumentParser()
1.257 + # Here one would populate the parser with other options
1.258 + commandline.add_logging_group(parser)
1.259 +
1.260 + args = parser.parse_args()
1.261 + logger = commandline.setup_logging("testsuite-name", args, {"raw": sys.stdout})
1.262 +
1.263 +Count the number of tests that timed out in a testsuite::
1.264 +
1.265 + from mozlog.structured import reader
1.266 +
1.267 + count = 0;
1.268 +
1.269 + def handle_test_end(data):
1.270 + global count
1.271 + if data["status"] == "TIMEOUT":
1.272 + count += 1
1.273 +
1.274 + reader.each_log(reader.read("my_test_run.log"),
1.275 + {"test_end": handle_test_end})
1.276 +
1.277 + print count
