cleanup logger names and logging

CHANGELOG.md

@@ -70,11 +70,15 @@ automation setup much in order to interface with this version of MQTTany.
   * Updated Adafruit Platform Detect version from 1.x to 2.x.
   * **GPIO** - Change language for `direction` to `pin mode` to be less specific and lay
     ground work for additional pin modes.
+  * Consolidate `get_module_logger` and `get_logger` into single function and remove
+    leading `mqttany` from all logger names.
 
 * **Fixed**
   * Remove requirements file for old MCP230xx module that was removed in v0.10.0.
   * Fix logger checking if ``TRACE`` logging was enabled for ``WARN`` messages.
   * Core not exiting correctly if an exception occurred in the core.
+  * Logging not truncating process name or logger name, this could have resulted in
+    misaligned log entries.
 
 ## 0.11.0
 

mqttany/bus.py

@@ -44,7 +44,7 @@
     ATTR_NODES,
 )
 
-log = logger.get_module_logger("bus")
+log = logger.get_logger("bus")
 
 # Communication module queues
 receive_queue = mproc.Queue()
@@ -70,7 +70,7 @@ class ReceiveThread(threading.Thread):
 
     def __init__(self):
         super().__init__(name="Receive")
-        self.log = logger.get_module_logger("bus.receive")
+        self.log = logger.get_logger("bus.receive")
 
     def run(self):
         self.log.trace("Message Bus Receive thread started successfully")
@@ -115,7 +115,7 @@ class TransmitThread(threading.Thread):
 
     def __init__(self):
         super().__init__(name="Transmit")
-        self.log = logger.get_module_logger("bus.transmit")
+        self.log = logger.get_logger("bus.transmit")
 
     def run(self):
         self.log.trace("Message Bus Transmit thread started successfully")

mqttany/core.py

@@ -52,7 +52,7 @@
     ATTR_NODES,
 )
 
-log = logger.get_module_logger("core")
+log = logger.get_logger("core")
 communication_modules = []
 interface_modules = []
 

mqttany/logger.py

@@ -36,22 +36,32 @@
 
 TRACE = 5  # trace level logging
 
-_log_file = os.path.join(os.path.dirname(__file__), "log", "mqttany.log")
-_log_format = "%(asctime)s [%(levelname)-5s] [%(name)-24s] %(message)s"
-_log_format_debug = (
-    "%(asctime)s [%(levelname)-5s] [%(processName)-8s] [%(name)-24s] %(message)s"
+_LOG_FILE = os.path.join(os.path.dirname(__file__), "log", "mqttany.log")
+
+_LOG_LEN_LEVEL = 5
+_LOG_LEN_PROCESS = 8
+_LOG_LEN_NAME = 20
+_LOG_FORMAT_FILE = "%(asctime)s [%(levelname)-{}s] [%(name)-{}s] %(message)s".format(
+    _LOG_LEN_LEVEL, _LOG_LEN_NAME
+)
+_LOG_FORMAT_FILE_DEBUG = "%(asctime)s [%(levelname)-{}s] [%(processName)-{}.{}s] [%(name)-{}s] %(message)s".format(
+    _LOG_LEN_LEVEL, _LOG_LEN_PROCESS, _LOG_LEN_PROCESS, _LOG_LEN_NAME
+)
+_LOG_FORMAT_TERM = "%(asctime)s [%(log_color)s%(levelname)-{}s%(reset)s] [%(name)-{}s] %(message_log_color)s%(message)s".format(
+    _LOG_LEN_LEVEL, _LOG_LEN_NAME
 )
-_log_format_color = "%(asctime)s [%(log_color)s%(levelname)-5s%(reset)s] [%(name)-24s] %(message_log_color)s%(message)s"
-_log_format_color_debug = "%(asctime)s [%(log_color)s%(levelname)-5s%(reset)s] [%(processName)-8s] [%(name)-24s] %(message_log_color)s%(message)s"
-_log_colors = {
+_LOG_FORMAT_TERM_DEBUG = "%(asctime)s [%(log_color)s%(levelname)-{}s%(reset)s] [%(processName)-{}.{}s] [%(name)-{}s] %(message_log_color)s%(message)s".format(
+    _LOG_LEN_LEVEL, _LOG_LEN_PROCESS, _LOG_LEN_PROCESS, _LOG_LEN_NAME
+)
+_LOG_COLORS = {
     "TRACE": "white",
     "DEBUG": "bold_white",
     "INFO": "bold_green",
     "WARN": "bold_yellow",
     "ERROR": "bold_red",
     "CRITICAL": "bold_red",
 }
-_secondary_log_colors = {
+_LOG_SECONDARY_COLORS = {
     "message": {
         "DEBUG": "bold",
         "INFO": "bold_green",
@@ -61,6 +71,8 @@
     }
 }
 
+_log_handlers = []
+
 
 def trace_log(self, msg, *args, **kwargs):
     """
@@ -91,84 +103,86 @@ def _init_logger():
     log.warn = MethodType(warn_log, log)
     log.setLevel(INFO)
 
-    if not os.path.exists(os.path.dirname(_log_file)):
+    if not os.path.exists(os.path.dirname(_LOG_FILE)):
         try:
-            os.makedirs(os.path.dirname(_log_file))
+            os.makedirs(os.path.dirname(_LOG_FILE))
         except OSError as err:
             if err.errno != errno.EEXIST:
                 raise
     handler_file = handlers.RotatingFileHandler(
-        _log_file, maxBytes=5242880, backupCount=5
+        _LOG_FILE, maxBytes=5242880, backupCount=5
     )
-    handler_file.setFormatter(logging.Formatter(_log_format))
-    log.addHandler(handler_file)
+    handler_file.setFormatter(logging.Formatter(_LOG_FORMAT_FILE))
+    _log_handlers.append(handler_file)
 
     handler_stdout = logging.StreamHandler()
     handler_stdout.setFormatter(
         colorlog.ColoredFormatter(
-            _log_format_color,
-            log_colors=_log_colors,
-            secondary_log_colors=_secondary_log_colors,
+            _LOG_FORMAT_TERM,
+            log_colors=_LOG_COLORS,
+            secondary_log_colors=_LOG_SECONDARY_COLORS,
         )
     )
-    log.addHandler(handler_stdout)
+    _log_handlers.append(handler_stdout)
 
+    for handler in _log_handlers:
+        log.addHandler(handler)
     return log
 
 
 _log = _init_logger()
 
 
-def get_logger(name="mqttany", level=None):
+def get_logger(name=None, level=None):
     """
-    Returns a logger
+    Returns a logger, if ``name`` is not specified the import name of the calling
+    file will be used.
     """
+    if name is None:
+        frm = inspect.stack()[1]
+        name = inspect.getmodule(frm[0]).__name__
+    name = ".".join([s for s in name.split(".") if s not in ["mqttany", "modules"]])
+    name = name[len(name) - _LOG_LEN_NAME :] if len(name) > _LOG_LEN_NAME else name
     logger = logging.getLogger(name)
+    for handler in _log_handlers:
+        logger.addHandler(handler)
     logger.trace = MethodType(trace_log, logger)
     logger.warn = MethodType(warn_log, logger)
     logger.setLevel(level or logging.getLogger("mqttany").level)
     return logger
 
 
-def get_module_logger(module=None, level=None):
-    """
-    Returns a logger for a module
-    """
-    if module is None:
-        frm = inspect.stack()[1]
-        module = ".".join(inspect.getmodule(frm[0]).__name__.split(".")[1:])
-    return get_logger("mqttany.{}".format(module), level)
-
-
 def set_level(level):
     """
     Sets logging level to level
     """
     _log.setLevel(level)
     if level <= DEBUG:
-        for handler in _log.handlers:
+        # for handler in _log.handlers:
+        for handler in _log_handlers:
             if isinstance(handler, logging.StreamHandler):
                 handler.setFormatter(
                     colorlog.ColoredFormatter(
-                        _log_format_color_debug,
-                        log_colors=_log_colors,
-                        secondary_log_colors=_secondary_log_colors,
+                        _LOG_FORMAT_TERM_DEBUG,
+                        log_colors=_LOG_COLORS,
+                        secondary_log_colors=_LOG_SECONDARY_COLORS,
                     )
                 )
             else:
-                handler.setFormatter(logging.Formatter(_log_format_debug))
+                handler.setFormatter(logging.Formatter(_LOG_FORMAT_FILE_DEBUG))
     else:
-        for handler in _log.handlers:
+        # for handler in _log.handlers:
+        for handler in _log_handlers:
             if isinstance(handler, logging.StreamHandler):
                 handler.setFormatter(
                     colorlog.ColoredFormatter(
-                        _log_format_color,
-                        log_colors=_log_colors,
-                        secondary_log_colors=_secondary_log_colors,
+                        _LOG_FORMAT_TERM,
+                        log_colors=_LOG_COLORS,
+                        secondary_log_colors=_LOG_SECONDARY_COLORS,
                     )
                 )
             else:
-                handler.setFormatter(logging.Formatter(_log_format))
+                handler.setFormatter(logging.Formatter(_LOG_FORMAT_FILE))
 
 
 def log_traceback(log, limit=None):
@@ -184,6 +198,7 @@ def uninit():
     """
     Flushes and closes all log handlers
     """
-    for handler in _log.handlers:
+    # for handler in _log.handlers:
+    for handler in _log_handlers:
         handler.flush()
         handler.close()

mqttany/modules/gpio/common.py

@@ -50,7 +50,7 @@
 import logger
 from common import DataType, BusNode, BusProperty
 
-log = logger.get_module_logger("gpio")
+log = logger.get_logger("gpio")
 CONFIG = {}
 
 publish_queue = None

mqttany/modules/gpio/lib/odroid.py

@@ -58,7 +58,7 @@
 )
 
 
-log = logger.get_module_logger("gpio.odroid")
+log = logger.get_logger("gpio.odroid")
 
 
 MAP_WIRINGPI_SETUP = {

mqttany/modules/gpio/lib/rpi.py

@@ -57,7 +57,7 @@
     TEXT_GPIO_MODE,
 )
 
-log = logger.get_module_logger("gpio.rpi")
+log = logger.get_logger("gpio.rpi")
 
 
 MAP_WIRINGPI_SETUP = {

mqttany/modules/gpio/pin/digital.py

@@ -108,7 +108,7 @@ class Digital(Pin):
 
     def __init__(self, pin: int, id: str, name: str, pin_config: dict = {}):
         super().__init__(pin, id, name, pin_config)
-        self._log = logger.get_module_logger("gpio.digital")
+        self._log = logger.get_logger("gpio.digital")
         self._pulse_timer = None
         self._interrupt = pin_config[CONF_KEY_INTERRUPT]
         self._resistor = pin_config[CONF_KEY_RESISTOR]

mqttany/modules/i2c/common.py

@@ -47,7 +47,7 @@
 from config import resolve_type
 from common import DataType, BusNode, BusProperty
 
-log = logger.get_module_logger("i2c")
+log = logger.get_logger("i2c")
 CONFIG = {}
 
 publish_queue = None

mqttany/modules/i2c/device/mcp230xx.py

@@ -629,7 +629,7 @@ def __init__(
         device_config: dict,
     ):
         super().__init__(id, name, device, address, bus, bus_path)
-        self._log = logger.get_module_logger("i2c.mcp23008")
+        self._log = logger.get_logger("i2c.mcp23008")
         self._pin_max = 7
         self._pins = [None] * (self._pin_max + 1)
         self._gpio = 0x0000
@@ -724,7 +724,7 @@ def __init__(
         device_config: dict,
     ):
         super().__init__(id, name, device, address, bus, bus_path)
-        self._log = logger.get_module_logger("i2c.mcp23017")
+        self._log = logger.get_logger("i2c.mcp23017")
         self._pin_max = 15
         self._pins = [None] * (self._pin_max + 1)
         self._gpio = 0x0000

mqttany/modules/led/anim.py

@@ -37,7 +37,7 @@
 
 from modules.led.common import log, CONFIG, CONF_KEY_ANIM_DIR
 
-log = logger.get_module_logger("led.anim")
+log = logger.get_logger("led.anim")
 
 DEFAULT_PATH = "/etc/mqttany/led-anim"
 
@@ -145,7 +145,7 @@ def load_animations():
 
     # add utils to anims
     for func in anims:
-        anims[func].__globals__["log"] = logger.get_module_logger(f"led.anim.{func}")
+        anims[func].__globals__["log"] = logger.get_logger(f"led.anim.{func}")
         for util in utils:
             anims[func].__globals__[util.__name__] = util
 

mqttany/modules/led/array/e131.py

@@ -39,7 +39,7 @@
 )
 from modules.led.array.base import baseArray
 
-log = logger.get_module_logger("led.sacn")
+log = logger.get_logger("led.sacn")
 
 CONF_KEY_SACN = "sacn"
 CONF_KEY_UNIVERSE = "universe"
@@ -78,7 +78,7 @@ def __init__(
         Returns an LED object that outputs via sACN
         """
         super().__init__(id, name, count, leds_per_pixel, color_order, fps)
-        self._log = logger.get_module_logger(f"led.sacn.{self.id}")
+        self._log = logger.get_logger(f"led.sacn.{self.id}")
         self._brightness = (
             255
             if array_config[CONF_KEY_BRIGHTNESS] > 255

mqttany/modules/led/array/rpi.py

@@ -121,7 +121,7 @@ def __init__(
         Returns an LED object wrapping ``rpi_ws281x.PixelStrip``
         """
         super().__init__(id, name, count, leds_per_pixel, color_order, fps)
-        self._log = logger.get_module_logger(f"led.rpi.{self.id}")
+        self._log = logger.get_logger(f"led.rpi.{self.id}")
         self._init_brightness = (
             255
             if array_config[CONF_KEY_BRIGHTNESS] > 255
@@ -362,7 +362,7 @@ def validateGPIO(
             pin_ok = True  # SPI0-MOSI
 
         if not pin_ok:
-            logger.get_module_logger("led.rpi").error(
+            logger.get_logger("led.rpi").error(
                 "GPIO%02d cannot be used for LED control on %s",
                 array_config[CONF_KEY_RPI][CONF_KEY_GPIO],
                 board_id,
@@ -381,10 +381,10 @@ def validateGPIO(
             )
 
     else:
-        logger.get_module_logger("led.rpi").error(
+        logger.get_logger("led.rpi").error(
             "This module only supports GPIO output on certain Raspberry Pi boards"
         )
-        logger.get_module_logger("led.rpi").error(
+        logger.get_logger("led.rpi").error(
             "Please see the documentation for supported boards"
         )
 

mqttany/modules/led/common.py

@@ -49,7 +49,7 @@
 
 import logger
 
-log = logger.get_module_logger("led")
+log = logger.get_logger("led")
 CONFIG = {}
 
 publish_queue = None

mqttany/modules/mqtt.py

@@ -46,7 +46,7 @@
 
 _module_type = ModuleType.COMMUNICATION
 
-log = logger.get_module_logger()
+log = logger.get_logger()
 CONFIG = {}
 
 core_queue = None

mqttany/modules/onewire/bus/wire1.py

@@ -33,7 +33,7 @@
 import logger
 from modules.onewire.bus.base import OneWireBus
 
-log = logger.get_module_logger("onewire.wire1")
+log = logger.get_logger("onewire.wire1")
 
 CONF_OPTIONS = {}
 CONF_BUS_SELECTION = ["w1", "W1", "wire1", "WIRE1", "Wire1"]

mqttany/modules/onewire/common.py

@@ -44,7 +44,7 @@
 import logger
 from common import DataType, BusNode, BusProperty
 
-log = logger.get_module_logger("onewire")
+log = logger.get_logger("onewire")
 CONFIG = {}
 
 publish_queue = None