Reduce bluetooth logging noise when an adapter is recovered (#77109)

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."""

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