[elbe-devel] [PATCH v3 11/52] log.py - New logging system

[dion at linutronix.de]

From: Olivier Dion <dion at linutronix.de>

* Logger objects

  By default, all logged message go to "log.txt" and to the SOAP
  server.  Thus, using 'logging.debug' is enough in most cases.

  However, we might sometime only send to the SOAP server, or write to
  a different files than "log.txt".  This is done using different
  loggers.

** logging

   Using 'logging' allows to write to "log.txt" and the SOAP server.

** log

   Using 'log' only write to "log.txt".

** validation

   Using 'validation' only write to "validation.txt".

** report

   Using 'report' only write to "elbe-report.txt".

** soap

   Using 'soap' only write to the SOAP server.

** Example

   ```````````````````````````````````````````````````````````````````
   import logging

   log = logging.getLogger("log")
   validation = logging.getLogger("validation")
   report = logging.getLogger("report")
   soap = logging.getLogger("soap")

   logging.debug("logging")
   log.debug("log")
   validation.debug("validation")
   report.debug("report")
   soap.debug("soap")
   ```````````````````````````````````````````````````````````````````

   log.txt
   -------------------------------------------------------------------
   logging
   log
   -------------------------------------------------------------------

   validation.txt
   -------------------------------------------------------------------
   validation
   -------------------------------------------------------------------

   elbe-report.txt
   -------------------------------------------------------------------
   report
   -------------------------------------------------------------------

   SOAP
   -------------------------------------------------------------------
   logging
   soap
   -------------------------------------------------------------------

* elbe_logging context manager

  Since multiple threads can work on multiple projects and since
  logging is shared between threads, this context manager allows to
  register handlers for that thread and remove them after.

* QHandler

  Simply push a record' message to a queue.  It can then be read
  later, e.g. with /wait_busy/.

* async_logging

  This function take a pipe and two logging objects, one streaming and
  one block, it then launch another thread.

  That thread proceed to read from the reading end of the pipe and
  write to the streaming logging object every time a newline is
  encountered.

  When the writting end of the pipe is closed, everything that has
  been readed through the pipe is logged to the block logging object
  in one message.

Signed-off-by: Olivier Dion <dion at linutronix.de>
Acked-by: Torben Hohn <torben.hohn at linutronix.de>
---
 elbepack/log.py | 176 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 176 insertions(+)
 create mode 100644 elbepack/log.py

