pretty logging

9 files changed, 74 insertions, 64 deletions

diff --git a/kvmd/kvmd.yaml b/kvmd/kvmd.yaml
index 78ef5e07..cfeabf00 100644
--- a/kvmd/kvmd.yaml
+++ b/kvmd/kvmd.yaml
@@ -49,7 +49,7 @@ logging:
             (): contextlog.SmartFormatter
             style: "{"
             datefmt: "%H:%M:%S"
-            format: "[{asctime}] {name:15.15} {levelname:>7} --- {message}"
+            format: "[{asctime}] {name:20.20} {levelname:>7} --- {message}"
 
     handlers:
         console:
diff --git a/kvmd/kvmd/__init__.py b/kvmd/kvmd/__init__.py
index a1eca26b..324b09fb 100644
--- a/kvmd/kvmd/__init__.py
+++ b/kvmd/kvmd/__init__.py
@@ -1,7 +1,7 @@
 import asyncio
-import logging
 
 from .application import init
+from .logging import get_logger
 
 from .atx import Atx
 from .streamer import Streamer
@@ -52,4 +52,4 @@ def main() -> None:
             host=config["server"]["host"],
             port=config["server"]["port"],
         )
-    logging.getLogger(__name__).info("Bye-bye")
+    get_logger().info("Bye-bye")
diff --git a/kvmd/kvmd/atx.py b/kvmd/kvmd/atx.py
index 839f33ce..686531a1 100644
--- a/kvmd/kvmd/atx.py
+++ b/kvmd/kvmd/atx.py
@@ -1,15 +1,13 @@
 import asyncio
-import logging
 
 from typing import Tuple
 
+from .logging import get_logger
+
 from . import gpio
 
 
 # =====
