#!/usr/bin/env python # ***** BEGIN LICENSE BLOCK ***** # 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/. # ***** END LICENSE BLOCK ***** """Generic logging classes and functionalities for single and multi file logging. Capturing console output and providing general logging functionalities. Attributes: FATAL_LEVEL (int): constant logging level value set based on the logging.CRITICAL value DEBUG (str): mozharness `debug` log name INFO (str): mozharness `info` log name WARNING (str): mozharness `warning` log name CRITICAL (str): mozharness `critical` log name FATAL (str): mozharness `fatal` log name IGNORE (str): mozharness `ignore` log name LOG_LEVELS (dict): mapping of the mozharness log level names to logging values ROOT_LOGGER (logging.Logger): instance of a logging.Logger class TODO: - network logging support. - log rotation config """ import logging import os import sys import time import traceback from datetime import datetime from six import binary_type # Define our own FATAL_LEVEL FATAL_LEVEL = logging.CRITICAL + 10 logging.addLevelName(FATAL_LEVEL, "FATAL") # mozharness log levels. DEBUG, INFO, WARNING, ERROR, CRITICAL, FATAL, IGNORE = ( "debug", "info", "warning", "error", "critical", "fatal", "ignore", ) LOG_LEVELS = { DEBUG: logging.DEBUG, INFO: logging.INFO, WARNING: logging.WARNING, ERROR: logging.ERROR, CRITICAL: logging.CRITICAL, FATAL: FATAL_LEVEL, } # mozharness root logger ROOT_LOGGER = logging.getLogger() # Force logging to use UTC timestamps logging.Formatter.converter = time.gmtime # LogMixin {{{1 class LogMixin(object): """This is a mixin for any object to access similar logging functionality The logging functionality described here is specially useful for those objects with self.config and self.log_obj member variables """ def _log_level_at_least(self, level): """Check if the current logging level is greater or equal than level Args: level (str): log level name to compare against mozharness log levels names Returns: bool: True if the current logging level is great or equal than level, False otherwise """ log_level = INFO levels = [DEBUG, INFO, WARNING, ERROR, CRITICAL, FATAL] if hasattr(self, "config"): log_level = self.config.get("log_level", INFO) return levels.index(level) >= levels.index(log_level) def _print(self, message, stderr=False): """prints a message to the sys.stdout or sys.stderr according to the value of the stderr argument. Args: message (str): The message to be printed stderr (bool, optional): if True, message will be printed to sys.stderr. Defaults to False. Returns: None """ if not hasattr(self, "config") or self.config.get("log_to_console", True): if stderr: print(message, file=sys.stderr) else: print(message) def log(self, message, level=INFO, exit_code=-1): """log the message passed to it according to level, exit if level == FATAL Args: message (str): message to be logged level (str, optional): logging level of the message. Defaults to INFO exit_code (int, optional): exit code to log before the scripts calls SystemExit. Returns: None """ if self.log_obj: return self.log_obj.log_message( message, level=level, exit_code=exit_code, post_fatal_callback=self._post_fatal, ) if level == INFO: if self._log_level_at_least(level): self._print(message) elif level == DEBUG: if self._log_level_at_least(level): self._print("DEBUG: %s" % message) elif level in (WARNING, ERROR, CRITICAL): if self._log_level_at_least(level): self._print("%s: %s" % (level.upper(), message), stderr=True) elif level == FATAL: if self._log_level_at_least(level): self._print("FATAL: %s" % message, stderr=True) raise SystemExit(exit_code) def worst_level(self, target_level, existing_level, levels=None): """Compare target_level with existing_level according to levels values and return the worst among them. Args: target_level (str): minimum logging level to which the current object should be set existing_level (str): current logging level levels (list(str), optional): list of logging levels names to compare target_level and existing_level against. Defaults to mozharness log level list sorted from most to less critical. Returns: str: the logging lavel that is closest to the first levels value, i.e. levels[0] """ if not levels: levels = [FATAL, CRITICAL, ERROR, WARNING, INFO, DEBUG, IGNORE] if target_level not in levels: self.fatal("'%s' not in %s'." % (target_level, levels)) for l in levels: if l in (target_level, existing_level): return l # Copying Bear's dumpException(): # https://hg.mozilla.org/build/tools/annotate/1485f23c38e0/sut_tools/sut_lib.py#l23 def exception(self, message=None, level=ERROR): """log an exception message base on the log level passed to it. This function fetches the information of the current exception being handled and adds it to the message argument. Args: message (str, optional): message to be printed at the beginning of the log. Default to an empty string. level (str, optional): log level to use for the logging. Defaults to ERROR Returns: None """ tb_type, tb_value, tb_traceback = sys.exc_info() if message is None: message = "" else: message = "%s\n" % message for s in traceback.format_exception(tb_type, tb_value, tb_traceback): message += "%s\n" % s # Log at the end, as a fatal will attempt to exit after the 1st line. self.log(message, level=level) def debug(self, message): """calls the log method with DEBUG as logging level Args: message (str): message to log """ self.log(message, level=DEBUG) def info(self, message): """calls the log method with INFO as logging level Args: message (str): message to log """ self.log(message, level=INFO) def warning(self, message): """calls the log method with WARNING as logging level Args: message (str): message to log """ self.log(message, level=WARNING) def error(self, message): """calls the log method with ERROR as logging level Args: message (str): message to log """ self.log(message, level=ERROR) def critical(self, message): """calls the log method with CRITICAL as logging level Args: message (str): message to log """ self.log(message, level=CRITICAL) def fatal(self, message, exit_code=-1): """calls the log method with FATAL as logging level Args: message (str): message to log exit_code (int, optional): exit code to use for the SystemExit exception to be raised. Default to -1. """ self.log(message, level=FATAL, exit_code=exit_code) def _post_fatal(self, message=None, exit_code=None): """Sometimes you want to create a report or cleanup or notify on fatal(); override this method to do so. Please don't use this for anything significantly long-running. Args: message (str, optional): message to report. Default to None exit_code (int, optional): exit code to use for the SystemExit exception to be raised. Default to None """ pass # OutputParser {{{1 class OutputParser(LogMixin): """Helper object to parse command output. This will buffer output if needed, so we can go back and mark [(linenum - 10) : linenum+10] as errors if need be, without having to get all the output first. linenum+10 will be easy; we can set self.num_post_context_lines to 10, and self.num_post_context_lines-- as we mark each line to at least error level X. linenum-10 will be trickier. We'll not only need to save the line itself, but also the level that we've set for that line previously, whether by matching on that line, or by a previous line's context. We should only log that line if all output has ended (self.finish() ?); otherwise store a list of dictionaries in self.context_buffer that is buffered up to self.num_pre_context_lines (set to the largest pre-context-line setting in error_list.) """ def __init__( self, config=None, log_obj=None, error_list=None, log_output=True, **kwargs ): """Initialization method for the OutputParser class Args: config (dict, optional): dictionary containing values such as `log_level` or `log_to_console`. Defaults to `None`. log_obj (BaseLogger, optional): instance of the BaseLogger class. Defaults to `None`. error_list (list, optional): list of the error to look for. Defaults to `None`. log_output (boolean, optional): flag for deciding if the commands output should be logged or not. Defaults to `True`. """ self.config = config self.log_obj = log_obj self.error_list = error_list or [] self.log_output = log_output self.num_errors = 0 self.num_warnings = 0 # TODO context_lines. # Not in use yet, but will be based off error_list. self.context_buffer = [] self.num_pre_context_lines = 0 self.num_post_context_lines = 0 self.worst_log_level = INFO def parse_single_line(self, line): """parse a console output line and check if it matches one in `error_list`, if so then log it according to `log_output`. Args: line (str): command line output to parse. Returns: If the line hits a match in the error_list, the new log level the line was (or should be) logged at is returned. Otherwise, returns None. """ for error_check in self.error_list: # TODO buffer for context_lines. match = False if "substr" in error_check: if error_check["substr"] in line: match = True elif "regex" in error_check: if error_check["regex"].search(line): match = True else: self.warning("error_list: 'substr' and 'regex' not in %s" % error_check) if match: log_level = error_check.get("level", INFO) if self.log_output: message = " %s" % line if error_check.get("explanation"): message += "\n %s" % error_check["explanation"] if error_check.get("summary"): self.add_summary(message, level=log_level) else: self.log(message, level=log_level) if log_level in (ERROR, CRITICAL, FATAL): self.num_errors += 1 if log_level == WARNING: self.num_warnings += 1 self.worst_log_level = self.worst_level(log_level, self.worst_log_level) return log_level if self.log_output: self.info(" %s" % line) def add_lines(self, output): """process a string or list of strings, decode them to utf-8,strip them of any trailing whitespaces and parse them using `parse_single_line` strings consisting only of whitespaces are ignored. Args: output (str | list): string or list of string to parse """ if not isinstance(output, list): output = [output] for line in output: if not line or line.isspace(): continue if isinstance(line, binary_type): line = line.decode("utf-8", "replace") line = line.rstrip() self.parse_single_line(line) # BaseLogger {{{1 class BaseLogger(object): """Base class in charge of logging handling logic such as creating logging files, dirs, attaching to the console output and managing its output. Attributes: LEVELS (dict): flat copy of the `LOG_LEVELS` attribute of the `log` module. TODO: status? There may be a status object or status capability in either logging or config that allows you to count the number of error,critical,fatal messages for us to count up at the end (aiming for 0). """ LEVELS = LOG_LEVELS def __init__( self, log_level=INFO, log_format="%(message)s", log_date_format="%H:%M:%S", log_name="test", log_to_console=True, log_dir=".", log_to_raw=False, logger_name="", append_to_log=False, ): """BaseLogger constructor Args: log_level (str, optional): mozharness log level name. Defaults to INFO. log_format (str, optional): message format string to instantiate a `logging.Formatter`. Defaults to '%(message)s' log_date_format (str, optional): date format string to instantiate a `logging.Formatter`. Defaults to '%H:%M:%S' log_name (str, optional): name to use for the log files to be created. Defaults to 'test' log_to_console (bool, optional): set to True in order to create a Handler instance base on the `Logger` current instance. Defaults to True. log_dir (str, optional): directory location to store the log files. Defaults to '.', i.e. current working directory. log_to_raw (bool, optional): set to True in order to create a *raw.log file. Defaults to False. logger_name (str, optional): currently useless parameter. According to the code comments, it could be useful if we were to have multiple logging objects that don't trample each other. append_to_log (bool, optional): set to True if the logging content should be appended to old logging files. Defaults to False """ self.log_format = log_format self.log_date_format = log_date_format self.log_to_console = log_to_console self.log_to_raw = log_to_raw self.log_level = log_level self.log_name = log_name self.log_dir = log_dir self.append_to_log = append_to_log # Not sure what I'm going to use this for; useless unless we # can have multiple logging objects that don't trample each other self.logger_name = logger_name self.all_handlers = [] self.log_files = {} self.create_log_dir() def create_log_dir(self): """create a logging directory if it doesn't exits. If there is a file with same name as the future logging directory it will be deleted. """ if os.path.exists(self.log_dir): if not os.path.isdir(self.log_dir): os.remove(self.log_dir) if not os.path.exists(self.log_dir): os.makedirs(self.log_dir) self.abs_log_dir = os.path.abspath(self.log_dir) def init_message(self, name=None): """log an init message stating the name passed to it, the current date and time and, the current working directory. Args: name (str, optional): name to use for the init log message. Defaults to the current instance class name. """ if not name: name = self.__class__.__name__ self.log_message( "%s online at %s in %s" % (name, datetime.utcnow().strftime("%Y%m%d %H:%M:%SZ"), os.getcwd()) ) def get_logger_level(self, level=None): """translate the level name passed to it and return its numeric value according to `LEVELS` values. Args: level (str, optional): level name to be translated. Defaults to the current instance `log_level`. Returns: int: numeric value of the log level name passed to it or 0 (NOTSET) if the name doesn't exists """ if not level: level = self.log_level return self.LEVELS.get(level, logging.NOTSET) def get_log_formatter(self, log_format=None, date_format=None): """create a `logging.Formatter` base on the log and date format. Args: log_format (str, optional): log format to use for the Formatter constructor. Defaults to the current instance log format. date_format (str, optional): date format to use for the Formatter constructor. Defaults to the current instance date format. Returns: logging.Formatter: instance created base on the passed arguments """ if not log_format: log_format = self.log_format if not date_format: date_format = self.log_date_format return logging.Formatter(log_format, date_format) def new_logger(self): """Create a new logger based on the ROOT_LOGGER instance. By default there are no handlers. The new logger becomes a member variable of the current instance as `self.logger`. """ self.logger = ROOT_LOGGER self.logger.setLevel(self.get_logger_level()) self._clear_handlers() if self.log_to_console: self.add_console_handler() if self.log_to_raw: self.log_files["raw"] = "%s_raw.log" % self.log_name self.add_file_handler( os.path.join(self.abs_log_dir, self.log_files["raw"]), log_format="%(message)s", ) def _clear_handlers(self): """remove all handlers stored in `self.all_handlers`. To prevent dups -- logging will preserve Handlers across objects :( """ attrs = dir(self) if "all_handlers" in attrs and "logger" in attrs: for handler in self.all_handlers: self.logger.removeHandler(handler) self.all_handlers = [] def __del__(self): """BaseLogger class destructor; shutdown, flush and remove all handlers""" logging.shutdown() self._clear_handlers() def add_console_handler(self, log_level=None, log_format=None, date_format=None): """create a `logging.StreamHandler` using `sys.stderr` for logging the console output and add it to the `all_handlers` member variable Args: log_level (str, optional): useless argument. Not used here. Defaults to None. log_format (str, optional): format used for the Formatter attached to the StreamHandler. Defaults to None. date_format (str, optional): format used for the Formatter attached to the StreamHandler. Defaults to None. """ console_handler = logging.StreamHandler() console_handler.setFormatter( self.get_log_formatter(log_format=log_format, date_format=date_format) ) self.logger.addHandler(console_handler) self.all_handlers.append(console_handler) def add_file_handler( self, log_path, log_level=None, log_format=None, date_format=None ): """create a `logging.FileHandler` base on the path, log and date format and add it to the `all_handlers` member variable. Args: log_path (str): filepath to use for the `FileHandler`. log_level (str, optional): useless argument. Not used here. Defaults to None. log_format (str, optional): log format to use for the Formatter constructor. Defaults to the current instance log format. date_format (str, optional): date format to use for the Formatter constructor. Defaults to the current instance date format. """ if not self.append_to_log and os.path.exists(log_path): os.remove(log_path) file_handler = logging.FileHandler(log_path) file_handler.setLevel(self.get_logger_level(log_level)) file_handler.setFormatter( self.get_log_formatter(log_format=log_format, date_format=date_format) ) self.logger.addHandler(file_handler) self.all_handlers.append(file_handler) def log_message(self, message, level=INFO, exit_code=-1, post_fatal_callback=None): """Generic log method. There should be more options here -- do or don't split by line, use os.linesep instead of assuming \n, be able to pass in log level by name or number. Adding the IGNORE special level for runCommand. Args: message (str): message to log using the current `logger` level (str, optional): log level of the message. Defaults to INFO. exit_code (int, optional): exit code to use in case of a FATAL level is used. Defaults to -1. post_fatal_callback (function, optional): function to callback in case of of a fatal log level. Defaults None. """ if level == IGNORE: return for line in message.splitlines(): self.logger.log(self.get_logger_level(level), line) if level == FATAL: if callable(post_fatal_callback): self.logger.log(FATAL_LEVEL, "Running post_fatal callback...") post_fatal_callback(message=message, exit_code=exit_code) self.logger.log(FATAL_LEVEL, "Exiting %d" % exit_code) raise SystemExit(exit_code) # SimpleFileLogger {{{1 class SimpleFileLogger(BaseLogger): """Subclass of the BaseLogger. Create one logFile. Possibly also output to the terminal and a raw log (no prepending of level or date) """ def __init__( self, log_format="%(asctime)s %(levelname)8s - %(message)s", logger_name="Simple", log_dir="logs", **kwargs ): """SimpleFileLogger constructor. Calls its superclass constructor, creates a new logger instance and log an init message. Args: log_format (str, optional): message format string to instantiate a `logging.Formatter`. Defaults to '%(asctime)s %(levelname)8s - %(message)s' log_name (str, optional): name to use for the log files to be created. Defaults to 'Simple' log_dir (str, optional): directory location to store the log files. Defaults to 'logs' **kwargs: Arbitrary keyword arguments passed to the BaseLogger constructor """ BaseLogger.__init__( self, logger_name=logger_name, log_format=log_format, log_dir=log_dir, **kwargs ) self.new_logger() self.init_message() def new_logger(self): """calls the BaseLogger.new_logger method and adds a file handler to it.""" BaseLogger.new_logger(self) self.log_path = os.path.join(self.abs_log_dir, "%s.log" % self.log_name) self.log_files["default"] = self.log_path self.add_file_handler(self.log_path) # MultiFileLogger {{{1 class MultiFileLogger(BaseLogger): """Subclass of the BaseLogger class. Create a log per log level in log_dir. Possibly also output to the terminal and a raw log (no prepending of level or date) """ def __init__( self, logger_name="Multi", log_format="%(asctime)s %(levelname)8s - %(message)s", log_dir="logs", log_to_raw=True, **kwargs ): """MultiFileLogger constructor. Calls its superclass constructor, creates a new logger instance and log an init message. Args: log_format (str, optional): message format string to instantiate a `logging.Formatter`. Defaults to '%(asctime)s %(levelname)8s - %(message)s' log_name (str, optional): name to use for the log files to be created. Defaults to 'Multi' log_dir (str, optional): directory location to store the log files. Defaults to 'logs' log_to_raw (bool, optional): set to True in order to create a *raw.log file. Defaults to False. **kwargs: Arbitrary keyword arguments passed to the BaseLogger constructor """ BaseLogger.__init__( self, logger_name=logger_name, log_format=log_format, log_to_raw=log_to_raw, log_dir=log_dir, **kwargs ) self.new_logger() self.init_message() def new_logger(self): """calls the BaseLogger.new_logger method and adds a file handler per logging level in the `LEVELS` class attribute. """ BaseLogger.new_logger(self) min_logger_level = self.get_logger_level(self.log_level) for level in list(self.LEVELS.keys()): if self.get_logger_level(level) >= min_logger_level: self.log_files[level] = "%s_%s.log" % (self.log_name, level) self.add_file_handler( os.path.join(self.abs_log_dir, self.log_files[level]), log_level=level, ) # ConsoleLogger {{{1 class ConsoleLogger(BaseLogger): """Subclass of the BaseLogger. Output logs to stderr. """ def __init__( self, log_format="%(levelname)8s - %(message)s", log_date_format="%H:%M:%S", logger_name="Console", **kwargs ): """ConsoleLogger constructor. Calls its superclass constructor, creates a new logger instance and log an init message. Args: log_format (str, optional): message format string to instantiate a `logging.Formatter`. Defaults to '%(levelname)8s - %(message)s' **kwargs: Arbitrary keyword arguments passed to the BaseLogger constructor """ BaseLogger.__init__( self, logger_name=logger_name, log_format=log_format, **kwargs ) self.new_logger() self.init_message() def new_logger(self): """Create a new logger based on the ROOT_LOGGER instance. By default there are no handlers. The new logger becomes a member variable of the current instance as `self.logger`. """ self.logger = ROOT_LOGGER self.logger.setLevel(self.get_logger_level()) self._clear_handlers() self.add_console_handler() def numeric_log_level(level): """Converts a mozharness log level (string) to the corresponding logger level (number). This function makes possible to set the log level in functions that do not inherit from LogMixin Args: level (str): log level name to convert. Returns: int: numeric value of the log level name. """ return LOG_LEVELS[level] # __main__ {{{1 if __name__ == "__main__": """Useless comparison, due to the `pass` keyword on its body""" pass