Skip to content

fix(health-check): a heartbeat restart reported every live cron as gone - #2600

Merged
john-the-dev merged 1 commit into
mainfrom
mini/session-cron-boundary
Aug 4, 2026
Merged

john-the-dev merged 1 commit into
mainfrom
mini/session-cron-boundary

Conversation

@sonichi

@sonichi sonichi commented Aug 4, 2026 •

Copy link
Copy Markdown
Owner

A standing warning that told the operator to fix a thing that wasn't broken

check_session_cron_registration (#2373) anchors its staleness comparison to .alive.started_at. That field is core_heartbeat._STARTED_AT — stamped once at module load — and both launch paths retain an existing heartbeat process, so it tracks the heartbeat writer, not the session that owns the crons. Restart the heartbeat under a live session and the boundary jumps forward, so a stamp written for that same session reads as predating it.

health-check.py already knew this

_marker_predates_running_core says so in its own docstring:

The heartbeat was the obvious candidate and is WRONG: core_heartbeat.py stamps _STARTED_AT once at module load and both launch paths RETAIN an existing heartbeat process, so .alive.started_at is the heartbeat process's age, not the session's. … which made the staleness comparison silently useless (john-the-dev, #2446).

#2446 introduced _last_core_launch_at() for exactly that reason. This probe was still comparing against the field that PR ruled out, for the same staleness question. Same field, same mistake, same fix.

Live evidence

Measured on this host with all nine expected crons registered and firing (confirmed against CronList, not inferred):

core      pid 30961  started 11:32:30    <- .alive "pid" (the core)
heartbeat pid 72981  started 16:13:56    <- .alive "heartbeat_pid"
.alive started_at    16:13:56            <- tracks the WRITER
stamp ts             11:37:21            <- 5 min after the core booted

Before / after, same live workspace, same host label:

BEFORE  warn  stamp predates this core boot (16595s older) — session crons are
              gone with the old session; re-run /schedule-crons
AFTER   ok    9 session cron(s) stamped registered this boot

The stamp itself records {"registered": 9, "config_total": 10} — nine expected (the tenth is the DISABLED wire entry on 0 0 31 2 *, excluded by the probe's own parked-and-unregistrable rule) and nine live.

Why this is worse than noise: the remedy it prescribes is to re-run /schedule-crons against a session whose crons are all present, and the skill documents a mid-session re-invocation inline-firing every entry (2026-06-03, which drowned a session and left owner DMs unprocessed).

Changes

  • Boundary comes from _last_core_launch_at(workspace). None keeps its fix(health-check): quota-telemetry false-warns on every Codex-runtime pass (follow-up to #2445) #2446 meaning — "no evidence", never "stale" — so a host without session-starts.log falls through to the stamp-only checks rather than warning.
  • _last_core_launch_at gains an optional workspace_dir defaulting to the global, so the existing caller is untouched. Without it the probe's injected workspace could not reach the log and every fixture would read None.
  • Message now says "predates this session's launch". "core boot" was the ambiguity that made the wrong field look right.

Tests

The fixture wrote only .alive, so every existing case exercised the wrong source — which is why a probe that misfires in production had a green suite. It now writes state/session-starts.log for the launch boundary, with .alive behind a separate argument so the regression can assert the field is no longer consulted.

parent  FAILED (failures=3)   <- both new cases + the message assertion
HEAD    Ran 22 tests, OK

Same test file at both commits; parent is a real worktree at dab9c998, not a synthesized tree.

test_session_launch_still_warns_when_both_are_present is the control: with a real launch record, a genuinely pre-launch stamp must still warn — otherwise this would have disabled the check rather than corrected its input. It fails on the parent too.

59 suites reference health-check.py; all 59 green. Added-line host-path scan clean (control fires on an injected /Users/...).

cc @sonichi @john-the-dev — John, this is the second consumer of the field #2446 ruled out; you may want to check whether any others remain.


The file already knew this, for a different probe (added 2026-08-04)

The strongest argument for this change isn't the symptom — it's that health-check.py already
documents .alive.started_at as the wrong anchor, and has since #2446
, while
check_session_cron_registration at :961 kept using it. From the same file, ~:3051:

The heartbeat was the obvious candidate and is WRONG: core_heartbeat.py stamps _STARTED_AT
once at module load and both launch paths RETAIN an existing heartbeat process, so
.alive.started_at is the heartbeat process's age, not the session's. After a Codex → Claude
switch it can be far older than a freshly-written marker, which made the staleness comparison
silently useless (john-the-dev, #2446).

So one probe in this file learned the lesson and the other did not. This PR makes the file
self-consistent with a rule it already states
— which is a merge argument that doesn't depend on
anyone reproducing a symptom.

Credit: john-the-dev established it in #2446; Sutando-Pro spotted that :961 had not adopted it.

Confirmed on a second host, and it fails OPEN there

Pro measured the same probe on their host, where it reports ok — and the accepted-but-wrong
window is 59.6 hours wide:

real boot (pane pid 6648)   2026-08-02T03:59:25Z
.alive started_at           2026-07-30T16:24:39Z   <- 59.6 h earlier
stamp                       2026-08-02T04:00:50Z   (85 s after the real boot)
.alive pid 83753 IS core_heartbeat.py, up 4d14h — it outlived the Aug-2 restart

Any stamp landing inside boot − started_at is accepted as "this boot" while actually predating it.
So on that host a restart with no /schedule-crons re-run would report ok with the crons gone,
for up to 59.6 h.

That is the direction that matters: on my host the wrong anchor is merely noisy; on Pro's it is
inert, in exactly the scenario #2373 built this probe to catch. Two hosts, opposite symptoms,
one root cause.

`check_session_cron_registration` anchored its staleness comparison to
`.alive.started_at`. That field is `core_heartbeat._STARTED_AT` — stamped once
at module load — and BOTH launch paths retain an existing heartbeat process, so
it tracks the heartbeat WRITER, not the session that owns the crons. Restart the
heartbeat under a live session and the boundary jumps forward, so a stamp
written for the current session reads as predating it.

`health-check.py` already knew this. `_marker_predates_running_core` says so in
its own docstring:

    The heartbeat was the obvious candidate and is WRONG: `core_heartbeat.py`
    stamps `_STARTED_AT` once at module load and both launch paths RETAIN an
    existing heartbeat process, so `.alive.started_at` is the heartbeat
    process's age, not the session's. (john-the-dev, #2446)

#2446 introduced `_last_core_launch_at()` for exactly that reason. This probe
was still comparing against the field that PR ruled out, for the same question.

Observed on Chis-Mac-mini 2026-08-04T03:0xZ with all nine expected crons
registered and firing:

    core      pid 30961  started 11:32:30    <- .alive "pid" (the core)
    heartbeat pid 72981  started 16:13:56    <- .alive "heartbeat_pid"
    .alive started_at    16:13:56            <- tracks the WRITER
    stamp ts             11:37:21            <- 5 min after the core booted

Before / after on that same live workspace:

    BEFORE  warn  stamp predates this core boot (16595s older) — session crons
                  are gone with the old session; re-run /schedule-crons
    AFTER   ok    9 session cron(s) stamped registered this boot

The false alarm is not merely noise: its remedy is to re-run /schedule-crons
against a session whose crons are all present, and the skill documents a
mid-session re-invocation inline-firing every entry (2026-06-03).

Changes:
- `check_session_cron_registration` takes its boundary from
  `_last_core_launch_at(workspace)`. `None` keeps its #2446 meaning — "no
  evidence", never "stale" — so a host without `session-starts.log` falls
  through to the stamp-only checks instead of warning.
- `_last_core_launch_at` gains an optional `workspace_dir` (defaults to the
  global, so the existing caller is unchanged) — without it the probe's injected
  workspace could not reach the log and every fixture would read None.
- Message says "predates this session's launch"; "core boot" was the ambiguity
  that made the wrong field look right.

Tests: the fixture wrote ONLY `.alive`, so every case exercised the wrong source
and the real-world false alarm was unreachable. It now writes
`state/session-starts.log` for the launch boundary, with `.alive` behind a
separate argument so the regression can assert the field is no longer consulted.

    parent  FAILED (failures=3)  <- both new cases + the message assertion
    HEAD    Ran 22 tests, OK

`test_session_launch_still_warns_when_both_are_present` is the control: with a
real launch record, a genuinely pre-launch stamp must still warn — otherwise
this would have disabled the check rather than corrected its input.

59 suites reference the module; all 59 green.

Stand: Echo Act IV Mini
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@github-actions

github-actions Bot commented Aug 4, 2026

Copy link
Copy Markdown
Contributor

Coverage Gate

✅ Diff coverage PASSES the 95% bar. Whole-tree (informational): 76%.

Diff Coverage

Diff: origin/main...HEAD, staged and unstaged changes

  • src/health-check.py (100%)

Summary

  • Total: 4 lines
  • Missing: 0 lines
  • Coverage: 100%

@qingyun-wu qingyun-wu left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed exact head 472e1628bae3358e18629109d16ca217c0658649. No blockers found — approving.

I checked the health-check boundary change against the previous .alive.started_at pitfall and the #2446 session-start log model. The new path uses state/session-starts.log as the session-owned cron boundary, preserves the "no evidence is not stale" behavior when no launch record exists, and keeps the existing stamp/count warnings intact. I also checked the host_label fixture path: production calls still use the local host label, and the tests patch the local-label resolver so the injected workspace exercises the intended host line.

Checks run locally:

  • python3 tests/health-check-session-cron-stamp.test.py passed.
  • python3 tests/health-check-quota-telemetry.test.py passed.
  • PYTHONPYCACHEPREFIX=/private/tmp/pycache-pr2600 python3 -m py_compile src/health-check.py tests/health-check-session-cron-stamp.test.py passed.
  • python3 -m ruff check src/health-check.py tests/health-check-session-cron-stamp.test.py passed.
  • git diff --check origin/main...HEAD passed.

Hosted coverage was green at last refresh; tsc + tests (clean install) was still in progress, so I am treating that as the remaining merge signal to watch rather than a code-review blocker.

Reviewed by Qingyun's Personal Codex.

@qingyun-wu qingyun-wu left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed exact head 472e1628bae3358e18629109d16ca217c0658649. APPROVE from code and failure-mode evidence.

The bug exists on current main: check_session_cron_registration treats .alive.started_at as the session boundary even though that value belongs to the retained heartbeat writer. This head reuses the already-hardened, host-filtered session-starts.log boundary; missing/unattributable launch records remain “no evidence,” so the fix cannot invent staleness. The paired regressions preserve both sides: a heartbeat-only restart no longer warns, while a real post-launch stale stamp still does.

I ran the 22 session-cron cases, all 43 quota/session-boundary cases, Python compilation, diff hygiene, and REVIEW.md path checks; all pass. Hosted coverage, Ruff, Python compatibility, shellcheck, CLA, and the other completed gates are green; clean-install CI is still running. Worst-case disruption is a false green when no attributable session record exists, mitigated by retaining the existing stamp presence/count validation instead of guessing a boundary. Code-ready, but not fully merge-ready until clean-install finishes green and the second current-head maintainer approval exists.

@john-the-dev john-the-dev left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM — approving with verification. I authored #2446 (_last_core_launch_at / _marker_predates_running_core), so I can confirm this is the same class of bug and the correct fix.

Root cause is right. check_session_cron_registration (#2373) anchored on .alive.started_at, which is core_heartbeat._STARTED_AT — stamped once at module load, and both launch paths retain an existing heartbeat process. So it tracks the heartbeat writer, not the session that owns the crons. #2446 already ruled that field out for _marker_predates_running_core for exactly this reason; this probe was making the same mistake for the same staleness question. Switching to _last_core_launch_at() (session boundary from state/session-starts.log) is the established, correct anchor.

Verified locally on head 472e1628 (worktree off origin/main):

  • python3 tests/health-check-session-cron-stamp.test.py → 22 passed, incl. test_alive_started_at_alone_does_not_warn (the exact regression: a fresh .alive.started_at with a stamp written for the live session no longer false-warns) and test_stamp_predating_boot_warns (true stale still warns via the session boundary).
  • python3 -m py_compile src/health-check.py tests/... → clean.
  • Added-lines scan for hardcoded host paths → none (the Chis-Mac-mini line is in a comment as live evidence, not a code path).

Nits (non-blocking): the workspace_dir param added to _last_core_launch_at defaults to WORKSPACE_DIR, so all existing callers are unaffected — good. None correctly keeps its #2446 meaning ("no evidence" → fall through to stamp-only, never "stale").

No blockers from me.

@sonichi

sonichi commented Aug 4, 2026

Copy link
Copy Markdown
Owner Author

This is now reproduced live on Chis-Mac-mini, not just in the fixture

The PR body proved this with a constructed workspace. It just happened on its own, on the running host, and the process table settles the cause beyond inference.

BEFORE — origin/main, the code actually running here, 2026-08-04T04:1xZ:

⚠ session-crons  warn  stamp predates this core boot (16595s older) —
                       session crons are gone with the old session; re-run /schedule-crons

The claim is false. CronList shows 9 registered session crons, and the health-check run above was itself fired by one of them (*/3 * * * * → /proactive-loop). Nothing was gone.

.alive.started_at is the heartbeat writer's start, and ps proves it

core       pid 30961  claude   started Mon Aug  3 11:32:30 PDT  (18:32:30Z)  etime 09:45:08
heartbeat  pid 72981  python   started Mon Aug  3 16:13:56 PDT  (23:13:56Z)  etime 05:03:42

state/cores/<host>.alive  started_at = 1785798836 = 23:13:56Z   <- the HEARTBEAT's start
state/session-starts.log  latest     = 1785781950 = 18:32:30Z   <- the CORE's launch

The core process has been up continuously for 9h45m and never restarted. session-starts.log holds 31 entries and zero fall within an hour of 1785798836 — no core launch happened at the moment .alive.started_at names.

The stamp lands 291 s after the real core launch, i.e. registration completed normally for this boot. And the reported gap is exactly the writer restart, not a rounding artifact:

1785798836 - 1785782241 = 16595   <- the "16595s older" in the warning, to the second

AFTER — same live workspace, PR head

Fetched pull/2600/head and asserted rev-parse equals headRefOid (472e1628) before measuring:

✓ session-crons  ok  9 session cron(s) stamped registered this boot

9 matches CronList's 9 — the fix is right for the right reason, not merely quiet.

One methodology note, in case you reproduce it

My first AFTER run printed ✓ ok — no schedules configured. That is the correct verdict for the wrong reason: a worktree resolves workspace to its own empty workspace/, so it found no crons.json at all and would have reported clean no matter what the code did. Pin workspace.path in the worktree's sutando.config.local.json to the live workspace before trusting either side of the comparison.

Why this matters more than a fixture

The failure mode is stochastic in the direction that hides it: it only appears after the heartbeat writer restarts under a long-lived core, so a short session never sees it, and the remedy it prints ("re-run /schedule-crons") is one an operator may well perform — re-registering 9 crons that were already live, which on a mid-session run is precisely the inline-fire hazard /schedule-crons step 3 warns about. A false alarm that recommends a risky no-op is worse than a silent one.

@sonichi

sonichi commented Aug 4, 2026

Copy link
Copy Markdown
Owner Author

This fired for real on Chis-Mac-mini today, and I caught it from the symptom side rather than the diff. Adding the live before/after, because until now this PR was approved on reasoning alone.

A routine health-check run warned that my session crons were gone. They were not — CronList showed 9 registered and firing, including the */3 main-loop that had just fired the pass I noticed it in.

Same live workspace, two heads, nothing else changed:

main     dab9c998   ⚠ session-crons  stamp predates this core boot (16595s older) —
                                     session crons are gone with the old session; re-run /schedule-crons
#2600    472e1628   ✓ session-crons  9 session cron(s) stamped registered this boot

The 9 is the part I'd point at: the fixed check doesn't just fall silent, it lands on the number CronList independently reports.

The live values, for the record

.alive  pid           30961        <- ps says this process has been up 12:11:52
.alive  heartbeat_pid 72981
.alive  started_at    7.51 h ago   <- does NOT describe pid 30961
stamp   ts           12.12 h ago   <- matches the CORE's real elapsed time
delta   -16596 s

The payload names a pid that has been alive for 12.2 h and a started_at from 7.5 h ago. Two different subjects in one file. pid was corrected to the core's on 2026-08-01; started_at was left tracking the writer, which is what this PR fixes.

The direction that worries me more than the noise

core_heartbeat.py's own docstring says the writer "is started detached by startup.sh (PPID 1), is never killed by restart.sh, and is only started if ! pgrep, so it outlived every core restart."

Take that seriously and the false-warn is the benign half. In the other direction — writer survives a core restart, so started_at stays old while a stamp from the previous session still exceeds it — the guard stays silent while the crons are genuinely gone. That is precisely the 2/18 silent failure #2373 built it to catch.

So the anchor doesn't just make it noisy; it can make it inert in exactly its own use case. test_alive_started_at_alone_does_not_warn pins the half I observed today; the session-launch boundary is what closes the other.

No change requested — this is already approved and clean. I'd just merge it on the strength of a real occurrence rather than a hypothetical one.

@sonichi

sonichi commented Aug 4, 2026

Copy link
Copy Markdown
Owner Author

Second-host confirmation from Chis-MacBook-Pro, and it exercises the false-negative direction rather than the noisy-warn one.

This host currently reports ok, so the defect is invisible here — but for a reason that is one restart away from being wrong:

real core boot (tmux pane pid 6648, ps lstart)   2026-08-02T03:59:25Z
.alive started_at                                2026-07-30T16:24:39Z   <- 59.6h OLDER than the boot
schedule-crons stamp ts                          2026-08-02T04:00:50Z   (85s after the real boot)

guard:   stamp_ts < .alive.started_at   -> False  => ok
correct: stamp_ts < real session boot   -> False  => ok

Right verdict, and here also the right reason — the stamp genuinely postdates the boot. The exposure is the gap between the two anchors:

BLIND WINDOW = boot - .alive.started_at = 214,486s = 59.6h

Any stamp landing inside that window is accepted as "this boot" while predating it. So on this host, if the core restarted and /schedule-crons never re-ran, a stamp up to 59.6 hours stale would still satisfy stamp_ts >= started_at and the probe would report ok while the crons were genuinely gone — the 2/18 failure #2373 built this guard for. The noisy warn is the visible half; this is the half that costs something.

Corroborating the mechanism directly: .alive's pid on this running host resolves to the heartbeat, not the core —

$ ps -o pid=,etime=,comm= -p 83753
83753  04-14:25:18  .../Python   (argv: src/core_heartbeat.py)

4d14h, i.e. it has outlived the Aug-2 core restart, which is exactly why started_at sits 59.6h behind. (Scoped claim: that is what this checkout is running right now, not an assertion about main.)

Worth noting the fix's own file already knew this — src/health-check.py:3051-3053 documents .alive.started_at as the wrong anchor for a different probe ("the heartbeat process's age, not the session's") while :961 still anchored session-crons to it. This PR moving to the launch marker makes the two consistent.

No change requested; adding evidence, not a review. Verified against the current head.

@sonichi

sonichi commented Aug 4, 2026

Copy link
Copy Markdown
Owner Author

Live instance of this false positive on Chis-Mac-mini, observed unprompted during a routine health check rather than constructed.

⚠ session-crons  warn  stamp predates this core boot (16595s older) —
                       session crons are gone with the old session; re-run /schedule-crons

The crons are not gone. CronList at that moment returned 9 registered, all live, including the */3 /proactive-loop entry that was driving the very pass which ran the check. The measurement:

stamp:      ts=1785782241  registered=9      (64076s ago)
heartbeat:  started_at=1785798836  pid=30961 (47480s ago)
            -> stamp predates .alive.started_at by 16596s

The corroboration I'd point at: the stamp says registered: 9 and there are exactly 9 live crons. The stamp is accurate — it just predates a heartbeat process that restarted independently, which is precisely the boundary this PR says is the wrong one to compare against (.alive.started_at tracks the WRITER, not the session).

The part that makes this worth more than a cosmetic warn: the prescribed remedy is harmful. "re-run /schedule-crons" mid-session is the exact action skills/schedule-crons/SKILL.md documents as having inline-fired every entry at once on 2026-06-03 — a morning briefing plus five cron bodies in one instant, drowning a live session that then ended without processing queued owner DMs. So a false NOT-registered doesn't just misreport; it points the reader at a known-destructive fix.

I did not act on the warn, and I did not re-stamp to silence it either — this PR is explicit that stamp age alone is deliberately not the signal, so papering it over would destroy the evidence for the real fix.

No change requested; adding the field observation because a defect that reproduces spontaneously on a second host is stronger than a constructed one. Still CLEAN + APPROVED here.

Stand: Echo Act IV Mini

@john-the-dev
john-the-dev merged commit fbd474e into main Aug 4, 2026
17 checks passed
@john-the-dev
john-the-dev deleted the mini/session-cron-boundary branch August 4, 2026 13:51
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants