fix(bindings): reset a BlueZ controller the kernel lost track of

CHANGELOG.md

@@ -70,6 +70,15 @@ archived by series under [docs/changelog/](docs/changelog/); see the
 
 ### Fixed
 
+- **Python: a Linux box that could no longer advertise recovers on its own.**
+  Linux loses track of the controller's advertising when a central-role
+  connection completes while advertising is on: the controller keeps
+  advertising, the kernel believes it stopped, and every later advertisement
+  is refused with "Failed to register advertisement" until the controller is
+  reset, across service restarts. When BlueZ refuses an advertisement that
+  way while reporting free slots, the peripheral now powers the adapter off
+  and on once (which resets the controller) and starts again, and both roles
+  register again whenever an adapter powers back on.
 - **Python: Bluetooth LE no longer takes bluetoothd down, and survives it
   restarting.** On BlueZ 5.87 bluetoothd exits the moment a
   discovery filter naming a service UUID is set, and the central set one at

bindings/python/offline_protocol_sdk/ble_peripheral.py

@@ -306,6 +306,112 @@ async def _unregister_bluez_application(server: Any) -> None:
         logger.debug("unexporting the GATT application failed", exc_info=True)
 
 
+# BlueZ's answer to a RegisterAdvertisement the kernel refused. A full set of
+# advertising slots is answered differently ("Maximum advertisements
+# reached"), before the kernel is asked.
+_ADVERTISEMENT_REFUSED = "Failed to register advertisement"
+_BLUEZ_ADAPTER_IFACE = "org.bluez.Adapter1"
+_BLUEZ_ADVERTISING_IFACE = "org.bluez.LEAdvertisingManager1"
+
+# Seconds to let a re-powered adapter settle before registering again.
+_ADAPTER_RESET_SETTLE = 1.0
+
+
+async def _reset_wedged_advertising() -> bool:
+    """Power-cycle an adapter whose controller refuses every advertisement.
+
+    Returns whether it did. Best effort, and never raises.
+
+    Linux loses track of the controller's advertising: the kernel clears its
+    "advertising" flag on every LE connection complete, assuming the
+    controller stopped advertising, which a controller only does for a link
+    in which it is the peripheral. When advertising is enabled while our
+    central's dial is pending (a discovery restart re-enables it), the dial
+    completes in the central role and the controller keeps advertising while
+    the kernel believes it stopped. From then on the kernel never disables it,
+    every LE Set Advertising Parameters is answered Command Disallowed, and
+    every new advertisement is refused with "Failed to register
+    advertisement", for this process and every later one, until the
+    controller is reset. Seen on Raspberry Pi 4s (Linux 6.18, BlueZ 5.87): a
+    replaced service could not advertise again, which looked like
+    advertisements left behind holding the slots, while BlueZ reported all of
+    them free.
+
+    Powering the adapter off and on re-initialises the controller with an
+    HCI Reset, which ends the stale advertising. It also drops every link the
+    adapter holds, for every process using it, which is why it runs only for
+    this refusal, and only when BlueZ reports a free slot: with none free the
+    refusal is about the slots, and a reset would not help.
+    """
+    try:
+        from dbus_next import BusType, Message, MessageType, Variant  # type: ignore[import-not-found]
+        from dbus_next.aio import MessageBus  # type: ignore[import-not-found]
+    except Exception:
+        return False
+    bus: Any = None
+    try:
+        bus = await MessageBus(bus_type=BusType.SYSTEM).connect()
+        reply = await bus.call(Message(
+            destination=_BLUEZ_SERVICE,
+            path="/",
+            interface="org.freedesktop.DBus.ObjectManager",
+            member="GetManagedObjects",
+        ))
+        if reply.message_type != MessageType.METHOD_RETURN:
+            return False
+        adapter = _advertising_adapter(reply.body[0])
+        if adapter is None:
+            return False
+        path, free_slots = adapter
+        if free_slots < 1:
+            return False
+        logger.warning(
+            "the controller refuses every advertisement while BlueZ has %d free; "
+            "power-cycling %s to reset it", free_slots, path,
+        )
+        for powered in (False, True):
+            reply = await bus.call(Message(
+                destination=_BLUEZ_SERVICE,
+                path=path,
+                interface="org.freedesktop.DBus.Properties",
+                member="Set",
+                signature="ssv",
+                body=[_BLUEZ_ADAPTER_IFACE, "Powered", Variant("b", powered)],
+            ))
+            if reply.message_type != MessageType.METHOD_RETURN:
+                logger.warning("powering %s %s failed: %s", path,
+                               "on" if powered else "off", reply.error_name)
+                return False
+        await asyncio.sleep(_ADAPTER_RESET_SETTLE)
+        return True
+    except Exception:
+        logger.debug("resetting the adapter failed", exc_info=True)
+        return False
+    finally:
+        if bus is not None:
+            try:
+                bus.disconnect()
+            except Exception:
+                logger.debug("closing the adapter reset bus failed", exc_info=True)
+
+
+def _advertising_adapter(objects: Any) -> tuple[str, int] | None:
+    """The first adapter that advertises, and its free advertising slots.
+
+    The first in path order, as bless picks it: ``hci0`` before ``hci1``.
+    """
+    for path in sorted(objects):
+        interfaces = objects[path]
+        if _BLUEZ_ADAPTER_IFACE not in interfaces:
+            continue
+        manager = interfaces.get(_BLUEZ_ADVERTISING_IFACE)
+        if manager is None:
+            continue
+        free = manager.get("SupportedInstances")
+        return path, int(getattr(free, "value", free) or 0)
+    return None
+
+
 def _central_id_from_device_path(path: Any) -> str | None:
     """``/org/bluez/hci0/dev_AA_BB_CC_DD_EE_FF`` -> ``AA:BB:CC:DD:EE:FF``."""
     if not isinstance(path, str):
