Wed, 31 Dec 2014 06:09:35 +0100
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 |