Skip to content

fix(cron): a drifted start-time fingerprint must not prove the owner died - #111454

Open
Monti76 wants to merge 1 commit into
NousResearch:mainfrom
Monti76:fix/cron-ledger-start-time-drift
Open

Monti76 wants to merge 1 commit into
NousResearch:mainfrom
Monti76:fix/cron-ledger-start-time-drift

Conversation

@Monti76

@Monti76 Monti76 commented Sep 15, 2026

Copy link
Copy Markdown

What

cron.executions._owner_is_live treats any mismatch between a ledger row's stored start-time fingerprint and the live fingerprint of the owning pid as proof that the owner died, and recover_interrupted_executions() then rewrites the attempt to unknown.

That fingerprint is a PID-reuse guard, not an identity proof, and it is not stable: on macOS the kernel re-derives a live process's start time across a sleep/wake clock correction.

Evidence (2026-09-14, one host, one scheduler)

  • Single scheduler identity throughout: one process_id, one pid (the running gateway), one live process. There was no duplicate claimant.
  • _process_start_time(os.getpid()) read 178940554382 for 2h21m — 16:27:01 → 18:47:53, and both edges land exactly on pmset -g log sleep transitions.
  • The same live pid reads 178940554282 (psutil create_time() = 1789405542.824212, stable over 300 consecutive samples), and no process on the host matches the drifted value.
  • 134 ledger rows written in that window carry the drifted value. Every one still in flight when a recovery pass ran was flipped to unknown.
  • Because finish_execution only rewrites claimed/running rows, the flip silently drops the run's real terminal state. Example wave at 18:39:33: four jobs claimed within 54 ms; three were flipped to unknown by one recovery pass sharing finished_at=…33.687332, while the fourth (committed after that pass's snapshot) recorded completed normally at …33.695897.
  • Net effect that day: 25 of 44 unknown rows belonged to two healthy jobs firing every 10 minutes — a false "unknown whether side effects ran" for runs that completed fine.

Fix

  • A start-time mismatch is only proof of death when it is gross. PID reuse requires the pid to be recycled first, and pid allocation is sequential, so a reused pid's start time is minutes-to-hours away — never a second. _FINGERPRINT_DRIFT_TOLERANCE = 500 centiseconds (5s).
  • An unreadable fingerprint (None) is now unknown, not death. That matches the sibling gate gateway.status._scoped_lock_owner_state and this module's own fail-safe rule ("inability to prove death must not rewrite state").

Scope

Deliberately limited to the ledger's liveness gate. The strict-equality start-time checks in gateway/status.py (_start_times_agree, used by terminate_pid(..., expected_start_time=...)) are not loosened: they gate process termination, where exactness is the safety property being protected.

Tests

tests/cron/test_execution_ledger.py, +3 cases:

case pre-patch post-patch
test_recovery_keeps_live_owner_whose_start_time_drifted FAIL pass
test_recovery_leaves_an_unreadable_fingerprint_alone FAIL pass
test_recovery_still_marks_a_recycled_pid_dead pass pass (guard: tolerance must not over-reach)

Whole file: 28 passed. Non-vacuity verified by reverting only cron/executions.py and re-running the new cases.

…died

The execution ledger stores a per-process start-time fingerprint
(`process_started_at`) as a PID-reuse guard, and `_owner_is_live` treats ANY
mismatch as proof the owner died -- which rewrites the attempt to `unknown`.
That fingerprint is not stable enough to carry that weight: on macOS the kernel
re-derives a live process's start time across a sleep/wake clock correction.

Observed 2026-09-14 on a live gateway (single scheduler identity, single pid):
`_process_start_time(os.getpid())` read 178940554382 for 2h21m
(16:27:01 -> 18:47:53 -- both edges land exactly on `pmset -g log` sleep
transitions) while the same live pid also reads 178940554282, and no process on
the host matches the former value. 134 ledger rows carried the drifted value.
Every one still in flight when a recovery pass ran was flipped to `unknown`, and
because `finish_execution` only rewrites `claimed`/`running` rows the run's real
terminal state was silently dropped: 25 of that day's 44 `unknown` rows belonged
to two healthy jobs firing every 10 minutes.

Only a *gross* mismatch actually proves reuse -- the pid must be recycled first
and allocation is sequential, so a reused pid's start time lands
minutes-to-hours away, never a second. A 5s tolerance keeps the reuse guard while
surviving clock drift, and an unreadable fingerprint is now treated as unknown
rather than death, matching the sibling gate
`gateway.status._scoped_lock_owner_state`.

Scope: the ledger's liveness gate only. The strict-equality start-time checks in
`gateway/status.py` are deliberately left alone -- they gate process
*termination*, where strictness is the safety property.

Tests: `tests/cron/test_execution_ledger.py` (+3 cases). Non-vacuity: with
`cron/executions.py` reverted, the drift and unreadable-fingerprint cases fail
(1 == 0 assertions); the recycled-pid case passes both ways by design, since it
exists to prove the tolerance does not over-reach. Full file: 28 passed.
@alt-glitch alt-glitch added type/bug Something isn't working P2 Medium — degraded but workaround exists comp/cron Cron scheduler and job management duplicate This issue or pull request already exists labels Sep 15, 2026
@alt-glitch

Copy link
Copy Markdown

This was generated by AI during triage.

Duplicate of #103249, which already replaces the exact start-time fingerprint match in cron/executions.py::_owner_is_live with a drift tolerance and treats an unreadable fingerprint as live (2s, non-Linux only, vs 5s on all platforms here). #108484 covers the unavailable-fingerprint half. The sleep/wake evidence in this PR (134 drifted rows, in-flight runs flipped to unknown) is the strongest field data in the cluster, so reviewers may want to fold the platform-agnostic tolerance and these tests into whichever PR lands.

@kyssta-exe

Copy link
Copy Markdown

Review: fix(cron) drifted start-time fingerprint must not prove owner died

Summary: Relaxes cron/executions.py::_owner_is_live from exact start-time equality to a ±5s tolerance, and treats unreadable fingerprints as unknown rather than dead. Grounded in strong field evidence: 134 ledger rows with +1.00s drift bounded by sleep/wake transitions, 25 of 44 unknown rows falsely flipped. Deliberately leaves the strict checks in termination paths alone.

What changed:

  • cron/executions.py: new _FINGERPRINT_DRIFT_TOLERANCE = 500 (centiseconds); _owner_is_live returns True within tolerance, True on None
  • tests/cron/test_execution_ledger.py: +3 cases (drifted-kept, recycled-reclaimed at +60001cs, unreadable-left-alone)

Strengths: Excellent failure analysis with a principled threshold argument (sequential PID allocation ⇒ reuse lands minutes/hours away, never ~1s). The guard test (drift=60001 still reclaimed) proves the tolerance doesn't over-reach. Scope discipline on termination paths is correct — exactness there is a safety property.

Findings: One consideration, non-blocking: the tolerance (5s) vs. observed drift (1s) leaves 4s of unexplained headroom; a comment justifying the headroom (clock slew bounds) would strengthen it, but PID-reuse distance makes this safe in practice. Also: gh pr checks reports no checks on this branch — CI hasn't run, so verify tests before merge.

Verdict: Looks good to merge (after confirming CI runs green).

Reviewed using Hermes-Agent

@youyoutu405-source

Copy link
Copy Markdown

The kanban dispatcher has the same class of bug this PR fixes for cron — the sleep/wake fingerprint drift also breaks release_stale_claims on macOS, and in the kanban case the drift is positive proof of death rather than a ledger annotation.

Live occurrence (2026-09-21, one card, origin/main @ db1f3f4564):

  • 22:21:50 worker pid 21366 spawned for a kanban card; fingerprint captured at spawn: worker_started_at = "|179000051092" (empty epoch on macOS — no /proc — so identity rests entirely on the psutil-derived start time, exactly the unstable quantity this PR documents).
  • The MacBook slept ~27 min in three segments (pmset -g log: 22:21:50 → 22:49:20, entries line up to the second with the spawn/reclaim times below).
  • 22:49:27 release_stale_claims re-derived the fingerprint of the still-live pid 21366, got a different value, and took the mismatch as PID recycling:
{"stale_lock": "Boy-Of-MacBook-Air.local:11469", "worker_pid": 21366, "host_local": true, "heartbeat_stale": false, "termination_attempted": false, "terminated": true, "sigkill": false, "pid_recycled": true}

Note terminated: true with termination_attempted: false — the reclaim believed the process was already gone. It was not: ps -p 21366 showed it alive 5+ minutes later, still appending to the card's worker log (and it later completed a valid request_review through the unblock path).

  • Net effect: claim released beside a live worker → duplicate spawn → both wrote the same card for ~30 min → breaker blocked the card on two stale_lock infrastructure errors.

Where the kanban side diverges from cron: in cron.executions._owner_is_live the drift demotes an attempt to unknown; in hermes_cli/kanban_db.py::release_stale_claims the same unstable comparison (_pid_recycled in hermes_cli/kanban_db_dispatch.py, which calls _process_fingerprint → psutil.Process.create_time()) releases the claim and books a failure toward the breaker. So the fix needs the kanban reclaim path too, not just the cron ledger.

Two additional observations from this incident, if useful:

  1. The macOS epoch half of the fingerprint is always empty (current_instantiation_epoch() returns "" without /proc), so on macOS the whole PID-reuse guarantee rests on the sleep-unstable start time — the weakest possible footing. A macOS-stable alternative (e.g. the kernel proc_pidinfo start time, or refusing to conclude "recycled" when the delta is small and positive) would fix every consumer at once.
  2. _claim_is_live (used by worker-side terminal calls) uses the same comparison, so a worker that finishes right after a wake can also be told its own run is not live — worth covering in tests either way.

Evidence preserved: board DB reclaim events, worker log (shows the live pid continuing to write after the reclaim), and the pmset timeline.

@youyoutu405-source

Copy link
Copy Markdown

Follow-up: filed the kanban-side consumer of the same unstable fingerprint as #118326 (stale-claim reaper releases a live worker's claim after sleep/wake), so the kanban gap is trackable independently of this PR's cron-side fix. Cross-linking both ways.

@Bin-Peng

Bin-Peng commented Oct 4, 2026

Copy link
Copy Markdown

Independent measurement from the same call site (cron.executions._owner_is_live), macOS, launchd gateway — offered in case it helps settle the window this PR picks.

Host: macOS, one scheduler identity throughout, no duplicate claimant.
Date: 2026-09-28.

row written by the gateway's own claim:  process_started_at = 178900855052
a reaper reading the SAME live pid:      178900854852
an unrelated row on the same pid:        178900855152

So the same live process fingerprints 2-3 s apart between calls (psutil reports a whole-second boot time, so the centisecond field re-derives). _owner_is_live(669, 178900855052) returned False, and the desktop serve scheduler's recovery pass flipped the gateway's in-flight 09:00 / 09:30 / 10:00 runs to unknown while they were still producing output. Since finish_execution only rewrites claimed/running rows, the real terminal state could never be recorded afterwards.

Relevant to this PR's boundary tests: the shared start_time_fingerprints_match comparator as landed (#117505) uses a 200 cs (2 s) default, which would still call that 2-3 s-drifted live owner dead — the 200 accepted / 201 rejected boundary is exactly the case observed here.

Locally I run the same comparator from the ledger path with an explicit, larger window:

START_TIME_TOLERANCE_CENTISECONDS = 1000   # 10 s, far below any plausible PID-reuse interval
return start_time_fingerprints_match(started_at, current, tolerance=START_TIME_TOLERANCE_CENTISECONDS)

Not attached as a competing PR — happy to adopt whatever window this one lands on (or to supply the test case as a patch here) so the ledger path and the runtime-status path don't end up with different tolerances by accident.

This branch has not been deployed

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

Labels

comp/cron Cron scheduler and job management P2 Medium — degraded but workaround exists type/bug Something isn't working

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants