fix(reporting): make the session's own record match what happened - #1178
Conversation
A concurrency sweep with no optimization to compare returns succeeded with was_skipped set: correct as a status, wrong as a verdict. The journal read the status and recorded KEEP, so the session's own record claimed a step it never took, and the timeline showed no cause because a skip states it under skip_reason rather than reason. Skips now settle as no_promote ahead of both the per-status and the promotable rules, and the timeline falls back to skip_reason. Co-authored-by: Cursor <cursoragent@cursor.com>
conc_sweep_done is the SWEEP exit for any sweep that reached a terminal result, a skip included, so the final report told the reader a "post-sweep concurrency sweep finished" on runs where none happened. The exit now records the skip and its reason as evidence, and the report names it instead of reusing the generic wording. Co-authored-by: Cursor <cursoragent@cursor.com>
…vage The double-run baseline evaluates accuracy only in the warmup round and decides on the measured round, which therefore has no accuracy of its own. Reading the warmup's score there is the design, but it logged as "salvaged ... from a sibling attempt" at WARNING, so every healthy baseline looked like it had survived a fault and the log gave triage no way to find the runs where a score really did go missing. That one case now logs at INFO under the cold-start guard's own name; every other salvage keeps the warning. Co-authored-by: Cursor <cursoragent@cursor.com>
…tamps session_meta read elapsed_minutes off the resolved session section, but two producers fill that section and only the collector writes the key. A live-recorded run therefore exported session_duration_seconds=0 after hours of work, and every downstream rate derived from it was wrong. The duration is now computed from start to end, with the recorded elapsed_minutes kept as the last resort. Co-authored-by: Cursor <cursoragent@cursor.com>
|
Blocking items only, verified at PR head. The four diagnoses are all correct — a skip really was recorded as 1. "did not run" is false for the sweep that ran out of budget
if budget_limited_no_pair:
payload["was_skipped"] = True
payload["skip_reason"] = "budget_exhausted_no_successful_pairs"The report reads if reason == "conc_sweep_done" and text:
skip_reason = _conc_sweep_skip_reason(state)
if skip_reason:
return f"Post-sweep concurrency sweep did not run ({skip_reason}); the phase settled and the run closed."
return textSo a session that burned its entire sweep budget on variants is reported as one where the sweep "did not run". That is a different false statement rather than a fix, and under a time-budget investigation it is the more expensive one to believe. This one gets worse with #1171 in: that PR enforces the sweep/grid budget, which drives 2. Re-classifying a skip as
|
Measuring the duration from the session's own timestamps replaced a stable zero with a moving number: a run that had already stopped was still measured up to now(), so a session from ten weeks ago exported as ten weeks and grew with every re-export. A plausible-looking duration is worse than the zero it replaced, because zero is visibly missing data. Only a session that is still running may be measured against the export clock now. One that carries a stop reason but no end timestamp falls back to elapsed_minutes, or to zero, and stays there. That end timestamp was missing because nobody recorded it: the recorder's session snapshot wrote a start and a stop reason but no end, and a recorder fragment replaces the collector's section wholesale. SharedState stamps stop_ts whenever a stop reason is written, so the end of the run is the Coordinator's final write in its finally block rather than CLOSE's early one on entry or the reader's clock; ordinary saves leave it alone. Both producers of the session section now report it. Co-authored-by: Cursor <cursoragent@cursor.com>
CI E2E report — ✅ Succeeded
|
…o run was_skipped marks two different conc_sweep outcomes: the pre-flight envelope, which declines before a server boots, and a sweep that ran its whole ladder and exhausted its budget without a comparable pair. The stop-reason explanation keyed on the flag alone, so the second was reported as a sweep that "did not run" — a different false statement, and the more expensive one to believe in exactly the sessions where the time budget is what is under investigation. Only the budget path can set budget_exhausted, so the two separate without reading skip_reason. The predicate lives next to the producers in conc_sweep.py, and the report names each outcome for what it was. Co-authored-by: Cursor <cursoragent@cursor.com>
Recording a conc_sweep skip as no_promote put it in front of the trajectory reviewer, which harvests REVERT and no_promote as evidence that a direction is exhausted. Both cluster keys are deterministic for a skip, so the two benign skips an ordinary session produces (no_optimization_to_compare, no_validated_gain_since_last_conc_sweep) were enough to advise the model to abandon conc_sweep entirely. OUTCOME_SKIP says what happened without claiming a measurement. The consumers: the trajectory reviewer ignores it (nothing was learned), the KB fact write already declines it (no gain, no pitfall severity), and the breakdown timeline, decision trace and Langfuse score carry it through as its own category. The guard is now scoped to the kinds that can actually declare was_skipped, so reusing that key on a patch kind cannot rewrite a kept patch into a non-KEEP. Co-authored-by: Cursor <cursoragent@cursor.com>
Measuring the duration from the session timestamps fixed the machine field, but session.elapsed_minutes -- the key the rendered report prints and the cross-section reads -- is written only by the collector, and the recorder fragment replaced that section wholesale. A live-recorded run therefore still printed elapsed=0min, and lost the image, host and pid the manifest resolves and the live state cannot know. The fragment now overlays the collected section instead of replacing it, and the elapsed minutes are recomputed from whichever timestamps won, so the human-readable field and session_duration_seconds measure the same window by construction. Resume semantics, previously undefined: elapsed_minutes measures the current leg from state.start_ts, the same anchor --max-hours is counted against, so the number stays comparable with max_minutes instead of including the dead time before a resume. The manifest's created_at_utc is exported alongside it and still names the first launch, so the gap remains visible. Both producers now carry start_ts and the collector falls back to created_at_utc only for a session that never recorded one. Co-authored-by: Cursor <cursoragent@cursor.com>
The double-run handoff was already excluded from the log line, but nonfatal_warnings still recorded baseline_accuracy_salvaged_from_sibling_attempt on every healthy double-run baseline, where reading the warmup round's accuracy is how the measured round is meant to get it. The structured channel feeds the report and the specialists, so it deserves the same treatment as the log: a run that hit no fault should not carry a warning saying it recovered from one. No consumer keys on this particular marker; the failure scanners that read nonfatal_warnings look for eval-failure markers instead. Co-authored-by: Cursor <cursoragent@cursor.com>
…s CLOSE The CLOSE fallback recovers a terminal reason for a session whose stop_reason never reached state.json, but it read the whole of phase_history. A resume clears state.stop_reason and stop_ts and cannot clear the previous leg's CLOSE row, so a running session was exported as having stopped days earlier for the reason it stopped last time, with ended_at_utc stamped from that old transition. The end then predated the start, and the guard that refuses a negative duration turned the report into elapsed=0min -- the same "0min" this PR set out to remove, reached by a different route. The scoping lives in the extractor rather than in _should_use_close_stop_reason, because the timestamp is stamped as the session's end even when the reason is not adopted, so the predicate alone would leave that second path reading the old leg. The extractor now answers for the current leg only and the predicate stays what its name says: a comparison of two reasons. The leg boundary is state.start_ts, the same anchor elapsed_minutes is measured from, so the two definitions cannot drift apart. Only two parseable timestamps can disqualify a row: a missing or unparseable one leaves the CLOSE in force, since a session that never recorded a start is the case the fallback was built for. The recorder path reads the live state's own stop_reason and so never resurrects one, but its snapshot carries an empty reason, which the export merge treats as absence of evidence -- the collector's value won there too, so fixing the collector fixes both paths. Co-authored-by: Cursor <cursoragent@cursor.com>
|
All three blocking items and the non-blocking one are fixed, and reviewing your item 3 turned up one more instance of the same class. One deliberate refusal is flagged below. 1. A sweep that spent its budget is not one that declined to run —
|
![github-advanced-security[bot]](https://avatars.githubusercontent.com/in/57789?s=60&v=4){kind=small}
stop_ts is the timestamp half of stop_reason, written by the same setter, but only the reason was registered as Coordinator-owned. Since apply_changes is a denylist, an update_state intent had its stop_reason rejected and its stop_ts accepted -- the one path where the recorded reason and the recorded end can disagree, which is the invariant the pair exists to hold. Co-authored-by: Cursor <cursoragent@cursor.com>
_commit_stop_reason re-stamped on every call, and coordinator.py's finally block re-asserts the reason CLOSE already wrote. CLOSE ships session_breakdown.json in between, so the artifact an operator reads and any later re-export disagreed about ended_at_utc and elapsed_minutes. The first terminal reason is when the session ended; later writes may still refine the reason. Co-authored-by: Cursor <cursoragent@cursor.com>
… began cf19442 disqualifies a CLOSE transition that predates start_ts, but a resume only re-anchors start_ts after a crash or a stop with a recorded reason. A clean stop keeps it, so the previous leg's CLOSE still sat inside the window: a session running for three hours exported as stopped, for the reason it stopped last time, with an end time in the past and less than half its real elapsed time. The state file had no record of where the current leg began, so resumed_ts now stamps it on both branches and the collector measures the leg from the later of the two. A session that was never resumed still recovers its reason and end from its CLOSE. Co-authored-by: Cursor <cursoragent@cursor.com>
Four places claimed a resume resets start_ts. Only the crash / recorded- stop branch does; a clean stop deliberately keeps it so --max-hours is still counted from the original session start, and on that branch elapsed_minutes spans the dead time the docstring said it excluded. The value is right either way -- it tracks the anchor the budget is charged against -- so this is what we tell the reader, not what we compute. Co-authored-by: Cursor <cursoragent@cursor.com>
iso_z assumes UTC for a naive timestamp and to_unix assumed the host's local time, and both now feed the same comparisons: the measured session duration and the CLOSE-transition boundary. Under a non-UTC TZ the same string placed the session at two different instants, which would let a stale CLOSE through the boundary check. Not reachable today -- every producer writes an offset -- but the check now rests on it. Co-authored-by: Cursor <cursoragent@cursor.com>
was_skipped covers both a sweep that declined before booting a server and one that spent its whole budget without a comparable pair, which is the ambiguity conc_sweep_declined_to_run exists to resolve; the exit evidence copied the flag without the budget_exhausted that separates them. The report's budget-skip test now builds last_conc_sweep through record_conc_sweep and a save/load round trip, so it proves the flag it reads survives persistence rather than assuming the shape by hand. Co-authored-by: Cursor <cursoragent@cursor.com>
Four narrow ones, all in what the exported session section claims: - A disqualified CLOSE row ended the scan instead of continuing it, so a phase_history written out of order lost the fallback entirely. - An unparseable stop_ts landed in ended_at_utc verbatim and collapsed the duration to zero, where the CLOSE transition or the export clock still answers. - The recorder writes every session key on every save, so an unset max_minutes arrives as 0 and overwrote the collector's value; phase, which only the recorder knows, vanished from the section when blank. - session_elapsed_minutes claimed it cannot drift from session_meta.session_duration_seconds. The two measure the same window from the same fields, which is a weaker and truthful guarantee. test_a_recorded_session_exports_the_time_it_actually_ran passed with the pin reverted, because a session that stops in a unit test stops now. It now stops three days before the export. Co-authored-by: Cursor <cursoragent@cursor.com>
``phase_started_unix`` is only rewritten by ``record_phase_transition``, and exiting the process is not a transition. The entry it stamps therefore spans both run legs, so a session resumed days later charges the whole idle gap to whichever phase it stopped in: a three-hour session resumed after three days reads 259200s spent in PRELUDE against a 4320s ceiling, and every optional arm bounded by that figure is silently dropped before the leg does any work. Floor the live segment at the current leg's boundary (``resumed_ts``) instead of re-stamping ``phase_started_unix`` on resume. The recorded facts stay true — the phase really was entered when ``phase_started_ts`` says, and that stamp stays equal to the last ``phase_history`` row — while every reader derives the right number. It also repairs sessions already resumed by older code, and needs no ``stop_ts``, which the crash branch never writes. The floor is self-limiting: the next entry stamps a later ``phase_started_unix``. Dropping the gap alone would make the previous leg's real work free, and a session that stopped and resumed repeatedly could re-spend a phase's whole share every time. So a resume also banks the segment the stopped leg never transitioned out of, using ``stop_ts`` as its end — the only recorded evidence of when that leg finished. Without it (a clean stop or a crash writes none) the segment stays unbanked, under-charging the phase, which is the direction ``phase_cumulative_seconds`` documents as tolerable since over-charging ends a phase early. Banking runs before ``resumed_ts`` is restamped, so two resumes in the same phase bank one segment each. The phase clock moves on both resume branches. It answers a different question from ``start_ts`` — which phase spent what, not when the budget started — and neither answer includes time nothing was running, so the branch that keeps ``start_ts`` gets the same treatment. Banking is now one write-owner, ``bank_phase_segment``, shared by the transition path and the resume path so the per-phase totals and the EXPLORE accumulator cannot drift apart. Co-authored-by: Cursor <cursoragent@cursor.com>
``stop_ts`` bounds the segment a resume banks for the leg that stopped, and it was floored at zero but never clamped to now. A stamp ten days after ``phase_started_unix`` would bank 864000s in one call — the over-charge direction both this helper and ``bank_phase_segment`` document as the one that must not happen, since over-charging ends a phase early. Nothing reaches it today: ``stop_ts`` only ever comes from ``_now_iso()``, and the branch that could carry a stale one clears it. Clamping makes the safe-direction claim structural rather than incidental. The second-resume test built its second leg from a ``stop_ts`` an hour in the future, which is the shape the clamp rejects; it now pins both legs in the past. Co-authored-by: Cursor <cursoragent@cursor.com>
Flooring the live segment at the leg boundary left three notes overstating what the phase clock promises. The charge-back note claimed ``session_remaining`` and ``phase_elapsed`` sum to a constant across the phase. That holds within a run leg only: a resume keeping ``start_ts`` leaves the session charged for the idle gap while the phase is not, so the sum — and the base the phase charges back against — drops by the gap. The smaller base is the honest one and stays, so the comment is what changes, and a test pins the base a kept anchor produces. ``phase_elapsed_totals`` names its writer, which is ``bank_phase_segment`` for both the transition and the resume path. ``bank_phase_segment`` sits under a block comment promising a ``SharedState`` forwarding shim it has never had. Those shims exist so call sites written when the functions were methods keep working; a helper born in this module with two callers needs none, and adding one would put another mutating method on a class the same convention calls a passive persisted record. Say that instead, and file the export under b. ``phase_elapsed_totals_from_history`` claimed to rebuild a LOWER bound. Two history rows either side of a process exit bound a "segment" that includes the idle gap and charge it to the phase named before the boundary, so across a resume the rebuild over-charges: 261120s reconstructed where 1920s was spent. The live half of that is exactly what the floor fixes, but the rebuild cannot see a leg boundary because ``phase_history`` records none, and only the legacy migration path reads it — so this corrects the claim, not the arithmetic. Co-authored-by: Cursor <cursoragent@cursor.com>
kernel.conc_sweep already imports the grid runner in this package, so a module-level import from report.py is the edge CodeQL reports as a cycle. The helper is only used in _explain_conc_sweep_skip. Co-authored-by: Cursor <cursoragent@cursor.com>
Co-authored-by: Cursor <cursoragent@cursor.com>
fix(reporting): make the session's own record match what happened
5 participants
Refs #1146.
Scoped to reporting honesty for #1146: the artefacts of the field session
hold four places where the record does not match what happened. Session hard
budget enforcement -- admission, in-flight cancellation, PRELUDE spend caps --
is #1171, not here. This PR does touch resume leg bookkeeping
(
bank_phase_segmenton resume) so phase elapsed totals and exported durationstay accurate across stop/resume, but it does not add or change deadline
enforcement.
The four mismatches are independent, and they share the same consequence:
whoever reads the record -- and the downstream analysis that depends on it --
concludes the opposite of what the session did.
A skip recorded as KEEP.
conc_sweepreturnsstatus=succeededwithwas_skipped=truewhen there is no optimization to compare against. Thestatus is right -- it did finish normally -- but the journal reads the status
and files it as
KEEP, so the session's own ledger gains an action thatnever happened. The timeline row does not show why either, because a skip
writes its cause to
skip_reasonrather thanreason.The final report says the sweep ran.
conc_sweep_doneis the reasonshared by every terminal exit of the SWEEP phase, "did not run at all"
included, so the report prints "Post-sweep concurrency sweep finished" in
sessions where it never started.
A healthy baseline looks like it just crawled out of a failure. The
double-round baseline measures accuracy only in the warmup round but decides
in the measure round, which by design has no accuracy of its own. Taking the
score from warmup is the designed path, yet it is logged as
WARNING: salvaged ... from a sibling attempt. Every normal baseline leavesa salvage warning behind, and the sessions that genuinely lost a score are
buried among them with no way to filter.
Exported session duration is always zero.
session_metareadselapsed_minutesfrom thesessionblock, but that block has two producers-- the live recorder's snapshot and the collector -- and only the latter
writes that key. A session that ran for over two hours exports as zero
seconds, and every downstream metric normalized by duration is distorted with
it.
Changes
was_skippedoutranks both the per-status rule and thepromotable rule, and classifies as
no_promote; the timeline's reason fallsback to
skip_reason.report says "did not run (cause)" on that basis. Sessions that did run read
exactly as before.
_is_double_run_accuracy_handoff()logs at INFO as a cold-startguard when, and only when, the decision is in the measure round and the score
came from warmup. Every other salvage still warns. Two
("warmup_round", "measure_round")literals are folded into a constant on theway.
for a session still running), with
elapsed_minutesdemoted to a last resort.restamping
resumed_ts, so stop/resume does not charge idle gap time to thephase the session stopped in.
Test plan
test_optimization_journal.py: a skip is no longer KEEP, and that ruleoutranks the per-status classification.
test_report.py: a skipped sweep is not described as finished, thewording for a sweep that did run is unchanged, and a skip with no recorded
cause still says so honestly.
test_baseline_eval_fallback.py: the designed warmup handoff is notreported as a salvage (no WARNING, signed as a cold-start guard), while a
cross-attempt salvage still warns.
test_breakdown_exporter_unit.py: duration from timestamps, a runningsession measured to now, fallback to
elapsed_minuteswithout timestamps,and zero when there is nothing to read.
Made with Cursor