-_logger = logging.getLogger(__name__)
-
-
 class Atx:
     def __init__(
         self,
@@ -39,15 +37,15 @@ class Atx:
 
     async def click_power(self) -> None:
         if (await self.__click(self.__power_switch, self.__click_delay)):
-            _logger.info("Clicked power")
+            get_logger().info("Clicked power")
 
     async def click_power_long(self) -> None:
         if (await self.__click(self.__power_switch, self.__long_click_delay)):
-            _logger.info("Clicked power (long press)")
+            get_logger().info("Clicked power (long press)")
 
     async def click_reset(self) -> None:
         if (await self.__click(self.__reset_switch, self.__click_delay)):
-            _logger.info("Clicked reset")
+            get_logger().info("Clicked reset")
 
     async def __click(self, pin: int, delay: float) -> bool:
         if not self.__lock.locked():
diff --git a/kvmd/kvmd/extras/cleanup/__init__.py b/kvmd/kvmd/extras/cleanup/__init__.py
index 62c1a709..13d27d78 100644
--- a/kvmd/kvmd/extras/cleanup/__init__.py
+++ b/kvmd/kvmd/extras/cleanup/__init__.py
@@ -1,28 +1,27 @@
 import subprocess
-import logging
 import time
 
 from ...application import init
+from ...logging import get_logger
 
 from ... import gpio
 
 
 # =====
-_logger = logging.getLogger(__name__)
-
-
 def main() -> None:
     config = init()
-    _logger.info("Cleaning up ...")
+    logger = get_logger(0)
+
+    logger.info("Cleaning up ...")
     with gpio.bcm():
         for (key, pin) in [
             *config["atx"]["switches"]["pinout"].items(),
             *config["video"]["pinout"].items(),
         ]:
-            _logger.info("Writing value=0 to pin=%d (%s)", pin, key)
+            logger.info("Writing value=0 to pin=%d (%s)", pin, key)
             gpio.write(pin, False)
 
-    _logger.info("Trying to find and kill mjpg_streamer ...")
+    logger.info("Trying to find and kill mjpg_streamer ...")
     try:
         subprocess.check_output(["killall", "mjpg_streamer"], stderr=subprocess.STDOUT)
         time.sleep(3)
@@ -30,4 +29,4 @@ def main() -> None:
     except subprocess.CalledProcessError:
         pass
 
-    _logger.info("Bye-bye")
+    logger.info("Bye-bye")
diff --git a/kvmd/kvmd/gpio.py b/kvmd/kvmd/gpio.py
index a7bdb45c..91c3c86f 100644
--- a/kvmd/kvmd/gpio.py
+++ b/kvmd/kvmd/gpio.py
@@ -1,24 +1,23 @@
 import contextlib
-import logging
 
 from typing import Generator
 
 from RPi import GPIO
 
-
-# =====
-_logger = logging.getLogger(__name__)
+from .logging import get_logger
 
 
+# =====
 @contextlib.contextmanager
 def bcm() -> Generator[None, None, None]:
+    logger = get_logger(2)
     GPIO.setmode(GPIO.BCM)
-    _logger.info("Configured GPIO mode as BCM")
+    logger.info("Configured GPIO mode as BCM")
     try:
         yield
     finally:
         GPIO.cleanup()
-        _logger.info("GPIO cleaned")
+        logger.info("GPIO cleaned")
 
 
 def set_output(pin: int, initial: bool=False) -> int:
diff --git a/kvmd/kvmd/logging.py b/kvmd/kvmd/logging.py
new file mode 100644
index 00000000..838e13d1
--- /dev/null
+++ b/kvmd/kvmd/logging.py
@@ -0,0 +1,15 @@
+import sys
+import logging
+
+
+# =====
+def get_logger(depth: int=1) -> logging.Logger:
+    frame = sys._getframe(1)  # pylint: disable=protected-access
+    frames = []
+    while frame:
+        frames.append(frame)
+        frame = frame.f_back
+        if len(frames) - 1 >= depth:
+            break
+    name = frames[depth].f_globals["__name__"]
+    return logging.getLogger(name)
diff --git a/kvmd/kvmd/ps2.py b/kvmd/kvmd/ps2.py
index 7ba646b4..7711ad6b 100644
--- a/kvmd/kvmd/ps2.py
+++ b/kvmd/kvmd/ps2.py
@@ -1,16 +1,14 @@
 import multiprocessing
 import multiprocessing.queues
 import queue
-import logging
 import time
 
+from .logging import get_logger
+
 from . import gpio
 
 
 # =====
-_logger = logging.getLogger(__name__)
-
-
 class Ps2Keyboard(multiprocessing.Process):
     def __init__(self, clock: int, data: int, pulse: float) -> None:
         super().__init__(daemon=True)
@@ -23,11 +21,11 @@ class Ps2Keyboard(multiprocessing.Process):
         self.__event = multiprocessing.Event()
 
     def start(self) -> None:
-        _logger.info("Starting keyboard daemon ...")
+        get_logger().info("Starting keyboard daemon ...")
         super().start()
 
     def stop(self) -> None:
-        _logger.info("Stopping keyboard daemon ...")
+        get_logger().info("Stopping keyboard daemon ...")
         self.__event.set()
         self.join()
 
@@ -35,17 +33,18 @@ class Ps2Keyboard(multiprocessing.Process):
         self.__queue.put(code)
 
     def run(self) -> None:
-        try:
-            while not self.__event.is_set():
-                try:
-                    code = self.__queue.get(timeout=0.1)
-                except queue.Empty:
-                    pass
-                else:
-                    self.__send_byte(code)
-        except Exception:
-            _logger.exception("Unhandled exception")
-            raise
+        with gpio.bcm():
+            try:
+                while not self.__event.is_set():
+                    try:
+                        code = self.__queue.get(timeout=0.1)
+                    except queue.Empty:
+                        pass
+                    else:
+                        self.__send_byte(code)
+            except Exception:
+                get_logger().exception("Unhandled exception")
+                raise
 
     def __send_byte(self, code: int) -> None:
         code_bits = list(map(bool, bin(code)[2:].zfill(8)))
diff --git a/kvmd/kvmd/server.py b/kvmd/kvmd/server.py
index 3233a7ec..81f928e4 100644
--- a/kvmd/kvmd/server.py
+++ b/kvmd/kvmd/server.py
@@ -1,7 +1,6 @@
 import os
 import signal
 import asyncio
-import logging
 import time
 
 from typing import List
@@ -15,11 +14,10 @@ from .atx import Atx
 from .streamer import Streamer
 from .ps2 import Ps2Keyboard
 
-
-# =====
-_logger = logging.getLogger(__name__)
+from .logging import get_logger
 
 
+# =====
 def _system_task(method: Callable) -> Callable:
     async def wrap(self: "Server") -> None:
         try:
@@ -27,7 +25,7 @@ def _system_task(method: Callable) -> Callable:
         except asyncio.CancelledError:
             pass
         except Exception:
-            _logger.exception("Unhandled exception, killing myself ...")
+            get_logger().exception("Unhandled exception, killing myself ...")
             os.kill(os.getpid(), signal.SIGTERM)
     return wrap
 
@@ -77,7 +75,7 @@ class Server:  # pylint: disable=too-many-instance-attributes
             app=app,
             host=host,
             port=port,
-            print=(lambda text: [_logger.info(line.strip()) for line in text.strip().splitlines()]),  # type: ignore
+            print=(lambda text: [get_logger().info(line.strip()) for line in text.strip().splitlines()]),  # type: ignore
         )
 
     async def __root_handler(self, _: aiohttp.web.Request) -> aiohttp.web.Response:
@@ -97,12 +95,14 @@ class Server:  # pylint: disable=too-many-instance-attributes
         return ws
 
     async def __on_shutdown(self, _: aiohttp.web.Application) -> None:
-        _logger.info("Cancelling system tasks ...")
+        logger = get_logger(0)
+
+        logger.info("Cancelling system tasks ...")
         for task in self.__system_tasks:
             task.cancel()
         await asyncio.gather(*self.__system_tasks)
 
-        _logger.info("Disconnecting clients ...")
+        logger.info("Disconnecting clients ...")
         for ws in list(self.__sockets):
             await self.__remove_socket(ws)
 
@@ -168,21 +168,21 @@ class Server:  # pylint: disable=too-many-instance-attributes
             if method:
                 await method()
                 return None
-        _logger.warning("Received an incorrect command: %r", command)
+        get_logger().warning("Received an incorrect command: %r", command)
         return "ERROR incorrect command"
 
     async def __register_socket(self, ws: aiohttp.web.WebSocketResponse) -> None:
         async with self.__sockets_lock:
             self.__sockets.add(ws)
-            _logger.info("Registered new client socket: remote=%s; id=%d; active=%d",
-                         ws._req.remote, id(ws), len(self.__sockets))  # pylint: disable=protected-access
+            get_logger().info("Registered new client socket: remote=%s; id=%d; active=%d",
+                              ws._req.remote, id(ws), len(self.__sockets))  # pylint: disable=protected-access
 
     async def __remove_socket(self, ws: aiohttp.web.WebSocketResponse) -> None:
         async with self.__sockets_lock:
             try:
                 self.__sockets.remove(ws)
-                _logger.info("Removed client socket: remote=%s; id=%d; active=%d",
-                             ws._req.remote, id(ws), len(self.__sockets))  # pylint: disable=protected-access
+                get_logger().info("Removed client socket: remote=%s; id=%d; active=%d",
+                                  ws._req.remote, id(ws), len(self.__sockets))  # pylint: disable=protected-access
                 await ws.close()
             except Exception:
                 pass
diff --git a/kvmd/kvmd/streamer.py b/kvmd/kvmd/streamer.py
index 8a34de02..2b47925f 100644
--- a/kvmd/kvmd/streamer.py
+++ b/kvmd/kvmd/streamer.py
@@ -1,17 +1,15 @@
 import asyncio
 import asyncio.subprocess
-import logging
 
 from typing import Dict
 from typing import Optional
 
+from .logging import get_logger
+
 from . import gpio
 
 
 # =====
-_logger = logging.getLogger(__name__)
-
-
 class Streamer:  # pylint: disable=too-many-instance-attributes
     def __init__(
         self,
@@ -38,13 +36,13 @@ class Streamer:  # pylint: disable=too-many-instance-attributes
 
     async def start(self) -> None:
         assert not self.__proc_task
-        _logger.info("Starting mjpg_streamer ...")
+        get_logger().info("Starting mjpg_streamer ...")
         await self.__set_hw_enabled(True)
         self.__proc_task = self.__loop.create_task(self.__process())
 
     async def stop(self) -> None:
         assert self.__proc_task
-        _logger.info("Stopping mjpg_streamer ...")
+        get_logger().info("Stopping mjpg_streamer ...")
         self.__proc_task.cancel()
         await asyncio.gather(self.__proc_task, return_exceptions=True)
         await self.__set_hw_enabled(False)
@@ -62,6 +60,8 @@ class Streamer:  # pylint: disable=too-many-instance-attributes
         await asyncio.sleep(self.__sync_delay)
 
     async def __process(self) -> None:
+        logger = get_logger(0)
+
         proc: Optional[asyncio.subprocess.Process] = None  # pylint: disable=no-member
         while True:
             try:
@@ -70,13 +70,13 @@ class Streamer:  # pylint: disable=too-many-instance-attributes
                     stdout=asyncio.subprocess.PIPE,
                     stderr=asyncio.subprocess.STDOUT,
                 )
-                _logger.info("Started mjpg_streamer pid=%d: %s", proc.pid, self.__cmd)
+                logger.info("Started mjpg_streamer pid=%d: %s", proc.pid, self.__cmd)
 
                 empty = 0
                 while proc.returncode is None:
                     line = (await proc.stdout.readline()).decode(errors="ignore").strip()
                     if line:
-                        _logger.info("mjpg_streamer: %s", line)
+                        logger.info("mjpg_streamer: %s", line)
                         empty = 0
                     else:
                         empty += 1
@@ -90,9 +90,9 @@ class Streamer:  # pylint: disable=too-many-instance-attributes
                 break
             except Exception as err:
                 if proc:
-                    _logger.error("Unexpected finished mjpg_streamer pid=%d with retcode=%d", proc.pid, proc.returncode)
+                    logger.exception("Unexpected finished mjpg_streamer pid=%d with retcode=%d", proc.pid, proc.returncode)
                 else:
-                    _logger.error("Can't start mjpg_streamer: %s", err)
+                    logger.exception("Can't start mjpg_streamer: %s", err)
                 await asyncio.sleep(1)
 
         if proc: