testing/mozbase/docs/mozlog_structured.rst

Wed, 31 Dec 2014 06:09:35 +0100

author
Michael Schloh von Bennewitz <michael@schloh.com>
date
Wed, 31 Dec 2014 06:09:35 +0100
changeset 0
6474c204b198
permissions
-rw-r--r--

Cloned upstream origin tor-browser at tor-browser-31.3.0esr-4.5-1-build1
revision ID fc1c9ff7c1b2defdbc039f12214767608f46423f for hacking purpose.

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

mercurial