Source code

Revision control

Other Tools

1
# This Source Code Form is subject to the terms of the Mozilla Public
2
# License, v. 2.0. If a copy of the MPL was not distributed with this
3
# file, You can obtain one at http://mozilla.org/MPL/2.0/.
4
5
from __future__ import absolute_import, print_function, unicode_literals
6
7
from multiprocessing import current_process
8
from threading import current_thread, Lock
9
import json
10
import sys
11
import time
12
import traceback
13
14
from .logtypes import (Unicode, TestId, TestList, Status, SubStatus, Dict, List, Int, Any, Tuple,
15
Boolean, Nullable)
16
from .logtypes import log_action, convertor_registry
17
import six
18
19
"""Structured Logging for recording test results.
20
21
Allowed actions, and subfields:
22
suite_start
23
tests - List of test names
24
name - Name for the suite
25
26
suite_end
27
28
test_start
29
test - ID for the test
30
path - Relative path to test (optional)
31
32
test_end
33
test - ID for the test
34
status [PASS | FAIL | OK | ERROR | TIMEOUT | CRASH |
35
ASSERT PRECONDITION_FAILED | SKIP] - test status
36
expected [As for status] - Status that the test was expected to get,
37
or absent if the test got the expected status
38
extra - Dictionary of harness-specific extra information e.g. debug info
39
known_intermittent - List of known intermittent statuses that should
40
not fail a test. eg. ['FAIL', 'TIMEOUT']
41
42
test_status
43
test - ID for the test
44
subtest - Name of the subtest
45
status [PASS | FAIL | TIMEOUT |
46
PRECONDITION_FAILED | NOTRUN | SKIP] - test status
47
expected [As for status] - Status that the subtest was expected to get,
48
or absent if the subtest got the expected status
49
known_intermittent - List of known intermittent statuses that should
50
not fail a test. eg. ['FAIL', 'TIMEOUT']
51
52
process_output
53
process - PID of the process
54
command - Command line of the process
55
data - Output data from the process
56
57
assertion_count
58
count - Number of assertions produced
59
min_expected - Minimum expected number of assertions
60
max_expected - Maximum expected number of assertions
61
62
lsan_leak
63
frames - List of stack frames from the leak report
64
scope - An identifier for the set of tests run during the browser session
65
(e.g. a directory name)
66
allowed_match - A stack frame in the list that matched a rule meaning the
67
leak is expected
68
69
lsan_summary
70
bytes - Number of bytes leaked
71
allocations - Number of allocations
72
allowed - Boolean indicating whether all detected leaks matched allow rules
73
74
mozleak_object
75
process - Process that leaked
76
bytes - Number of bytes that leaked
77
name - Name of the object that leaked
78
scope - An identifier for the set of tests run during the browser session
79
(e.g. a directory name)
80
allowed - Boolean indicating whether the leak was permitted
81
82
log
83
level [CRITICAL | ERROR | WARNING |
84
INFO | DEBUG] - level of the logging message
85
message - Message to log
86
87
Subfields for all messages:
88
action - the action type of the current message
89
time - the timestamp in ms since the epoch of the log message
90
thread - name for the thread emitting the message
91
pid - id of the python process in which the logger is running
92
source - name for the source emitting the message
93
component - name of the subcomponent emitting the message
94
"""
95
96
_default_logger_name = None
97
98
99
def get_default_logger(component=None):
100
"""Gets the default logger if available, optionally tagged with component
101
name. Will return None if not yet set
102
103
:param component: The component name to tag log messages with
104
"""
105
global _default_logger_name
106
107
if not _default_logger_name:
108
return None
109
110
return StructuredLogger(_default_logger_name, component=component)
111
112
113
def set_default_logger(default_logger):
114
"""Sets the default logger to logger.
115
116
It can then be retrieved with :py:func:`get_default_logger`
117
118
Note that :py:func:`~mozlog.commandline.setup_logging` will
119
set a default logger for you, so there should be no need to call this
120
function if you're using setting up logging that way (recommended).
121
122
:param default_logger: The logger to set to default.
123
"""
124
global _default_logger_name
125
126
_default_logger_name = default_logger.name
127
128
129
log_levels = dict((k.upper(), v) for v, k in
130
enumerate(["critical", "error", "warning", "info", "debug"]))
131
132
lint_levels = ["ERROR", "WARNING"]
133
134
135
def log_actions():
136
"""Returns the set of actions implemented by mozlog."""
137
return set(convertor_registry.keys())
138
139
140
class LoggerShutdownError(Exception):
141
"""Raised when attempting to log after logger.shutdown() has been called."""
142
143
144
class LoggerState(object):
145
146
def __init__(self):
147
self.reset()
148
149
def reset(self):
150
self.handlers = []
151
self.running_tests = set()
152
self.suite_started = False
153
self.component_states = {}
154
self.has_shutdown = False
155
156
157
class ComponentState(object):
158
159
def __init__(self):
160
self.filter_ = None
161
162
163
class StructuredLogger(object):
164
_lock = Lock()
165
_logger_states = {}
166
"""Create a structured logger with the given name
167
168
:param name: The name of the logger.
169
:param component: A subcomponent that the logger belongs to (typically a library name)
170
"""
171
172
def __init__(self, name, component=None):
173
self.name = name
174
self.component = component
175
176
with self._lock:
177
if name not in self._logger_states:
178
self._logger_states[name] = LoggerState()
179
180
if component not in self._logger_states[name].component_states:
181
self._logger_states[name].component_states[component] = ComponentState()
182
183
self._state = self._logger_states[name]
184
self._component_state = self._state.component_states[component]
185
186
def add_handler(self, handler):
187
"""Add a handler to the current logger"""
188
self._state.handlers.append(handler)
189
190
def remove_handler(self, handler):
191
"""Remove a handler from the current logger"""
192
self._state.handlers.remove(handler)
193
194
def reset_state(self):
195
"""Resets the logger to a brand new state. This means all handlers
196
are removed, running tests are discarded and components are reset.
197
"""
198
self._state.reset()
199
self._component_state = self._state.component_states[self.component] = ComponentState()
200
201
def send_message(self, topic, command, *args):
202
"""Send a message to each handler configured for this logger. This
203
part of the api is useful to those users requiring dynamic control
204
of a handler's behavior.
205
206
:param topic: The name used by handlers to subscribe to a message.
207
:param command: The name of the command to issue.
208
:param args: Any arguments known to the target for specialized
209
behavior.
210
"""
211
rv = []
212
for handler in self._state.handlers:
213
if hasattr(handler, "message_handler"):
214
rv += handler.message_handler.handle_message(topic, command, *args)
215
return rv
216
217
@property
218
def handlers(self):
219
"""A list of handlers that will be called when a
220
message is logged from this logger"""
221
return self._state.handlers
222
223
@property
224
def component_filter(self):
225
return self._component_state.filter_
226
227
@component_filter.setter
228
def component_filter(self, value):
229
self._component_state.filter_ = value
230
231
def log_raw(self, raw_data):
232
if "action" not in raw_data:
233
raise ValueError
234
235
action = raw_data["action"]
236
converted_data = convertor_registry[action].convert_known(**raw_data)
237
for k, v in six.iteritems(raw_data):
238
if (k not in converted_data and
239
k not in convertor_registry[action].optional_args):
240
converted_data[k] = v
241
242
data = self._make_log_data(action, converted_data)
243
244
if action in ("test_status", "test_end"):
245
if (data["expected"] == data["status"] or
246
data["status"] == "SKIP" or
247
"expected" not in raw_data):
248
del data["expected"]
249
250
if not self._ensure_suite_state(action, data):
251
return
252
253
self._handle_log(data)
254
255
def _log_data(self, action, data=None):
256
if data is None:
257
data = {}
258
259
log_data = self._make_log_data(action, data)
260
self._handle_log(log_data)
261
262
def _handle_log(self, data):
263
if self._state.has_shutdown:
264
raise LoggerShutdownError("{} action received after shutdown.".format(data['action']))
265
266
with self._lock:
267
if self.component_filter:
268
data = self.component_filter(data)
269
if data is None:
270
return
271
272
for handler in self.handlers:
273
try:
274
handler(data)
275
except Exception:
276
# Write the exception details directly to stderr because
277
# log() would call this method again which is currently locked.
278
print('%s: Failure calling log handler:' % __name__, file=sys.__stderr__)
279
print(traceback.format_exc(), file=sys.__stderr__)
280
281
def _make_log_data(self, action, data):
282
all_data = {"action": action,
283
"time": int(time.time() * 1000),
284
"thread": current_thread().name,
285
"pid": current_process().pid,
286
"source": self.name}
287
if self.component:
288
all_data['component'] = self.component
289
all_data.update(data)
290
return all_data
291
292
def _ensure_suite_state(self, action, data):
293
if action == 'suite_start':
294
if self._state.suite_started:
295
# limit data to reduce unnecessary log bloat
296
self.error("Got second suite_start message before suite_end. " +
297
"Logged with data: {}".format(json.dumps(data)[:100]))
298
return False
299
self._state.suite_started = True
300
elif action == 'suite_end':
301
if not self._state.suite_started:
302
self.error("Got suite_end message before suite_start. " +
303
"Logged with data: {}".format(json.dumps(data)))
304
return False
305
self._state.suite_started = False
306
return True
307
308
@log_action(TestList("tests"),
309
Unicode("name", default=None, optional=True),
310
Dict(Any, "run_info", default=None, optional=True),
311
Dict(Any, "version_info", default=None, optional=True),
312
Dict(Any, "device_info", default=None, optional=True),
313
Dict(Any, "extra", default=None, optional=True))
314
def suite_start(self, data):
315
"""Log a suite_start message
316
317
:param dict tests: Test identifiers that will be run in the suite, keyed by group name.
318
:param str name: Optional name to identify the suite.
319
:param dict run_info: Optional information typically provided by mozinfo.
320
:param dict version_info: Optional target application version information provided
321
by mozversion.
322
:param dict device_info: Optional target device information provided by mozdevice.
323
"""
324
if not self._ensure_suite_state('suite_start', data):
325
return
326
327
self._log_data("suite_start", data)
328
329
@log_action(Dict(Any, "extra", default=None, optional=True))
330
def suite_end(self, data):
331
"""Log a suite_end message"""
332
if not self._ensure_suite_state('suite_end', data):
333
return
334
335
self._log_data("suite_end", data)
336
337
@log_action(TestId("test"),
338
Unicode("path", default=None, optional=True))
339
def test_start(self, data):
340
"""Log a test_start message
341
342
:param test: Identifier of the test that will run.
343
:param path: Path to test relative to some base (typically the root of
344
the source tree).
345
"""
346
if not self._state.suite_started:
347
self.error("Got test_start message before suite_start for test %s" %
348
data["test"])
349
return
350
if data["test"] in self._state.running_tests:
351
self.error("test_start for %s logged while in progress." %
352
data["test"])
353
return
354
self._state.running_tests.add(data["test"])
355
self._log_data("test_start", data)
356
357
@log_action(TestId("test"),
358
Unicode("subtest"),
359
SubStatus("status"),
360
SubStatus("expected", default="PASS"),
361
Unicode("message", default=None, optional=True),
362
Unicode("stack", default=None, optional=True),
363
Dict(Any, "extra", default=None, optional=True),
364
List(SubStatus, "known_intermittent", default=None,
365
optional=True))
366
def test_status(self, data):
367
"""
368
Log a test_status message indicating a subtest result. Tests that
369
do not have subtests are not expected to produce test_status messages.
370
371
:param test: Identifier of the test that produced the result.
372
:param subtest: Name of the subtest.
373
:param status: Status string indicating the subtest result
374
:param expected: Status string indicating the expected subtest result.
375
:param message: String containing a message associated with the result.
376
:param stack: a stack trace encountered during test execution.
377
:param extra: suite-specific data associated with the test result.
378
"""
379
380
if (data["expected"] == data["status"] or
381
data["status"] == "SKIP"):
382
del data["expected"]
383
384
if data["test"] not in self._state.running_tests:
385
self.error("test_status for %s logged while not in progress. "
386
"Logged with data: %s" % (data["test"], json.dumps(data)))
387
return
388
389
self._log_data("test_status", data)
390
391
@log_action(TestId("test"),
392
Status("status"),
393
Status("expected", default="OK"),
394
Unicode("message", default=None, optional=True),
395
Unicode("stack", default=None, optional=True),
396
Dict(Any, "extra", default=None, optional=True),
397
List(Status, "known_intermittent", default=None,
398
optional=True))
399
def test_end(self, data):
400
"""
401
Log a test_end message indicating that a test completed. For tests
402
with subtests this indicates whether the overall test completed without
403
errors. For tests without subtests this indicates the test result
404
directly.
405
406
:param test: Identifier of the test that produced the result.
407
:param status: Status string indicating the test result
408
:param expected: Status string indicating the expected test result.
409
:param message: String containing a message associated with the result.
410
:param stack: a stack trace encountered during test execution.
411
:param extra: suite-specific data associated with the test result.
412
"""
413
414
if (data["expected"] == data["status"] or
415
data["status"] == "SKIP"):
416
del data["expected"]
417
418
if data["test"] not in self._state.running_tests:
419
self.error("test_end for %s logged while not in progress. "
420
"Logged with data: %s" % (data["test"], json.dumps(data)))
421
else:
422
self._state.running_tests.remove(data["test"])
423
self._log_data("test_end", data)
424
425
@log_action(Unicode("process"),
426
Unicode("data"),
427
Unicode("command", default=None, optional=True))
428
def process_output(self, data):
429
"""Log output from a managed process.
430
431
:param process: A unique identifier for the process producing the output
432
(typically the pid)
433
:param data: The output to log
434
:param command: A string representing the full command line used to start
435
the process.
436
"""
437
self._log_data("process_output", data)
438
439
@log_action(Unicode("process", default=None),
440
Unicode("signature", default="[Unknown]"),
441
TestId("test", default=None, optional=True),
442
Unicode("minidump_path", default=None, optional=True),
443
Unicode("minidump_extra", default=None, optional=True),
444
Int("stackwalk_retcode", default=None, optional=True),
445
Unicode("stackwalk_stdout", default=None, optional=True),
446
Unicode("stackwalk_stderr", default=None, optional=True),
447
List(Unicode, "stackwalk_errors", default=None))
448
def crash(self, data):
449
if data["stackwalk_errors"] is None:
450
data["stackwalk_errors"] = []
451
452
self._log_data("crash", data)
453
454
@log_action(Unicode("primary", default=None),
455
List(Unicode, "secondary", default=None))
456
def valgrind_error(self, data):
457
self._log_data("valgrind_error", data)
458
459
@log_action(Unicode("process"),
460
Unicode("command", default=None, optional=True))
461
def process_start(self, data):
462
"""Log start event of a process.
463
464
:param process: A unique identifier for the process producing the
465
output (typically the pid)
466
:param command: A string representing the full command line used to
467
start the process.
468
"""
469
self._log_data("process_start", data)
470
471
@log_action(Unicode("process"),
472
Int("exitcode"),
473
Unicode("command", default=None, optional=True))
474
def process_exit(self, data):
475
"""Log exit event of a process.
476
477
:param process: A unique identifier for the process producing the
478
output (typically the pid)
479
:param exitcode: the exit code
480
:param command: A string representing the full command line used to
481
start the process.
482
"""
483
self._log_data("process_exit", data)
484
485
@log_action(TestId("test"),
486
Int("count"),
487
Int("min_expected"),
488
Int("max_expected"))
489
def assertion_count(self, data):
490
"""Log count of assertions produced when running a test.
491
492
:param count: - Number of assertions produced
493
:param min_expected: - Minimum expected number of assertions
494
:param max_expected: - Maximum expected number of assertions
495
"""
496
self._log_data("assertion_count", data)
497
498
@log_action(List(Unicode, "frames"),
499
Unicode("scope", optional=True, default=None),
500
Unicode("allowed_match", optional=True, default=None))
501
def lsan_leak(self, data):
502
self._log_data("lsan_leak", data)
503
504
@log_action(Int("bytes"),
505
Int("allocations"),
506
Boolean("allowed", optional=True, default=False))
507
def lsan_summary(self, data):
508
self._log_data("lsan_summary", data)
509
510
@log_action(Unicode("process"),
511
Int("bytes"),
512
Unicode("name"),
513
Unicode("scope", optional=True, default=None),
514
Boolean("allowed", optional=True, default=False))
515
def mozleak_object(self, data):
516
self._log_data("mozleak_object", data)
517
518
@log_action(Unicode("process"),
519
Nullable(Int, "bytes"),
520
Int("threshold"),
521
List(Unicode, "objects"),
522
Unicode("scope", optional=True, default=None),
523
Boolean("induced_crash", optional=True, default=False),
524
Boolean("ignore_missing", optional=True, default=False))
525
def mozleak_total(self, data):
526
self._log_data("mozleak_total", data)
527
528
@log_action()
529
def shutdown(self, data):
530
"""Shutdown the logger.
531
532
This logs a 'shutdown' action after which any further attempts to use
533
the logger will raise a :exc:`LoggerShutdownError`.
534
535
This is also called implicitly from the destructor or
536
when exiting the context manager.
537
"""
538
self._log_data('shutdown', data)
539
self._state.has_shutdown = True
540
541
def __enter__(self):
542
return self
543
544
def __exit__(self, exc, val, tb):
545
self.shutdown()
546
547
548
def _log_func(level_name):
549
@log_action(Unicode("message"),
550
Any("exc_info", default=False))
551
def log(self, data):
552
exc_info = data.pop("exc_info", None)
553
if exc_info:
554
if not isinstance(exc_info, tuple):
555
exc_info = sys.exc_info()
556
if exc_info != (None, None, None):
557
bt = traceback.format_exception(*exc_info)
558
data["stack"] = u"\n".join(bt)
559
560
data["level"] = level_name
561
self._log_data("log", data)
562
563
log.__doc__ = """Log a message with level %s
564
565
:param message: The string message to log
566
:param exc_info: Either a boolean indicating whether to include a traceback
567
derived from sys.exc_info() or a three-item tuple in the
568
same format as sys.exc_info() containing exception information
569
to log.
570
""" % level_name
571
log.__name__ = str(level_name).lower()
572
return log
573
574
575
def _lint_func(level_name):
576
@log_action(Unicode("path"),
577
Unicode("message", default=""),
578
Int("lineno", default=0),
579
Int("column", default=None, optional=True),
580
Unicode("hint", default=None, optional=True),
581
Unicode("source", default=None, optional=True),
582
Unicode("rule", default=None, optional=True),
583
Tuple((Int, Int), "lineoffset", default=None, optional=True),
584
Unicode("linter", default=None, optional=True))
585
def lint(self, data):
586
data["level"] = level_name
587
self._log_data("lint", data)
588
lint.__doc__ = """Log an error resulting from a failed lint check
589
590
:param linter: name of the linter that flagged this error
591
:param path: path to the file containing the error
592
:param message: text describing the error
593
:param lineno: line number that contains the error
594
:param column: column containing the error
595
:param hint: suggestion for fixing the error (optional)
596
:param source: source code context of the error (optional)
597
:param rule: name of the rule that was violated (optional)
598
:param lineoffset: denotes an error spans multiple lines, of the form
599
(<lineno offset>, <num lines>) (optional)
600
"""
601
lint.__name__ = str("lint_%s" % level_name)
602
return lint
603
604
605
# Create all the methods on StructuredLog for log/lint levels
606
for level_name in log_levels:
607
setattr(StructuredLogger, level_name.lower(), _log_func(level_name))
608
609
for level_name in lint_levels:
610
level_name = level_name.lower()
611
name = "lint_%s" % level_name
612
setattr(StructuredLogger, name, _lint_func(level_name))
613
614
615
class StructuredLogFileLike(object):
616
"""Wrapper for file-like objects to redirect writes to logger
617
instead. Each call to `write` becomes a single log entry of type `log`.
618
619
When using this it is important that the callees i.e. the logging
620
handlers do not themselves try to write to the wrapped file as this
621
will cause infinite recursion.
622
623
:param logger: `StructuredLogger` to which to redirect the file write operations.
624
:param level: log level to use for each write.
625
:param prefix: String prefix to prepend to each log entry.
626
"""
627
628
def __init__(self, logger, level="info", prefix=None):
629
self.logger = logger
630
self.log_func = getattr(self.logger, level)
631
self.prefix = prefix
632
633
def write(self, data):
634
if data.endswith("\n"):
635
data = data[:-1]
636
if data.endswith("\r"):
637
data = data[:-1]
638
if self.prefix is not None:
639
data = "%s: %s" % (self.prefix, data)
640
self.log_func(data)
641
642
def flush(self):
643
pass