logging: Use RotatingFileHandler to trim logfile at 5MB

Remove all direct uses of args.logfd: everything goes through the logger now.

Only the container manager process is allowed to write to the log, which now
has 0o644 permissions.

Other commands will only log to stdout. Logs that would previously appear
in the logfile will now only be visible with --details-to-stdout.

diff --git a/tools/helpers/logging.py b/tools/helpers/logging.py
index 768f2bf4d6b3f2352a18d1d7f71aef601ab0cc93..4b337351b5ccf618ad642b4abc7c0828010e4e83 100644 (file)
--- a/tools/helpers/logging.py
+++ b/tools/helpers/logging.py
@@ -1,33 +1,30 @@
 # Copyright 2021 Oliver Smith
 # SPDX-License-Identifier: GPL-3.0-or-later
 import logging
+from logging.handlers import RotatingFileHandler
 import os
 import sys
 
 
-class log_handler(logging.StreamHandler):
+class stdout_logger(logging.StreamHandler):
     """
     Write to stdout and to the already opened log file.
     """
     _args = None
 
     def emit(self, record):
+        # INFO or higher: Write to stdout
+        if self._args.quiet or (
+                record.levelno < logging.INFO and
+                not self._args.details_to_stdout):
+            return
+
         try:
             msg = self.format(record)
-
-            # INFO or higher: Write to stdout
-            if (not self._args.details_to_stdout and
-                not self._args.quiet and
-                    record.levelno >= logging.INFO):
-                stream = self.stream
-                stream.write(msg)
-                stream.write(self.terminator)
-                self.flush()
-
-            # Everything: Write to logfd
-            msg = "(" + str(os.getpid()).zfill(6) + ") " + msg
-            self._args.logfd.write(msg + "\n")
-            self._args.logfd.flush()
+            stream = self.stream
+            stream.write(msg)
+            stream.write(self.terminator)
+            self.flush()
 
         except (KeyboardInterrupt, SystemExit):
             raise
@@ -55,35 +52,8 @@ def add_verbose_log_level():
 
 
 def init(args):
-    """
-    Set log format and add the log file descriptor to args.logfd, add the
-    verbose log level.
-    """
-    # Set log file descriptor (logfd)
-    if args.details_to_stdout:
-        setattr(args, "logfd", sys.stdout)
-    else:
-        # Require containing directory to exist (so we don't create the work
-        # folder and break the folder migration logic, which needs to set the
-        # version upon creation)
-        dir = os.path.dirname(args.log)
-        if os.path.exists(dir):
-            setattr(args, "logfd", open(args.log, "a+"))
-            try:
-                os.chmod(args.log, 0o666)
-            except PermissionError:
-                pass
-        else:
-            setattr(args, "logfd", open(os.devnull, "a+"))
-            if args.action != "init":
-                print("WARNING: Can't create log file in '" + dir + "', path"
-                      " does not exist!")
-
-    # Set log format
     root_logger = logging.getLogger()
     root_logger.handlers = []
-    formatter = logging.Formatter("[%(asctime)s] %(message)s",
-                                  datefmt="%H:%M:%S")
 
     # Set log level
     add_verbose_log_level()
@@ -91,12 +61,20 @@ def init(args):
     if args.verbose:
         root_logger.setLevel(logging.VERBOSE)
 
-    # Add a custom log handler
-    handler = log_handler()
-    log_handler._args = args
-    handler.setFormatter(formatter)
+    # Add custom stdout log handler
+    handler = stdout_logger()
+    handler._args = args
+    handler.setFormatter(logging.Formatter("[%(asctime)s] %(message)s",
+                                  datefmt="%H:%M:%S"))
     root_logger.addHandler(handler)
 
+    # Add file log handler
+    if args.action == "container" and not args.details_to_stdout:
+        os.chmod(args.log, 0o644)
+        handler = RotatingFileHandler(args.log, maxBytes=5*1024*1024)
+        handler.setFormatter(logging.Formatter("(%(process)d) [%(asctime)s] %(message)s",
+                                      datefmt="%H:%M:%S"))
+        root_logger.addHandler(handler)
 
 def disable():
     logger = logging.getLogger()

diff --git a/tools/helpers/run_core.py b/tools/helpers/run_core.py
index dcc4c53682755dcc501cba5e1915b6cee204f0bf..88322166422df15003ad6d439ae3df9eab903df9 100644 (file)
--- a/tools/helpers/run_core.py
+++ b/tools/helpers/run_core.py
@@ -35,18 +35,27 @@ def sanity_checks(output="log", output_return=False, check=None):
         raise RuntimeError("Can't use output_return with output: " + output)
 
 
+def forward_stream(pipe, level):
+    with pipe:
+        for line in iter(pipe.readline, b''):
+            logging.log(level, line.decode(errors="replace").rstrip())
+
+
 def background(args, cmd, working_dir=None):
     """ Run a subprocess in background and redirect its output to the log. """
-    ret = subprocess.Popen(cmd, stdout=args.logfd, stderr=args.logfd,
-                           cwd=working_dir)
-    logging.debug("New background process: pid={}, output=background".format(ret.pid))
-    return ret
+    proc = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE,
+                            cwd=working_dir)
+    threading.Thread(target=forward_stream, args=(proc.stdout, logging.DEBUG), daemon=True).start()
+    threading.Thread(target=forward_stream, args=(proc.stderr, logging.DEBUG), daemon=True).start()
+    logging.debug("New background process: pid={}, output=background".format(proc.pid))
+    return proc
 
 
 def pipe(args, cmd, working_dir=None):
     """ Run a subprocess in background and redirect its output to a pipe. """
-    ret = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=args.logfd,
+    ret = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE,
                            cwd=working_dir)
+    threading.Thread(target=forward_stream, args=(proc.stderr, logging.DEBUG), daemon=True).start()
     logging.verbose("New background process: pid={}, output=pipe".format(ret.pid))
     return ret
 
@@ -69,7 +78,7 @@ def pipe_read(args, process, output_to_stdout=False, output_return=False,
         # Copy available output
         out = process.stdout.readline()
         if len(out):
-            args.logfd.buffer.write(out)
+            logging.debug(out.decode(errors="replace").rstrip())
             if output_to_stdout:
                 sys.stdout.buffer.write(out)
             if output_return:
@@ -77,7 +86,6 @@ def pipe_read(args, process, output_to_stdout=False, output_return=False,
             continue
 
         # No more output (flush buffers)
-        args.logfd.flush()
         if output_to_stdout:
             sys.stdout.flush()
         return