diff --git a/elbepack/log.py b/elbepack/log.py
new file mode 100644
index 00000000..53d41e64
--- /dev/null
+++ b/elbepack/log.py
@@ -0,0 +1,176 @@
+# ELBE - Debian Based Embedded Rootfilesystem Builder
+# Copyright (c) 2019 Olivier Dion <dion at linutronix.de>
+#
+# SPDX-License-Identifier: GPL-3.0-or-later
+
+import os
+import logging
+import threading
+import collections
+from contextlib import contextmanager
+
+class QHandler(logging.Handler):
+
+    queues = {}
+
+    def __init__(self, target, *args, **kwargs):
+        super(QHandler, self).__init__(*args, **kwargs)
+        if target not in QHandler.queues:
+            QHandler.queues[target] = collections.deque(maxlen=1024)
+        self.Q = QHandler.queues[target]
+
+    def emit(self, record):
+        self.Q.append(self.format(record))
+
+    @classmethod
+    def pop(cls, target):
+        try:
+            return cls.queues[target].popleft()
+        except (IndexError, KeyError):
+            return ''
+
+class ThreadFilter(logging.Filter):
+
+    def __init__(self, allowed, *args, **kwargs):
+        super(ThreadFilter, self).__init__(*args, **kwargs)
+        self.allowed = allowed
+        self.thread = threading.current_thread().ident
+
+    def filter(self, record):
+        if hasattr(record, '_thread'):
+            thread = record._thread
+        else:
+            thread = record.thread
+        retval = record.name in self.allowed and thread == self.thread
+        if retval and not hasattr(record, 'context'):
+            record.context = "[%s] " % record.levelname
+        return retval
+
+root = logging.getLogger()
+root.setLevel(logging.DEBUG)
+local = threading.local()
+normal_fmt = logging.Formatter("%(context)s%(message)s")
+
+
+ at contextmanager
+def elbe_logging(*args, **kwargs):
+    try:
+        open_logging(*args, **kwargs)
+        yield
+    finally:
+        close_logging()
+
+def open_logging(builddir=None, stdout=False):
+
+    if stdout:
+        out = logging.StreamHandler()
+        out.setFormatter(normal_fmt)
+        out.addFilter(ThreadFilter(['root' 'log', 'report', 'validation', 'echo', 'soap']))
+        root.addHandler(out)
+        local.handlers = [out]
+        return
+
+    # Handlers
+    validation = logging.FileHandler(os.path.join(builddir, "validation.txt"))
+    report = logging.FileHandler(os.path.join(builddir, "elbe-report.txt"))
+    log = logging.FileHandler(os.path.join(builddir, "log.txt"))
+    echo = QHandler(builddir)
+    soap = QHandler(builddir)
+    local.handlers = [validation, report, log, echo, soap]
+
+    # Filter
+    validation.addFilter(ThreadFilter(['validation']))
+    report.addFilter(ThreadFilter(['report']))
+    log.addFilter(ThreadFilter(['root', 'log']))
+    echo.addFilter(ThreadFilter(['root', 'report', 'validation']))
+    soap.addFilter(ThreadFilter(['soap']))
+
+    # Fmt
+    validation.setFormatter(normal_fmt)
+    report.setFormatter(normal_fmt)
+    log.setFormatter(normal_fmt)
+    echo.setFormatter(normal_fmt)
+    soap.setFormatter(normal_fmt)
+
+    # Registering
+    root.addHandler(validation)
+    root.addHandler(report)
+    root.addHandler(log)
+    root.addHandler(echo)
+    root.addHandler(soap)
+
+
+def close_logging():
+    for h in local.handlers:
+        root.removeHandler(h)
+    local.handlers = []
+
+
+def read_loggingQ(builddir):
+    return QHandler.pop(builddir)
+
+
+import select
+
+def async_logging(r, w, stream, block, atmost=80):
+    t = threading.Thread(target=AsyncLogging(atmost, stream, block),
+                         args=(r, w))
+    t.daemon = True
+    t.start()
+
+
+class AsyncLogging(object):
+
+    def __init__(self, atmost, stream, block):
+        self.lines = []
+        self.epoll = select.epoll()
+        self.atmost = atmost
+        self.fd = None
+        calling_thread = threading.current_thread().ident
+        extra = {"_thread":calling_thread}
+        extra["context"] = ""
+        self.stream = logging.LoggerAdapter(stream, extra)
+        self.block = logging.LoggerAdapter(block, extra)
+
+    def __call__(self, r, w):
+        os.close(w)
+        self.epoll.register(r, select.EPOLLIN | select.EPOLLHUP)
+        self.fd = r
+        try:
+            self.run()
+        finally:
+            os.close(r)
+
+    def run(self):
+        alive = True
+        rest = ""
+        while alive:
+            events = self.epoll.poll()
+            for fd, event in events:
+                if event & select.EPOLLIN:
+                    rest = self.read(rest)
+                if event & select.EPOLLHUP:
+                    alive = False
+
+        # Reading rest after pipe hang up
+        while True:
+            rest = self.read(rest)
+            if not rest:
+                break
+
+        if self.lines:
+            self.lines[-1] += rest
+            self.block.info("\n".join(self.lines))
+
+    def read(self, rest):
+        buff = rest + os.read(self.fd, self.atmost)
+        j = 0
+        count = 0
+        for i in xrange(len(buff)):
+            if buff[i] == '\n':
+                self.lines.append(buff[j:i])
+                count += 1
+                j = i + 1
+        if count:
+            self.stream.info("\n".join(self.lines[-count:]))
+        return buff[j:]
-- 
2.11.0