diff --git a/CHANGELOG.md b/CHANGELOG.md index fd55fdbf..12ef16a6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -11,6 +11,22 @@ PyPI version — not the changelog header. ## [2026-07-14] +### Fixed + +- **TG bots no longer hot-spin when the internet drops.** Live find from + Patrick's on-location tether outage: DNS failure makes `urlopen` fail + instantly (no 30s long-poll wait), so the shared poll loop retried as fast as + it could — up to 13 ERROR lines/second per bot, all 5 bots spinning for the + whole offline window (rotation saved the disk; nothing saved the CPU, and the + flood tripped the medic circuit breaker fleet-wide). Now network-class poll + failures (DNS/connection/socket, classified via `_NetworkPollError`) back off + exponentially 1s→60s cap and reset on the first successful poll, with + log-once semantics: one "unreachable, backing off" line, one summary per 5 + minutes while offline, one recovery line with suppressed count. Routine + long-poll read-timeouts (expected getUpdates behavior, ~863 medic-suppressed + events/day) no longer log at all. Bots still self-recover the moment + connectivity returns. 25 new tests; 822 TG + 252 skills green. + ### Added - **Medic is back on — and the loop is proven live.** Off since 2026-05-10 (a diff --git a/src/aipass/skills/lib/telegram/apps/handlers/base_bot.py b/src/aipass/skills/lib/telegram/apps/handlers/base_bot.py index 6dc8c45a..ec586f42 100644 --- a/src/aipass/skills/lib/telegram/apps/handlers/base_bot.py +++ b/src/aipass/skills/lib/telegram/apps/handlers/base_bot.py @@ -139,6 +139,37 @@ CLAUDE_BIN = str(Path.home() / ".local" / "bin" / "claude") MIRROR_SESSION_TYPE = "interactive-mirror" TEMP_DIR = Path(tempfile.gettempdir()) / "telegram_uploads" MAX_FILE_SIZE = 10 * 1024 * 1024 # 10MB +NETWORK_BACKOFF_INIT = 1 # seconds +NETWORK_BACKOFF_CAP = 60 # seconds +NETWORK_LOG_INTERVAL = 300 # 5 minutes between offline summary lines + + +class _NetworkPollError(Exception): + """Raised by poll_updates when a network-class error occurs (DNS, connection, socket).""" + + +def _is_network_error(exc: Exception) -> bool: + reason = getattr(exc, "reason", None) + if isinstance(reason, OSError): + return True + reason_str = str(reason) if reason else str(exc) + for pattern in ( + "Name or service not known", + "getaddrinfo", + "Temporary failure", + "Network is unreachable", + "No route to host", + "Connection refused", + "Connection reset", + "Connection timed out", + ): + if pattern in reason_str: + return True + return False + + +def _is_routine_read_timeout(exc: Exception) -> bool: + return "timed out" in str(exc) and "read operation" in str(getattr(exc, "reason", exc)) # ============================================= @@ -299,17 +330,36 @@ class BaseBot: offset = self._load_offset() logger.info("Starting poll loop (offset=%d)", offset) - # Retry backoff sequence: 5s, 10s, 20s, 40s, 60s max + # General retry backoff (non-network errors) retry_delay = 5 max_retry_delay = 60 + # Network-error state tracking + net_backoff = NETWORK_BACKOFF_INIT + net_offline_since: float | None = None + net_suppressed = 0 + net_last_summary: float = 0.0 + while self.state["running"]: try: updates = self.poll_updates(offset) - # Reset backoff on successful poll + # Reset general backoff on successful poll retry_delay = 5 + # Network recovery + if net_offline_since is not None: + elapsed = time.time() - net_offline_since + mins = int(elapsed / 60) + logger.info( + "Telegram reachable again after %dm, %d attempts suppressed", + mins, + net_suppressed, + ) + net_offline_since = None + net_suppressed = 0 + net_backoff = NETWORK_BACKOFF_INIT + for update in updates: if not self.state["running"]: break @@ -323,6 +373,26 @@ class BaseBot: self.process_update(update) + except _NetworkPollError as e: + self._health["errors"] = self._health.get("errors", 0) + 1 + now = time.time() + if net_offline_since is None: + net_offline_since = now + net_suppressed = 0 + net_last_summary = now + logger.error("Telegram unreachable, backing off: %s", e) + else: + net_suppressed += 1 + if now - net_last_summary >= NETWORK_LOG_INTERVAL: + mins = int((now - net_offline_since) / 60) + logger.warning( + "Still offline (%dm), %d attempts suppressed", + mins, + net_suppressed, + ) + net_last_summary = now + time.sleep(net_backoff) + net_backoff = min(net_backoff * 2, NETWORK_BACKOFF_CAP) except KeyboardInterrupt: logger.info("KeyboardInterrupt received") break @@ -394,8 +464,14 @@ class BaseBot: return data.get("result", []) except URLError as e: + if _is_routine_read_timeout(e): + return [] + if _is_network_error(e): + raise _NetworkPollError(str(e)) from e logger.error("Poll error: %s", e) return [] + except (ConnectionError, OSError) as e: + raise _NetworkPollError(str(e)) from e except Exception as e: logger.error("Unexpected poll error: %s", e) return [] diff --git a/src/aipass/skills/lib/telegram/tests/test_network_backoff.py b/src/aipass/skills/lib/telegram/tests/test_network_backoff.py new file mode 100644 index 00000000..b6fe1a74 --- /dev/null +++ b/src/aipass/skills/lib/telegram/tests/test_network_backoff.py @@ -0,0 +1,364 @@ +""" +Tests for network-error backoff and routine-timeout log level in the poll loop. + +Tests cover: + - Exponential backoff on network errors (1s, 2s, 4s... capped at 60s) + - Backoff resets on successful poll after network recovery + - Log-once semantics: first failure logs error, subsequent suppressed + - Periodic summary logged every 5 minutes while offline + - Recovery log line with elapsed time and suppressed count + - Routine read-timeout returns [] silently (not logged at ERROR) + - Non-network URLError still logged at ERROR + - ConnectionError/OSError raised as _NetworkPollError + - _is_network_error classification + - _is_routine_read_timeout classification +""" + +from unittest.mock import patch +from urllib.error import URLError + +import pytest + +from aipass.skills.lib.telegram.apps.handlers.base_bot import ( + BaseBot, + _NetworkPollError, + _is_network_error, + _is_routine_read_timeout, + NETWORK_LOG_INTERVAL, +) + + +@pytest.fixture +def _patch_base_bot_deps(tmp_path): + patches = [ + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.PENDING_DIR", tmp_path), + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.signal.signal"), + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.atexit.register"), + ] + for p in patches: + p.start() + yield + for p in patches: + p.stop() + + +def _make_bot(tmp_path, _patch_base_bot_deps): + workdir = tmp_path / "workdir" + workdir.mkdir(exist_ok=True) + bot = BaseBot( + bot_id="test_bot", + bot_token="123:FAKETOKEN", + work_dir=workdir, + bot_name="Test Bot", + ) + bot.verify_connection = lambda timeout=15: True + bot._set_command_menu = lambda: None + bot._boot_monitor = lambda: None + bot._check_lock = lambda: False + bot._create_lock = lambda: None + bot._remove_lock = lambda: None + bot._load_offset = lambda: 0 # type: ignore[assignment] + bot._save_offset = lambda o: None # type: ignore[assignment] + return bot + + +# ============================================= +# 1. _is_network_error classification +# ============================================= + + +class TestIsNetworkError: + def test_dns_failure(self): + exc = URLError(OSError("[Errno -2] Name or service not known")) + assert _is_network_error(exc) is True + + def test_getaddrinfo_failure(self): + exc = URLError(OSError("[Errno -3] getaddrinfo failed")) + assert _is_network_error(exc) is True + + def test_connection_refused(self): + exc = URLError(OSError("Connection refused")) + assert _is_network_error(exc) is True + + def test_network_unreachable(self): + exc = URLError(OSError("Network is unreachable")) + assert _is_network_error(exc) is True + + def test_temporary_failure(self): + exc = URLError(OSError("Temporary failure in name resolution")) + assert _is_network_error(exc) is True + + def test_reason_is_oserror_instance(self): + exc = URLError(OSError("any socket error")) + assert _is_network_error(exc) is True + + def test_http_error_not_network(self): + exc = URLError("HTTP Error 502") + assert _is_network_error(exc) is False + + def test_generic_string_not_network(self): + exc = URLError("some other error") + assert _is_network_error(exc) is False + + +# ============================================= +# 2. _is_routine_read_timeout classification +# ============================================= + + +class TestIsRoutineReadTimeout: + def test_read_timeout(self): + exc = URLError(OSError("The read operation timed out")) + assert _is_routine_read_timeout(exc) is True + + def test_connect_timeout_not_routine(self): + exc = URLError(OSError("Connection timed out")) + assert _is_routine_read_timeout(exc) is False + + def test_dns_failure_not_timeout(self): + exc = URLError(OSError("Name or service not known")) + assert _is_routine_read_timeout(exc) is False + + +# ============================================= +# 3. poll_updates error classification +# ============================================= + + +class TestPollUpdatesErrorClassification: + def test_routine_read_timeout_returns_empty(self, tmp_path, _patch_base_bot_deps): + bot = _make_bot(tmp_path, _patch_base_bot_deps) + exc = URLError(OSError("The read operation timed out")) + with patch("aipass.skills.lib.telegram.apps.handlers.base_bot.urlopen", side_effect=exc): + result = bot.poll_updates(0) + assert result == [] + + def test_routine_read_timeout_no_error_log(self, tmp_path, _patch_base_bot_deps): + bot = _make_bot(tmp_path, _patch_base_bot_deps) + exc = URLError(OSError("The read operation timed out")) + with ( + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.urlopen", side_effect=exc), + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.logger") as mock_logger, + ): + bot.poll_updates(0) + mock_logger.error.assert_not_called() + + def test_dns_failure_raises_network_poll_error(self, tmp_path, _patch_base_bot_deps): + bot = _make_bot(tmp_path, _patch_base_bot_deps) + exc = URLError(OSError("[Errno -2] Name or service not known")) + with patch("aipass.skills.lib.telegram.apps.handlers.base_bot.urlopen", side_effect=exc): + with pytest.raises(_NetworkPollError): + bot.poll_updates(0) + + def test_connection_error_raises_network_poll_error(self, tmp_path, _patch_base_bot_deps): + bot = _make_bot(tmp_path, _patch_base_bot_deps) + exc = ConnectionResetError("Connection reset by peer") + with patch("aipass.skills.lib.telegram.apps.handlers.base_bot.urlopen", side_effect=exc): + with pytest.raises(_NetworkPollError): + bot.poll_updates(0) + + def test_os_error_raises_network_poll_error(self, tmp_path, _patch_base_bot_deps): + bot = _make_bot(tmp_path, _patch_base_bot_deps) + exc = OSError("Socket error") + with patch("aipass.skills.lib.telegram.apps.handlers.base_bot.urlopen", side_effect=exc): + with pytest.raises(_NetworkPollError): + bot.poll_updates(0) + + def test_non_network_urlerror_logs_error(self, tmp_path, _patch_base_bot_deps): + bot = _make_bot(tmp_path, _patch_base_bot_deps) + exc = URLError("HTTP Error 502") + with ( + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.urlopen", side_effect=exc), + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.logger") as mock_logger, + ): + result = bot.poll_updates(0) + assert result == [] + mock_logger.error.assert_called_once() + assert "Poll error" in str(mock_logger.error.call_args) + + def test_unexpected_exception_logs_error(self, tmp_path, _patch_base_bot_deps): + bot = _make_bot(tmp_path, _patch_base_bot_deps) + exc = ValueError("something weird") + with ( + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.urlopen", side_effect=exc), + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.logger") as mock_logger, + ): + result = bot.poll_updates(0) + assert result == [] + mock_logger.error.assert_called_once() + assert "Unexpected poll error" in str(mock_logger.error.call_args) + + +# ============================================= +# 4. Run loop network backoff +# ============================================= + + +class TestRunLoopNetworkBackoff: + def test_backoff_doubles_and_caps(self, tmp_path, _patch_base_bot_deps): + """Backoff should go 1, 2, 4, 8, 16, 32, 60, 60...""" + bot = _make_bot(tmp_path, _patch_base_bot_deps) + call_count = 0 + sleep_values = [] + + def failing_poll(offset): + nonlocal call_count + call_count += 1 + if call_count > 8: + bot.state["running"] = False + return [] + raise _NetworkPollError("DNS failure") + + bot.poll_updates = failing_poll + with patch("aipass.skills.lib.telegram.apps.handlers.base_bot.time.sleep") as mock_sleep: + bot.run() + sleep_values = [c.args[0] for c in mock_sleep.call_args_list if c.args[0] >= 1] + + assert sleep_values == [1, 2, 4, 8, 16, 32, 60, 60] + + def test_backoff_resets_on_recovery(self, tmp_path, _patch_base_bot_deps): + bot = _make_bot(tmp_path, _patch_base_bot_deps) + call_count = 0 + + def poll_with_recovery(offset): + nonlocal call_count + call_count += 1 + if call_count <= 3: + raise _NetworkPollError("DNS failure") + if call_count == 4: + return [] # success — resets backoff + if call_count == 5: + raise _NetworkPollError("DNS failure again") + bot.state["running"] = False + return [] + + bot.poll_updates = poll_with_recovery + with patch("aipass.skills.lib.telegram.apps.handlers.base_bot.time.sleep") as mock_sleep: + bot.run() + sleep_values = [c.args[0] for c in mock_sleep.call_args_list if c.args[0] >= 1] + + # 1, 2, 4 (first storm), then reset, then 1 (second failure) + assert sleep_values == [1, 2, 4, 1] + + +# ============================================= +# 5. Log-once semantics +# ============================================= + + +class TestLogOnceSemantics: + def test_first_failure_logs_error(self, tmp_path, _patch_base_bot_deps): + bot = _make_bot(tmp_path, _patch_base_bot_deps) + call_count = 0 + + def failing_poll(offset): + nonlocal call_count + call_count += 1 + if call_count > 1: + bot.state["running"] = False + return [] + raise _NetworkPollError("DNS failure") + + bot.poll_updates = failing_poll + with ( + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.time.sleep"), + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.logger") as mock_logger, + ): + bot.run() + + error_calls = [c for c in mock_logger.error.call_args_list if "unreachable" in str(c)] + assert len(error_calls) == 1 + + def test_subsequent_failures_suppressed(self, tmp_path, _patch_base_bot_deps): + bot = _make_bot(tmp_path, _patch_base_bot_deps) + call_count = 0 + + def failing_poll(offset): + nonlocal call_count + call_count += 1 + if call_count > 10: + bot.state["running"] = False + return [] + raise _NetworkPollError("DNS failure") + + bot.poll_updates = failing_poll + with ( + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.time.sleep"), + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.logger") as mock_logger, + ): + bot.run() + + error_calls = [c for c in mock_logger.error.call_args_list if "unreachable" in str(c)] + # Only one "unreachable" error, not 10 + assert len(error_calls) == 1 + + def test_recovery_logs_info(self, tmp_path, _patch_base_bot_deps): + bot = _make_bot(tmp_path, _patch_base_bot_deps) + call_count = 0 + + def poll_with_recovery(offset): + nonlocal call_count + call_count += 1 + if call_count <= 3: + raise _NetworkPollError("DNS failure") + bot.state["running"] = False + return [] + + bot.poll_updates = poll_with_recovery + with ( + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.time.sleep"), + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.logger") as mock_logger, + ): + bot.run() + + recovery_calls = [c for c in mock_logger.info.call_args_list if "reachable again" in str(c)] + assert len(recovery_calls) == 1 + + def test_periodic_summary_during_offline(self, tmp_path, _patch_base_bot_deps): + bot = _make_bot(tmp_path, _patch_base_bot_deps) + call_count = 0 + fake_time = [100.0] + + def failing_poll(offset): + nonlocal call_count + call_count += 1 + # Advance fake clock past NETWORK_LOG_INTERVAL each call + fake_time[0] += NETWORK_LOG_INTERVAL + 1 + if call_count > 4: + bot.state["running"] = False + return [] + raise _NetworkPollError("DNS failure") + + bot.poll_updates = failing_poll + + def fake_time_fn(): + return fake_time[0] + + with ( + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.time.sleep"), + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.time.time", side_effect=fake_time_fn), + patch("aipass.skills.lib.telegram.apps.handlers.base_bot.logger") as mock_logger, + ): + bot.run() + + summary_calls = [c for c in mock_logger.warning.call_args_list if "Still offline" in str(c)] + # Calls 2, 3, 4 should each trigger a summary (time jumped >5m each time) + assert len(summary_calls) >= 2 + + def test_health_errors_incremented(self, tmp_path, _patch_base_bot_deps): + bot = _make_bot(tmp_path, _patch_base_bot_deps) + call_count = 0 + + def failing_poll(offset): + nonlocal call_count + call_count += 1 + if call_count > 5: + bot.state["running"] = False + return [] + raise _NetworkPollError("DNS failure") + + bot.poll_updates = failing_poll + with patch("aipass.skills.lib.telegram.apps.handlers.base_bot.time.sleep"): + bot.run() + + assert bot._health["errors"] == 5