Return most relevant log file from /compose/log

Return anaconda.log if anaconda is running, composer otherwise

Return packaging.log if it's at least 15s newer than anaconda.log

src/pylorax/api/queue.py

@@ -16,6 +16,8 @@
 """ Functions to monitor compose queue and run anaconda"""
 import logging
 log = logging.getLogger("pylorax")
+program_log = logging.getLogger("program")
+dnf_log = logging.getLogger("dnf")
 
 import os
 import grp
@@ -34,7 +36,7 @@ from pylorax.api.timestamp import TS_CREATED, TS_STARTED, TS_FINISHED, write_tim
 import pylorax.api.toml as toml
 from pylorax.base import DataHolder
 from pylorax.creator import run_creator
-from pylorax.sysutils import joinpaths
+from pylorax.sysutils import joinpaths, read_tail
 
 def check_queues(cfg):
     """Check to make sure the new and run queue symlinks are correct
@@ -136,6 +138,23 @@ def monitor(cfg):
                 # The symlink may vanish if uuid_cancel() has been called
                 continue
 
+            # The anaconda logs are also copied into ./anaconda/ in this directory
+            os.makedirs(joinpaths(dst, "logs"), exist_ok=True)
+
+            def open_handler(loggers, file_name):
+                handler = logging.FileHandler(joinpaths(dst, "logs", file_name))
+                handler.setLevel(logging.DEBUG)
+                handler.setFormatter(logging.Formatter("%(asctime)s %(levelname)s: %(message)s"))
+                for logger in loggers:
+                    logger.addHandler(handler)
+                return (handler, loggers)
+
+            loggers = (((log, program_log, dnf_log), "combined.log"),
+                       ((log,), "composer.log"),
+                       ((program_log,), "program.log"),
+                       ((dnf_log,), "dnf.log"))
+            handlers = [open_handler(loggers, file_name) for loggers, file_name in loggers]
+
             log.info("Starting new compose: %s", dst)
             open(joinpaths(dst, "STATUS"), "w").write("RUNNING\n")
 
@@ -152,6 +171,11 @@ def monitor(cfg):
 #                log.error("Error running compose: %s", e)
                 open(joinpaths(dst, "STATUS"), "w").write("FAILED\n")
                 write_timestamp(dst, TS_FINISHED)
+            finally:
+                for handler, loggers in handlers:
+                    for logger in loggers:
+                        logger.removeHandler(handler)
+                    handler.close()
 
             os.unlink(dst)
 
@@ -179,11 +203,6 @@ def make_compose(cfg, results_dir):
     if not os.path.exists(ks_path):
         raise RuntimeError("Missing kickstart file at %s" % ks_path)
 
-    # The anaconda logs are copied into ./anaconda/ in this directory
-    log_dir = joinpaths(results_dir, "logs/")
-    if not os.path.exists(log_dir):
-        os.makedirs(log_dir)
-
     # Load the compose configuration
     cfg_path = joinpaths(results_dir, "config.toml")
     if not os.path.exists(cfg_path):
@@ -631,20 +650,23 @@ def get_image_name(uuid_dir):
     return (image_name, joinpaths(uuid_dir, image_name))
 
 def uuid_log(cfg, uuid, size=1024):
-    """Return `size` kbytes from the end of the anaconda.log
+    """Return `size` KiB from the end of the most currently relevant log for a
+    given compose
 
     :param cfg: Configuration settings
     :type cfg: ComposerConfig
     :param uuid: The UUID of the build
     :type uuid: str
-    :param size: Number of kbytes to read. Default is 1024
+    :param size: Number of KiB to read. Default is 1024
     :type size: int
-    :returns: Up to `size` kbytes from the end of the log
+    :returns: Up to `size` KiB from the end of the log
     :rtype: str
     :raises: RuntimeError if there was a problem (eg. no log file available)
 
-    This function tries to return lines from the end of the log, it will
+    This function will return the end of either the anaconda log, the packaging
-    attempt to start on a line boundry, and may return less than `size` kbytes.
+    log, or the combined composer logs, depending on the progress of the
+    compose. It tries to return lines from the end of the log, it will attempt
+    to start on a line boundary, and it may return less than `size` kbytes.
     """
     uuid_dir = joinpaths(cfg.get("composer", "lib_dir"), "results", uuid)
     if not os.path.exists(uuid_dir):
