fixes + optional logging structure

Author: bookman-dius

src/powersensor_local/devices.py

@@ -1,5 +1,6 @@
 """Abstraction interface for unified event stream from Powersensor devices."""
 import asyncio
+import logging
 import sys
 
 from datetime import datetime, timezone
@@ -35,9 +36,40 @@ class _PowersensorDevicesBase:
     callback.  Subclasses are responsible for discovery — they call
     _plug_discovered(mac, ip, port) when a plug appears and
     _plug_lost(mac) when one disappears.
+
+    Known events
+    ------------
+    All subclasses emit the following lifecycle events:
+
+    **device_found**
+        A device has been discovered or re-discovered.
+        ``{ event: "device_found", device_type: "plug"|"sensor", mac: "..." }``
+
+    **device_lost**
+        A device has definitively disappeared (plug) or been inactive long
+        enough to expire (sensor).
+        ``{ event: "device_lost", mac: "..." }``
+
+    Additionally, all events from ``xlatemsg.translate_raw_message`` may be
+    issued for subscribed devices, with the event name inserted into the
+    ``event`` field.  Known measurement events include:
+
+    ``average_flow``, ``average_power``, ``average_power_components``,
+    ``battery_level``, ``exception``, ``now_relaying_for``,
+    ``radio_signal_quality``, ``summation_energy``, ``summation_volume``.
+
+    When ``relay_now_relaying_for=True`` the raw ``now_relaying_for`` wire
+    message is forwarded to the callback immediately after the synthesised
+    ``device_found`` for the same sensor MAC.
+
+    Note: ``scan_complete`` is only emitted by PowersensorLegacyDevices.
     """
 
-    def __init__(self, relay_now_relaying_for: bool = False) -> None:
+    def __init__(
+        self,
+        relay_now_relaying_for: bool = False,
+        logger: 'logging.Logger | None' = None,
+    ) -> None:
         """Initialise the base.
 
         Parameters
@@ -50,12 +82,17 @@ def __init__(self, relay_now_relaying_for: bool = False) -> None:
             caller's callback unchanged, in addition to any ``device_found``
             synthesis.  Set this to True when the caller wants to inspect relay
             metadata directly (e.g. the HA dispatcher).
+        logger:
+            Optional :class:`logging.Logger` instance.  When provided, the
+            library emits debug/warning/error messages via this logger.  When
+            None (default) the library is completely silent.
         """
         self._event_cb = None
         self._devices: dict[str, '_PowersensorDevicesBase._Device'] = {}
         self._plug_apis: dict[str, PlugApi] = {}
         self._timer: '_PowersensorDevicesBase._Timer | None' = None
         self._relay_now_relaying_for = relay_now_relaying_for
+        self._logger = logger
 
     # ------------------------------------------------------------------
     # Public subscription API
@@ -105,8 +142,8 @@ async def _plug_discovered(self, mac: str, ip: str, port: int) -> None:
             if api.ip_address == ip and api.port == port:
                 return  # no change
             # Address changed — disconnect stale connection and reconnect.
-            await api.disconnect()
-            self._plug_apis.pop(mac)
+            await self._plug_apis.pop(mac).disconnect()
+            await self._remove_device(mac)
 
         await self._add_device(mac, 'plug')
         api = PlugApi(mac, ip, port)
@@ -136,9 +173,8 @@ async def _emit_if_subscribed(self, ev: str, mac: str, obj: dict) -> None:
     async def _reemit(self, ev: str, obj: dict[str, str]) -> None:
         mac: str|None = obj.get('mac')
         if mac is None:
-            # we don't log anything in this library, but if we did perhaps
-            # _LOGGER.warning("Received event '%s' with no MAC address -- ignoring", ev) might be appropriate
-            # for now...silence
+            if self._logger:
+                self._logger.warning("Received event '%s' with no MAC address — ignoring", ev)
             return
         device = self._devices.get(mac)
         if device is not None:
@@ -230,9 +266,10 @@ def __init__(
         self,
         bcast_addr: str = '<broadcast>',
         relay_now_relaying_for: bool = False,
+        logger: 'logging.Logger | None' = None,
     ) -> None:
         """Create a fresh instance, without scanning for devices."""
-        super().__init__(relay_now_relaying_for=relay_now_relaying_for)
+        super().__init__(relay_now_relaying_for=relay_now_relaying_for, logger=logger)
         self._discovery = LegacyDiscovery(bcast_addr)
 
     async def start(self, async_event_cb) -> int:
@@ -242,25 +279,20 @@ async def start(self, async_event_cb) -> int:
 
             async def yourcallback(event: dict) -> None
 
-        Known lifecycle events emitted:
+        See _PowersensorDevicesBase for the full list of known events.
+
+        Additionally emits:
 
         **scan_complete**
             Indicates discovery has completed.
             ``{ event: "scan_complete", gateway_count: N }``
 
-        **device_found**
-            A new device found on the network.
-            ``{ event: "device_found", device_type: "plug"|"sensor", mac: "..." }``
-
-        **device_lost**
-            A device appears to no longer be present.
-            ``{ event: "device_lost", mac: "..." }``
-
-        Additionally all events from xlatemsg.translate_raw_message may be
-        issued, with the event name inserted into the ``event`` field.
-
         Returns the number of gateway plugs found.
         """
