|
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 |