diff --git a/python/mozlog/mozlog/__init__.py b/python/mozlog/mozlog/__init__.py new file mode 100644 index 00000000000..bfa23eae645 --- /dev/null +++ b/python/mozlog/mozlog/__init__.py @@ -0,0 +1,26 @@ +# 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/. + +""" +Mozlog aims to standardize log formatting within Mozilla. + +It simply wraps Python's logging_ module and adds a few convenience methods +for logging test results and events. + +The structured submodule takes a different approach and implements a +JSON-based logging protocol designed for recording test results.""" + +from logger import * +from loglistener import LogMessageServer +from loggingmixin import LoggingMixin + +try: + import structured +except ImportError: + # Structured logging doesn't work on python 2.6 which is still used on some + # legacy test machines; https://bugzilla.mozilla.org/show_bug.cgi?id=864866 + # Once we move away from Python 2.6, please cleanup devicemanager.py's + # exception block + pass + diff --git a/python/mozlog/mozlog/logger.py b/python/mozlog/mozlog/logger.py new file mode 100644 index 00000000000..60bd4912fb3 --- /dev/null +++ b/python/mozlog/mozlog/logger.py @@ -0,0 +1,180 @@ +# 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 logging import getLogger as getSysLogger +from logging import * +# Some of the build slave environments don't see the following when doing +# 'from logging import *' +# see https://bugzilla.mozilla.org/show_bug.cgi?id=700415#c35 +from logging import getLoggerClass, addLevelName, setLoggerClass, shutdown, debug, info, basicConfig +import json + +_default_level = INFO +_LoggerClass = getLoggerClass() + +# Define mozlog specific log levels +START = _default_level + 1 +END = _default_level + 2 +PASS = _default_level + 3 +KNOWN_FAIL = _default_level + 4 +FAIL = _default_level + 5 +CRASH = _default_level + 6 +# Define associated text of log levels +addLevelName(START, 'TEST-START') +addLevelName(END, 'TEST-END') +addLevelName(PASS, 'TEST-PASS') +addLevelName(KNOWN_FAIL, 'TEST-KNOWN-FAIL') +addLevelName(FAIL, 'TEST-UNEXPECTED-FAIL') +addLevelName(CRASH, 'PROCESS-CRASH') + +class MozLogger(_LoggerClass): + """ + MozLogger class which adds some convenience log levels + related to automated testing in Mozilla and ability to + output structured log messages. + """ + def testStart(self, message, *args, **kwargs): + """Logs a test start message""" + self.log(START, message, *args, **kwargs) + + def testEnd(self, message, *args, **kwargs): + """Logs a test end message""" + self.log(END, message, *args, **kwargs) + + def testPass(self, message, *args, **kwargs): + """Logs a test pass message""" + self.log(PASS, message, *args, **kwargs) + + def testFail(self, message, *args, **kwargs): + """Logs a test fail message""" + self.log(FAIL, message, *args, **kwargs) + + def testKnownFail(self, message, *args, **kwargs): + """Logs a test known fail message""" + self.log(KNOWN_FAIL, message, *args, **kwargs) + + def processCrash(self, message, *args, **kwargs): + """Logs a process crash message""" + self.log(CRASH, message, *args, **kwargs) + + def log_structured(self, action, params=None): + """Logs a structured message object.""" + if params is None: + params = {} + + level = params.get('_level', _default_level) + if isinstance(level, int): + params['_level'] = getLevelName(level) + else: + params['_level'] = level + level = getLevelName(level.upper()) + + # If the logger is fed a level number unknown to the logging + # module, getLevelName will return a string. Unfortunately, + # the logging module will raise a type error elsewhere if + # the level is not an integer. + if not isinstance(level, int): + level = _default_level + + params['action'] = action + + # The can message be None. This is expected, and shouldn't cause + # unstructured formatters to fail. + message = params.get('_message') + + self.log(level, message, extra={'params': params}) + +class JSONFormatter(Formatter): + """Log formatter for emitting structured JSON entries.""" + + def format(self, record): + # Default values determined by logger metadata + output = { + '_time': int(round(record.created * 1000, 0)), + '_namespace': record.name, + '_level': getLevelName(record.levelno), + } + + # If this message was created by a call to log_structured, + # anything specified by the caller's params should act as + # an override. + output.update(getattr(record, 'params', {})) + + if record.msg and output.get('_message') is None: + # For compatibility with callers using the printf like + # API exposed by python logging, call the default formatter. + output['_message'] = Formatter.format(self, record) + + return json.dumps(output, indent=output.get('indent')) + +class MozFormatter(Formatter): + """ + MozFormatter class used to standardize formatting + If a different format is desired, this can be explicitly + overriden with the log handler's setFormatter() method + """ + level_length = 0 + max_level_length = len('TEST-START') + + def __init__(self, include_timestamp=False): + """ + Formatter.__init__ has fmt and datefmt parameters that won't have + any affect on a MozFormatter instance. + + :param include_timestamp: if True, include formatted time at the + beginning of the message + """ + self.include_timestamp = include_timestamp + Formatter.__init__(self) + + def format(self, record): + # Handles padding so record levels align nicely + if len(record.levelname) > self.level_length: + pad = 0 + if len(record.levelname) <= self.max_level_length: + self.level_length = len(record.levelname) + else: + pad = self.level_length - len(record.levelname) + 1 + sep = '|'.rjust(pad) + fmt = '%(name)s %(levelname)s ' + sep + ' %(message)s' + if self.include_timestamp: + fmt = '%(asctime)s ' + fmt + # this protected member is used to define the format + # used by the base Formatter's method + self._fmt = fmt + return Formatter.format(self, record) + +def getLogger(name, handler=None): + """ + Returns the logger with the specified name. + If the logger doesn't exist, it is created. + If handler is specified, adds it to the logger. Otherwise a default handler + that logs to standard output will be used. + + :param name: The name of the logger to retrieve + :param handler: A handler to add to the logger. If the logger already exists, + and a handler is specified, an exception will be raised. To + add a handler to an existing logger, call that logger's + addHandler method. + """ + setLoggerClass(MozLogger) + + if name in Logger.manager.loggerDict: + if handler: + raise ValueError('The handler parameter requires ' + \ + 'that a logger by this name does ' + \ + 'not already exist') + return Logger.manager.loggerDict[name] + + logger = getSysLogger(name) + logger.setLevel(_default_level) + + if handler is None: + handler = StreamHandler() + handler.setFormatter(MozFormatter()) + + logger.addHandler(handler) + logger.propagate = False + return logger + diff --git a/python/mozlog/mozlog/loggingmixin.py b/python/mozlog/mozlog/loggingmixin.py new file mode 100644 index 00000000000..8e958edac82 --- /dev/null +++ b/python/mozlog/mozlog/loggingmixin.py @@ -0,0 +1,41 @@ +# 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/. + +import mozlog + +class LoggingMixin(object): + """Expose a subset of logging functions to an inheriting class.""" + + def set_logger(self, logger_instance=None, name=None): + """Method for setting the underlying logger instance to be used.""" + + if logger_instance and not isinstance(logger_instance, mozlog.Logger): + raise ValueError("logger_instance must be an instance of" + + "mozlog.Logger") + + if name is None: + name = ".".join([self.__module__, self.__class__.__name__]) + + self._logger = logger_instance or mozlog.getLogger(name) + + def _log_msg(self, cmd, *args, **kwargs): + if not hasattr(self, "_logger"): + self._logger = mozlog.getLogger(".".join([self.__module__, + self.__class__.__name__])) + getattr(self._logger, cmd)(*args, **kwargs) + + def log(self, *args, **kwargs): + self._log_msg("log", *args, **kwargs) + + def info(self, *args, **kwargs): + self._log_msg("info", *args, **kwargs) + + def error(self, *args, **kwargs): + self._log_msg("error", *args, **kwargs) + + def warn(self, *args, **kwargs): + self._log_msg("warn", *args, **kwargs) + + def log_structured(self, *args, **kwargs): + self._log_msg("log_structured", *args, **kwargs) diff --git a/python/mozlog/mozlog/loglistener.py b/python/mozlog/mozlog/loglistener.py new file mode 100644 index 00000000000..e4b54c3988b --- /dev/null +++ b/python/mozlog/mozlog/loglistener.py @@ -0,0 +1,47 @@ +# 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/. + +import SocketServer +import socket +import json + +class LogMessageServer(SocketServer.TCPServer): + def __init__(self, server_address, logger, message_callback=None, timeout=3): + SocketServer.TCPServer.__init__(self, server_address, LogMessageHandler) + self._logger = logger + self._message_callback = message_callback + self.timeout = timeout + +class LogMessageHandler(SocketServer.BaseRequestHandler): + """Processes output from a connected log source, logging to an + existing logger upon receipt of a well-formed log messsage.""" + + def handle(self): + """Continually listens for log messages.""" + self._partial_message = '' + self.request.settimeout(self.server.timeout) + + while True: + try: + data = self.request.recv(1024) + if not data: + return + self.process_message(data) + except socket.timeout: + return + + def process_message(self, data): + """Processes data from a connected log source. Messages are assumed + to be newline delimited, and generally well-formed JSON.""" + for part in data.split('\n'): + msg_string = self._partial_message + part + try: + msg = json.loads(msg_string) + self._partial_message = '' + self.server._logger.log_structured(msg.get('action', 'UNKNOWN'), msg) + if self.server._message_callback: + self.server._message_callback() + + except ValueError: + self._partial_message = msg_string diff --git a/python/mozlog/mozlog/structured/__init__.py b/python/mozlog/mozlog/structured/__init__.py new file mode 100644 index 00000000000..31a779108b4 --- /dev/null +++ b/python/mozlog/mozlog/structured/__init__.py @@ -0,0 +1,7 @@ +# 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/. + +import commandline +import structuredlog +from structuredlog import get_default_logger, set_default_logger diff --git a/python/mozlog/mozlog/structured/commandline.py b/python/mozlog/mozlog/structured/commandline.py new file mode 100644 index 00000000000..d4a993febe5 --- /dev/null +++ b/python/mozlog/mozlog/structured/commandline.py @@ -0,0 +1,225 @@ +# 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/. + +import sys +import os +import optparse + +from collections import defaultdict +from structuredlog import StructuredLogger, set_default_logger +import handlers +import formatters + +log_formatters = { + 'raw': (formatters.JSONFormatter, "Raw structured log messages"), + 'unittest': (formatters.UnittestFormatter, "Unittest style output"), + 'xunit': (formatters.XUnitFormatter, "xUnit compatible XML"), + 'html': (formatters.HTMLFormatter, "HTML report"), + 'mach': (formatters.MachFormatter, "Human-readable output"), + 'tbpl': (formatters.TbplFormatter, "TBPL style log format"), +} + +TEXT_FORMATTERS = ('raw', 'mach') +"""a subset of formatters for non test harnesses related applications""" + +def level_filter_wrapper(formatter, level): + return handlers.LogLevelFilter(formatter, level) + +def verbose_wrapper(formatter, verbose): + formatter.verbose = verbose + return formatter + +def buffer_handler_wrapper(handler, buffer_limit): + if buffer_limit == "UNLIMITED": + buffer_limit = None + else: + buffer_limit = int(buffer_limit) + return handlers.BufferingLogFilter(handler, buffer_limit) + +formatter_option_defaults = { + 'verbose': False, + 'level': 'info', +} + +fmt_options = { + #