From 0e2ebfe5c45716250280186234123f170e3bd08c Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Tue, 13 Dec 2022 11:57:40 -1000 Subject: [PATCH] Move bluetooth watchdog into the scanner base class (#83888) --- .../components/bluetooth/base_scanner.py | 50 +++++++++++++++++++ homeassistant/components/bluetooth/scanner.py | 32 ++---------- .../components/bluetooth/test_diagnostics.py | 1 + tests/components/bluetooth/test_scanner.py | 32 ++++++------ tests/components/shelly/test_diagnostics.py | 1 + 5 files changed, 73 insertions(+), 43 deletions(-) diff --git a/homeassistant/components/bluetooth/base_scanner.py b/homeassistant/components/bluetooth/base_scanner.py index f0a1f1198d2..ffa2c4f568d 100644 --- a/homeassistant/components/bluetooth/base_scanner.py +++ b/homeassistant/components/bluetooth/base_scanner.py @@ -6,6 +6,7 @@ from collections.abc import Callable, Generator from contextlib import contextmanager import datetime from datetime import timedelta +import logging from typing import Any, Final from bleak.backends.device import BLEDevice @@ -29,10 +30,13 @@ from . import models from .const import ( CONNECTABLE_FALLBACK_MAXIMUM_STALE_ADVERTISEMENT_SECONDS, FALLBACK_MAXIMUM_STALE_ADVERTISEMENT_SECONDS, + SCANNER_WATCHDOG_INTERVAL, + SCANNER_WATCHDOG_TIMEOUT, ) from .models import HaBluetoothConnector MONOTONIC_TIME: Final = monotonic_time_coarse +_LOGGER = logging.getLogger(__name__) class BaseHaScanner(ABC): @@ -47,6 +51,8 @@ class BaseHaScanner(ABC): "name", "scanning", "_last_detection", + "_start_time", + "_cancel_watchdog", ) def __init__( @@ -65,6 +71,47 @@ class BaseHaScanner(ABC): self.name = adapter_human_name(adapter, source) if adapter != source else source self.scanning = True self._last_detection = 0.0 + self._start_time = 0.0 + self._cancel_watchdog: CALLBACK_TYPE | None = None + + @hass_callback + def _async_stop_scanner_watchdog(self) -> None: + """Stop the scanner watchdog.""" + if self._cancel_watchdog: + self._cancel_watchdog() + self._cancel_watchdog = None + + @hass_callback + def _async_setup_scanner_watchdog(self) -> None: + """If something has restarted or updated, we need to restart the scanner.""" + self._start_time = self._last_detection = MONOTONIC_TIME() + if not self._cancel_watchdog: + self._cancel_watchdog = async_track_time_interval( + self.hass, self._async_scanner_watchdog, SCANNER_WATCHDOG_INTERVAL + ) + + @hass_callback + def _async_watchdog_triggered(self) -> bool: + """Check if the watchdog has been triggered.""" + time_since_last_detection = MONOTONIC_TIME() - self._last_detection + _LOGGER.debug( + "%s: Scanner watchdog time_since_last_detection: %s", + self.name, + time_since_last_detection, + ) + return time_since_last_detection > SCANNER_WATCHDOG_TIMEOUT + + async def _async_scanner_watchdog(self, now: datetime.datetime) -> None: + """Check if the scanner is running. + + Override this method if you need to do something else when the watchdog is triggered. + """ + if self._async_watchdog_triggered(): + _LOGGER.info( + "%s: Bluetooth scanner has gone quiet for %ss, check logs on the scanner device for more information", + self.name, + SCANNER_WATCHDOG_TIMEOUT, + ) @contextmanager def connecting(self) -> Generator[None, None, None]: @@ -93,6 +140,7 @@ class BaseHaScanner(ABC): """Return diagnostic information about the scanner.""" return { "name": self.name, + "start_time": self._start_time, "source": self.source, "scanning": self.scanning, "type": self.__class__.__name__, @@ -166,10 +214,12 @@ class BaseHaRemoteScanner(BaseHaScanner): cancel_stop = self.hass.bus.async_listen( EVENT_HOMEASSISTANT_STOP, self._save_history ) + self._async_setup_scanner_watchdog() @hass_callback def _cancel() -> None: self._save_history() + self._async_stop_scanner_watchdog() cancel_track() cancel_stop() diff --git a/homeassistant/components/bluetooth/scanner.py b/homeassistant/components/bluetooth/scanner.py index 55a33af976a..6f2da53ce7f 100644 --- a/homeassistant/components/bluetooth/scanner.py +++ b/homeassistant/components/bluetooth/scanner.py @@ -20,13 +20,11 @@ from bleak_retry_connector import restore_discoveries from bluetooth_adapters import DEFAULT_ADDRESS from dbus_fast import InvalidMessageError -from homeassistant.core import CALLBACK_TYPE, HomeAssistant, callback as hass_callback +from homeassistant.core import HomeAssistant, callback as hass_callback from homeassistant.exceptions import HomeAssistantError -from homeassistant.helpers.event import async_track_time_interval -from homeassistant.util.dt import monotonic_time_coarse from homeassistant.util.package import is_docker_env -from .base_scanner import BaseHaScanner +from .base_scanner import MONOTONIC_TIME, BaseHaScanner from .const import ( SCANNER_WATCHDOG_INTERVAL, SCANNER_WATCHDOG_TIMEOUT, @@ -37,7 +35,6 @@ from .models import BluetoothScanningMode, BluetoothServiceInfoBleak from .util import async_reset_adapter OriginalBleakScanner = bleak.BleakScanner -MONOTONIC_TIME = monotonic_time_coarse # or_patterns is a workaround for the fact that passive scanning # needs at least one matcher to be set. The below matcher @@ -137,8 +134,6 @@ class HaScanner(BaseHaScanner): self.mode = mode self.adapter = adapter self._start_stop_lock = asyncio.Lock() - self._cancel_watchdog: CALLBACK_TYPE | None = None - self._start_time = 0.0 self._new_info_callback = new_info_callback self.scanning = False @@ -166,7 +161,6 @@ class HaScanner(BaseHaScanner): base_diag = await super().async_diagnostics() return base_diag | { "adapter": self.adapter, - "start_time": self._start_time, } @hass_callback @@ -315,24 +309,9 @@ class HaScanner(BaseHaScanner): self._async_setup_scanner_watchdog() await restore_discoveries(self.scanner, self.adapter) - @hass_callback - def _async_setup_scanner_watchdog(self) -> None: - """If Dbus gets restarted or updated, we need to restart the scanner.""" - self._start_time = self._last_detection = MONOTONIC_TIME() - if not self._cancel_watchdog: - self._cancel_watchdog = async_track_time_interval( - self.hass, self._async_scanner_watchdog, SCANNER_WATCHDOG_INTERVAL - ) - async def _async_scanner_watchdog(self, now: datetime) -> None: """Check if the scanner is running.""" - time_since_last_detection = MONOTONIC_TIME() - self._last_detection - _LOGGER.debug( - "%s: Scanner watchdog time_since_last_detection: %s", - self.name, - time_since_last_detection, - ) - if time_since_last_detection < SCANNER_WATCHDOG_TIMEOUT: + if not self._async_watchdog_triggered(): return if self._start_stop_lock.locked(): _LOGGER.debug( @@ -346,6 +325,7 @@ class HaScanner(BaseHaScanner): SCANNER_WATCHDOG_TIMEOUT, ) async with self._start_stop_lock: + time_since_last_detection = MONOTONIC_TIME() - 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() @@ -378,10 +358,8 @@ class HaScanner(BaseHaScanner): async def async_stop(self) -> None: """Stop bluetooth scanner.""" - if self._cancel_watchdog: - self._cancel_watchdog() - self._cancel_watchdog = None async with self._start_stop_lock: + self._async_stop_scanner_watchdog() await self._async_stop_scanner() async def _async_stop_scanner(self) -> None: diff --git a/tests/components/bluetooth/test_diagnostics.py b/tests/components/bluetooth/test_diagnostics.py index 552ea6d8d0b..f0101afad81 100644 --- a/tests/components/bluetooth/test_diagnostics.py +++ b/tests/components/bluetooth/test_diagnostics.py @@ -604,6 +604,7 @@ async def test_diagnostics_remote_adapter( "source": "esp32", "storage": None, "type": "FakeScanner", + "start_time": ANY, }, ], }, diff --git a/tests/components/bluetooth/test_scanner.py b/tests/components/bluetooth/test_scanner.py index c3a08ac3361..4a15edf6938 100644 --- a/tests/components/bluetooth/test_scanner.py +++ b/tests/components/bluetooth/test_scanner.py @@ -204,7 +204,7 @@ async def test_recovery_from_dbus_restart(hass, one_adapter): # Ensure we don't restart the scanner if we don't need to with patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic + 10, ): async_fire_time_changed(hass, dt_util.utcnow() + SCANNER_WATCHDOG_INTERVAL) @@ -214,7 +214,7 @@ async def test_recovery_from_dbus_restart(hass, one_adapter): # Fire a callback to reset the timer with patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic, ): _callback( @@ -224,7 +224,7 @@ async def test_recovery_from_dbus_restart(hass, one_adapter): # Ensure we don't restart the scanner if we don't need to with patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic + 20, ): async_fire_time_changed(hass, dt_util.utcnow() + SCANNER_WATCHDOG_INTERVAL) @@ -234,7 +234,7 @@ async def test_recovery_from_dbus_restart(hass, one_adapter): # We hit the timer, so we restart the scanner with patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic + SCANNER_WATCHDOG_TIMEOUT + 20, ): async_fire_time_changed( @@ -279,7 +279,7 @@ async def test_adapter_recovery(hass, one_adapter): start_time_monotonic = time.monotonic() with patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic, ), patch( "homeassistant.components.bluetooth.scanner.OriginalBleakScanner", @@ -294,7 +294,7 @@ async def test_adapter_recovery(hass, one_adapter): # Ensure we don't restart the scanner if we don't need to with patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic + 10, ): async_fire_time_changed(hass, dt_util.utcnow() + SCANNER_WATCHDOG_INTERVAL) @@ -304,7 +304,7 @@ async def test_adapter_recovery(hass, one_adapter): # Ensure we don't restart the scanner if we don't need to with patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic + 20, ): async_fire_time_changed(hass, dt_util.utcnow() + SCANNER_WATCHDOG_INTERVAL) @@ -314,7 +314,7 @@ async def test_adapter_recovery(hass, one_adapter): # We hit the timer with no detections, so we reset the adapter and restart the scanner with patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic + SCANNER_WATCHDOG_TIMEOUT + SCANNER_WATCHDOG_INTERVAL.total_seconds(), @@ -366,7 +366,7 @@ async def test_adapter_scanner_fails_to_start_first_time(hass, one_adapter): start_time_monotonic = time.monotonic() with patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic, ), patch( "homeassistant.components.bluetooth.scanner.OriginalBleakScanner", @@ -381,7 +381,7 @@ async def test_adapter_scanner_fails_to_start_first_time(hass, one_adapter): # Ensure we don't restart the scanner if we don't need to with patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic + 10, ): async_fire_time_changed(hass, dt_util.utcnow() + SCANNER_WATCHDOG_INTERVAL) @@ -391,7 +391,7 @@ async def test_adapter_scanner_fails_to_start_first_time(hass, one_adapter): # Ensure we don't restart the scanner if we don't need to with patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic + 20, ): async_fire_time_changed(hass, dt_util.utcnow() + SCANNER_WATCHDOG_INTERVAL) @@ -401,7 +401,7 @@ async def test_adapter_scanner_fails_to_start_first_time(hass, one_adapter): # We hit the timer with no detections, so we reset the adapter and restart the scanner with patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic + SCANNER_WATCHDOG_TIMEOUT + SCANNER_WATCHDOG_INTERVAL.total_seconds(), @@ -417,7 +417,7 @@ async def test_adapter_scanner_fails_to_start_first_time(hass, one_adapter): # We hit the timer again the previous start call failed, make sure # we try again with patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic + SCANNER_WATCHDOG_TIMEOUT + SCANNER_WATCHDOG_INTERVAL.total_seconds(), @@ -474,7 +474,7 @@ async def test_adapter_fails_to_start_and_takes_a_bit_to_init( "homeassistant.components.bluetooth.scanner.ADAPTER_INIT_TIME", 0, ), patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic, ), patch( "homeassistant.components.bluetooth.scanner.OriginalBleakScanner", @@ -523,7 +523,7 @@ async def test_restart_takes_longer_than_watchdog_time(hass, one_adapter, caplog "homeassistant.components.bluetooth.scanner.ADAPTER_INIT_TIME", 0, ), patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic, ), patch( "homeassistant.components.bluetooth.scanner.OriginalBleakScanner", @@ -538,7 +538,7 @@ async def test_restart_takes_longer_than_watchdog_time(hass, one_adapter, caplog # Now force a recover adapter 2x for _ in range(2): with patch( - "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + "homeassistant.components.bluetooth.base_scanner.MONOTONIC_TIME", return_value=start_time_monotonic + SCANNER_WATCHDOG_TIMEOUT + SCANNER_WATCHDOG_INTERVAL.total_seconds(), diff --git a/tests/components/shelly/test_diagnostics.py b/tests/components/shelly/test_diagnostics.py index e9ee21e92d4..fb78cdd5316 100644 --- a/tests/components/shelly/test_diagnostics.py +++ b/tests/components/shelly/test_diagnostics.py @@ -127,6 +127,7 @@ async def test_rpc_config_entry_diagnostics( "monotonic_time": ANY, "name": "Mock Title (12:34:56:78:9A:BC)", "scanning": True, + "start_time": ANY, "source": "12:34:56:78:9A:BC", "storage": None, "time_since_last_device_detection": {"AA:BB:CC:DD:EE:FF": ANY},