HexLab
594308d4bb
* fix(credential-pool): throttle "no available entries" log to stop Windows log-lock storm
Credential selection runs on a hot path (every model call plus auxiliary
tasks), so an empty/exhausted pool logged "no available entries" at INFO on
*every* selection. On Windows, where multiple Hermes processes share one
rotating log guarded by concurrent-log-handler's cross-process lock, that
per-selection volume storms the lock (RuntimeError: Cannot acquire lock after
20 attempts), pegs a core, and stalls the asyncio event loop long enough that
the Desktop backend readiness probe times out ("Timed out connecting to Hermes
backend after 15000ms") even though the backend already announced
HERMES_BACKEND_READY.
Log the condition at most once per 60s window, re-arming on a successful
selection so recovery->re-exhaustion still surfaces promptly. Same fix class as
the warn-once dedup in #58265.
* test(credential-pool): cover no-available-entries log throttle
Assert the empty-pool INFO line logs at most once per throttle window, logs
again after the window elapses, and re-arms on a successful selection so a
recover->re-exhaust transition surfaces promptly. Uses a deterministic fake
monotonic clock (no sleeps, no network).
104 lines
3.5 KiB
Python
104 lines
3.5 KiB
Python
"""Regression: the credential-pool "no available entries" INFO line must be
|
|
throttled so an empty/exhausted pool cannot storm the shared rotating log.
|
|
|
|
Selection runs on a hot path (every model call plus auxiliary tasks). Before
|
|
the throttle, an empty/exhausted pool logged this line on *every* select(),
|
|
which on Windows storms concurrent-log-handler's cross-process lock
|
|
("Cannot acquire lock after 20 attempts"), stalls the asyncio event loop, and
|
|
fails the Desktop backend readiness handshake ("Timed out connecting to Hermes
|
|
backend after 15000ms"). See #58265 for the same fix class on another message.
|
|
"""
|
|
|
|
from __future__ import annotations
|
|
|
|
import logging
|
|
|
|
from agent.credential_pool import (
|
|
NO_AVAILABLE_ENTRIES_LOG_THROTTLE_SECONDS,
|
|
CredentialPool,
|
|
PooledCredential,
|
|
)
|
|
|
|
_NO_ENTRIES_MSG = "credential pool: no available entries (all exhausted or empty)"
|
|
|
|
|
|
class _FakeClock:
|
|
"""Deterministic monotonic clock driven by the test."""
|
|
|
|
def __init__(self) -> None:
|
|
self.now = 1000.0
|
|
|
|
def __call__(self) -> float:
|
|
return self.now
|
|
|
|
|
|
def _no_entries_records(caplog) -> list[logging.LogRecord]:
|
|
return [r for r in caplog.records if r.getMessage() == _NO_ENTRIES_MSG]
|
|
|
|
|
|
def _make_entry(entry_id: str) -> PooledCredential:
|
|
return PooledCredential(
|
|
provider="test",
|
|
id=entry_id,
|
|
label=entry_id,
|
|
auth_type="api_key",
|
|
source="manual",
|
|
access_token=f"tok-{entry_id}",
|
|
priority=0,
|
|
)
|
|
|
|
|
|
def test_empty_pool_logs_once_within_throttle_window(monkeypatch, caplog):
|
|
clock = _FakeClock()
|
|
monkeypatch.setattr("agent.credential_pool.time.monotonic", clock)
|
|
|
|
pool = CredentialPool("test", [])
|
|
|
|
with caplog.at_level(logging.INFO, logger="agent.credential_pool"):
|
|
for _ in range(50):
|
|
clock.now += 0.1 # tighter than the throttle window
|
|
assert pool.select() is None
|
|
|
|
# 50 selections, well inside one window -> exactly one log line.
|
|
assert len(_no_entries_records(caplog)) == 1
|
|
|
|
|
|
def test_logs_again_after_throttle_window_elapses(monkeypatch, caplog):
|
|
clock = _FakeClock()
|
|
monkeypatch.setattr("agent.credential_pool.time.monotonic", clock)
|
|
|
|
pool = CredentialPool("test", [])
|
|
|
|
with caplog.at_level(logging.INFO, logger="agent.credential_pool"):
|
|
assert pool.select() is None # log #1
|
|
clock.now += NO_AVAILABLE_ENTRIES_LOG_THROTTLE_SECONDS + 1
|
|
assert pool.select() is None # window elapsed -> log #2
|
|
|
|
assert len(_no_entries_records(caplog)) == 2
|
|
|
|
|
|
def test_successful_selection_rearms_throttle(monkeypatch, caplog):
|
|
"""A recover -> re-exhaust transition must log immediately, even inside the
|
|
window opened by the previous empty stretch (observability of the flip)."""
|
|
clock = _FakeClock()
|
|
monkeypatch.setattr("agent.credential_pool.time.monotonic", clock)
|
|
|
|
pool = CredentialPool("test", [])
|
|
|
|
with caplog.at_level(logging.INFO, logger="agent.credential_pool"):
|
|
assert pool.select() is None # log #1, throttle armed
|
|
clock.now += 1
|
|
assert pool.select() is None # within window -> no log
|
|
|
|
# Pool recovers: a successful selection re-arms the throttle.
|
|
pool._entries = [_make_entry("a")]
|
|
clock.now += 1
|
|
assert pool.select() is not None
|
|
|
|
# Pool empties again shortly after (< throttle window since log #1).
|
|
pool._entries = []
|
|
clock.now += 1
|
|
assert pool.select() is None # re-armed -> log #2 immediately
|
|
|
|
assert len(_no_entries_records(caplog)) == 2
|