@@ -536,7 +642,7 @@ def __init__(
         # restart drops the GATT application and the advertisement, and
         # nothing on the bus tells the process that registered them.
         self._registration = StaysRegistered(
-            self._start_advertising, self._stop_advertising, self._emit_diagnostic
+            self._bring_up, self._stop_advertising, self._emit_diagnostic
         )
         # Central id -> the address its hello proved. A link bound here feeds
         # its fragments to the core under that address, which is what lets a
@@ -609,6 +715,27 @@ async def stop(self) -> None:
         """Stop advertising and disconnect all centrals."""
         await self._registration.stop()
 
+    async def _bring_up(self) -> None:
+        """Start advertising, resetting a wedged controller once (Linux).
+
+        See :func:`_reset_wedged_advertising`. Once, not in a loop: a refusal
+        that survives a controller reset has another cause, and resetting
+        again would only drop every link on the adapter again.
+        """
+        try:
+            await self._start_advertising()
+        except TransportError as exc:
+            if sys.platform != "linux" or _ADVERTISEMENT_REFUSED not in str(exc):
+                raise
+            if not await _reset_wedged_advertising():
+                raise
+            self._emit_diagnostic(
+                "warning",
+                "the controller refused the advertisement; reset the adapter, starting again",
+                {"error": str(exc)},
+            )
+            await self._start_advertising()
+
     async def _start_advertising(self) -> None:
         if self._state == TransportState.RUNNING:
             raise TransportError("BLE peripheral is already running")

bindings/python/offline_protocol_sdk/bluez_restarts.py

@@ -15,6 +15,14 @@
 ``on_restart`` once the name has a new owner, which is when registering
 again can succeed.
 
+An adapter powered off and on again is the same loss for the central: BlueZ
+drops every discovery session when the adapter powers off, and the scan does
+not come back with the power. So ``on_restart`` is also called when an
+adapter's ``Powered`` turns true. The peripheral powers the adapter off and on
+itself to reset a controller that refuses every advertisement (see
+``ble_peripheral._reset_wedged_advertising``); without this the central in
+the same process stopped hearing anyone from then on.
+
 Linux only, and best effort: where there is no system bus to watch (a test
 host, a container without the grant) it logs and stays inert, which is the
 behaviour that existed before it.
@@ -32,10 +40,15 @@
 logger = logging.getLogger(__name__)
 
 _MATCH = "type='signal',sender='org.freedesktop.DBus',member='NameOwnerChanged',arg0='org.bluez'"
+_POWER_MATCH = (
+    "type='signal',sender='org.bluez',interface='org.freedesktop.DBus.Properties',"
+    "member='PropertiesChanged',arg0='org.bluez.Adapter1'"
+)
 
 
 class BlueZRestarts:
-    """Counts bluetoothd's exits and calls ``on_restart`` when it is back."""
+    """Counts bluetoothd's exits and calls ``on_restart`` when it is back, or
+    when an adapter powers back on."""
 
     def __init__(self, on_restart: Callable[[], None]) -> None:
         self._on_restart = on_restart
@@ -57,16 +70,17 @@ async def start(self) -> None:
             from dbus_fast.aio import MessageBus
 
             bus = await MessageBus(bus_type=BusType.SYSTEM).connect()
-            await bus.call(
-                Message(
-                    destination="org.freedesktop.DBus",
-                    path="/org/freedesktop/DBus",
-                    interface="org.freedesktop.DBus",
-                    member="AddMatch",
-                    signature="s",
-                    body=[_MATCH],
+            for rule in (_MATCH, _POWER_MATCH):
+                await bus.call(
+                    Message(
+                        destination="org.freedesktop.DBus",
+                        path="/org/freedesktop/DBus",
+                        interface="org.freedesktop.DBus",
+                        member="AddMatch",
+                        signature="s",
+                        body=[rule],
+                    )
                 )
-            )
         except Exception as exc:
             logger.info("bluetoothd restarts are not watched here: %s", exc)
             return
@@ -95,6 +109,10 @@ def stop(self) -> None:
             logger.debug("closing the bluetoothd watch failed", exc_info=True)
 
     def _observe(self, message: Any) -> None:
+        if _powered_on(message):
+            logger.warning("the Bluetooth adapter powered on again; what was registered with it is gone")
+            self._call_back()
+            return
         if message.member != "NameOwnerChanged" or not message.body or message.body[0] != "org.bluez":
             return
         _, old_owner, new_owner = message.body
@@ -104,10 +122,26 @@ def _observe(self, message: Any) -> None:
             logger.warning("bluetoothd left the bus; what was registered with it is gone")
         elif new_owner:
             self._owned.set()
-            try:
-                self._on_restart()
-            except Exception:
-                logger.exception("handling a bluetoothd restart failed")
+            self._call_back()
+
+    def _call_back(self) -> None:
+        try:
+            self._on_restart()
+        except Exception:
+            logger.exception("handling a bluetoothd restart failed")
+
+
+def _powered_on(message: Any) -> bool:
+    """Whether ``message`` says an adapter's ``Powered`` turned true."""
+    if message.member != "PropertiesChanged" or not message.body:
+        return False
+    if message.body[0] != "org.bluez.Adapter1" or len(message.body) < 2:
+        return False
+    changed = message.body[1]
+    if not isinstance(changed, dict) or "Powered" not in changed:
+        return False
+    powered = changed["Powered"]
+    return bool(getattr(powered, "value", powered))
 
 
 class StaysRegistered:
@@ -120,8 +154,9 @@ class StaysRegistered:
       "Message recipient disconnected from message bus without replying") is
       retried once the new bluetoothd is up. A start refused for any other
       reason is raised at once, as before.
-    - A role that is running when bluetoothd restarts is torn down and
-      brought up again, so it is registered with the new process.
+    - A role that is running when bluetoothd restarts, or when an adapter
+      powers on again, is torn down and brought up again, so it is
+      registered with the process and the adapter as they are now.
 
     Only one of the two ever drives the role. A start cut short by an exit
     is followed, about 150 ms later, by the successor claiming the name; that
@@ -225,7 +260,7 @@ def _restarted(self) -> None:
         self._recovery = asyncio.ensure_future(self._register_again())
 
     async def _register_again(self) -> None:
-        self._emit("warning", "bluetoothd restarted; registering with it again", None)
+        self._emit("warning", "bluetoothd restarted or the adapter powered on again; registering again", None)
         await self._tear_down()
         # A bluetoothd that has just started can refuse a registration for a
         # while (its adapter still powering up, or "InProgress" for a
@@ -241,11 +276,11 @@ async def _register_again(self) -> None:
                 error = exc
                 await self._tear_down()
             else:
-                self._emit("info", "registered with the restarted bluetoothd", None)
+                self._emit("info", "registered with bluetoothd again", None)
                 return
         # Nothing tries again after this until bluetoothd restarts once more
         # or the owner restarts the role: the error is the operator's signal.
-        self._emit("error", "could not register with the restarted bluetoothd", {"error": str(error)})
+        self._emit("error", "could not register with bluetoothd again", {"error": str(error)})
 
 
 def _weakly(fn: Callable[..., Any]) -> Callable[..., Any]: