Local builds: buffer up initial logs and replay to the module build file

Logging during a build that occurs before the build directory is created
used to be logged to the console, but not retained in the build log
file. This made referring to the build log file confusing. Solve this
by buffering logs in memory until the log file is created and replaying
them.

A little bit of hackery is needed to avoid saving dangling references to
libsolv objects.

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: