Add per-module-build logging feature

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):
     """

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,

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":

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. """

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()