+        if self._timer is not None:
+            if self._logger:
+                self._logger.warning("start() called while already running — ignoring")
+            return len(self._plug_apis)
         self._event_cb = async_event_cb
         await self._on_scanned(await self._discovery.scan())
         self._start_expiry_timer()

src/powersensor_local/zeroconf_devices.py

@@ -66,8 +66,6 @@
 
 from powersensor_local.devices import _PowersensorDevicesBase
 
-_LOGGER = logging.getLogger(__name__)
-
 _SERVICE_TYPE_UDP = '_powersensor._udp.local.'
 _SERVICE_TYPE_TCP = '_powersensor._tcp.local.'
 
@@ -114,6 +112,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,
         ) -> None:
             """Initialise.
 
@@ -131,8 +130,10 @@ def __init__(
                 the plug as truly gone.  Defaults to 60 s.
             relay_now_relaying_for:
                 See _PowersensorDevicesBase for documentation.
+            logger:
+                See _PowersensorDevicesBase for documentation.
             """
-            super().__init__(relay_now_relaying_for=relay_now_relaying_for)
+            super().__init__(relay_now_relaying_for=relay_now_relaying_for, logger=logger)
             self._zc_instance = zeroconf_instance
             self._zc_owned = zeroconf_instance is None  # True → we close it in stop()
             self._service_type = service_type
@@ -152,6 +153,11 @@ async def start(self, async_event_cb) -> None:
             Plugs already present on the network will trigger add_service
             callbacks shortly after the browser starts.
             """
+            if self._browser is not None:
+                if self._logger:
+                    self._logger.warning("start() called while already running — ignoring")
+                return
+
             self._event_cb = async_event_cb
             self._start_expiry_timer()
 
@@ -224,19 +230,22 @@ def _schedule_removal(self, mac: str) -> None:
                 mac,
             )
             self._pending_removals[mac] = handle
-            _LOGGER.debug("Scheduled removal for %s in %.0f s", mac, self._debounce_seconds)
+            if self._logger:
+                self._logger.debug("Scheduled removal for %s in %.0f s", mac, self._debounce_seconds)
 
         def _on_debounce_expired(self, mac: str) -> None:
             """Called by the event loop when the debounce timer fires."""
             self._pending_removals.pop(mac, None)
-            _LOGGER.info("Plug %s still absent after debounce — removing", mac)
+            if self._logger:
+                self._logger.info("Plug %s still absent after debounce — removing", mac)
             asyncio.get_running_loop().create_task(self._plug_lost(mac))
 
         def _cancel_pending_removal(self, mac: str, source: str) -> None:
             handle = self._pending_removals.pop(mac, None)
             if handle:
                 handle.cancel()
-                _LOGGER.debug("Cancelled pending removal for %s (%s)", mac, source)
+                if self._logger:
+                    self._logger.debug("Cancelled pending removal for %s (%s)", mac, source)
 
         # ------------------------------------------------------------------
         # Called from _Listener (zeroconf thread → event loop via stored loop ref)
@@ -300,40 +309,46 @@ def _extract(self, zc: Any, type_: str, name: str) -> tuple[str, str, int] | Non
             """
             info = _zc.ServiceInfo(type_, name)
             if not info.load_from_cache(zc):
