From 93092a43bea4711ac8010cb9b3afb28b4cdaa542 Mon Sep 17 00:00:00 2001 From: Jan Kaluza Date: Fri, 30 Jun 2017 16:29:24 +0200 Subject: [PATCH] Add per-module-build logging feature --- module_build_service/__init__.py | 3 +- module_build_service/config.py | 4 + module_build_service/logger.py | 82 ++++++++++++++++++- module_build_service/scheduler/consumer.py | 9 ++ .../scheduler/handlers/modules.py | 7 +- 5 files changed, 102 insertions(+), 3 deletions(-) diff --git a/module_build_service/__init__.py b/module_build_service/__init__.py index 60ef8a0f..856d3451 100644 --- a/module_build_service/__init__.py +++ b/module_build_service/__init__.py @@ -44,7 +44,7 @@ from flask import Flask, has_app_context, url_for from flask_sqlalchemy import SQLAlchemy from logging import getLogger -from module_build_service.logger import init_logging +from module_build_service.logger import init_logging, ModuleBuildLogs from module_build_service.errors import ( ValidationError, Unauthorized, UnprocessableEntity, Conflict, NotFound, @@ -102,6 +102,7 @@ def notfound_error(e): init_logging(conf) log = getLogger(__name__) +build_logs = ModuleBuildLogs(conf.build_logs_dir) def get_url_for(*args, **kwargs): """ diff --git a/module_build_service/config.py b/module_build_service/config.py index 34198830..ff8768f8 100644 --- a/module_build_service/config.py +++ b/module_build_service/config.py @@ -257,6 +257,10 @@ class Config(object): 'type': str, 'default': 0, 'desc': 'Log level'}, + 'build_logs_dir': { + 'type': Path, + 'default': "", + 'desc': 'Directory to store module build logs to.'}, 'krb_keytab': { 'type': None, 'default': None, diff --git a/module_build_service/logger.py b/module_build_service/logger.py index 5c442a24..c48b8ee4 100644 --- a/module_build_service/logger.py +++ b/module_build_service/logger.py @@ -42,6 +42,7 @@ logging.warn("%s failed to build", task_id) """ +import os import logging levels = {} @@ -50,6 +51,86 @@ levels["error"] = logging.ERROR levels["warning"] = logging.WARNING levels["info"] = logging.INFO +log_format = '%(asctime)s - %(threadName)s - %(name)s - %(levelname)s - %(message)s' + +class ModuleBuildFileHandler(logging.FileHandler): + """ + FileHandler subclass which handles only messages generated during + particular module build with `build_id` set in its constructor. + """ + def __init__(self, build_id, filename, mode='a', encoding=None, delay=0): + logging.FileHandler.__init__(self, filename, mode, encoding, delay) + self.build_id = build_id + + def emit(self, record): + # Imported here because of importing cycle between __init__.py, + # scheduler and models. + from module_build_service.scheduler.consumer import MBSConsumer + + # Check the currently handled module build and emit the message only + # if it's associated with current module. + build_id = MBSConsumer.current_module_build_id + if not build_id or build_id != self.build_id: + return + + logging.FileHandler.emit(self, record) + + +class ModuleBuildLogs(object): + """ + Manages ModuleBuildFileHandler logging handlers. + """ + def __init__(self, build_logs_dir): + """ + Creates new ModuleBuildLogs instance. Module build logs are stored + to `build_logs_dir` directory. + """ + self.handlers = {} + self.build_logs_dir = build_logs_dir + + def path(self, build_id): + """ + Returns the full path to build log of module with id `build_id`. + """ + path = os.path.join(self.build_logs_dir, "build-%d.log" % build_id) + return path + + def start(self, build_id): + """ + Starts logging build log for module with `build_id` id. + """ + if not self.build_logs_dir: + return + + if build_id in self.handlers: + return + + # Create and add ModuleBuildFileHandler. + handler = ModuleBuildFileHandler(build_id, self.path(build_id)) + handler.setFormatter(logging.Formatter(log_format, None)) + log = logging.getLogger() + log.addHandler(handler) + + self.handlers[build_id] = handler + + def stop(self, build_id): + """ + Stops logging build log for module with `build_id` id. It does *not* + remove the build log from fs. + """ + if build_id not in self.handlers: + return + + handler = self.handlers[build_id] + handler.flush() + handler.close() + + # Remove the log handler. + log = logging.getLogger() + log.removeHandler(handler) + del self.handlers[build_id] + + def str_to_log_level(level): """ Returns internal representation of logging level defined @@ -69,7 +150,6 @@ def init_logging(conf): """ Initializes logging according to configuration file. """ - log_format = '%(asctime)s - %(threadName)s - %(name)s - %(levelname)s - %(message)s' log_backend = conf.log_backend if not log_backend or len(log_backend) == 0 or log_backend == "console": diff --git a/module_build_service/scheduler/consumer.py b/module_build_service/scheduler/consumer.py index 5f601051..a9a363fb 100644 --- a/module_build_service/scheduler/consumer.py +++ b/module_build_service/scheduler/consumer.py @@ -55,6 +55,11 @@ class MBSConsumer(fedmsg.consumers.FedmsgConsumer): log.debug('Setting topics: {}'.format(', '.join(topic))) config_key = 'mbsconsumer' + # It is set to the id of currently handled module build. It is used to + # group all the log messages associated with single module build to + # per module build log file. + current_module_build_id = None + def __init__(self, hub): super(MBSConsumer, self).__init__(hub) @@ -202,6 +207,8 @@ class MBSConsumer(fedmsg.consumers.FedmsgConsumer): log.debug("No module associated with msg {}".format(msg.msg_id)) return + MBSConsumer.current_module_build_id = build.id + # Execute our chosen handler idx = "%s: %s, %s" % (handler.__name__, type(msg).__name__, msg.msg_id) if handler is self.NO_OP: @@ -231,6 +238,8 @@ class MBSConsumer(fedmsg.consumers.FedmsgConsumer): log.info(" Scheduling faked event %r" % event) self.incoming.put(event) + MBSConsumer.current_module_build_id = None + def get_global_consumer(): """ Return a handle to the active consumer object, if it exists. """ diff --git a/module_build_service/scheduler/handlers/modules.py b/module_build_service/scheduler/handlers/modules.py index d277fc5f..af679ee3 100644 --- a/module_build_service/scheduler/handlers/modules.py +++ b/module_build_service/scheduler/handlers/modules.py @@ -23,7 +23,7 @@ """ Handlers for module change events on the message bus. """ -from module_build_service import conf, models, log +from module_build_service import conf, models, log, build_logs import module_build_service.builder import module_build_service.pdc import module_build_service.utils @@ -100,6 +100,7 @@ def failed(config, session, msg): build.transition(config, state="failed") session.commit() + build_logs.stop(build.id) def done(config, session, msg): @@ -126,6 +127,8 @@ def done(config, session, msg): build.transition(config, state="ready") session.commit() + build_logs.stop(build.id) + def wait(config, session, msg): """ Called whenever a module enters the 'wait' state. @@ -149,6 +152,8 @@ def wait(config, session, msg): .format(build)) build = _get_build_containing_xmd_for_mbs() + build_logs.start(build.id) + log.info("Found build=%r from message" % build) module_info = build.json()