hermes-gateway-auth-store-lock-starvation-tick-failure
The solution is written to /workspace/solution.md (with a runnable mechanism reproducer at /workspace/repro_lock_budget.py).
Diagnosis (confirmed): A host-scope lock-budget inversion on the single cross-process ~/.hermes/auth.json.lock:
- Reader (agent startup) budget = AUTH_LOCK_TIMEOUT_SECONDS = 15.0
- Refresh holder runs the token-endpoint POST inside the lock, so its real hold can reach ~20–25 s (_single_use_refresh_lock_timeout = max(15, 20+5.0))
15 < 20 ⇒ any startup read colliding with a live refresh is deterministically killed → whole tick lost. Fleet load (10–32 spawns/min, every process reads the store) makes the collision inevitable; rarity is per-tick, not per-mechanism.
I verified the mechanism locally with a standalone clone of the exact 0.05 s flock poll loop:
OLD waiter=15.0s hold=20.0s → FAIL raised after 15.03s: Timed out waiting for auth store lock
FIXED waiter=25.0s hold=20.0s → OK acquired after 20.00s
Fix (two parts):
1. Root cause (B): move the token POST out of the auth-store lock — read lock → network with lock released → short write lock with re-read/merge (prevents lost updates).
2. Invariant guard (A): derive AUTH_LOCK_HOLD_CEILING_SECONDS and AUTH_LOCK_READ_TIMEOUT_SECONDS from one place in auth_constants.py, add an import-time assert that read timeout >= hold ceiling, and split the read lock (_auth_store_read_lock) from the write lock in auth.py.
Explicitly rejected: raising AUTH_LOCK_TIMEOUT_SECONDS alone (option C) — it only turns a fast failure into a 25 s stall.
Verification provided: an invariant unit test (tests/test_auth_lock_budget.py), an E2E test holding auth.json.lock ~18 s while an agent start must block-and-succeed (tests/test_auth_lock_e2e.py), and host-level acceptance commands. Acceptance = a tick whose spawn coincides with a held lock completes and reports. Rollback is a single git revert; no project code touched.
# Evidence - Problem class: hermes-gateway-auth-store-lock-starvation-tick-failure - Model: openrouter/deepseek/deepseek-v4.1-flash - Solved: 2026-09-19T12:47:40.430Z - Verification: solution produced by pi in sandbox; see signatures.json
{"description": "SYMPTOM. A fleet foreman tick died with zero output: my-project-2026-09-19-12-35-04 (spawned 2026-09-19T07:35:04-05:00, idle chain, model k3 / provider kimi-for-coding) was recorded failed at 07:35:39 as 'gateway response failed (len=37): Timed out waiting for auth store lock'. The scheduler delivered nothing (DELIVER ... no output), the project smoke canary flipped two checks to FAIL (registration consecutive_failures=1, plus one new failed tick since the last board entry), and the whole agent turn was lost - not a slow response, no partial work. Fleet-wide frequency: exactly one occurrence (2 log lines in gateway.log, 0 in gateway.log.1/.2/.3, 2 in errors.log, 2 in scheduler.log); no other project affected. That rarity is the trap: it reads like a flake and gets re-run instead of diagnosed.\n\nROOT CAUSE (lock budget inversion, host-scope, not project code). Every Hermes process serializes auth-store transactions on ONE cross-process flock: auth.json.lock next to auth.json (hermes_cli/auth.py:632-644, _auth_store_lock -> _file_lock with the message constant 'Timed out waiting for auth store lock'). The WAITER budget is AUTH_LOCK_TIMEOUT_SECONDS = 15.0 (hermes_cli/auth_constants.py:50), enforced by a 0.05s poll loop that raises TimeoutError at the deadline (auth.py:610-618). The HOLDER budget is larger and unbounded relative to the waiter: agent/credential_pool.py:1396 takes the SAME auth-store lock with timeout_seconds=self._single_use_refresh_lock_timeout(), defined at credential_pool.py:1487-1491 as max(AUTH_LOCK_TIMEOUT_SECONDS, env_float(_REFRESH_TIMEOUT_ENV_VARS[provider], 20) + 5.0) - i.e. up to ~25s with the default 20s refresh POST timeout - and the token-endpoint POST runs INSIDE that lock, so the hold is network-bound. 15 < 25: any reader that collides with a slow refresh is guaranteed to time out, even though the store itself is perfectly healthy.\n\nTRIGGER CONTEXT. The fleet spawns 10-32 ticks/minute (183 spawns in the 07:30-07:39 local window; 8 ticks running fleet-wide at probe time). Every spawned process reads the auth store at agent startup, so the collision surface is large and grows with load. The refresh path is demonstrably live on this host: auth.json's updated_at advanced to 2026-09-19T12:41:25Z while the failed tick's window was being investigated, and the store carries credential_pool rows for 45 provider keys including the two providers whose refresh timeouts are env-overridable (openai-codex via HERMES_CODEX_REFRESH_TIMEOUT_SECONDS, xai-oauth via HERMES_XAI_REFRESH_TIMEOUT_SECONDS - both unset here, so the 20s default applies).\n\nDIAGNOSIS RECIPE (read-only, ~2 min). 1) Pair the scheduler and gateway logs for the same tick id: 'grep <tick-id> ~/.hermes/coding-hermes/scheduler.log' shows SPAWN -> GATEWAY-POST-TRACE classification=completed -> 'GATEWAY FAIL ... Timed out waiting for auth store lock'; 'grep -n \"auth store lock\" ~/.hermes/logs/gateway.log' shows the raise site as TimeoutError through gateway/platforms/api_server.py _run_agent -> run_in_executor, which proves it is the agent-start read, not the spawner. 2) Confirm the lock budget inversion from source, not from docs: AUTH_LOCK_TIMEOUT_SECONDS in hermes_cli/auth_constants.py vs _single_use_refresh_lock_timeout in agent/credential_pool.py. 3) Check whether the env overrides are set (they extend the hold, they do not shrink it). 4) Rule out a mass event by counting the string across the rotated logs - one hit = a collision, many hits = stop and re-scope.\n\nFIXES (choose by ownership): (A) cheapest and most robust - retry/bound-wait the READ path so a slow holder can never fail a whole tick (a read of a 34KB JSON does not need to be a hard-fail at 15s); (B) shrink the hold - move the token POST outside the auth-store lock (the deferred refresh path already documents exactly this intent at credential_pool.py:929-932, 'single-use-token refresh path (network I/O outside the lock by design)'), which makes the hold CPU-bound again; (C) raise AUTH_LOCK_TIMEOUT_SECONDS above the longest possible hold (only viable once the ceiling is known, so pair it with (B)).\n\nVERIFICATION THAT WOULD FALSIFY THE FIX. A test in hermes-agent asserting the invariant 'auth read timeout >= longest refresh lock hold', plus an E2E where one process holds auth.json.lock for ~20s while another starts an agent - today the second raises TimeoutError; after the fix it waits or degrades gracefully. Accept as fixed when a tick whose spawn coincides with a held lock completes and reports.", "environment": "Linux host, Hermes Agent gateway + coding-hermes scheduler fleet; cross-process advisory flock on ~/.hermes/auth.json.lock; 10-32 tick spawns/minute fleet load; gitreins/judge unaffected", "language": "", "model": "openrouter/deepseek/deepseek-v4.1-flash", "problem_class": "hermes-gateway-auth-store-lock-starvation-tick-failure", "provider": "openrouter", "solved_at": "2026-09-19T12:47:40.430Z", "version": ""}The solution is written to /workspace/solution.md (with a runnable mechanism reproducer at /workspace/repro_lock_budget.py).
Diagnosis (confirmed): A host-scope lock-budget inversion on the single cross-process ~/.hermes/auth.json.lock:
- Reader (agent startup) budget = AUTH_LOCK_TIMEOUT_SECONDS = 15.0
- Refresh holder runs the token-endpoint POST inside the lock, so its real hold can reach ~20–25 s (_single_use_refresh_lock_timeout = max(15, 20+5.0))
15 < 20 ⇒ any startup read colliding with a live refresh is deterministically killed → whole tick lost. Fleet load (10–32 spawns/min, every process reads the store) makes the collision inevitable; rarity is per-tick, not per-mechanism.
I verified the mechanism locally with a standalone clone of the exact 0.05 s flock poll loop:
OLD waiter=15.0s hold=20.0s → FAIL raised after 15.03s: Timed out waiting for auth store lock
FIXED waiter=25.0s hold=20.0s → OK acquired after 20.00s
Fix (two parts):
1. Root cause (B): move the token POST out of the auth-store lock — read lock → network with lock released → short write lock with re-read/merge (prevents lost updates).
2. Invariant guard (A): derive AUTH_LOCK_HOLD_CEILING_SECONDS and AUTH_LOCK_READ_TIMEOUT_SECONDS from one place in auth_constants.py, add an import-time assert that read timeout >= hold ceiling, and split the read lock (_auth_store_read_lock) from the write lock in auth.py.
Explicitly rejected: raising AUTH_LOCK_TIMEOUT_SECONDS alone (option C) — it only turns a fast failure into a 25 s stall.
Verification provided: an invariant unit test (tests/test_auth_lock_budget.py), an E2E test holding auth.json.lock ~18 s while an agent start must block-and-succeed (tests/test_auth_lock_e2e.py), and host-level acceptance commands. Acceptance = a tick whose spawn coincides with a held lock completes and reports. Rollback is a single git revert; no project code touched.
# Evidence - Problem class: hermes-gateway-auth-store-lock-starvation-tick-failure - Model: openrouter/deepseek/deepseek-v4.1-flash - Solved: 2026-09-19T12:47:40.430Z - Verification: solution produced by pi in sandbox; see signatures.json
{"description": "SYMPTOM. A fleet foreman tick died with zero output: my-project-2026-09-19-12-35-04 (spawned 2026-09-19T07:35:04-05:00, idle chain, model k3 / provider kimi-for-coding) was recorded failed at 07:35:39 as 'gateway response failed (len=37): Timed out waiting for auth store lock'. The scheduler delivered nothing (DELIVER ... no output), the project smoke canary flipped two checks to FAIL (registration consecutive_failures=1, plus one new failed tick since the last board entry), and the whole agent turn was lost - not a slow response, no partial work. Fleet-wide frequency: exactly one occurrence (2 log lines in gateway.log, 0 in gateway.log.1/.2/.3, 2 in errors.log, 2 in scheduler.log); no other project affected. That rarity is the trap: it reads like a flake and gets re-run instead of diagnosed.\n\nROOT CAUSE (lock budget inversion, host-scope, not project code). Every Hermes process serializes auth-store transactions on ONE cross-process flock: auth.json.lock next to auth.json (hermes_cli/auth.py:632-644, _auth_store_lock -> _file_lock with the message constant 'Timed out waiting for auth store lock'). The WAITER budget is AUTH_LOCK_TIMEOUT_SECONDS = 15.0 (hermes_cli/auth_constants.py:50), enforced by a 0.05s poll loop that raises TimeoutError at the deadline (auth.py:610-618). The HOLDER budget is larger and unbounded relative to the waiter: agent/credential_pool.py:1396 takes the SAME auth-store lock with timeout_seconds=self._single_use_refresh_lock_timeout(), defined at credential_pool.py:1487-1491 as max(AUTH_LOCK_TIMEOUT_SECONDS, env_float(_REFRESH_TIMEOUT_ENV_VARS[provider], 20) + 5.0) - i.e. up to ~25s with the default 20s refresh POST timeout - and the token-endpoint POST runs INSIDE that lock, so the hold is network-bound. 15 < 25: any reader that collides with a slow refresh is guaranteed to time out, even though the store itself is perfectly healthy.\n\nTRIGGER CONTEXT. The fleet spawns 10-32 ticks/minute (183 spawns in the 07:30-07:39 local window; 8 ticks running fleet-wide at probe time). Every spawned process reads the auth store at agent startup, so the collision surface is large and grows with load. The refresh path is demonstrably live on this host: auth.json's updated_at advanced to 2026-09-19T12:41:25Z while the failed tick's window was being investigated, and the store carries credential_pool rows for 45 provider keys including the two providers whose refresh timeouts are env-overridable (openai-codex via HERMES_CODEX_REFRESH_TIMEOUT_SECONDS, xai-oauth via HERMES_XAI_REFRESH_TIMEOUT_SECONDS - both unset here, so the 20s default applies).\n\nDIAGNOSIS RECIPE (read-only, ~2 min). 1) Pair the scheduler and gateway logs for the same tick id: 'grep <tick-id> ~/.hermes/coding-hermes/scheduler.log' shows SPAWN -> GATEWAY-POST-TRACE classification=completed -> 'GATEWAY FAIL ... Timed out waiting for auth store lock'; 'grep -n \"auth store lock\" ~/.hermes/logs/gateway.log' shows the raise site as TimeoutError through gateway/platforms/api_server.py _run_agent -> run_in_executor, which proves it is the agent-start read, not the spawner. 2) Confirm the lock budget inversion from source, not from docs: AUTH_LOCK_TIMEOUT_SECONDS in hermes_cli/auth_constants.py vs _single_use_refresh_lock_timeout in agent/credential_pool.py. 3) Check whether the env overrides are set (they extend the hold, they do not shrink it). 4) Rule out a mass event by counting the string across the rotated logs - one hit = a collision, many hits = stop and re-scope.\n\nFIXES (choose by ownership): (A) cheapest and most robust - retry/bound-wait the READ path so a slow holder can never fail a whole tick (a read of a 34KB JSON does not need to be a hard-fail at 15s); (B) shrink the hold - move the token POST outside the auth-store lock (the deferred refresh path already documents exactly this intent at credential_pool.py:929-932, 'single-use-token refresh path (network I/O outside the lock by design)'), which makes the hold CPU-bound again; (C) raise AUTH_LOCK_TIMEOUT_SECONDS above the longest possible hold (only viable once the ceiling is known, so pair it with (B)).\n\nVERIFICATION THAT WOULD FALSIFY THE FIX. A test in hermes-agent asserting the invariant 'auth read timeout >= longest refresh lock hold', plus an E2E where one process holds auth.json.lock for ~20s while another starts an agent - today the second raises TimeoutError; after the fix it waits or degrades gracefully. Accept as fixed when a tick whose spawn coincides with a held lock completes and reports.", "environment": "Linux host, Hermes Agent gateway + coding-hermes scheduler fleet; cross-process advisory flock on ~/.hermes/auth.json.lock; 10-32 tick spawns/minute fleet load; gitreins/judge unaffected", "language": "", "model": "openrouter/deepseek/deepseek-v4.1-flash", "problem_class": "hermes-gateway-auth-store-lock-starvation-tick-failure", "provider": "openrouter", "solved_at": "2026-09-19T12:47:40.430Z", "version": ""}