feat: improve logging of scanner failures and time_since_last_detection (#155)

Author: bdraco

src/habluetooth/base_scanner.pxd

@@ -30,6 +30,8 @@ cdef class BaseHaScanner:
 
     cpdef tuple get_discovered_device_advertisement_data(self, str address)
 
+    cpdef float time_since_last_detection(self)
+
 
 cdef class BaseHaRemoteScanner(BaseHaScanner):
 

src/habluetooth/base_scanner.py

@@ -88,6 +88,10 @@ def __init__(
             adapter=self.adapter,
         )
 
+    def time_since_last_detection(self) -> float:
+        """Return the time since the last detection."""
+        return monotonic_time_coarse() - self._last_detection
+
     def async_setup(self) -> CALLBACK_TYPE:
         """Set up the scanner."""
         self._loop = asyncio.get_running_loop()
@@ -123,7 +127,7 @@ def _async_call_scanner_watchdog(self) -> None:
 
     def _async_watchdog_triggered(self) -> bool:
         """Check if the watchdog has been triggered."""
-        time_since_last_detection = monotonic_time_coarse() - self._last_detection
+        time_since_last_detection = self.time_since_last_detection()
         _LOGGER.debug(
             "%s: Scanner watchdog time_since_last_detection: %s",
             self.name,
@@ -139,13 +143,14 @@ def _async_scanner_watchdog(self) -> None:
         is triggered.
         """
         if self._async_watchdog_triggered():
-            _LOGGER.info(
+            _LOGGER.log(
+                logging.WARNING if self.scanning else logging.DEBUG,
                 (
                     "%s: Bluetooth scanner has gone quiet for %ss, check logs on the"
                     " scanner device for more information"
                 ),
                 self.name,
-                SCANNER_WATCHDOG_TIMEOUT,
+                self.time_since_last_detection(),
             )
             self.scanning = False
             return

src/habluetooth/scanner.py

@@ -508,10 +508,11 @@ def _async_scanner_watchdog(self) -> None:
                 self.name,
             )
             return
-        _LOGGER.info(
+        _LOGGER.log(
+            logging.WARNING if self.scanning else logging.DEBUG,
             "%s: Bluetooth scanner has gone quiet for %ss, restarting",
             self.name,
-            SCANNER_WATCHDOG_TIMEOUT,
+            self.time_since_last_detection(),
         )
         # Immediately mark the scanner as not scanning
         # since the restart task will have to wait for the lock
@@ -521,7 +522,6 @@ def _async_scanner_watchdog(self) -> None:
     async def _async_restart_scanner(self) -> None:
         """Restart the scanner."""
         async with self._start_stop_lock:
-            time_since_last_detection = monotonic_time_coarse() - self._last_detection
             # Stop the scanner but not the watchdog
             # since we want to try again later if it's still quiet
             await self._async_stop_scanner()
@@ -530,7 +530,7 @@ async def _async_restart_scanner(self) -> None:
             # do the reset.
             if (
                 self._start_time == self._last_detection
-                or time_since_last_detection > SCANNER_WATCHDOG_MULTIPLE
+                or self.time_since_last_detection() > SCANNER_WATCHDOG_MULTIPLE
             ):
                 await self._async_reset_adapter()
             try: