diff --git a/CHANGELOG.md b/CHANGELOG.md index ea43f9c..189d465 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -30,7 +30,7 @@ semantic versioning. ### Fixed -- A service plugin that does not start because it is not configured (Discord or Telegram with no channels, the map uploader with no key) is no longer restarted every 5 seconds with a warning each time. The health check restarted any service that was not running, and the restart counted as a success, which cleared its backoff. Such services are now left alone, with one log line saying so, and a restart that leaves a service unhealthy waits out `service_restart_backoff_seconds` before the next try. Restarts also no longer subscribe a service to radio events a second time: services never unsubscribed in `stop()`, so after a restart packet capture published every packet twice and the Discord, Telegram and prefix-collision services handled every event twice. +- A service plugin that does not start because it is not configured (Discord or Telegram with no channels, the map uploader with no key) is no longer restarted every 5 seconds with a warning each time. The health check restarted any service that was not running, and the restart counted as a success, which cleared its backoff. A service that does not start, or is still unhealthy after a restart, now waits out `service_restart_backoff_seconds` before the next try, so one that was only waiting for the radio still recovers. A restarted packet capture or map uploader service also gets its background work back; `stop()` left a shutdown flag set that `start()` never cleared. Restarts also no longer subscribe a service to radio events a second time: services never unsubscribed in `stop()`, so after a restart packet capture published every packet twice and the Discord, Telegram and prefix-collision services handled every event twice. - A delivered DM is no longer reported as failed because its ACK came back after the bot stopped waiting (#290). Each attempt waited 1.2 times the radio's `suggested_timeout`, which the firmware derives from the packet's airtime and hop count with well under a second of fixed allowance, so on fast presets a zero-hop attempt gave up after about 1.3 seconds, before the recipient's ACK delay and the radio's TX queue had even played out. Webhook DMs then returned an error for messages the recipient had. New `[Bot] dm_min_ack_timeout` (default 8 seconds) sets a floor on each attempt's wait; an ACK still ends it at once, so successful sends are no slower, but a DM that is never acknowledged now takes at least 24 seconds to report failure with the default three attempts. Values are capped at 60 seconds. Set it to 0 for the old behavior. - A radio that rejects `set_flood_scope` is now reported. The check compared the reply's `EventType` to the string `"ERROR"`, which never matches, so a rejected regional scope (the message then goes out at whatever scope the radio holds) and a rejected restore to global flood (the radio stays pinned to the region for every later send) were both silent. - Reverse geocoding for contact adverts no longer blocks the bot. `track_contact_advertisement`, background geocoding, the repeater scan and the geolocation backfill called rate-limited Nominatim synchronously from async code, so every other task (command replies, sends, the mesh reader) stalled for the length of each lookup, including the rate limiter's sleep. These calls now run in a worker thread. Advert tracking decides whether to geocode before its write block and re-checks the duplicate-packet guard inside it, so concurrent adverts still cannot double-count. diff --git a/modules/core.py b/modules/core.py index ed19002..e76455d 100644 --- a/modules/core.py +++ b/modules/core.py @@ -433,9 +433,6 @@ class MeshCoreBot: # Service plugin restart state (name -> timestamp of last failed restart) self._service_restart_failures: dict[str, float] = {} self._service_restarting: set = set() - # Services whose start() returned without running (missing config, nothing - # to do): restarting them cannot help, so the health loop leaves them alone. - self._services_inactive: set[str] = set() # Transport reconnect (serial/BLE/TCP) — lock created when event loop runs self._transport_reconnect_lock: asyncio.Lock | None = None @@ -2402,7 +2399,7 @@ long_jokes = false if webhook_service is not None and getattr(webhook_service, 'enabled', False): try: await webhook_service.start() - if not self._note_if_service_inactive('webhook', webhook_service): + if not self._note_if_service_not_running('webhook', webhook_service): self.logger.info("Service 'webhook' started (early, before radio connect)") except Exception as e: self.logger.error(f"Failed to start service 'webhook' early: {e}") @@ -2455,7 +2452,7 @@ long_jokes = false continue try: await service_instance.start() - if not self._note_if_service_inactive(service_name, service_instance): + if not self._note_if_service_not_running(service_name, service_instance): self.logger.info(f"Service '{service_name}' started") except Exception as e: self.logger.error(f"Failed to start service '{service_name}': {e}") @@ -2537,19 +2534,7 @@ long_jokes = false ) now = time.time() for name, service in self.services.items(): - if not getattr(service, 'enabled', True): - continue - try: - healthy = service.is_healthy() - except Exception: - healthy = False - if healthy: - continue - if name in self._service_restarting or name in self._services_inactive: - continue - if name in self._service_restart_failures and ( - now - self._service_restart_failures[name] - ) < restart_backoff: + if not self._service_restart_due(name, service, now, restart_backoff): continue self.logger.warning( f"Service '{name}' unhealthy, attempting restart..." @@ -2651,21 +2636,41 @@ long_jokes = false finally: self._shutdown_complete = True - def _note_if_service_inactive(self, service_name: str, service_instance: Any) -> bool: - """Record a service whose start() returned without running; True if so.""" + def _service_restart_due(self, name: str, service: Any, now: float, backoff: float) -> bool: + """Whether the health loop should restart *service* now.""" + if not getattr(service, 'enabled', True): + return False + try: + if service.is_healthy(): + return False + except Exception: + pass + if name in self._service_restarting: + return False + last_failure = self._service_restart_failures.get(name) + return last_failure is None or now - last_failure >= backoff + + def _note_if_service_not_running(self, service_name: str, service_instance: Any) -> bool: + """Back off a service whose start() returned without running; True if so. + + That happens for missing configuration (Discord or Telegram with no + channels, the map uploader with no key) and for transient conditions + (the radio not connected yet). Either way, restarting it on every + health tick cannot help; after the backoff the health loop tries again, + which recovers the transient case. + """ try: running = service_instance.is_running() except Exception: running = True if running: - self._services_inactive.discard(service_name) return False - if service_name not in self._services_inactive: - self.logger.info( - f"Service '{service_name}' did not start (check its configuration); " - "it will not be restarted automatically" - ) - self._services_inactive.add(service_name) + backoff = self.config.getint('Bot', 'service_restart_backoff_seconds', fallback=300) + self.logger.info( + f"Service '{service_name}' did not start (check its configuration); " + f"next attempt in {backoff}s" + ) + self._service_restart_failures[service_name] = time.time() return True async def _restart_service(self, service_name: str, service_instance: Any) -> bool: @@ -2676,7 +2681,7 @@ long_jokes = false try: await service_instance.stop() await service_instance.start() - if self._note_if_service_inactive(service_name, service_instance): + if self._note_if_service_not_running(service_name, service_instance): return False if not service_instance.is_healthy(): # Restarted but still unhealthy: wait out the backoff before the diff --git a/modules/service_plugins/discord_bridge_service.py b/modules/service_plugins/discord_bridge_service.py index 1c8737a..bc0119e 100644 --- a/modules/service_plugins/discord_bridge_service.py +++ b/modules/service_plugins/discord_bridge_service.py @@ -338,6 +338,9 @@ class DiscordBridgeService(BaseServicePlugin): self.logger.info("Subscribed to CHANNEL_MSG_RECV events") else: self.logger.error("Cannot subscribe to events - meshcore not available") + if self.http_session is not None: + await self.http_session.close() + self.http_session = None return # Register for bot-sent channel messages so bot responses are bridged too diff --git a/modules/service_plugins/map_uploader_service.py b/modules/service_plugins/map_uploader_service.py index f2c4c0f..b179ede 100644 --- a/modules/service_plugins/map_uploader_service.py +++ b/modules/service_plugins/map_uploader_service.py @@ -221,6 +221,9 @@ class MapUploaderService(BaseServicePlugin): self.logger.info("Map uploader service is disabled") return + # stop() sets this; clear it so a restart's background work actually runs. + self.should_exit = False + # Check dependencies if not AIOHTTP_AVAILABLE: self.logger.error("aiohttp is required for map uploader service. Install with: pip install aiohttp") diff --git a/modules/service_plugins/packet_capture_service.py b/modules/service_plugins/packet_capture_service.py index 9fba0dc..5789466 100644 --- a/modules/service_plugins/packet_capture_service.py +++ b/modules/service_plugins/packet_capture_service.py @@ -944,6 +944,9 @@ class PacketCaptureService(BaseServicePlugin): self.logger.info("Packet capture service is disabled") return + # stop() sets this; clear it so a restart's background loops actually run. + self.should_exit = False + # Wait for bot to be connected (with timeout) max_wait = 30 # seconds wait_time: float = 0 diff --git a/modules/service_plugins/telegram_bridge_service.py b/modules/service_plugins/telegram_bridge_service.py index 0183c55..9353a9d 100644 --- a/modules/service_plugins/telegram_bridge_service.py +++ b/modules/service_plugins/telegram_bridge_service.py @@ -239,6 +239,9 @@ class TelegramBridgeService(BaseServicePlugin): self.logger.info("Subscribed to CHANNEL_MSG_RECV events") else: self.logger.error("Cannot subscribe to events - meshcore not available") + if self.http_session is not None: + await self.http_session.close() + self.http_session = None return # Register for bot-sent channel messages so bot responses are bridged too diff --git a/tests/test_service_lifecycle.py b/tests/test_service_lifecycle.py index 53367f2..3837b40 100644 --- a/tests/test_service_lifecycle.py +++ b/tests/test_service_lifecycle.py @@ -46,11 +46,37 @@ def test_base_unsubscribe_tolerates_errors(): service = RepeaterPrefixCollisionService(bot) broken = MagicMock() broken.unsubscribe.side_effect = RuntimeError("gone") - service._meshcore_subscriptions = [broken] + meshcore = MagicMock() + meshcore.subscribe.return_value = broken + service._subscribe(meshcore, EventType.NEW_CONTACT, service._on_new_contact) service._unsubscribe_all() + broken.unsubscribe.assert_called_once() assert service._meshcore_subscriptions == [] +def test_packet_capture_restart_clears_should_exit(): + import configparser + + from modules.service_plugins.packet_capture_service import PacketCaptureService + + bot = MagicMock() + bot.config = configparser.ConfigParser() + bot.config.read_dict({"PacketCapture": {"enabled": "true"}}) + bot.connected = False + service = PacketCaptureService(bot) + service.enabled = True + service.should_exit = True # as stop() leaves it + + async def no_wait(*args, **kwargs): + return None + + from unittest.mock import patch + + with patch("asyncio.sleep", no_wait): + asyncio.run(service.start()) # gives up waiting for the radio, then returns + assert service.should_exit is False + + def _core_bot(tmp_path: Path): from modules.core import MeshCoreBot from tests.test_core import _write_config @@ -86,16 +112,62 @@ class _StillUnhealthy(_Declining): return True -def test_a_service_that_declines_to_start_is_not_restarted(tmp_path): +class _Recovers(_Declining): + """Declines while the radio is down, then starts once it is back.""" + + def __init__(self): + super().__init__() + self.radio_up = False + self._running = False + + async def start(self): + self.starts += 1 + self._running = self.radio_up + + def is_running(self): + return self._running + + def is_healthy(self): + return self._running + + +def test_a_service_that_declines_to_start_waits_out_the_backoff(tmp_path): bot = _core_bot(tmp_path) service = _Declining() assert asyncio.run(bot._restart_service("declining", service)) is False - assert "declining" in bot._services_inactive - assert "declining" not in bot._service_restart_failures + failed_at = bot._service_restart_failures["declining"] + backoff = 300 + assert bot._service_restart_due("declining", service, failed_at + 5, backoff) is False + assert bot._service_restart_due("declining", service, failed_at + backoff, backoff) is True + + +def test_a_transient_start_failure_recovers_after_the_backoff(tmp_path): + bot = _core_bot(tmp_path) + service = _Recovers() + assert asyncio.run(bot._restart_service("bridge", service)) is False # radio still down + service.radio_up = True + later = bot._service_restart_failures["bridge"] + 300 + assert bot._service_restart_due("bridge", service, later, 300) is True + assert asyncio.run(bot._restart_service("bridge", service)) is True + assert "bridge" not in bot._service_restart_failures + assert bot._service_restart_due("bridge", service, later + 5, 300) is False # healthy now + + +def test_restart_due_skips_disabled_healthy_and_in_progress_services(tmp_path): + bot = _core_bot(tmp_path) + unhealthy = _Declining() + assert bot._service_restart_due("a", unhealthy, 0.0, 300) is True + disabled = _Declining() + disabled.enabled = False + assert bot._service_restart_due("b", disabled, 0.0, 300) is False + healthy = _Recovers() + healthy._running = True + assert bot._service_restart_due("c", healthy, 0.0, 300) is False + bot._service_restarting.add("a") + assert bot._service_restart_due("a", unhealthy, 0.0, 300) is False def test_a_restart_that_leaves_the_service_unhealthy_backs_off(tmp_path): bot = _core_bot(tmp_path) assert asyncio.run(bot._restart_service("flaky", _StillUnhealthy())) is False assert "flaky" in bot._service_restart_failures - assert "flaky" not in bot._services_inactive