@@ -656,20 +678,29 @@ def uuid_log(cfg, uuid, size=1024):
     if status is None:
         raise RuntimeError("Status is missing for %s" % uuid)
 
-    if status["queue_status"] == "RUNNING":
+    def get_log_path():
-        log_path = "/tmp/anaconda.log"
+        # Try to return the most relevant log at any given time during the
-    else:
+        # compose. If the compose is not running, return the composer log.
-        log_path = joinpaths(uuid_dir, "logs", "anaconda", "anaconda.log")
+        anaconda_log = "/tmp/anaconda.log"
-    if not os.path.exists(log_path):
+        packaging_log = "/tmp/packaging.log"
-        raise RuntimeError("No anaconda.log available.")
+        combined_log = joinpaths(uuid_dir, "logs", "combined.log")
-
+        if status["queue_status"] != "RUNNING" or not os.path.isfile(anaconda_log):
-    with open(log_path, "r") as f:
+            return combined_log
-        f.seek(0, 2)
+        if not os.path.isfile(packaging_log):
-        end = f.tell()
+            return anaconda_log
-        if end < 1024 * size:
+        try:
-            f.seek(0, 0)
+            anaconda_mtime = os.stat(anaconda_log).st_mtime
-        else:
+            packaging_mtime = os.stat(packaging_log).st_mtime
-            f.seek(end - (1024 * size))
+            # If the packaging log exists and its last message is at least 15
-        # Find the start of the next line and return the rest
+            # seconds newer than the anaconda log, return the packaging log.
-        f.readline()
+            if packaging_mtime > anaconda_mtime + 15:
-        return f.read()
+                return packaging_log
+            return anaconda_log
+        except OSError:
+            # Return the combined log if anaconda_log or packaging_log disappear
+            return combined_log
+    try:
+        tail = read_tail(get_log_path(), size)
+    except OSError as e:
+        raise RuntimeError("No log available.") from e
+    return tail

src/pylorax/api/v0.py

@@ -2006,13 +2006,15 @@ def v0_compose_image(uuid):
 @v0_api.route("/compose/log/<uuid>")
 @checkparams([("uuid","", "no UUID given")])
 def v0_compose_log_tail(uuid):
-    """Return the end of the main anaconda.log, defaults to 1Mbytes
+    """Return the tail of the most currently relevant log
 
-    **/api/v0/compose/log/<uuid>[?size=kbytes]**
+    **/api/v0/compose/log/<uuid>[?size=KiB]**
 
-      Returns the end of the anaconda.log. The size parameter is optional and defaults to 1Mbytes
+      Returns the end of either the anaconda log, the packaging log, or the
-      if it is not included. The returned data is raw text from the end of the logfile, starting on
+      composer logs, depending on the progress of the compose. The size
-      a line boundry.
+      parameter is optional and defaults to 1 MiB if it is not included.  The
+      returned data is raw text from the end of the log file, starting on a
+      line boundary.
 
       Example::
 

src/pylorax/sysutils.py

@@ -130,3 +130,16 @@ def flatconfig(filename):
     config = UnquotingConfigParser()
     config.read_string(conftext)
     return config['main']
+
+def read_tail(path, size):
+    """Read up to `size` kibibytes from the end of a file"""
+    with open(path, "r") as f:
+        f.seek(0, 2)
+        end = f.tell()
+        if end < 1024 * size:
+            f.seek(0, 0)
+        else:
+            f.seek(end - (1024 * size))
+        # Find the start of the next line and return the rest
+        f.readline()
+        return f.read()