diff --git a/README.md b/README.md index e9d4286c..2f7cc0ca 100644 --- a/README.md +++ b/README.md @@ -1655,6 +1655,33 @@ the current one and `final` supersedes them all. The partials exist because killed or times out is exactly the run whose startup timings you want, and it was precisely the one that left no trace of them at all. +### Skipped ticks — the usage-gate pause row (#160) + +A tick the weekly-budget pace gate pauses (usage-gate exit 10) still writes one +`stage: final` row, from the runner's exit-10 path over an empty trace: + +```json +"skipped": "usage-gate", "skipReason": "", "outcome": "skipped", "exitCode": 10 +``` + +`exitCode` is the GATE's 10, the same way the preflight-abort row records +preflight's 12 — the runner itself still exits 0 because a pause is not a +failure. Both skip fields are **absent** — not null — on every other row, so a +consumer keys on the field existing at all and pre-#160 records read unchanged. +Before this row existed a paused stretch left nothing in the file, and the +dashboard drew nine consecutive gated ticks as a dead cron. A config REFUSAL +(usage-gate exit 2) is NOT a skip: the tick aborts loudly and writes no row — +broken config must never render as pacing. + +### How the file reaches main + +The runners append rows and never push. The hourly `refresh-human-queue` cron +stages `metrics/runs.jsonl` beside the snapshot it already commits straight to +main, publishing when EITHER file moved. That cron carries it because it is +data-only and never usage-gated — the one committer still awake during a pause, +which is exactly when skip rows are written and nothing else runs. A skip row is +therefore visible to the dashboard within about an hour of its gated tick. + ### Live token spend — and the one number that is not knowable `run-metrics` reads tokens from the terminal `result` event, so a killed run diff --git a/campaign-run.sh b/campaign-run.sh index 72daefd9..abae3b66 100755 --- a/campaign-run.sh +++ b/campaign-run.sh @@ -87,14 +87,32 @@ fi # --- weekly-budget pace gate: skip this tick when usage is over the ceiling or inside the BAU # headroom band under the linear burn toward the reset — the crons hold ~USAGE_HEADROOM_PCT points # BEHIND pace so interactive work keeps standing budget (#158). `usage-gate` reads -# /api/oauth/usage itself; exit 10 means PAUSE (log it, exit 0). It is INERT when it cannot read -# usage and no fallback is set — it prints OK and we run. Any OTHER non-zero exit is a config -# REFUSAL (the retired USAGE_SLACK_PCT still set: exit 2, reason on stderr, captured into the -# log): the tick must not run on config the gate refused to read, so propagate the failure — a -# refusal is neither a run nor a pause. --- +# /api/oauth/usage itself; exit 10 means PAUSE (record one skip row, exit 0). It is INERT when it +# cannot read usage and no fallback is set — it prints OK and we run. Any OTHER non-zero exit is a +# config REFUSAL (the retired USAGE_SLACK_PCT still set: exit 2, reason on stderr, captured into +# the log): the tick must not run on config the gate refused to read, so propagate the failure — a +# refusal is neither a run nor a pause, and it writes NO row. --- _ug="$(pr-review-report usage-gate 2>&1)"; _ugrc=$? echo "$(date -u +%FT%TZ) usage-gate: $_ug" >> "$LOG" -[ "$_ugrc" -eq 10 ] && exit 0 +if [ "$_ugrc" -eq 10 ]; then + # A paused tick still writes its metrics/runs.jsonl row (#160): the dashboard reads runs from + # that file, and a pause that wrote nothing rendered as a dead stretch indistinguishable from a + # broken cron. Same shape as the preflight abort below — an empty trace, so the record's shape + # still comes from `run-metrics` and no second place knows what a runs.jsonl line looks like. + # The row records the GATE's exit 10 (as the preflight row records preflight's 12) plus the + # gate's own line, verbatim; this script still exits 0 because a pause is not a failure. The row + # reaches origin/main via the hourly refresh-human-queue cron, which stages this file — the one + # committer still awake during a pause. + TS="$(date -u +%Y%m%dT%H%M%SZ)" + RUNLOG="$RUNDIR/$TS.jsonl" + mkdir -p "$RUNDIR" "$DIR/metrics" + : > "$RUNLOG" + pr-review-report run-metrics "$RUNLOG" \ + --run-id "$TS" --role producer --model "$MODEL" --exit-code 10 \ + --skipped usage-gate --skip-reason "$_ug" \ + >> "$DIR/metrics/runs.jsonl" 2>/dev/null || true + exit 0 +fi if [ "$_ugrc" -ne 0 ]; then echo "$(date -u +%FT%TZ) campaign run ABORTED: usage-gate refused its config (exit $_ugrc) — fix cron.env" >> "$LOG" exit "$_ugrc" @@ -313,8 +331,9 @@ fi echo "$(date -u +%FT%TZ) campaign run END (exit=$rc, trace=$RUNLOG, err=$ERRLOG)" >> "$LOG" # Persist per-run metrics BEFORE the next run's rotation deletes this trace. -# Appends one enriched JSON line to metrics/runs.jsonl (committed periodically, -# never from here — the cron does not push). Best-effort: never fail the run on it. +# Appends one enriched JSON line to metrics/runs.jsonl (committed+pushed to main by the hourly +# refresh-human-queue cron, never from here — this cron does not push). Best-effort: never fail +# the run on it. # `run-metrics` emits the whole enriched record itself now, including `outcome` — which it derives # with the same typed classifier the fallback loop uses, so the metrics line and the fallback # decision can never disagree about whether a run was quota-limited. diff --git a/pr-review-report-rs/src/main.rs b/pr-review-report-rs/src/main.rs index 2d619578..1b24cebb 100644 --- a/pr-review-report-rs/src/main.rs +++ b/pr-review-report-rs/src/main.rs @@ -2678,6 +2678,7 @@ fn run_metrics_mode( exit_code: Option, preflight_missing: &[String], infra_path: Option<&str>, + skip: Option<(&str, &str)>, ) -> i32 { let content = match std::fs::read_to_string(path) { Ok(c) => c, @@ -2692,7 +2693,7 @@ fn run_metrics_mode( let outcome = exit_code.map(|rc| { ( rc, - classify_outcome(&content, rc, preflight_missing, &infra), + classify_outcome(&content, rc, skip.is_some(), preflight_missing, &infra), ) }); println!( @@ -2704,7 +2705,8 @@ fn run_metrics_mode( outcome, &tooling, preflight_missing, - &infra + &infra, + skip )) .unwrap() ); @@ -2715,6 +2717,7 @@ fn run_metrics_mode( /// outcome that only exist once the run has finished. Built here rather than inline in /// [`run_metrics_mode`] so the record's shape — `stage` above all — is a tested value, not a /// side effect of printing. +#[allow(clippy::too_many_arguments)] // one record, one assembly point — splitting it would put the row's shape in two places fn final_record( path: &str, m: &RunMetrics, @@ -2723,6 +2726,7 @@ fn final_record( tooling: &ToolingReport, preflight_missing: &[String], infra: &InfraRecord, + skip: Option<(&str, &str)>, ) -> Value { let mut doc = serde_json::json!({ "trace": path, @@ -2770,6 +2774,15 @@ fn final_record( obj.insert("exitCode".into(), serde_json::json!(rc)); obj.insert("outcome".into(), serde_json::json!(verdict.as_str())); } + // The SKIP stamp (#160): present on a skipped tick's row, ABSENT — not null — on every other, + // so a consumer can key on the field existing at all and every pre-skip record stays + // byte-compatible. `skipReason` is the gate's own output line, verbatim: the row is the only + // durable copy (the runner's log rotates with the box), and a paraphrase would be a second + // place that knows what the gate says. + if let (Some(obj), Some((gate, reason))) = (doc.as_object_mut(), skip) { + obj.insert("skipped".into(), serde_json::json!(gate)); + obj.insert("skipReason".into(), serde_json::json!(reason)); + } doc } @@ -3644,6 +3657,13 @@ enum TraceOutcome { /// `ai:blocked-infra` with an exit is that the fact must ACCUMULATE somewhere countable. One is /// noise; the same one across twenty runs is the signal a human acts on. InfraDown, + /// A pre-model gate SKIPPED the tick on purpose (#160): `usage-gate` said PAUSE, the model + /// never started, and the runner exited 0. Neither `ok` (nothing ran) nor `error` (nothing + /// failed) — before this variant a paused stretch left NO row at all, and the dashboard read + /// nine consecutive gated ticks as a dead cron. A config REFUSAL (usage-gate exit 2) is NOT + /// a skip: the runners abort loudly on it and write no row, and conflating the two would + /// dress broken config up as pacing. + Skipped, } impl TraceOutcome { @@ -3656,6 +3676,7 @@ impl TraceOutcome { TraceOutcome::ToolingFailure => "tooling-failure", TraceOutcome::Error => "error", TraceOutcome::InfraDown => "infra-down", + TraceOutcome::Skipped => "skipped", } } } @@ -3722,11 +3743,17 @@ fn classify_trace(trace: &str, exit_code: i32) -> TraceOutcome { TraceOutcome::Ok } -/// The whole run's outcome: what the trace says, plus what `preflight` found before the trace -/// existed. +/// The whole run's outcome: what the trace says, plus what the runner's pre-model gates found +/// before the trace existed. +/// +/// A SKIP (#160) outranks everything: `usage-gate` runs before preflight, before the lock, before +/// a token is spent, so a skipped tick has no trace, no preflight result and no infra record — +/// every other classification of it would be an artifact of the empty trace (an `exitCode` of 10 +/// over zero events reads as `error`, which is precisely the "dead cron" rendering the skip row +/// exists to correct). /// /// A preflight failure has no trace to classify — the model never ran — so the fact arrives as the -/// list of binaries that would not resolve. It outranks everything else: a run that was stopped +/// list of binaries that would not resolve. It outranks everything below: a run that was stopped /// before it started is neither quota-limited nor merely errored. /// /// An infra exit (#108) is folded in LAST and only over an otherwise-`ok` run. The ordering is @@ -3737,9 +3764,13 @@ fn classify_trace(trace: &str, exit_code: i32) -> TraceOutcome { fn classify_outcome( trace: &str, exit_code: i32, + skipped: bool, preflight_missing: &[String], infra: &InfraRecord, ) -> TraceOutcome { + if skipped { + return TraceOutcome::Skipped; + } if !preflight_missing.is_empty() { return TraceOutcome::ToolingFailure; } @@ -17874,6 +17905,16 @@ enum Cmd { /// line and makes the outcome `infra-down` rather than `ok` (#108). #[arg(long)] infra: Option, + /// The pre-model gate that SKIPPED this tick (`usage-gate` on a pause, #160). Present + /// means the model never started and the tick was a deliberate skip, not a failure: the + /// row carries `skipped` + `skipReason` and its outcome is `skipped`. A config REFUSAL + /// (usage-gate exit 2) is NOT a skip — the runners abort loudly on it and write no row. + #[arg(long, requires = "skip_reason")] + skipped: Option, + /// The gate's own output line, verbatim, recorded as `skipReason` beside `skipped` — + /// the two arrive together or not at all. + #[arg(long, requires = "skipped")] + skip_reason: Option, }, /// Resolve every external binary the HARNESS needs at read time. Exit 12 if any is missing. /// @@ -19706,6 +19747,8 @@ fn main() { exit_code, preflight_missing, infra, + skipped, + skip_reason, } => run_metrics_mode( &trace, &RunIdentity { @@ -19716,6 +19759,7 @@ fn main() { exit_code, &preflight_missing, infra.as_deref(), + skipped.as_deref().zip(skip_reason.as_deref()), ), Cmd::Preflight => preflight_mode(), Cmd::ClosurePreflight { flake } => closure_preflight_mode(&flake), @@ -21724,6 +21768,7 @@ mod startup_split_tests { &ToolingReport::default(), &[], &InfraRecord::default(), + None, ); assert_eq!(doc["stage"], STAGE_FINAL); assert_eq!(doc["bootMs"], 1125); @@ -21760,6 +21805,7 @@ mod startup_split_tests { &ToolingReport::default(), &[], &InfraRecord::default(), + None, ); assert!(doc.get("runId").is_none()); assert!(doc.get("role").is_none()); @@ -21769,6 +21815,113 @@ mod startup_split_tests { } } +/// The usage-gate SKIP row (#160). +/// +/// A paused tick used to leave NO runs.jsonl row at all, so the dashboard drew nine consecutive +/// gated ticks as a dead cron. These pin the row's contract — a sibling renderer is built against +/// exactly these fields — and the line between a SKIP (exit 10, row) and a config REFUSAL +/// (exit 2, loud abort, no row), which must not conflate. +#[cfg(test)] +mod skip_row_tests { + use super::{ + classify_outcome, final_record, InfraRecord, RunIdentity, RunMetrics, ToolingReport, + TraceOutcome, STAGE_FINAL, + }; + + /// The gate's real ceiling-pause line, verbatim — em-dash, percent signs and all — because the + /// contract is "the gate's own output line", not a normalization of it. + const PAUSE_LINE: &str = + "PAUSE: 91% of the weekly budget used (endpoint) — at/over the 90% ceiling"; + + fn id() -> RunIdentity<'static> { + RunIdentity { + run_id: Some("20260731T090001Z"), + role: Some("producer"), + model: Some("claude-fable-5"), + } + } + + /// The full contract of one skip row: the typed discriminant, the verbatim reason, and every + /// standard field a consumer already reconciles rows by. + #[test] + fn a_skip_row_carries_the_gate_and_its_reason_verbatim() { + let doc = final_record( + "/runs/20260731T090001Z.jsonl", + &RunMetrics::default(), + &id(), + Some((10, TraceOutcome::Skipped)), + &ToolingReport::default(), + &[], + &InfraRecord::default(), + Some(("usage-gate", PAUSE_LINE)), + ); + assert_eq!(doc["skipped"], "usage-gate"); + assert_eq!(doc["skipReason"], PAUSE_LINE, "the reason must be verbatim"); + assert_eq!(doc["stage"], STAGE_FINAL); + assert_eq!(doc["runId"], "20260731T090001Z"); + assert_eq!(doc["role"], "producer"); + assert_eq!(doc["model"], "claude-fable-5"); + assert_eq!(doc["exitCode"], 10); + assert_eq!( + doc["outcome"], "skipped", + "a paused tick is neither ok nor error — those are the words that drew a dead cron" + ); + } + + /// ABSENT, not null: a consumer keys on the field existing at all, and every record written + /// before the skip fields must stay byte-identical to what this build would write for it. + #[test] + fn an_unskipped_row_omits_both_skip_fields_entirely() { + let doc = final_record( + "/t.jsonl", + &RunMetrics::default(), + &id(), + Some((0, TraceOutcome::Ok)), + &ToolingReport::default(), + &[], + &InfraRecord::default(), + None, + ); + assert!( + doc.get("skipped").is_none(), + "skipped must be absent, not null, on a run that ran" + ); + assert!( + doc.get("skipReason").is_none(), + "skipReason must be absent, not null, on a run that ran" + ); + } + + /// The classification half of the same contract: a skip outranks what the empty trace would + /// otherwise read as. The runner records the GATE's exit 10 on the row, and 10 over zero + /// events classifies `error` — the very rendering the skip row exists to correct. + #[test] + fn a_skip_classifies_skipped_where_the_bare_exit_code_would_read_error() { + assert_eq!( + classify_outcome("", 10, true, &[], &InfraRecord::default()), + TraceOutcome::Skipped + ); + assert_eq!( + classify_outcome("", 10, false, &[], &InfraRecord::default()), + TraceOutcome::Error, + "without the skip fact, the same row reads as an error — the flag is load-bearing" + ); + assert_eq!(TraceOutcome::Skipped.as_str(), "skipped"); + } + + /// A config REFUSAL is NOT a skip. The runners abort loudly on usage-gate exit 2 and write no + /// row at all — so nothing may classify a refusal's exit as `skipped` unless the runner + /// explicitly said so, and the runner never does. + #[test] + fn a_refusal_exit_is_never_skipped_without_the_flag() { + assert_eq!( + classify_outcome("", 2, false, &[], &InfraRecord::default()), + TraceOutcome::Error, + "a refusal must stay loud, never dressed up as pacing" + ); + } +} + /// Live token usage and the rate-limit windows (#97). /// /// The oracle for the token half is not this code's own output: it is the `result` event that the @@ -22277,6 +22430,7 @@ mod usage_probe_tests { &ToolingReport::default(), &[], &InfraRecord::default(), + None, ); assert_eq!(doc["rateLimits"]["five_hour"]["status"], "allowed"); // The terminal totals stay authoritative — including the output count the probe cannot @@ -22293,6 +22447,7 @@ mod usage_probe_tests { &ToolingReport::default(), &[], &InfraRecord::default(), + None, ); assert!( bare["rateLimits"].is_object(), @@ -27115,6 +27270,8 @@ mod cli_tests { exit_code: None, preflight_missing: vec![], infra: None, + skipped: None, + skip_reason: None, } ); // The form the runners now use in place of the `| jq '. + {…}'` pipe. @@ -27140,6 +27297,8 @@ mod cli_tests { exit_code: Some(0), preflight_missing: vec![], infra: None, + skipped: None, + skip_reason: None, } ); // The abort form: `preflight` found nothing to render with, so the model never started. @@ -27161,8 +27320,64 @@ mod cli_tests { exit_code: Some(12), preflight_missing: vec!["pdftoppm".to_string(), "pdfinfo".to_string()], infra: None, + skipped: None, + skip_reason: None, + } + ); + // The SKIP form (#160): the usage-gate paused the tick, the runners record the row with + // the gate's own line, verbatim. + assert_eq!( + parse(&[ + "prr", + "run-metrics", + "/t.jsonl", + "--run-id", + "20260731T090001Z", + "--role", + "producer", + "--model", + "claude-fable-5", + "--exit-code", + "10", + "--skipped", + "usage-gate", + "--skip-reason", + "PAUSE: 91% of the weekly budget used (endpoint) — at/over the 90% ceiling" + ]), + Cmd::RunMetrics { + trace: "/t.jsonl".to_string(), + run_id: Some("20260731T090001Z".to_string()), + role: Some("producer".to_string()), + model: Some("claude-fable-5".to_string()), + exit_code: Some(10), + preflight_missing: vec![], + infra: None, + skipped: Some("usage-gate".to_string()), + skip_reason: Some( + "PAUSE: 91% of the weekly budget used (endpoint) — at/over the 90% ceiling" + .to_string() + ), } ); + // The two skip flags arrive together or not at all: a gate with no reason would emit a + // row that cannot say WHY the tick paused, and a reason with no gate has no field to + // hang it on. Refused at parse, so no runner edit can half-supply the pair. + assert!( + Cli::try_parse_from(["prr", "run-metrics", "/t.jsonl", "--skipped", "usage-gate"]) + .is_err(), + "--skipped without --skip-reason must be refused" + ); + assert!( + Cli::try_parse_from([ + "prr", + "run-metrics", + "/t.jsonl", + "--skip-reason", + "PAUSE: x" + ]) + .is_err(), + "--skip-reason without --skipped must be refused" + ); } #[test] @@ -27577,12 +27792,12 @@ mod cli_tests { // that a declared binary would not resolve. let missing = vec!["pdftoppm".to_string()]; assert_eq!( - classify_outcome("", 12, &missing, &InfraRecord::default()), + classify_outcome("", 12, false, &missing, &InfraRecord::default()), TraceOutcome::ToolingFailure ); // …and an empty list must not change what the trace already said. assert_eq!( - classify_outcome("", 0, &[], &InfraRecord::default()), + classify_outcome("", 0, false, &[], &InfraRecord::default()), TraceOutcome::Ok ); } @@ -34764,20 +34979,23 @@ mod infra_down_tests { }; let up = InfraRecord::default(); assert_eq!( - classify_outcome("", 0, &[], &down), + classify_outcome("", 0, false, &[], &down), TraceOutcome::InfraDown, "an otherwise-clean run that stopped early must not read as ok" ); - assert_eq!(classify_outcome("", 0, &[], &up), TraceOutcome::Ok); + assert_eq!(classify_outcome("", 0, false, &[], &up), TraceOutcome::Ok); // Worse outcomes win. - assert_eq!(classify_outcome("", 1, &[], &down), TraceOutcome::Error); assert_eq!( - classify_outcome("", 0, &["pdftoppm".to_string()], &down), + classify_outcome("", 1, false, &[], &down), + TraceOutcome::Error + ); + assert_eq!( + classify_outcome("", 0, false, &["pdftoppm".to_string()], &down), TraceOutcome::ToolingFailure ); let quota = r#"{"type":"result","api_error_status":429,"result":""}"#; assert_eq!( - classify_outcome(quota, 0, &[], &down), + classify_outcome(quota, 0, false, &[], &down), TraceOutcome::QuotaLimited, "a quota refusal must still advance model fallback" ); @@ -34802,6 +35020,7 @@ mod infra_down_tests { &ToolingReport::default(), &[], &InfraRecord::default(), + None, ); assert_eq!(clean["infraDown"], false); assert_eq!(clean["infraReason"], ""); @@ -34821,6 +35040,7 @@ mod infra_down_tests { &ToolingReport::default(), &[], &down, + None, ); assert_eq!(doc["infraDown"], true); assert_eq!(doc["infraReason"], "fork RPCs erroring org-wide"); diff --git a/pr-review-report-rs/tests/refresh_human_queue.rs b/pr-review-report-rs/tests/refresh_human_queue.rs index d80db1d4..e02dfd82 100644 --- a/pr-review-report-rs/tests/refresh_human_queue.rs +++ b/pr-review-report-rs/tests/refresh_human_queue.rs @@ -171,6 +171,15 @@ impl Fixture { "{\"ts\":\"2026-07-01T00:00:00Z\",\"counts\":{\"a\":1}}\n", ) .unwrap(); + // The run-metrics ledger is TRACKED in the real repo, and the script publishes it + // alongside the snapshot (#160) — the fixture mirrors that so `git add` has the same + // tracked file to stage. + std::fs::create_dir_all(f.install.join("metrics")).unwrap(); + std::fs::write( + f.install.join("metrics/runs.jsonl"), + "{\"runId\":\"20260701T000000Z\",\"role\":\"producer\",\"outcome\":\"ok\"}\n", + ) + .unwrap(); std::fs::write(f.install.join("unrelated.txt"), "seed\n").unwrap(); git(&f.install, &["add", "-A"]); git(&f.install, &["commit", "--quiet", "-m", "seed"]); @@ -484,8 +493,99 @@ fn divergence_is_reported_loudly_and_nothing_is_merged_or_discarded() { ); } +/// The pause-visibility half of #160: a usage-gate skip row appended to `metrics/runs.jsonl` by a +/// gated runner tick must reach the remote on the NEXT hourly refresh, even though the queue +/// snapshot did not move — during a pause, nothing else runs to move it. Publishing is asserted +/// on the remote's own copy of the file; the history ledger must not gain a rollup line, because +/// its contract is one line per CHANGED snapshot and the snapshot did not change. +#[test] +fn a_metrics_only_append_publishes_without_a_history_line() { + let Some(f) = Fixture::new("metrics-only") else { + return; + }; + f.set_next_snapshot("{\"counts\":{\"a\":1}}\n"); // identical to the seed + let skip_row = "{\"runId\":\"20260731T090001Z\",\"role\":\"producer\",\"exitCode\":10,\ + \"outcome\":\"skipped\",\"skipped\":\"usage-gate\",\ + \"skipReason\":\"PAUSE: 91% of the weekly budget used (endpoint)\"}\n"; + let mut runs = std::fs::read_to_string(f.install.join("metrics/runs.jsonl")).unwrap(); + runs.push_str(skip_row); + std::fs::write(f.install.join("metrics/runs.jsonl"), &runs).unwrap(); + let head_before = f.install_head(); + + let out = f.tick(); + assert!( + out.status.success(), + "a metrics-only tick must publish: {}", + stderr(&out) + ); + let head = f.install_head(); + assert_ne!(head, head_before, "the skip row must be committed"); + assert_eq!( + f.origin_head(), + head, + "the skip row must reach the remote — visibility DURING the pause is the point\n{}", + stderr(&out) + ); + assert!( + git(&f.install, &["show", "HEAD:metrics/runs.jsonl"]).contains("usage-gate"), + "the committed ledger must carry the skip row" + ); + assert_eq!( + std::fs::read_to_string(f.install.join("human-queue-history.jsonl")) + .unwrap() + .lines() + .count(), + 1, + "an unchanged snapshot must not append a history line, whatever the metrics did" + ); +} + +/// The change probes compare against HEAD, not the index. A tick that staged its files and then +/// failed to commit (lock contention, a full disk) leaves the change STAGED — and `git diff` +/// without `HEAD` reads staged-only content as unchanged, so every later tick would skip the +/// publish and the skip rows would sit there until unrelated queue churn rescued them. Driven the +/// way the failure leaves the tree: the row already staged before the tick runs. +#[test] +fn a_staged_but_uncommitted_append_is_still_published() { + let Some(f) = Fixture::new("staged-metrics") else { + return; + }; + f.set_next_snapshot("{\"counts\":{\"a\":1}}\n"); // identical to the seed + let skip_row = "{\"runId\":\"20260731T110001Z\",\"role\":\"vetter\",\"exitCode\":10,\ + \"outcome\":\"skipped\",\"skipped\":\"usage-gate\",\ + \"skipReason\":\"PAUSE: 91% of the weekly budget used (endpoint)\"}\n"; + let mut runs = std::fs::read_to_string(f.install.join("metrics/runs.jsonl")).unwrap(); + runs.push_str(skip_row); + std::fs::write(f.install.join("metrics/runs.jsonl"), &runs).unwrap(); + git(&f.install, &["add", "metrics/runs.jsonl"]); + let head_before = f.install_head(); + + let out = f.tick(); + assert!( + out.status.success(), + "a staged-only change must still publish: {}", + stderr(&out) + ); + assert_ne!( + f.install_head(), + head_before, + "a staged-only change must still be committed — the probe must compare against HEAD" + ); + assert_eq!( + f.origin_head(), + f.install_head(), + "the staged row must reach the remote\n{}", + stderr(&out) + ); + assert!( + git(&f.install, &["show", "HEAD:metrics/runs.jsonl"]).contains("usage-gate"), + "the committed ledger must carry the staged skip row" + ); +} + /// The early exit predates both fixes and has to keep holding: an unchanged snapshot commits -/// nothing, pushes nothing and succeeds. +/// nothing, pushes nothing and succeeds — and an unchanged METRICS ledger (#160) is part of that +/// stillness: this fixture's runs.jsonl has no new rows, so nothing may publish. #[test] fn an_unchanged_snapshot_stays_a_no_op() { let Some(f) = Fixture::new("unchanged") else { diff --git a/pr-review-report-rs/tests/usage_gate_skip.rs b/pr-review-report-rs/tests/usage_gate_skip.rs new file mode 100644 index 00000000..3584e5a7 --- /dev/null +++ b/pr-review-report-rs/tests/usage_gate_skip.rs @@ -0,0 +1,254 @@ +//! Behavioural tests for the runners' usage-gate paths (#160). +//! +//! A gate PAUSE (exit 10) must leave one skip row in `metrics/runs.jsonl` — before this, a paused +//! stretch left nothing at all and the dashboard drew nine consecutive gated ticks as a dead +//! cron. A config REFUSAL (exit 2) must stay a loud abort that writes NO row: dressing broken +//! config up as pacing is the conflation the typed fields exist to prevent. Both properties live +//! in the SHELL of `campaign-run.sh` / `review-run.sh`, which no unit test in the binary can see, +//! so these drive the real scripts as processes. +//! +//! Only `usage-gate` is stubbed — its verdict is the fixture's input. Every other subcommand, +//! `run-metrics` above all, is delegated to the REAL binary cargo just built, because the row's +//! shape is exactly what must not be asserted against a stub's belief: "there is no second place +//! that knows what a runs.jsonl line looks like" is the invariant under test. +//! +//! Like `refresh_human_queue.rs`, these return early when the checkout is absent (the nix build +//! sandbox filters the scripts out of the crate's source); the `rainix-rs-test` gate runs against +//! a full checkout, which is where they execute. Both gate paths exit before the runners' `flock`, +//! `timeout` or `claude` are ever reached, so nothing else needs stubbing or skipping. + +use std::path::{Path, PathBuf}; +use std::process::{Command, Output}; + +/// The binary cargo just built. Never a PATH lookup — that would test whatever +/// `pr-review-report` happens to be installed on the box. +const REAL_BIN: &str = env!("CARGO_BIN_EXE_pr-review-report"); + +/// The gate's real ceiling-pause line, verbatim — the fixture feeds it through the runner's +/// `$_ug` capture and the row must return it byte-identical. +const PAUSE_LINE: &str = + "PAUSE: 91% of the weekly budget used (endpoint) — at/over the 90% ceiling"; + +/// The refusal's first line (the real one is longer; one line is enough to prove it is carried). +const REFUSE_LINE: &str = "REFUSED: USAGE_SLACK_PCT=3 is set, but that knob is retired (#158)"; + +/// The repo root, one level up from the crate. +fn repo_root() -> PathBuf { + Path::new(env!("CARGO_MANIFEST_DIR")) + .parent() + .expect("the crate always has a parent directory") + .to_path_buf() +} + +struct Fixture { + root: PathBuf, + install: PathBuf, + script: PathBuf, +} + +impl Fixture { + /// `None` when the checkout is not there (nix build sandbox) — enforced by the rs-test gate. + fn new( + name: &str, + script: &str, + prompt_file: &str, + gate_rc: i32, + gate_line: &str, + ) -> Option { + let script = repo_root().join(script); + if !script.is_file() { + return None; + } + let root = std::env::temp_dir() + .join("usage-gate-skip-tests") + .join(format!("{}-{}", std::process::id(), name)); + let _ = std::fs::remove_dir_all(&root); + let install = root.join("install"); + std::fs::create_dir_all(&install).expect("create install dir"); + // The runner's install-dir probe: any content will do, the gate exits long before it is read. + std::fs::write(install.join(prompt_file), "prompt body (never reached)\n").unwrap(); + + // The stub: `usage-gate` answers with the fixture's verdict; EVERYTHING else is the real + // binary, so the emitted row is the real contract and not this test's opinion of it. + let bin = root.join("bin"); + std::fs::create_dir_all(&bin).expect("create stub bin dir"); + let stub = format!( + "#!/usr/bin/env bash\n\ + set -uo pipefail\n\ + if [ \"${{1:-}}\" = usage-gate ]; then\n\ + \x20 printf '%s\\n' {line}\n\ + \x20 exit {rc}\n\ + fi\n\ + exec {real} \"$@\"\n", + line = shell_quote(gate_line), + rc = gate_rc, + real = REAL_BIN, + ); + let path = bin.join("pr-review-report"); + std::fs::write(&path, stub).expect("write stub"); + #[cfg(unix)] + { + use std::os::unix::fs::PermissionsExt; + std::fs::set_permissions(&path, std::fs::Permissions::from_mode(0o755)) + .expect("chmod stub"); + } + Some(Fixture { + root, + install, + script, + }) + } + + /// Run one cron tick. `bash -euo pipefail` is the prelude `writeShellApplication` puts above + /// the script text, so the shell options match the packaged runner exactly. + fn tick(&self) -> Output { + let path = format!( + "{}:{}", + self.root.join("bin").display(), + std::env::var("PATH").unwrap_or_default() + ); + Command::new("bash") + .args(["-euo", "pipefail"]) + .arg(&self.script) + .env("PATH", path) + .env("HOME", &self.root) + .env("CRON_DIR", &self.install) + .output() + .expect("run the runner script") + } + + fn runs_jsonl(&self) -> PathBuf { + self.install.join("metrics/runs.jsonl") + } +} + +impl Drop for Fixture { + fn drop(&mut self) { + let _ = std::fs::remove_dir_all(&self.root); + } +} + +/// Single-quote a string for embedding in the stub script. +fn shell_quote(s: &str) -> String { + format!("'{}'", s.replace('\'', "'\\''")) +} + +/// The one skip row a paused tick leaves, parsed. Asserts there is exactly one line. +fn the_only_row(f: &Fixture) -> serde_json::Value { + let content = std::fs::read_to_string(f.runs_jsonl()).expect("metrics/runs.jsonl must exist"); + let lines: Vec<&str> = content.lines().filter(|l| !l.trim().is_empty()).collect(); + assert_eq!( + lines.len(), + 1, + "a paused tick writes exactly one row, got: {content:?}" + ); + serde_json::from_str(lines[0]).expect("the row must be one valid JSON object") +} + +fn assert_skip_row(f: &Fixture, out: &Output, role: &str) { + assert!( + out.status.success(), + "a paused tick still exits 0 — a pause is not a failure: {}", + String::from_utf8_lossy(&out.stderr) + ); + let row = the_only_row(f); + assert_eq!(row["skipped"], "usage-gate"); + assert_eq!( + row["skipReason"], PAUSE_LINE, + "the reason must be the gate's own line, verbatim" + ); + assert_eq!(row["role"], role); + assert_eq!(row["model"], "claude-fable-5", "the runners' default model"); + assert_eq!( + row["exitCode"], 10, + "the row records the GATE's exit, like the preflight row records preflight's 12" + ); + assert_eq!(row["outcome"], "skipped"); + assert_eq!(row["stage"], "final"); + let run_id = row["runId"].as_str().expect("runId present"); + assert_eq!( + run_id.len(), + "20260731T090001Z".len(), + "runId is the runner's UTC stamp: {run_id}" + ); + // The empty trace the row was distilled from exists where the row says it does — the same + // relationship every other runs.jsonl row has with its trace. + let trace = row["trace"].as_str().expect("trace present"); + let meta = std::fs::metadata(trace).expect("the empty trace file must exist"); + assert_eq!(meta.len(), 0, "the skip trace is EMPTY: no model ran"); +} + +#[test] +fn a_paused_producer_tick_writes_one_skip_row_and_exits_zero() { + let Some(f) = Fixture::new( + "producer-pause", + "campaign-run.sh", + "campaign-prompt.txt", + 10, + PAUSE_LINE, + ) else { + return; + }; + let out = f.tick(); + assert_skip_row(&f, &out, "producer"); +} + +#[test] +fn a_paused_vetter_tick_writes_one_skip_row_and_exits_zero() { + let Some(f) = Fixture::new( + "vetter-pause", + "review-run.sh", + "review-prompt.txt", + 10, + PAUSE_LINE, + ) else { + return; + }; + let out = f.tick(); + assert_skip_row(&f, &out, "vetter"); +} + +/// The conflation guard: a config REFUSAL is NOT a skip. The tick aborts with the gate's own +/// exit code and writes NO row — swapping the two branches (or widening the skip write to every +/// non-zero gate exit) fails here by producing a row, or a zero exit, or both. +#[test] +fn a_refused_producer_tick_aborts_loudly_and_writes_no_row() { + let Some(f) = Fixture::new( + "producer-refuse", + "campaign-run.sh", + "campaign-prompt.txt", + 2, + REFUSE_LINE, + ) else { + return; + }; + let out = f.tick(); + assert_eq!( + out.status.code(), + Some(2), + "a refusal propagates the gate's exit — the tick must not run on config the gate refused" + ); + assert!( + !f.runs_jsonl().exists(), + "a refusal writes NO runs.jsonl row: it is a loud abort, not pacing" + ); +} + +#[test] +fn a_refused_vetter_tick_aborts_loudly_and_writes_no_row() { + let Some(f) = Fixture::new( + "vetter-refuse", + "review-run.sh", + "review-prompt.txt", + 2, + REFUSE_LINE, + ) else { + return; + }; + let out = f.tick(); + assert_eq!(out.status.code(), Some(2)); + assert!( + !f.runs_jsonl().exists(), + "a refusal writes NO runs.jsonl row: it is a loud abort, not pacing" + ); +} diff --git a/refresh-human-queue.sh b/refresh-human-queue.sh index 3f0a9faa..e28a9c36 100755 --- a/refresh-human-queue.sh +++ b/refresh-human-queue.sh @@ -4,7 +4,11 @@ # The snapshot itself is OVERWRITE (point-in-time); alongside it we APPEND one rollup line per # changed refresh to human-queue-history.jsonl ({ts, counts}, mirroring metrics/runs.jsonl) so the # dashboard can render per-state inventory over time (Theory-of-Constraints flow panel; -# rain-org-health#32). Data-only, safe unattended. Installed on a cron; see crontab. +# rain-org-health#32). This tick is also what publishes metrics/runs.jsonl itself (#160): the +# model runners append rows but never push, and during a usage-gate pause they are the ONLY thing +# writing (one skip row per gated tick) — this cron is data-only, never usage-gated, and already +# commits straight to main every hour, which makes it the one committer still awake during a +# pause. Data-only, safe unattended. Installed on a cron; see crontab. # Packaged as a flake output (`packages.refresh-human-queue`); nix builds PATH from the flake's # locked nixpkgs. errexit is turned back off — writeShellApplication forces it, but this script # reads exit status as data (`git diff --quiet` says whether the snapshot moved, a rejected push @@ -107,34 +111,59 @@ else exit 1 fi -# Commit + push only on a real change. -if git -C "$DIR" diff --quiet -- human-queue.json; then - log "snapshot unchanged at $(git -C "$DIR" rev-parse --short HEAD); nothing to publish" +# Commit + push only on a real change — to the snapshot OR to the run-metrics ledger (#160). +# metrics/runs.jsonl rides this tick because the runners that append it never push, and a +# usage-gate pause suspends the very runs whose completion used to be the occasion for committing +# it — while the pause path itself appends one skip row per gated tick. Gating the publish on the +# snapshot alone would hold those rows hostage to unrelated queue churn; either file moving is a +# reason to publish both. +# Both probes compare against HEAD, not the index: a tick that staged its files and then failed +# to commit leaves the change STAGED, and a bare `git diff` reads staged-only content as +# unchanged — every later tick would then skip the publish it exists to make. +snapshot_changed=1 +git -C "$DIR" diff --quiet HEAD -- human-queue.json && snapshot_changed=0 +metrics_changed=1 +git -C "$DIR" diff --quiet HEAD -- metrics/runs.jsonl && metrics_changed=0 +if [ "$snapshot_changed" -eq 0 ] && [ "$metrics_changed" -eq 0 ]; then + log "snapshot and run metrics unchanged at $(git -C "$DIR" rev-parse --short HEAD); nothing to publish" exit 0 fi # Append one rollup line {ts, counts} to the append-only history so the dashboard can # render per-state inventory over time (Theory-of-Constraints flow panel; -# rain-org-health#32). One line per CHANGED snapshot, mirroring metrics/runs.jsonl. -# counts come straight from the tool-generated snapshot (the tool stays the single -# source of truth); ts is this refresh's real UTC time (never synthesized downstream). -# `queue-history-line` is the same code path the backfill uses, so the live append and the -# historical rewrite can never produce different line shapes for the same snapshot. -ts="$(date -u +%Y-%m-%dT%H:%M:%SZ)" -histerr="$(mktemp)" -hist="$(pr-review-report queue-history-line "$DIR/human-queue.json" --ts "$ts" 2>"$histerr")"; hist_rc=$? -if [ "$hist_rc" -eq 0 ] && [ -n "$hist" ]; then - printf '%s\n' "$hist" >>"$DIR/human-queue-history.jsonl" -else - # The snapshot is what the dashboard reads; a missing history point costs one plot marker, so - # this is reported rather than fatal. Buffering the line (instead of appending the pipe straight - # into the file) is what keeps a failure from writing a partial record into an append-only file. - log "history line failed (rc=$hist_rc): $(tr '\n' ' ' <"$histerr")— publishing the snapshot without it" +# rain-org-health#32). One line per CHANGED snapshot, mirroring metrics/runs.jsonl — so it stays +# gated on the SNAPSHOT having moved: a metrics-only tick appends no history line, or an idle +# queue would grow one identical rollup per skip row. +if [ "$snapshot_changed" -eq 1 ]; then + # counts come straight from the tool-generated snapshot (the tool stays the single + # source of truth); ts is this refresh's real UTC time (never synthesized downstream). + # `queue-history-line` is the same code path the backfill uses, so the live append and the + # historical rewrite can never produce different line shapes for the same snapshot. + ts="$(date -u +%Y-%m-%dT%H:%M:%SZ)" + histerr="$(mktemp)" + hist="$(pr-review-report queue-history-line "$DIR/human-queue.json" --ts "$ts" 2>"$histerr")"; hist_rc=$? + if [ "$hist_rc" -eq 0 ] && [ -n "$hist" ]; then + printf '%s\n' "$hist" >>"$DIR/human-queue-history.jsonl" + else + # The snapshot is what the dashboard reads; a missing history point costs one plot marker, so + # this is reported rather than fatal. Buffering the line (instead of appending the pipe straight + # into the file) is what keeps a failure from writing a partial record into an append-only file. + log "history line failed (rc=$hist_rc): $(tr '\n' ' ' <"$histerr")— publishing the snapshot without it" + fi + rm -f "$histerr" fi -rm -f "$histerr" -git_q add human-queue.json human-queue-history.jsonl || exit 1 -git_q -c commit.gpgsign=false commit --no-verify -m "chore(dashboard): refresh human-queue.json snapshot" --quiet || exit 1 +# The commit message names what actually moved: metrics-only ticks keep the `chore(metrics):` +# prefix the file's hand-committed history already uses. +if [ "$snapshot_changed" -eq 1 ] && [ "$metrics_changed" -eq 1 ]; then + msg="chore(dashboard): refresh human-queue.json snapshot + run metrics" +elif [ "$snapshot_changed" -eq 1 ]; then + msg="chore(dashboard): refresh human-queue.json snapshot" +else + msg="chore(metrics): publish accrued run metrics" +fi +git_q add human-queue.json human-queue-history.jsonl metrics/runs.jsonl || exit 1 +git_q -c commit.gpgsign=false commit --no-verify -m "$msg" --quiet || exit 1 mine="$(git -C "$DIR" rev-parse HEAD)" # The remote can still move between the fetch above and this push — a PR merging mid-tick. Replay diff --git a/review-run.sh b/review-run.sh index 88166955..6d3a004b 100755 --- a/review-run.sh +++ b/review-run.sh @@ -76,14 +76,29 @@ fi # --- weekly-budget pace gate: skip this tick when usage is over the ceiling or inside the BAU # headroom band under the linear burn toward the reset — the crons hold ~USAGE_HEADROOM_PCT points # BEHIND pace so interactive work keeps standing budget (#158). `usage-gate` reads -# /api/oauth/usage itself; exit 10 means PAUSE (log it, exit 0). It is INERT when it cannot read -# usage and no fallback is set — it prints OK and we run. Any OTHER non-zero exit is a config -# REFUSAL (the retired USAGE_SLACK_PCT still set: exit 2, reason on stderr, captured into the -# log): the tick must not run on config the gate refused to read, so propagate the failure — a -# refusal is neither a run nor a pause. --- +# /api/oauth/usage itself; exit 10 means PAUSE (record one skip row, exit 0). It is INERT when it +# cannot read usage and no fallback is set — it prints OK and we run. Any OTHER non-zero exit is a +# config REFUSAL (the retired USAGE_SLACK_PCT still set: exit 2, reason on stderr, captured into +# the log): the tick must not run on config the gate refused to read, so propagate the failure — a +# refusal is neither a run nor a pause, and it writes NO row. --- _ug="$(pr-review-report usage-gate 2>&1)"; _ugrc=$? echo "$(date -u +%FT%TZ) usage-gate: $_ug" >> "$LOG" -[ "$_ugrc" -eq 10 ] && exit 0 +if [ "$_ugrc" -eq 10 ]; then + # A paused tick still writes its metrics/runs.jsonl row (#160) — same shape and same reasoning + # as campaign-run.sh: an empty trace so the record's shape still comes from `run-metrics`, the + # GATE's exit 10 on the row, the gate's own line verbatim, and exit 0 because a pause is not a + # failure. The hourly refresh-human-queue cron is what carries the row to origin/main during a + # pause. A REFUSAL (exit 2, below) writes no row and aborts loudly. + TS="$(date -u +%Y%m%dT%H%M%SZ)" + RUNLOG="$RUNDIR/$TS.jsonl" + mkdir -p "$RUNDIR" "$DIR/metrics" + : > "$RUNLOG" + pr-review-report run-metrics "$RUNLOG" \ + --run-id "$TS" --role vetter --model "$REVIEW_MODEL" --exit-code 10 \ + --skipped usage-gate --skip-reason "$_ug" \ + >> "$DIR/metrics/runs.jsonl" 2>/dev/null || true + exit 0 +fi if [ "$_ugrc" -ne 0 ]; then echo "$(date -u +%FT%TZ) review run ABORTED: usage-gate refused its config (exit $_ugrc) — fix cron.env" >> "$LOG" exit "$_ugrc"