diff --git a/build/virtualenv/packages.txt b/build/virtualenv/packages.txt index aa0f576b29e1..5df0f09002dc 100644 --- a/build/virtualenv/packages.txt +++ b/build/virtualenv/packages.txt @@ -7,5 +7,6 @@ setup.py:testing/mozbase/mozprocess:develop setup.py:testing/mozbase/mozprofile:develop setup.py:testing/mozbase/mozrunner:develop setup.py:python/blessings:develop +setup.py:python/mozbuild:develop mozilla.pth:build mozilla.pth:config diff --git a/python/mozbuild/README.rst b/python/mozbuild/README.rst new file mode 100644 index 000000000000..ef9aef897a08 --- /dev/null +++ b/python/mozbuild/README.rst @@ -0,0 +1,99 @@ +======== +mozbuild +======== + +mozbuild is a Python package providing functionality used by Mozilla's +build system. + +Modules Overview +================ + +* mozbuild.logging -- Defines mozbuild's logging infrastructure. + mozbuild uses a structured logging backend. + +Structured Logging +================== + +One of the features of mozbuild is structured logging. Instead of +conventional logging where simple strings are logged, the internal +logging mechanism logs all events with the following pieces of +information: + +* A string *action* +* A dict of log message fields +* A formatting string + +Essentially, instead of assembling a human-readable string at +logging-time, you create an object holding all the pieces of data that +will constitute your logged event. For each unique type of logged event, +you assign an *action* name. + +Depending on how logging is configured, your logged event could get +written a couple of different ways. + +JSON Logging +------------ + +Where machines are the intended target of the logging data, a JSON +logger is configured. The JSON logger assembles an array consisting of +the following elements: + +* Decimal wall clock time in seconds since UNIX epoch +* String *action* of message +* Object with structured message data + +The JSON-serialized array is written to a configured file handle. +Consumers of this logging stream can just perform a readline() then feed +that into a JSON deserializer to reconstruct the original logged +message. They can key off the *action* element to determine how to +process individual events. There is no need to invent a parser. +Convenient, isn't it? + +Logging for Humans +------------------ + +Where humans are the intended consumer of a log message, the structured +log message are converted to more human-friendly form. This is done by +utilizing the *formatting* string provided at log time. The logger +simply calls the *format* method of the formatting string, passing the +dict containing the message's fields. + +When *mach* is used in a terminal that supports it, the logging facility +also supports terminal features such as colorization. This is done +automatically in the logging layer - there is no need to control this at +logging time. + +In addition, messages intended for humans typically prepends every line +with the time passed since the application started. + +Logging HOWTO +------------- + +Structured logging piggybacks on top of Python's built-in logging +infrastructure provided by the *logging* package. We accomplish this by +taking advantage of *logging.Logger.log()*'s *extra* argument. To this +argument, we pass a dict with the fields *action* and *params*. These +are the string *action* and dict of message fields, respectively. The +formatting string is passed as the *msg* argument, like normal. + +If you were logging to a logger directly, you would do something like: + + logger.log(logging.INFO, 'My name is {name}', + extra={'action': 'my_name', 'params': {'name': 'Gregory'}}) + +The JSON logging would produce something like: + + [1339985554.306338, "my_name", {"name": "Gregory"}] + +Human logging would produce something like: + + 0.52 My name is Gregory + +Since there is a lot of complexity using logger.log directly, it is +recommended to go through a wrapping layer that hides part of the +complexity for you. e.g. + + def log(self, level, action, params, format_str): + self.logger.log(level, format_str, + extra={'action': action, 'params': params) + diff --git a/python/mozbuild/mozbuild/__init__.py b/python/mozbuild/mozbuild/__init__.py new file mode 100644 index 000000000000..e69de29bb2d1 diff --git a/python/mozbuild/mozbuild/logger.py b/python/mozbuild/mozbuild/logger.py new file mode 100644 index 000000000000..04b7046bb1c4 --- /dev/null +++ b/python/mozbuild/mozbuild/logger.py @@ -0,0 +1,202 @@ +# This Source Code Form is subject to the terms of the Mozilla Public +# License, v. 2.0. If a copy of the MPL was not distributed with this file, +# You can obtain one at http://mozilla.org/MPL/2.0/. + +# This file contains logging functionality for mozbuild. This functionality +# could likely be split out of mozbuild. For now, mozbuild is the only +# consumer and thus it lives here. + +try: + import blessings +except ImportError: + blessings = None + +import json +import logging +import sys +import time + + +class ConvertToStructuredFilter(logging.Filter): + """Filter that converts unstructured records into structured ones.""" + def filter(self, record): + if hasattr(record, 'action') and hasattr(record, 'params'): + return True + + record.action = 'unstructured' + record.params = {'msg': record.msg} + record.msg = '{msg}' + + return True + + +class StructuredJSONFormatter(logging.Formatter): + """Log formatter that writes a structured JSON entry.""" + + def format(self, record): + action = getattr(record, 'action', 'UNKNOWN') + params = getattr(record, 'params', {}) + + return json.dumps([record.created, action, params]) + + +class StructuredHumanFormatter(logging.Formatter): + """Log formatter that writes structured messages for humans. + + It is important that this formatter never be added to a logger that + produces unstructured/classic log messages. If it is, the call to format() + could fail because the string could contain things (like JSON) that look + like formatting character sequences. + + Because of this limitation, format() will fail with a KeyError if an + unstructured record is passed or if the structured message is malformed. + """ + def __init__(self, start_time, write_interval=False): + self.start_time = start_time + self.write_interval = write_interval + self.last_time = None + + def format(self, record): + elapsed = self._time(record) + + return u'%4.2f %s' % (elapsed, record.msg.format(**record.params)) + + def _time(self, record): + t = record.created - self.start_time + + if self.write_interval and self.last_time is not None: + t = record.created - self.last_time + + self.last_time = record.created + + return t + + +class StructuredTerminalFormatter(StructuredHumanFormatter): + """Log formatter for structured messages writing to a terminal.""" + + def set_terminal(self, terminal): + self.terminal = terminal + + def format(self, record): + t = self.terminal.blue('%4.2f' % self._time(record)) + f = record.msg.format(**record.params) + + return u'%s %s' % (t, self._colorize(f)) + + def _colorize(self, s): + if not self.terminal: + return s + + result = s + + if s.startswith('TEST-PASS'): + result = self.terminal.green(s[0:9]) + s[9:] + elif s.startswith('TEST-UNEXPECTED'): + result = self.terminal.red(s[0:20]) + s[21:] + + return result.decode('UTF-8', 'ignore') + + +class LoggingManager(object): + """Holds and controls global logging state. + + A mozbuild application should instantiate one of these and configure it + as needed. + + This class provides a mechanism to configure the output of logging data + both from mozbuild and from the overall logging system (e.g. from other + modules). + """ + + def __init__(self): + self.start_time = time.time() + + self.json_handlers = [] + self.terminal_handler = None + self.terminal_formatter = None + + self.root_logger = logging.getLogger() + self.root_logger.setLevel(logging.DEBUG) + + self.mozbuild_logger = logging.getLogger('mozbuild') + self.mozbuild_logger.setLevel(logging.DEBUG) + + self.structured_filter = ConvertToStructuredFilter() + + self._terminal = None + + @property + def terminal(self): + if not self._terminal and blessings: + terminal = blessings.Terminal(stream=sys.stdout) + + if terminal.is_a_tty: + self._terminal = terminal + + return self._terminal + + def add_json_handler(self, fh): + """Enable JSON logging on the specified file object.""" + + # Configure the consumer of structured messages. + handler = logging.StreamHandler(stream=fh) + handler.setFormatter(StructuredJSONFormatter()) + handler.setLevel(logging.DEBUG) + + # And hook it up. + self.mozbuild_logger.addHandler(handler) + + self.json_handlers.append(handler) + + def add_terminal_logging(self, fh=sys.stdout, level=logging.INFO, + write_interval=False): + """Enable logging to the terminal.""" + + formatter = StructuredHumanFormatter(self.start_time, + write_interval=write_interval) + + if self.terminal: + formatter = StructuredTerminalFormatter(self.start_time, + write_interval=write_interval) + formatter.set_terminal(self.terminal) + + handler = logging.StreamHandler(stream=fh) + handler.setFormatter(formatter) + handler.setLevel(level) + + self.mozbuild_logger.addHandler(handler) + + self.terminal_handler = handler + self.terminal_formatter = formatter + + def replace_terminal_handler(self, handler): + """Replace the installed terminal handler. + + Returns the old handler or None if none was configured. + If the new handler is None, removes any existing handler and disables + logging to the terminal. + """ + old = self.terminal_handler + + if old: + self.mozbuild_logger.removeHandler(old) + + if handler: + self.mozbuild_logger.addHandler(handler) + + self.terminal_handler = handler + + return old + + def enable_unstructured(self): + """Enable logging of unstructured messages.""" + if self.terminal_handler: + self.terminal_handler.addFilter(self.structured_filter) + self.root_logger.addHandler(self.terminal_handler) + + def disable_unstructured(self): + """Disable logging of unstructured messages.""" + if self.terminal_handler: + self.terminal_handler.removeFilter(self.structured_filter) + self.root_logger.removeHandler(self.terminal_handler) diff --git a/python/mozbuild/setup.py b/python/mozbuild/setup.py new file mode 100644 index 000000000000..fe267abee613 --- /dev/null +++ b/python/mozbuild/setup.py @@ -0,0 +1,15 @@ +# This Source Code Form is subject to the terms of the Mozilla Public +# License, v. 2.0. If a copy of the MPL was not distributed with this file, +# You can obtain one at http://mozilla.org/MPL/2.0/. + +from setuptools import setup + +VERSION = '0.1' + +setup( + name='mozbuild', + description='Mozilla build system functionality.', + license='MPL 2.0', + packages=['mozbuild'], + version=VERSION +)