def _log_func(level_name):
@log_action(Unicode("message"),
Any("exc_info", default=False))
def log(self, data):
exc_info = data.pop("exc_info", None)
if exc_info:
if not isinstance(exc_info, tuple):
exc_info = sys.exc_info()
if exc_info != (None, None, None):
bt = traceback.format_exception(*exc_info)
data["stack"] = u"\n".join(bt)
data["level"] = level_name
self._log_data("log", data)
log.__doc__ = """Log a message with level %s
:param message: The string message to log
:param exc_info: Either a boolean indicating whether to include a traceback
derived from sys.exc_info() or a three-item tuple in the
same format as sys.exc_info() containing exception information
to log.
""" % level_name
log.__name__ = str(level_name).lower()
return log
def _log_func(level_name):
@log_action(Unicode("message"))
def log(self, data):
data["level"] = level_name
self._log_data("log", data)
log.__doc__ = """Log a message with level %s
:param message: The string message to log
""" % level_name
log.__name__ = str(level_name).lower()
return log
def _lint_func(level_name):
@log_action(Unicode("path"), Unicode("message", default=""),
Int("lineno", default=0),
Int("column", default=None, optional=True),
Unicode("hint", default=None, optional=True),
Unicode("source", default=None, optional=True),
Unicode("rule", default=None, optional=True),
Tuple((Int, Int), "lineoffset", default=None, optional=True),
Unicode("linter", default=None, optional=True))
def lint(self, data):
data["level"] = level_name
self._log_data("lint", data)
lint.__doc__ = """Log an error resulting from a failed lint check
:param linter: name of the linter that flagged this error
:param path: path to the file containing the error
:param message: text describing the error
:param lineno: line number that contains the error
:param column: column containing the error
:param hint: suggestion for fixing the error (optional)
:param source: source code context of the error (optional)
:param rule: name of the rule that was violated (optional)
:param lineoffset: denotes an error spans multiple lines, of the form
(<lineno offset>, <num lines>) (optional)
"""
lint.__name__ = str("lint_%s" % level_name)
return lint
class StructuredLogger(object):
_lock = Lock()
_logger_states = {}
"""Create a structured logger with the given name
:param name: The name of the logger.
:param component: A subcomponent that the logger belongs to (typically a library name)
"""
def __init__(self, name, component=None):
self.name = name
self.component = component
with self._lock:
if name not in self._logger_states:
self._logger_states[name] = LoggerState()
@property
def _state(self):
return self._logger_states[self.name]
def add_handler(self, handler):
"""Add a handler to the current logger"""
self._state.handlers.append(handler)
def remove_handler(self, handler):
"""Remove a handler from the current logger"""
for i, candidate_handler in enumerate(self._state.handlers[:]):
if candidate_handler == handler:
del self._state.handlers[i]
break
@property
def handlers(self):
"""A list of handlers that will be called when a
message is logged from this logger"""
return self._state.handlers
def log_raw(self, raw_data):
if "action" not in raw_data:
raise ValueError
action = raw_data["action"]
converted_data = convertor_registry[action].convert_known(**raw_data)
for k, v in raw_data.iteritems():
if k not in converted_data:
converted_data[k] = v
data = self._make_log_data(action, converted_data)
if action in ("test_status", "test_end"):
if (data["expected"] == data["status"] or data["status"] == "SKIP"
or "expected" not in raw_data):
del data["expected"]
self._handle_log(data)
def _log_data(self, action, data=None):
if data is None:
data = {}
log_data = self._make_log_data(action, data)
self._handle_log(log_data)
def _handle_log(self, data):
with self._lock:
for handler in self.handlers:
handler(data)
def _make_log_data(self, action, data):
all_data = {
"action": action,
"time": int(time.time() * 1000),
"thread": current_thread().name,
"pid": current_process().pid,
"source": self.name
}
if self.component:
all_data['component'] = self.component
all_data.update(data)
return all_data
@log_action(List("tests", Unicode),
Dict("run_info", default=None, optional=True),
Dict("version_info", default=None, optional=True),
Dict("device_info", default=None, optional=True))
def suite_start(self, data):
"""Log a suite_start message
:param list tests: Test identifiers that will be run in the suite.
:param dict run_info: Optional information typically provided by mozinfo.
:param dict version_info: Optional target application version information provided by mozversion.
:param dict device_info: Optional target device information provided by mozdevice.
"""
if self._state.suite_started:
self.error(
"Got second suite_start message before suite_end. Logged with data %s"
% json.dumps(data))
return
self._state.suite_started = True
self._log_data("suite_start", data)
@log_action()
def suite_end(self, data):
"""Log a suite_end message"""
if not self._state.suite_started:
self.error("Got suite_end message before suite_start.")
return
self._state.suite_started = False
self._log_data("suite_end")
@log_action(TestId("test"))
def test_start(self, data):
"""Log a test_start message
:param test: Identifier of the test that will run.
"""
if not self._state.suite_started:
self.error(
"Got test_start message before suite_start for test %s" %
data["test"])
return
if data["test"] in self._state.running_tests:
self.error("test_start for %s logged while in progress." %
data["test"])
return
self._state.running_tests.add(data["test"])
self._log_data("test_start", data)
@log_action(TestId("test"), Unicode("subtest"), SubStatus("status"),
SubStatus("expected", default="PASS"),
Unicode("message", default=None, optional=True),
Unicode("stack", default=None, optional=True),
Dict("extra", default=None, optional=True))
def test_status(self, data):
"""
Log a test_status message indicating a subtest result. Tests that
do not have subtests are not expected to produce test_status messages.
:param test: Identifier of the test that produced the result.
:param subtest: Name of the subtest.
:param status: Status string indicating the subtest result
:param expected: Status string indicating the expected subtest result.
:param message: String containing a message associated with the result.
:param stack: a stack trace encountered during test execution.
:param extra: suite-specific data associated with the test result.
"""
if (data["expected"] == data["status"] or data["status"] == "SKIP"):
del data["expected"]
if data["test"] not in self._state.running_tests:
self.error("test_status for %s logged while not in progress. "
"Logged with data: %s" %
(data["test"], json.dumps(data)))
return
self._log_data("test_status", data)
@log_action(TestId("test"), Status("status"),
Status("expected", default="OK"),
Unicode("message", default=None, optional=True),
Unicode("stack", default=None, optional=True),
Dict("extra", default=None, optional=True))
def test_end(self, data):
"""
Log a test_end message indicating that a test completed. For tests
with subtests this indicates whether the overall test completed without
errors. For tests without subtests this indicates the test result
directly.
:param test: Identifier of the test that produced the result.
:param status: Status string indicating the test result
:param expected: Status string indicating the expected test result.
:param message: String containing a message associated with the result.
:param stack: a stack trace encountered during test execution.
:param extra: suite-specific data associated with the test result.
"""
if (data["expected"] == data["status"] or data["status"] == "SKIP"):
del data["expected"]
if data["test"] not in self._state.running_tests:
self.error("test_end for %s logged while not in progress. "
"Logged with data: %s" %
(data["test"], json.dumps(data)))
else:
self._state.running_tests.remove(data["test"])
self._log_data("test_end", data)
@log_action(Unicode("process"), Unicode("data"),
Unicode("command", default=None, optional=True))
def process_output(self, data):
"""Log output from a managed process.
:param process: A unique identifier for the process producing the output
(typically the pid)
:param data: The output to log
:param command: A string representing the full command line used to start
the process.
"""
self._log_data("process_output", data)
@log_action(Unicode("process", default=None),
Unicode("signature", default="[Unknown]"),
TestId("test", default=None, optional=True),
Unicode("minidump_path", default=None, optional=True),
Unicode("minidump_extra", default=None, optional=True),
Int("stackwalk_retcode", default=None, optional=True),
Unicode("stackwalk_stdout", default=None, optional=True),
Unicode("stackwalk_stderr", default=None, optional=True),
List("stackwalk_errors", Unicode, default=None))
def crash(self, data):
if data["stackwalk_errors"] is None:
data["stackwalk_errors"] = []
self._log_data("crash", data)
class StructuredLogger(object):
_lock = Lock()
_logger_states = {}
"""Create a structured logger with the given name
:param name: The name of the logger.
:param component: A subcomponent that the logger belongs to (typically a library name)
"""
def __init__(self, name, component=None):
self.name = name
self.component = component
with self._lock:
if name not in self._logger_states:
self._logger_states[name] = LoggerState()
if component not in self._logger_states[name].component_states:
self._logger_states[name].component_states[
component] = ComponentState()
self._state = self._logger_states[name]
self._component_state = self._state.component_states[component]
def add_handler(self, handler):
"""Add a handler to the current logger"""
self._state.handlers.append(handler)
def remove_handler(self, handler):
"""Remove a handler from the current logger"""
self._state.handlers.remove(handler)
def send_message(self, topic, command, *args):
"""Send a message to each handler configured for this logger. This
part of the api is useful to those users requiring dynamic control
of a handler's behavior.
:param topic: The name used by handlers to subscribe to a message.
:param command: The name of the command to issue.
:param args: Any arguments known to the target for specialized
behavior.
"""
rv = []
for handler in self._state.handlers:
if hasattr(handler, "handle_message"):
rv += handler.handle_message(topic, command, *args)
return rv
@property
def handlers(self):
"""A list of handlers that will be called when a
message is logged from this logger"""
return self._state.handlers
@property
def component_filter(self):
return self._component_state.filter_
@component_filter.setter
def component_filter(self, value):
self._component_state.filter_ = value
def log_raw(self, raw_data):
if "action" not in raw_data:
raise ValueError
action = raw_data["action"]
converted_data = convertor_registry[action].convert_known(**raw_data)
for k, v in raw_data.iteritems():
if k not in converted_data:
converted_data[k] = v
data = self._make_log_data(action, converted_data)
if action in ("test_status", "test_end"):
if (data["expected"] == data["status"] or data["status"] == "SKIP"
or "expected" not in raw_data):
del data["expected"]
if not self._ensure_suite_state(action, data):
return
self._handle_log(data)
def _log_data(self, action, data=None):
if data is None:
data = {}
log_data = self._make_log_data(action, data)
self._handle_log(log_data)
def _handle_log(self, data):
with self._lock:
if self.component_filter:
data = self.component_filter(data)
if data is None:
return
for handler in self.handlers:
try:
handler(data)
except Exception:
# Write the exception details directly to stderr because
# log() would call this method again which is currently locked.
print >> sys.__stderr__, '%s: Failure calling log handler:' % __name__
print >> sys.__stderr__, traceback.format_exc()
def _make_log_data(self, action, data):
all_data = {
"action": action,
"time": int(time.time() * 1000),
"thread": current_thread().name,
"pid": current_process().pid,
"source": self.name
}
if self.component:
all_data['component'] = self.component
all_data.update(data)
return all_data
def _ensure_suite_state(self, action, data):
if action == 'suite_start':
if self._state.suite_started:
self.error(
"Got second suite_start message before suite_end. " +
"Logged with data: {}".format(json.dumps(data)))
return False
self._state.suite_started = True
elif action == 'suite_end':
if not self._state.suite_started:
self.error("Got suite_end message before suite_start. " +
"Logged with data: {}".format(json.dumps(data)))
return False
self._state.suite_started = False
return True
@log_action(TestList("tests"),
Dict(Any, "run_info", default=None, optional=True),
Dict(Any, "version_info", default=None, optional=True),
Dict(Any, "device_info", default=None, optional=True),
Dict(Any, "extra", default=None, optional=True))
def suite_start(self, data):
"""Log a suite_start message
:param dict tests: Test identifiers that will be run in the suite, keyed by group name.
:param dict run_info: Optional information typically provided by mozinfo.
:param dict version_info: Optional target application version information provided
by mozversion.
:param dict device_info: Optional target device information provided by mozdevice.
"""
if not self._ensure_suite_state('suite_start', data):
return
self._log_data("suite_start", data)
@log_action(Dict(Any, "extra", default=None, optional=True))
def suite_end(self, data):
"""Log a suite_end message"""
if not self._ensure_suite_state('suite_end', data):
return
self._log_data("suite_end")
@log_action(TestId("test"), Unicode("path", default=None, optional=True))
def test_start(self, data):
"""Log a test_start message
:param test: Identifier of the test that will run.
:param path: Path to test relative to some base (typically the root of
the source tree).
"""
if not self._state.suite_started:
self.error(
"Got test_start message before suite_start for test %s" %
data["test"])
return
if data["test"] in self._state.running_tests:
self.error("test_start for %s logged while in progress." %
data["test"])
return
self._state.running_tests.add(data["test"])
self._log_data("test_start", data)
@log_action(TestId("test"), Unicode("subtest"), SubStatus("status"),
SubStatus("expected", default="PASS"),
Unicode("message", default=None, optional=True),
Unicode("stack", default=None, optional=True),
Dict(Any, "extra", default=None, optional=True))
def test_status(self, data):
"""
Log a test_status message indicating a subtest result. Tests that
do not have subtests are not expected to produce test_status messages.
:param test: Identifier of the test that produced the result.
:param subtest: Name of the subtest.
:param status: Status string indicating the subtest result
:param expected: Status string indicating the expected subtest result.
:param message: String containing a message associated with the result.
:param stack: a stack trace encountered during test execution.
:param extra: suite-specific data associated with the test result.
"""
if (data["expected"] == data["status"] or data["status"] == "SKIP"):
del data["expected"]
if data["test"] not in self._state.running_tests:
self.error("test_status for %s logged while not in progress. "
"Logged with data: %s" %
(data["test"], json.dumps(data)))
return
self._log_data("test_status", data)
@log_action(TestId("test"), Status("status"),
Status("expected", default="OK"),
Unicode("message", default=None, optional=True),
Unicode("stack", default=None, optional=True),
Dict(Any, "extra", default=None, optional=True))
def test_end(self, data):
"""
Log a test_end message indicating that a test completed. For tests
with subtests this indicates whether the overall test completed without
errors. For tests without subtests this indicates the test result
directly.
:param test: Identifier of the test that produced the result.
:param status: Status string indicating the test result
:param expected: Status string indicating the expected test result.
:param message: String containing a message associated with the result.
:param stack: a stack trace encountered during test execution.
:param extra: suite-specific data associated with the test result.
"""
if (data["expected"] == data["status"] or data["status"] == "SKIP"):
del data["expected"]
if data["test"] not in self._state.running_tests:
self.error("test_end for %s logged while not in progress. "
"Logged with data: %s" %
(data["test"], json.dumps(data)))
else:
self._state.running_tests.remove(data["test"])
self._log_data("test_end", data)
@log_action(Unicode("process"), Unicode("data"),
Unicode("command", default=None, optional=True))
def process_output(self, data):
"""Log output from a managed process.
:param process: A unique identifier for the process producing the output
(typically the pid)
:param data: The output to log
:param command: A string representing the full command line used to start
the process.
"""
self._log_data("process_output", data)
@log_action(Unicode("process", default=None),
Unicode("signature", default="[Unknown]"),
TestId("test", default=None, optional=True),
Unicode("minidump_path", default=None, optional=True),
Unicode("minidump_extra", default=None, optional=True),
Int("stackwalk_retcode", default=None, optional=True),
Unicode("stackwalk_stdout", default=None, optional=True),
Unicode("stackwalk_stderr", default=None, optional=True),
List(Unicode, "stackwalk_errors", default=None))
def crash(self, data):
if data["stackwalk_errors"] is None:
data["stackwalk_errors"] = []
self._log_data("crash", data)
@log_action(Unicode("primary", default=None),
List(Unicode, "secondary", default=None))
def valgrind_error(self, data):
self._log_data("valgrind_error", data)
@log_action(Unicode("process"),
Unicode("command", default=None, optional=True))
def process_start(self, data):
"""Log start event of a process.
:param process: A unique identifier for the process producing the
output (typically the pid)
:param command: A string representing the full command line used to
start the process.
"""
self._log_data("process_start", data)
@log_action(Unicode("process"), Int("exitcode"),
Unicode("command", default=None, optional=True))
def process_exit(self, data):
"""Log exit event of a process.
:param process: A unique identifier for the process producing the
output (typically the pid)
:param exitcode: the exit code
:param command: A string representing the full command line used to
start the process.
"""
self._log_data("process_exit", data)
@log_action(TestId("test"), Int("count"), Int("min_expected"),
Int("max_expected"))
def assertion_count(self, data):
"""Log count of assertions produced when running a test.
:param count: - Number of assertions produced
:param min_expected: - Minimum expected number of assertions
:param max_expected: - Maximum expected number of assertions
"""
self._log_data("assertion_count", data)
