master/log: parse names, better filtering, cleanup

artiq/master/log.py

@@ -1,5 +1,4 @@
 import logging
-import time
 
 from artiq.protocols.sync_struct import Notifier
 
@@ -9,10 +8,10 @@ class LogBuffer:
         self.depth = depth
         self.data = Notifier([])
 
-    def log(self, level, source, message):
+    def log(self, level, source, time, message):
         if len(self.data.read) >= self.depth:
             del self.data[0]
-        self.data.append((level, source, time.time(), message))
+        self.data.append((level, source, time, message))
 
 
 class LogBufferHandler(logging.Handler):
@@ -22,8 +21,7 @@ class LogBufferHandler(logging.Handler):
 
     def emit(self, record):
         message = self.format(record)
-        source = getattr(record, "source", "master")
-        self.log_buffer.log(record.levelno, source, message)
+        self.log_buffer.log(record.levelno, record.source, record.created, message)
 
 
 name_to_level = {
@@ -39,15 +37,24 @@ name_to_level = {
 def parse_log_message(msg):
     for name, level in name_to_level.items():
         if msg.startswith(name + ":"):
-            return level, msg[len(name) + 1:]
-    return logging.INFO, msg
+            remainder = msg[len(name) + 1:]
+            try:
+                idx = remainder.index(":")
+            except:
+                continue
+            return level, remainder[:idx], remainder[idx+1:]
+    return logging.INFO, "print", msg
+
+
+fwd_logger = logging.getLogger("fwd")
 
 
 class LogForwarder:
     def log_worker(self, rid, message):
-        level, message = parse_log_message(message)
-        logging.log(level, message,
-                    extra={"source": "worker:{}".format(rid)})
+        level, name, message = parse_log_message(message)
+        fwd_logger.name = name
+        fwd_logger.log(level, message,
+                       extra={"source": "worker({})".format(rid)})
     log_worker.worker_pass_rid = True
 
 
@@ -56,11 +63,14 @@ class SourceFilter:
         self.master_level = master_level
 
     def filter(self, record):
-        # log messages that are forwarded from a source have already
-        # been filtered, and may have a level below the master level.
-        if hasattr(record, "source"):
+        if not hasattr(record, "source"):
+            record.source = "master"
+        if record.source == "master":
+            return record.levelno >= self.master_level
+        else:
+            # log messages that are forwarded from a source have already
+            # been filtered, and may have a level below the master level.
             return True
-        return record.levelno >= self.master_level
 
 
 def log_args(parser):
@@ -73,12 +83,12 @@ def log_args(parser):
 
 def init_log(args):
     root_logger = logging.getLogger()
-    root_logger.setLevel(logging.NOTSET) # we use our custom filter only
+    root_logger.setLevel(logging.NOTSET)  # we use our custom filter only
     flt = SourceFilter(logging.WARNING + args.quiet*10 - args.verbose*10)
 
     handlers = []
     console_handler = logging.StreamHandler()
-    console_handler.setFormatter(logging.Formatter("%(levelname)s:%(name)s:%(message)s"))
+    console_handler.setFormatter(logging.Formatter("%(levelname)s:%(source)s:%(name)s:%(message)s"))
     handlers.append(console_handler)
     
     log_buffer = LogBuffer(1000)