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