testing/mozbase/docs/mozlog_structured.rst

changeset 0
6474c204b198
equal deleted inserted replaced
-1:000000000000 0:042cc8063120
1 :mod:`mozlog.structured` --- Structured logging for test output
2 ===============================================================
3
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.
8
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.
17
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.
23
24 Data Format
25 -----------
26
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:
34
35 ``action``
36 The type of the message (string).
37
38 ``time``
39 The timestamp of the message in ms since the epoch (int).
40
41 ``thread``
42 The name of the thread emitting the message (string).
43
44 ``pid``
45 The pid of the process creating the message (int).
46
47 ``source``
48 Name of the logger creating the message (string).
49
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:
53
54 ``suite_start``
55 Emitted when the testsuite starts running.
56
57 ``tests``
58 A list of test_ids (list).
59
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.
65
66 ``suite_end``
67 Emitted when the testsuite is finished and no more results will be produced.
68
69 ``test_start``
70 Emitted when a test is being started.
71
72 ``test``
73 A unique id for the test (string or list of strings).
74
75 ``test_status``
76 Emitted for a test which has subtests to record the result of a
77 single subtest
78
79 ``test``
80 The same unique id for the test as in the ``test_start`` message.
81
82 ``subtest``
83 Name of the subtest (string).
84
85 ``status``
86 Result of the test (string enum; ``PASS``, ``FAIL``, ``TIMEOUT``,
87 ``NOTRUN``)
88
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``).
92
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.
96
97 ``test``
98 The same unique id for the test as in the ``test_start`` message.
99
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``).
106
107 ``expected``
108 The expected status, or emitted if the expected status matches the
109 actual status (string enum, same as ``status``).
110
111 ``process_output``
112 Output from a managed subprocess.
113
114 ``process``
115 pid of the subprocess.
116
117 ``command``
118 Command used to launch the subprocess.
119
120 ``data``
121 Data output by the subprocess.
122
123 ``log``
124 General human-readable logging message, used to debug the harnesses
125 themselves rather than to provide input to other tools.
126
127 ``level``
128 Level of the log message (string enum ``CRITICAL``, ``ERROR``,
129 ``WARNING``, ``INFO``, ``DEBUG``).
130
131 ``message``
132 Text of the log message.
133
134 StructuredLogger Objects
135 ------------------------
136
137 .. automodule:: mozlog.structured.structuredlog
138
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
143
144 .. autoclass:: StructuredLogFileLike
145 :members:
146
147 Handlers
148 --------
149
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.
155
156 .. automodule:: mozlog.structured.handlers
157
158 .. autoclass:: StreamHandler
159 :members:
160
161 .. autoclass:: LogLevelFilter
162 :members:
163
164 Formatters
165 ----------
166
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.
174
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.
178
179 .. automodule:: mozlog.structured.formatters.base
180
181 .. autoclass:: BaseFormatter
182 :members:
183
184 .. automodule:: mozlog.structured.formatters.unittest
185
186 .. autoclass:: UnittestFormatter
187 :members:
188
189 .. automodule:: mozlog.structured.formatters.xunit
190
191 .. autoclass:: XUnitFormatter
192 :members:
193
194 .. automodule:: mozlog.structured.formatters.html
195
196 .. autoclass:: HTMLFormatter
197 :members:
198
199 .. automodule:: mozlog.structured.formatters.machformatter
200
201 .. autoclass:: MachFormatter
202 :members:
203
204 .. autoclass:: MachTerminalFormatter
205 :members:
206
207 Processing Log Files
208 --------------------
209
210 The ``mozlog.structured.reader`` module provides utilities for working
211 with structured log files.
212
213 .. automodule:: mozlog.structured.reader
214 :members:
215
216 Integration with argparse
217 -------------------------
218
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.
224
225 .. automodule:: mozlog.structured.commandline
226 :members:
227
228 Examples
229 --------
230
231 Log to stdout::
232
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()
244
245
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::
249
250 import argparse
251 from mozlog.structured import commandline
252
253 parser = argparse.ArgumentParser()
254 # Here one would populate the parser with other options
255 commandline.add_logging_group(parser)
256
257 args = parser.parse_args()
258 logger = commandline.setup_logging("testsuite-name", args, {"raw": sys.stdout})
259
260 Count the number of tests that timed out in a testsuite::
261
262 from mozlog.structured import reader
263
264 count = 0;
265
266 def handle_test_end(data):
267 global count
268 if data["status"] == "TIMEOUT":
269 count += 1
270
271 reader.each_log(reader.read("my_test_run.log"),
272 {"test_end": handle_test_end})
273
274 print count

mercurial