diff --git a/Bot_Usage.md b/Bot_Usage.md index 50d6ecb..00b146b 100644 --- a/Bot_Usage.md +++ b/Bot_Usage.md @@ -379,6 +379,36 @@ WantedBy=multi-user.target `!adm restart` schedules teardown ~5 seconds after the acknowledgment reply so the ACK has time to be sent and confirmed before the disconnect. +### Radio reconnection (radio reboot / power-cycle / link loss) + +The bot recovers from a lost radio link automatically, in three layers: + +1. **Library auto-reconnect** (first line): the meshcore library retries the + transport 3 times over ~3 seconds and re-sends `APP_START` on success. + This covers sub-second blips; on success the bot refreshes `self_info` + and re-syncs contacts. +2. **Full restart with backoff**: anything longer (a radio reboot takes + 5-60s) exhausts the library's retries, and the bot then tears down and + rebuilds through the same path as `!adm restart` -- a complete startup + resync. If the radio is still unreachable, it keeps retrying with capped + exponential backoff (5s doubling to 60s, forever) instead of exiting, so + it also rides out long outages without help from systemd. +3. **Watchdog probe** (`watchdog_interval`, default 180s, 0 = off): every N + seconds the bot sends a device query; two consecutive missed replies + trigger the full restart. This is what catches the TCP half-open case -- + a silently power-cycled radio on WiFi never signals a disconnect, and an + idle bot might otherwise not notice for hours. On USB serial, disconnects + are detected immediately by the OS, so the watchdog is just a backstop. + Runtime-managed like other settings (`!adm setting watchdog_interval N` + or web Manage->Radio). + +For USB serial, prefer a `/dev/serial/by-id/...` device path in `[radio]` +serial_port -- it is stable across re-enumeration, while `/dev/ttyACM0` can +come back under a different name after a radio reboot. + +A clean `Ctrl-C` / `SIGTERM` always wins over a pending reconnect: signals +end the process even if a restart or backoff wait is in progress. + --- ## 5. Day-to-Day Management diff --git a/bot.py b/bot.py index 1fc92d2..b68db4b 100644 --- a/bot.py +++ b/bot.py @@ -92,6 +92,10 @@ def __init__(self, cfg: Config, log: logging.Logger): # set true by !adm restart to make amain() loop and rebuild a # fresh MCBot instance rather than exiting after shutdown. self.restart_requested: bool = False + # set when the startup connect fails and auto_reconnect is on, so + # amain() retries with backoff instead of exiting the process. + self.connect_failed: bool = False + self._reconnect_restart_armed = False self.my_private_key: Optional[bytes] = None # 64 bytes self.my_public_key_bytes: Optional[bytes] = None # 32 bytes # web admin UI/API (uvicorn server + its serve() task), or None @@ -1748,12 +1752,77 @@ async def _on_connected(self, event) -> None: self.logger.info( "radio %s", "RECONNECTED" if reconnected else "CONNECTED" ) + if reconnected: + # the library re-established the transport in place (short blip) + # and already re-sent APP_START; refresh whatever the radio may + # have changed across its restart and force a contact re-sync. + self._contacts_dirty = True + try: + await self.refresh_self_info() + except Exception: + self.logger.exception("post-reconnect self_info refresh failed") + + def _trigger_reconnect_restart(self, why: str) -> None: + # recover the radio link with a full teardown + rebuild via the + # amain() outer loop (same path as '!adm restart'), so recovery is + # always a complete, well-tested startup resync. + if self.stop_event.is_set() or self._reconnect_restart_armed: + return + self._reconnect_restart_armed = True + self.logger.warning( + "radio link lost (%s) — restarting to reconnect", why + ) + self.restart_requested = True + self.stop_event.set() async def _on_disconnected(self, event) -> None: reason = None if event and isinstance(event.payload, dict): reason = event.payload.get("reason") self.logger.warning("radio DISCONNECTED reason=%s", reason) + # "manual_disconnect" is our own shutdown/restart teardown. Anything + # else means the library has given up (it only emits DISCONNECTED + # once auto-reconnect is exhausted — 3 attempts over ~3s — or off), + # so without action here the bot would sit dead forever. + if reason != "manual_disconnect": + self._trigger_reconnect_restart(f"disconnect: {reason}") + + async def _watchdog_runner(self) -> None: + # Periodic link-liveness probe. A silently power-cycled radio on TCP + # leaves a half-open socket that never raises connection_lost, and an + # idle bot may not send for hours — so the dead link would go + # unnoticed. The probe forces traffic; two consecutive silent probes + # trigger the reconnect/restart path. Interval is a runtime setting + # (watchdog_interval, 0 = disabled), re-read every cycle. + misses = 0 + while not self.stop_event.is_set(): + interval = self.watchdog_interval or 0 + wait = interval if interval > 0 else 60.0 + try: + await asyncio.wait_for(self.stop_event.wait(), timeout=wait) + return + except asyncio.TimeoutError: + pass + if interval <= 0 or self.mc is None: + continue + try: + ev = await asyncio.wait_for( + self.mc.commands.send_device_query(), timeout=10.0 + ) + # any reply — even ERROR — proves the link is alive + ok = ev is not None + except Exception: + ok = False + if ok: + misses = 0 + continue + misses += 1 + self.logger.warning( + "watchdog: radio unresponsive to device query (%d/2)", misses + ) + if misses >= 2: + self._trigger_reconnect_restart("watchdog: radio unresponsive") + return # command dispatch async def _dispatch_command(self, ctx: CommandContext) -> None: @@ -2642,6 +2711,11 @@ async def run(self) -> int: except Exception: self.logger.exception("connect failed (%s)", self.cfg.target_desc()) self.db.close() + if self.cfg.auto_reconnect: + # radio likely rebooting/unplugged: have amain() rebuild and + # retry with backoff rather than exiting the process. + self.connect_failed = True + self.restart_requested = True return 1 # undo MeshCore.__init__'s override so [logging] log_level wins @@ -2816,6 +2890,7 @@ async def periodic_advert(): periodic_task = asyncio.create_task(periodic_contacts()) advert_task = asyncio.create_task(periodic_advert()) + watchdog_task = asyncio.create_task(self._watchdog_runner()) self._start_web() @@ -2823,7 +2898,7 @@ async def periodic_advert(): try: await self.stop_event.wait() finally: - await self.shutdown([periodic_task, advert_task]) + await self.shutdown([periodic_task, advert_task, watchdog_task]) return 0 def _start_web(self) -> None: diff --git a/config.py b/config.py index 2184cd9..152385b 100644 --- a/config.py +++ b/config.py @@ -106,6 +106,13 @@ class Config: # bot_meta, then the DB value is authoritative and runtime-managed (via # '!adm command delay N' and the web Manage->Commands page). command_delay: float = 0.0 + # Radio-link watchdog interval in seconds (0 = disabled). Every N seconds + # the bot pings the radio with a device query; two consecutive missed + # replies trigger a full reconnect/resync. Catches silently dead TCP links + # (e.g. a power-cycled radio) that never signal a disconnect. SEED only: + # first run writes it to bot_meta, then the DB value is authoritative and + # runtime-managed ('!adm setting watchdog_interval N' / web Manage->Radio). + watchdog_interval: int = 180 # --- web admin UI / API ([web] section) --- web_enabled: bool = False web_host: str = "127.0.0.1" # 0.0.0.0 to expose on all interfaces @@ -141,7 +148,8 @@ def target_desc(self) -> str: "dm_max_flood_attempts", "radio_evict_enabled", "radio_evict_headroom", "radio_evict_max_per_run", "radio_evict_min_interval", "radio_evict_protect_types", - "advert_interval_hours", "command_delay", "owner_pubkeys"}, + "advert_interval_hours", "command_delay", "watchdog_interval", + "owner_pubkeys"}, "web": {"enabled", "host", "port", "admin_user", "admin_password_hash", "session_secret", "cors_origins", "api_tokens", "tls_cert", "tls_key"}, @@ -272,6 +280,9 @@ def load_config(args) -> Config: cfg.command_delay = min(2.0, max(0.0, parser["bot"].getfloat( "command_delay", cfg.command_delay ))) + cfg.watchdog_interval = max(0, parser["bot"].getint( + "watchdog_interval", cfg.watchdog_interval + )) protect_raw = parser["bot"].get("radio_evict_protect_types", "") if protect_raw.strip(): cfg.radio_evict_protect_types = parse_contact_types( diff --git a/mcbot.conf.example b/mcbot.conf.example index 3f911bf..47303a2 100644 --- a/mcbot.conf.example +++ b/mcbot.conf.example @@ -151,6 +151,16 @@ owner_pubkeys = 0000000000000000000000000000000000000000000000000000000000000000 ; command delay N' or the web Manage->Commands page (persists across restarts). ;command_delay = 0 +; Radio-link watchdog interval in seconds (0 = disabled; otherwise 30-3600). +; Every N seconds the bot pings the radio with a device query; two consecutive +; missed replies trigger a full reconnect/resync. This catches silently dead +; TCP links (e.g. after a radio power-cycle, which often leaves a half-open +; socket that never signals a disconnect). On USB serial, disconnects are +; detected immediately, so the watchdog is just a backstop there. FIRST-RUN +; SEED only: copied into the database on first start, then runtime-managed via +; '!adm setting watchdog_interval N' or the web Manage->Radio page. +;watchdog_interval = 180 + ; Environment variables for the bot and command scripts. ; Each key here is exported into the process environment at startup, so ; command scripts can read it via os.environ (e.g. commands/pws.py reads diff --git a/mcbot.py b/mcbot.py index 25f89f6..103a9a8 100755 --- a/mcbot.py +++ b/mcbot.py @@ -135,9 +135,12 @@ def parse_args(argv=None): async def amain(argv=None) -> int: - # outer loop so '!adm restart' can fully tear down and rebuild without - # exiting the process. on normal shutdown (Ctrl-C, SIGTERM) we exit - # after the first iteration. + # outer loop so '!adm restart' and radio-loss recovery can fully tear + # down and rebuild without exiting the process. on normal shutdown + # (Ctrl-C, SIGTERM) we exit after the current iteration — signals set + # shutdown_event, which overrides any pending internal restart. + shutdown_event = asyncio.Event() + backoff = 5.0 while True: args = parse_args(argv) cfg = load_config(args) @@ -148,6 +151,7 @@ async def amain(argv=None) -> int: def _signal_handler(): log.info("signal received, stopping") + shutdown_event.set() bot.stop_event.set() for sig in (signal.SIGINT, signal.SIGTERM): @@ -157,8 +161,20 @@ def _signal_handler(): pass rc = await bot.run() - if not bot.restart_requested: + if shutdown_event.is_set() or not bot.restart_requested: return rc + if bot.connect_failed: + # radio unreachable (rebooting / unplugged / WiFi down): retry + # with capped exponential backoff instead of hammering or exiting. + log.warning("radio unavailable — retrying connect in %.0fs", backoff) + try: + await asyncio.wait_for(shutdown_event.wait(), timeout=backoff) + return rc + except asyncio.TimeoutError: + pass + backoff = min(backoff * 2, 60.0) + else: + backoff = 5.0 log.info("=" * 60) log.info("RESTART: reinitializing from fresh config") log.info("=" * 60) diff --git a/settings.py b/settings.py index 1452033..e992e27 100644 --- a/settings.py +++ b/settings.py @@ -102,6 +102,20 @@ def describe(self) -> dict: "database (mcbot.conf only seeds the first-run default)." ), ), + RuntimeSetting( + key="watchdog_interval", kind=int, max=3600, + nonzero_min=30, clamp_max=3600, + label="Radio watchdog interval", unit="seconds", group="radio", + audit_action="radio.watchdog", audit_detail="watchdog={v}s", + description=( + "0 = disabled, otherwise 30–3600s. Every N seconds the bot pings " + "the radio with a device query; two consecutive missed replies " + "trigger a full reconnect/resync. Catches silently dead TCP links " + "(e.g. after a radio power-cycle) that never signal a disconnect. " + "Persists in the database (mcbot.conf only seeds the first-run " + "default)." + ), + ), RuntimeSetting( key="channel_retry_max", kind=int, max=5, clamp_max=5, label="Channel resend on no-repeat", unit="", group="commands", diff --git a/tests/test_reconnect.py b/tests/test_reconnect.py new file mode 100644 index 0000000..031ee6e --- /dev/null +++ b/tests/test_reconnect.py @@ -0,0 +1,150 @@ +"""Radio-link recovery: disconnect-triggered full restart, post-reconnect +resync, the liveness watchdog, and startup connect-retry flags.""" + +import asyncio +from types import SimpleNamespace + + +def ev(payload): + return SimpleNamespace(payload=payload) + + +async def test_disconnect_triggers_restart(bot_factory): + bot = bot_factory() + await bot._on_disconnected(ev({"reason": "tcp_disconnect", "reconnect_failed": True})) + assert bot.restart_requested, "non-manual disconnect requests a restart" + assert bot.stop_event.is_set(), "stop_event set so run() unwinds" + + +async def test_disconnect_trigger_fires_once(bot_factory): + bot = bot_factory() + await bot._on_disconnected(ev({"reason": "serial_disconnect"})) + bot.stop_event.clear() # simulate a racing second event mid-teardown + await bot._on_disconnected(ev({"reason": "serial_disconnect"})) + assert bot._reconnect_restart_armed, "armed flag latches" + assert not bot.stop_event.is_set(), "second event is a no-op" + + +async def test_manual_disconnect_ignored(bot_factory): + bot = bot_factory() + await bot._on_disconnected(ev({"reason": "manual_disconnect"})) + assert not bot.restart_requested and not bot.stop_event.is_set(), \ + "own shutdown/restart teardown must not re-trigger a restart" + + +async def test_disconnect_during_shutdown_ignored(bot_factory): + bot = bot_factory() + bot.stop_event.set() # already shutting down (e.g. Ctrl-C) + await bot._on_disconnected(ev({"reason": "tcp_disconnect"})) + assert not bot.restart_requested, "no restart once shutdown is underway" + + +async def test_reconnected_resyncs_state(bot_factory): + bot = bot_factory() + calls = [] + + async def fake_refresh(): + calls.append(1) + + bot.refresh_self_info = fake_refresh + bot._contacts_dirty = False + await bot._on_connected(ev({"reconnected": True})) + assert bot._contacts_dirty, "contact re-sync forced after in-place reconnect" + assert calls == [1], "self_info refreshed after in-place reconnect" + + # the initial CONNECTED (fresh startup) must not trigger the resync + bot._contacts_dirty = False + calls.clear() + await bot._on_connected(ev({})) + assert not bot._contacts_dirty and calls == [] + + +async def test_watchdog_restarts_after_two_misses(bot_factory): + bot = bot_factory() + bot.watchdog_interval = 0.05 + pings = [] + + async def dead_query(): + pings.append(1) + raise asyncio.TimeoutError + + bot.mc = SimpleNamespace(commands=SimpleNamespace(send_device_query=dead_query)) + await asyncio.wait_for(bot._watchdog_runner(), timeout=2) + assert len(pings) == 2, "gives the radio a second chance before acting" + assert bot.restart_requested and bot.stop_event.is_set(), \ + "two silent probes trigger the reconnect/restart path" + + +async def test_watchdog_error_reply_counts_as_alive(bot_factory): + bot = bot_factory() + bot.watchdog_interval = 0.05 + n = 0 + + async def err_query(): + nonlocal n + n += 1 + return SimpleNamespace(type=SimpleNamespace(name="ERROR"), payload={}) + + bot.mc = SimpleNamespace(commands=SimpleNamespace(send_device_query=err_query)) + task = asyncio.create_task(bot._watchdog_runner()) + await asyncio.sleep(0.3) + bot.stop_event.set() + await asyncio.wait_for(task, timeout=2) + assert n >= 2, "kept probing" + assert not bot.restart_requested, "any reply — even ERROR — is a live link" + + +async def test_watchdog_single_miss_recovers(bot_factory): + bot = bot_factory() + bot.watchdog_interval = 0.05 + n = 0 + + async def flaky_query(): + nonlocal n + n += 1 + if n == 1: + return None # one lost probe + return SimpleNamespace(type=SimpleNamespace(name="OK"), payload={}) + + bot.mc = SimpleNamespace(commands=SimpleNamespace(send_device_query=flaky_query)) + task = asyncio.create_task(bot._watchdog_runner()) + await asyncio.sleep(0.3) + bot.stop_event.set() + await asyncio.wait_for(task, timeout=2) + assert n >= 3, "kept probing after the miss" + assert not bot.restart_requested, "a single miss followed by a reply resets" + + +async def test_watchdog_disabled_never_pings(bot_factory): + bot = bot_factory() + bot.watchdog_interval = 0 + pinged = False + + async def query(): + nonlocal pinged + pinged = True + + bot.mc = SimpleNamespace(commands=SimpleNamespace(send_device_query=query)) + task = asyncio.create_task(bot._watchdog_runner()) + await asyncio.sleep(0.1) + bot.stop_event.set() + await asyncio.wait_for(task, timeout=2) + assert not pinged, "0 = disabled" + + +async def test_connect_failure_sets_retry_flags(bot_factory): + # 127.0.0.1:1 refuses immediately — exercises run()'s connect-error path + bot = bot_factory(transport="tcp", host="127.0.0.1", port=1, + auto_reconnect=True) + rc = await bot.run() + assert rc == 1 + assert bot.connect_failed and bot.restart_requested, \ + "amain() gets the signal to rebuild + back off" + + +async def test_connect_failure_no_retry_when_disabled(bot_factory): + bot = bot_factory(transport="tcp", host="127.0.0.1", port=1, + auto_reconnect=False) + rc = await bot.run() + assert rc == 1 + assert not bot.restart_requested, "auto_reconnect=false exits as before"