greatly improved from implementing the "logging endgame" notebook

button.py

@@ -1,13 +1,15 @@
 import json
+import logging
 from dataclasses import dataclass
 from logging import Logger
-from typing import List
+from typing import TYPE_CHECKING, List
 
 from appdaemon.plugins.mqtt.mqttapi import Mqtt
 from console import setup_component_logging
 from model import ButtonConfig
 
-from room_control import RoomController
+if TYPE_CHECKING:
+    from room_control import RoomController
 
 
 @dataclass(init=False)
@@ -20,7 +22,7 @@ class Button(Mqtt):
     async def initialize(self):
         self.config = ButtonConfig(**self.args)
         self.logger = setup_component_logging(self)
-        self.app: RoomController = await self.get_app(self.args['app'])
+        self.app: 'RoomController' = await self.get_app(self.args['app'])
         self.log(f'Connected to AD app [room]{self.app.name}[/]', level='DEBUG')
 
         self.button = self.config.button

console.py

@@ -3,6 +3,7 @@ import logging.config
 import re
 from abc import ABC
 from dataclasses import asdict, dataclass
+from typing import Optional
 
 from appdaemon.logging import AppNameFormatter
 from rich.console import Console
@@ -10,18 +11,6 @@ from rich.highlighter import RegexHighlighter
 from rich.logging import RichHandler
 from rich.theme import Theme
 
-
-class RCHighlighter(RegexHighlighter):
-    highlights = [
-        r'(?P<light>(light|switch)\.\w+)',
-        r'(?P<time>\d+:\d+:\d+)',
-        r'(?P<z2m>zigbee2mqtt/)',
-        r'(?P<sensor>binary_sensor\.\w+)',
-        # r"'state': '(?P<on>on)|(?P<off>off)'"
-        r'(?P<true>True)|(?P<false>False)',
-    ]
-
-
 console = Console(
     width=100,
     theme=Theme(
@@ -45,17 +34,52 @@ console = Console(
 )
 
 
+class RCHighlighter(RegexHighlighter):
+    highlights = [
+        r'(?P<light>(light|switch)\.\w+)',
+        r'(?P<time>\d+:\d+:\d+)',
+        r'(?P<z2m>zigbee2mqtt/)',
+        r'(?P<sensor>binary_sensor\.\w+)',
+        # r"'state': '(?P<on>on)|(?P<off>off)'"
+        r'(?P<true>True)|(?P<false>False)',
+    ]
+
+
+RICH_HANDLER_CFG = {
+    '()': 'rich.logging.RichHandler',
+    'markup': True,
+    'show_path': False,
+    # 'show_time': False,
+    'omit_repeated_times': False,
+    'console': console,
+    'highlighter': RCHighlighter(),
+}
+
+
 class ContextSettingFilter(logging.Filter, ABC):
     def filter(self, record: logging.LogRecord) -> logging.LogRecord:
         for name, val in asdict(self).items():
+            if val is not None:
                 setattr(record, name, val)
         return record
 
 
-@dataclass
+class RoomFilter(logging.Filter):
-class RoomControllerFilter(ContextSettingFilter):
+    """Used to filter out messages that have a component field because they will have already been printed by their respective logger."""
-    room: str
+
-    component: str
+    def filter(self, record: logging.LogRecord) -> bool:
+        return getattr(record, 'component', None) is None
+
+
+# @dataclass
+# class RoomControllerFilter(ContextSettingFilter):
+#     room: str
+#     component: Optional[str] = None
+
+
+# class RoomControllerFormatter(logging.Formatter):
+#     def format(self, record: logging.LogRecord):
+#         return super().format(record)
 
 
 class UnMarkupFilter(logging.Filter):
@@ -66,71 +90,73 @@ class UnMarkupFilter(logging.Filter):
         return record
 
 
-def create_rich_logging_dict(parent_room: str, typ: str = None):
+def room_logging_config(name: str):
-    logger_name = f'AppDaemon.{parent_room}'
+    return {
-    if typ is not None:
-        logger_name += f'.{typ}'
-        fmt = '[room]{room}[/] [component]{component}[/] {message}'
-    else:
-        fmt = '[room]{room}[/] {message}'
-
-    LOG_CFG = {
         'version': 1,
         'disable_existing_loggers': False,
         'filters': {
-            logger_name: {
+            'room': {'()': 'console.RoomFilter'},
-                '()': 'console.RoomControllerFilter',
-                'room': parent_room,
-                'component': typ,
-            },
             'unmarkup': {'()': 'console.UnMarkupFilter'},
         },
         'formatters': {
-            'rich': {'style': '{', 'format': fmt, 'datefmt': '%H:%M:%S.%f'},
+            'rich_room': {
-            'err': {
                 'style': '{',
-                'format': '{asctime}.{msecs:03.0f} {levelname:8} {room:>10} {component:<9} {message}',
+                'format': '[room]{room}[/] {message}',
+                'datefmt': '%H:%M:%S.%f',
+            },
+            'file': {
+                'style': '{',
+                'format': '{asctime}.{msecs:03.0f} {levelname:8} {name}: {message}',
                 'datefmt': '%Y-%m-%d %H:%M:%S',
-                # 'datefmt': '%H:%M:%S.%f',
             },
         },
         'handlers': {
-            logger_name: {
+            'rich_room': {'formatter': 'rich_room', 'filters': ['room'], **RICH_HANDLER_CFG},
-                'filters': [logger_name],
-                'formatter': 'rich',
-                '()': 'rich.logging.RichHandler',
-                'markup': True,
-                'show_path': False,
-                # 'show_time': False,
-                'omit_repeated_times': False,
-                'console': console,
-                'highlighter': RCHighlighter(),
-            },
-            'stderr': {
-                'filters': [logger_name, 'unmarkup'],
-                'formatter': 'err',
-                'class': 'logging.StreamHandler',
-                'stream': 'ext://sys.stderr',
-            },
             'file': {
-                'filters': [logger_name, 'unmarkup'],
+                'filters': ['unmarkup'],
+                'formatter': 'file',
                 'class': 'logging.handlers.RotatingFileHandler',
-                'filename': f'/logs/{parent_room}.log',
+                # 'class': 'logging.FileHandler',
-                'formatter': 'err',
+                'filename': f'/logs/{name}.log',
                 'mode': 'w',
-                'maxBytes': 10**6,
+                'maxBytes': 1000000,
                 'backupCount': 3,
             },
         },
         'loggers': {
-            logger_name: {
+            f'AppDaemon.{name}': {
                 'level': 'INFO',
                 'propagate': False,
-                'handlers': [
+                'handlers': ['rich_room', 'file'],
-                    logger_name,
+            },
-                    'file',
+        },
-                    # 'stderr'
+    }
-                ],
+
+
+def component_logging_config(parent_room: str, component: str):
+    logger_name = f'AppDaemon.{parent_room}.{component}'
+
+    LOG_CFG = {
+        'version': 1,
+        'disable_existing_loggers': False,
+        'formatters': {
+            'rich_component': {
+                'style': '{',
+                'format': '[room]{room}[/] [component]{component}[/] {message}',
+                'datefmt': '%H:%M:%S.%f',
+            },
+        },
+        'handlers': {
+            'rich_component': {
+                'formatter': 'rich_component',
+                **RICH_HANDLER_CFG,
+            },
+        },
+        'loggers': {
+            logger_name: {
+                # 'level': 'INFO',
+                'propagate': True,
+                'handlers': ['rich_component'],
             }
         },
     }
@@ -139,9 +165,9 @@ def create_rich_logging_dict(parent_room: str, typ: str = None):
 
 def setup_component_logging(self) -> logging.Logger:
     """Creates a logger for a subcomponent with a RichHandler"""
-    typ = type(self).__name__
+    component = type(self).__name__
     parent = self.args['app']
-    cfg_dict = create_rich_logging_dict(parent_room=parent, typ=typ)
+    cfg_dict = component_logging_config(parent_room=parent, component=component)
     logger_name = next(iter(cfg_dict['loggers']))
 
     try:
@@ -149,4 +175,6 @@ def setup_component_logging(self) -> logging.Logger:
     except Exception:
         console.print_exception()
     else:
-        return logging.getLogger(logger_name)
+        logger = logging.getLogger(logger_name)
+        logger = logging.LoggerAdapter(logger, {'room': parent, 'component': component})
+        return logger

motion.py

@@ -1,14 +1,16 @@
-from logging import Logger
+import logging
 import re
 from datetime import timedelta
-from typing import Literal, Optional
+from logging import Logger
+from typing import TYPE_CHECKING, Literal, Optional
 
 from appdaemon.entity import Entity
 from appdaemon.plugins.hass.hassapi import Hass
 from console import setup_component_logging
 from pydantic import BaseModel, TypeAdapter
 
-from room_control import RoomController
+if TYPE_CHECKING:
+    from room_control import RoomController
 
 
 class CallbackEntry(BaseModel):
@@ -27,6 +29,7 @@ Callbacks = dict[str, dict[str, CallbackEntry]]
 
 class Motion(Hass):
     logger: Logger
+    app: 'RoomController'
 
     @property
     def sensor(self) -> Entity:
@@ -44,9 +47,13 @@ class Motion(Hass):
     def ref_entity_state(self) -> bool:
         return self.ref_entity.get_state() == 'on'
 
+    @property
+    def state_mismatch(self) -> bool:
+        return self.sensor_state != self.ref_entity_state
+
     def initialize(self):
         self.logger = setup_component_logging(self)
-        self.app: RoomController = self.get_app(self.args['app'])
+        self.app: 'RoomController' = self.get_app(self.args['app'])
         self.log(f'Connected to AD app [room]{self.app.name}[/]', level='DEBUG')
 
         assert self.entity_exists(self.args['sensor'])
@@ -57,7 +64,7 @@ class Motion(Hass):
             immediate=True,  # avoids needing to sync the state
         )
 
-        if self.sensor_state != self.ref_entity_state:
+        if self.state_mismatch:
             self.log(
                 f'Sensor is {self.sensor_state} ' f'and light is {self.ref_entity_state}',
                 level='WARNING',
@@ -75,15 +82,12 @@ class Motion(Hass):
 
         if callbacks := self.callbacks():
             for handle, entry in callbacks.items():
-                self.log(f'Handle [yellow]{handle[:4]}[/]: {entry.function}')
+                self.log(f'Handle [yellow]{handle[:4]}[/]: {entry.function}', level='DEBUG')
 
     def callbacks(self):
+        """Returns a dictionary of validated CallbackEntry objects that are associated with this app"""
         data = TypeAdapter(Callbacks).validate_python(self.get_callback_entries())
-        name: str = self.name
+        return data.get(self.name, {})
-        try:
-            return data[name]
-        except KeyError:
-            return []
 
     def listen_motion_on(self):
         """Sets up the motion on callback to activate the room"""
@@ -95,10 +99,10 @@ class Motion(Hass):
             oneshot=True,
             cause='motion on',
         )
-        self.log(f'Waiting for motion on [friendly_name]{self.sensor.friendly_name}[/]')
+        self.log(f'Waiting for sensor motion on [friendly_name]{self.sensor.friendly_name}[/]')
         if self.sensor_state:
             self.log(
-                f'[friendly_name]{self.sensor.friendly_name}[/] is already on', level='WARNING'
+                f'Sensor [friendly_name]{self.sensor.friendly_name}[/] is already on', level='WARNING'
             )
 
     def listen_motion_off(self, duration: timedelta):
@@ -113,12 +117,13 @@ class Motion(Hass):
             cause='motion off',
         )
         self.log(
-            f'Waiting for [friendly_name]{self.sensor.friendly_name}[/] to be clear for {duration}'
+            f'Waiting for sensor [friendly_name]{self.sensor.friendly_name}[/] to be clear for {duration}'
         )
 
         if not self.sensor_state:
             self.log(
-                f'[friendly_name]{self.sensor.friendly_name}[/] is currently off', level='WARNING'
+                f'Sensor [friendly_name]{self.sensor.friendly_name}[/] is currently off',
+                level='WARNING',
             )
 
     def callback_light_on(self, entity=None, attribute=None, old=None, new=None, kwargs=None):

room_control.py

@@ -7,7 +7,7 @@ from typing import Dict, List
 from appdaemon.entity import Entity
 from appdaemon.plugins.hass.hassapi import Hass
 from appdaemon.plugins.mqtt.mqttapi import Mqtt
-from console import console, create_rich_logging_dict
+from console import console, room_logging_config
 from model import ControllerStateConfig, RoomControllerConfig
 
 logger = logging.getLogger(__name__)
@@ -32,11 +32,14 @@ class RoomController(Hass, Mqtt):
         assert all(isinstance(s, ControllerStateConfig) for s in new), f'Invalid: {new}'
         self._room_config.states = new
 
-    def initialize(self):
+    def configure_logging(self) -> dict:
-        cfg_dict = create_rich_logging_dict(parent_room=self.name)
+        logging.config.dictConfig(room_logging_config(self.name))
-        logging.config.dictConfig(cfg_dict)
+        self.logger = logging.LoggerAdapter(
-        self.logger = logging.getLogger(next(iter(cfg_dict['loggers'])))
+            logging.getLogger(f'AppDaemon.{self.name}'), {'room': self.name}
+        )
 
+    def initialize(self):
+        self.configure_logging()
         self.app_entities = self.gather_app_entities()
         # self.log(f'entities: {self.app_entities}')
         self.refresh_state_times()
@@ -88,9 +91,9 @@ class RoomController(Hass, Mqtt):
 
             assert isinstance(state.time, datetime.time), f'Invalid time: {state.time}'
 
-        if self.logger.isEnabledFor(logging.DEBUG):
+        # if self.logger.isEnabledFor(logging.DEBUG):
-            # table = self._room_config.rich_table(self.name)
+        #     # table = self._room_config.rich_table(self.name)
-            console.print(self._room_config)
+        #     console.print(self._room_config)
 
         self.states = sorted(self.states, key=lambda s: s.time, reverse=True)