Skip to content

Fix scheduler wedge: scope tick lock to dispatch, add LLM stream timeouts - #29350

Closed
benjaminm95 wants to merge 1 commit into
NousResearch:mainfrom
benjaminm95:fix/scheduler-wedge
Closed

benjaminm95 wants to merge 1 commit into
NousResearch:mainfrom
benjaminm95:fix/scheduler-wedge

Conversation

@benjaminm95

Copy link
Copy Markdown

Real-world reproduction

Reproduced twice in production on a Hermes gateway pointed at a
self-hosted Ollama server (see docs/incidents/2026-05-19-scheduler-wedge.md
on this branch for the full forensic write-up):

  • 2026-05-11 — first wedge, noticed but root cause not pinned
    at the time (filed as "Hermes scheduler wedge" in operator
    notes — .tick.lock held after a cron-launched script was
    killed mid-run, no new ticks until gateway restart).
  • 2026-05-19 — second wedge, 32 minutes wall-clock
    (time=1962.8s api_calls=3 response=1177 chars in the gateway
    log). A single Telegram chat triggered a long agent loop on a
    cold-loaded LLM. cron/scheduler.py:tick() held
    .tick.lock for the entire 32 minutes; every cron tick that
    fell in the window logged "Tick skipped — another instance holds the lock" and returned 0. 4 consecutive */5 * * * *
    catalysts ticks were starved
    (15:25 → 15:50 EDT) before the
    operator manually removed the lock file.

The fix is below; details in the incident write-up. 5
regression tests
cover the recovery paths:

  1. Total-timeout abort raises StreamTimeoutError(which="total").
  2. Per-chunk-timeout abort raises StreamTimeoutError(which="chunk").
  3. Lock released during a long-running stream — second tick
    fired mid-flight from another thread acquires + dispatches its
    own due jobs (the exact pre-fix wedge mode).
  4. Lock released on KeyboardInterrupt mid-dispatch.
  5. Lock released on arbitrary RuntimeError mid-dispatch.

2026-05-19 — Cron scheduler wedged for 32 minutes

Symptom

The algotrader operator running on this Hermes instance saw the
algotrader-catalysts-scan and algotrader-catalysts-evaluate
crons (both */5 * * * *, no_agent=True) stop firing for
roughly 25 minutes (15:25 → 15:50 EDT). During the same window:

  • The Telegram chat thread spent 32 minutes processing a single
    inbound message (gateway log: response ready: ... time=1962.8s api_calls=3 response=1177 chars).
  • ~/.hermes/cron/.tick.lock was held continuously across the
    whole window.
  • Other cron jobs (analyst-batch, polymarket, fear-greed) also
    missed their schedule, but the operator-visible pain was
    concentrated on the 5-minute catalysts because they were the
    shortest-cadence jobs in the gap.

Manual rm ~/.hermes/cron/.tick.lock followed by the next minute
boundary restored normal firing immediately.

Mechanism

cron/scheduler.py:tick() (the function the gateway calls every
60 s from a background thread) acquires the file lock, then runs
every due job to completion inside the try: block before
releasing in finally: (lines 1447–1590 of the file at incident
time).

When at least one due job in a tick is an LLM-backed job (not
no_agent=True), run_job() calls
agent.run_conversation(prompt) which internally streams from
the model provider via chat.completions.create(stream=True) and
iterates synchronously over chunks (run_agent.py:6907-6933).

There is no enforced end-to-end deadline on that stream:

  • HERMES_STREAM_READ_TIMEOUT (default 120 s) is an httpx-level
    per-chunk read timeout — it resets on every byte received, so a
    stream that emits one token every 119 s never trips.
  • HERMES_STREAM_STALE_TIMEOUT (default 180 s) is a stale-stream
    detector inside the chunk loop; same per-chunk semantics.
  • HERMES_CRON_TIMEOUT (default 600 s) is inactivity-based —
    it's reset by _touch_activity("receiving stream response")
    on every chunk, so an active-but-slow stream keeps it pinned at
    zero indefinitely.
  • max_iterations (default 90) is a tool-loop ceiling, not a
    wall-clock ceiling — each iteration can itself be an
    arbitrarily long stream.

So in pathological cases (provider degradation, retry storm with
keepalive pings, agent stuck in a tool/think/answer cycle that
makes progress slowly), a single LLM job can sit inside tick()
for minutes-to-hours while holding the file lock.

Every subsequent tick attempt during that window logs
"Tick skipped — another instance holds the lock" and returns 0
without firing any cron — including unrelated no_agent cron
that wouldn't touch the LLM at all.

Lock-scope audit

A repo-wide grep (tick.lock | tick_lock | _get_lock_paths)
shows only cron/scheduler.py and its tests touch the lock.
The lock has exactly one purpose: prevent two concurrent
tick() calls from picking up the same due job twice (the
gateway's background ticker and a standalone python -m cron.scheduler daemon running in parallel — explicitly called
out in the module docstring).

It does not serialize:

  • LLM provider concurrency (each job constructs its own
    AIAgent, its own httpx client, its own credential pool).
  • Job output storage (save_job_output is fd-per-write,
    independent per job_id).
  • Per-job state (jobs have independent SessionDB rows keyed by
    cron_session_id).
  • Shared adapters (delivery uses live adapters via
    asyncio.run_coroutine_threadsafe, no lock).

Conclusion: the lock's purpose is single-flight on cron-job
dispatch
, nothing else. There is no second purpose to preserve;
narrowing the lock to dispatch-only is safe.

Fix plan (this branch)

A. LLM stream deadline. Add two env vars —
HERMES_LLM_STREAM_TIMEOUT_SECONDS (default 300 s, total
wall-clock budget for one stream) and
HERMES_LLM_STREAM_CHUNK_TIMEOUT_SECONDS (default 60 s, max
gap between chunks). Both enforced inside the chunk loop with
a new StreamTimeoutError. On breach: close the stream
cleanly, raise, surface to the agent loop's existing retry /
error-propagation paths. Set either to 0 to opt that specific
deadline out.

Implementation note: the OpenAI SDK stream path is synchronous
(for chunk in stream:) and the cron caller already wraps it in
a ThreadPoolExecutor. The deadlines are enforced by a daemon
watchdog thread alongside the chunk loop — same end-to-end
guarantee asyncio.wait_for would give, in-place, without
rewriting the entire sync chunk loop into async.

B. Narrow lock scope. Hold .tick.lock only across
get_due_jobs() + advance_next_run() (the actual dispatch
step). Release before job execution. Subsequent ticks during
the LLM run land with an empty due-job list (already advanced)
and become a fast no-op. Single-flight semantics preserved
because advance_next_run() happens under the lock.

C. Guaranteed release. Wrap the lock acquisition in an
explicit try/finally that covers asyncio.CancelledError,
KeyboardInterrupt, and arbitrary BaseException
the pre-fix try block caught typed Exception only.

Tests

5 regression tests in tests/scheduler/test_wedge_recovery.py,
plus 2 env-var resolution tests (7 total). Existing
tests/cron/test_scheduler.py (115 tests) still passes.

Test invocation:

.venv/bin/python -m pytest tests/scheduler/ tests/cron/

What this does NOT fix

  • LaunchAgent supervision. The Hermes gateway on the incident
    host was not registered with launchd; no auto-respawn on
    crash. Filed in docs/todos/scheduler-followups.md with a
    recommended plist (KeepAlive=Crashed-only,
    ThrottleInterval ≥ 60).
  • Per-job stream timeout overrides. HERMES_LLM_STREAM_TIMEOUT_SECONDS
    is process-wide. Some long-form jobs (compliance check, deep
    research) genuinely need >300 s. Also filed in
    docs/todos/scheduler-followups.md.

Files changed

  • cron/scheduler.py — new _dispatch_lock() context manager;
    tick() releases lock before job execution.
  • run_agent.py — new StreamTimeoutError + watchdog thread in
    _call_chat_completions.
  • tests/scheduler/test_wedge_recovery.py (new) — 7 tests.
  • AGENTS.md — cron-hardening section updated with new
    lock-scope semantics + env vars.
  • docs/incidents/2026-05-19-scheduler-wedge.md (new) — full
    forensic write-up.
  • docs/todos/scheduler-followups.md (new) — LaunchAgent
    supervision + per-job timeout overrides, both deferred.

🤖 Generated with Claude Code

Root cause of the 2026-05-19 wedge: `cron/scheduler.py:tick()`
held `.tick.lock` across the ENTIRE due-job execution, including
the synchronous LLM streaming inside each job. A single 1962 s
agent run (Telegram conversation that landed on a degraded
provider) blocked the lock continuously and starved four
back-to-back `*/5 * * * *` ticks. Forensic write-up in
docs/incidents/2026-05-19-scheduler-wedge.md.

Three fixes, one branch:

A. LLM stream deadlines (run_agent.py). New `StreamTimeoutError`
   (subclass of TimeoutError so existing handlers still catch it)
   raised on either of two breaches enforced by a daemon
   watchdog inside `_call_chat_completions`:
   - `HERMES_LLM_STREAM_TIMEOUT_SECONDS` (default 300 s) total
     wall-clock budget — bounds the worst-case stream duration
     independent of provider behaviour.
   - `HERMES_LLM_STREAM_CHUNK_TIMEOUT_SECONDS` (default 60 s)
     per-chunk silence budget — catches stalled-after-some-tokens
     paths the existing httpx read timeout misses.
   Set either to 0 to opt that specific deadline out.

   Deviation from spec: spec asked for `asyncio.wait_for`, but the
   OpenAI SDK stream path here is synchronous (`for chunk in
   stream:`) and the cron caller already wraps it in a
   ThreadPoolExecutor. The watchdog-thread pattern enforces the
   same two-deadline guarantee in-place without rewriting the
   whole sync chunk loop into async — much smaller blast radius.

B. Narrow tick-lock scope (cron/scheduler.py). Investigation
   showed the lock has exactly one purpose (cron-fire single-
   flight); no hidden Ollama-guard, shared-state, or
   storage-serialization purpose to preserve. New
   `_dispatch_lock()` context manager holds the lock only across
   `get_due_jobs()` + `advance_next_run()` — job execution runs
   outside the lock. Subsequent ticks during a long-running job
   see an empty due-list (already advanced) and exit fast.

C. Bullet-proof lock release. `_dispatch_lock()` uses
   `try/finally` with bare `except BaseException` on the release
   path so `asyncio.CancelledError`, `KeyboardInterrupt`, and
   `SystemExit` cannot bypass release and leave the lock stuck
   (the 2026-05-19 wedge mode).

Tests (tests/scheduler/test_wedge_recovery.py, 7 added):
- total-timeout abort raises StreamTimeoutError(which="total")
- per-chunk-timeout abort raises StreamTimeoutError(which="chunk")
- env-var resolution falls back to default when unset / negative
- lock released during long-running stream: second tick fired
  mid-flight from another thread acquires and dispatches its
  own due-list
- lock released on KeyboardInterrupt mid-dispatch
- lock released on arbitrary RuntimeError mid-dispatch

Docs:
- docs/incidents/2026-05-19-scheduler-wedge.md (forensic +
  lock-scope audit + fix plan)
- docs/todos/scheduler-followups.md (LaunchAgent supervision
  with KeepAlive=Crashed-only + per-job stream timeout
  overrides — both intentionally deferred)
- AGENTS.md cron-hardening section updated with new lock-scope
  semantics + env vars (no CLAUDE.md in this repo)

Test impact: 325 scheduler-adjacent tests pass (200 of the
pre-existing 202 failures elsewhere are unrelated to this
patch — same set fails on `main`); my branch is strictly
+8 passes / -1 failure / -1 error vs main.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
@alt-glitch alt-glitch added type/bug Something isn't working comp/cron Cron scheduler and job management comp/agent Core agent runtime: loop, agent_init, prompt builder, context-compression, responses endpoint P1 High — major feature broken, no workaround labels May 20, 2026
@alt-glitch

Copy link
Copy Markdown
Contributor

Overlaps with open #27492 (same tick-lock narrowing fix). This PR additionally adds LLM stream timeouts and includes a detailed incident write-up. Related: #10443 (scheduler reliability), #3764 (early lock release attempt, closed).

@benjaminm95

Copy link
Copy Markdown
Author

Closing — not maintaining a fork. Filing for awareness only; feel free to take any of the diagnosis or fix if useful.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

comp/agent Core agent runtime: loop, agent_init, prompt builder, context-compression, responses endpoint comp/cron Cron scheduler and job management P1 High — major feature broken, no workaround type/bug Something isn't working

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants