From f3e432c9c7735daddd2946773cc6572567821a5e Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Sun, 21 Aug 2022 12:03:14 -1000 Subject: [PATCH] Reduce bluetooth logging noise when an adapter is recovered (#77109) --- homeassistant/components/bluetooth/scanner.py | 38 ++++++++++-- tests/components/bluetooth/test_scanner.py | 59 +++++++++++++++++++ 2 files changed, 92 insertions(+), 5 deletions(-) diff --git a/homeassistant/components/bluetooth/scanner.py b/homeassistant/components/bluetooth/scanner.py index 96a0fe572c6..730249d70a0 100644 --- a/homeassistant/components/bluetooth/scanner.py +++ b/homeassistant/components/bluetooth/scanner.py @@ -44,12 +44,19 @@ _LOGGER = logging.getLogger(__name__) MONOTONIC_TIME = time.monotonic +# If the adapter is in a stuck state the following errors are raised: NEED_RESET_ERRORS = [ "org.bluez.Error.Failed", "org.bluez.Error.InProgress", "org.bluez.Error.NotReady", ] -START_ATTEMPTS = 2 + +# When the adapter is still initializing, the scanner will raise an exception +# with org.freedesktop.DBus.Error.UnknownObject +WAIT_FOR_ADAPTER_TO_INIT_ERRORS = ["org.freedesktop.DBus.Error.UnknownObject"] +ADAPTER_INIT_TIME = 1.5 + +START_ATTEMPTS = 3 SCANNING_MODE_TO_BLEAK = { BluetoothScanningMode.ACTIVE: "active", @@ -231,17 +238,35 @@ class HaScanner: f"{self.name}: Timed out starting Bluetooth after {START_TIMEOUT} seconds" ) from ex except BleakError as ex: + error_str = str(ex) if attempt == 0: - error_str = str(ex) if any( needs_reset_error in error_str for needs_reset_error in NEED_RESET_ERRORS ): await self._async_reset_adapter() continue + if attempt != START_ATTEMPTS - 1: + # If we are not out of retry attempts, and the + # adapter is still initializing, wait a bit and try again. + if any( + wait_error in error_str + for wait_error in WAIT_FOR_ADAPTER_TO_INIT_ERRORS + ): + _LOGGER.debug( + "%s: Waiting for adapter to initialize; attempt (%s/%s)", + self.name, + attempt + 1, + START_ATTEMPTS, + ) + await asyncio.sleep(ADAPTER_INIT_TIME) + continue + _LOGGER.debug( - "%s: BleakError while starting bluetooth: %s", + "%s: BleakError while starting bluetooth; attempt: (%s/%s): %s", self.name, + attempt + 1, + START_ATTEMPTS, ex, exc_info=True, ) @@ -310,9 +335,12 @@ class HaScanner: async def _async_reset_adapter(self) -> None: """Reset the adapter.""" - _LOGGER.warning("%s: adapter stopped responding; executing reset", self.name) + # There is currently nothing the user can do to fix this + # so we log at debug level. If we later come up with a repair + # strategy, we will change this to raise a repair issue as well. + _LOGGER.debug("%s: adapter stopped responding; executing reset", self.name) result = await async_reset_adapter(self.adapter) - _LOGGER.info("%s: adapter reset result: %s", self.name, result) + _LOGGER.debug("%s: adapter reset result: %s", self.name, result) async def async_stop(self) -> None: """Stop bluetooth scanner.""" diff --git a/tests/components/bluetooth/test_scanner.py b/tests/components/bluetooth/test_scanner.py index fc2e74144e7..26e949ad2e3 100644 --- a/tests/components/bluetooth/test_scanner.py +++ b/tests/components/bluetooth/test_scanner.py @@ -432,3 +432,62 @@ async def test_adapter_scanner_fails_to_start_first_time(hass, one_adapter): assert len(mock_recover_adapter.mock_calls) == 1 assert called_start == 4 + + +async def test_adapter_fails_to_start_and_takes_a_bit_to_init( + hass, one_adapter, caplog +): + """Test we can recover the adapter at startup and we wait for Dbus to init.""" + + called_start = 0 + called_stop = 0 + _callback = None + mock_discovered = [] + + class MockBleakScanner: + async def start(self, *args, **kwargs): + """Mock Start.""" + nonlocal called_start + called_start += 1 + if called_start == 1: + raise BleakError("org.bluez.Error.InProgress") + if called_start == 2: + raise BleakError("org.freedesktop.DBus.Error.UnknownObject") + + async def stop(self, *args, **kwargs): + """Mock Start.""" + nonlocal called_stop + called_stop += 1 + + @property + def discovered_devices(self): + """Mock discovered_devices.""" + nonlocal mock_discovered + return mock_discovered + + def register_detection_callback(self, callback: AdvertisementDataCallback): + """Mock Register Detection Callback.""" + nonlocal _callback + _callback = callback + + scanner = MockBleakScanner() + start_time_monotonic = 1000 + + with patch( + "homeassistant.components.bluetooth.scanner.ADAPTER_INIT_TIME", + 0, + ), patch( + "homeassistant.components.bluetooth.scanner.MONOTONIC_TIME", + return_value=start_time_monotonic, + ), patch( + "homeassistant.components.bluetooth.scanner.OriginalBleakScanner", + return_value=scanner, + ), patch( + "homeassistant.components.bluetooth.util.recover_adapter", return_value=True + ) as mock_recover_adapter: + await async_setup_with_one_adapter(hass) + + assert called_start == 3 + + assert len(mock_recover_adapter.mock_calls) == 1 + assert "Waiting for adapter to initialize" in caplog.text