queuelogger: Add critical information to each logfile on rollover

When the log file does a rollover, start the top of the log with
critical system information (eg, software versions).

Signed-off-by: Kevin O'Connor <kevin@koconnor.net>

klippy/klippy.py

@@ -107,19 +107,25 @@ class ConfigWrapper:
         return ConfigWrapper(self.printer, section)
 
 class ConfigLogger():
-    def __init__(self, cfg):
+    def __init__(self, cfg, bglogger):
-        logging.info("===== Config file =====")
+        self.lines = ["===== Config file ====="]
         cfg.write(self)
-        logging.info("=======================")
+        self.lines.append("=======================")
+        data = "\n".join(self.lines)
+        logging.info(data)
+        bglogger.set_rollover_info("config", data)
     def write(self, data):
-        logging.info(data.strip())
+        self.lines.append(data.strip())
 
 class Printer:
     def __init__(self, conffile, input_fd, startup_state
-                 , is_fileinput=False, version="?"):
+                 , is_fileinput=False, version="?", bglogger=None):
         self.conffile = conffile
         self.startup_state = startup_state
         self.software_version = version
+        self.bglogger = bglogger
+        if bglogger is not None:
+            bglogger.set_rollover_info("config", None)
         self.reactor = reactor.Reactor()
         self.objects = {}
         self.gcode = gcode.GCodeParser(self, input_fd, is_fileinput)
@@ -159,8 +165,8 @@ class Printer:
         if not res:
             raise ConfigParser.Error("Unable to open config file %s" % (
                 self.conffile,))
-        if self.debugoutput is None:
+        if self.bglogger is not None:
-            ConfigLogger(self.fileconfig)
+            ConfigLogger(self.fileconfig, self.bglogger)
         self.mcu = mcu.MCU(self, ConfigWrapper(self, 'mcu'))
         if self.debugoutput is not None:
             self.mcu.connect_file(self.debugoutput, self.dictionary)
@@ -308,18 +314,21 @@ def main():
         logging.basicConfig(level=debuglevel)
     logging.info("Starting Klippy...")
     software_version = util.get_git_version()
-    if debugoutput is None:
+    if bglogger is not None:
-        logging.info("Args: %s" % (sys.argv,))
+        lines = ["Args: %s" % (sys.argv,),
-        logging.info("Git version: %s" % (repr(software_version),))
+                 "Git version: %s" % (repr(software_version),),
-        logging.info("CPU: %s" % (util.get_cpu_info(),))
+                 "CPU: %s" % (util.get_cpu_info(),),
-        logging.info("Python: %s" % (repr(sys.version),))
+                 "Python: %s" % (repr(sys.version),)]
+        lines = "\n".join(lines)
+        logging.info(lines)
+        bglogger.set_rollover_info('versions', lines)
 
     # Start firmware
     res = 'startup'
     while 1:
         is_fileinput = debuginput is not None
         printer = Printer(
-            conffile, input_fd, res, is_fileinput, software_version)
+            conffile, input_fd, res, is_fileinput, software_version, bglogger)
         if debugoutput:
             proto_dict = read_dictionary(options.read_dictionary)
             printer.set_fileoutput(debugoutput, proto_dict)

klippy/mcu.py

@@ -385,6 +385,8 @@ class MCU:
         self._restart_method = config.getchoice(
             'restart_method', rmethods, 'arduino')
         # Config building
+        if printer.bglogger is not None:
+            printer.bglogger.set_rollover_info("mcu", None)
         self._config_error = config.error
         self._emergency_stop_cmd = self._reset_cmd = None
         self._oids = []
@@ -575,6 +577,15 @@ class MCU:
             raise error("Printer CRC does not match config")
         move_count = config_params['move_count']
         logging.info("Configured (%d moves)" % (move_count,))
+        if self._printer.bglogger is not None:
+            msgparser = self.serial.msgparser
+            info = [
+                "Configured (%d moves)" % (move_count,),
+                "Loaded %d commands (%s)" % (
+                    len(msgparser.messages_by_id), msgparser.version),
+                "MCU config: %s" % (" ".join(
+                    ["%s=%s" % (k, v) for k, v in msgparser.config.items()]))]
+            self._printer.bglogger.set_rollover_info("mcu", "\n".join(info))
         stepqueues = tuple(s._stepqueue for s in self._steppers)
         self._steppersync = self._ffi_lib.steppersync_alloc(
             self.serial.serialqueue, stepqueues, len(stepqueues), move_count)

klippy/queuelogger.py

@@ -3,7 +3,7 @@
 # Copyright (C) 2016,2017  Kevin O'Connor <kevin@koconnor.net>
 #
 # This file may be distributed under the terms of the GNU GPLv3 license.
-import logging, logging.handlers, threading, Queue
+import logging, logging.handlers, threading, Queue, time
 
 # Class to forward all messages through a queue to a background thread
 class QueueHandler(logging.Handler):
@@ -21,27 +21,39 @@ class QueueHandler(logging.Handler):
             self.handleError(record)
 
 # Class to poll a queue in a background thread and log each message
-class QueueListener(object):
+class QueueListener(logging.handlers.TimedRotatingFileHandler):
-    def __init__(self, handler):
+    def __init__(self, filename):
-        self.handler = handler
+        logging.handlers.TimedRotatingFileHandler.__init__(
-        self.queue = Queue.Queue()
+            self, filename, when='midnight', backupCount=5)
-        self.thread = threading.Thread(target=self._bg_thread)
+        self.bg_queue = Queue.Queue()
-        self.thread.start()
+        self.bg_thread = threading.Thread(target=self._bg_thread)
+        self.bg_thread.start()
+        self.rollover_info = {}
     def _bg_thread(self):
         while 1:
-            record = self.queue.get(True)
+            record = self.bg_queue.get(True)
             if record is None:
                 break
-            self.handler.handle(record)
+            self.handle(record)
     def stop(self):
-        self.queue.put_nowait(None)
+        self.bg_queue.put_nowait(None)
-        self.thread.join()
+        self.bg_thread.join()
+    def set_rollover_info(self, name, info):
+        self.rollover_info[name] = info
+    def doRollover(self):
+        logging.handlers.TimedRotatingFileHandler.doRollover(self)
+        lines = [self.rollover_info[name]
+                 for name in sorted(self.rollover_info)
+                 if self.rollover_info[name]]
+        lines.append(
+            "=============== Log rollover at %s ===============" % (
+                time.asctime(),))
+        self.emit(logging.makeLogRecord(
+            {'msg': "\n".join(lines), 'level': logging.INFO}))
 
 def setup_bg_logging(filename, debuglevel):
-    handler = logging.handlers.TimedRotatingFileHandler(
+    ql = QueueListener(filename)
-        filename, when='midnight', backupCount=5)
+    qh = QueueHandler(ql.bg_queue)
-    ql = QueueListener(handler)
-    qh = QueueHandler(ql.queue)
     root = logging.getLogger()
     root.addHandler(qh)
     root.setLevel(debuglevel)