diff --git a/homeassistant/components/bluetooth/manager.py b/homeassistant/components/bluetooth/manager.py index 75809f42e6c..3210822e795 100644 --- a/homeassistant/components/bluetooth/manager.py +++ b/homeassistant/components/bluetooth/manager.py @@ -18,6 +18,7 @@ from bluetooth_adapters import ( ) from homeassistant import config_entries +from homeassistant.components.logger import EVENT_LOGGING_CHANGED from homeassistant.core import ( CALLBACK_TYPE, Event, @@ -113,6 +114,7 @@ class BluetoothManager: self.hass = hass self._integration_matcher = integration_matcher self._cancel_unavailable_tracking: CALLBACK_TYPE | None = None + self._cancel_logging_listener: CALLBACK_TYPE | None = None self._advertisement_tracker = AdvertisementTracker() @@ -136,6 +138,7 @@ class BluetoothManager: self._bluetooth_adapters = bluetooth_adapters self.storage = storage self.slot_manager = slot_manager + self._debug = _LOGGER.isEnabledFor(logging.DEBUG) @property def supports_passive_scan(self) -> bool: @@ -201,6 +204,11 @@ class BluetoothManager: self._adapters = self._bluetooth_adapters.adapters return self._find_adapter_by_address(address) + @hass_callback + def _async_logging_changed(self, event: Event) -> None: + """Handle logging change.""" + self._debug = _LOGGER.isEnabledFor(logging.DEBUG) + async def async_setup(self) -> None: """Set up the bluetooth manager.""" await self._bluetooth_adapters.refresh() @@ -208,6 +216,9 @@ class BluetoothManager: self._all_history, self._connectable_history = async_load_history_from_system( self._bluetooth_adapters, self.storage ) + self._cancel_logging_listener = self.hass.bus.async_listen( + EVENT_LOGGING_CHANGED, self._async_logging_changed + ) self.async_setup_unavailable_tracking() seen: set[str] = set() for address, service_info in itertools.chain( @@ -225,6 +236,9 @@ class BluetoothManager: if self._cancel_unavailable_tracking: self._cancel_unavailable_tracking() self._cancel_unavailable_tracking = None + if self._cancel_logging_listener: + self._cancel_logging_listener() + self._cancel_logging_listener = None uninstall_multiple_bleak_catcher() @hass_callback @@ -342,7 +356,6 @@ class BluetoothManager: self, old: BluetoothServiceInfoBleak, new: BluetoothServiceInfoBleak, - debug: bool, ) -> bool: """Prefer previous advertisement from a different source if it is better.""" if new.time - old.time > ( @@ -351,7 +364,7 @@ class BluetoothManager: ) ): # If the old advertisement is stale, any new advertisement is preferred - if debug: + if self._debug: _LOGGER.debug( ( "%s (%s): Switching from %s to %s (time elapsed:%s > stale" @@ -370,7 +383,7 @@ class BluetoothManager: ): # If new advertisement is RSSI_SWITCH_THRESHOLD more, # the new one is preferred. - if debug: + if self._debug: _LOGGER.debug( ( "%s (%s): Switching from %s to %s (new rssi:%s - threshold:%s >" @@ -414,7 +427,6 @@ class BluetoothManager: old_connectable_service_info = connectable and connectable_history.get(address) source = service_info.source - debug = _LOGGER.isEnabledFor(logging.DEBUG) # This logic is complex due to the many combinations of scanners # that are supported. # @@ -437,7 +449,7 @@ class BluetoothManager: and (scanner := self._sources.get(old_service_info.source)) and scanner.scanning and self._prefer_previous_adv_from_different_source( - old_service_info, service_info, debug + old_service_info, service_info ) ): # If we are rejecting the new advertisement and the device is connectable @@ -461,7 +473,7 @@ class BluetoothManager: ) and connectable_scanner.scanning and self._prefer_previous_adv_from_different_source( - old_connectable_service_info, service_info, debug + old_connectable_service_info, service_info ) ) ): @@ -523,7 +535,7 @@ class BluetoothManager: ) matched_domains = self._integration_matcher.match_domains(service_info) - if debug: + if self._debug: _LOGGER.debug( "%s: %s %s match: %s", self._async_describe_source(service_info), diff --git a/homeassistant/components/bluetooth/manifest.json b/homeassistant/components/bluetooth/manifest.json index 5f535819473..dd384e80c1e 100644 --- a/homeassistant/components/bluetooth/manifest.json +++ b/homeassistant/components/bluetooth/manifest.json @@ -4,7 +4,7 @@ "after_dependencies": ["hassio"], "codeowners": ["@bdraco"], "config_flow": true, - "dependencies": ["usb"], + "dependencies": ["logger", "usb"], "documentation": "https://www.home-assistant.io/integrations/bluetooth", "iot_class": "local_push", "loggers": [ diff --git a/homeassistant/components/logger/__init__.py b/homeassistant/components/logger/__init__.py index 0d087ef23b7..fe29447aeba 100644 --- a/homeassistant/components/logger/__init__.py +++ b/homeassistant/components/logger/__init__.py @@ -22,6 +22,7 @@ from .const import ( SERVICE_SET_DEFAULT_LEVEL, SERVICE_SET_LEVEL, ) +from .const import EVENT_LOGGING_CHANGED # noqa: F401 from .helpers import ( LoggerDomainConfig, LoggerSettings, diff --git a/tests/components/bluetooth/test_manager.py b/tests/components/bluetooth/test_manager.py index bd1aaea5b6f..85da27b027e 100644 --- a/tests/components/bluetooth/test_manager.py +++ b/tests/components/bluetooth/test_manager.py @@ -992,3 +992,60 @@ async def test_goes_unavailable_dismisses_discovery_and_makes_discoverable( cancel() unsetup_connectable_scanner() cancel_connectable_scanner() + + +async def test_debug_logging( + hass: HomeAssistant, + enable_bluetooth: None, + register_hci0_scanner: None, + register_hci1_scanner: None, + caplog: pytest.LogCaptureFixture, +) -> None: + """Test debug logging.""" + await hass.services.async_call( + "logger", + "set_level", + {"homeassistant.components.bluetooth": "DEBUG"}, + blocking=True, + ) + + address = "44:44:33:11:23:41" + start_time_monotonic = 50.0 + + switchbot_device_poor_signal_hci0 = generate_ble_device( + address, "wohand_poor_signal_hci0" + ) + switchbot_adv_poor_signal_hci0 = generate_advertisement_data( + local_name="wohand_poor_signal_hci0", service_uuids=[], rssi=-100 + ) + inject_advertisement_with_time_and_source( + hass, + switchbot_device_poor_signal_hci0, + switchbot_adv_poor_signal_hci0, + start_time_monotonic, + "hci0", + ) + assert "wohand_poor_signal_hci0" in caplog.text + caplog.clear() + + await hass.services.async_call( + "logger", + "set_level", + {"homeassistant.components.bluetooth": "WARNING"}, + blocking=True, + ) + + switchbot_device_good_signal_hci0 = generate_ble_device( + address, "wohand_good_signal_hci0" + ) + switchbot_adv_good_signal_hci0 = generate_advertisement_data( + local_name="wohand_good_signal_hci0", service_uuids=[], rssi=-33 + ) + inject_advertisement_with_time_and_source( + hass, + switchbot_device_good_signal_hci0, + switchbot_adv_good_signal_hci0, + start_time_monotonic, + "hci0", + ) + assert "wohand_good_signal_hci0" not in caplog.text diff --git a/tests/components/bluetooth/test_scanner.py b/tests/components/bluetooth/test_scanner.py index fcff8c15d58..bc32a5b302d 100644 --- a/tests/components/bluetooth/test_scanner.py +++ b/tests/components/bluetooth/test_scanner.py @@ -461,7 +461,13 @@ async def test_adapter_fails_to_start_and_takes_a_bit_to_init( hass: HomeAssistant, one_adapter: None, caplog: pytest.LogCaptureFixture ) -> None: """Test we can recover the adapter at startup and we wait for Dbus to init.""" - + assert await async_setup_component(hass, "logger", {}) + await hass.services.async_call( + "logger", + "set_level", + {"homeassistant.components.bluetooth": "DEBUG"}, + blocking=True, + ) called_start = 0 called_stop = 0 _callback = None