diff --git a/recipes-devtools/python/python3-improv/imx93-jaguar-eink/onboarding-server.py b/recipes-devtools/python/python3-improv/imx93-jaguar-eink/onboarding-server.py index b93c3467..14ae1744 100644 --- a/recipes-devtools/python/python3-improv/imx93-jaguar-eink/onboarding-server.py +++ b/recipes-devtools/python/python3-improv/imx93-jaguar-eink/onboarding-server.py @@ -27,6 +27,7 @@ import socket import struct import fcntl +import time logging.basicConfig(level=logging.DEBUG) logger = logging.getLogger(name=__name__) @@ -199,14 +200,41 @@ def get_hw_revision(): """Hardware revision. No standard source on this SoC; overridable via env.""" return "unknown" -# Board-specific configuration for imx93-jaguar-eink (overridable via environment) -SERVER_HOST = os.getenv("IMPROV_SERVER_HOST", "api.co.uk") +# Board-specific configuration for imx93-jaguar-eink (overridable via environment). +# Default is the live Active-ESL onboarding backend; improv.service also sets this +# via IMPROV_SERVER_HOST, but the default must be a real host so the server still +# points somewhere valid if the env var is ever missing. +SERVER_HOST = os.getenv( + "IMPROV_SERVER_HOST", "active-esl-onboard.active-esl.workers.dev" +) BOARD_ID = get_board_id() DEFAULT_SERVICE_NAME = f"eink-{BOARD_ID}" SERVICE_NAME = os.getenv("IMPROV_SERVICE_NAME", DEFAULT_SERVICE_NAME) CON_NAME = os.getenv("IMPROV_CONNECTION_NAME", "improv-eink") INTERFACE = os.getenv("IMPROV_WIFI_INTERFACE", "wlan0") TIMEOUT = int(os.getenv("IMPROV_CONNECTION_TIMEOUT", "10000")) +# How often the advertising watchdog re-checks that BlueZ is still advertising +# and re-registers it if not. Kept short so a dropped advert self-heals within +# seconds — onboarding must never depend on a manual service restart. +ADVERT_WATCHDOG_SECS = int(os.getenv("IMPROV_ADVERT_WATCHDOG_SECS", "15")) +# Hard timeout on each BlueZ D-Bus call the watchdog makes, so a wedged BLE +# stack can never freeze the watchdog loop itself. +ADVERT_DBUS_TIMEOUT = float(os.getenv("IMPROV_ADVERT_DBUS_TIMEOUT", "5")) +# Consecutive watchdog failures (can't query state, or can't re-register) after +# which we treat the BLE stack as unrecoverable and exit so systemd restarts us +# (Restart=always) — a clean re-init reliably restores advertising. +ADVERT_MAX_FAILURES = int(os.getenv("IMPROV_ADVERT_MAX_FAILURES", "3")) +# How often we proactively BOUNCE (unregister + re-register) the advertisement +# even while BlueZ reports it as active. This is the backstop for the "ghost +# advertising" state: BlueZ reports ActiveInstances>=1 but nothing is actually +# on-air, so is_advertising() looks healthy and the drop-detection above never +# fires. Observed after a failed/aborted BLE connect and around a fresh boot, +# with Wi-Fi OFF (so not coexistence) — the board silently becomes +# un-onboardable until a manual restart. Since ActiveInstances cannot tell us +# whether the advert is truly radiating, we periodically re-assert it; kept +# short so onboarding recovers within ~a minute without a restart. A bounce is +# a sub-second re-register gap and is skipped whenever a central is mid-session. +ADVERT_BOUNCE_SECS = int(os.getenv("IMPROV_ADVERT_BOUNCE_SECS", "60")) # Device Information Service values (auto-detected, overridable via environment # for multi-board reuse). @@ -386,6 +414,159 @@ async def net_status_loop(loop): _net_refresh_event.clear() +def _drop_stale_adverts(): + """Unexport and forget any advertisement objects bless is still tracking. + + Used when BlueZ has already dropped the advertisement (ActiveInstances==0): + bless's stale objects would otherwise leak D-Bus objects and keep pushing the + advertisement instance index upward on repeated recoveries. + + This is deliberately NOT wrapped in a timeout like the stop/start_advertising + calls: ``bus.unexport`` is purely local, non-blocking bookkeeping. It removes + the object from dbus-fast's export table and buffers a non-blocking + ``InterfacesRemoved`` signal — there is no awaited D-Bus round-trip that a + wedged BlueZ stack could stall on, so there is nothing to time out. It must + also run on the event-loop thread (the dbus-fast bus is loop-affine), so it + cannot be offloaded to an executor. Each call is guarded so one bad object + can never abort the cleanup of the rest. + """ + app = server.app + stale = getattr(app, "advertisements", None) + if not stale: + return + for old in list(stale): + try: + app.bus.unexport(old.path) + except Exception as e: + logger.debug(f"unexport of stale advert {old.path!r} failed: {e!r}") + stale.clear() + + +async def _reassert_advert(had_registration: bool): + """(Re)assert the BLE advertisement so it is actually radiating again. + + had_registration True -> BlueZ still reports the advert (a bounce): cleanly + stop_advertising() first so BlueZ drops the live + instance, then start a fresh one. + had_registration False -> BlueZ already forgot it: drop bless's stale + trackers, then start a fresh one. + """ + app = server.app + adapter = server.adapter + if had_registration: + try: + await asyncio.wait_for( + app.stop_advertising(adapter), timeout=ADVERT_DBUS_TIMEOUT) + except Exception as e: + logger.warning( + f"advert bounce: stop_advertising failed ({e!r}); " + "clearing stale objects instead") + _drop_stale_adverts() + else: + _drop_stale_adverts() + await asyncio.wait_for( + app.start_advertising(adapter), timeout=ADVERT_DBUS_TIMEOUT) + + +async def advertising_watchdog(): + """Keep the Improv BLE advertisement alive AND actually on-air for the whole + product lifetime. + + Two independent failure modes are handled: + + 1. Registration drop — BlueZ forgets the advertisement entirely + (ActiveInstances==0). bless registers it exactly once (in + ``server.start()``), so without this it stays gone until a manual restart. + Seen after ~an hour of uptime, adapter resets, and post-provision + NetworkManager churn. + + 2. On-air stall ("ghost advertising") — BlueZ still reports + ActiveInstances>=1 but nothing is radiating, so ``is_advertising()`` looks + healthy and case 1 never fires. Reproduced after a failed/aborted BLE + connect and around a fresh boot, with Wi-Fi OFF (so not coexistence): the + board silently becomes un-onboardable until a manual restart. Because + ActiveInstances cannot tell us whether the advert is truly on-air, we + cannot *detect* this directly — instead we periodically BOUNCE (re-assert) + the advertisement every ``ADVERT_BOUNCE_SECS`` so any stall self-heals + within about a minute. + + Both re-assertions are skipped while a central is mid-session (a subscribed + characteristic) so we never disrupt an in-progress onboarding. + """ + logger.info( + f"advertising watchdog started (check every {ADVERT_WATCHDOG_SECS}s, " + f"bounce every {ADVERT_BOUNCE_SECS}s)") + failures = 0 + last_assert = time.monotonic() + while True: + await asyncio.sleep(ADVERT_WATCHDOG_SECS) + + # 1) Query current state, but never let a wedged BLE stack freeze the + # loop: bound every D-Bus call with a timeout. + try: + connected = await asyncio.wait_for( + server.is_connected(), timeout=ADVERT_DBUS_TIMEOUT) + advertising = await asyncio.wait_for( + server.is_advertising(), timeout=ADVERT_DBUS_TIMEOUT) + except asyncio.CancelledError: + raise + except Exception as e: + failures += 1 + logger.error( + f"advertising watchdog: cannot query BLE state ({e!r}); " + f"failures={failures}/{ADVERT_MAX_FAILURES}") + if failures >= ADVERT_MAX_FAILURES: + logger.error("advertising watchdog: BLE stack unresponsive; " + "exiting so systemd restarts the service") + os._exit(1) + continue + + logger.debug( + f"advertising watchdog: connected={connected} " + f"advertising={advertising}") + + # 2) A central is mid-session — never disturb an in-progress onboarding. + # Reset the bounce clock so we don't bounce the instant it leaves. + if connected: + failures = 0 + last_assert = time.monotonic() + continue + + now = time.monotonic() + due_for_bounce = (now - last_assert) >= ADVERT_BOUNCE_SECS + + # 3) Healthy registration and not yet due a bounce — leave it alone. + if advertising and not due_for_bounce: + if failures: + logger.info("advertising watchdog: BLE advertising healthy again") + failures = 0 + continue + + # 4) Re-assert the advertisement: either it is fully down + # (ActiveInstances==0), or it is due a periodic bounce to clear a + # possible on-air stall that BlueZ still reports as active. + reason = ("advertisement is down (ActiveInstances==0)" + if not advertising else + "periodic bounce (clears on-air stalls BlueZ reports as active)") + logger.warning(f"re-asserting BLE advertisement: {reason}") + try: + await _reassert_advert(had_registration=advertising) + last_assert = time.monotonic() + logger.info("BLE advertisement re-asserted by watchdog") + failures = 0 + except asyncio.CancelledError: + raise + except Exception as e: + failures += 1 + logger.error( + f"advertising watchdog: re-assert failed ({e!r}); " + f"failures={failures}/{ADVERT_MAX_FAILURES}") + if failures >= ADVERT_MAX_FAILURES: + logger.error("advertising watchdog: cannot restore advertising; " + "exiting so systemd restarts the service") + os._exit(1) + + def wifi_connect(ssid: str, passwd: str) -> Optional[list[str]]: logger.warning( f"Creating Improv WiFi connection for '{ssid.decode('utf-8')}' with password: '{passwd.decode('utf-8')}'") @@ -529,14 +710,20 @@ async def run(loop): # Populate the static Device Information Service values. _set_dis_values() - # Seed network status once (off the BLE loop so nmcli doesn't stall startup), - # then refresh periodically / on demand. + # Start the background tasks FIRST — especially the advertising watchdog, + # which must run even if the initial network probe below is slow/blocks. + # (Creating them before the initial seed guarantees the event loop keeps the + # watchdog alive regardless of how long the seed's executor call takes.) + net_task = loop.create_task(net_status_loop(loop)) + # Self-healing advertising: onboarding must never rely on a manual restart. + advert_task = loop.create_task(advertising_watchdog()) + # Seed network status once (off the BLE loop so nmcli doesn't stall startup); + # net_status_loop also refreshes it periodically / on demand. try: status = await loop.run_in_executor(None, compute_net_status) _publish_net_status(status, notify=False) except Exception as e: logger.debug(f"initial net status failed: {e}") - net_task = loop.create_task(net_status_loop(loop)) try: trigger.clear() @@ -547,7 +734,20 @@ async def run(loop): except KeyboardInterrupt: logger.debug("Shutting Down") finally: + # Cancel the background tasks AND wait for them to actually finish before + # tearing BlueZ down. The watchdog may be mid _reassert_advert() + # (stop/start advertising) — if we let server.stop() run concurrently the + # two would race over the same BlueZ/D-Bus advertisement resources and + # produce a messy teardown. Awaiting the cancellation serialises it. net_task.cancel() + advert_task.cancel() + for t in (net_task, advert_task): + try: + await t + except asyncio.CancelledError: + pass + except Exception as e: + logger.debug(f"background task raised during shutdown: {e!r}") await server.stop() try: