fix: TG bot offline hot-spin — network-class poll errors (DNS/connection/socket) back off exponentially 1s-60s cap, reset on first successful poll; log-once semantics (1 unreachable line + 5min summaries + 1 recovery line) instead of 13 err/sec; routine long-poll read-timeouts silent (863/day medic noise class gone). Found live: Patrick's tether outage spun all 5 bots for an hour. 25 new tests, 822 TG + 252 skills green devpulse-verified
This commit is contained in:
@@ -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
|
||||
|
||||
@@ -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 []
|
||||
|
||||
@@ -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
|
||||
Reference in New Issue
Block a user