fix(credential-pool): throttle "no available entries" log to stop Windows log-lock storm (contributes to #62698) (#66338)

* 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).

agent/credential_pool.py

@@ -114,6 +114,20 @@ EXHAUSTED_TTL_401_SECONDS = 5 * 60           # 5 minutes
 EXHAUSTED_TTL_429_SECONDS = 60 * 60          # 1 hour
 EXHAUSTED_TTL_DEFAULT_SECONDS = 60 * 60      # 1 hour
 
+# Throttle window for the "no available entries" INFO line. Credential
+# selection runs on a hot path (every model call, plus auxiliary tasks like
+# compression/moa/titles), so when a pool is empty or fully exhausted the
+# un-throttled log fires on *every* selection. On Windows several 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 to fail the Desktop backend
+# readiness handshake ("Timed out connecting to Hermes backend after
+# 15000ms"). Logging the condition at most once per window preserves the
+# signal while removing the storm — same class of fix as the warn-once
+# dedup in #58265.
+NO_AVAILABLE_ENTRIES_LOG_THROTTLE_SECONDS = 60.0
+
 # Pool key prefix for custom OpenAI-compatible endpoints.
 # Custom endpoints all share provider='custom' but are keyed by their
 # custom_providers name: 'custom:<normalized_name>'.
@@ -566,6 +580,12 @@ class CredentialPool:
         self._lock = threading.Lock()
         self._active_leases: Dict[str, int] = {}
         self._max_concurrent = DEFAULT_MAX_CONCURRENT_PER_CREDENTIAL
+        # Monotonic timestamp of the last "no available entries" log, used to
+        # throttle that message so an empty/exhausted pool cannot storm the
+        # shared rotating log (see NO_AVAILABLE_ENTRIES_LOG_THROTTLE_SECONDS).
+        # Re-armed to None on every successful selection so a recover→re-exhaust
+        # transition logs promptly instead of being swallowed by a stale window.
+        self._last_no_entries_log_at: Optional[float] = None
 
     def has_credentials(self) -> bool:
         return bool(self._entries)
@@ -1604,13 +1624,32 @@ class CredentialPool:
             self._persist(removed_ids=entries_to_prune)
         return available
 
+    def _log_no_available_entries(self) -> None:
+        """Emit the empty-pool INFO line at most once per throttle window.
+
+        Called on every selection while the pool is empty/exhausted. Without
+        throttling this storms the Windows cross-process log lock and stalls the
+        event loop (see NO_AVAILABLE_ENTRIES_LOG_THROTTLE_SECONDS).
+        """
+        now = time.monotonic()
+        last = self._last_no_entries_log_at
+        if last is not None and (now - last) < NO_AVAILABLE_ENTRIES_LOG_THROTTLE_SECONDS:
+            return
+        self._last_no_entries_log_at = now
+        logger.info("credential pool: no available entries (all exhausted or empty)")
+
     def _select_unlocked(self, *, refresh: bool = True) -> Optional[PooledCredential]:
         available = self._available_entries(clear_expired=True, refresh=refresh)
         if not available:
             self._current_id = None
-            logger.info("credential pool: no available entries (all exhausted or empty)")
+            self._log_no_available_entries()
             return None
 
+        # A successful selection means the pool recovered; re-arm the throttle
+        # so a later re-exhaustion logs immediately rather than being silenced
+        # by a window opened during the previous empty stretch.
+        self._last_no_entries_log_at = None
+
         if self._strategy == STRATEGY_RANDOM:
             entry = random.choice(available)
             self._current_id = entry.id

tests/agent/test_credential_pool_no_entries_log_throttle.py

@@ -0,0 +1,103 @@
+"""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