From 4c826539dd9fd30b149b5d3627c18abcbbb41921 Mon Sep 17 00:00:00 2001 From: matt Date: Fri, 18 Sep 2026 19:07:35 +0200 Subject: [PATCH 1/2] feat(bin): record per-card worker time in a work ledger and report only drift edges Append one row per turn boundary, dispatch, PR-ready registration, and merge to state/work-ledger/.events from the scripts that already run at those moments, so a card's cost is on record without anyone remembering to write it. Capture never blocks or fails a turn, and a harness that reports no turn boundaries is recorded as unmeasured rather than as zero. bin/fm-work-ledger.sh copies local homes' ledgers into the primary home's store and is a registered check that prints only edges: a card crossing 3x or 6x its rating's budget, capture going dead for a home, and a five-card lane digest. A run in which nothing changed prints nothing. Retiring a second mate copies its ledger first and refuses when the copy fails. --- .agents/skills/work-ledger/SKILL.md | 51 ++ AGENTS.md | 4 + bin/fm-busy-event.sh | 53 +- bin/fm-merge-outcome-lib.sh | 7 + bin/fm-pr-check.sh | 6 + bin/fm-spawn.sh | 21 + bin/fm-teardown.sh | 19 + bin/fm-test-run.sh | 3 +- bin/fm-work-ledger-lib.sh | 138 +++++ bin/fm-work-ledger.sh | 702 ++++++++++++++++++++++ docs/configuration.md | 18 + docs/documentation-audiences.json | 4 + tests/fm-busy-adapter-wiring.test.sh | 35 ++ tests/fm-secondmate-lifecycle-e2e.test.sh | 17 + tests/fm-teardown.test.sh | 36 ++ tests/fm-work-ledger.test.sh | 367 +++++++++++ 16 files changed, 1466 insertions(+), 15 deletions(-) create mode 100644 .agents/skills/work-ledger/SKILL.md create mode 100644 bin/fm-work-ledger-lib.sh create mode 100755 bin/fm-work-ledger.sh create mode 100755 tests/fm-work-ledger.test.sh diff --git a/.agents/skills/work-ledger/SKILL.md b/.agents/skills/work-ledger/SKILL.md new file mode 100644 index 00000000000..3910f7313a9 --- /dev/null +++ b/.agents/skills/work-ledger/SKILL.md @@ -0,0 +1,51 @@ +--- +name: work-ledger +description: >- + Agent-only procedure for the per-card work ledger's wakes. + Use on any `check: work-ledger:` wake: an over-budget card, capture dead in a + home, a lane digest, or a check error. + Also use before writing a card's rating or parent into its backlog title. + Owns what each wake asks firstmate to do, what must never be done with the + numbers, and the title fields the ledger reads at dispatch. +user-invocable: false +metadata: + internal: true +--- + +# work-ledger + +Load this on any `check: work-ledger:` wake, and before writing a card's rating or parent into its backlog title. + +The ledger exists to show, while the work is still happening, that a card is taking far longer than its difficulty warrants. +It is a problem finder, never a score: nothing here ranks a harness, a model, or an agent, and no number from it is ever shown to a worker. +`bin/fm-work-ledger-lib.sh` owns what is recorded and `bin/fm-work-ledger.sh` owns the store, the edges, and the measurement rules; read their headers rather than restating them. + +## The wakes + +The check reports an edge once and is silent otherwise, so a wake is never a repeat of one already handled. + +- **`over-budget in `** - look at that card's current state and its worker, then record exactly one of three as a keyed status note in that lane: continue, with the reason; re-scope, which goes to the captain as a decision; or re-rate, which is a blind re-rate by a session that has not seen the card's cost and never replaces the frozen rating. + The thresholds are post hoc and the line says so, so treat the wake as a prompt to look, not as proof of a problem. + Never interrupt, relaunch, or re-scope a card on the strength of the wake alone. +- **`capture dead in `** - capture stopped for a whole home, which is the one ledger failure that needs a person. + Find the cause in that home's `state/work-ledger/` - disk, permissions, or a writer regression - and check its `.errors` file. + A single card with a gap never wakes anyone; it is counted in the next digest. +- **`digest `** - relay the one line to the captain at the next natural reply, in plain language. + Name any factor that moved by 2x or more against the previous digest. + Take no other action: fewer than 20 cards cannot support a trend claim, so never present a digest as a trend alarm. +- **`check error`** - the evaluation itself failed; fix the named cause, because a broken check is otherwise silent. + `data/work-ledger/.last-run` shows when the check last ran. + +## Reading the numbers honestly + +An unmeasured card ran on a worker runtime that reports no turn boundaries; it is unmeasured, never zero minutes. +An incomplete or unrated card is left out of pace and counted in the digest rather than estimated. +These are turn-bracketed minutes, a different measurement from minutes rebuilt out of transcripts, so never compare the two series or join them, and never backfill the ledger from history. + +## Rating and parent fields + +Spawn reads two optional fields from the card's backlog title at dispatch: `(rating: by= blind= at=)` and `(parent: )`. +Write them before the `(kind: ...)` field so the backlog tool keeps them as part of the title. +Only the rating present at the card's first dispatch is its frozen rating; a rating added later is recorded on later launches and is never the anchor. +A card dispatched without one is recorded as unrated, which is visible in the digest, so rate before dispatch rather than after. +Sub-cards of a split card name the original as `parent` so their time folds into it. diff --git a/AGENTS.md b/AGENTS.md index c4f62af7dbc..6b5597c2b9e 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -91,6 +91,7 @@ data/ personal fleet records; LOCAL, gitignored as a whole captain.md this home's domain-local captain preferences and working style; LOCAL, gitignored, canonical even if harness memory mirrors it, and updated with inspect-then-update captain-shared.md main-authoritative shared captain preferences propagated read-only to secondmate homes; LOCAL, gitignored, owned by secondmate-provisioning learnings.md fleet-local operational facts and gotchas; LOCAL, gitignored; dated, evidence-backed, curated, and updated with inspect-then-update - rewrite and prune rather than append forever, the same contract as captain.md; created lazily, absent until this home has a learning to store + work-ledger/ per-lane copy of every local home's work ledger, its edge cursor, and its last-run marker; written only by bin/fm-work-ledger.sh (docs/configuration.md "Work ledger") projects.md thin fleet navigation registry recording each project's standing delivery posture; firstmate-private, parsed for mechanical sync and seeding by fm-project-mode.sh (section 6) secondmates.md local and remote secondmate routing table; firstmate-private, maintained by the secondmate seed helpers (section 6) /brief.md per-task crewmate brief, or per-secondmate charter brief when kind=secondmate @@ -126,6 +127,8 @@ state/ runtime records and signals; gitignored tool-updates.check.sh generated watched-tool update poll shim and its .check-trust binding; present only after bin/fm-tool-update-check.sh arm; its report record .tool-updates is what keeps one pending update from being reported on every poll mail.check.sh generated received-mail poll shim and its .check-trust binding; present only after bin/fm-mail-check.sh arm; report record .mail-check (mail schema: docs/configuration.md "Mail plane") .mail-seen .mail-woken .mail-retry .mail-retry-pos .mail-turn .mail-seen.lock mail-plane poll cursor, emission journal, transient-fetch retry set, retry-scan position, contended-slot turn flag, and overlapping-poll lock; written only by bin/fm-mail.sh (mail schema: docs/configuration.md "Mail plane") + work-ledger/ append-only per-task turn, spawn, PR-ready, and merged rows that survive teardown and relaunch; bin/fm-work-ledger-lib.sh owns the format, and teardown must never remove it + work-ledger.check.sh generated work-ledger poll shim and its .check-trust binding; primary home only, present only after bin/fm-work-ledger.sh arm pending-replies/ parent-owned secondmate pending-reply records (correlation id, delivery vs reply, recovery, escalation); fm-pending-reply-lib.sh procevent/ registered process-to-event sources, one private record per canonical source id; written only by bin/fm-procevent.sh, and their presence alone keeps supervision required (section 13) procevent-inbox/ private captured results and their durable handled-acknowledgement markers; source output lives here and never in an event line @@ -585,6 +588,7 @@ These skills are not captain-invocable; load them only at their precise triggers - `captain-hold-lifecycle` - load before treating an investigation or visual review as complete, before ending a visual review that exposed a captain decision, when recording or routing the captain's answer, and on any `RECORD DIVERGENCE` line from the wake drain. - `process-event-sources` - load before arming a long-polling source, before registering a deterministic condition->action watch (do X as soon as Y is true), on any `procevent ` check wake, and on any `process-event source stranded` or `process-event source failed to start` check wake. Never run a registered source's blocking command yourself in a conversational turn. +- `work-ledger` - load on any `check: work-ledger:` wake, and before writing a card's rating or parent into its backlog title. - `fmx-respond` - load on an `x-mention ` `check:` wake to handle the mention, on an `x-mode-error ...` `check:` wake to report the Relay configuration blocker, on a `public-followup ...` `check:` wake or a startup-surfaced public commitment, and on any milestone or terminal wake for a Relay-linked task before posting its completion follow-up; relevant only when Relay is on. - `firstmate-codexapp` - load before coordinating a visible Codex Desktop thread, evaluating a Codex App backend request, or reconciling Codex Desktop host-tool smoke evidence for Firstmate work. - `firstmate-coding-guidelines` - load before changing firstmate's shared, tracked material, as defined by section 1's list, whether editing directly or briefing a crewmate for a firstmate-repo task. diff --git a/bin/fm-busy-event.sh b/bin/fm-busy-event.sh index aa4bfee82f3..0281e41f665 100755 --- a/bin/fm-busy-event.sh +++ b/bin/fm-busy-event.sh @@ -35,6 +35,12 @@ # an old task from retiring a newly armed incarnation. A missing sidecar # is already retired, so any orphan record is removed idempotently. # +# Work ledger: inside the same lock, and only after the record write (or the +# retirement) succeeded, arm, apply, and retire each append one row to +# /work-ledger/.events. bin/fm-work-ledger-lib.sh owns that row +# format and its fail-open rule: a failed append never changes this script's +# exit code or output, so capture can never block or fail a turn. +# # Exit codes: 0 applied; 1 refused (stale gen, unarmed task, lock timeout, # invalid input); 2 usage. Adapter hook command lines append `|| true` so a # refusal never breaks the harness's own lifecycle. @@ -55,6 +61,8 @@ EOF SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" # shellcheck source=bin/fm-busy-lib.sh . "$SCRIPT_DIR/fm-busy-lib.sh" +# shellcheck source=bin/fm-work-ledger-lib.sh +. "$SCRIPT_DIR/fm-work-ledger-lib.sh" CMD=${1:-} case "$CMD" in @@ -152,6 +160,30 @@ write_record() { # mv -f "$tmp" "$REC" } +# Called with the lock held and the mutation already durable. +ledger_row() { # + fm_work_ledger_append "$STATE" "$ID" "$1" \ + "gen=$2 seq=$3 state=$4 source=${SOURCE:--} event=${EVENT:--}" +} + +# The seq of the record currently held for , or 0 when there is none. +record_seq() { # + local line field + [ -f "$REC" ] || { printf '0\n'; return 0; } + line=$(head -n 1 "$REC" 2>/dev/null || true) + case "$line" in + *" gen=$1 "*) + field=${line##* seq=} + field=${field%% *} + case "$field" in + ''|*[!0-9]*) printf '0\n' ;; + *) printf '%s\n' "$field" ;; + esac + ;; + *) printf '0\n' ;; + esac +} + old_umask=$(umask) umask 077 @@ -162,6 +194,7 @@ if [ "$CMD" = arm ]; then printf '%s\n' "$GEN" > "$GEN_FILE.tmp.$$" && mv -f "$GEN_FILE.tmp.$$" "$GEN_FILE" \ && write_record "$GEN" 1 && rm -f "$STATE/$ID.progress" } || { lock_release; umask "$old_umask"; echo "error: arm failed for $ID" >&2; exit 1; } + ledger_row arm "$GEN" 1 "$NEW_STATE" lock_release umask "$old_umask" printf '%s\n' "$GEN" @@ -208,12 +241,16 @@ if [ "$GEN" != "$CURRENT" ]; then exit 1 fi if [ "$CMD" = retire ]; then + RETIRE_SEQ=$(($(record_seq "$GEN") + 1)) rm -f "$GEN_FILE" "$REC" "$STATE/$ID.progress" || { lock_release umask "$old_umask" echo "error: busy-state retirement failed for $ID" >&2 exit 1 } + SOURCE=fm-retire + EVENT=retire + ledger_row retire "$GEN" "$RETIRE_SEQ" retired lock_release umask "$old_umask" exit 0 @@ -224,26 +261,14 @@ if [ "$CMD" = progress ]; then umask "$old_umask" exit 0 fi -OLD_SEQ=0 -if [ -f "$REC" ]; then - old_line=$(head -n 1 "$REC" 2>/dev/null || true) - case "$old_line" in - *" gen=$GEN "*) - old_seq_field=${old_line##* seq=} - old_seq_field=${old_seq_field%% *} - case "$old_seq_field" in - ''|*[!0-9]*) OLD_SEQ=0 ;; - *) OLD_SEQ=$old_seq_field ;; - esac - ;; - esac -fi +OLD_SEQ=$(record_seq "$GEN") write_record "$GEN" $((OLD_SEQ + 1)) || { lock_release umask "$old_umask" echo "error: record write failed for $ID" >&2 exit 1 } +ledger_row turn "$GEN" $((OLD_SEQ + 1)) "$NEW_STATE" lock_release umask "$old_umask" exit 0 diff --git a/bin/fm-merge-outcome-lib.sh b/bin/fm-merge-outcome-lib.sh index db279351145..6042da5c7b1 100755 --- a/bin/fm-merge-outcome-lib.sh +++ b/bin/fm-merge-outcome-lib.sh @@ -31,6 +31,8 @@ _FM_MERGE_OUTCOME_LIB_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" . "$_FM_MERGE_OUTCOME_LIB_DIR/fm-pr-lib.sh" # shellcheck source=bin/fm-parent-channel-lib.sh . "$_FM_MERGE_OUTCOME_LIB_DIR/fm-parent-channel-lib.sh" +# shellcheck source=bin/fm-work-ledger-lib.sh +. "$_FM_MERGE_OUTCOME_LIB_DIR/fm-work-ledger-lib.sh" # shellcheck disable=SC2034 # Public result consumed by sourcing callers. FM_MERGE_OUTCOME_ALREADY_RECORDED=false @@ -96,6 +98,11 @@ fm_merge_outcome_report() { # [autho return 0 fi + # The work ledger's merged row shares this operation's deduplication, so it + # inherits the same at-least-once shape: a retried publication may repeat the + # row, and the ledger's reader takes the first one. + fm_work_ledger_append "$state" "$id" merged "pr=$(fm_work_ledger_token "$FM_PR_URL")" + if [ -n "$destination" ]; then fm_parent_channel_append_once "$destination" "$line" || status=1 fi diff --git a/bin/fm-pr-check.sh b/bin/fm-pr-check.sh index c355233fd12..a312757d5ab 100755 --- a/bin/fm-pr-check.sh +++ b/bin/fm-pr-check.sh @@ -19,6 +19,8 @@ STATE="${FM_STATE_OVERRIDE:-$FM_HOME/state}" . "$SCRIPT_DIR/fm-wake-lib.sh" # shellcheck source=bin/fm-parent-channel-lib.sh . "$SCRIPT_DIR/fm-parent-channel-lib.sh" +# shellcheck source=bin/fm-work-ledger-lib.sh +. "$SCRIPT_DIR/fm-work-ledger-lib.sh" if [ "$#" -ne 2 ]; then echo "error: invalid PR check request" >&2 @@ -135,6 +137,10 @@ fm_pr_metadata_identity_parse "$META" || exit 1 && [ "$FM_PR_META_NUMBER" = "$NUMBER" ] || exit 1 fm_lock_release "$META_LOCK" META_LOCK_HELD=0 +# Stamp the PR-ready moment in the work ledger with this home's clock, since +# neither the meta line above nor the worker's status line carries a time +# (bin/fm-work-ledger-lib.sh; the append cannot fail this registration). +fm_work_ledger_append "$STATE" "$ID" pr-ready "pr=$(fm_work_ledger_token "$URL")" PR_POLL_PUBLISH_LOCK="$STATE/.pr-poll-publish-$ID.lock" fm_lock_acquire_wait "$PR_POLL_PUBLISH_LOCK" diff --git a/bin/fm-spawn.sh b/bin/fm-spawn.sh index fa8da51d9ea..f445a49eedb 100755 --- a/bin/fm-spawn.sh +++ b/bin/fm-spawn.sh @@ -497,6 +497,8 @@ fm_backlog_directory_present "$STATE" "state directory" || { . "$SCRIPT_DIR/fm-gate-refuse-lib.sh" # shellcheck source=bin/fm-busy-lib.sh . "$SCRIPT_DIR/fm-busy-lib.sh" +# shellcheck source=bin/fm-work-ledger-lib.sh +. "$SCRIPT_DIR/fm-work-ledger-lib.sh" # shellcheck source=bin/fm-cursor-lib.sh . "$SCRIPT_DIR/fm-cursor-lib.sh" # shellcheck source=bin/fm-pr-lib.sh @@ -4635,6 +4637,25 @@ fi fm_lock_release "$SPAWN_META_LOCK" SPAWN_META_LOCK_HELD=0 +# One work-ledger spawn row per launch, relaunches included, so a harness or +# model switch is on record beside the turns it explains. It is written only +# here, after the commit point, so a refused spawn leaves no row. The card's +# frozen rating and parent come from its backlog title, and a harness spawn did +# not arm the busy-state contract for is recorded as unmeasured rather than +# left to look like zero minutes (bin/fm-work-ledger-lib.sh owns the row format +# and guarantees the append cannot fail this spawn). +if [ "$KIND" != secondmate ]; then + LEDGER_TITLE= + LEDGER_RATING_READ=failed + if LEDGER_SHOW=$(fm_backlog_row_show "$DATA" "$ID" --full 2>/dev/null); then + LEDGER_RATING_READ=ok + LEDGER_TITLE=$(printf '%s\n' "$LEDGER_SHOW" | sed -n 's/^ title: *//p' | head -1) + fi + LEDGER_PARENT=$(fm_work_ledger_title_field "$LEDGER_TITLE" parent || true) + fm_work_ledger_append "$STATE_REAL" "$ID" spawn \ + "harness=$(fm_work_ledger_token "$HARNESS") model=$(fm_work_ledger_token "$MODEL") kind=$(fm_work_ledger_token "$KIND") parent=$(fm_work_ledger_token "$LEDGER_PARENT") capture=$(fm_work_ledger_harness_capture "$HARNESS" "${BUSY_GEN:-}") $(fm_work_ledger_rating_fields "$LEDGER_TITLE") rating_read=$LEDGER_RATING_READ" +fi + SPAWN_DELIVERY= [ -z "$MODE" ] || SPAWN_DELIVERY=" mode=$MODE yolo=$YOLO" echo "spawned $ID harness=$HARNESS kind=$KIND$SPAWN_DELIVERY window=$META_WINDOW worktree=$WT" diff --git a/bin/fm-teardown.sh b/bin/fm-teardown.sh index dcdac9ef2db..3e5cac81c04 100755 --- a/bin/fm-teardown.sh +++ b/bin/fm-teardown.sh @@ -2487,12 +2487,31 @@ EOF printf '%s\n' "$abs_home_path" } +# A retiring home takes its work ledger with it, and this is the one place a +# missed copy would lose that history for good, so the removal refuses until +# the ledger is in this home's store (bin/fm-work-ledger.sh owns the copy). A +# home that recorded nothing has nothing to lose and is not held up. +preserve_firstmate_home_work_ledger() { + local home=$1 label=$2 lane=${3:-} events + [ -n "$lane" ] || lane=$(cat "$home/$SUB_HOME_MARKER" 2>/dev/null || true) + for events in "$home/state/work-ledger"/*.events; do + [ -e "$events" ] || continue + if FM_HOME="$FM_HOME" FM_DATA_OVERRIDE="$DATA" "$SCRIPT_DIR/fm-work-ledger.sh" copy --home "$home" --lane "$lane" >/dev/null; then + return 0 + fi + echo "REFUSED: $label $home still holds a work ledger that could not be copied into $DATA/work-ledger; removing it would lose that history" >&2 + return 1 + done + return 0 +} + remove_firstmate_home() { local home=$1 label=$2 expected_id=${3:-} abs_home_path process_event_backup [ -n "$home" ] || return 0 [ -e "$home" ] || return 0 abs_home_path=$(validate_firstmate_home_for_removal "$home" "$label" "$expected_id") || return 1 [ -n "$abs_home_path" ] || return 0 + preserve_firstmate_home_work_ledger "$abs_home_path" "$label" "$expected_id" || return 1 process_event_backup=$(snapshot_firstmate_home_process_events "$abs_home_path" "$label") || return 1 if ! cleanup_firstmate_home_process_events "$abs_home_path" "$label"; then restore_firstmate_home_process_events "$abs_home_path" "$label" "$process_event_backup" || return $? diff --git a/bin/fm-test-run.sh b/bin/fm-test-run.sh index b939101c943..1e594a04f5e 100755 --- a/bin/fm-test-run.sh +++ b/bin/fm-test-run.sh @@ -300,7 +300,7 @@ family_for_basename() { fm-session-lock-ancestry.test.sh|fm-cursor-primary.test.sh|\ fm-supervision-events.test.sh|fm-turnend-guard.test.sh|fm-wake-daemon-lifecycle-e2e.test.sh|\ fm-wake-drain-unread-status.test.sh|\ - fm-tool-update-check.test.sh|\ + fm-tool-update-check.test.sh|fm-work-ledger.test.sh|\ fm-mail.test.sh|fm-mail-check.test.sh|\ fm-turnend-foreign-owner-arm-fix.test.sh|\ fm-wake-queue.test.sh|fm-watch-arm.test.sh|fm-watch-checkpoint.test.sh|fm-watch-recovery-loop.test.sh|\ @@ -839,6 +839,7 @@ tests/fm-watch-checkpoint.test.sh 6076 tests/fm-watch-recovery-loop.test.sh 58946 tests/fm-watch-triage.test.sh 697969 tests/fm-watcher-lock.test.sh 108940 +tests/fm-work-ledger.test.sh 5180 EOF } diff --git a/bin/fm-work-ledger-lib.sh b/bin/fm-work-ledger-lib.sh new file mode 100644 index 00000000000..c63f06bfe8e --- /dev/null +++ b/bin/fm-work-ledger-lib.sh @@ -0,0 +1,138 @@ +#!/usr/bin/env bash +# fm-work-ledger-lib.sh - the append side of the per-card work ledger. +# +# This file is the single owner of the ledger row format and of the rule that +# capture never costs a turn. bin/fm-work-ledger.sh owns the read side: the copy +# into the primary home, the cursor, and the three edges it may report. +# +# WHERE +# /work-ledger/.events, one append-only file per task id, in +# the home that spawned the task. It sits outside every worktree, so returning +# a worktree to its pool cannot lose it, and teardown removes state/.* by +# name, so a subdirectory survives the task. Both incarnations of a relaunched +# task land in the same file because the key is the task id and each turn row +# carries its own gen. +# +# ROWS +# Every row is one line of space-separated key=value tokens, written with a +# single short write under O_APPEND: +# +# v1 ts= id= row= +# +# row=arm|turn|retire gen= seq= state= +# source= event= +# Written only by bin/fm-busy-event.sh, inside its per-task lock and after +# the busy-state record write succeeded, so seq here is the record's seq. +# An event from a superseded gen is refused before it reaches the append. +# row=spawn harness= model= kind= parent= capture=supported|unsupported +# rating= rater= blind= rated_at= rating_read=ok|failed +# Written by bin/fm-spawn.sh once per launch, relaunches included. Only +# the FIRST spawn row of a task is its frozen rating; a rating that shows +# up on a later row was given after work began and is never the anchor. +# rating=none means unrated, which the reader counts and never drops. +# capture=unsupported means this harness reports no turn boundaries, so +# the card is unmeasured - never zero minutes. +# row=pr-ready pr= written by bin/fm-pr-check.sh +# row=merged pr= written by bin/fm-merge-outcome-lib.sh +# Both are stamped by firstmate's clock when firstmate observes them. +# +# FAILURE +# fm_work_ledger_append always returns 0 and prints nothing. A failed append +# adds one line to /work-ledger/.errors, which is created with the +# directory so it stays appendable after the directory itself stops accepting +# new files, and is otherwise dropped; the reader detects the missing row from +# the seq gap or from the live record running ahead, and marks the card +# incomplete. +# +# Sourced by bin/fm-busy-event.sh, bin/fm-spawn.sh, bin/fm-pr-check.sh, +# bin/fm-merge-outcome-lib.sh, and bin/fm-work-ledger.sh. No side effects on +# source. + +FM_WORK_LEDGER_DIRNAME=work-ledger + +fm_work_ledger_dir() { printf '%s/%s\n' "$1" "$FM_WORK_LEDGER_DIRNAME"; } + +# Reduce a value to one ledger token. Anything outside the token alphabet +# becomes `_`, and an empty value becomes `-`, so a row always splits cleanly on +# spaces and `=` no matter what a backlog title or a model name contained. +fm_work_ledger_token() { + local value=${1-} + value=${value//[!A-Za-z0-9._:+@\/-]/_} + [ -n "$value" ] || value=- + printf '%s\n' "${value:0:200}" +} + +# fm_work_ledger_harness_capture +# A harness is measured exactly when spawn armed the busy-state contract for it, +# because the arm is what its adapter wiring reports turn boundaries against. +# Reading the armed gen rather than re-listing harness names keeps this in step +# with bin/fm-spawn.sh's own arm decision. +fm_work_ledger_harness_capture() { + if [ -n "${2-}" ]; then + printf 'supported\n' + else + printf 'unsupported\n' + fi +} + +# fm_work_ledger_title_field <name> +# Print the value of a `(<name>: <value>)` field carried in a backlog title. +# Returns 1 when the field is absent. +fm_work_ledger_title_field() { + local title=$1 name=$2 rest + case "$title" in + *"($name: "*) ;; + *) return 1 ;; + esac + rest=${title#*"($name: "} + case "$rest" in + *")"*) ;; + *) return 1 ;; + esac + printf '%s\n' "${rest%%)*}" +} + +# fm_work_ledger_rating_fields <title> +# Print `rating=<v> rater=<v> blind=<v> rated_at=<v>` from a title carrying +# (rating: <value> by=<rater> blind=<yes|no> at=<when>) +# A title with no rating field, or a rating that is not a plain number, prints +# the unrated record. by=, blind= and at= are each optional. +fm_work_ledger_rating_fields() { + local title=$1 record value rater=- blind=- at=- word + if ! record=$(fm_work_ledger_title_field "$title" rating); then + printf 'rating=none rater=- blind=- rated_at=-\n' + return 0 + fi + value=${record%% *} + case "$value" in + ''|*[!0-9.]*|.|*.*.*) printf 'rating=none rater=- blind=- rated_at=-\n'; return 0 ;; + esac + for word in $record; do + case "$word" in + by=*) rater=$(fm_work_ledger_token "${word#by=}") ;; + blind=*) blind=$(fm_work_ledger_token "${word#blind=}") ;; + at=*) at=$(fm_work_ledger_token "${word#at=}") ;; + esac + done + printf 'rating=%s rater=%s blind=%s rated_at=%s\n' "$value" "$rater" "$blind" "$at" +} + +# fm_work_ledger_append <state-dir> <task-id> <row-kind> <fields> +fm_work_ledger_append() { + local state=${1-} id=${2-} kind=${3-} fields=${4-} dir old_umask + [ -n "$state" ] && [ -n "$id" ] && [ -n "$kind" ] || return 0 + case "$id" in *[!A-Za-z0-9._-]*) return 0 ;; esac + dir=$(fm_work_ledger_dir "$state") + old_umask=$(umask) + umask 077 + { + { [ -d "$dir" ] || { mkdir -p "$dir" && : >> "$dir/.errors"; }; } && + [ ! -L "$dir" ] && [ ! -L "$dir/$id.events" ] && + printf 'v1 ts=%s id=%s row=%s %s\n' "$(date +%s)" "$id" "$kind" "$fields" >> "$dir/$id.events" + } 2>/dev/null || { + [ -d "$dir" ] && [ ! -L "$dir" ] && [ ! -L "$dir/.errors" ] && + printf '%s %s %s\n' "$(date +%s)" "$id" "$kind" >> "$dir/.errors" + } 2>/dev/null || true + umask "$old_umask" + return 0 +} diff --git a/bin/fm-work-ledger.sh b/bin/fm-work-ledger.sh new file mode 100755 index 00000000000..bda1929ee3c --- /dev/null +++ b/bin/fm-work-ledger.sh @@ -0,0 +1,702 @@ +#!/usr/bin/env bash +# fm-work-ledger.sh - the read side of the per-card work ledger: copy every +# local home's ledger into this home's durable store, and tell firstmate about +# three edges and nothing else. +# +# Usage: +# fm-work-ledger.sh [check] +# fm-work-ledger.sh copy [--home <path> --lane <name>] +# fm-work-ledger.sh arm +# fm-work-ledger.sh disarm +# fm-work-ledger.sh --help +# +# bin/fm-work-ledger-lib.sh owns the row format and the capture side. This +# script never writes into a home it reads. +# +# STORE +# <data>/work-ledger/<lane>/<task-id>.events, where <lane> is `@primary` for +# this home and the registry id for each LOCAL secondmate in +# data/secondmates.md. A remote secondmate's state is on another host, so its +# lane is unmeasured and is not listed. The copy appends the source's complete +# lines the store does not already hold, so it is idempotent, ignores a +# trailing partial line, and runs under one store lock so a sweep and a +# retirement copy cannot interleave. +# +# CHECK +# `check` composes with the watcher's state-check contract: it prints a line +# only when firstmate should wake. The watcher does not deduplicate, so every +# line is an EDGE recorded in <data>/work-ledger/.cursor before it is printed, +# and a run in which nothing crossed an edge prints nothing at all. There is +# no periodic summary and no timer: elapsed time alone never produces output. +# A line is printed only after its cursor landed, so a store that cannot be +# written stays silent here and surfaces through the home's existing alarms +# instead of repeating every sweep. +# +# over-budget A rated, measured card's worker-active minutes crossed 3x, and +# later 6x, of (median minutes per point x rating). Once per +# level per card, and only while the card has a worker in +# flight, so a changed median never re-reports finished work; a +# card that crosses both inside one sweep reports only 6x. +# Minutes are the UNION of open turns across the card's +# incarnations and its sub-cards (tasks naming it as `parent`), +# and an open turn counts up to now only while its incarnation +# is still the live one. The median starts at +# FM_WORK_LEDGER_MEDIAN_MIN_PER_POINT (default 9.9) and is +# replaced by the store's own once 13 rated, complete, merged +# cards exist. Both are post hoc and the line says so. +# capture dead In some home, every in-flight task's ledger has trailed its +# live busy-state record for 2 consecutive sweeps, or the +# ledger directory stopped accepting writes while tasks are in +# flight. Once per episode; it re-arms when capture recovers. +# digest 5 more rated cards merged in a lane. At most one per lane per +# sweep. It carries pace (points per worker-active hour), active +# share, mean rating and points per wall hour, each against the +# previous digest, plus counts of what was left out. +# check error The evaluation itself failed. Once per distinct failure. +# +# Nothing is reported per merge, per harness, per model, or per agent. +# +# MEASUREMENT RULES +# A card with a seq gap, a live record ahead of its ledger, a turn-closing +# event with no turn open, or a turn left open by an incarnation that is gone +# is INCOMPLETE. A card launched on a harness with no turn capture is +# UNMEASURED. A card whose first spawn row carries no rating is UNRATED. None +# of the three enters pace, none is imputed or read as zero, and each is +# counted in the digest. +# These are turn-bracketed minutes. They are a different measurement from +# transcript-gap minutes and the two series must not be joined. +# +# `arm` writes state/work-ledger.check.sh and binds it with +# fm-check-register.sh; it refuses in a secondmate home, because the lane being +# measured must not be the one reading its own pace. `disarm` retires the shim. +# Secondmate retirement calls `copy --home <path> --lane <id>` and refuses to +# remove the home when it fails. +# +# Each check run touches <data>/work-ledger/.last-run so a check that stopped +# running is visible by its age. +set -u +export LC_ALL=C + +SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" +FM_HOME="${FM_HOME:-${FM_ROOT_OVERRIDE:-$(cd "$SCRIPT_DIR/.." && pwd)}}" +STATE="${FM_STATE_OVERRIDE:-$FM_HOME/state}" +DATA="${FM_DATA_OVERRIDE:-$FM_HOME/data}" +STORE="$DATA/work-ledger" +CURSOR="$STORE/.cursor" +STORE_LOCK="$STORE/.lock" +PRIMARY_LANE=@primary +SUB_HOME_MARKER=.fm-secondmate-home +CHECK_ID=work-ledger +CHECK_SHIM="$STATE/$CHECK_ID.check.sh" +REGISTER_BIN="$SCRIPT_DIR/fm-check-register.sh" +UNREGISTER_BIN="$SCRIPT_DIR/fm-check-unregister.sh" + +# shellcheck source=bin/fm-work-ledger-lib.sh +. "$SCRIPT_DIR/fm-work-ledger-lib.sh" +# shellcheck source=bin/fm-busy-lib.sh +. "$SCRIPT_DIR/fm-busy-lib.sh" +# shellcheck source=bin/fm-pr-lib.sh +. "$SCRIPT_DIR/fm-pr-lib.sh" +# shellcheck source=bin/fm-check-lib.sh +. "$SCRIPT_DIR/fm-check-lib.sh" +# shellcheck source=bin/fm-secondmate-registry-lib.sh +. "$SCRIPT_DIR/fm-secondmate-registry-lib.sh" + +usage() { + cat <<'EOF' +usage: + fm-work-ledger.sh [check] copy local ledgers, then print only new edges (silent otherwise) + fm-work-ledger.sh copy [--home <path> --lane <name>] + copy every local home's ledger, or one named home's, into this home's store + fm-work-ledger.sh arm write and register state/work-ledger.check.sh (primary home only) + fm-work-ledger.sh disarm retire the check shim and its trust binding + fm-work-ledger.sh --help print this help +See the header comment for the store, the edges, and the measurement rules. +EOF +} + +die_usage() { + printf 'fm-work-ledger: %s\n' "$1" >&2 + usage >&2 + exit 2 +} + +if [ "$(uname)" = Darwin ]; then + file_mtime() { /usr/bin/stat -f %m "$1" 2>/dev/null; } +else + file_mtime() { stat -c %Y "$1" 2>/dev/null; } +fi + +store_prepare() { + [ -d "$DATA" ] && [ ! -L "$DATA" ] || return 1 + if [ ! -d "$STORE" ]; then + (umask 077; mkdir -p "$STORE") 2>/dev/null || return 1 + fi + [ ! -L "$STORE" ] +} + +STORE_LOCK_HELD=0 +store_lock() { + local tries=0 now mtime + while ! mkdir "$STORE_LOCK" 2>/dev/null; do + tries=$((tries + 1)) + if [ "$tries" -ge 100 ]; then + now=$(date +%s) + mtime=$(file_mtime "$STORE_LOCK" || true) + case "$mtime" in ''|*[!0-9]*) mtime=$now ;; esac + if [ $((now - mtime)) -ge "${FM_WORK_LEDGER_LOCK_STALE_SECS:-120}" ]; then + rmdir "$STORE_LOCK" 2>/dev/null || true + mkdir "$STORE_LOCK" 2>/dev/null && break + fi + return 1 + fi + sleep 0.05 + done + STORE_LOCK_HELD=1 + return 0 +} +store_unlock() { + [ "$STORE_LOCK_HELD" = 1 ] || return 0 + rmdir "$STORE_LOCK" 2>/dev/null || true + STORE_LOCK_HELD=0 +} + +lane_valid() { + case "$1" in + "$PRIMARY_LANE") return 0 ;; + ''|.|..|*[!A-Za-z0-9._-]*) return 1 ;; + esac + return 0 +} + +# Print `<lane><TAB><home>` for this home and every local registered secondmate. +local_homes() { + local reg="$DATA/secondmates.md" line + printf '%s\t%s\n' "$PRIMARY_LANE" "$FM_HOME" + [ -f "$reg" ] && [ ! -L "$reg" ] || return 0 + while IFS= read -r line || [ -n "$line" ]; do + secondmate_registry_parse_line "$line" || continue + [ "$SECONDMATE_REGISTRY_REMOTE" = 0 ] || continue + lane_valid "$SECONDMATE_REGISTRY_ID" || continue + [ "$SECONDMATE_REGISTRY_ID" != "$PRIMARY_LANE" ] || continue + printf '%s\t%s\n' "$SECONDMATE_REGISTRY_ID" "$SECONDMATE_REGISTRY_HOME" + done < "$reg" +} + +# Snapshot one home's in-flight incarnations as `<id> <gen> <seq>` lines, plus +# a `!unwritable` line when its ledger directory cannot take a new row. This is +# read BEFORE the ledger is copied: the writer updates the record first and the +# ledger second under one lock, so a ledger copied after this read can only be +# level with or ahead of what was snapshotted unless a row was really lost. +snapshot_live() { # <home-state-dir> <dest-file> + local state=$1 dest=$2 gen_file id gen rec line seq dir + : > "$dest" || return 1 + [ -d "$state" ] || return 0 + for gen_file in "$state"/*.busy-gen; do + [ -f "$gen_file" ] || continue + id=$(basename "$gen_file" .busy-gen) + case "$id" in ''|*[!A-Za-z0-9._-]*) continue ;; esac + gen=$(fm_busy_current_gen "$state" "$id") || continue + rec=$(fm_busy_record_path "$state" "$id") + line=$(head -n 1 "$rec" 2>/dev/null || true) + seq=0 + case "$line" in + *" gen=$gen "*) + seq=${line##* seq=} + seq=${seq%% *} + case "$seq" in ''|*[!0-9]*) seq=0 ;; esac + ;; + esac + printf '%s %s %s\n' "$id" "$gen" "$seq" >> "$dest" || return 1 + done + dir=$(fm_work_ledger_dir "$state") + if [ -s "$dest" ] && [ -e "$dir" ] && { [ ! -d "$dir" ] || [ ! -w "$dir" ]; }; then + printf '!unwritable - 0\n' >> "$dest" || return 1 + fi + return 0 +} + +# Append to the store every complete source line it does not already hold. +copy_file() { # <src> <dest> + local src=$1 dest=$2 lines + [ -f "$src" ] && [ ! -L "$src" ] || return 0 + [ ! -L "$dest" ] || return 1 + lines=$(wc -l < "$src") || return 1 + lines=${lines//[!0-9]/} + [ -n "$lines" ] && [ "$lines" -gt 0 ] || return 0 + [ -e "$dest" ] || (umask 077; : > "$dest") || return 1 + head -n "$lines" "$src" | awk -v dest="$dest" ' + BEGIN { while ((getline held < dest) > 0) seen[held] = 1; close(dest) } + !($0 in seen) { seen[$0] = 1; print } + ' >> "$dest" +} + +copy_home() { # <lane> <home> + local lane=$1 home=$2 src dest file + lane_valid "$lane" || return 1 + [ -d "$home" ] || return 0 + dest="$STORE/$lane" + if [ ! -d "$dest" ]; then + (umask 077; mkdir -p "$dest") 2>/dev/null || return 1 + fi + [ ! -L "$dest" ] || return 1 + snapshot_live "$home/state" "$dest/.live.tmp.$$" || { rm -f -- "$dest/.live.tmp.$$"; return 1; } + mv -f -- "$dest/.live.tmp.$$" "$dest/.live" || { rm -f -- "$dest/.live.tmp.$$"; return 1; } + src=$(fm_work_ledger_dir "$home/state") + [ -d "$src" ] || return 0 + [ -r "$src" ] && [ -x "$src" ] || return 1 + for file in "$src"/*.events; do + [ -f "$file" ] || continue + copy_file "$file" "$dest/$(basename "$file")" || return 1 + done + return 0 +} + +copy_all() { + local lane home status=0 + while IFS=$'\t' read -r lane home; do + [ -n "$lane" ] || continue + copy_home "$lane" "$home" || status=1 + done <<EOF +$(local_homes) +EOF + return "$status" +} + +action_copy() { + local home='' lane='' status=0 + while [ $# -gt 0 ]; do + case "$1" in + --home) home=${2:-}; shift 2 || die_usage "--home needs a path" ;; + --lane) lane=${2:-}; shift 2 || die_usage "--lane needs a name" ;; + *) die_usage "unknown copy argument: $1" ;; + esac + done + if [ -n "$home" ] || [ -n "$lane" ]; then + [ -n "$home" ] && [ -n "$lane" ] || die_usage "--home and --lane go together" + lane_valid "$lane" || die_usage "invalid lane: $lane" + fi + store_prepare || { printf 'fm-work-ledger: the store %s is unavailable\n' "$STORE" >&2; return 1; } + store_lock || { printf 'fm-work-ledger: the store %s is locked\n' "$STORE" >&2; return 1; } + if [ -n "$home" ]; then + copy_home "$lane" "$home" || status=1 + else + copy_all || status=1 + fi + store_unlock + [ "$status" -eq 0 ] || printf 'fm-work-ledger: copy failed\n' >&2 + return "$status" +} + +# Evaluate the whole store against the cursor. Prints the new cursor to +# <cursor-out> and the lines to report to <lines-out>. +evaluate() { # <cursor-out> <lines-out> + local cursor_out=$1 lines_out=$2 lane_dir + local -a inputs=() + [ ! -f "$CURSOR" ] || inputs+=("$CURSOR") + for lane_dir in "$STORE"/*/; do + [ -d "$lane_dir" ] || continue + [ ! -f "${lane_dir}.live" ] || inputs+=("${lane_dir}.live") + for file in "$lane_dir"*.events; do + [ -f "$file" ] || continue + inputs+=("$file") + done + done + awk -v now="$(date +%s)" \ + -v seed_median="${FM_WORK_LEDGER_MEDIAN_MIN_PER_POINT:-9.9}" \ + -v own_median_cards="${FM_WORK_LEDGER_OWN_MEDIAN_CARDS:-13}" \ + -v digest_cards="${FM_WORK_LEDGER_DIGEST_CARDS:-5}" \ + -v cursor_path="$CURSOR" \ + -v cursor_out="$cursor_out" -v lines_out="$lines_out" ' + function field(name, i, n, kv) { + for (i = 1; i <= NF; i++) { + n = index($i, "=") + if (n && substr($i, 1, n - 1) == name) return substr($i, n + 1) + } + return "" + } + function interval(lane, card, from, to, k) { + if (to <= from) return + k = ++icount[lane, card] + istart[lane, card, k] = from + iend[lane, card, k] = to + } + function mark_incomplete(m) { incomplete[m] = 1 } + # Close whatever turn <m> has open at <at>. A turn closed this way ended + # with its incarnation rather than with a close event, so the card is + # incomplete. + function abandon(m, at) { + if (open_at[m] == "") return + interval(mlane[m], m, open_at[m], at) + open_at[m] = "" + mark_incomplete(m) + } + # Minutes in the union of a lane/card interval set, clipped to [lo, hi]. + function union_minutes(lane, key, lo, hi, n, i, j, s, e, cs, ce, total, a, b) { + n = icount[lane, key] + for (i = 1; i <= n; i++) { us[i] = istart[lane, key, i]; ue[i] = iend[lane, key, i] } + for (i = 2; i <= n; i++) { + s = us[i]; e = ue[i] + for (j = i - 1; j >= 1 && us[j] > s; j--) { us[j + 1] = us[j]; ue[j + 1] = ue[j] } + us[j + 1] = s; ue[j + 1] = e + } + total = 0; cs = ""; ce = "" + for (i = 1; i <= n; i++) { + a = us[i]; b = ue[i] + if (hi != "" && b > hi) b = hi + if (lo != "" && a < lo) a = lo + if (b <= a) continue + if (cs == "") { cs = a; ce = b } + else if (a <= ce) { if (b > ce) ce = b } + else { total += ce - cs; cs = a; ce = b } + } + if (cs != "") total += ce - cs + return total / 60 + } + function ratio(current, previous) { + if (previous == "" || previous + 0 == 0 || current + 0 == 0) return "" + if (current >= previous) return sprintf(", x%.2f", current / previous) + return sprintf(", /%.2f", previous / current) + } + function versus(current, previous) { + if (previous == "" || previous == "-") return "" + return sprintf(" (prev %.2f%s)", previous, ratio(current, previous)) + } + + BEGIN { + # Events that close exactly one turn, so one arriving with no turn open + # means the open was never seen. Other idle events (a session end, an + # interrupt, a repeated status) legitimately arrive while already idle. + strict_close["stop"] = 1; strict_close["stop-failure"] = 1; strict_close["after-agent"] = 1 + } + FILENAME == cursor_path { + if ($1 == "budget") budget_level[$2, $3] = $4 + else if ($1 == "capture") { capture_streak[$2] = $3; capture_fired[$2] = $4 } + else if ($1 == "digested") digested[$2, $3] = 1 + else if ($1 == "digest") { d_end[$2] = $3; d_pace[$2] = $4; d_share[$2] = $5; d_mean[$2] = $6; d_wall[$2] = $7 } + next + } + { + parts = split(FILENAME, path, "/") + lane = path[parts - 1] + name = path[parts] + if (!(lane in lanes)) { lanes[lane] = 1; lane_order[++lane_count] = lane } + } + name == ".live" { + if ($1 == "!unwritable") { unwritable[lane] = 1; next } + live_count[lane]++ + live_id[lane, live_count[lane]] = $1 + live_gen[lane, $1] = $2 + live_seq[lane, $1] = $3 + next + } + $1 != "v1" { next } + { + id = name + sub(/\.events$/, "", id) + m = lane SUBSEP id + if (!(m in mlane)) { mlane[m] = lane; mid[m] = id; member_order[++member_count] = m } + ts = field("ts") + 0 + row = field("row") + } + row == "spawn" { + if (!(m in spawned)) { + spawned[m] = ts + rating[m] = field("rating") + rater[m] = field("rater") + parent[m] = field("parent") + } + if (field("capture") != "supported") unmeasured[m] = 1 + next + } + row == "pr-ready" { if (!(m in ready_at)) ready_at[m] = ts; next } + row == "merged" { if (!(m in merged_at)) merged_at[m] = ts; next } + row == "arm" || row == "turn" || row == "retire" { + gen = field("gen"); seq = field("seq") + 0; st = field("state") + if (gen != cur_gen[m]) { + abandon(m, last_ts[m]) + cur_gen[m] = gen + if (seq != 1) mark_incomplete(m) + } else if (seq != last_seq[m] + 1) mark_incomplete(m) + last_seq[m] = seq + last_ts[m] = ts + if (st == "busy") { + if (open_at[m] == "") open_at[m] = ts + } else if (open_at[m] != "") { + interval(lane, m, open_at[m], ts) + open_at[m] = "" + } else if (row == "turn" && st == "idle" && (field("event") in strict_close)) mark_incomplete(m) + next + } + + END { + # Settle each member: a turn still open counts to now only while its + # incarnation is the live one, and a live record ahead of the ledger + # means rows were lost. + for (x = 1; x <= member_count; x++) { + m = member_order[x]; lane = mlane[m]; id = mid[m] + is_live = ((lane, id) in live_gen) + if (is_live && live_gen[lane, id] == cur_gen[m]) { + if (live_seq[lane, id] > last_seq[m]) { mark_incomplete(m); lag[lane] += live_seq[lane, id] - last_seq[m]; lagging[lane]++ } + if (open_at[m] != "") { interval(lane, m, open_at[m], now); open_at[m] = "" } + } else if (is_live) { + mark_incomplete(m); lag[lane] += live_seq[lane, id]; lagging[lane]++ + abandon(m, last_ts[m]) + } else abandon(m, last_ts[m]) + ledgered[lane, id] = 1 + } + for (x = 1; x <= lane_count; x++) { + lane = lane_order[x] + for (y = 1; y <= live_count[lane]; y++) { + id = live_id[lane, y] + if (!((lane, id) in ledgered)) { lag[lane] += live_seq[lane, id]; lagging[lane]++ } + } + } + + # Fold members into cards. A member naming a parent belongs to that card; + # the card takes its rating from its own ledger when it has one, and + # otherwise from the first sub-card spawned. + for (x = 1; x <= member_count; x++) { + m = member_order[x]; lane = mlane[m] + card = (parent[m] != "" && parent[m] != "-") ? parent[m] : mid[m] + c = lane SUBSEP card + if (!(c in clane)) { clane[c] = lane; cname[c] = card; card_order[++card_count] = c } + members[c]++ + if (mid[m] != card) subcards[c]++ + for (k = 1; k <= icount[lane, m]; k++) { + interval(lane, "card:" card, istart[lane, m, k], iend[lane, m, k]) + interval(lane, "lane", istart[lane, m, k], iend[lane, m, k]) + } + if (incomplete[m]) c_incomplete[c] = 1 + if (unmeasured[m]) c_unmeasured[c] = 1 + if (m in spawned) { + if (mid[m] == card) { c_own[c] = 1; c_rating[c] = rating[m]; c_rater[c] = rater[m] } + else if (!c_own[c] && (c_first[c] == "" || spawned[m] < c_first[c])) { c_rating[c] = rating[m]; c_rater[c] = rater[m] } + if (c_first[c] == "" || spawned[m] < c_first[c]) c_first[c] = spawned[m] + } else c_incomplete[c] = 1 + if (m in merged_at) { if (merged_at[m] > c_merged[c]) c_merged[c] = merged_at[m] } + else if ((m in ready_at) || ((lane, mid[m]) in live_gen)) c_pending[c] = 1 + if ((lane, mid[m]) in live_gen) c_live[c] = 1 + } + for (x = 1; x <= card_count; x++) { + c = card_order[x] + c_min[c] = union_minutes(clane[c], "card:" cname[c], "", "") + c_rated[c] = (c_rating[c] != "" && c_rating[c] != "none" && c_rating[c] + 0 > 0) + c_done[c] = (c_merged[c] != "" && !c_pending[c]) + if (c_done[c] && c_rated[c] && !c_incomplete[c] && !c_unmeasured[c] && c_min[c] > 0) + sample[++samples] = c_min[c] / c_rating[c] + } + median = seed_median + 0; median_source = "inherited" + if (samples >= own_median_cards + 0) { + for (i = 2; i <= samples; i++) { + v = sample[i] + for (j = i - 1; j >= 1 && sample[j] > v; j--) sample[j + 1] = sample[j] + sample[j + 1] = v + } + median = (samples % 2) ? sample[(samples + 1) / 2] : (sample[samples / 2] + sample[samples / 2 + 1]) / 2 + median_source = "ledger" + } + + # Edge 1: over budget. + for (x = 1; x <= card_count; x++) { + c = card_order[x]; lane = clane[c]; card = cname[c] + level = budget_level[lane, card] + 0 + if (c_rated[c] && !c_unmeasured[c] && c_live[c] && median > 0) { + multiple = c_min[c] / (median * c_rating[c]) + crossed = (multiple >= 6) ? 6 : ((multiple >= 3) ? 3 : 0) + if (crossed > level) { + level = crossed + printf("work-ledger: over-budget %s in %s (rated %s, rater %s): %.0f worker-min = %.1fx budget, crossed %dx (post hoc %s median %.1f min/pt); %d sub-cards; capture %s\n", \ + card, lane, c_rating[c], (c_rater[c] == "" ? "-" : c_rater[c]), c_min[c], multiple, crossed, median_source, median, subcards[c] + 0, \ + (c_incomplete[c] ? "incomplete" : "complete")) > lines_out + } + } + if (level > 0) printf("budget %s %s %d\n", lane, card, level) > cursor_out + } + + # Edge 2: capture dead, per home. + for (x = 1; x <= lane_count; x++) { + lane = lane_order[x] + dead = (live_count[lane] > 0 && (unwritable[lane] || lagging[lane] >= live_count[lane])) + streak = dead ? capture_streak[lane] + 1 : 0 + fired = dead ? capture_fired[lane] + 0 : 0 + if (dead && streak >= 2 && !fired) { + fired = 1 + printf("work-ledger: capture dead in %s: %d tasks, ledger %d rows behind busy-state%s\n", \ + lane, live_count[lane], lag[lane] + 0, (unwritable[lane] ? "; ledger directory not writable" : "")) > lines_out + } + if (streak > 0) printf("capture %s %d %d\n", lane, streak, fired) > cursor_out + } + + # Edge 3: one digest per lane once enough rated cards have merged. + for (x = 1; x <= lane_count; x++) { + lane = lane_order[x] + n = 0 + for (y = 1; y <= card_count; y++) { + c = card_order[y] + if (clane[c] != lane || !c_done[c] || !c_rated[c] || digested[lane, cname[c]]) continue + due[++n] = c + } + for (i = 2; i <= n; i++) { + v = due[i] + for (j = i - 1; j >= 1 && c_merged[due[j]] > c_merged[v]; j--) due[j + 1] = due[j] + due[j + 1] = v + } + if (n >= digest_cards + 0) { + window_end = c_merged[due[digest_cards + 0]] + window_start = d_end[lane] + if (window_start == "") { + for (i = 1; i <= digest_cards + 0; i++) + if (window_start == "" || c_first[due[i]] < window_start) window_start = c_first[due[i]] + } + points = 0; all_points = 0; minutes = 0; n_incomplete = 0; n_unmeasured = 0; n_unrated = 0 + for (i = 1; i <= digest_cards + 0; i++) { + c = due[i] + digested[lane, cname[c]] = 1 + all_points += c_rating[c] + if (c_unmeasured[c]) n_unmeasured++ + else if (c_incomplete[c]) n_incomplete++ + else { points += c_rating[c]; minutes += c_min[c] } + } + for (y = 1; y <= card_count; y++) { + c = card_order[y] + if (clane[c] != lane || !c_done[c] || c_rated[c] || digested[lane, cname[c]] || c_merged[c] > window_end) continue + digested[lane, cname[c]] = 1 + n_unrated++ + } + wall_hours = (window_end - window_start) / 3600 + pace = (minutes > 0) ? points / (minutes / 60) : 0 + share = (wall_hours > 0) ? union_minutes(lane, "lane", window_start, window_end) / 60 / wall_hours : 0 + mean = all_points / (digest_cards + 0) + per_wall = (wall_hours > 0) ? all_points / wall_hours : 0 + printf("work-ledger: digest %s %s..%s (%d rated cards): pace %s pts/active-h%s; active share %.2f%s; mean rating %.2f%s; points/wall-h %.2f%s. Excluded from pace: %d unrated, %d incomplete, %d unmeasured\n", \ + lane, cname[due[1]], cname[due[digest_cards + 0]], digest_cards + 0, \ + (minutes > 0 ? sprintf("%.2f", pace) : "n/a"), (minutes > 0 ? versus(pace, d_pace[lane]) : ""), \ + share, versus(share, d_share[lane]), mean, versus(mean, d_mean[lane]), per_wall, versus(per_wall, d_wall[lane]), \ + n_unrated, n_incomplete, n_unmeasured) > lines_out + d_end[lane] = window_end + if (minutes > 0) d_pace[lane] = pace + d_share[lane] = share; d_mean[lane] = mean; d_wall[lane] = per_wall + } + if (d_end[lane] != "") + printf("digest %s %s %s %s %s %s\n", lane, d_end[lane], (d_pace[lane] == "" ? "-" : d_pace[lane]), d_share[lane], d_mean[lane], d_wall[lane]) > cursor_out + for (y = 1; y <= card_count; y++) { + c = card_order[y] + if (clane[c] == lane && digested[lane, cname[c]]) printf("digested %s %s\n", lane, cname[c]) > cursor_out + } + } + } + ' ${inputs[@]+"${inputs[@]}"} < /dev/null +} + +# Report an evaluation failure once per distinct failure, never per sweep. The +# marker is what makes it an edge, so a failure that cannot be recorded is not +# printed. +check_error() { # <message> + local message=$1 marker="$STATE/.work-ledger-check-error" + [ "$(cat "$marker" 2>/dev/null || true)" != "$message" ] || return 0 + (umask 077; printf '%s\n' "$message" > "$marker") 2>/dev/null || return 0 + printf 'work-ledger: check error: %s\n' "$message" +} + +action_check() { + local cursor_tmp lines_tmp + store_prepare || { check_error "the store $STORE is unavailable"; return 0; } + store_lock || { check_error "the store $STORE stayed locked"; return 0; } + (umask 077; : > "$STORE/.last-run") 2>/dev/null || true + # A home whose ledger cannot be copied is not a check error by itself: the + # capture-dead edge below is what reports a home that stopped recording. + copy_all || true + cursor_tmp=$(umask 077; mktemp "$STORE/.cursor.XXXXXX" 2>/dev/null) || { + store_unlock; check_error "the cursor in $STORE cannot be written"; return 0 + } + lines_tmp=$(umask 077; mktemp "$STORE/.lines.XXXXXX" 2>/dev/null) || { + rm -f -- "$cursor_tmp"; store_unlock; check_error "the cursor in $STORE cannot be written"; return 0 + } + if ! evaluate "$cursor_tmp" "$lines_tmp" 2>/dev/null; then + rm -f -- "$cursor_tmp" "$lines_tmp" + store_unlock + check_error "the ledger in $STORE could not be evaluated" + return 0 + fi + if ! mv -f -- "$cursor_tmp" "$CURSOR"; then + rm -f -- "$cursor_tmp" "$lines_tmp" + store_unlock + check_error "the cursor in $STORE cannot be written" + return 0 + fi + rm -f -- "$STATE/.work-ledger-check-error" 2>/dev/null || true + cat "$lines_tmp" + rm -f -- "$lines_tmp" + store_unlock + return 0 +} + +shim_content() { + local home=$1 + printf '%s\n' \ + '#!/usr/bin/env bash' \ + '# Auto-generated by fm-work-ledger.sh - work ledger poll shim.' \ + '# The watcher validates these bytes, then dispatches the trusted check script.' \ + "export FM_HOME=$(printf '%q' "$home")" \ + "exec $(printf '%q' "$SCRIPT_DIR/fm-work-ledger.sh") check" +} + +action_arm() { + local home want device tmp + home=$(CDPATH='' cd -- "$FM_HOME" 2>/dev/null && pwd -P) || { + printf 'fm-work-ledger: cannot resolve FM_HOME %s\n' "$FM_HOME" >&2 + return 1 + } + if [ -e "$home/$SUB_HOME_MARKER" ]; then + printf 'fm-work-ledger: %s is a secondmate home; the ledger check runs in the primary home only\n' "$home" >&2 + return 1 + fi + [ -d "$STATE" ] && [ ! -L "$STATE" ] || { printf 'fm-work-ledger: state directory %s is unavailable\n' "$STATE" >&2; return 1; } + if fm_custom_check_registered "$STATE" "$CHECK_ID" && [ "$(cat "$CHECK_SHIM" 2>/dev/null)" = "$(shim_content "$home")" ]; then + printf 'armed: state/%s.check.sh\n' "$CHECK_ID" + return 0 + fi + want=$(shim_content "$home") + device=$(fm_pr_file_device "$STATE") || return 1 + fm_pr_regular_destination_on_device_or_absent "$CHECK_SHIM" "$device" || { + printf 'fm-work-ledger: %s is not a plain file this home owns\n' "$CHECK_SHIM" >&2 + return 1 + } + tmp=$(umask 077; mktemp "$STATE/.fm-work-ledger-check.XXXXXX" 2>/dev/null) || return 1 + # An unregistered shim is not inert - the watcher rejects it every cycle and + # wakes firstmate - so a failed or interrupted arm leaves no shim behind. + trap 'rm -f -- "$tmp" "$CHECK_SHIM"; exit 1' HUP INT TERM + if ! printf '%s\n' "$want" > "$tmp" || ! chmod 0700 "$tmp" || ! mv -f -- "$tmp" "$CHECK_SHIM" \ + || ! FM_HOME="$home" "$REGISTER_BIN" "$CHECK_ID" >/dev/null; then + rm -f -- "$tmp" "$CHECK_SHIM" + trap - HUP INT TERM + printf 'fm-work-ledger: could not arm %s\n' "$CHECK_SHIM" >&2 + return 1 + fi + trap - HUP INT TERM + printf 'armed: state/%s.check.sh\n' "$CHECK_ID" +} + +action_disarm() { + if [ -e "$CHECK_SHIM" ] || [ -e "$STATE/$CHECK_ID.check-trust" ]; then + FM_HOME="$FM_HOME" "$UNREGISTER_BIN" "$CHECK_ID" >/dev/null || { + printf 'fm-work-ledger: could not retire %s\n' "$CHECK_SHIM" >&2 + return 1 + } + fi + printf 'disarmed: state/%s.check.sh\n' "$CHECK_ID" +} + +trap store_unlock EXIT + +ACTION=${1:-check} +[ $# -eq 0 ] || shift +case "$ACTION" in + check) action_check ;; + copy) action_copy "$@" ;; + arm) action_arm ;; + disarm) action_disarm ;; + -h|--help) usage ;; + *) die_usage "unknown action: $ACTION" ;; +esac diff --git a/docs/configuration.md b/docs/configuration.md index f23b741243e..63a9e399fea 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -553,6 +553,24 @@ The locked bootstrap inheritance pass uses the same placement-specific behavior; That live discovery starts from `state/*.meta` records with `kind=secondmate`; `data/secondmates.md` only backfills `home=` for older or incomplete meta records. Skipped items, such as a destination checkout that does not yet gitignore the item, are visible warnings but not hard failures. +## Work ledger (state/work-ledger/, data/work-ledger/) + +Firstmate records what each card costs in worker time as the work happens, so a card taking far longer than its difficulty warrants is visible before it finishes rather than rebuilt afterwards. +Nothing has to be remembered for this to happen: the rows are written by the same turn-boundary writer every measured worker runtime already calls, by dispatch, by PR registration, and by the merge outcome. +`bin/fm-work-ledger-lib.sh`'s header owns the row format and the rule that capture can never block or fail a turn, and `bin/fm-work-ledger.sh`'s header owns the store, the three reported edges, and the measurement rules. + +Each home writes `state/work-ledger/<task-id>.events`, which outlives the task, its local copy, and any relaunch. +The primary home copies every local second mate's ledger into `data/work-ledger/<lane>/`, and retiring a second mate copies its ledger first and refuses the retirement when that copy fails. +Remote second mates are not covered, and a worker runtime that reports no turn boundaries is recorded as unmeasured rather than as zero. + +Arm the check once, in the primary home only, with `bin/fm-work-ledger.sh arm`; it refuses in a second mate's home, and `disarm` ends it. +Like the watched tool check below, a registered check is itself a reason to keep watching. +The check is edge-triggered and has no timer: a run in which nothing changed prints nothing, and each over-budget level, capture failure, and five-card lane digest is reported once. +The [`work-ledger` skill](../.agents/skills/work-ledger/SKILL.md) owns what firstmate does with each report and the backlog title fields that carry a card's rating and parent. + +`FM_WORK_LEDGER_MEDIAN_MIN_PER_POINT` (default 9.9) is the inherited minutes-per-point median used until the store holds `FM_WORK_LEDGER_OWN_MEDIAN_CARDS` (default 13) rated, complete, merged cards, and `FM_WORK_LEDGER_DIGEST_CARDS` (default 5) sets the digest size. +All three thresholds are post hoc, and the reports label them so. + ## Watched tool updates (config/watched-tools.json) `config/watched-tools.json` is an optional local, gitignored list of the tools this home depends on. diff --git a/docs/documentation-audiences.json b/docs/documentation-audiences.json index e459e95006a..ba4976f645e 100644 --- a/docs/documentation-audiences.json +++ b/docs/documentation-audiences.json @@ -256,6 +256,10 @@ "path": ".agents/skills/updatefirstmate/SKILL.md", "audience": "agent-runtime" }, + { + "path": ".agents/skills/work-ledger/SKILL.md", + "audience": "agent-runtime" + }, { "path": ".greptile/rules.md", "audience": "maintainer-architecture" diff --git a/tests/fm-busy-adapter-wiring.test.sh b/tests/fm-busy-adapter-wiring.test.sh index c8967b4256d..40637dc001a 100755 --- a/tests/fm-busy-adapter-wiring.test.sh +++ b/tests/fm-busy-adapter-wiring.test.sh @@ -288,6 +288,35 @@ test_claude_hooks_stale_incarnation_harmless() { pass "claude hook events from a superseded incarnation are rejected without breaking the hook" } +# The spawn row carries the card's frozen rating and parent from its backlog +# title, and a card dispatched without a rating is recorded as unrated rather +# than dropped. +test_spawn_row_records_the_frozen_rating() { + local rec id=busy-led-1 out ledger + rec=$(make_spawn_case ledger-rated claude "$id") + read_case_record "$rec" + cp "$ROOT/.tasks.toml" "$HOME_DIR/.tasks.toml" + printf '%s\n' '# Backlog' '' '## In flight' '## Queued' \ + "- [ ] $id - Rated card (rating: 4.5 by=fresh-session blind=yes at=2026-09-18T02:08Z) (parent: busy-led-0) (kind: ship) (since 2026-09-18)" \ + '## Done' > "$HOME_DIR/data/backlog.md" + out=$(run_spawn "$HOME_DIR" "$WT_DIR" "$FAKEBIN_DIR" "$id" "$PROJ_DIR") + expect_code 0 $? "rated spawn should succeed: $out" + ledger="$HOME_DIR/state/work-ledger/$id.events" + assert_grep "id=$id row=spawn harness=claude " "$ledger" "spawn row missing" + assert_grep ' parent=busy-led-0 capture=supported rating=4.5 rater=fresh-session blind=yes rated_at=2026-09-18T02:08Z rating_read=ok' "$ledger" \ + "spawn row did not carry the frozen rating and parent" + assert_grep ' row=arm ' "$ledger" "a measured harness must record its arm" + + id=busy-led-2 + rec=$(make_spawn_case ledger-unrated claude "$id") + read_case_record "$rec" + out=$(run_spawn "$HOME_DIR" "$WT_DIR" "$FAKEBIN_DIR" "$id" "$PROJ_DIR") + expect_code 0 $? "unrated spawn should succeed: $out" + assert_grep ' capture=supported rating=none ' "$HOME_DIR/state/work-ledger/$id.events" \ + "a card with no rating must be recorded as unrated" + pass "the spawn row records the frozen rating, the parent, and an unrated card" +} + test_codex_unverified_until_a_semantic_source_exists() { local rec id=busy-cx-1 out state rec=$(make_spawn_case codex-unverified codex "$id") @@ -298,6 +327,11 @@ test_codex_unverified_until_a_semantic_source_exists() { assert_absent "$state/$id.busy-gen" "codex must not arm a busy contract with no verified semantic source" assert_absent "$WT_DIR/.codex/hooks.json" "codex must not install unverified busy hooks" assert_contains "$out" 'spawned '"$id"' harness=codex' "codex spawn did not complete normally" + # No turn boundaries can be observed, so the work ledger must say so rather + # than leave a card that reads as zero minutes. + assert_grep "id=$id row=spawn harness=codex " "$state/work-ledger/$id.events" "codex spawn wrote no work-ledger spawn row" + assert_grep ' capture=unsupported ' "$state/work-ledger/$id.events" "codex must be recorded as unmeasured" + assert_no_grep ' row=arm ' "$state/work-ledger/$id.events" "codex must not record turn rows it cannot observe" out=$(classify codex "$id" "$state") [ "$out" = "unknown codex-unverified" ] || fail "codex must classify 'unknown codex-unverified', got '$out'" out=$(fm_busy_classify tmux fake:w codex "$id" "$state" '• Working (6s • esc to interrupt)') @@ -434,5 +468,6 @@ test_gemini_hooks_stale_incarnation_harmless test_raw_gemini_launch_has_no_semantic_wiring test_gemini_is_refused_as_a_secondmate test_codex_unverified_until_a_semantic_source_exists +test_spawn_row_records_the_frozen_rating echo "all fm-busy-adapter-wiring tests passed" diff --git a/tests/fm-secondmate-lifecycle-e2e.test.sh b/tests/fm-secondmate-lifecycle-e2e.test.sh index 56b7ac3f1f5..bb685cc6f9b 100755 --- a/tests/fm-secondmate-lifecycle-e2e.test.sh +++ b/tests/fm-secondmate-lifecycle-e2e.test.sh @@ -302,6 +302,21 @@ phase_teardown() { rm -f "$HOME_DIR/state/pending-replies/aaaaaaaaaaaaaaaa" \ "$HOME_DIR/state/pending-replies/$other_corr" \ "$HOME_DIR/state/pending-replies/.delivery-confirmed-$other_corr" + # The retiring home holds a work ledger. Retirement must land it in the + # parent's store first, and must refuse rather than lose it when it cannot. + mkdir -p "$SUB/state/work-ledger" + printf 'v1 ts=100 id=card-1 row=spawn harness=claude model=- kind=ship parent=- capture=supported rating=3 rater=fresh blind=yes rated_at=- rating_read=ok\n' \ + > "$SUB/state/work-ledger/card-1.events" + : > "$HOME_DIR/data/work-ledger" + if PATH="$FAKEBIN:$PATH" FM_HOME="$HOME_DIR" FM_FAKE_TMUX_LOG="$LOG" FM_FAKE_TMUX_CAPTURE="$PANE" \ + "$ROOT/bin/fm-teardown.sh" design > "$TMP_ROOT/ledger-refusal.out" 2>&1; then + fail "local retirement removed a home whose work ledger could not be copied" + fi + assert_grep 'still holds a work ledger that could not be copied' "$TMP_ROOT/ledger-refusal.out" \ + "the work-ledger refusal did not say why" + assert_present "$SUB/state/work-ledger/card-1.events" "a refused retirement lost the work ledger" + assert_present "$HOME_DIR/state/design.meta" "a refused work-ledger retirement removed parent metadata" + rm -f "$HOME_DIR/data/work-ledger" printf 'confirmed:%s\n' "$corr" > "$HOME_DIR/state/.backlog-handoff-design.wake-pending" : > "$LOG" teardown_out=$(PATH="$FAKEBIN:$PATH" FM_HOME="$HOME_DIR" FM_FAKE_TMUX_LOG="$LOG" FM_FAKE_TMUX_CAPTURE="$PANE" \ @@ -310,6 +325,8 @@ phase_teardown() { printf '%s\n' "$teardown_out" | grep -F 'Backlog:' >/dev/null \ && fail "secondmate teardown emitted a main-backlog completion reminder" assert_absent "$SUB" "teardown did not remove the retired secondmate home" + assert_grep 'id=card-1 row=spawn' "$HOME_DIR/data/work-ledger/design/card-1.events" \ + "retirement removed the home without keeping its work ledger" assert_absent "$HOME_DIR/state/design.meta" "teardown did not clear the parent meta" assert_absent "$HOME_DIR/state/.backlog-handoff-design.wake-pending" \ "teardown left receiver wake state that could poison a replacement route" diff --git a/tests/fm-teardown.test.sh b/tests/fm-teardown.test.sh index 43fa7df5543..6e3d0ffb6ec 100755 --- a/tests/fm-teardown.test.sh +++ b/tests/fm-teardown.test.sh @@ -804,6 +804,41 @@ test_no_mistakes_origin_remote_allows() { pass "no-mistakes worktree with HEAD on origin is torn down (no regression)" } +# The work ledger outlives the task. Teardown removes state/<id>.* by name and +# retires the busy record, and neither may reach state/work-ledger/: the PR-ready +# stamp and the turn rows are the only durable record of what the card cost. +test_teardown_leaves_the_work_ledger_intact() { + local case_dir rc gen ledger + case_dir=$(make_case ledger-survives) + write_meta "$case_dir" no-mistakes ship + wt_commit "$case_dir" "shippable work" + git -C "$case_dir/wt" push -q origin fm/task-x1 + git -C "$case_dir/project" fetch -q origin + add_gh_pr_merged_for_head "$case_dir" "$(git -C "$case_dir/wt" rev-parse HEAD)" + ledger="$case_dir/state/work-ledger/task-x1.events" + gen=$("$ROOT/bin/fm-busy-event.sh" arm "$case_dir/state" task-x1) || fail "ledger-survives: arm failed" + "$ROOT/bin/fm-busy-event.sh" apply "$case_dir/state" task-x1 idle --gen "$gen" --source claude-hook --event stop \ + || fail "ledger-survives: apply failed" + FM_ROOT_OVERRIDE="$ROOT" FM_STATE_OVERRIDE="$case_dir/state" PATH="$case_dir/fakebin:$PATH" \ + "$PR_CHECK" task-x1 https://github.com/example/repo/pull/7 >/dev/null \ + || fail "ledger-survives: fm-pr-check failed" + assert_grep 'row=pr-ready pr=https://github.com/example/repo/pull/7' "$ledger" \ + "ledger-survives: fm-pr-check did not stamp the PR-ready row" + + set +e + run_teardown "$case_dir" > "$case_dir/stdout" 2> "$case_dir/stderr" + rc=$? + set -e + + expect_code 0 "$rc" "ledger-survives: teardown should succeed: $(cat "$case_dir/stderr")" + assert_absent "$case_dir/state/task-x1.busy-state" "ledger-survives: teardown did not retire the busy record" + assert_grep "row=arm gen=$gen seq=1" "$ledger" "ledger-survives: teardown lost the arm row" + assert_grep "row=turn gen=$gen seq=2 state=idle" "$ledger" "ledger-survives: teardown lost a turn row" + assert_grep 'row=pr-ready' "$ledger" "ledger-survives: teardown lost the PR-ready row" + assert_grep "row=retire gen=$gen seq=3" "$ledger" "ledger-survives: the retirement was not recorded" + pass "teardown retires the task and leaves its work ledger intact" +} + test_no_mistakes_truly_unpushed_refuses() { local case_dir rc case_dir=$(make_case nm-unpushed) @@ -3672,6 +3707,7 @@ test_teardown_manual_backend_leaves_the_backlog_to_the_operator test_local_only_truly_unpushed_refuses test_local_only_merged_to_local_main_allows test_no_mistakes_origin_remote_allows +test_teardown_leaves_the_work_ledger_intact test_no_mistakes_truly_unpushed_refuses test_local_only_force_overrides_unpushed test_secondmate_pr_registration_publishes_ready_line diff --git a/tests/fm-work-ledger.test.sh b/tests/fm-work-ledger.test.sh new file mode 100755 index 00000000000..cf5c0f979f2 --- /dev/null +++ b/tests/fm-work-ledger.test.sh @@ -0,0 +1,367 @@ +#!/usr/bin/env bash +# Tests for the per-card work ledger: the rows bin/fm-busy-event.sh appends at +# every turn boundary (bin/fm-work-ledger-lib.sh), and the copy, cursor, and +# edge-only reporting in bin/fm-work-ledger.sh. +# +# The property that matters most is silence. The watcher turns any output of a +# registered check into a wake and never deduplicates, so a check that repeats +# itself wakes firstmate every sweep forever. Every reporting case therefore +# runs the check a second time and asserts it prints nothing. +set -u + +# shellcheck source=tests/lib.sh +. "$(dirname "${BASH_SOURCE[0]}")/lib.sh" + +BUSY="$ROOT/bin/fm-busy-event.sh" +LEDGER="$ROOT/bin/fm-work-ledger.sh" +TMP_ROOT=$(fm_test_tmproot fm-work-ledger) + +make_home() { + local home="$TMP_ROOT/$1" + mkdir -p "$home/state" "$home/data" + printf '%s\n' "$home" +} + +run_check() { # <home> + env -u FM_STATE_OVERRIDE -u FM_DATA_OVERRIDE -u FM_ROOT_OVERRIDE FM_HOME="$1" "$LEDGER" check +} + +events() { printf '%s/state/work-ledger/%s.events\n' "$1" "$2"; } + +# write_rows <home> <id>: append rows given on stdin as `<ts> <row> <fields>`. +write_rows() { + local home=$1 id=$2 ts row fields + mkdir -p "$home/state/work-ledger" + while read -r ts row fields; do + [ -n "$ts" ] || continue + printf 'v1 ts=%s id=%s row=%s %s\n' "$ts" "$id" "$row" "$fields" >> "$(events "$home" "$id")" + done +} + +SPAWN_RATED='harness=claude model=opus kind=ship parent=- capture=supported rating=2 rater=fresh blind=yes rated_at=2026-09-18 rating_read=ok' + +test_turn_rows_follow_the_record() { + local home gen out + home=$(make_home rows) + gen=$("$BUSY" arm "$home/state" t1) + "$BUSY" apply "$home/state" t1 idle --gen "$gen" --source claude-hook --event stop + "$BUSY" apply "$home/state" t1 busy --gen "$gen" --source claude-hook --event user-prompt-submit + out=$(cat "$(events "$home" t1)") + assert_equals 3 "$(printf '%s\n' "$out" | wc -l | tr -d ' ')" "one row per arm and apply" + assert_contains "$out" "row=arm gen=$gen seq=1 state=busy source=fm-spawn event=launch-brief" "arm row" + assert_contains "$out" "row=turn gen=$gen seq=2 state=idle source=claude-hook event=stop" "close row" + assert_contains "$out" "row=turn gen=$gen seq=3 state=busy" "open row carries the record's seq" + assert_grep "seq=3 " "$home/state/t1.busy-state" "the record and the ledger agree on seq" + pass "arm and apply append one row each, numbered like the record" +} + +test_stale_incarnation_is_not_appended() { + local home old new before + home=$(make_home stale) + old=$("$BUSY" arm "$home/state" t1) + new=$("$BUSY" arm "$home/state" t1) + before=$(wc -l < "$(events "$home" t1)") + if "$BUSY" apply "$home/state" t1 idle --gen "$old" --source claude-hook --event stop 2>/dev/null; then + fail "a superseded incarnation's event was accepted" + fi + assert_equals "$before" "$(wc -l < "$(events "$home" t1)")" "a refused event must not reach the ledger" + assert_no_grep "gen=$old seq=2" "$(events "$home" t1)" "stale row present" + [ "$old" != "$new" ] || fail "arming twice minted the same gen" + pass "a stale incarnation is refused before the append" +} + +test_relaunch_keeps_both_incarnations_in_one_file() { + local home first second + home=$(make_home relaunch) + first=$("$BUSY" arm "$home/state" t1) + "$BUSY" apply "$home/state" t1 idle --gen "$first" --source claude-hook --event stop + "$BUSY" retire "$home/state" t1 --gen "$first" + second=$("$BUSY" arm "$home/state" t1) + "$BUSY" apply "$home/state" t1 idle --gen "$second" --source pi-ext --event agent_settled + assert_grep "row=retire gen=$first seq=3 state=retired" "$(events "$home" t1)" "retire row missing" + assert_grep "row=arm gen=$first seq=1" "$(events "$home" t1)" "first incarnation lost" + assert_grep "row=arm gen=$second seq=1" "$(events "$home" t1)" "second incarnation missing" + assert_grep "gen=$second seq=2 state=idle source=pi-ext" "$(events "$home" t1)" "second incarnation's turn missing" + pass "a relaunch keeps both incarnations in one file" +} + +test_capture_never_fails_a_turn() { + local home gen rc=0 + home=$(make_home failopen) + gen=$("$BUSY" arm "$home/state" t1) + # A ledger path that cannot take the row: the record must still advance and + # the writer must still exit 0 with nothing on stdout or stderr. + rm -f "$(events "$home" t1)" + mkdir "$(events "$home" t1)" + out=$("$BUSY" apply "$home/state" t1 idle --gen "$gen" --source claude-hook --event stop 2>&1) || rc=$? + expect_code 0 "$rc" "apply with an unwritable ledger" + assert_equals "" "$out" "a failed append must be silent" + assert_grep "seq=2 state=idle" "$home/state/t1.busy-state" "the busy record must still be written" + assert_grep " t1 turn" "$home/state/work-ledger/.errors" "the failed append must be counted" + pass "a failed append is swallowed, counted, and never fails the turn" +} + +test_concurrent_appends_do_not_interleave() { + local home gen i pids=() bad + home=$(make_home concurrent) + gen=$("$BUSY" arm "$home/state" t1) + for i in 1 2 3 4 5 6 7 8 9 10 11 12; do + "$BUSY" apply "$home/state" t1 busy --gen "$gen" --source claude-hook --event user-prompt-submit & + pids+=("$!") + done + for i in "${pids[@]}"; do wait "$i" || fail "a concurrent apply failed"; done + assert_equals 13 "$(wc -l < "$(events "$home" t1)" | tr -d ' ')" "every append landed as its own line" + bad=$(grep -cv "^v1 ts=[0-9]* id=t1 row=[a-z]* gen=$gen seq=[0-9]* state=busy source=[a-z-]* event=[a-z-]*\$" "$(events "$home" t1)" || true) + assert_equals 0 "$bad" "no row was torn or merged with another" + assert_equals "$(seq 1 13 | tr '\n' ' ')" \ + "$(sed -n 's/.* seq=\([0-9]*\) .*/\1/p' "$(events "$home" t1)" | tr '\n' ' ')" \ + "rows are in seq order with none missing or repeated" + pass "concurrent appends neither interleave nor skip a seq" +} + +test_check_is_silent_when_nothing_changed() { + local home gen out + home=$(make_home silent) + out=$(run_check "$home") + assert_equals "" "$out" "an empty home must be silent" + gen=$("$BUSY" arm "$home/state" t1) + "$BUSY" apply "$home/state" t1 idle --gen "$gen" --source claude-hook --event stop + write_rows "$home" t1 <<EOF +$(date +%s) spawn $SPAWN_RATED +EOF + for _ in 1 2 3; do + out=$(run_check "$home") + assert_equals "" "$out" "a healthy, in-budget card must never produce output" + done + assert_present "$home/data/work-ledger/@primary/t1.events" "the ledger was not copied into the store" + assert_present "$home/data/work-ledger/.last-run" "the run marker is missing" + pass "the check prints nothing when no edge was crossed, however often it runs" +} + +test_copy_is_idempotent_and_ignores_a_partial_line() { + local home store + home=$(make_home copy) + write_rows "$home" t1 <<EOF +100 spawn $SPAWN_RATED +EOF + printf 'v1 ts=200 id=t1 row=turn gen=g1 seq=' >> "$(events "$home" t1)" + FM_HOME="$home" "$LEDGER" copy || fail "copy failed" + FM_HOME="$home" "$LEDGER" copy || fail "second copy failed" + store="$home/data/work-ledger/@primary/t1.events" + assert_equals 1 "$(wc -l < "$store" | tr -d ' ')" "copy repeated a row or took a partial line" + printf '2 state=busy source=x event=y\n' >> "$(events "$home" t1)" + FM_HOME="$home" "$LEDGER" copy || fail "third copy failed" + assert_equals 2 "$(wc -l < "$store" | tr -d ' ')" "the completed line was not copied" + pass "copy is idempotent and waits for a complete line" +} + +test_over_budget_reports_each_level_once() { + local home gen now out + home=$(make_home budget) + now=$(date +%s) + gen=$("$BUSY" arm "$home/state" t1) + # Rated 2 at the inherited 9.9 min/pt gives a 19.8 minute budget. One turn + # open for 70 minutes is 3.5x. + : > "$(events "$home" t1)" + write_rows "$home" t1 <<EOF +$((now - 4200)) spawn $SPAWN_RATED +$((now - 4200)) arm gen=$gen seq=1 state=busy source=fm-spawn event=launch-brief +EOF + out=$(run_check "$home") + assert_contains "$out" "work-ledger: over-budget t1 in @primary (rated 2, rater fresh)" "3x crossing not reported" + assert_contains "$out" "crossed 3x" "level missing" + assert_contains "$out" "post hoc inherited median 9.9" "the threshold must be labelled post hoc" + assert_contains "$out" "capture complete" "completeness missing" + assert_equals 1 "$(printf '%s\n' "$out" | wc -l | tr -d ' ')" "exactly one line per edge" + out=$(run_check "$home") + assert_equals "" "$out" "the same crossing must not be reported twice" + # Same card, now 130 minutes open: 6.6x. + sed -i.bak "s/ts=$((now - 4200)) /ts=$((now - 7800)) /" "$(events "$home" t1)" + rm -f "$(events "$home" t1).bak" "$home/data/work-ledger/@primary/t1.events" + out=$(run_check "$home") + assert_contains "$out" "crossed 6x" "6x crossing not reported" + out=$(run_check "$home") + assert_equals "" "$out" "the 6x crossing must not repeat" + pass "over-budget fires once at 3x and once at 6x, then stays silent" +} + +test_sub_cards_aggregate_to_the_parent_as_a_union() { + local home now ga gb out + home=$(make_home parent) + now=$(date +%s) + ga=$("$BUSY" arm "$home/state" p1-a) + gb=$("$BUSY" arm "$home/state" p1-b) + : > "$(events "$home" p1-a)" + : > "$(events "$home" p1-b)" + # Two sub-cards each open for the SAME 40 minutes. Summed that is 80 minutes + # and 4x the 19.8 minute budget; as a union it is 40 minutes and 2x. + write_rows "$home" p1-a <<EOF +$((now - 2400)) spawn ${SPAWN_RATED/parent=-/parent=p1} +$((now - 2400)) arm gen=$ga seq=1 state=busy source=fm-spawn event=launch-brief +EOF + write_rows "$home" p1-b <<EOF +$((now - 2400)) spawn ${SPAWN_RATED/parent=-/parent=p1} +$((now - 2400)) arm gen=$gb seq=1 state=busy source=fm-spawn event=launch-brief +EOF + out=$(run_check "$home") + assert_equals "" "$out" "overlapping sub-card time was summed instead of unioned" + pass "sub-cards fold into their parent by union, not by sum" +} + +test_unrated_and_unmeasured_cards_never_alarm() { + local home now gen out + home=$(make_home unrated) + now=$(date +%s) + gen=$("$BUSY" arm "$home/state" t1) + : > "$(events "$home" t1)" + write_rows "$home" t1 <<EOF +$((now - 90000)) spawn harness=claude model=opus kind=ship parent=- capture=supported rating=none rater=- blind=- rated_at=- rating_read=ok +$((now - 90000)) arm gen=$gen seq=1 state=busy source=fm-spawn event=launch-brief +EOF + write_rows "$home" t2 <<EOF +$((now - 90000)) spawn harness=codex model=gpt kind=ship parent=- capture=unsupported rating=2 rater=fresh blind=yes rated_at=x rating_read=ok +EOF + out=$(run_check "$home") + assert_equals "" "$out" "an unrated or unmeasured card has no budget to cross" + pass "unrated and unmeasured cards are never read as a budget" +} + +test_capture_dead_needs_two_sweeps_and_fires_once() { + local home gen out + home=$(make_home dead) + gen=$("$BUSY" arm "$home/state" t1) + "$BUSY" apply "$home/state" t1 idle --gen "$gen" --source claude-hook --event stop + # Lose the last row: the live record now runs ahead of the ledger. + sed -i.bak '$d' "$(events "$home" t1)" + rm -f "$(events "$home" t1).bak" + out=$(run_check "$home") + assert_equals "" "$out" "one lagging sweep is not yet an edge" + out=$(run_check "$home") + assert_contains "$out" "work-ledger: capture dead in @primary: 1 tasks, ledger 1 rows behind busy-state" "capture dead not reported" + out=$(run_check "$home") + assert_equals "" "$out" "capture dead must fire once per episode" + # Capture recovers, then dies again: a new episode is a new edge. + printf 'v1 ts=%s id=t1 row=turn gen=%s seq=2 state=idle source=claude-hook event=stop\n' "$(date +%s)" "$gen" >> "$(events "$home" t1)" + out=$(run_check "$home") + assert_equals "" "$out" "recovery is not an edge" + "$BUSY" apply "$home/state" t1 busy --gen "$gen" --source claude-hook --event user-prompt-submit + sed -i.bak '$d' "$(events "$home" t1)" + rm -f "$(events "$home" t1).bak" + out=$(run_check "$home"; run_check "$home") + assert_contains "$out" "work-ledger: capture dead in @primary" "a second episode must be reported again" + pass "capture dead needs two lagging sweeps and reports once per episode" +} + +test_seq_gap_marks_the_card_incomplete() { + local home now out i + home=$(make_home gap) + now=$(date +%s) + # Five rated cards merge, which is a digest. One of them has a seq gap, so it + # is counted as excluded rather than entering pace. + for i in 1 2 3 4 5; do + write_rows "$home" "c$i" <<EOF +$((now - 7200)) spawn $SPAWN_RATED +$((now - 7200)) arm gen=g$i seq=1 state=busy source=fm-spawn event=launch-brief +$((now - 6000)) turn gen=g$i seq=$([ "$i" = 3 ] && echo 3 || echo 2) state=idle source=claude-hook event=stop +$((now - 5900)) retire gen=g$i seq=$([ "$i" = 3 ] && echo 4 || echo 3) state=retired source=fm-retire event=retire +$((now - 3600 + i)) merged pr=https://example.invalid/pr/$i +EOF + done + out=$(run_check "$home") + assert_contains "$out" "work-ledger: digest @primary c1..c5 (5 rated cards)" "digest not reported" + assert_contains "$out" "1 incomplete" "the seq gap was not detected" + assert_contains "$out" "0 unrated" "unrated count missing" + # Four complete cards: 8 points over 4 x 20 minutes = 6.00 pts/active-h. + assert_contains "$out" "pace 6.00 pts/active-h" "pace must leave the incomplete card out" + assert_equals 1 "$(printf '%s\n' "$out" | wc -l | tr -d ' ')" "one digest line" + out=$(run_check "$home") + assert_equals "" "$out" "a digest must not repeat" + pass "a seq gap excludes the card from pace and is counted in the digest" +} + +test_digest_waits_for_five_rated_cards() { + local home now out i + home=$(make_home digestwait) + now=$(date +%s) + for i in 1 2 3 4; do + write_rows "$home" "c$i" <<EOF +$((now - 7200)) spawn $SPAWN_RATED +$((now - 7200)) arm gen=g$i seq=1 state=busy source=fm-spawn event=launch-brief +$((now - 6000)) turn gen=g$i seq=2 state=idle source=claude-hook event=stop +$((now - 3600 + i)) merged pr=https://example.invalid/pr/$i +EOF + done + out=$(run_check "$home") + assert_equals "" "$out" "four merged cards are not a digest, and a merge alone is never reported" + pass "no per-merge output, and no digest before five rated cards" +} + +test_secondmate_lane_is_copied_without_writing_to_it() { + local home mate before out + home=$(make_home primary) + mate=$(make_home mate-a) + printf '%s\n' "- mate-a - cards lane (home: $mate; scope: cards; projects: none; added 2026-09-18)" > "$home/data/secondmates.md" + write_rows "$mate" m1 <<EOF +100 spawn $SPAWN_RATED +EOF + before=$(find "$mate" | sort) + out=$(run_check "$home") + assert_equals "" "$out" "copying a lane is not an edge" + assert_present "$home/data/work-ledger/mate-a/m1.events" "the secondmate lane was not copied" + assert_equals "$before" "$(find "$mate" | sort)" "the check wrote into the home it reads" + pass "a local secondmate's ledger is copied read-only into its own lane" +} + +test_arm_is_primary_only_and_registers_the_shim() { + local home mate out rc=0 + home=$(make_home arm) + out=$(FM_HOME="$home" "$LEDGER" arm) || fail "arm failed: $out" + assert_contains "$out" "armed: state/work-ledger.check.sh" "arm output" + assert_present "$home/state/work-ledger.check-trust" "the shim was not registered" + out=$("$home/state/work-ledger.check.sh") + assert_equals "" "$out" "the armed shim must be silent on an empty home" + FM_HOME="$home" "$LEDGER" disarm >/dev/null || fail "disarm failed" + assert_absent "$home/state/work-ledger.check.sh" "disarm left the shim" + mate=$(make_home arm-mate) + printf 'mate-x\n' > "$mate/.fm-secondmate-home" + out=$(FM_HOME="$mate" "$LEDGER" arm 2>&1) || rc=$? + expect_code 1 "$rc" "arm in a secondmate home" + assert_absent "$mate/state/work-ledger.check.sh" "a secondmate home must never hold the check" + pass "arm registers the shim in a primary home and refuses a secondmate home" +} + +test_retirement_copy_fails_closed() { + local home mate rc=0 + home=$(make_home retire) + mate=$(make_home retire-mate) + write_rows "$mate" m1 <<EOF +100 spawn $SPAWN_RATED +EOF + FM_HOME="$home" "$LEDGER" copy --home "$mate" --lane mate-r || fail "retirement copy failed" + assert_present "$home/data/work-ledger/mate-r/m1.events" "retirement copy did not land" + chmod 500 "$home/data/work-ledger/mate-r" + write_rows "$mate" m2 <<EOF +100 spawn $SPAWN_RATED +EOF + FM_HOME="$home" "$LEDGER" copy --home "$mate" --lane mate-r 2>/dev/null || rc=$? + chmod 700 "$home/data/work-ledger/mate-r" + [ "$(id -u)" = 0 ] || expect_code 1 "$rc" "a copy that cannot land must fail" + pass "the retirement copy step reports failure instead of losing rows" +} + +test_turn_rows_follow_the_record +test_stale_incarnation_is_not_appended +test_relaunch_keeps_both_incarnations_in_one_file +test_capture_never_fails_a_turn +test_concurrent_appends_do_not_interleave +test_check_is_silent_when_nothing_changed +test_copy_is_idempotent_and_ignores_a_partial_line +test_over_budget_reports_each_level_once +test_sub_cards_aggregate_to_the_parent_as_a_union +test_unrated_and_unmeasured_cards_never_alarm +test_capture_dead_needs_two_sweeps_and_fires_once +test_seq_gap_marks_the_card_incomplete +test_digest_waits_for_five_rated_cards +test_secondmate_lane_is_copied_without_writing_to_it +test_arm_is_primary_only_and_registers_the_shim +test_retirement_copy_fails_closed From bf17ca3174c8193b7b6d27594b81ed50e7180f73 Mon Sep 17 00:00:00 2001 From: matt <matt@local> Date: Fri, 18 Sep 2026 19:10:25 +0200 Subject: [PATCH 2/2] test: pin that a confirmed merge stamps the work ledger once --- tests/fm-work-ledger.test.sh | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) diff --git a/tests/fm-work-ledger.test.sh b/tests/fm-work-ledger.test.sh index cf5c0f979f2..c745018056a 100755 --- a/tests/fm-work-ledger.test.sh +++ b/tests/fm-work-ledger.test.sh @@ -349,6 +349,21 @@ EOF pass "the retirement copy step reports failure instead of losing rows" } +test_a_confirmed_merge_is_stamped_once() { + local merged_home pr_url=https://github.com/example/repo/pull/7 rc=0 + merged_home=$(make_home merged) + ( + # shellcheck source=bin/fm-merge-outcome-lib.sh + . "$ROOT/bin/fm-merge-outcome-lib.sh" + fm_merge_outcome_report "$merged_home" "$merged_home/state" t1 "$pr_url" self && + fm_merge_outcome_report "$merged_home" "$merged_home/state" t1 "$pr_url" poll + ) >/dev/null 2>&1 || rc=$? + expect_code 0 "$rc" "recording the merge outcome" + assert_equals 1 "$(grep -c "row=merged pr=$pr_url" "$(events "$merged_home" t1)")" \ + "a merge already recorded must not be stamped again" + pass "a confirmed merge is stamped in the ledger once" +} + test_turn_rows_follow_the_record test_stale_incarnation_is_not_appended test_relaunch_keeps_both_incarnations_in_one_file @@ -365,3 +380,4 @@ test_digest_waits_for_five_rated_cards test_secondmate_lane_is_copied_without_writing_to_it test_arm_is_primary_only_and_registers_the_shim test_retirement_copy_fails_closed +test_a_confirmed_merge_is_stamped_once