diff --git a/CHANGELOG.rst b/CHANGELOG.rst index 067627157..e5700c1f4 100644 --- a/CHANGELOG.rst +++ b/CHANGELOG.rst @@ -21,6 +21,7 @@ Changed Fixed ----- * Fixed handling empty notification payloads in BlueZ backend when using "AcquireNotify". Fixes #1982. +* Fixed ``BleakScanner.stop()`` raising ``BleakDBusError`` with ``org.bluez.Error.InProgress`` in BlueZ backend when the kernel had already stopped scanning. A single rejection is now logged and tolerated; two in a row on the same adapter still raise, since that means bluetoothd's discovery state is stuck. Fixes #2021. `3.0.2`_ (2026-05-02) ===================== diff --git a/bleak/backends/bluezdbus/manager.py b/bleak/backends/bluezdbus/manager.py index 414731c0b..3b04a0aef 100644 --- a/bleak/backends/bluezdbus/manager.py +++ b/bleak/backends/bluezdbus/manager.py @@ -196,6 +196,9 @@ def __init__(self) -> None: defaultdict(list) ) self._device_removed_callbacks: list[DeviceRemovedCallbackAndState] = [] + # adapters whose most recent StopDiscovery was rejected with InProgress + # and has not been followed by a clean stop since; see active_scan() + self._stop_rejected: set[str] = set() self._device_watchers: dict[str, set[DeviceWatcher]] = {} self._condition_callbacks: dict[str, set[DeviceConditionCallback]] = {} self._services_cache: dict[str, BleakGATTServiceCollection] = {} @@ -502,9 +505,51 @@ async def stop() -> None: try: assert_reply(reply) except BleakDBusError as ex: - if ex.dbus_error != defs.BLUEZ_ERROR_NOT_READY: + # InProgress here is the kernel rejecting the stop + # because it is not actively scanning at that + # moment (already stopped, or mid-restart); BlueZ + # has already removed our discovery session by the + # time it replies, so nothing is left to stop: + # bluetoothd's stop_discovery_complete() calls + # discovery_remove() before checking the status, + # then relays MGMT_STATUS_REJECTED as InProgress. + # See https://github.com/hbldh/bleak/issues/2021 + # and https://github.com/bluez/bluez/issues/807. + if ex.dbus_error not in ( + defs.BLUEZ_ERROR_NOT_READY, + defs.BLUEZ_ERROR_IN_PROGRESS, + ): raise + if ex.dbus_error == defs.BLUEZ_ERROR_IN_PROGRESS: + # A one-off rejection is a harmless race with + # the kernel's own scan timeout, and the next + # stop on the adapter succeeds. Two in a row + # with no clean stop between them cannot come + # from that race: bluetoothd has lost track of + # the kernel's scan state and no scan on this + # adapter will reach the kernel until it is + # reset. Surface that one as the error it is; + # see the Linux section of docs/troubleshooting. + if adapter_path in self._stop_rejected: + logger.warning( + "StopDiscovery on %s returned InProgress " + "twice in a row; bluetoothd's discovery " + "state appears stuck and scans on this " + "adapter will see nothing until it is " + "reset (power cycle or re-plug the " + "adapter, or restart bluetoothd)", + adapter_path, + ) + raise + self._stop_rejected.add(adapter_path) + logger.info( + "StopDiscovery on %s returned InProgress; " + "BlueZ had already ended our discovery " + "session, so the scan is stopped", + adapter_path, + ) else: + self._stop_rejected.discard(adapter_path) # remove the filters reply = await self._bus.call( Message( diff --git a/docs/troubleshooting.rst b/docs/troubleshooting.rst index 3634b6612..27c82a608 100644 --- a/docs/troubleshooting.rst +++ b/docs/troubleshooting.rst @@ -149,6 +149,32 @@ with similar problems on Raspberry Pi and other devices. If you need Wi-Fi, you can possibly work around the issue by using a USB Bluetooth adapter instead. +"StopDiscovery returned InProgress" in the log, or scans that see nothing +========================================================================= + +On Linux the kernel ends an LE scan on its own after about 10 seconds and +BlueZ restarts it a few seconds later for as long as a scanner is active. If +Bleak stops a scan in the moment between those two, BlueZ rejects the stop +with ``InProgress`` even though it has already ended Bleak's discovery +session. Bleak treats this as a completed stop and logs it at INFO level. +Seen once, it is harmless: the scan that follows may return no devices, +because BlueZ still believes it is discovering and does not start the kernel +scan, and the scan after that works normally. + +``bluetoothd`` can also lose track of the kernel's scan state for good (see +`bluez/bluez#807 `_). Then every +stop on that adapter is rejected and no scan on it reaches the kernel until +the adapter is reset. Bleak detects this as two ``InProgress`` rejections in +a row with no successful stop between them: the second one is logged at +WARNING level and ``BleakScanner.stop()`` raises ``BleakDBusError`` so the +caller knows the adapter is not scanning. Power cycle or re-plug the adapter, +or restart ``bluetoothd``. The ``Discovering`` property of the adapter is not +a reliable indicator here, since BlueZ leaves it set to ``true`` in both the +harmless and the stuck case. The detection only sees stops made by the +current process while it is the only scanner on the adapter; another active +scanner on the same adapter makes BlueZ answer the stop without asking the +kernel, which counts as a successful stop. + ---------- macOS Bugs ---------- diff --git a/tests/backends/bluezdbus/test_issue_2021.py b/tests/backends/bluezdbus/test_issue_2021.py new file mode 100644 index 000000000..b9249d88a --- /dev/null +++ b/tests/backends/bluezdbus/test_issue_2021.py @@ -0,0 +1,169 @@ +"""Regression test for .""" + +import logging +import sys + +import pytest + +if sys.platform != "linux": + pytest.skip("skipping linux-only tests", allow_module_level=True) + assert False # HACK: work around pyright bug + +from dbus_fast import Message, MessageType, Variant + +from bleak.backends.bluezdbus import defs +from bleak.backends.bluezdbus.manager import ( + AdvertisementCallback, + BlueZManager, + Device1, + DeviceRemovedCallback, +) +from bleak.exc import BleakDBusError + +ADAPTER_PATH = "/org/bluez/hci0" + +NO_FILTERS: dict[str, Variant] = {} + +LOGGER = "bleak.backends.bluezdbus.manager" + + +def _on_advertisement(path: str, props: Device1) -> None: + pass + + +def _on_removed(path: str) -> None: + pass + + +_ADV: AdvertisementCallback = _on_advertisement +_REMOVED: DeviceRemovedCallback = _on_removed + + +class FakeBus: + """ + Answers every call with a method return, except StopDiscovery, which is + answered from ``stop_errors`` in order (``None`` means success) and with + success once that list is used up. + """ + + def __init__(self, stop_errors: "list[str | None]") -> None: + self.stop_errors = list(stop_errors) + self.members: "list[str | None]" = [] + + async def call(self, msg: Message) -> Message: + # outgoing messages carry serial 0 until a real bus assigns one, so + # replies are built explicitly rather than derived from the request + self.members.append(msg.member) + if msg.member == "StopDiscovery" and self.stop_errors: + error = self.stop_errors.pop(0) + if error is not None: + return Message( + message_type=MessageType.ERROR, + reply_serial=1, + error_name=error, + signature="s", + body=["Operation already in progress"], + ) + return Message(message_type=MessageType.METHOD_RETURN, reply_serial=1) + + +def make_manager(stop_errors: "list[str | None]") -> "tuple[BlueZManager, FakeBus]": + manager = BlueZManager() + bus = FakeBus(stop_errors) + manager._bus = bus # type: ignore[assignment] + properties = manager._properties # pyright: ignore[reportPrivateUsage] + properties[ADAPTER_PATH] = {defs.ADAPTER_INTERFACE: {}} + return manager, bus + + +async def _scan_and_stop(manager: BlueZManager) -> None: + stop = await manager.active_scan(ADAPTER_PATH, NO_FILTERS, _ADV, _REMOVED) + await stop() + + +def _assert_callbacks_removed(manager: BlueZManager) -> None: + """stop() removes the session's callbacks before it talks to BlueZ, so + they must be gone whether or not the StopDiscovery call succeeded.""" + adv = manager._advertisement_callbacks # pyright: ignore[reportPrivateUsage] + removed = manager._device_removed_callbacks # pyright: ignore[reportPrivateUsage] + assert adv[ADAPTER_PATH] == [] + assert removed == [] + + +def _records(caplog: pytest.LogCaptureFixture, level: int) -> "list[str]": + return [r.getMessage() for r in caplog.records if r.levelno == level] + + +async def test_stop_tolerates_in_progress(caplog: pytest.LogCaptureFixture) -> None: + """ + BlueZ answers StopDiscovery with InProgress when the kernel has already + stopped scanning; the discovery session is gone by then, so stop() must + return normally, leave the manager's bookkeeping clean, and leave a + record in the log. + """ + manager, bus = make_manager([defs.BLUEZ_ERROR_IN_PROGRESS]) + + with caplog.at_level(logging.INFO, logger=LOGGER): + await _scan_and_stop(manager) + + assert bus.members == ["SetDiscoveryFilter", "StartDiscovery", "StopDiscovery"] + _assert_callbacks_removed(manager) + assert any( + "InProgress" in m and ADAPTER_PATH in m for m in _records(caplog, logging.INFO) + ) + assert not _records(caplog, logging.WARNING) + + +async def test_second_consecutive_in_progress_raises( + caplog: pytest.LogCaptureFixture, +) -> None: + """ + A single rejection is a race with the kernel's scan timeout and the next + stop succeeds. Two in a row means bluetoothd's discovery state is stuck + and no scan on the adapter reaches the kernel, so the second one must be + reported as an error, with a warning that says what to do. + """ + manager, bus = make_manager( + [defs.BLUEZ_ERROR_IN_PROGRESS, defs.BLUEZ_ERROR_IN_PROGRESS] + ) + + with caplog.at_level(logging.INFO, logger=LOGGER): + await _scan_and_stop(manager) + with pytest.raises(BleakDBusError) as info: + await _scan_and_stop(manager) + + assert info.value.dbus_error == defs.BLUEZ_ERROR_IN_PROGRESS + assert bus.members.count("StopDiscovery") == 2 + _assert_callbacks_removed(manager) + warnings = _records(caplog, logging.WARNING) + assert len(warnings) == 1 + assert "twice in a row" in warnings[0] and ADAPTER_PATH in warnings[0] + + +async def test_a_clean_stop_resets_the_count(caplog: pytest.LogCaptureFixture) -> None: + """A successful stop between two rejections means they were two separate + races, not a stuck adapter; neither may raise.""" + manager, bus = make_manager( + [defs.BLUEZ_ERROR_IN_PROGRESS, None, defs.BLUEZ_ERROR_IN_PROGRESS] + ) + + with caplog.at_level(logging.INFO, logger=LOGGER): + await _scan_and_stop(manager) + await _scan_and_stop(manager) + await _scan_and_stop(manager) + + assert bus.members.count("StopDiscovery") == 3 + # only the successful stop goes on to reset the discovery filter + assert bus.members.count("SetDiscoveryFilter") == 3 + 1 + assert len(_records(caplog, logging.INFO)) == 2 + assert not _records(caplog, logging.WARNING) + + +async def test_stop_still_raises_other_errors() -> None: + manager, _ = make_manager([defs.BLUEZ_ERROR_FAILED]) + + stop = await manager.active_scan(ADAPTER_PATH, NO_FILTERS, _ADV, _REMOVED) + with pytest.raises(BleakDBusError) as info: + await stop() + + assert info.value.dbus_error == defs.BLUEZ_ERROR_FAILED