-                _LOGGER.warning(
-                    "No cache entry for %s — device will appear on next mDNS announcement",
-                    name,
-                )
+                if self._owner._logger:
+                    self._owner._logger.warning(
+                        "No cache entry for %s — device will appear on next mDNS announcement",
+                        name,
+                    )
                 return None
 
             addresses = info.parsed_addresses()
             if not addresses:
-                _LOGGER.warning("No addresses in zeroconf cache record for %s", name)
+                if self._owner._logger:
+                    self._owner._logger.warning("No addresses in zeroconf cache record for %s", name)
                 return None
 
             try:
                 raw_id = info.properties[b'id']
             except KeyError:
-                _LOGGER.error("Missing 'id' property in zeroconf record for %s", name)
+                if self._owner._logger:
+                    self._owner._logger.error("Missing 'id' property in zeroconf record for %s", name)
                 return None
 
             if raw_id is None:
-                _LOGGER.error("'id' property in zeroconf record for %s has no value", name)
+                if self._owner._logger:
+                    self._owner._logger.error("'id' property in zeroconf record for %s has no value", name)
                 return None
 
             if info.port is None:
-                _LOGGER.error("No port in zeroconf record for %s", name)
+                if self._owner._logger:
+                    self._owner._logger.error("No port in zeroconf record for %s", name)
                 return None
 
             return raw_id.decode('utf-8'), addresses[0], info.port
 
         def add_service(self, zc: Any, type_: str, name: str) -> None:
             result = self._extract(zc, type_, name)
             if result is None:
-                _LOGGER.warning(
-                    "add_service: no info available for %s — will retry on next announcement",
-                    name,
-                )
+                if self._owner._logger:
+                    self._owner._logger.warning(
+                        "add_service: no info available for %s — will retry on next announcement",
+                        name,
+                    )
                 return
             mac, ip, port = result
             self._name_to_mac[name] = mac
@@ -342,10 +357,11 @@ def add_service(self, zc: Any, type_: str, name: str) -> None:
         def update_service(self, zc: Any, type_: str, name: str) -> None:
             result = self._extract(zc, type_, name)
             if result is None:
-                _LOGGER.warning(
-                    "update_service: no info available for %s — will retry on next announcement",
-                    name,
-                )
+                if self._owner._logger:
+                    self._owner._logger.warning(
+                        "update_service: no info available for %s — will retry on next announcement",
+                        name,
+                    )
                 return
             mac, ip, port = result
             self._name_to_mac[name] = mac
@@ -354,9 +370,10 @@ def update_service(self, zc: Any, type_: str, name: str) -> None:
         def remove_service(self, zc: Any, type_: str, name: str) -> None:
             mac = self._name_to_mac.pop(name, None)
             if mac is None:
-                _LOGGER.warning(
-                    "remove_service for %s: MAC not in cache — removal ignored", name
-                )
+                if self._owner._logger:
+                    self._owner._logger.warning(
+                        "remove_service for %s: MAC not in cache — removal ignored", name
+                    )
                 return
             self._owner._on_zc_remove(mac, self._loop)