Merge #1764 local builds: improve handling of build.log

module_build_service/common/config.py

@@ -79,6 +79,7 @@ class LocalBuildConfiguration(BaseConfiguration):
     CACHE_DIR = "~/modulebuild/cache"
     LOG_LEVEL = "debug"
     MESSAGING = "drop"
+    BUILD_LOGS_NAME_FORMAT = "build.log"
 
     ALLOW_CUSTOM_SCMURLS = True
     RESOLVER = "mbs"

module_build_service/common/logger.py

@@ -22,6 +22,7 @@ logging.warning("%s failed to build", task_id)
 from __future__ import absolute_import
 import os
 import logging
+import logging.handlers
 import inspect
 
 levels = {
@@ -65,6 +66,47 @@ class ModuleBuildFileHandler(logging.FileHandler):
         logging.FileHandler.emit(self, record)
 
 
+def _is_solv_object(o):
+    """
+    Returns true if the object is a libsolv object or contains one.
+    (Contains is implemented pragmatically and might need to be extended)
+    """
+    if isinstance(o, (tuple, list)):
+        return any(_is_solv_object(x) for x in o)
+    else:
+        return str(type(o)).startswith("<class 'solv.")
+
+
+class _ReprString(str):
+    """
+    String that doesn't add quotes for repr()
+    """
+    def __repr__(self):
+        return self
+
+
+class ModuleBuildInitialHandler(logging.handlers.MemoryHandler):
+    """
+    MemoryHandler subclass that never flushes - we use this to record initial log
+    messages for a Mock build so that we can write them into the build logs for
+    the module or modules.
+    """
+    def __init__(self):
+        logging.handlers.MemoryHandler.__init__(self, 0, flushOnClose=False)
+
+    def handle(self, record):
+        # Python libsolv proxies don't actually reference the underlying object
+        # and keep it from being destroyed, so we need to avoid saving them
+        # in record.args
+        if any(_is_solv_object(a) for a in record.args):
+            record.args = tuple(_ReprString(a) if _is_solv_object(a) else a for a in record.args)
+
+        logging.handlers.MemoryHandler.handle(self, record)
+
+    def shouldFlush(self, record):
+        return False
+
+
 class ModuleBuildLogs(object):
     """
     Manages ModuleBuildFileHandler logging handlers.
@@ -75,6 +117,8 @@ class ModuleBuildLogs(object):
         Creates new ModuleBuildLogs instance. Module build logs are stored
         to `build_logs_dir` directory.
         """
+        self.initial_handler = None
+        self.initial_logs = []
         self.handlers = {}
         self.build_logs_dir = build_logs_dir
         self.build_logs_name_format = build_logs_name_format
@@ -94,6 +138,20 @@ class ModuleBuildLogs(object):
         name = self.build_logs_name_format.format(**build.json(db_session))
         return name
 
+    def buffer_initially(self):
+        """
+        Starts saving messages before builds start - these messages will be
+        added to all build logs
+        """
+        handler = ModuleBuildInitialHandler()
+        handler.setLevel(self.level)
+
+        log = logging.getLogger()
+        log.setLevel(self.level)
+        log.addHandler(handler)
+
+        self.initial_handler = handler
+
     def start(self, db_session, build):
         """
         Starts logging build log for module with `build_id` id.
@@ -101,6 +159,16 @@ class ModuleBuildLogs(object):
         if not self.build_logs_dir:
             return
 
+        log = logging.getLogger()
+
+        # We've finished recording the initial setup logs that we replay
+        # to all the build logs.
+        if self.initial_handler:
+            log = logging.getLogger()
+            self.initial_logs = self.initial_handler.buffer
+            log.removeHandler(self.initial_handler)
+            self.initial_handler = None
+
         if build.id in self.handlers:
             return
 
@@ -108,10 +176,13 @@ class ModuleBuildLogs(object):
         handler = ModuleBuildFileHandler(build.id, self.path(db_session, build))
         handler.setLevel(self.level)
         handler.setFormatter(logging.Formatter(log_format, None))
-        log = logging.getLogger()
         log.setLevel(self.level)
         log.addHandler(handler)
 
+        # Replay the initial logs to this handler
+        for record in self.initial_logs:
+            handler.handle(record)
+
         self.handlers[build.id] = handler
 
     def stop(self, build):

module_build_service/manage.py

@@ -16,7 +16,7 @@ from module_build_service import app, db
 from module_build_service.builder.MockModuleBuilder import (
     import_builds_from_local_dnf_repos, load_local_builds
 )
-from module_build_service.common import conf, models
+from module_build_service.common import build_logs, conf, models
 from module_build_service.common.errors import StreamAmbigous, StreamNotXyz
 from module_build_service.common.utils import load_mmd_file, import_mmd
 import module_build_service.scheduler.consumer
@@ -130,6 +130,10 @@ def build_module_locally(
 ):
     """ Performs local module build using Mock
     """
+    # accumulate initial log messages in memory - we'll output them to a log in the
+    # module build directories when we know what they are
+    build_logs.buffer_initially()
+
     # if debug is not specified, set log level of console to INFO
     if not log_debug:
         for handler in logging.getLogger().handlers: