fix(cron): decouple heartbeat from cron_tick() returning - #60729
Conversation
…h#60703) The in-process ticker only bumped record_ticker_heartbeat after cron_tick returned, so any iteration that blocks silently (lock contention, slow jobs.json I/O, a long-running synchronous code path) leaves the previous heartbeat to age until the next iteration finally completes — easily minutes, which 'hermes cron status' then reports as STALLED with no log evidence. Add an independent daemon watchdog thread (heartbeat at half the configured cadence, capped to [5s, interval]) so the liveness signal refreshes as long as the ticker thread itself is runnable, independent of whether cron_tick is making progress. Surface a WARNING when a single tick exceeds the configured interval so a slow ticker is observable instead of silent, and wrap the heartbeat write in a logger-aware helper that escalates write failures to ERROR so an actual disk issue isn't masquerading as 'no heartbeat for Ns'. Fixes NousResearch#60703.
teknium1
left a comment
There was a problem hiding this comment.
Thanks for isolating the blocked-tick observability gap. The reported #60703 lock/claim failure mode is already fixed on main by #60855 (7ecc822e1), but the generic blocked-tick work remains reviewable.
Problems
cron/scheduler_provider.py:201computesmax(5, min(interval // 2, interval)). With the PR test'sinterval=1, this is 5 seconds, not 1 second as stated attests/cron/test_scheduler_provider.py:691-742; the expected third beat is therefore deadline-edge and not a valid cadence regression.cron/scheduler_provider.py:283cannot log the promised write failures.record_ticker_heartbeat()already suppresses_atomic_write_epoch()exceptions incron/jobs.py:694-702, so this wrapper'sexceptis not reached for filesystem failures.
Suggested changes
- Correct the cadence bounds and make the watchdog test assert a non-deadline-edge schedule.
- Return write success from the heartbeat helper or place logging at the atomic-write boundary, with a forced-write-failure logging test.
Automated hermes-sweeper review.
| # Half-cadence refresh; cap to at least 5s and at most the | ||
| # tick interval itself so a misconfigured 1s interval can't | ||
| # spam the heartbeat file. | ||
| cadence = max(5, min(interval // 2, interval)) |
There was a problem hiding this comment.
This order does not cap the cadence at interval: with the new test's interval=1, it evaluates to 5 seconds. That contradicts the test's one-second expectation and makes its third beat deadline-edge. Apply the lower bound before the upper cap, then adjust the test to avoid timing the final expected beat at the timeout boundary.
| """ | ||
| try: | ||
| from cron.jobs import record_ticker_heartbeat | ||
| record_ticker_heartbeat(success=success) |
There was a problem hiding this comment.
record_ticker_heartbeat() already catches write failures internally (cron/jobs.py:694-702), so filesystem failures never reach this wrapper's except and no error is logged. Expose success/failure from the lower-level helper or log at the atomic-write boundary, and cover a real forced write failure.
|
obsolete The issue this PR closes appears to be resolved already. Please reopen with a fresh target if this still covers a distinct gap. Signed: GPT-5.6-terra-low in Codex |
Problem
The cron ticker's heartbeat file (
~/.hermes/cron/ticker_heartbeat) only gets bumped aftercron_tick()returns. Any single iteration that blocks silently —.tick.lockcontention, slowjobs.jsonI/O, a stray synchronous code path sneaking back in, or a long-running synchronous dispatch — leaves the previous heartbeat to age until the next iteration finally completes, easily adding multiple minutes to the recorded timestamp.hermes cron statusthen interprets that as a STALLED ticker that "may NOT be firing" (#60703). The gateway process is alive the whole time.Reproduction:
no_agentscripts).hermes gateway restart.hermes cron statusfirst reports healthy; within ~30 minutes it flips to "STALLED — no heartbeat for Ns" with no error in the gateway log.Runtime signal:
hermes cron run <id>returns "Already being fired by the scheduler; not run again" — the in-process CAS claim is honoring the running tick, so the live code path is alive, but the tick isn't observable.Root Cause
InProcessCronScheduler.start()(the built-in 60s ticker that backs bothgateway/run.py::start_gatewayandhermes_cli/web_server.py::_start_desktop_cron_ticker) writes the heartbeat only aftercron_tick()returns:If
cron_tickever blocks, the heartbeat ages unmolested. TheTICKER_HEARTBEAT_FILEonly signals "the ticker thread's most recent loop iteration completed" — it does NOT signal "the gateway is runnable and the ticker is alive". The same hardening gap exists in PR #39720's description (long sequential job monopolizing the ticker thread), but addressed only the symptom there; the user-facing symptom (STALLED — no heartbeat for Ns, no error) is what triggered this PR.Sibling paths:
_start_desktop_cron_ticker) — uses the sameInProcessCronSchedulervia the samecron.scheduler.tick, reaches the same blunt edge.CronScheduler.fire_due/ Chronos) — explicitly already out-of-band-report provider status, so the watcher is a no-op for them.Fix
Three small additions to
InProcessCronScheduler.start(), all additive — no public API surface changed:1. Independent watchdog thread (
cron-ticker-heartbeat,daemon=True). Bumpsrecord_ticker_heartbeat(success=False)on a fixed cadence —max(5, interval // 2)seconds, capped at the configured interval itself. The success marker is NEVER bumped by the watchdog; the main loop's existingsuccess=Truebeat remains the source of truth for "did a tick actually fire". Sohermes cron statusresolves the exact same way for healthy / alive-but-failing / stalled — only the threshold for "alive" widens.The watchdog runs in its own
threading.Thread(not a coroutine / timer) because the parent code path is also synchronous and we want zero dependency on the asyncio loop being runnable while the cron ticker is mid-tick. It exits cleanly onwatchdog_stop.set()from the main loop'sfinally:block — noatexithook, no race with interpreter finalization.2. Tick-duration guard.
cron_tick()is timed withtime.monotonic(). If a single iteration exceeds the configured interval, log a WARNING (not error — the jobs are still firing, just late). Previously this went completely silent; now the gateway log carries a forensic breadcrumb (Cron tick took NNs (interval=Ms)), andhermes cron statusreports a fresh heartbeat instead of "STALLED".3.
_record_or_log_heartbeatwrapper.record_ticker_heartbeatis intentionally best-effort and silent (transient disk errors must never break the tick loop); but when that silence becomes the proximate cause of a STALLED report ("no heartbeat for Ns — check the filesystem"), the wrapper escalates a write failure tologger.error("Ticker heartbeat write failed (success=%s): %s", ...)so the gateway log has something to surface. The "never break the loop" contract holds — the wrapper still swallows and returns.Files
cron/scheduler_provider.py—InProcessCronScheduler.start()restructure + new_record_or_log_heartbeatmethodtests/cron/test_scheduler_provider.py— 3 new regression tests covering each guaranteeHow to Test
.venv/bin/python -m pytest tests/cron/test_scheduler_provider.py -v -o addopts= -p no:cacheprovider .venv/bin/python -m pytest tests/cron/ -o addopts= -p no:cacheprovider # full cron suite as a regression checkExpected: 40 passed for the provider suite (37 existing + 3 new), 644 passed for the full cron directory.
The three new tests:
test_heartbeat_refreshes_while_tick_blocks— replacescron.scheduler.tickwith a callable that never returns; asserts the watchdog bumps heartbeat at least 3 times within ~5s while the main loop is hung, proving liveness is independent of tick progress.test_watchdog_stops_when_main_loop_exits— setsstop_event, asserts the watchdog thread emits at most one trailing heartbeat write within the next 300ms; guards against runaway heartbeats masking shutdown.test_slow_tick_logs_warning_but_keeps_loop_alive— runs a tick that sleeps longer than the configured interval; asserts the loop survives ≥2 iterations AND a 'Cron tick took' WARNING was emitted; proves the duration guard surfaces slowness instead of silently sliding past it.Result
tests/cron/suite (644 tests including existing F2a/F2b ticker-survival tests for [Bug]: Cron ticker dies silently — no error log, no watchdog, misleading status #32612/fix: cron ticker thread stops silently, jobs never fire #32895): all PASS, no regressions.Checklist
tests/cron/)cron/scheduler_provider.py's ABC notesHERMES_*env vars / no.envsecrets (per the "new env vars for non-secret config" rejection criterion)