Spread the logging around more.

Author: jmattsson

src/powersensor_local/async_event_emitter.py

@@ -40,4 +40,4 @@ async def emit(self, event_name: str, *args: Any) -> None:
                 await callback(event_name, *args)
             except Exception as e:
                 if self._logger is not None:
-                    self._logger.exception(f"Logic error: exception escaped from callback: {e}")
+                    self._logger.exception("Logic error: exception escaped from callback: %s", e)

src/powersensor_local/plug_api.py

@@ -46,9 +46,9 @@ def __init__(self, mac: str, ip: str, port: int = 49476, proto: str = 'udp', log
         self._mac: str = mac
         self._listener: PlugListenerUdp | PlugListenerTcp
         if proto == 'udp':
-            self._listener = PlugListenerUdp(ip, port)
+            self._listener = PlugListenerUdp(ip, port, logger)
         elif proto == 'tcp':
-            self._listener = PlugListenerTcp(ip, port)
+            self._listener = PlugListenerTcp(ip, port, logger)
         else:
             raise ValueError(f'Unsupported proto: {proto}')
         self._listener.subscribe('message', self._on_message)

src/powersensor_local/plug_listener_tcp.py

@@ -4,6 +4,7 @@
 import sys
 
 from asyncio import StreamReader, StreamWriter
+from logging import Logger
 
 from powersensor_local.async_event_emitter import AsyncEventEmitter
 
@@ -23,7 +24,7 @@ class PlugListenerTcp(AsyncEventEmitter):
     The event handlers must be async.
     """
 
-    def __init__(self, ip: str, port: int = 49476):
+    def __init__(self, ip: str, port: int = 49476, logger: Logger|None = None):
         """
         Create a :class:`PlugListenerTcp` bound to the given IP address.
 
@@ -34,7 +35,7 @@ def __init__(self, ip: str, port: int = 49476):
         port : int, optional
             TCP port used by the plug (default ``49476``).
         """
-        super().__init__()
+        super().__init__(logger = logger)
         self._ip: str = ip
         self._port: int = port
         self._task: asyncio.Task[None] | None = None

src/powersensor_local/plug_listener_udp.py

@@ -5,6 +5,7 @@
 import sys
 
 from asyncio import TimerHandle
+from logging import Logger
 from typing import Any, Coroutine
 
 from powersensor_local.async_event_emitter import AsyncEventEmitter
@@ -27,7 +28,7 @@ class PlugListenerUdp(AsyncEventEmitter, asyncio.DatagramProtocol):
     The event handlers must be async.
     """
 
-    def __init__(self, ip: str, port: int = 49476):
+    def __init__(self, ip: str, port: int = 49476, logger: Logger|None = None):
         """
         Create a :class:`PlugListenerUdp` bound to the given IP address.
 
@@ -38,7 +39,7 @@ def __init__(self, ip: str, port: int = 49476):
         port : int, optional
             UDP port used by the plug (default ``49476``).
         """
-        super().__init__()
+        super().__init__(logger = logger)
         self._ip: str  = ip
         self._port: int = port
         self._backoff: int = 0               # exponential backoff

src/powersensor_local/virtual_household.py

@@ -2,6 +2,7 @@
 
 import sys
 from dataclasses import dataclass
+from logging import Logger
 from typing import Optional
 
 from .async_event_emitter import AsyncEventEmitter
@@ -138,9 +139,9 @@ class VirtualHousehold(AsyncEventEmitter):
     field to take note of summation resets.
     """
 
-    def __init__(self, with_solar: bool):
+    def __init__(self, with_solar: bool, logger: Logger|None = None):
         """Constructor.
-        with_solar True if it's already known that solar exists. Will be
+        with_solar: True if it's already known that solar exists. Will be
           automatically enabled upon encountering a solar event during
           processing, but until such a time may generate incorrect values
           for home usage. Similarly, if this is set to True but no solar
@@ -156,8 +157,10 @@ def __init__(self, with_solar: bool):
           would be generating incorrect data until such a time the solar
           sensor is recharged. It is vastly preferable to have the system
           show no data than show incorrect data.
+        logger: An optional logger to capture leaked exceptions from event
+          callbacks.
         """
-        super().__init__()
+        super().__init__(logger)
         self._expect_solar = with_solar
         self._summation = self.SummationInfo(0, 0, 0, 0)
         self._counters = self.Counters(0, 0, 0, 0, 0)

src/powersensor_local/zeroconf_devices.py

@@ -37,6 +37,9 @@
 import asyncio
 import logging
 import sys
+
+from asyncio import Task
+from logging import Logger
 from typing import Any, Callable, Coroutine
 
 from .devices import _AsyncCallback, _LogLevel, _PowersensorDevicesBase
@@ -92,7 +95,7 @@ def __init__(
                 service_type: str = _SERVICE_TYPE_UDP,
                 debounce_timeout: float = _DEBOUNCE_DEFAULT_S,
                 relay_now_relaying_for: bool = False,
-                logger: 'logging.Logger | None' = None,
+                logger: Logger|None = None,
         ) -> None:
             """Initialise.
 
@@ -118,6 +121,7 @@ def __init__(
             self._zc_owned = zeroconf_instance is None  # True → we close it in stop()
             self._service_type = service_type
             self._debounce_seconds = debounce_timeout
+            self._cb_logger = logger
             self._browser: Any = None
             self._listener: _Listener | None = None
             self._pending_removals: dict[str, asyncio.TimerHandle] = {}
@@ -223,8 +227,15 @@ async def _on_zc_remove(self, mac: str) -> None:
         def _internal_callback(self, coro: _InternalCallback) -> None:
             """Helper to prevent gc collection of short-lived callback tasks."""
             task = asyncio.create_task(coro)
+
+            def cleanup(task: Task[None]) -> None:
+                self._internal_callbacks.discard(task)
+                e = task.exception()
+                if e is not None and not task.cancelled():
+                    self._maybe_log(_LogLevel.ERROR, 'Exception escaped callback: %s', e)
+
             self._internal_callbacks.add(task)
-            task.add_done_callback(self._internal_callbacks.discard)
+            task.add_done_callback(cleanup)
 
 
     class _Listener(_zc.ServiceListener):

tests/test_async_event_emitter.py

@@ -68,7 +68,8 @@ async def test_exception_unhandled() -> None:
   emitter = AsyncEventEmitter(logger)
   mock = AsyncMock()
   emitter.subscribe('e', mock)
-  mock.side_effect = KeyError('oops')
+  e = KeyError('oops')
+  mock.side_effect = e
   await emitter.emit('e')
   mock.assert_called_once()
-  logger.exception.assert_called_once_with("Logic error: exception escaped from callback: 'oops'")
+  logger.exception.assert_called_once_with("Logic error: exception escaped from callback: %s", e)