feat(observability): classify a run as working / stalled / crashed / done - #218
feat(observability): classify a run as working / stalled / crashed / done#218OsherElhadad wants to merge 5 commits into
Conversation
…ve tail A classic `cap-evolve run` was completely silent for its whole duration: every phase ran under subprocess.run(capture_output=True), so a multi-hour hill-climb showed a blank terminal until it returned one JSON blob — and a hung run was indistinguishable from a working one. The only live view was the web dashboard, which leaves CI/ssh/headless/air-gapped users with nothing. - New core module `cap_evolve.eventstream` (stdlib only, zero new deps): the ONE place that reads a run's events.jsonl. read_new_events() (byte-offset incremental read, partial trailing line left unconsumed), follow_events() (blocking generator that waits for the file, stops on finalize/idle/signal), and format_event()/render_line() (one human-readable line per event, ANSI applied only by render_line). - `cap-evolve run --follow`: prints stage transitions, baseline, per-candidate accept/reject with candidate id + val + reason, budget warnings, optimizer errors, finalize, plus a cumulative cost/token meter. Progress goes to STDERR so stdout stays the machine-readable final JSON scripts parse. Runs on a daemon thread started before baseline creates the run dir, so the first events are never missed; it can never raise into the run. - `cap-evolve tail [run_dir]`: attaches to an existing or ongoing run (default: newest run_* under --base). Waits for the run dir to appear, so you can attach before the run creates it. --from-start replays history. - The dashboard's SSE route now imports read_new_events from the shared core helper instead of owning its own copy, so terminal and web read the same typed event stream and can never disagree. #118 (stall detection), #122 (replay), #138 and #144 build on this module. - Degrades cleanly with no TTY: plain text when piped, in CI, or under NO_COLOR. Closes #116
…ion, honest cost, stderr safety Review fixes for #191 (hub PR for #118/#122/#138/#144). - A malformed event no longer kills the follower thread. format_event is total (non-dict / bad `t` degrade to None or `--:--:--`), and cli.py reports on stderr instead of swallowing, so a dead follower is never mistaken for a silent run — the exact bug #116 exists to fix. - read_new_events returns only JSON objects, so no consumer (CLI or dashboard SSE) receives a bare 42/null/[1,2]; unreadable records surface as a log_corruption event instead of vanishing. - All rendered text is sanitised: C0/C1 controls and ESC sequences are stripped and newlines collapse, so an optimizer's stderr cannot set the window title, clear the screen, or forge a fake FINALIZE line. - The cost meter no longer double-counts: runner spend from `evaluate`, optimizer spend from `step`-likes, intake from `intake` — matching Spent.total_usd. Exposed as public accrue_totals so #138 does not fork the arithmetic. - --follow disables itself when stderr is unusable (`2>&-`) rather than letting progress corrupt the stdout JSON contract. - Hub API: follow_events yields a typed _follow_end sentinel naming its exit reason (stop_kind/idle/should_stop) for #118, should_stop now receives the last event, the 300s idle_timeout module default is gone, a shrunk file re-reads from 0 for #122, and format_event(skip_kinds=()) exposes bookkeeping kinds for #138. - tail exits 2 on an impossible run dir and 3 on an idle timeout with no events; --resume --follow no longer replays the whole prior log; use_color requires its stream; negative --idle-timeout is rejected.
…done Closes #118 A hung run used to masquerade as finished. The dashboard's SSE stream closed after a fixed ~5 idle minutes and the UI flipped to "idle" — which reads like completion — and the hub's `_status` left a run that produced one candidate and then crashed as `live` forever. Both surfaces are now driven by ONE classifier in `cap_evolve.eventstream` (built on #116's shared event tail), consumed by `cap-evolve tail`, `run --follow`, the hub row, the DeepDive header and the SSE route, so the terminal and the web UI cannot disagree about the same run dir. The threshold is derived from the run, not a constant. A fixed 5 minutes is wrong in both directions: a toy run is silent that long only if it is dead, while one τ²-bench rollout can legitimately take 20 minutes, and a false "hung" is the worst outcome available because the user's reaction is to kill a working run. The bar is `max(300s, 3 × the slowest inter-event gap this run has already shown)` — max, not a mean, because a run alternating 1s evals with 20-minute optimizer calls has a small mean and a mean-based bar would fire during every optimizer call. So the run that sets the bar is the run judged by it, and it only ever rises. `CAPEVOLVE_STALL_SECONDS` pins a fixed number for a workload the user knows better than the heuristic does. Liveness needs proof, so `cap-evolve run` writes a small `run.pid` (`{pid, host, started}`) into the run dir and never deletes it: after the process exits the pid stops existing, and that absence is what separates "dead" from "alive but quiet". A pid from another host, or no pid file at all (the per-phase skill chain has no single owner), reads as *unknown* and is never reported crashed. `done` outranks everything, so a finished run degrades to a clean `done` however long ago it ran. - `cap-evolve tail` exits 4 on a stall and 5 on a crash and prints the verdict with its numbers on stderr, instead of a silence that reads like success. `--no-stall-check` opts out; `--idle-timeout` now bounds only the wait for the FIRST event. - `run --follow` warns once when the run goes quieter than its own pace and re-arms when progress resumes — it warns rather than stopping, because whether a wedged phase is worth killing is the user's call. - The SSE route no longer drops the connection on a fixed idle period: it periodically emits a typed `status` frame naming which kind of quiet the run is in (doubling as the keepalive) and closes only on a proven crash — never as `done`, which means sealed. - `liveness` is computed per request, deliberately outside `reduce_run`: that reducer is cached on the run's on-disk stamp (#119), and "how long has this run been silent" is the one fact that changes while nothing on disk does. 37 new tests (21 core + 13 dashboard backend + 13 frontend), including the negative case that matters most: a 20-minute-per-step run quiet for 25 minutes stays `live` on every surface, where the old fixed rule called it hung.
Caught by the real end-to-end evidence: for a run whose log carried `finalize` but whose final.json/splits.json lagged, `liveness.status` said `done` while `_status` still said `live` — the two surfaces disagreeing about the same run dir, which is the exact failure this issue exists to remove. `test_sealed`/`test_reward` and the `finalize` event are the same fact seen through artifacts vs the log; accept either.
|
|
||
| import json | ||
| import os | ||
| import sys |
| for usd_key, tok_key in pairs: | ||
| try: | ||
| totals["usd"] = totals.get("usd", 0.0) + float(ev.get(usd_key) or 0.0) | ||
| except (TypeError, ValueError): |
| pass | ||
| try: | ||
| totals["tokens"] = totals.get("tokens", 0) + int(ev.get(tok_key) or 0) | ||
| except (TypeError, ValueError): |
| fixed = float(override) | ||
| if fixed > 0: | ||
| return fixed | ||
| except ValueError: |
| """A run whose log says `finalize` but whose final.json/splits.json lag must still | ||
| read `done` — otherwise the hub says `live` while `cap-evolve tail` says `done`.""" | ||
| from capevolve_dashboard import runs | ||
| rd = make_run("run_a", events=BASE_EVENTS + [{"t": time.time(), "kind": "finalize", |
🔬 EvidenceEvery command below was run in a clean worktree at 1. Baseline before this PR (main + #191)2. Full core suite with this PR217 → 238 (+21), 0 failed. 3. The new core module, test by test4. The new dashboard-backend module, test by test5. Full dashboard-backend suite (42 before → 56)6. compileall7. Frontend —
|
|
❌ Automatic Labeling Failed An error occurred while trying to automatically label this pull request. Please check the workflow logs for details and add labels manually. |
🔍 Review — PR #218CHANGES REQUESTED The design is right — deriving the bar from the run's own pace beats a constant, and the Base established: #191 ( Blocking1.
Reproduced against a run dir whose Swept against elapsed time in the first step (all with the owner alive, all healthy): Consequence: exactly the false positive the PR description says is the worst outcome, on the Fix: fold the open gap into the estimate — 2.
This is reachable: the per-phase skill chain ( Consequence: Fix: if facts.get("alive") is False and (facts.get("silence") or 0) > (facts.get("threshold") or STALL_FLOOR_SECONDS):And separately: compare the recorded 3.
A run whose seed eval blows up (adapter raises → no candidates) and whose process then dies hits 4.
Same shape with a finite timeout, where it degrades to the old ambiguous answer instead of the Consequence: the crash verdict — the headline feature — is only available when the caller Non-blocking5. Every browser tab left open on a completed run holds a connection emitting 720 6.
7. That happens to be correct here, but the two quantities come from different clocks ( 8. Verdict: acceptable as a first cut, given the false-positive asymmetry — 60 minutes late is 9. Test coverage — the false-positive direction is untested in exactly the shape that 10.
Nits11. 12. 13. False-positive probesOwner process genuinely alive (
Two ❌ classes, both false-positive: the first-slow-step / resume family (#1) and the stale Live That one-poll PID liveness audit
Do the surfaces actually agree?Three real run dirs, produced by This PR alone:
So the surfaces agree with each other — including on the false positive, which is the point: Merged tree with #204 (conflict in The Two status models, #218 vs #204: consistent, not contradictory. Old cached Unknown named SSE frames are silently dropped by Merge-order note
Verification I re-ran238 / 56 / 53 / Merged with #194: Merged with #204 (one conflict, resolved): Real e2e (a) completed run: Real e2e (b) SIGKILLed run: Real e2e (c) slow-but-live run — did not reproduce as claimed; see blocking #1. Your
and the same dir with only fast gaps falls to the floor and trips, which is blocking #1 again, Security (#15/#209): clean. |
A false `stalled`/`crashed` gets a working, money-spending run killed, so both directions the review found are fixed at the root rather than at the callers. 1. The derived bar maxes over COMPLETED gaps, so a healthy run in its FIRST slow step had only its sub-second opening burst to learn from, fell to the 300s floor, and reported `stalled` with its owner alive in `ps`. Guaranteed for any run whose first optimizer call exceeds five minutes, i.e. τ²-bench-shaped. Folding the open gap into the bar cannot work — the bar is what that silence is compared against, so slack >= 1 makes `stalled` unreachable forever and slack < 1 collapses onto the floor (pinned by a test). The uninformed case gets a conservative prior instead: STALL_FLOOR_SECONDS 300s -> 3600s, the same slack applied to the slowest plausible unobserved step. `crashed` needs proof, not silence, so the case that most needs a fast answer is unaffected. 2. `started` was written and never read, so a stale dead `run.pid` in a reused dir condemned a live writer: `crashed` at silence=0.0s. Now `classify` requires corroborating silence before ever saying `crashed`, and `_pid_alive` compares the marker's `started` against the process's real start time (`ps -o lstart=`, no new dependency) so a reused pid is caught too. 3. The hub's zero-candidate `failed` branch moved BELOW the liveness verdict: a dead run with no candidates read `failed` on the hub and `crashed` in the DeepDive. One run, one word. 4. `tail` ran no liveness probe while `last is None`, so `--idle-timeout 0` hung forever on a provably dead run and a finite timeout gave the old exit 3 rather than 5. `crashed` is proof-based and no longer gated on having seen an event; `stalled` still is, since a run may not have started talking yet. Also: liveness_facts now folds only NEW bytes into the previous scan, so the SSE route's 5s probe costs 0.016ms instead of re-parsing the whole log (119ms on a 5.7MB/50k-event log, 720x/hour/connection); named the two probe intervals; documented that exit 0 means "finished OR still working" and that the CAPEVOLVE_STALL_SECONDS pin does not suppress `crashed`; noted the mtime/`t` clock-skew assumption. Tests 238 -> 247: the first-slow-step, stale-marker, pid-reuse, zombie, legacy-marker, --idle-timeout 0, and no-`--from-start` crash paths, plus a hub/DeepDive agreement test on the zero-candidate dead-process shape. The marker test now checks the marker's LOCATION through _owner_alive instead of only grepping cli.py.
🔧 Review fixesAll 4 blocking findings fixed, all 9 non-blocking addressed or declined with a reason. One correction up front, because it changed the shape of fix #1: the suggested fix for With slack ≥ 1 the bar outruns the silence forever and False-positive probesRebuilt from scratch with no pre-seeded completed gaps — that pre-seeding is exactly
The same sweep against the pre-fix code, so the regression is documented rather than 9/18 → 18/18. Both ❌ classes you identified are closed, and probe M (the safe-direction
Previously this exact dir gave 1. Blocking — first slow step reported
|
…ll-clock rate (#138 review) Three evidence-header honesty defects from the #234 review, all fixed at the layer that owns the fact rather than at the renderer. 1. `✓ Implement & check` claimed the hard gate passed on no evidence. The `check` phase lit off `target_profile` — logged by the ALGORITHM runner, AFTER baseline, only when a target model is configured — so any `--target-model` run rendered a green tick over the gate that guards all spend. `seed_dir_created` was no better: it fires inside `harness.baseline`, and only when the seed dir is missing. `cap-evolve run` now logs `check_gate` (ok, problems) from the gate itself, and that is the only kind the phase accepts. Silence about the hard gate reads `unknown` — never `done`, never `skipped`, because unlike `intake` there is no legitimate path that skips it. Proven on a real `--target-model` run: with `check_gate` -> done; with it stripped, `target_profile` alone -> unknown (that same log rendered `done` before). 2. The events-only burn understated GEPA 3.9x — $0.28 against a true $1.09. Fixed at the EVENT SOURCE, not the dashboard, because #191's `--follow` meter and every future consumer read the same events. `minibatch` now carries `cost_usd`/`tokens` (GEPA's rollouts never pass through `evaluate`, the only other runner-spend event), and `gepa_local_gate` carries `opt_cost_usd`/`opt_tokens` — the local gate, not `gepa_val_gate`, because the optimizer is paid every iteration while the val gate only fires on the ones that pass, so keying off it would still lose every locally-rejected iteration's spend. `accrue_totals`' elif-chain became one `_SPEND_SOURCES` table where each kind appears exactly once, which is what keeps a dollar counted once. On the real logs, re-priced per each algorithm's own `update_spent` calls: GEPA $0.36 -> $1.56 == Spent (was 0.23x); hill-climb and skillopt unchanged at MATCH. 3. The live rate divided by the event span, not wall clock. `last_t - first_t` freezes the instant the log goes quiet, so a run 58 minutes into one slow step reported 30x the honest $/min — the same class as the `$18.69/min` already fixed, surviving in the live branch. The denominator is now `now - first_t`, and the rate is suppressed once the log has been silent past `_RATE_STALE_SECONDS`: a quiet log supports no recent-burn claim at all. Verified: the 30x case -> None; a live run with a current log still gets a rate, off wall clock (the span would have claimed 1.5x more). Swept every rate/percentage/average denominator — all eight edge cases yield None or a guarded value, including a backwards clock and out-of-order timestamps. Merged-header contradiction (#218 + #221 + this). A phase must not read as *currently active* when liveness says the run is dead or wedged: that is where the run STOPPED, not what is running. `derive_pipeline` takes `liveness` and renders the latest phase `interrupted` for crashed/stalled, and `EvidenceHeader` takes the same value the StatusBadge beside it renders, so the two cannot disagree. `aria-current="step"` goes with it — it claims "this is where you are". Verified on the merged tree with #218's own `classify`: no contradictory pair in any of its four states. #221's plateau is left out on purpose: "live and plateaued" is coherent, "live and crashed" is not. Non-blocking + nits: * An errored phase can no longer render as `skipped` or `done`. `skipped` says "legitimately not run" and `done` says "completed"; a phase whose only evidence is failure is neither, so it reads `errored`. A `check_gate` attesting its own FAILURE is likewise not evidence of a pass. * Dropped the three dead `_PHASE_KINDS` entries (`algorithm`, `diagnose`, and the misattributed `target_profile`); a test now asserts every remaining kind is really emitted in core/ and that no kind is claimed by two phases. * `metric_direction` deleted, not rewired: it was a hardcoded constant whose `lower_is_better` branch nothing could reach, with a frontend test asserting a value the backend cannot produce. Net deletion across four files; the renderers state the constant. * Declined: a shared 1s tick for `useSecondsSince` (cosmetic, one interval per header). #194's reduce cache is not in this tree, so its `state.json` coupling is contingent on that merge — documented at the call site, and the rate can only ever decay to `None` as a run goes quiet, never grow into a fabricated figure. Two claims corrected from the previous commit message: the naive-sum overstatement is 1.26x, not "~2x" (the 2x figure is #191's different arithmetic), and the three-way $0.8100 equality holds for hill-climb only — it is exactly the generalisation to GEPA that finding 2 was. Tests: +9 core (burn == Spent for EVERY algorithm, the emitter contract, optimizer spend on locally-rejected GEPA iterations, check-phase evidence, the stale-rate 30x case, dead run -> interrupted, errored != skipped, backwards clock, kind-table drift), +4 frontend. 235 core (1 pre-existing #200 port-7878 flake, fails identically on b35e390), 42 backend, 65 frontend, tsc clean, compileall clean. dist/ untouched (#188).
Closes #118
Built directly on #191 (issue #116), which landed the shared event tail specifically for this:
follow_events(..., idle_timeout=None)left the stall threshold for me to define, and the typed{"kind": FOLLOW_END, "reason": ...}sentinel already distinguishes finished from went quiet from stopped. This PR turns that distinction into a named, surfaced state.Before → After
Before. A hung run masqueraded as finished. The SSE stream closed after a fixed ~5 idle minutes (
app.py:116) and the UI flipped to "idle" — which reads like completion, not a hang. And_status(runs.py:43-51) was coarse enough that a run which produced one candidate and then crashed showedliveforever.After. Every surface reports one of four states, from one classifier:
livestalledcrasheddonefinalizesealed the test — terminal, nothing downgrades itDesign decision 1: the threshold, and why it won't false-alarm
A fixed 5-minute idle timeout is wrong in both directions. A toy run is silent that long only if it is dead; one τ²-bench rollout with 50 tool calls can legitimately take 20 minutes. And the two errors are not symmetric: a false "hung" is worse than no signal at all, because the user's reaction to "hung" is to kill a run that was working — and that run cost money.
So the expectation is derived from the same run:
Three deliberate choices:
max, not a mean or a quantile. A run alternating 1s evals with 20-minute optimizer calls has a mean of a couple of minutes — a mean-based bar would fire during every optimizer call. The slowest thing the run has already done is the only defensible estimate of the slowest thing it might do next.Configurable:
CAPEVOLVE_STALL_SECONDS=Npins a fixed number for a user who knows their workload better than the heuristic does;cap-evolve tail --no-stall-checkopts out entirely.One subtlety worth naming:
tailwithout--from-startprints only new events, but the bar is derived from the whole log — otherwise attaching mid-run to a 20-min-per-step run would see no gaps at all, fall back to the 300s floor, and report a healthy run hung. That istest_tail_attaching_mid_run_uses_the_whole_log_not_just_what_it_streamed.Design decision 2: liveness — is the process gone, or just quiet?
In an append-only log a dead run and a slow run look identical, so the log alone cannot answer it. There was no liveness signal, so this PR adds the cheapest possible one:
cap-evolve runwrites a smallrun.pid({pid, host, started}) into the run dir — one write, once — and never deletes it. Once the process exits, its pid stops existing, and that absence is the signal. Deleting the marker on exit would erase the evidence.Liveness is deliberately three-valued, and only a definite "this pid is gone" yields
crashed:False→crashedPermissionError: owned by another user) →TrueNone(unknown) — a pid recorded on another host (shared filesystem), an unparseable marker, or no marker at all (the per-phase/cap-evolve:baseline… skill chain has no single long-lived owner). Never reported crashed; can still be reported stalled.No heartbeat event was added: it would mean touching the harness and every algorithm's hot loop, and
run.pid+ the events file's own mtime answers the same question for free. (ponytail:pid-only liveness could in principle hit a recycled pid — needs ~32k intervening spawns and the same host, and the failure direction is the safe one: a dead run looks quiet, not a live run looking dead. Upgrade path is a pid+start-time pair, noted in the code.)Silence is measured from the events file's mtime, not from the last event's
t:tis wall-clock recorded by the writer and can be skewed or malformed (log_eventserialises withdefault=str), while mtime is the filesystem's own answer to "when did this run last make a noise".Design decision 3: what the dashboard shows, and finished runs
GET /api/runs/{id}both carrystatusplus alivenessobject (silence_seconds,stall_threshold_seconds,slowest_gap_seconds,process_alive, and a one-sentencedetail). Same key, same computation, same function — so the two payloads cannot disagree.StatusBadgegainsstalled(amber triangle) andcrashed(red plug); color is never the sole signal (icon + label always), and thedetailsentence is the accessibletitle, because a user deciding whether to kill a run needs the bar, not just the word.statusframe naming which kind of quiet the run is in — which doubles as the keepalive, so an idle proxy has traffic to see — and closes only on a proven crash. Never asdone:donemeans sealed. The old ambiguousidleframe is gone.doneoutranks both stall and crash, so a run finalized 30 days ago whose process is long gone reads a cleandone, notcrashed. Tested explicitly.livenessis computed per request, outsidereduce_run— deliberately. That reducer is cached on the run's on-disk stamp (#119 / PR #194), and "how long has this run been silent" is precisely the one fact that changes while nothing on disk changes; a cached answer would be permanently0s. This is also how the change composes with #194: it adds no field to the cached reduction and touches neither_reducenor the cache key.A bug the real evidence caught: for a run whose log carried
finalizebut whosefinal.json/splits.jsonlagged,livenesssaiddonewhile_statusstill saidlive— the two surfaces disagreeing about the same run dir, which is the exact failure this issue exists to remove._statusnow accepts either the sealed artifacts or thefinalizeevent; they are the same fact seen through the log vs the artifacts (second commit).Verification
Real end-to-end, zero API cost (
examples/toy_calc+mockoptimizer)(a) A run that completes →
done. Realcap-evolve run --follow, thentailon the finished dir:(b) A run SIGKILLed mid-flight →
crashed. The run process (and its tree) iskill -9ed after baseline + one accepted candidate; nofinalizein the log:(c) A deliberately SLOW run → stays
working. A live run with real 150-second steps, then 380s of genuine silence — past the old 300s rule — before finalizing. Sampled every 30s against both rules:This is the money row. The old fixed rule would have called this run hung — twice — and it went on to finish successfully. The live
tailattached to it, verbatim:Note the threshold tracking the run:
450swhile its worst gap was 150s,1140sonce it had demonstrated a 380s gap. The bar rose because the run earned it.The surfaces agree — same three run dirs, both surfaces
Terminal, on the same three dirs:
done(exit 0) /CRASHED(exit 5) /done(exit 0). Dashboarddone / crashed / done= terminaldone / crashed / done.Suites
Baseline on this branch's base (main + #191) is 217 → +21, 0 failed.
(42 before → +14.)
Frontend (CI never runs vitest — #207 — so run locally):
dashboard/frontend/dist/is not committed, per epic #127's policy (#188 rebuilds it once after the frontend PRs land).The tests that matter
test_a_slow_but_healthy_run_is_never_called_hungsilence > 300syetlive; and it does fire at 4× its own gaptest_a_slow_but_healthy_run_is_not_reported_stalledtest_tail_does_not_stall_out_a_slow_but_healthy_runtest_tail_attaching_mid_run_uses_the_whole_log_not_just_what_it_streamed--from-startmust not fall back to the floortest_a_toy_run_still_gets_the_five_minute_floortest_threshold_uses_the_slowest_gap_not_the_meanmax, not a meantest_a_finalized_run_is_done_even_when_ancient_and_processlessdonetest_a_pid_from_another_host_is_unknown_not_dead/test_no_pid_file_means_unknown_never_crashedcrashedrequires prooftest_stream_sends_a_status_frame_naming_the_stallidleclose is gone; a stall is never adoneframetest_a_finalize_event_alone_is_enough_to_report_donetest_dashboard_classifies_through_the_shared_helper_not_its_own_ruleExpected merge order
--followandcap-evolve tail#191 (issue Classic cap-evolve run is silent for its entire duration — add --follow / cap-evolve tail #116) — this branch is built on it;eventstream.pymust land first. (This branch =origin/main+ feat(observability): live terminal progress via--followandcap-evolve tail#191 + these two commits, so a merge after feat(observability): live terminal progress via--followandcap-evolve tail#191 is a clean fast-forward-shaped diff.)livenessdeliberately stays out of the cachedreduce_run; no shared line inruns.pybeyond thelist_runssignature, and no overlap inapp.pypast thesnapshotframe). Either order works; after perf(dashboard): memoize reduce_run on events mtime+size, drop dead SSE snapshot, paginate runs/rollouts #194 the SSEsnapshotframe carries only{run_id}, which this PR does not depend on.eventstream; no conflict with the newclassify/liveness_factssurface.dist/once, after the frontend PRs.House rules
Zero new runtime deps in core (
eventstream.pyadditions usejson,os,socket,time,pathlibonly). New tests incore/tests/(+ the dashboard's owntests/).harness.pyuntouched: the run already logged everything needed, which is why the diff is small.