diff --git a/AGENTS.md b/AGENTS.md index 382413e821..abc1f6dca7 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -108,8 +108,8 @@ state/ volatile runtime signals; gitignored .afk durable away-mode flag; present = sub-supervisor may inject escalations (set by /afk, cleared on user return) .watch.lock .wake-queue.lock watcher singleton and queue serialization locks .claude-autoarm.lock .claude-autoarm-epoch .turnend-claude-blocks Claude Stop auto-arm single-flight, epoch, and guard-budget records; never touch - .hash-* .count-* .stale-* .stale-since-* .paused-* .wedge-escalations-* .seen-* .hb-surfaced-* .last-* .heartbeat-streak watcher internals; never touch - .watch-triage.log watcher's absorbed-wake debug log (size-capped); never relied on, safe to delete + .hash-* .count-* .stale-* .stale-since-* .paused-* .wedge-escalations-* .progress-* .park-* .seen-* .hb-surfaced-* .last-* .heartbeat-streak watcher internals; never touch + .watch-triage.log absorbed-wake and supervision-telemetry debug log written by the watcher and the wake drain (size-capped); never relied on, safe to delete .last-watcher-beat watcher liveness beacon, touched every poll (including while absorbing benign wakes); guard scripts read it .subsuper-* .supervise-daemon.* sub-supervisor internals; never touch .no-mistakes/ local validation state and evidence; gitignored @@ -260,6 +260,7 @@ After spawning, confirm the worker is processing the brief, handle any trust dia A persistent secondmate is recorded in the secondmate registry and runtime state, never as a backlog work item. Steer a worker with short single-line messages through fail-closed `fm-send`; put long instructions in a file. +Every metadata-routed steer is marked as coming from firstmate, so a worker can always tell firstmate from a human at its keyboard; only a harness-dispatched command such as a slash command is sent bare, and `bin/fm-send.sh` owns that boundary. A secondmate's routed reply returns through status or a document pointer, not by firstmate peeking into its chat. For the parent-owned correlation, recovery, and escalation contract on marked secondmate requests, see `bin/fm-pending-reply-lib.sh`. Supervise all live work under section 8. diff --git a/bin/fm-brief.sh b/bin/fm-brief.sh index 00ea34ddab..729f2c7ab4 100755 --- a/bin/fm-brief.sh +++ b/bin/fm-brief.sh @@ -230,6 +230,13 @@ if [ "$KIND" = scout ]; then cat > "$BRIEF" < "$BRIEF" <" opening. +# Nothing downstream could tell which rule fired, so per-branch wake attribution +# had to be reconstructed from truncation patterns in state/.watch-triage.log; +# that method left 44% of stale wakes unattributed across two independent +# readings of this system, and the wedge and pause regression tests need to +# assert on the branch rather than on a window string three code paths produce. +# The tag is PROSE inside the reason, never a parsed protocol field. Read it with +# a substring match; recover the window with stale_reason_window below, never by +# stripping the "stale: " prefix alone. +stale_reason() { # [detail] + if [ -n "${3:-}" ]; then + printf 'stale: %s (%s) [branch=%s]' "$2" "$3" "$1" + else + printf 'stale: %s [branch=%s]' "$2" "$1" + fi +} + +# The window named by a "stale:" wake reason, with trailing decoration removed. +# A wake reason is PROSE written for firstmate, never a protocol: the watcher +# already appends details such as "(idle 300s, possible wedge, escalation 2)" or +# "(paused 3600s, awaiting external ...)", and every stale reason additionally +# carries a "[branch=]" classification tag. A consumer that needs the +# window back out of a reason must strip that decoration through this one owner. +# A bare "${reason#stale: }" yields " (idle 300s, ...)", which matches no +# recorded window= line, so window_to_task falls through to its suffix heuristic +# and returns a garbage task id - the reason the decorated wedge and pause +# reasons were already mis-parsed before the branch tag existed. +stale_reason_window() { # + local s=${1#stale: } + s=${s%%" ("*} + s=${s%%" ["*} + printf '%s' "$s" +} + # 0 (actionable) if ANY status file listed in a "signal:" wake carries a # captain-relevant last line; 1 otherwise. Pass the space-separated file list that # follows the "signal:" prefix. Non-.status arguments (e.g. .turn-ended markers, @@ -356,6 +394,55 @@ crew_is_provably_working() { # [ "$(crew_absorb_class "$1")" = working ] } +# The crew's progress fingerprint - a token that is constant while nothing +# advances and changes when something does. bin/fm-crew-state.sh's --progress +# block is the single owner of what may and may not appear in it; read that +# before touching this, because the obvious fields are the wrong ones. +# +# Empty on any failure, and empty compares equal to empty, so an unreadable +# fingerprint leaves a caller's wedge escalation behaving exactly as it did +# before this existed. That is the safe direction: treating "could not tell" as +# progress would silence the escalation on a genuinely frozen worker, which is +# the one failure this whole mechanism exists to keep detectable. "Failure" here +# includes a run read that was owed and did not answer, not just a reader that +# died - a partially-populated fingerprint would be a distinct non-empty token +# and would compare UNEQUAL, which is the same false negative wearing a +# different shape. +# +# NOT a pure read - it makes the same bounded no-mistakes call crew_absorb_class +# does, minus the ci-log read - so callers use it only where the alternative is +# spending a coordinator turn, never on every poll. FM_CREW_STATE_BIN lets tests +# stub the answer; a stub or an older reader that does not know --progress +# returns its ordinary state line instead, which is itself stable under no +# change, so version skew degrades to a coarser signal rather than a wrong one. +crew_progress_fingerprint() { # + local id=$1 out + [ -n "$id" ] || return 0 + out=$("$FM_CREW_STATE_BIN" "$id" --progress 2>/dev/null) || true + printf '%s' "$out" | head -1 | tr -d '\r' +} + +# The pipeline gate a crew's run is parked at, or empty when it is not parked. +# Reuses bin/fm-crew-state.sh's own gate detection through the same authoritative +# line crew_absorb_class reads, rather than re-deriving "is this parked" from run +# output a second time. The returned text is both the comparison token and the +# human-readable gate name, and it is stable while the run sits at that gate. +# +# NOT a pure read - same bounded no-mistakes call as crew_absorb_class - so +# callers run it on a slow bounded sweep, never every poll. +crew_parked_gate() { # + local id=$1 line state + [ -n "$id" ] || return 0 + line=$("$FM_CREW_STATE_BIN" "$id" 2>/dev/null) || true + case "$line" in state:*) ;; *) return 0 ;; esac + state=${line#state: }; state=${state%% *} + [ "$state" = parked ] || return 0 + case "$line" in + *"parked at "*) printf 'parked at %s' "${line#*"parked at "}" ;; + *) printf 'a pipeline gate' ;; + esac +} + # 0 if crew 's authoritative current state is a declared external-wait pause. # The stale path absorbs such a crew (on a long re-surface cadence) instead of # escalating a possible wedge. diff --git a/bin/fm-crew-state.sh b/bin/fm-crew-state.sh index 32dff23668..9d41d6c3b3 100755 --- a/bin/fm-crew-state.sh +++ b/bin/fm-crew-state.sh @@ -63,8 +63,17 @@ STATE="${FM_STATE_OVERRIDE:-$FM_HOME/state}" # shellcheck source=bin/fm-classify-lib.sh . "$SCRIPT_DIR/fm-classify-lib.sh" -ID=${1:-} -[ -n "$ID" ] || { echo "usage: fm-crew-state.sh " >&2; exit 2; } +ID="" +MODE=state +for arg in "$@"; do + case "$arg" in + --progress) MODE=progress ;; + -*) echo "usage: fm-crew-state.sh [--progress]" >&2; exit 2 ;; + *) [ -n "$ID" ] && { echo "usage: fm-crew-state.sh [--progress]" >&2; exit 2; } + ID=$arg ;; + esac +done +[ -n "$ID" ] || { echo "usage: fm-crew-state.sh [--progress]" >&2; exit 2; } META="$STATE/$ID.meta" LOG="$STATE/$ID.status" @@ -86,9 +95,22 @@ emit() { # [detail] exit 0 } +# In --progress mode every exit prints a progress fingerprint (see +# compute_progress_fingerprint below), never a state line. The two bail-outs here +# fire before a worktree is even resolved, so there is no evidence of progress to +# report at all, and NO EVIDENCE IS THE EMPTY STRING - not a punctuation skeleton +# with empty fields. A skeleton is a distinct non-empty token, so it compares +# UNEQUAL to a healthy fingerprint and the caller reads a failed read as forward +# progress. Emitting nothing keeps the caller's wedge escalation behaving exactly +# as it does without a fingerprint at all. +progress_bail() { exit 0; } + # --- meta resolution -------------------------------------------------------- -[ -f "$META" ] || emit unknown none "no metadata for $ID" +if [ ! -f "$META" ]; then + [ "$MODE" = progress ] && progress_bail + emit unknown none "no metadata for $ID" +fi meta_value() { # grep "^$1=" "$META" 2>/dev/null | tail -1 | cut -d= -f2- || true @@ -101,6 +123,7 @@ HARNESS=$(meta_value harness) # A torn-down (or never-created) worktree has no current state to read. if [ -z "$WT" ] || [ ! -d "$WT" ]; then + [ "$MODE" = progress ] && progress_bail emit unknown none "worktree gone (torn down?)" fi @@ -208,6 +231,111 @@ strip_quotes() { trim "$s" } +# --- progress fingerprint (--progress) -------------------------------------- +# +# A wedge escalation asks "has this worker stopped making progress". Progress is +# a DIFFERENCE, and nothing in this system stored a previous value, so that +# health verdict was structurally stateless: the escalation could only measure +# elapsed wall-clock against an unchanged pane. A healthy worker driving a +# no-mistakes run produces exactly that by construction, because the pipeline +# owns the branch and renders nothing to the worker's own pane. The fingerprint +# below is the missing previous value: a short token that is CONSTANT while +# nothing advances and CHANGES when something does, so a caller holding two +# reads can turn a stateless verdict into a transition. +# +# ONLY fields that are stable under no change may appear in it. The fields that +# look most informative in `axi status` are precisely the ones that must not: +# +# active_steps[1]{step,status,active_for,last_activity,agent_pid,round}: +# ci,running,2h3m,"quiet 1h25m ago: log: all CI checks passed - still monitoring +# until merged or closed","",starting +# +# - active_for ("2h3m") and last_activity ("quiet 1h25m ago: ...") each embed a +# ticking elapsed counter, so they differ on EVERY read of an unchanged run. +# A fingerprint containing either differs every time it is compared, the +# caller's reset fires unconditionally, and a genuinely frozen worker then +# never escalates again. That is a false negative on the one signal that +# catches a frozen worker - strictly worse than the false positive it would +# be replacing, and invisible, because nothing reports an escalation that +# did not happen. Do not add them here however much more legible they look. +# They may be carried in human-facing detail text; they may not be compared. +# - agent_pid is empty on a live, healthy, running step, so its presence proves +# nothing about liveness. +# - round is the non-numeric token "starting" here, so it is compared as an +# opaque string and never parsed as an integer. +# +# What remains: the completed-step count (monotonic), the active step's name and +# status, the opaque round token, and the worktree head. The head sha is what +# covers scouts and pre-validation ship work, which have no attributed run at +# all - for them a new commit is the only available evidence of progress. +# +# A FAILED read and NO RUN are different answers and must not print the same +# thing. "No run" is a real, positive observation: a scout, a secondmate, or a +# ship task that has not started validating genuinely has no run, and the head +# sha is legitimately the whole fingerprint. "Could not read the run" is the +# absence of an observation: the bounded no-mistakes call was attempted for a +# task that could have had a run and answered with nothing (timed out, the CLI +# is not installed, or only the coarse runs-list status word came back, which +# carries no step detail). Printing the sha-only form there would make the +# fingerprint flip between two shapes as the CLI comes and goes, and each flip +# reads to the caller as forward progress - the exact false negative this +# mechanism exists to prevent. A degraded read therefore prints the EMPTY +# fingerprint, which compares equal and escalates. RUN_DEGRADED (set with +# HAVE_RUN/RUN_SOURCE, below) is that distinction. +# +# tests/fm-crew-state.test.sh asserts that two reads of an unchanged run produce +# byte-identical output. That assertion is the direct guard against a ticking +# field being reintroduced here, and it must not be dropped. + +# Number of completed rows in the steps[] table. Anchored at the row's own step +# name so a comma inside a later quoted free-text column cannot match. +nm_completed_step_count() { + printf '%s\n' "$RUN_OUT" | grep -cE '^[[:space:]]+[A-Za-z0-9_.-]+,[[:space:]]*"?completed"?[[:space:]]*,' || true +} + +# The first active_steps[] row, or empty. A TOON table's rows are indented +# deeper than their header, so the block ends at the first line indented no +# further than the header - which is what keeps this from running on into +# whatever key follows the table. +nm_active_step_row() { + printf '%s\n' "$RUN_OUT" | awk ' + /^[[:space:]]*active_steps\[/ { match($0, /^[[:space:]]*/); hdr = RLENGTH; inblk = 1; next } + inblk { + if ($0 ~ /^[[:space:]]*$/) { exit } + match($0, /^[[:space:]]*/) + if (RLENGTH <= hdr) { exit } + print + exit + } + ' +} + +# Named apart from fm-classify-lib.sh's caller-facing crew_progress_fingerprint +# , which this script is sourced alongside and which shells back out to this +# script with --progress. Two incompatible contracts under one name meant the +# only thing keeping `fm-crew-state.sh --progress` from re-exec'ing itself +# forever was this definition happening to be declared after that source line. +compute_progress_fingerprint() { + local completed='' step='' status='' round='' head='' row rest + [ "${RUN_DEGRADED:-0}" = 1 ] && return 0 + if [ "${HAVE_RUN:-0}" = 1 ] && [ "${RUN_SOURCE:-}" = full ]; then + completed=$(nm_completed_step_count | tr -d '[:space:]') + case "$completed" in ''|*[!0-9]*) completed='' ;; esac + row=$(trim "$(nm_active_step_row)") + if [ -n "$row" ]; then + step=$(strip_quotes "${row%%,*}") + rest=${row#*,} + status=$(strip_quotes "$(trim "${rest%%,*}")") + # round is the LAST column. last_activity is a quoted free-text column that + # can contain commas, so index the round token from the right; counting + # columns from the left would silently read part of that prose instead. + round=$(strip_quotes "${row##*,}") + fi + fi + head=$(git -C "$WT" rev-parse --short HEAD 2>/dev/null || true) + printf '%s/%s/%s/%s/%s\n' "$completed" "$step" "$status" "$round" "$head" +} + # Bounded no-mistakes call in the worktree; stdout only, never fails the script. HAVE_TIMEOUT=none if command -v timeout >/dev/null 2>&1; then HAVE_TIMEOUT=timeout @@ -453,31 +581,58 @@ HAVE_RUN=0 # run-step block below skips the TOON field parsing entirely for this crew. RUN_SOURCE=full COARSE_STATUS="" +# RUN_DEGRADED marks "a run lookup was owed for this crew and came back with no +# usable answer" - as distinct from both "a run was attributed" and "this crew +# never has a run". Read only by compute_progress_fingerprint, whose header +# explains why the two no-run cases must not print the same token. The state +# machine below is unaffected: it already treats HAVE_RUN=0 the same either way, +# falling back to pane then status log. +RUN_DEGRADED=0 # Scouts and secondmates never drive a no-mistakes validation of their own # worktree, so skip the lookup for them and read state from pane/log directly. -if [ "$KIND" = ship ] && [ -n "$CREW_BRANCH" ] && command -v no-mistakes >/dev/null 2>&1; then - RUN_OUT=$(nm_run axi status) - if [ -n "$RUN_OUT" ]; then - run_branch=$(strip_quotes "$(nm_field branch)") - if [ -n "$run_branch" ] && [ "$run_branch" = "$CREW_BRANCH" ] && nm_run_head_matches_worktree; then - HAVE_RUN=1 +if [ "$KIND" = ship ] && [ -n "$CREW_BRANCH" ]; then + # The one authority on this crew's run not being installed is a non-answer, + # not an observation that no run exists. + command -v no-mistakes >/dev/null 2>&1 || RUN_DEGRADED=1 + if [ "$RUN_DEGRADED" = 0 ]; then + RUN_OUT=$(nm_run axi status) + if [ -z "$RUN_OUT" ]; then + # Timed out, or the CLI answered with nothing at all. + RUN_DEGRADED=1 else - # The active-or-most-recent run is for another branch, or same branch with - # a rewritten/diverged head (the CLI is alive and answered; only the - # attribution missed) - try the coarse fallback. - # Deliberately nested inside `[ -n "$RUN_OUT" ]`: an empty/timed-out - # primary call means the CLI itself did not respond, so retrying it - # immediately with a second bounded call would just double the wait - # for no better answer. - COARSE_STATUS=$(nm_runs_status_for_branch "$CREW_BRANCH") - if [ -n "$COARSE_STATUS" ]; then + run_branch=$(strip_quotes "$(nm_field branch)") + if [ -n "$run_branch" ] && [ "$run_branch" = "$CREW_BRANCH" ] && nm_run_head_matches_worktree; then HAVE_RUN=1 - RUN_SOURCE=coarse + else + # The active-or-most-recent run is for another branch, or same branch + # with a rewritten/diverged head (the CLI is alive and answered; only + # the attribution missed) - try the coarse fallback. + # Deliberately not attempted when the primary call came back empty: that + # means the CLI itself did not respond, so retrying it immediately with a + # second bounded call would just double the wait for no better answer. + COARSE_STATUS=$(nm_runs_status_for_branch "$CREW_BRANCH") + if [ -n "$COARSE_STATUS" ]; then + HAVE_RUN=1 + RUN_SOURCE=coarse + # A bare status word carries no step detail, so it is a degraded read + # for fingerprint purposes even though it is enough for the state + # machine below. + RUN_DEGRADED=1 + fi fi fi fi fi +# Attribution is everything the fingerprint needs, so --progress answers here +# rather than falling through the state machine below. That skips the ci-step +# log read, which is the one genuinely expensive call in this script and has no +# bearing on whether the run advanced. +if [ "$MODE" = progress ]; then + compute_progress_fingerprint + exit 0 +fi + # --- run-step authoritative path ------------------------------------------- if [ "$HAVE_RUN" = 1 ]; then diff --git a/bin/fm-operational-input.sh b/bin/fm-operational-input.sh index 11d6a459d5..0f1bacbf19 100755 --- a/bin/fm-operational-input.sh +++ b/bin/fm-operational-input.sh @@ -9,6 +9,13 @@ # U+2063 FIRSTMATE_OP: v1 : # # The landed U+2063 + "FIRSTMATE_OP: " prefix is permanent compatibility. +# `firstmate-steer` carries an ordinary supervision message from firstmate to a +# crewmate or scout. A worker receives exactly one marked message at birth - its +# launch brief - and before this kind existed every later steer arrived bare, +# indistinguishable from a human typing into the pane. The operating contract +# forbids a crewmate from addressing the captain while the transport gave it no +# way to tell who was speaking, and both directions of that confusion have been +# observed. # The version and kind header make current inputs structurally typed without # deriving provenance from body prose. The established from-firstmate routing # marker remains a current compatibility carrier because already-running @@ -28,7 +35,7 @@ FM_OPERATIONAL_MARK=$'\xE2\x81\xA3' FM_OPERATIONAL_PREFIX="${FM_OPERATIONAL_MARK}FIRSTMATE_OP: " FM_OPERATIONAL_VERSION=v1 FM_OPERATIONAL_HEADER_PREFIX="${FM_OPERATIONAL_PREFIX}${FM_OPERATIONAL_VERSION} " -FM_OPERATIONAL_KINDS='session-start watcher turn-end-guard away-supervisor launch-brief' +FM_OPERATIONAL_KINDS='session-start watcher turn-end-guard away-supervisor launch-brief firstmate-steer' # Compatibility name retained for the away-mode owner and its tests. # shellcheck disable=SC2034 # Public source-library variable used by callers. diff --git a/bin/fm-push-transition-lib.sh b/bin/fm-push-transition-lib.sh index 75b8faf6c8..93f657a5a6 100644 --- a/bin/fm-push-transition-lib.sh +++ b/bin/fm-push-transition-lib.sh @@ -16,20 +16,8 @@ FM_PUSH_TRANSITION_LIB_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" # shellcheck source=bin/fm-transition-lib.sh . "$FM_PUSH_TRANSITION_LIB_DIR/fm-transition-lib.sh" -TRIAGE_LOG="$STATE/.watch-triage.log" -TRIAGE_LOG_MAX_BYTES=${FM_WATCH_TRIAGE_LOG_MAX_BYTES:-262144} - -# Append one bounded best-effort line for an absorbed supervision event. -triage_log() { - local sz - printf '[%s] %s\n' "$(date '+%Y-%m-%dT%H:%M:%S%z')" "$1" >> "$TRIAGE_LOG" 2>/dev/null || return 0 - sz=$(wc -c < "$TRIAGE_LOG" 2>/dev/null | tr -d '[:space:]') - case "$sz" in ''|*[!0-9]*) return 0 ;; esac - if [ "$sz" -ge "$TRIAGE_LOG_MAX_BYTES" ]; then - tail -n 2000 "$TRIAGE_LOG" > "$TRIAGE_LOG.tmp" 2>/dev/null && mv -f "$TRIAGE_LOG.tmp" "$TRIAGE_LOG" 2>/dev/null - rm -f "$TRIAGE_LOG.tmp" 2>/dev/null || true - fi -} +# triage_log and its bounded log path come from fm-wake-lib.sh, sourced above, +# so the watcher and the wake drain share one writer against one bound. # Exit after reporting one actionable wake. Tests override this callback. wake() { @@ -68,7 +56,7 @@ handle_push_transition() { # fm_backend_commit_transition "$backend" "$STATE" "$session" "$record" || exit 1 return fi - reason="stale: $window (herdr: agent $to - waiting on human, escalated immediately, not via wedge timer)" + reason=$(stale_reason push-transition "$window" "herdr: agent $to - waiting on human, escalated immediately, not via wedge timer") fm_wake_append stale "$window" "$reason" || exit 1 fm_backend_commit_transition "$backend" "$STATE" "$session" "$record" || exit 1 mark_surfaced "$STATE/$task.status" diff --git a/bin/fm-send.sh b/bin/fm-send.sh index dfae6f49e6..1019e5ff3f 100755 --- a/bin/fm-send.sh +++ b/bin/fm-send.sh @@ -25,9 +25,26 @@ # records kind=secondmate, the text uses the live-charter-compatible # from-firstmate carrier owned by bin/fm-operational-input.sh so the secondmate # routes its reply via its status file or a status-pointed doc instead of -# stranding it in chat the main firstmate never reads. A crewmate/scout target, -# an explicit backend-target escape-hatch target, and the --key path are never -# marked - their behavior is unchanged. +# stranding it in chat the main firstmate never reads. +# +# A crewmate or scout target is marked with the generic `firstmate-steer` +# operational kind from the same owner. A worker used to receive exactly one +# marked message - its launch brief - and a bare stream afterwards, so it could +# not tell a firstmate steer from the captain typing into its pane. That is not +# hypothetical: a crewmate composed "Captain, the pipeline paused on one decision +# you need to make..." into its own pane and blocked for ten minutes, and the +# captain has separately opened a crewmate pane believing it was firstmate. A +# steer carries no reply expectation, so unlike the secondmate path it creates no +# pending-reply record. +# +# Two carve-outs, both narrow. An explicit backend-target escape-hatch target and +# the --key path stay unmarked, as before. And a message the HARNESS itself must +# dispatch - a leading "/" slash command anywhere, or a leading "$" skill +# invocation on codex - is sent bare, because any prefix in front of it turns the +# command into plain text and the steer silently fails to run. Those are the same +# two shapes the submit settle below already recognizes as harness-dispatched. +# The identity confusion this closes is about prose that reads like a person +# speaking; a slash command cannot be mistaken for the captain asking a question. # # Parent-owned pending-reply expectation: every newly marked secondmate request # also receives a privacy-safe correlation id and a durable parent record under @@ -193,18 +210,24 @@ shift fm_backend_validate "$TARGET_BACKEND" || exit 1 -# Classify a from-firstmate -> secondmate request. Only a task selector resolved -# through this home's meta whose authoritative kind is secondmate is marked: the -# secondmate then routes its reply via the status path (see fm-marker-lib.sh). -# An explicit backend target (the escape hatch for endpoints outside this home) -# and any crewmate/scout target are left unmarked, and so is the --key path. +# Classify the request. Only a task selector resolved through this home's meta is +# marked at all: an explicit backend target is the escape hatch for endpoints +# outside this home and stays bare, and so does the --key path. A secondmate +# selector takes the from-firstmate carrier and its reply-routing contract; every +# other selector is an ordinary crewmate or scout and takes the generic +# firstmate-steer kind, which carries no reply expectation. MARK_FROM_FIRSTMATE=0 +MARK_FIRSTMATE_STEER=0 PENDING_REPLY_CORR= PENDING_REPLY_CREATED=0 TARGET_TASK_ID= -if [ -n "$TARGET_SELECTOR" ] && [ -n "$TARGET_META" ] && [ "$(fm_meta_get "$TARGET_META" kind)" = secondmate ]; then - MARK_FROM_FIRSTMATE=1 - TARGET_TASK_ID=$(fm_send_id_from_meta "$TARGET_META") +if [ -n "$TARGET_SELECTOR" ] && [ -n "$TARGET_META" ]; then + if [ "$(fm_meta_get "$TARGET_META" kind)" = secondmate ]; then + MARK_FROM_FIRSTMATE=1 + TARGET_TASK_ID=$(fm_send_id_from_meta "$TARGET_META") + else + MARK_FIRSTMATE_STEER=1 + fi fi # Resolve the target's harness from its meta (recorded by fm-spawn), used only to @@ -226,6 +249,14 @@ if [ "${1:-}" = "--key" ]; then fi else MESSAGE=$* + if [ "$MARK_FIRSTMATE_STEER" = 1 ]; then + # Harness-dispatched commands are sent bare; see the carve-out note above. + case "$MESSAGE" in + /*) ;; + \$*) [ "$TARGET_HARNESS" = codex ] || fm_operational_input_construct firstmate-steer "$MESSAGE" MESSAGE ;; + *) fm_operational_input_construct firstmate-steer "$MESSAGE" MESSAGE ;; + esac + fi if [ "$MARK_FROM_FIRSTMATE" = 1 ]; then # Reuse an existing correlation id for recovery resends; otherwise create a # durable parent expectation before delivery. Transport success never diff --git a/bin/fm-supervise-daemon.sh b/bin/fm-supervise-daemon.sh index 6ec14aed4b..c36e89f7bf 100755 --- a/bin/fm-supervise-daemon.sh +++ b/bin/fm-supervise-daemon.sh @@ -464,7 +464,9 @@ clear_pause_tracking() { # watcher_key=$(_stale_key "$win") rm -f "$state/.subsuper-paused-$key" "$state/.subsuper-stale-$key" \ "$state/.paused-$watcher_key" "$state/.paused-rechecked-$watcher_key" "$state/.paused-resurfaced-$watcher_key" \ - "$state/.stale-$watcher_key" "$state/.stale-since-$watcher_key" "$state/.wedge-escalations-$watcher_key" + "$state/.paused-liveprobe-$watcher_key" \ + "$state/.stale-$watcher_key" "$state/.stale-since-$watcher_key" "$state/.wedge-escalations-$watcher_key" \ + "$state/.progress-$watcher_key" } reconcile_pause_tracking() { # @@ -1190,7 +1192,7 @@ handle_wake() { # case "$reason" in signal:*) kind=signal; arg="${reason#signal: }" decision=$(classify_signal "$arg" "$state") ;; - stale:*) kind=stale; arg="${reason#stale: }" + stale:*) kind=stale; arg=$(stale_reason_window "$reason") decision=$(classify_stale "$arg" "$state") ;; check:*) decision=$(classify_check "$reason") ;; heartbeat|heartbeat:*) decision=$(classify_heartbeat) ;; diff --git a/bin/fm-wake-drain.sh b/bin/fm-wake-drain.sh index c3bf7335c0..b78f896078 100755 --- a/bin/fm-wake-drain.sh +++ b/bin/fm-wake-drain.sh @@ -74,6 +74,28 @@ DRAIN_LOCK_HELD=false # Raw output and queue deletion are authoritative. Everything below is # best-effort and cannot restore, duplicate, hide, or fail the consumed rows. + +# Supervision latency and drain depth. Each queue record carries the epoch at +# which the watcher enqueued it, but nothing recorded when firstmate actually +# consumed it, so the delay between an event happening and the coordinator +# acting on it - the most direct expression of coordinator attention cost - had +# no series at all. Depth is the DEDUPED record count, the number of distinct +# wakes this turn must handle: the raw queue coalesces repeat records per key, +# so a raw count reads high against what firstmate is really handed. Latency is +# the age of the oldest record in that deduped set. Written to the same bounded +# log the watcher uses, from the same writer, at drain cadence (a few times an +# hour), strictly after the authoritative consumption boundary above. +drain_telemetry() { + local depth oldest now + [ -n "$RAW_ROWS" ] || return 0 + depth=$(printf '%s\n' "$RAW_ROWS" | grep -c .) || return 0 + oldest=$(printf '%s\n' "$RAW_ROWS" | cut -f1 | grep -E '^[0-9]+$' | sort -n | head -1) + [ -n "$oldest" ] || return 0 + now=$(date +%s) + triage_log "drain: depth=$depth oldest_wait=$(( now - oldest ))s" +} +drain_telemetry || true + (fm_wake_print_annotations "$RAW_ROWS") || true assert_watcher_liveness exit 0 diff --git a/bin/fm-wake-lib.sh b/bin/fm-wake-lib.sh index 929c7231a4..8c4856031b 100755 --- a/bin/fm-wake-lib.sh +++ b/bin/fm-wake-lib.sh @@ -11,6 +11,24 @@ FM_WAKE_QUEUE_LOCK="${FM_WAKE_QUEUE_LOCK:-$STATE/.wake-queue.lock}" FM_LOCK_STALE_AFTER="${FM_LOCK_STALE_AFTER:-2}" mkdir -p "$STATE" +TRIAGE_LOG="${TRIAGE_LOG:-$STATE/.watch-triage.log}" +TRIAGE_LOG_MAX_BYTES=${FM_WATCH_TRIAGE_LOG_MAX_BYTES:-262144} + +# Append one bounded best-effort line for an absorbed supervision event. Lives +# here rather than beside the watcher's other helpers because the wake drain +# also records supervision telemetry and must not open a second, differently +# bounded writer against the same log. +triage_log() { + local sz + printf '[%s] %s\n' "$(date '+%Y-%m-%dT%H:%M:%S%z')" "$1" >> "$TRIAGE_LOG" 2>/dev/null || return 0 + sz=$(wc -c < "$TRIAGE_LOG" 2>/dev/null | tr -d '[:space:]') + case "$sz" in ''|*[!0-9]*) return 0 ;; esac + if [ "$sz" -ge "$TRIAGE_LOG_MAX_BYTES" ]; then + tail -n 2000 "$TRIAGE_LOG" > "$TRIAGE_LOG.tmp" 2>/dev/null && mv -f "$TRIAGE_LOG.tmp" "$TRIAGE_LOG" 2>/dev/null + rm -f "$TRIAGE_LOG.tmp" 2>/dev/null || true + fi +} + fm_current_pid() { printf '%s\n' "${BASHPID:-$$}" } diff --git a/bin/fm-watch-arm.sh b/bin/fm-watch-arm.sh index 0a783ce287..ac9d0a71ca 100755 --- a/bin/fm-watch-arm.sh +++ b/bin/fm-watch-arm.sh @@ -301,12 +301,30 @@ watch_output_has_wake() { grep -Eq '^(signal:|stale:|check:|heartbeat($|:))' "$out" 2>/dev/null } +# A stale reason carries the classification branch that produced it as a +# "[branch=]" tag (bin/fm-classify-lib.sh's stale_reason, the one owner of +# that format). Carrying +# it into this ledger row is what makes actionable wakes countable per branch +# from state/.watch-cycle-exits.log, which is the existing telemetry surface - +# no second collector is introduced for it. An untagged stale reason (an older +# watcher mid-upgrade, or a hand-written fixture) still classifies as the plain +# actionable-stale it always did. +watch_output_stale_branch() { # + local rest=${1#*"[branch="} + [ "$rest" != "$1" ] || return 0 + rest=${rest%%"]"*} + case "$rest" in + ''|*[!a-z-]*) return 0 ;; + esac + printf -- '-%s' "$rest" +} + watch_output_reason_type() { local out=$1 line line=$(grep -E '^(signal:|stale:|check:|heartbeat($|:))' "$out" 2>/dev/null | head -1 || true) case "$line" in signal:*) printf 'actionable-signal' ;; - stale:*) printf 'actionable-stale' ;; + stale:*) printf 'actionable-stale%s' "$(watch_output_stale_branch "$line")" ;; check:*) printf 'actionable-check' ;; heartbeat*) printf 'actionable-heartbeat' ;; *) printf 'none' ;; @@ -318,6 +336,14 @@ print_watch_output() { [ -s "$out" ] && cat "$out" } +# --- Main entry: the runtime below runs only when this file is executed as a +# script. When sourced (unit tests loading the classifier above), return here +# before parsing a mode or touching the singleton lock. Same guard, same reason, +# and the same position relative to the runtime as bin/fm-watch.sh's. +if [ "${BASH_SOURCE[0]}" != "$0" ]; then + return 0 +fi + mode=arm case "${1:-}" in ''|arm|--arm) mode=arm ;; diff --git a/bin/fm-watch.sh b/bin/fm-watch.sh index b7006e6362..d2d66016d5 100755 --- a/bin/fm-watch.sh +++ b/bin/fm-watch.sh @@ -140,6 +140,42 @@ PAUSE_RESURFACE_SECS=${FM_PAUSE_RESURFACE_SECS:-$FM_PAUSE_RESURFACE_SECS_DEFAULT # 5c trigger 3: proven-unreliable-at-runtime). A watcher restart re-probes # capability, so a transient herdr hiccup self-heals on the next cycle chain. EVENT_CAP_FAIL_MAX=${FM_EVENT_CAP_FAIL_MAX:-3} +# Park scan: a validation run that reaches a decision gate emits no wake of any +# kind. The gate state is computed correctly, but nothing polls for the +# transition - it is consulted only after a stale pane has already triggered +# classification, and a parked worker's pane may never go stale, so a worker that +# does not answer its gate is silent until something unrelated happens to look at +# it. The observed instance was ten minutes of silence, caught only because +# firstmate inspected the pane during an unrelated wake. +# This is the only wake class here that surfaces regardless of pane state, which +# is why it is bounded twice: a slow cadence, and a hard cap on how many tasks +# one sweep may read. It is also the only increment that ADDS wakes, so both +# bounds are configuration rather than constants. +PARK_SCAN_INTERVAL=${FM_PARK_SCAN_SECS:-120} # seconds between park sweeps +case "$PARK_SCAN_INTERVAL" in ''|*[!0-9]*) PARK_SCAN_INTERVAL=120 ;; esac +PARK_SCAN_MAX=${FM_PARK_SCAN_MAX:-3} # tasks read per sweep; 0 disables +case "$PARK_SCAN_MAX" in ''|*[!0-9]*) PARK_SCAN_MAX=3 ;; esac +# Slow-poll telemetry threshold. The only supervision question a per-poll +# duration answers is "can this loop still hold its cadence" - the saturation +# signal that would justify a second supervisor process or a supervisor +# hierarchy. That question needs the measurement ONLY once a poll approaches +# FM_POLL, so a healthy poll records nothing: stamping every poll would write +# ~5,700 lines a day into state/.watch-triage.log and evict the absorbed-wake +# history that log exists for, well inside FM_WATCH_TRIAGE_LOG_MAX_BYTES. +# Default is two thirds of the poll interval, the same fraction the saturation +# gate is stated against. Set FM_SLOW_POLL_SECS=0 to record every poll. +SLOW_POLL_SECS=${FM_SLOW_POLL_SECS:-} +if [ -z "$SLOW_POLL_SECS" ]; then + # FM_POLL may be fractional - tests drive sub-second cadences - so derive the + # default only from a whole-second interval and otherwise use the threshold the + # saturation gate is stated at directly. + case "$POLL" in + ''|*[!0-9]*) SLOW_POLL_SECS=10 ;; + *) SLOW_POLL_SECS=$(( POLL * 2 / 3 )) ;; + esac + [ "$SLOW_POLL_SECS" -ge 1 ] || SLOW_POLL_SECS=1 +fi +case "$SLOW_POLL_SECS" in ''|*[!0-9]*) SLOW_POLL_SECS=10 ;; esac # Per-process memo for the push-capability probe (fm_backend_events_capable runs # a ~220KB `herdr api schema` read, too heavy to repeat every poll). Keyed by # ":"; re-probed only when that key changes. @@ -251,13 +287,47 @@ FM_WEDGE_DEMAND_INSPECT_COUNT=${FM_WEDGE_DEMAND_INSPECT_COUNT:-3} # Repeat-poll wedge-timer bookkeeping for an already-classified stale hash # absorbed as provably-working - repairs a missing/corrupt timer (self-heals a # watcher restart between recording the hash and recording the timer), or -# escalates once STALE_ESCALATE_SECS have elapsed. Never re-reads the crew -# state (the costly check already ran once, at classification time). Shared by -# both places a hash can be absorbed this way: the plain non-terminal path, -# and the stale_is_terminal-overridden path (a captain-relevant status-log -# line that an active run/busy pane outranked). +# escalates once STALE_ESCALATE_SECS have elapsed. Shared by both places a hash +# can be absorbed this way: the plain non-terminal path, and the +# stale_is_terminal-overridden path (a captain-relevant status-log line that an +# active run/busy pane outranked). +# +# The timer's own reset conditions are a pane-hash change and a busy signature - +# precisely the two things a healthy worker driving a no-mistakes run cannot +# produce, because the pipeline owns the branch and renders nothing to that +# worker's pane. So the escalation fired on healthy validating workers, over and +# over, on the same unchanged hash: 28 of 61 stale wakes across one measured +# 22.5-hour window, concentrated on three panes, every inter-wake interval at or +# above STALE_ESCALATE_SECS plus one coordinator turn. +# +# The fix is a third reset condition that a validating worker CAN produce: +# forward progress in its pipeline. Progress is a difference, so it needs a +# previous value; state/.progress- is that value. See +# crew_progress_fingerprint (bin/fm-classify-lib.sh) and bin/fm-crew-state.sh's +# --progress block. +# +# Three properties of the comparison matter, and all three are deliberate: +# - It runs ONLY on the escalation branch, so the one bounded no-mistakes call +# it costs is spent at the exact moment the alternative is spending a whole +# coordinator turn. The repeat-poll path still re-reads nothing. +# - With no stored baseline it escalates, exactly as before. The first +# escalation of a chain is preserved on purpose: with nothing to compare +# against, absence of evidence is not evidence of progress, and suppressing +# it would trade this false positive for a false negative on a frozen worker. +# What the fingerprint suppresses is the REPEAT escalations, each backed by +# positive evidence that the run moved. +# - An empty or unreadable fingerprint compares equal and escalates. +# +# Known and accepted narrowing: a worker that freezes while its pipeline keeps +# advancing is absorbed here. That shape is real, because the pipeline spawns its +# own agents. It is accepted because the alternative today is escalating every +# healthy validating worker, and because a run that reaches a gate and gets no +# response is separately surfaced by the park scan. If evidence ever shows +# workers freezing under advancing pipelines, the fix is one more deterministic +# term in the fingerprint, not a supervisor above this one. wedge_timer_check() { # local win=$1 since_file=$2 label=$3 escalation_file=$4 since age n reason + local progress_file fp prev_fp since=$(cat "$since_file" 2>/dev/null || true) case "$since" in ''|*[!0-9]*) @@ -267,11 +337,22 @@ wedge_timer_check() { # /dev/null || true) + if [ -n "$fp" ] && [ -n "$prev_fp" ] && [ "$fp" != "$prev_fp" ]; then + printf '%s' "$fp" > "$progress_file" + date +%s > "$since_file" + rm -f "$escalation_file" + triage_log "absorbed $label (advanced since the last check): $win" + return 0 + fi + [ -n "$fp" ] && printf '%s' "$fp" > "$progress_file" n=$(( $(cat "$escalation_file" 2>/dev/null || echo 0) + 1 )) echo "$n" > "$escalation_file" - reason="stale: $win (idle ${age}s, possible wedge, escalation $n)" + reason=$(stale_reason wedge "$win" "idle ${age}s, possible wedge, escalation $n") if [ "$n" -ge "$FM_WEDGE_DEMAND_INSPECT_COUNT" ]; then - reason="stale: $win (idle ${age}s, possible wedge, escalation $n, demand-deep-inspection: same pane has wedge-escalated $n times in a row - do not re-absorb on the run-step/pane state alone)" + reason=$(stale_reason wedge "$win" "idle ${age}s, possible wedge, escalation $n, demand-deep-inspection: same pane has wedge-escalated $n times in a row - do not re-absorb on the run-step/pane state alone") fi fm_wake_append stale "$win" "$reason" || exit 1 rm -f "$since_file" @@ -296,7 +377,7 @@ handle_paused_stale() { # key=$(printf '%s' "$win" | tr ':/.' '___') printf '%s' "$h" > "$STATE/.stale-$key" : > "$STATE/.paused-$key" - rm -f "$STATE/.stale-since-$key" "$STATE/.wedge-escalations-$key" + rm -f "$STATE/.stale-since-$key" "$STATE/.wedge-escalations-$key" "$STATE/.progress-$key" statusf="$STATE/$task.status" mtime=$(stat_mtime "$statusf") case "$mtime" in ''|*[!0-9]*) mtime=$(date +%s) ;; esac @@ -304,7 +385,7 @@ handle_paused_stale() { # rf="$STATE/.paused-resurfaced-$key" rf_age=$(age_of "$rf") # 999999 when no prior re-surface if [ "$age" -ge "$PAUSE_RESURFACE_SECS" ] && [ "$rf_age" -ge "$PAUSE_RESURFACE_SECS" ]; then - reason="stale: $win (paused ${age}s, awaiting external - declared pause, rechecked on a long cadence not a wedge; confirm the wait still holds)" + reason=$(stale_reason pause-resurface "$win" "paused ${age}s, awaiting external - declared pause, rechecked on a long cadence not a wedge; confirm the wait still holds") fm_wake_append stale "$win" "$reason" || exit 1 date +%s > "$rf" wake "$reason" @@ -326,12 +407,38 @@ clear_pause_tracking() { # key=${key//\//_} key=${key//./_} clear_pause_state "$win" - rm -f "$STATE/.stale-$key" "$STATE/.stale-since-$key" "$STATE/.wedge-escalations-$key" + rm -f "$STATE/.stale-$key" "$STATE/.stale-since-$key" "$STATE/.wedge-escalations-$key" "$STATE/.progress-$key" } # Reconcile a declared pause or captain-held status with authoritative crew state. # Only a confidently dead ordinary crew may recover paused classification after # fm-crew-state has fallen back to stopped or unknown. +# +# A declared pause on a crew whose agent is NOT confidently dead deliberately +# fails open to `none`, which surfaces: the documented intent is that a live +# agent under a declared pause gets looked at, because it might be sitting on a +# decision gate its own status line has silenced. The defect was that this +# classification re-runs on every distinct pane hash, so "looked at once" was +# implemented as "looked at once per pane redraw" - unthrottled, and unbounded in +# principle, since a pane rendering a ticking clock or a token counter produces a +# new hash every poll forever. That is the shape of the incident this fixes; the +# measured production rate on an ordinary pane was low, but the ceiling is what +# matters. +# +# .paused-liveprobe- records that this pause window has already HAD its one +# live-agent surface. It is a pure predicate here and is written by +# surface_nonterminal_stale, at the moment a surface actually happens - not here, +# because this classification also returns `none` on paths that do not surface, +# and spending the budget on one of those would consume the documented look +# without ever taking it. It is released when the crew is observed to no longer +# be in a declared pause, so the next pause gets its own look. Once spent, a live +# agent takes the same bounded PAUSE_RESURFACE_SECS cadence a dead one takes, +# which keeps a forgotten pause from rotting invisibly. The first surface, and +# the dead-agent behaviour, are both unchanged. +pause_live_probe_spent() { # + [ -e "$STATE/.paused-liveprobe-$1" ] +} + pause_state_class() { # local win=$1 task=$2 key last recheck_file class agent_alive key=${win//:/_} @@ -348,6 +455,10 @@ pause_state_class() { # if [ "$(window_kind "$win")" != secondmate ]; then agent_alive=$(fm_backend_agent_alive "$(window_backend "$win")" "$win" 2>/dev/null) || agent_alive=unknown if [ "$agent_alive" != dead ]; then + if pause_live_probe_spent "$key"; then + printf 'paused' + return + fi rm -f "$recheck_file" printf 'none' return @@ -365,6 +476,10 @@ pause_state_class() { # if [ "$(window_kind "$win")" != secondmate ]; then agent_alive=$(fm_backend_agent_alive "$(window_backend "$win")" "$win" 2>/dev/null) || agent_alive=unknown if [ "$agent_alive" != dead ]; then + if pause_live_probe_spent "$key"; then + printf 'paused' + return + fi rm -f "$recheck_file" printf 'none' return @@ -379,9 +494,10 @@ pause_state_class() { # } surface_nonterminal_stale() { # - local win=$1 h=$2 key task last + local win=$1 h=$2 key task last reason key=$(printf '%s' "$win" | tr ':/.' '___') - fm_wake_append stale "$win" "stale: $win" || exit 1 + reason=$(stale_reason nonterminal "$win") + fm_wake_append stale "$win" "$reason" || exit 1 printf '%s' "$h" > "$STATE/.stale-$key" rm -f "$STATE/.stale-since-$key" task=$(window_to_task "$win" "$STATE") @@ -390,10 +506,15 @@ surface_nonterminal_stale() { # : > "$STATE/.paused-$key" date +%s > "$STATE/.paused-rechecked-$key" date +%s > "$STATE/.paused-resurfaced-$key" + # This IS the one live-agent look a declared pause is owed. Record it here, + # where the surface is real, so every later redraw of the same pause window + # takes the bounded cadence instead of surfacing again. + : > "$STATE/.paused-liveprobe-$key" else - rm -f "$STATE/.paused-$key" "$STATE/.paused-rechecked-$key" "$STATE/.paused-resurfaced-$key" + rm -f "$STATE/.paused-$key" "$STATE/.paused-rechecked-$key" "$STATE/.paused-resurfaced-$key" \ + "$STATE/.paused-liveprobe-$key" fi - wake "stale: $win" + wake "$reason" } # Check and heartbeat cadence must survive actionable exits and restarts: the @@ -692,6 +813,8 @@ while :; do # Liveness beacon for fm-guard.sh: a fresh mtime here means a watcher is # alive. Supervision scripts warn when this goes stale with tasks in flight. touch "$STATE/.last-watcher-beat" + cycle_started=$(date +%s) + cycle_windows=0 # Parent-owned secondmate pending-reply reconciliation: resolve correlated # parent reports, observe backend busy/idle turn completion, send one recovery @@ -767,6 +890,83 @@ while :; do touch "$STATE/.last-check" fi + # Park scan. Placed with the other slow sweep and before the signal scan for + # the same anti-starvation reason: wake() exits the cycle, so a sweep placed + # after the per-wake paths would be starved by a chatty sibling crewmate + # exactly when a quiet parked worker most needs noticing. It is due only every + # PARK_SCAN_INTERVAL, so most cycles skip this block entirely. + # + # A gate must be seen UNCHANGED across two sweeps before it surfaces: a run + # that reaches a gate and gets answered promptly is normal and must stay + # silent, and one sweep cannot tell those apart. Once surfaced, the same gate + # is not surfaced again - firstmate has been told - until the gate itself + # changes. Only a run-attributed gate is visible here; a worker blocked on + # something outside its run is not, and nothing detects that deterministically + # today short of the worker declaring it, which the status protocol already is. + # + # PARK_SCAN_MAX and state/.park-scan-cursor solve two DIFFERENT problems and + # both are required; do not delete the cap because the cursor looks like it + # made it redundant. The cap bounds the work of ONE sweep - each scanned task + # costs a bounded but real `no-mistakes` call, so an uncapped sweep over a + # large fleet is an unbounded-work bug on every interval. The cursor bounds the + # TIME TO FULL COVERAGE - the cap alone re-read the same first PARK_SCAN_MAX + # tasks forever, so every task past the cap was never park-scanned at all and + # the silent-gate hole this sweep exists to close stayed permanently open for + # them. Together: at most PARK_SCAN_MAX reads per sweep, and every ship task + # covered within ceil(N/PARK_SCAN_MAX) sweeps. + # + # The rotation is a persisted offset into recorded_windows' stable glob order, + # advanced by the number of ship windows actually scanned and wrapped modulo + # the ship-window count - deterministic, so coverage is provable rather than + # probabilistic. It is advanced BEFORE each window is read, because wake() + # exits the cycle: an offset advanced afterwards would be lost on exactly the + # sweeps that surfaced something, and the next sweep would re-read the window + # it just reported. The cursor lives beside .last-park-scan under STATE with + # the rest of the watcher's per-sweep bookkeeping, and is only a hint: a + # missing, corrupt or out-of-range value reads as 0 and simply restarts + # coverage from the top of the fleet. + if [ "$PARK_SCAN_MAX" -gt 0 ] && [ "$(age_of "$STATE/.last-park-scan")" -ge "$PARK_SCAN_INTERVAL" ]; then + touch "$STATE/.last-park-scan" + park_windows=() + while IFS= read -r w; do + [ "$(window_kind "$w")" = ship ] || continue + [ -n "$(window_to_task "$w" "$STATE")" ] || continue + park_windows+=("$w") + done < <(recorded_windows) + park_total=${#park_windows[@]} + if [ "$park_total" -gt 0 ]; then + park_cursor=$(cat "$STATE/.park-scan-cursor" 2>/dev/null || true) + case "$park_cursor" in ''|*[!0-9]*) park_cursor=0 ;; esac + park_cursor=$((park_cursor % park_total)) + park_scanned=0 + while [ "$park_scanned" -lt "$PARK_SCAN_MAX" ] && [ "$park_scanned" -lt "$park_total" ]; do + w=${park_windows[$(((park_cursor + park_scanned) % park_total))]} + park_scanned=$((park_scanned + 1)) + printf '%s' "$(((park_cursor + park_scanned) % park_total))" > "$STATE/.park-scan-cursor" + task=$(window_to_task "$w" "$STATE") + [ -n "$task" ] || continue + key=$(printf '%s' "$w" | tr ':/.' '___') + gate=$(crew_parked_gate "$task") + if [ -z "$gate" ]; then + rm -f "$STATE/.park-$key" "$STATE/.park-surfaced-$key" + continue + fi + if [ "$(cat "$STATE/.park-surfaced-$key" 2>/dev/null || true)" = "$gate" ]; then + triage_log "absorbed park (already surfaced, $gate): $w" + continue + fi + if [ "$(cat "$STATE/.park-$key" 2>/dev/null || true)" = "$gate" ]; then + printf '%s' "$gate" > "$STATE/.park-surfaced-$key" + reason=$(stale_reason park "$w" "$gate across two sweeps - the run is waiting on a response the worker has not given") + fm_wake_append stale "$w" "$reason" || exit 1 + wake "$reason" + fi + printf '%s' "$gate" > "$STATE/.park-$key" + triage_log "absorbed park (first sighting, $gate): $w" + done + fi + fi + # On the first changed signal, linger one grace period and re-scan before # classifying: a crewmate's final status write and the same turn's turn-end # hook land seconds apart, and reporting them as separate actionable wakes @@ -829,14 +1029,16 @@ EOF # stale hash is surfaced, absorbed, or timed toward escalation once (.stale-* # remembers the hash already classified). while IFS= read -r w; do + cycle_windows=$(( cycle_windows + 1 )) kind=$(window_kind "$w") task=$(window_to_task "$w" "$STATE") key=${w//:/_} key=${key//\//_} key=${key//./_} last=$(last_status_line "$STATE/$task.status") - if ! status_is_paused_or_captain_held "$last" && [ -e "$STATE/.paused-$key" ]; then - clear_pause_tracking "$w" + if ! status_is_paused_or_captain_held "$last"; then + rm -f "$STATE/.paused-liveprobe-$key" + [ -e "$STATE/.paused-$key" ] && clear_pause_tracking "$w" fi if [ "$kind" = secondmate ] && ! status_is_paused "$last"; then continue @@ -849,6 +1051,7 @@ EOF sf="$STATE/.stale-$key" ssf="$STATE/.stale-since-$key" ewf="$STATE/.wedge-escalations-$key" + pgf="$STATE/.progress-$key" # last progress fingerprint seen for this key (wedge_timer_check) pf="$STATE/.paused-$key" # flag: this key's stale is using the bounded pause cadence prev=$(cat "$hf" 2>/dev/null || true) if [ "$h" = "$prev" ]; then @@ -869,9 +1072,10 @@ EOF elif afk_present; then # Daemon owns triage: one-shot per distinct stale hash, as before. if [ "$(cat "$sf" 2>/dev/null || true)" != "$h" ]; then - fm_wake_append stale "$w" "stale: $w" || exit 1 + reason=$(stale_reason afk "$w") + fm_wake_append stale "$w" "$reason" || exit 1 printf '%s' "$h" > "$sf" - wake "stale: $w" + wake "$reason" fi elif stale_is_terminal "$w" "$STATE"; then # The log's last line is captain-relevant - but that alone is not @@ -894,11 +1098,12 @@ EOF date +%s > "$ssf" triage_log "absorbed stale (provably working, overriding a stale captain-relevant status): $w" else - fm_wake_append stale "$w" "stale: $w" || exit 1 + reason=$(stale_reason terminal "$w") + fm_wake_append stale "$w" "$reason" || exit 1 printf '%s' "$h" > "$sf" rm -f "$ssf" mark_surfaced "$STATE/$(window_to_task "$w" "$STATE").status" - wake "stale: $w" + wake "$reason" fi elif [ -e "$ssf" ]; then # This exact hash was already overridden as provably-working (a @@ -959,7 +1164,7 @@ EOF fi else # Pane busy or not yet stably stale: reset pending escalation bookkeeping. - rm -f "$ssf" "$ewf" + rm -f "$ssf" "$ewf" "$pgf" if [ -e "$pf" ] && { [ "$n" -ge 2 ] || ! status_is_paused_or_captain_held "$(last_status_line "$STATE/$(window_to_task "$w" "$STATE").status")"; }; then clear_pause_tracking "$w" fi @@ -967,7 +1172,7 @@ EOF else printf '%s' "$h" > "$hf" echo 0 > "$cf" - rm -f "$ssf" "$ewf" + rm -f "$ssf" "$ewf" "$pgf" task=$(window_to_task "$w" "$STATE") if ! afk_present && status_is_paused_or_captain_held "$(last_status_line "$STATE/$task.status")" && ! window_is_busy "$w" "$tail40"; then case "$(pause_state_class "$w" "$task")" in @@ -1009,10 +1214,27 @@ EOF else touch "$STATE/.last-heartbeat" echo $(( $(cat "$STATE/.heartbeat-streak" 2>/dev/null || echo 0) + 1 )) > "$STATE/.heartbeat-streak" - triage_log "absorbed heartbeat (no captain-relevant change)" + # The heartbeat line carries this home's recorded endpoint count. Fleet + # size is instantaneously readable at any time by counting state/*.meta, + # but it was never RECORDED, so no historical series existed to check the + # concurrency thresholds that gate a batch supervisor or a supervisor + # hierarchy against. The heartbeat is the right carrier precisely because + # it is rare and already backs off on an idle fleet: those thresholds are + # stated as sustained levels over days, which coarse periodic sampling + # answers, and no separate collector or cadence is introduced for it. + triage_log "absorbed heartbeat (no captain-relevant change) fleet=$cycle_windows" fi fi + # Saturation telemetry, recorded only when this poll's classification work + # approached the poll interval. A cycle that ends in a wake never reaches here + # because wake() exits the process, which is correct: the question is whether + # the ABSORBING loop can hold its cadence, not how long a surfaced cycle took. + cycle_elapsed=$(( $(date +%s) - cycle_started )) + if [ "$cycle_elapsed" -ge "$SLOW_POLL_SECS" ]; then + triage_log "slow poll: ${cycle_elapsed}s of ${POLL}s over $cycle_windows recorded endpoint(s)" + fi + # Terminal wait: a bounded native-event wait for push-capable homes (herdr), # else the blind poll sleep. See event_wait_or_sleep. event_wait_or_sleep diff --git a/docs/architecture.md b/docs/architecture.md index d1bbb1c1ff..dde9961525 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -10,7 +10,21 @@ firstmate's always-loaded operating contract and routing index for conditional p A zero-token bash watcher (`bin/fm-watch.sh`) sleeps on the fleet, classifies detected wakes in bash, and wakes the first mate only when something is actionable. Actionable wakes include captain-relevant status signals, no-verb signals whose crew is not provably working, authenticated check output such as PR merge polling or an X-mode mention, stale panes whose crew is not provably working whether their status log looks terminal or non-terminal, provably-working stale panes that persist past `FM_STALE_ESCALATE_SECS`, declared external waits that remain paused past `FM_PAUSE_RESURFACE_SECS`, and heartbeat backstop hits. +A bounded park sweep adds the one wake class that does not depend on pane state at all: a validation run that reaches a decision gate produces no signal, no stale pane, and no log line of any kind, so a worker that never answers its gate was silent until something unrelated happened to look at it. +The sweep reads at most `FM_PARK_SCAN_MAX` tasks every `FM_PARK_SCAN_SECS`, surfaces only a gate seen unchanged across two sweeps, and surfaces that gate only once; a run that keeps moving between gates, or leaves them, stays silent. +A persisted cursor in `state/.park-scan-cursor` rotates which tasks the next sweep reads, so the cap bounds the work of one sweep while every ship task is still covered within `ceil(N / FM_PARK_SCAN_MAX)` sweeps. +Both bounds are required: without the cursor a fleet larger than the cap left every task past it never scanned at all, and without the cap a large fleet would pay an unbounded number of run reads on every interval. +Setting `FM_PARK_SCAN_MAX` to zero switches it off, because it is the only supervision change here that adds wakes rather than removing them. +It sees only gates the run itself names: a worker blocked on something outside its run is not visible to it, and the status protocol is what already covers that. Repeated provably-working stale escalations on the same unchanged pane add an escalation count to the wake reason and, at `FM_WEDGE_DEMAND_INSPECT_COUNT`, a `demand-deep-inspection` marker. +That escalation resets on a pane-hash change, a busy signature, or forward progress in the crew's pipeline. +The progress term exists because a healthy worker driving a no-mistakes run can produce neither of the first two: the pipeline owns the branch and renders nothing to the worker's own pane, so a validating worker used to escalate on the same unchanged hash indefinitely. +Progress is a difference, so the watcher stores the previous value in `state/.progress-` and compares it only on the escalation branch, where the alternative is spending a coordinator turn. +`bin/fm-crew-state.sh --progress` is the single owner of that fingerprint and of which fields may appear in it; a field carrying elapsed time may not, because a fingerprint that differs on every read would reset the escalation unconditionally and leave a genuinely frozen worker unable to escalate at all. +With no stored previous value, and with an unreadable fingerprint, the escalation fires exactly as it did before: the reset is taken only on positive evidence that the run advanced. +A run read that was owed and did not answer, such as a timed-out or absent `no-mistakes`, reports an empty fingerprint for the same reason, because a partially-populated one would compare unequal and read as progress. +Every stale wake reason ends with a `[branch=]` tag naming the classification rule that produced it, because six separate paths emit an otherwise identical `stale: ` opening. +The tag is prose for a reader and a substring match, never a parsed protocol field; `stale_reason_window` in `bin/fm-classify-lib.sh` is the one owner that recovers a window from a decorated reason. Those actionable wakes are written to a durable local queue (`state/.wake-queue`) before detector state advances, so a missed process exit can be recovered by draining the queue. When a canonical validated PR poll returns exactly `merged`, the watcher appends that durable notification before publishing a private receipt bound to the poll's registration, bytes, file identities, metadata, provider, URL, and task ID. The receipt makes retirement safely retryable across restarts: fixed-path recovery revalidates the same evidence, removes the runnable check first, removes its registration and data sidecars, removes the receipt last, and preserves task metadata including `pr=` and `pr_head=`. @@ -18,8 +32,10 @@ A concurrent replacement remains armed, every non-merged or invalid observation `bin/fm-pr-lib.sh` owns the receipt format and strict identity mechanics, while `bin/fm-watch.sh` owns queue-before-retirement ordering. No-verb wakes, such as `working:` notes and bare turn-ended signals, are benign only when `bin/fm-crew-state.sh` reports positive evidence that the crew is still working: an actively running no-mistakes step attributed to that crew's current code or a backend busy signature. A crew that declares `paused:` for a known external wait is separately absorbed while idle and re-surfaced only on the longer pause cadence, rather than being treated as a possible wedge. -For an ordinary crew that has stopped, the normal-mode watcher first surfaces one stale wake, then applies that same cadence to an unchanged `paused:` or durable `captain-held` endpoint only when the backend confidently reports its agent dead. -Live or inconclusive liveness remains fail-open at that initial surface, and the secondmate idle-endpoint exemption is unchanged. +For an ordinary crew that has stopped, the normal-mode watcher surfaces one stale wake per pause window, then applies that same cadence to an unchanged `paused:` or durable `captain-held` endpoint. +A backend that confidently reports the agent dead takes the bounded cadence immediately. +Live or inconclusive liveness still fails open for that one surface, because such a crew may be sitting on a decision gate its own status line silenced; `state/.paused-liveprobe-` records that the look has been taken, so a pane that keeps redrawing cannot convert "once" into "once per redraw". +The marker is released when the crew is observed to no longer declare a pause, so a later pause gets its own look, and the secondmate idle-endpoint exemption is unchanged. Its initial normal-mode status signal still surfaces through the no-verb path, while away mode self-handles that routine signal and owns the later recheck. Fresh stale panes use the same current-state read before trusting the status log, so an active run or busy pane outranks an old captain-relevant status-log line left behind before validation. No-change heartbeats are also benign. @@ -52,12 +68,16 @@ A bounded direct-report terminal tail can help diagnose a mismatch by showing th The snapshot strips control sequences, retains only capture metadata and literal event-corroboration flags, and never lets terminal evidence override a valid structured classification. The default path remains local-only; live GitHub enrichment exists only behind the bearings `--include-prs` opt-in. Optional X mode integrates with the watcher only after explicit opt-in; [configuration.md](configuration.md#x-mode-env) owns its generated-artifact and dispatch mechanics. +[`supervision-dormant-designs.md`](supervision-dormant-designs.md) owns the larger supervision architectures this design deliberately does not build - a batch abstraction, speculative-parallel execution, a second or hierarchical supervisor, a model in the supervision loop, and a typed event bus - each with the measurable trigger that would justify revisiting it. At session start, `bin/fm-session-start.sh` emits exactly one primary-harness supervision block rendered by `bin/fm-supervision-instructions.sh` from `docs/supervision-protocols/`. That block owns the live wait shape for the running primary harness: Claude's Stop `asyncRewake` hook owns tokenless re-arm cycles, Grok uses background-notify cycles, Codex uses bounded foreground checkpoints, Pi uses its two tracked primary extensions, and OpenCode uses its TUI plugin. `bin/fm-watch-arm.sh` remains the verified arm wrapper for protocols that call it; it forks the watcher as a tracked child, verifies it is genuinely alive with a fresh liveness beacon, and prints an honest `started`, `attached`, or nonzero `FAILED` status. On `attached` it stays live across identity-matched successors, and an unexplained clean child close either attaches to a verified healthy successor or becomes the typed nonzero `watcher: FAILED - cycle ended without an actionable reason` result. -The arm layer records one bounded lifecycle row per observed cycle in `state/.watch-cycle-exits.log`; `state/.watch-triage.log` remains exclusively the absorbed-wake debug log. +The arm layer records one bounded lifecycle row per observed cycle in `state/.watch-cycle-exits.log`; `state/.watch-triage.log` carries absorbed wakes plus the sampled supervision measurements below, and carries no lifecycle semantics. +A stale cycle's ledger row records `reason=actionable-stale-`, so actionable wakes are countable per classification rule from telemetry that already existed rather than from a second collector. +Two further measurements ride the same two logs and are deliberately sampled rather than continuous: the watcher stamps a `slow poll` line only once a poll's classification work reaches `FM_SLOW_POLL_SECS`, which is the saturation threshold that would justify a second supervisor, and it stamps this home's recorded endpoint count onto the rare no-change heartbeat line so sustained concurrency has a historical series. +After the drain commits its authoritative output, `bin/fm-wake-drain.sh` appends one `drain:` line recording how many distinct wakes the turn was handed and how long the oldest of them waited. Pi and OpenCode verify session-lock ownership and launch one singleton successor from their child-close handlers before delivering an actionable wake prompt, with bounded exponential retry for failed restoration. Claude's `bin/fm-claude-stop-autoarm.sh` hook fires on every Stop and, when the home is eligible and still needs supervision, claims one home-scoped cycle, foregrounds the arm wrapper, and translates an actionable close or typed failure into one exit-2 rewake. [`watcher-continuity.md`](watcher-continuity.md) owns Claude's residual active-turn coverage and watcher-status command-gating boundary. @@ -165,8 +185,13 @@ Seeding is transactional: if validation, cloning, initialization, or registry up The same project may appear in multiple secondmate homes when their scopes differ, such as issue triage versus feature development. Secondmates are idle by default: after startup recovery reconciles only work already in their own home, an empty queue waits silently for routed tasks, and they never self-initiate surveys or audits. When called with `FM_HOME=` or when `FM_HOME` is already set to the active firstmate home, metadata-routed `fm-send.sh` requests to a live `kind=secondmate` use the live-charter-compatible `from-firstmate` carrier owned by `bin/fm-operational-input.sh`, so the secondmate returns terse answers through status lines and detailed answers through docs plus status pointers instead of replying only in its own chat. +A metadata-routed steer to an ordinary crewmate or scout carries the generic `firstmate-steer` kind from the same owner, and creates no reply expectation. +Before that, a worker received exactly one marked message - its launch brief - and a bare stream afterwards, so it could not tell a firstmate steer from a human typing into its pane; the operating contract forbids a crewmate from addressing the captain while the transport withheld the means to tell who was speaking, and both directions of that confusion were observed in practice. +An explicit backend target, the key-send path, and any message the harness itself must dispatch - a leading `/` slash command, or a leading `$` skill invocation on codex - stay bare, the last because a prefix in front of such a message turns it into plain text and the steer silently fails to run. +Generated briefs teach the rule at the only moment a worker reads instructions. +Deliberately not extended to crewmates: the correlated pending-reply record. Acknowledgement machinery answers "sent but not received"; the observed failure is a message never sent, which no acknowledgement protocol can detect. The parent guards every marked request against a missing correlated report without reading the secondmate conversation; `bin/fm-pending-reply-lib.sh` owns the correlation, recovery, escalation, and retention contract. -Explicit backend-target sends and direct human typing stay unmarked, so captain intervention in a secondmate pane remains conversational. +Direct human typing stays unmarked, so captain intervention in a worker pane remains conversational. After seeding a secondmate, `fm-backlog-handoff.sh` validates the fleet-specific handoff, then atomically delegates already-judged in-scope queued item moves to `tasks-axi mv` so the domain queue starts in the right place. Idle secondmate panes are healthy; teardown is explicit and refuses while the secondmate home has in-flight work unless the captain has approved discard with `--force`. diff --git a/docs/configuration.md b/docs/configuration.md index 896b98ae31..d310fcdbc2 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -427,7 +427,10 @@ FM_CLASSIFY_PAUSED_VERB=paused # leading status verb for a declared external FM_STALE_ESCALATE_SECS=240 # idle seconds before a provably-working stale pane escalates; stale panes whose crew is not provably working surface immediately unless they declare the pause verb FM_PAUSE_RESURFACE_SECS=3600 # seconds before an idle declared external wait re-surfaces for a recheck in the watcher or away-mode daemon FM_WEDGE_DEMAND_INSPECT_COUNT=3 # consecutive provably-working stale escalations on the same unchanged pane before demand-deep-inspection is added -FM_WATCH_TRIAGE_LOG_MAX_BYTES=262144 # size cap for the watcher's absorbed-wake debug log +FM_PARK_SCAN_SECS=120 # seconds between bounded park sweeps for a run parked at a decision gate its worker has not answered +FM_PARK_SCAN_MAX=3 # ship tasks read per park sweep, rotated by a persisted cursor so a larger fleet is still fully covered; 0 disables the sweep +FM_SLOW_POLL_SECS= # seconds of watcher classification work in one poll before a saturation line is recorded; unset derives two thirds of FM_POLL, 0 records every poll +FM_WATCH_TRIAGE_LOG_MAX_BYTES=262144 # size cap for the watcher and wake-drain supervision debug log FM_FLEET_SYNC_BOOTSTRAP_TIMEOUT= # optional seconds allowed for bootstrap's best-effort clone refresh; unset/blank defaults to max(20, 5 + 3 * origin-backed-project-count) FM_FLEET_PRUNE=1 # set to 0 to skip pruning local branches whose upstream is gone FM_STALE_WORKTREE_LOCK_AGE_SECS=30 # min mtime age before fm-teardown.sh treats a leftover worktree git index.lock as provably stale diff --git a/docs/documentation-audiences.json b/docs/documentation-audiences.json index 60773b0d45..0ff15b2a73 100644 --- a/docs/documentation-audiences.json +++ b/docs/documentation-audiences.json @@ -267,6 +267,10 @@ "path": "docs/subagent-guard.md", "audience": "maintainer-architecture" }, + { + "path": "docs/supervision-dormant-designs.md", + "audience": "maintainer-architecture" + }, { "path": "docs/supervision-protocols/claude.md", "audience": "agent-runtime" diff --git a/docs/supervision-dormant-designs.md b/docs/supervision-dormant-designs.md new file mode 100644 index 0000000000..cc3e4ac6d8 --- /dev/null +++ b/docs/supervision-dormant-designs.md @@ -0,0 +1,131 @@ +# Supervision dormant designs + +Larger supervision architectures that were considered, deliberately not built, and preserved here with the evidence that would justify revisiting them. + +[`architecture.md`](architecture.md) owns how supervision actually works. +This file owns why it is not something larger, so a future contributor inherits the argument rather than only the outcome. + +A record here is not a backlog item and not a promise. +Each one names the problem it would solve, the evidence for and against it today, and a measurable trigger. +A record without a trigger stated as a number against a named metric is a graveyard entry, not a dormant design, because nothing would ever cause anyone to look at it again. +Where a trigger cannot be measured with what the system currently records, that is stated too, along with the instrument it needs. + +## What supervision instruments today, and why only that + +Three measurements were added alongside the supervision fixes, all of them riding logs that already existed. +Every stale wake reason carries the classification rule that produced it, which the arm layer records in the existing cycle-exit ledger. +The watcher writes a slow-poll line only once a poll's classification work reaches `FM_SLOW_POLL_SECS`, and stamps this home's recorded endpoint count onto the rare no-change heartbeat line. +The wake drain records how many distinct wakes a turn was handed and how long the oldest of them waited. + +The rule applied was to collect only what an actual gate below depends on, and to reuse an existing surface wherever one would serve. +The alternative - a supervision telemetry subsystem sized for the metrics a dormant record might one day want - was rejected on its own terms: a second collector is a second component that must agree with the first, and this fleet has been bitten twice by duplicate ownership of the same facts. +Continuous per-poll sampling was rejected for a concrete reason rather than a stylistic one. +Stamping every poll would write roughly 5,700 lines a day into the absorbed-wake log and evict the history that log exists for, well inside its own size bound, so the instrument would have destroyed the evidence it was added to produce. +Threshold-triggered and heartbeat-cadence sampling answer the same questions, because every gate below is stated as a level sustained over days rather than as an instantaneous reading. + +Two metrics were deliberately left uncollected. +A human-intervention rate would require classifying captain messages, which is outside the supervision runtime. +An average fan-out cannot exist until a batch does, and the batch record below is the reason none does. + +## The wake-outcome ledger + +Nothing records what a wake led to. +Without that, "the classifier could not decide and a human judgement was needed" has never been counted, and neither has the false-positive share of any wake class. +This gates the model-supervisor record below, and it is the only honest measure of whether a supervision change removed noise rather than signal. + +It is not built because it is the only proposed instrument that costs the coordinator something on every turn, which makes adopting it a captain decision rather than an implementation one. +Until it exists, any claim that a supervision change reduced useless work rather than useful work is an estimate, and should be written as one. + +## Batch abstraction - deferred, not rejected + +**What it would be.** A `batch=` grouping key in task metadata plus a plan-document schema covering independence basis, verification, maximum concurrency, failure budget and base revision, so that a fan-out of related tasks is a first-class object rather than N unrelated ones. + +**Why it is not built.** The usual argument for defining an interface before it is exercised is that a later migration is expensive. +Measured here, it is not. +Task metadata is a flat key-value file that has already absorbed at least four independent field additions from four different writers, with no migration, no version, and no schema; readers use targeted line lookups rather than a parser. +Adding a grouping key when a real batch first exists is a non-event, so the compatibility benefit that would fund building it now is close to zero. + +The cost, by contrast, is concrete. +The plan-document schema is where an unexercised interface ossifies, and every semantic field in it is currently a guess. +A failure budget assumes batch failures are countable and fungible. +A maximum-concurrency field assumes the batch rather than the scheduler owns capacity, which contradicts the standing separation between deciding who does work and deciding when it runs. +A scoring of twenty real backlog items found four that justify parallel fan-out, and all four are the same shape - mechanical transformation against disjoint targets with a machine verifier - so a schema written against them would encode that one shape as if it were general. + +**What is preserved instead.** This record, and the implementation staying shaped so the key can be added later without rework: nothing in supervision assumes a task is unrelated to every other task, and nothing would have to be undone to group them. + +**Measurable trigger.** Revisit when all three hold for three consecutive days: actionable wakes per hour attributable to per-task supervision branches reach 30; concurrent active workers reach 12; and watcher per-poll duration reaches two thirds of the poll interval, meaning the loop can no longer hold its cadence. +The first and third are collectable now, from the branch tag and the slow-poll line. +The second is collectable now from the heartbeat fleet stamp, and has no history before it. + +**If it is ever built.** It must be a pure consumer of the existing fleet snapshot, never a second classifier, or it recreates the duplicate-ownership failure this fleet has already paid for twice. + +## Speculative-parallel execution - dormant and structurally blocked + +**What it would be.** Running competing attempts at the same task and keeping the winner, to buy wall-clock on task classes with a low first-attempt success rate. + +**Why it is disabled rather than merely unbuilt.** Every losing arm of a speculative round is, by definition, a worktree holding unlanded work. +Cleanup refuses to discard unlanded work without explicit captain authority, and that refusal is one of the strongest safety boundaries this fleet has, because unlanded work has been lost before. +So an N-way speculative round costs N-1 explicit captain authorizations, every round, forever. + +That is decisive rather than merely expensive: the mechanism would *increase* the exact cost it would be adopted to reduce. +Coordinator and captain attention is the measured scarce resource, model quota is the other, and speculative execution spends both to buy wall-clock, which is not the binding constraint. + +There is a second, quieter problem. +The task shape that satisfies deterministic verification - mechanical transformation with a machine verifier - is the same shape with a *high* first-attempt success rate. +The class that makes speculative execution safe is the class least likely to need it, and that is a property rather than a coincidence. + +**Why no compatibility work is warranted today.** Preserving compatibility would mean either an attempt-group abstraction in dispatch, which is the batch abstraction above and rejected on its own independent grounds, or relaxing the unlanded-work refusal into a general declared-scratch mode. +The second is a change to the fleet's strongest safety boundary, with a real cost today and no measured benefit, so preserving compatibility would cost more than the thing it preserves compatibility for. + +**Measurable trigger.** Revisit only when all of: a named task class shows a first-attempt success rate below 50% over at least 20 dispatches; deterministic verification exists for that class, so the winner is picked without judgement; wall-clock is identified as the binding constraint rather than attention or quota; and discarding a losing arm is cheap. +The success rate is not collectable today and needs an attempt counter in task metadata, which is independently useful for answering which task classes need rework. + +**If the cleanup contract ever changes.** A scout worktree is already declared scratch at dispatch and may be discarded once its report exists and the completion gate passes. +A speculative arm could be declared scratch under that same doctrine. +That mechanism exists and can be imitated when there is a reason to; it does not need to be generalized in advance, and generalizing it in advance is exactly the safety-boundary relaxation rejected above. + +## Batch supervisor process, and hierarchical supervision + +**What they would be.** A second long-lived supervisor owning a fan-out, or N supervisors partitioned across the fleet. + +**Why they are not built.** Both exist to answer "is this worker healthy?", and the progress-aware wedge reset made that question deterministic inside the supervisor that already exists. +Making the existing supervisor able to see forward progress removes the reason to add a tier above it. +One supervisor absorbs the overwhelming majority of events in bash at the concurrency this fleet has actually reached, and the two behavioural fixes attack precisely the pane-count-driven wake classes that would otherwise grow with the fleet. + +The cost is not the classification logic, which is small. +It is that this repo already carries an arm wrapper, a guard, a turn-end guard, an auto-arm hook and a lock protocol to make *one* supervisor reliable, and every backend, harness and recovery path would gain a second component that has to agree with the first. + +**Measurable trigger.** Watcher per-poll duration reaching the full poll interval at any concurrency, which is the loop failing to keep cadence; or concurrent workers reaching 20 with actionable wakes per hour at 30 after the current fixes have landed. +Both are collectable now. +Nothing in the current design forecloses a hierarchy - the durable wake queue is already the serialization point a merge would use - which is why no compatibility work is warranted for it either. + +## Model-mediated supervision + +**What it would be.** A model asked "is this worker stuck, confused, or working on the wrong thing?", sitting in the supervision loop. + +**Why it is not built.** Every decision the supervisor makes today is a string or integer comparison. +The one genuinely interpretive question is already routed to firstmate by the deep-inspection demand, and routing it to a cheaper model first yields a second-hand judgement firstmate then has to re-derive, costing a model call *and* the coordinator turn. + +The deeper objection is that the absorb model rests on every absorb decision being replayable from files. +A model verdict is not replayable, so supervision failures would stop being reproducible - which is precisely what made the misdiagnoses in this area expensive in the first place. + +**Measurable trigger.** At least 20% of actionable wakes over a rolling seven days terminating in "inspected, no action needed" after the current fixes have landed, or deep-inspection demands sustained at three a day for seven days. +The first half is not collectable without the wake-outcome ledger above. +The second half is collectable now from the branch tag. + +**If it is ever built.** It must sit beside the deterministic classifier as an advisory annotation on a wake firstmate already receives, never as an absorb authority. + +## Structured supervision event bus + +**What it would be.** Typed supervision events with schemas, consumed by more than one reader, replacing prose wake reasons. + +**Why it is not built.** One reader exists. +The classification branch is carried as a tagged substring inside the existing prose reason, which cost about fifteen lines; a bus costs a schema, a version, and a second component that must agree with the first. +Build it when a second consumer exists, not before. +Until then the tag is prose and a substring match, and nothing may branch on it as if it were a field. + +## Related + +- [`architecture.md`](architecture.md) - how supervision works today, including the wedge reset, the pause throttle, the steer marker and the park sweep. +- [`turnend-guard.md`](turnend-guard.md) - the structural backstop beneath every harness protocol. +- `bin/fm-crew-state.sh` - owns the progress fingerprint, including which fields may never enter it and why a simpler-looking version silently breaks the wedge escalation. diff --git a/docs/watcher-continuity.md b/docs/watcher-continuity.md index 457c035268..e4095a5067 100644 --- a/docs/watcher-continuity.md +++ b/docs/watcher-continuity.md @@ -44,7 +44,7 @@ An attached arm follows verified identity-matched successors and reports the sam The arm layer appends one tab-separated record per observed cycle to `state/.watch-cycle-exits.log`. Each record includes arm and watcher PIDs, start and end timestamps, exit code and signal, classified reason, beacon age, lock identity before and after close, and successor disposition. The file is size-capped through `FM_WATCH_CYCLE_LOG_MAX_BYTES` and `FM_WATCH_CYCLE_LOG_KEEP_LINES`. -`state/.watch-triage.log` remains only the watcher's bounded absorbed-wake debug log and carries no lifecycle semantics. +`state/.watch-triage.log` carries no lifecycle semantics; [architecture.md](architecture.md) owns what that bounded log does carry. The default 300-second grace is unchanged. Only the watcher process touches `state/.last-watcher-beat`; no helper process can make a wedged watcher appear healthy. diff --git a/tests/fm-backend-orca.test.sh b/tests/fm-backend-orca.test.sh index 66c3dd3653..88bbb24317 100755 --- a/tests/fm-backend-orca.test.sh +++ b/tests/fm-backend-orca.test.sh @@ -725,8 +725,13 @@ test_peek_send_and_crew_state_route_through_orca_meta() { "peek/crew-state did not read the recorded Orca terminal" assert_not_contains "$(cat "$LOG")" $'orca\x1f''terminal'$'\x1f''read'$'\x1f''--terminal'$'\x1f'"fm-$id" \ "crew-state should not read the stable Orca alias as a terminal handle" - assert_contains "$(cat "$LOG")" $'orca\x1f''terminal'$'\x1f''send'$'\x1f''--terminal'$'\x1f''term-io'$'\x1f''--text'$'\x1f''hello orca'$'\x1f''--json' \ + # Body match, not whole-argument match: a metadata-routed scout steer also carries + # the firstmate-steer mark (bin/fm-send.sh). This case is about the Orca route, not + # the marker, which is pinned in tests/fm-send-secondmate-marker.test.sh. + assert_contains "$(cat "$LOG")" $'orca\x1f''terminal'$'\x1f''send'$'\x1f''--terminal'$'\x1f''term-io'$'\x1f''--text'$'\x1f' \ "send did not type through the recorded Orca terminal" + assert_contains "$(cat "$LOG")" $'hello orca\x1f''--json' \ + "send did not type the steer body through the recorded Orca terminal" assert_contains "$(cat "$LOG")" $'orca\x1f''terminal'$'\x1f''send'$'\x1f''--terminal'$'\x1f''term-io'$'\x1f''--text'$'\x1f\x1f''--enter'$'\x1f''--json' \ "send did not submit Enter through the recorded Orca terminal" pass "fm-peek/fm-send/fm-crew-state route through backend=orca metadata" diff --git a/tests/fm-crew-state.test.sh b/tests/fm-crew-state.test.sh index bc0161d624..fc1ac53833 100755 --- a/tests/fm-crew-state.test.sh +++ b/tests/fm-crew-state.test.sh @@ -1047,6 +1047,172 @@ SH } # (i) kind=scout skips the run lookup entirely (its deliverable is a report). +# --- --progress: the wedge escalation's missing previous value --------------- +# +# The fingerprint exists so a caller holding two reads can tell "this worker has +# advanced" from "this worker is frozen". Everything it is allowed to contain +# follows from one property: it must be BYTE-IDENTICAL across two reads of a run +# that has not changed. The live `axi status` shape carries two fields that look +# ideal and violate exactly that property - active_for and last_activity both +# embed a ticking elapsed counter - and a fingerprint built from either differs +# on every comparison, resets the escalation unconditionally, and leaves a +# genuinely frozen worker unable to escalate ever again. That failure is silent, +# because nothing reports an escalation that did not happen, so it has to be +# caught here. This fixture reproduces the real shape verbatim, including the +# empty agent_pid and the non-numeric "starting" round token observed live. +run_ci_with_active_steps() { # [round] [ci-status] [completed] + local completed=${6:-3} + cat < + PATH="$1/fakebin:$PATH" FM_STATE_OVERRIDE="$1/state" "$CREW_STATE" "$2" --progress +} + +test_progress_fingerprint_is_stable_under_no_change() { + reset_fakes + local d first second; d=$(new_case progress-stable) + make_repo_on_branch "$d/wt" fm/prog-a + make_fakebin "$d" >/dev/null + fm_write_meta "$d/state/prog-a.meta" "window=fm:fm-prog-a" "worktree=$d/wt" "kind=ship" + + FM_FAKE_AXI_STATUS="$(run_ci_with_active_steps fm/prog-a 1h22m 43m56s)" + first=$(run_progress "$d" prog-a) + # Only the two ticking fields move. Nothing about the run has advanced. + FM_FAKE_AXI_STATUS="$(run_ci_with_active_steps fm/prog-a 2h3m 1h25m)" + second=$(run_progress "$d" prog-a) + [ "$first" = "$second" ] \ + || fail "a ticking elapsed field reached the fingerprint: '$first' then '$second' - the wedge escalation would now reset on every poll and never fire again" + assert_contains "$first" "ci" "fingerprint lost the active step name" + case "$first" in + *1h22m*|*43m56s*|*2h3m*|*1h25m*) fail "fingerprint embedded an elapsed counter: $first" ;; + esac + pass "--progress is byte-identical across two reads of an unchanged run (ticking fields excluded)" +} + +test_progress_fingerprint_moves_on_real_progress() { + reset_fakes + local d base advanced; d=$(new_case progress-advances) + make_repo_on_branch "$d/wt" fm/prog-b + make_fakebin "$d" >/dev/null + fm_write_meta "$d/state/prog-b.meta" "window=fm:fm-prog-b" "worktree=$d/wt" "kind=ship" + + FM_FAKE_AXI_STATUS="$(run_ci_with_active_steps fm/prog-b 10m 1m starting running 2)" + base=$(run_progress "$d" prog-b) + # A step completed: the monotonic completed-step count moves even though the + # active step, its status and its round are all unchanged. + FM_FAKE_AXI_STATUS="$(run_ci_with_active_steps fm/prog-b 10m 1m starting running 3)" + advanced=$(run_progress "$d" prog-b) + [ "$base" != "$advanced" ] || fail "a completed step did not move the fingerprint: $base" + # The active step's status moved. + FM_FAKE_AXI_STATUS="$(run_ci_with_active_steps fm/prog-b 10m 1m starting fixing 3)" + [ "$(run_progress "$d" prog-b)" != "$advanced" ] || fail "an active-step status change did not move the fingerprint" + # The round token moved. It is an opaque string here, never parsed as an int. + FM_FAKE_AXI_STATUS="$(run_ci_with_active_steps fm/prog-b 10m 1m 2 running 3)" + [ "$(run_progress "$d" prog-b)" != "$advanced" ] || fail "a round-token change did not move the fingerprint" + pass "--progress moves when a step completes, an active step changes status, or the round advances" +} + +test_progress_fingerprint_without_a_run_tracks_commits() { + reset_fakes + local d before after same; d=$(new_case progress-no-run) + make_repo_on_branch "$d/wt" fm/prog-c + make_fakebin "$d" >/dev/null + # kind=scout never drives a run of its own, so the head sha is the only + # available evidence of forward progress. Same for a ship task that has not + # started validating yet. + fm_write_meta "$d/state/prog-c.meta" "window=fm:fm-prog-c" "worktree=$d/wt" "kind=scout" + before=$(run_progress "$d" prog-c) + same=$(run_progress "$d" prog-c) + [ "$before" = "$same" ] || fail "no-run fingerprint was unstable: '$before' then '$same'" + git -C "$d/wt" commit -q --allow-empty -m "scout progress" + after=$(run_progress "$d" prog-c) + [ "$before" != "$after" ] || fail "a new commit did not move the no-run fingerprint: $before" + pass "--progress with no attributed run is stable, and moves on a new commit" +} + +test_progress_fingerprint_degrades_gracefully() { + reset_fakes + local d out; d=$(new_case progress-degraded) + make_repo_on_branch "$d/wt" fm/prog-d + make_fakebin "$d" >/dev/null + fm_write_meta "$d/state/prog-d.meta" "window=fm:fm-prog-d" "worktree=$d/wt" "kind=ship" + # A run with no active_steps[] table at all: the run-derived terms are empty + # and the fingerprint still compares equal to itself, so the caller's + # escalation behaves exactly as it did before this existed. + FM_FAKE_AXI_STATUS="$(run_running fm/prog-d)" + out=$(run_progress "$d" prog-d) + [ "$out" = "$(run_progress "$d" prog-d)" ] || fail "a run without active_steps[] produced an unstable fingerprint" + + # Torn-down worktree and missing metadata report no evidence rather than a + # state line, and exit 0 so a caller can compare the result unconditionally. + # No evidence is the EMPTY string: a punctuation skeleton with empty fields is + # a distinct non-empty token, so it would compare UNEQUAL to a healthy + # fingerprint and the caller would read the failed read as forward progress. + fm_write_meta "$d/state/gone-d.meta" "window=fm:fm-gone-d" "worktree=$d/no-such-worktree" "kind=ship" + out=$(run_progress "$d" gone-d) || fail "--progress on a torn-down worktree did not exit 0" + [ -z "$out" ] || fail "--progress on a torn-down worktree did not report empty evidence: $out" + out=$(run_progress "$d" never-existed) || fail "--progress on missing metadata did not exit 0" + [ -z "$out" ] || fail "--progress on missing metadata did not report empty evidence: $out" + pass "--progress degrades to empty evidence rather than to a false reset" +} + +# A FAILED run read and a genuine NO RUN are different answers, and printing the +# same token for both is what turns "could not tell" into "the run advanced": the +# caller resets its wedge timer on any difference, so a fingerprint that flips +# between the full form and a sha-only form as the CLI comes and goes absorbs the +# escalation twice - once on the way down and once on the way back - on a worker +# that may be genuinely frozen. A run read that was owed and did not answer must +# therefore be EMPTY, which compares equal and escalates. The consumer half of +# that contract - an empty fingerprint mid-chain escalates instead of absorbing, +# and does not overwrite the stored baseline - is owned by +# test_wedge_escalation_unreadable_progress_still_escalates in +# tests/fm-watch-triage.test.sh. +test_progress_fingerprint_is_empty_when_the_run_read_fails() { + reset_fakes + local d short healthy timedout coarse + d=$(new_case progress-degraded-read) + make_repo_on_branch "$d/wt" fm/prog-e + short=$(git -C "$d/wt" rev-parse --short=7 HEAD) + make_fakebin "$d" >/dev/null + fm_write_meta "$d/state/prog-e.meta" "window=fm:fm-prog-e" "worktree=$d/wt" "kind=ship" + + FM_FAKE_AXI_STATUS="$(run_ci_with_active_steps fm/prog-e 10m 1m)" + healthy=$(run_progress "$d" prog-e) + [ -n "$healthy" ] || fail "a healthy ship read produced no fingerprint at all" + + # The CLI answered with nothing: timed out, or died. The head sha is still + # readable, but reporting it alone would differ from the healthy form above. + FM_FAKE_AXI_STATUS="" + timedout=$(run_progress "$d" prog-e) + [ -z "$timedout" ] \ + || fail "a ship task whose run read returned nothing reported '$timedout' instead of no evidence - the wedge timer would reset on the difference from '$healthy'" + + # The coarse runs-list fallback answered with a bare status word and no step + # detail. Enough for the state machine, not enough to compare progress with. + FM_FAKE_AXI_STATUS="$(run_running fm/other-crew)" + FM_FAKE_RUNS_LIST=" running fm/prog-e ${short} 2026-07-02 22:05" + coarse=$(run_progress "$d" prog-e) + [ -z "$coarse" ] \ + || fail "a coarse-fallback run read reported '$coarse' instead of no evidence" + pass "--progress reports no evidence when a run read was owed and did not answer" +} + test_scout_skips_run_lookup() { reset_fakes local d; d=$(new_case scout) @@ -1269,6 +1435,11 @@ test_dead_window_ignores_stale_status_log test_dead_window_still_reports_terminal_run_step test_dead_window_still_reports_active_run_step test_no_timeout_uses_perl_bound +test_progress_fingerprint_is_stable_under_no_change +test_progress_fingerprint_moves_on_real_progress +test_progress_fingerprint_without_a_run_tracks_commits +test_progress_fingerprint_degrades_gracefully +test_progress_fingerprint_is_empty_when_the_run_read_fails test_scout_skips_run_lookup test_torn_down_worktree test_missing_meta diff --git a/tests/fm-gate-refuse.test.sh b/tests/fm-gate-refuse.test.sh index e788eb1f21..05cd73dd88 100755 --- a/tests/fm-gate-refuse.test.sh +++ b/tests/fm-gate-refuse.test.sh @@ -272,7 +272,11 @@ test_send_refuses_and_admits() { expect_code 0 "$rc" "send: a normal session must still send" assert_not_contains "$out" "$ENV_MSG" "send: normal send must not print the gate refusal" assert_not_contains "$out" "$PATH_MSG" "send: normal send must not print the backstop refusal" - assert_contains "$(cat "$log")" "target=sess:fm-lane-ok literal=1 arg=hello captain" "send: normal send should type the text" + # Body match, not whole-argument match: a metadata-routed crewmate steer also + # carries the firstmate-steer mark (bin/fm-send.sh). This case is about the gate + # refusal, not the marker, which is pinned in tests/fm-send-secondmate-marker.test.sh. + assert_contains "$(cat "$log")" "target=sess:fm-lane-ok literal=1 arg=" "send: normal send should type to the endpoint" + assert_contains "$(cat "$log")" "hello captain" "send: normal send should type the text" pass "fm-send: refuses on marker and gate-worktree backstop; a normal steer is unaffected" } diff --git a/tests/fm-pending-reply.test.sh b/tests/fm-pending-reply.test.sh index 325125eeeb..642dfd36fe 100755 --- a/tests/fm-pending-reply.test.sh +++ b/tests/fm-pending-reply.test.sh @@ -580,9 +580,13 @@ test_unmarked_captain_input_creates_no_expectation() { "window=sess:fm-build" "worktree=$home/wt" "project=$home/p" \ "harness=echo" "kind=ship" "mode=no-mistakes" "yolo=off" run_send "$fb" "$home" "$log" "build" "captain says hello"; rc=$? - expect_code 0 "$rc" "unmarked crewmate send should succeed" - [ "$(cat "$log")" = "captain says hello" ] \ - || fail "crewmate send should stay unmarked"$'\n'"$(cat "$log" | od -An -c)" + expect_code 0 "$rc" "crewmate send should succeed" + # A crewmate steer is marked so the worker knows who is speaking, but it uses + # the generic firstmate-steer kind, NOT the secondmate reply-routing carrier - + # only the latter opens a durable expectation, which is what this pins. + case "$(cat "$log")" in + *"$FM_FROMFIRST_LABEL"*) fail "a crewmate steer used the secondmate reply-routing carrier"$'\n'"$(cat "$log" | od -An -c)" ;; + esac pending_count=$(find "$home/state/pending-replies" -type f 2>/dev/null | wc -l | tr -d ' ') [ "$pending_count" = 0 ] || fail "unmarked input must create no pending-reply records (got $pending_count)" pass "direct unmarked captain input creates no expectation" diff --git a/tests/fm-send-secondmate-marker.test.sh b/tests/fm-send-secondmate-marker.test.sh index d50c580205..8e24c8ec23 100755 --- a/tests/fm-send-secondmate-marker.test.sh +++ b/tests/fm-send-secondmate-marker.test.sh @@ -143,25 +143,85 @@ test_exact_secondmate_task_id_is_marked() { pass "fm-send: an exact kind=secondmate task id is marked with corr exactly once" } -test_crewmate_target_is_not_marked() { - local dir fb log home rc got +# A crewmate or scout steer carries the generic firstmate-steer kind, NOT the +# secondmate from-firstmate carrier: the two marks mean different things, and only +# the secondmate one opens a reply expectation. A worker that cannot tell a +# firstmate steer from a human at the keyboard has composed a message addressed +# to the captain into its own pane and blocked on it. +test_crewmate_target_is_marked_as_a_steer() { + local dir fb log home rc got expected dir="$TMP_ROOT/crew"; mkdir -p "$dir" fb=$(make_stubs "$dir"); log="$dir/send.log" home=$(setup_home crew) fm_write_meta "$home/state/build.meta" \ "window=sess:fm-build" "worktree=$home/wt" "project=$home/p" \ "harness=echo" "kind=ship" "mode=no-mistakes" "yolo=off" + fm_operational_input_construct firstmate-steer "fix the test" expected \ + || fail "could not construct a firstmate-steer message" run_send "$fb" "$home" "$log" "fm-build" "fix the test"; rc=$? expect_code 0 "$rc" "send to a stable-label crewmate target should succeed" got=$(cat "$log") - [ "$got" = "fix the test" ] \ - || fail "stable-label crewmate send: expected bare text, got marker or other"$'\n'"--- bytes ---"$'\n'"$(printf '%s' "$got" | od -An -c)" + [ "$got" = "$expected" ] \ + || fail "stable-label crewmate send: expected a firstmate-steer mark"$'\n'"--- bytes ---"$'\n'"$(printf '%s' "$got" | od -An -c)" + case "$got" in + *"$FM_FROMFIRST_LABEL"*) fail "a crewmate steer used the secondmate reply-routing carrier" ;; + esac + [ -z "$(ls -A "$home/state/pending-replies" 2>/dev/null || true)" ] \ + || fail "a crewmate steer created a pending-reply expectation" + + fm_operational_input_construct firstmate-steer "fix the exact test" expected run_send "$fb" "$home" "$log" "build" "fix the exact test"; rc=$? expect_code 0 "$rc" "send to an exact-id crewmate target should succeed" got=$(cat "$log") - [ "$got" = "fix the exact test" ] \ - || fail "exact-id crewmate send: expected bare text, got marker or other"$'\n'"--- bytes ---"$'\n'"$(printf '%s' "$got" | od -An -c)" - pass "fm-send: exact-id and stable-label kind=ship selectors are sent unmarked" + [ "$got" = "$expected" ] \ + || fail "exact-id crewmate send: expected a firstmate-steer mark"$'\n'"--- bytes ---"$'\n'"$(printf '%s' "$got" | od -An -c)" + + # A scout is an ordinary crewmate for this purpose. + fm_write_meta "$home/state/probe.meta" \ + "window=sess:fm-probe" "worktree=$home/wt" "project=$home/p" \ + "harness=echo" "kind=scout" + fm_operational_input_construct firstmate-steer "check the logs" expected + run_send "$fb" "$home" "$log" "probe" "check the logs"; rc=$? + expect_code 0 "$rc" "send to a scout target should succeed" + [ "$(cat "$log")" = "$expected" ] || fail "a scout steer was not marked" + pass "fm-send: kind=ship and kind=scout selectors carry the firstmate-steer mark and no reply expectation" +} + +# A message the harness itself dispatches must stay bare: any prefix in front of +# a slash command turns it into plain text and the steer silently does not run. +# This is the carve-out that keeps "/no-mistakes" working. +test_harness_dispatched_commands_stay_bare() { + local dir fb log home rc + dir="$TMP_ROOT/crew-cmd"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); log="$dir/send.log" + home=$(setup_home crew-cmd) + fm_write_meta "$home/state/build.meta" \ + "window=sess:fm-build" "worktree=$home/wt" "project=$home/p" \ + "harness=claude" "kind=ship" "mode=no-mistakes" "yolo=off" + run_send "$fb" "$home" "$log" "build" "/no-mistakes"; rc=$? + expect_code 0 "$rc" "slash-command steer should succeed" + [ "$(cat "$log")" = "/no-mistakes" ] \ + || fail "a slash command was prefixed and would no longer dispatch: $(cat "$log")" + + fm_write_meta "$home/state/cdx.meta" \ + "window=sess:fm-cdx" "worktree=$home/wt" "project=$home/p" \ + "harness=codex" "kind=ship" "mode=no-mistakes" "yolo=off" + # shellcheck disable=SC2016 # A literal leading '$' is the codex skill form under test. + run_send "$fb" "$home" "$log" "cdx" '$review'; rc=$? + expect_code 0 "$rc" "codex skill-invocation steer should succeed" + # shellcheck disable=SC2016 # Same literal '$' as above. + [ "$(cat "$log")" = '$review' ] \ + || fail "a codex skill invocation was prefixed: $(cat "$log")" + + # The same leading "$" on a non-codex harness is ordinary prose and IS marked. + # shellcheck disable=SC2016 # A literal '$5' is the prose case under test. + run_send "$fb" "$home" "$log" "build" '$5 a month is the budget'; rc=$? + expect_code 0 "$rc" "dollar-prefixed prose steer should succeed" + case "$(cat "$log")" in + *"FIRSTMATE_OP:"*) : ;; + *) fail "dollar-prefixed prose to a non-codex target was left unmarked" ;; + esac + pass "fm-send: slash commands and codex skill invocations stay bare so the harness still dispatches them" } test_explicit_window_is_not_marked() { @@ -255,7 +315,8 @@ test_marked_send_preserves_trailing_newlines() { test_secondmate_target_is_marked test_exact_secondmate_task_id_is_marked -test_crewmate_target_is_not_marked +test_crewmate_target_is_marked_as_a_steer +test_harness_dispatched_commands_stay_bare test_explicit_window_is_not_marked test_key_path_is_not_marked test_marker_is_label_plus_invisible_separator diff --git a/tests/fm-send-strict.test.sh b/tests/fm-send-strict.test.sh index 1faf98a0ce..9c303b8e98 100755 --- a/tests/fm-send-strict.test.sh +++ b/tests/fm-send-strict.test.sh @@ -83,7 +83,12 @@ test_exact_lane_id_send_still_works() { "$SEND" mpf-lane-m8 "lost dispatch" >/dev/null 2>"$err"; rc=$? expect_code 0 "$rc" "exact task id send should succeed when metadata exists" got=$(cat "$log") - assert_contains "$got" "target=sess:fm-mpf-lane-m8 literal=1 arg=lost dispatch" "exact id should type literal text to the meta target" + # The body reaches the resolved target. A metadata-routed crewmate steer also + # carries the firstmate-steer mark (bin/fm-send.sh), so match the body rather + # than the whole literal argument; the marker itself is pinned in + # tests/fm-send-secondmate-marker.test.sh. + assert_contains "$got" "target=sess:fm-mpf-lane-m8 literal=1 arg=" "exact id should type literal text to the meta target" + assert_contains "$got" "lost dispatch" "exact id should type the steer body" assert_contains "$got" "target=sess:fm-mpf-lane-m8 literal=0 arg=Enter" "exact id should submit with Enter" pass "fm-send strict: exact task/lane ids resolve through home metadata" } @@ -157,7 +162,10 @@ test_healthy_fm_id_send_still_works() { "$SEND" fm-lane-ok "hello captain" >/dev/null 2>"$err"; rc=$? expect_code 0 "$rc" "healthy fm-id send should succeed" got=$(cat "$log") - assert_contains "$got" "target=sess:fm-lane-ok literal=1 arg=hello captain" "healthy send should type literal text to the meta target" + # Body match, not whole-argument match: a metadata-routed crewmate steer also + # carries the firstmate-steer mark (see tests/fm-send-secondmate-marker.test.sh). + assert_contains "$got" "target=sess:fm-lane-ok literal=1 arg=" "healthy send should type literal text to the meta target" + assert_contains "$got" "hello captain" "healthy send should type the steer body" assert_contains "$got" "target=sess:fm-lane-ok literal=0 arg=Enter" "healthy send should submit with Enter" assert_contains "$(cat "$err")" "requested message WILL still be sent" "fm-send guard banner should keep send-specific continuation wording" pass "fm-send strict: healthy fm- sends still type once and submit" diff --git a/tests/fm-wake-queue.test.sh b/tests/fm-wake-queue.test.sh index 569f18b42f..58e00f2d42 100755 --- a/tests/fm-wake-queue.test.sh +++ b/tests/fm-wake-queue.test.sh @@ -98,7 +98,7 @@ test_stale_enqueue_before_suppressor() { printf '1\n' > "$state/.count-$key" PATH="$fakebin:$PATH" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$capture_file" FM_STATE_OVERRIDE="$state" FM_POLL=1 FM_SIGNAL_GRACE=1 FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & wait_for_exit "$!" 40 || fail "watcher did not exit for stale pane" - grep -Fx "stale: $window" "$out" >/dev/null || fail "watcher did not print stale wake" + grep -Fx "stale: $window [branch=terminal]" "$out" >/dev/null || fail "watcher did not print stale wake" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" || fail "drain after stale wake failed" grep "$(printf '\tstale\t')" "$drain_out" | grep -F "$window" >/dev/null || fail "stale wake was not queued" [ "$(cat "$state/.stale-$key" 2>/dev/null || true)" = "$pane_hash" ] || fail "stale suppressor was not written" @@ -136,7 +136,7 @@ test_not_working_stale_enqueue_before_suppressor() { FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" \ FM_STALE_ESCALATE_SECS=999 FM_POLL=1 FM_SIGNAL_GRACE=1 FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & wait_for_exit "$!" 40 || fail "watcher did not surface a not-provably-working stale" - grep -Fx "stale: $window" "$out" >/dev/null || fail "watcher did not print the immediate stale wake" + grep -Fx "stale: $window [branch=nonterminal]" "$out" >/dev/null || fail "watcher did not print the immediate stale wake" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" || fail "drain after the immediate stale wake failed" grep "$(printf '\tstale\t')" "$drain_out" | grep -F "$window" >/dev/null || fail "immediate stale wake was not queued" [ "$(cat "$state/.stale-$key" 2>/dev/null || true)" = "$pane_hash" ] || fail "stale suppressor was not advanced after the enqueue" diff --git a/tests/fm-watch-triage.test.sh b/tests/fm-watch-triage.test.sh index 19dae9bba3..7c7a61f6ca 100755 --- a/tests/fm-watch-triage.test.sh +++ b/tests/fm-watch-triage.test.sh @@ -417,7 +417,7 @@ test_terminal_stale_surfaced() { FM_STATE_OVERRIDE="$state" FM_POLL=1 FM_SIGNAL_GRACE=1 FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! wait_for_exit "$pid" 40 || fail "watcher did not exit for a stale pane on a terminal status" - grep -Fx "stale: $window" "$out" >/dev/null || fail "watcher did not print the terminal stale wake" + grep -Fx "stale: $window [branch=terminal]" "$out" >/dev/null || fail "watcher did not print the terminal stale wake" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null || fail "drain after the terminal stale failed" grep "$(printf '\tstale\t')" "$drain_out" | grep -F "$window" >/dev/null || fail "terminal stale was not queued" pass "a stale pane sitting on a terminal status is surfaced (queue + exit)" @@ -478,6 +478,7 @@ test_stale_terminal_status_overridden_by_active_run() { wait_for_exit "$pid" 40 || fail "watcher did not escalate an overridden stale terminal status past the threshold" grep -F "stale: $window" "$out" >/dev/null || fail "escalation did not print a stale wake" grep -F "possible wedge" "$out" >/dev/null || fail "escalation did not flag a possible wedge" + grep -F "[branch=wedge]" "$out" >/dev/null || fail "wedge escalation did not tag its classification branch" unset FM_FAKE_CREW_STATE pass "a stale terminal-looking status is overridden and absorbed while a run is actively working, then wedge-escalated" } @@ -530,6 +531,7 @@ test_nonterminal_stale_provably_working_absorbed_then_escalated() { wait_for_exit "$pid" 40 || fail "watcher did not escalate a provably-working non-terminal stale past the threshold" grep -F "stale: $window" "$out" >/dev/null || fail "escalation did not print a stale wake" grep -F "possible wedge" "$out" >/dev/null || fail "escalation did not flag a possible wedge" + grep -F "[branch=wedge]" "$out" >/dev/null || fail "wedge escalation did not tag its classification branch" [ ! -e "$state/.stale-since-$key" ] || fail "stale-since timer was not cleared after escalation" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null || fail "drain after the wedge escalation failed" grep "$(printf '\tstale\t')" "$drain_out" | grep -F "$window" >/dev/null || fail "wedge escalation was not queued" @@ -566,7 +568,7 @@ test_nonterminal_stale_not_working_surfaced() { FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! wait_for_exit "$pid" 40 || fail "watcher did not surface a not-provably-working non-terminal stale at once" - grep -Fx "stale: $window" "$out" >/dev/null || fail "watcher did not print the immediate stale wake" + grep -Fx "stale: $window [branch=nonterminal]" "$out" >/dev/null || fail "watcher did not print the immediate stale wake" grep -F "possible wedge" "$out" >/dev/null && fail "an immediate stopped-crew stale was mislabeled a wedge" [ "$(cat "$state/.stale-$key" 2>/dev/null || true)" = "$pane_hash" ] || fail "stale suppressor was not advanced on surface" [ ! -e "$state/.stale-since-$key" ] || fail "stale-since timer should not be set when surfacing immediately" @@ -636,6 +638,7 @@ test_nonterminal_stale_paused_absorbed_then_resurfaced() { wait_for_exit "$pid" 40 || fail "watcher did not re-surface a declared pause past the threshold" grep -F "stale: $window" "$out" >/dev/null || fail "re-surface did not print a stale wake" grep -F "awaiting external" "$out" >/dev/null || fail "re-surface was not labeled a paused/awaiting-external recheck" + grep -F "[branch=pause-resurface]" "$out" >/dev/null || fail "paused re-surface did not tag its classification branch" grep -F "possible wedge" "$out" >/dev/null && fail "a declared pause was mislabeled a possible wedge" [ -e "$state/.paused-resurfaced-$key" ] || fail "the paused re-surface throttle marker was not recorded" [ ! -e "$state/.stale-since-$key" ] || fail "a paused re-surface must not use the wedge timer" @@ -679,7 +682,7 @@ test_exited_declared_pause_is_bounded_but_live_gate_surfaces() { round=$((round + 1)) done wakes=$(awk -F '\t' -v w="$window" '$3 == "stale" && $4 == w { n++ } END { print n + 0 }' "$state/.wake-queue") - bare=$(awk -F '\t' -v w="$window" '$3 == "stale" && $4 == w && $5 == "stale: " w { n++ } END { print n + 0 }' "$state/.wake-queue") + bare=$(awk -F '\t' -v w="$window" '$3 == "stale" && $4 == w && $5 == "stale: " w " [branch=nonterminal]" { n++ } END { print n + 0 }' "$state/.wake-queue") [ "$wakes" -le 1 ] || fail "dead-agent declared pause flooded $wakes stale wakes across six unchanged polls" [ "$bare" -eq 0 ] || fail "dead-agent declared pause surfaced as $bare bare stopped-crew wakes" grep -F "awaiting external" "$state/.wake-queue" >/dev/null \ @@ -747,12 +750,77 @@ test_exited_declared_pause_is_bounded_but_live_gate_surfaces() { [ ! -e "$state/.stale-since-$key" ] || { reap "$pid"; fail "live external-decision gate retained the wedge timer"; } reap "$pid" wakes=$(awk -F '\t' -v w="$window" '$3 == "stale" && $4 == w { n++ } END { print n + 0 }' "$state/.wake-queue") - bare=$(awk -F '\t' -v w="$window" '$3 == "stale" && $4 == w && $5 == "stale: " w { n++ } END { print n + 0 }' "$state/.wake-queue") + bare=$(awk -F '\t' -v w="$window" '$3 == "stale" && $4 == w && $5 == "stale: " w " [branch=nonterminal]" { n++ } END { print n + 0 }' "$state/.wake-queue") [ "$wakes" -eq 1 ] || fail "live external-decision gate should surface once, got $wakes wakes" [ "$bare" -eq 1 ] || fail "live external-decision gate lost its immediate bare stale surface" pass "exited declared-pause and captain-held panes use bounded pause cadence while a live decision gate still surfaces once" } +# --- a live-agent declared pause surfaces once per pause WINDOW --------------- +# +# A declared pause on a crew whose agent is not confidently dead fails open and +# surfaces, deliberately: it might be sitting on a decision gate its own status +# line silenced. The defect was that the classification re-runs on every distinct +# pane hash, so "looked at once" meant "looked at once per pane redraw" - one +# wake per redraw, unthrottled, and unbounded in principle, because a pane +# rendering a ticking clock produces a new hash every poll forever. +# +# Each round below rewrites the pane, which is exactly the trigger. The first +# round must still surface - that is the documented safety behaviour and it is +# not what is being removed - and every later round must take the bounded +# cadence instead. +test_live_declared_pause_surfaces_once_per_pause_window() { + local dir state fakebin out capture_file statusf window key sig pid round wakes + dir=$(make_case live-pause-throttle); state="$dir/state"; fakebin="$dir/fakebin" + out="$dir/watch.out"; capture_file="$dir/pane.txt"; statusf="$state/livepause.status" + window="test:fm-livepause" + printf 'round 0 output\n' > "$capture_file" + printf 'window=%s\nkind=ship\nharness=claude\nbackend=tmux\n' "$window" > "$state/livepause.meta" + printf 'paused: waiting on the upstream release\n' > "$statusf" + sig=$(seen_sig "$statusf"); printf '%s' "$sig" > "$state/.seen-livepause_status" + key=$(printf '%s' "$window" | tr ':/.' '___') + # No FM_FAKE_TMUX_CURRENT_COMMAND: the liveness probe reads inconclusive, which + # is the fail-open population this throttle governs. A long resurface window + # keeps the bounded hourly recheck out of the count. + export FM_FAKE_CREW_STATE='state: paused · source: status-log · waiting on the upstream release' + + round=1 + while [ "$round" -le 4 ]; do + printf 'round %s output, the pane redrew\n' "$round" > "$capture_file" + PATH="$fakebin:$PATH" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$capture_file" \ + FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" \ + FM_PAUSE_RESURFACE_SECS=999999 FM_STALE_ESCALATE_SECS=999999 FM_POLL=1 FM_SIGNAL_GRACE=1 \ + FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" >> "$out" & + pid=$! + if wait_live "$pid" 60; then reap "$pid"; else wait "$pid" || fail "live-pause round $round failed"; fi + if [ "$round" -eq 1 ]; then + wakes=$(awk -F '\t' -v w="$window" '$3 == "stale" && $4 == w { n++ } END { print n + 0 }' "$state/.wake-queue") + [ "$wakes" -eq 1 ] || fail "a live-agent declared pause lost its one documented surface, got $wakes" + [ -e "$state/.paused-liveprobe-$key" ] || fail "the surface did not record that this pause window had its look" + fi + round=$((round + 1)) + done + wakes=$(awk -F '\t' -v w="$window" '$3 == "stale" && $4 == w { n++ } END { print n + 0 }' "$state/.wake-queue") + [ "$wakes" -eq 1 ] || fail "a live-agent declared pause surfaced $wakes times across four pane redraws" + grep -F "absorbed stale (paused, awaiting external" "$state/.watch-triage.log" >/dev/null \ + || fail "later redraws of the same pause window did not take the bounded cadence" + + # The budget belongs to the pause window, not to the task: when the crew stops + # declaring a pause, the next pause gets its own look. + printf 'working: resumed\n' > "$statusf" + sig=$(seen_sig "$statusf"); printf '%s' "$sig" > "$state/.seen-livepause_status" + printf 'resumed output\n' > "$capture_file" + PATH="$fakebin:$PATH" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$capture_file" \ + FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" \ + FM_PAUSE_RESURFACE_SECS=999999 FM_STALE_ESCALATE_SECS=999999 FM_POLL=1 FM_SIGNAL_GRACE=1 \ + FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" >> "$out" & + pid=$! + if wait_live "$pid" 40; then reap "$pid"; else wait "$pid" || true; fi + [ ! -e "$state/.paused-liveprobe-$key" ] || fail "leaving a declared pause did not release its live-agent look" + unset FM_FAKE_CREW_STATE + pass "a live-agent declared pause surfaces once per pause window, not once per pane redraw" +} + test_secondmate_paused_resurfaces_in_normal_mode() { local dir state fakebin out capture_file statusf window key pane_hash sig pid back dir=$(make_case secondmate-paused-resurface); state="$dir/state"; fakebin="$dir/fakebin" @@ -1055,6 +1123,309 @@ test_wedge_escalation_resets_when_pane_becomes_active() { pass "a pane becoming active again resets the consecutive wedge-escalation counter" } +# --- the wedge escalation resets when the PIPELINE advances ------------------- +# +# The escalation's only reset conditions were a pane-hash change and a busy +# signature, and a healthy worker driving a no-mistakes run produces neither: the +# pipeline owns the branch and renders nothing to the worker's pane. So a healthy +# validating worker escalated on the same unchanged hash every threshold, forever +# - 28 of 61 stale wakes across one measured 22.5-hour window. +# +# The pair below pins both directions, because getting only the first is exactly +# how this fix turns into a worse defect than the one it replaces: +# forward - a moved fingerprint absorbs the escalation and restarts the timer +# frozen - an unchanged fingerprint escalates on the ordinary schedule +# The frozen direction is also covered by every pre-existing wedge test in this +# file, all of which run against a fixed fake fingerprint. +test_wedge_escalation_resets_when_the_pipeline_advances() { + local dir state fakebin out capture_file window key pane_hash sig pid + dir=$(make_case wedge-progress-reset); state="$dir/state"; fakebin="$dir/fakebin" + out="$dir/watch.out"; capture_file="$dir/pane.txt" + window="test:fm-validating" + printf 'idle, pipeline owns the branch' > "$capture_file" + printf 'window=%s\nkind=ship\n' "$window" > "$state/validating.meta" + printf 'working: handed to validation\n' > "$state/validating.status" + sig=$(seen_sig "$state/validating.status"); printf '%s' "$sig" > "$state/.seen-validating_status" + key=$(printf '%s' "$window" | tr ':/.' '___') + pane_hash=$(hash_text "idle, pipeline owns the branch") + printf '%s' "$pane_hash" > "$state/.hash-$key" + printf '1\n' > "$state/.count-$key" + printf '%s' "$pane_hash" > "$state/.stale-$key" + export FM_FAKE_CREW_STATE='state: working · source: run-step · ci running' + export FM_FAKE_CREW_PROGRESS + + # Round 1: no stored baseline. With nothing to compare against there is no + # evidence of progress, so this escalates exactly as it always did - absence of + # evidence must never be read as progress, or a frozen worker goes silent. + FM_FAKE_CREW_PROGRESS='3/ci/running/starting/aaaaaaa' + echo $(( $(date +%s) - 500 )) > "$state/.stale-since-$key" + PATH="$fakebin:$PATH" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$capture_file" \ + FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_STALE_ESCALATE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ + FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & + pid=$! + wait_for_exit "$pid" 40 || fail "the first wedge round did not escalate without a progress baseline" + grep -F "[branch=wedge]" "$out" >/dev/null || fail "the first wedge round did not escalate" + [ "$(cat "$state/.progress-$key" 2>/dev/null || true)" = '3/ci/running/starting/aaaaaaa' ] \ + || fail "the first escalation did not record a progress baseline for the next round" + [ "$(cat "$state/.wedge-escalations-$key" 2>/dev/null || true)" = 1 ] || fail "escalation count did not advance" + + # Round 2: the pane is still byte-identical and the status log is unchanged, + # but the pipeline completed a step. That is positive evidence the worker is + # healthy, so the escalation is absorbed, the timer restarts, and the + # consecutive-escalation count clears. + : > "$out"; : > "$state/.wake-queue" + FM_FAKE_CREW_PROGRESS='4/ci/running/starting/aaaaaaa' + echo $(( $(date +%s) - 500 )) > "$state/.stale-since-$key" + PATH="$fakebin:$PATH" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$capture_file" \ + FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_STALE_ESCALATE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ + FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & + pid=$! + if ! wait_live "$pid" 30; then + reap "$pid"; fail "an advancing pipeline still wedge-escalated: $(cat "$out")" + fi + [ ! -s "$out" ] || fail "an advancing pipeline printed a wake reason: $(cat "$out")" + [ ! -s "$state/.wake-queue" ] || fail "an advancing pipeline enqueued a wake" + [ "$(cat "$state/.progress-$key" 2>/dev/null || true)" = '4/ci/running/starting/aaaaaaa' ] \ + || fail "the progress baseline was not advanced on reset" + [ ! -e "$state/.wedge-escalations-$key" ] || fail "forward progress did not clear the consecutive-escalation count" + [ -s "$state/.stale-since-$key" ] || fail "forward progress did not restart the wedge timer" + reap "$pid" + + # Round 3: the pipeline stops moving. The same unchanged fingerprint is now + # evidence, not absence of it, so the escalation fires again on the ordinary + # schedule. This is the assertion that keeps the fix from becoming a permanent + # blind spot. + : > "$out"; : > "$state/.wake-queue" + echo $(( $(date +%s) - 500 )) > "$state/.stale-since-$key" + PATH="$fakebin:$PATH" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$capture_file" \ + FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_STALE_ESCALATE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ + FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & + pid=$! + wait_for_exit "$pid" 40 || fail "a frozen pipeline stopped escalating after a progress reset" + grep -F "possible wedge" "$out" >/dev/null || fail "a frozen pipeline did not re-escalate: $(cat "$out")" + unset FM_FAKE_CREW_PROGRESS FM_FAKE_CREW_STATE + pass "the wedge escalation resets on pipeline progress and still fires on a frozen pipeline" +} + +# An unreadable progress fingerprint must escalate, not absorb. The reset is only +# ever taken on POSITIVE evidence that the run moved; "could not tell" has to +# behave like the code did before the fingerprint existed, because the opposite +# choice silences the escalation for every worker whose state cannot be read. +test_wedge_escalation_unreadable_progress_still_escalates() { + local dir state fakebin out capture_file window key pane_hash sig pid + dir=$(make_case wedge-progress-unreadable); state="$dir/state"; fakebin="$dir/fakebin" + out="$dir/watch.out"; capture_file="$dir/pane.txt" + window="test:fm-unreadable" + printf 'idle building output' > "$capture_file" + printf 'window=%s\nkind=ship\n' "$window" > "$state/unreadable.meta" + printf 'working: still compiling\n' > "$state/unreadable.status" + sig=$(seen_sig "$state/unreadable.status"); printf '%s' "$sig" > "$state/.seen-unreadable_status" + key=$(printf '%s' "$window" | tr ':/.' '___') + pane_hash=$(hash_text "idle building output") + printf '%s' "$pane_hash" > "$state/.hash-$key" + printf '1\n' > "$state/.count-$key" + printf '%s' "$pane_hash" > "$state/.stale-$key" + # A stored baseline exists, and the reader now answers with nothing at all. + printf '3/ci/running/starting/aaaaaaa' > "$state/.progress-$key" + echo $(( $(date +%s) - 500 )) > "$state/.stale-since-$key" + export FM_FAKE_CREW_STATE='state: working · source: run-step · ci running' + export FM_FAKE_CREW_PROGRESS='' + PATH="$fakebin:$PATH" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$capture_file" \ + FM_STATE_OVERRIDE="$state" FM_CREW_STATE_BIN="$fakebin/fm-crew-state.sh" FM_STALE_ESCALATE_SECS=240 FM_POLL=1 FM_SIGNAL_GRACE=1 \ + FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & + pid=$! + wait_for_exit "$pid" 40 || fail "an unreadable progress fingerprint suppressed the wedge escalation" + grep -F "possible wedge" "$out" >/dev/null || fail "an unreadable fingerprint did not escalate: $(cat "$out")" + [ "$(cat "$state/.progress-$key" 2>/dev/null || true)" = '3/ci/running/starting/aaaaaaa' ] \ + || fail "an unreadable fingerprint overwrote the stored baseline with nothing" + unset FM_FAKE_CREW_PROGRESS FM_FAKE_CREW_STATE + pass "an unreadable progress fingerprint escalates and preserves the stored baseline" +} + +# --- a run parked at a gate with no response wakes on a bounded sweep --------- +# +# A validation run that reaches a decision gate emits no wake of any kind. The +# gate state is computed correctly, but nothing polls for the transition, and a +# parked worker's pane may never go stale - so a worker that does not answer its +# gate is silent until something unrelated happens to look at it. The observed +# instance was ten minutes of silence, caught only because firstmate inspected +# the pane during an unrelated wake. This is also the only wake class that +# surfaces regardless of pane state, and the only increment that ADDS wakes, so +# what it must NOT do is pinned as carefully as what it must. +# +# Every case below runs exactly one sweep: with no .last-park-scan on disk the +# age reads as effectively infinite, so a very long interval still lets the first +# sweep run and then blocks every later one in the same process. That makes each +# transition of the two-sweep state machine assertable on its own. +park_case() { # -> echoes dir + local dir state capture_file sig + dir=$(make_case "$1"); state="$dir/state"; capture_file="$dir/pane.txt" + # A busy pane: the sweep must not need a stale pane to notice a gate, and + # keeping this pane busy proves any wake came from the sweep and nothing else. + printf 'running the review step... esc to interrupt\n' > "$capture_file" + printf 'window=%s\nkind=ship\n' "$2" > "$state/$3.meta" + printf 'working: handed to validation\n' > "$state/$3.status" + sig=$(seen_sig "$state/$3.status"); printf '%s' "$sig" > "$state/.seen-${3}_status" + printf '%s\n' "$dir" +} + +# One sweep, then stop. Returns 0 if the watcher surfaced a wake, 1 if it kept +# absorbing (the caller asserts which one it wanted). PARK_MAX in the caller's +# environment overrides the sweep cap. +park_sweep_once() { # + local dir=$1 window=$2 out=$3 pid rc + rm -f "$dir/state/.last-park-scan" + : > "$out" + PATH="$dir/fakebin:$PATH" FM_FAKE_TMUX_WINDOW="$window" FM_FAKE_TMUX_CAPTURE="$dir/pane.txt" \ + FM_STATE_OVERRIDE="$dir/state" FM_CREW_STATE_BIN="$dir/fakebin/fm-crew-state.sh" \ + FM_PARK_SCAN_SECS=999999 FM_PARK_SCAN_MAX="${PARK_MAX:-3}" FM_POLL=1 FM_SIGNAL_GRACE=1 \ + FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" >> "$out" & + pid=$! + if wait_live "$pid" 40; then reap "$pid"; rc=1; else wait "$pid" 2>/dev/null; rc=0; fi + return "$rc" +} + +test_park_scan_surfaces_an_unanswered_gate() { + local dir state out window key gate + window="test:fm-parked"; gate='parked at review: 2 finding(s)' + dir=$(park_case park-scan "$window" parked); state="$dir/state"; out="$dir/watch.out" + key=$(printf '%s' "$window" | tr ':/.' '___') + export FM_FAKE_CREW_STATE="state: parked · source: run-step · $gate" + + # First sighting stays silent: a run that reaches a gate and is answered + # promptly is normal, and one sweep cannot tell that from an unanswered one. + ! park_sweep_once "$dir" "$window" "$out" || fail "a first-sighting gate surfaced immediately: $(cat "$out")" + [ "$(cat "$state/.park-$key" 2>/dev/null || true)" = "$gate" ] \ + || fail "the first sweep did not record the observed gate" + [ ! -s "$out" ] || fail "the first sweep printed a wake reason: $(cat "$out")" + + # Second sweep, same gate: nobody answered it. + park_sweep_once "$dir" "$window" "$out" || fail "an unanswered gate did not surface on the second sweep" + grep -F "$gate" "$out" >/dev/null || fail "the park wake did not name the gate: $(cat "$out")" + grep -F "[branch=park]" "$out" >/dev/null || fail "the park wake did not tag its classification branch" + [ "$(cat "$state/.park-surfaced-$key" 2>/dev/null || true)" = "$gate" ] \ + || fail "the surfaced gate was not recorded" + + # Having told firstmate once, the same gate must not surface again. + : > "$state/.wake-queue" + ! park_sweep_once "$dir" "$window" "$out" || fail "an already-surfaced gate surfaced again: $(cat "$out")" + [ ! -s "$state/.wake-queue" ] || fail "an already-surfaced gate enqueued a second wake" + unset FM_FAKE_CREW_STATE + pass "a run parked at an unanswered gate surfaces once on the second bounded sweep" +} + +test_park_scan_stays_silent_when_the_run_moves() { + local dir state out window key + window="test:fm-moving" + dir=$(park_case park-moving "$window" moving); state="$dir/state"; out="$dir/watch.out" + key=$(printf '%s' "$window" | tr ':/.' '___') + + # A gate was seen last sweep, and the run has since moved to a different one. + # A moving run is not a park, so this stays silent even though a gate is + # present on both sweeps. + printf 'parked at review: 2 finding(s)' > "$state/.park-$key" + export FM_FAKE_CREW_STATE='state: parked · source: run-step · parked at fix_review: 1 finding(s)' + ! park_sweep_once "$dir" "$window" "$out" || fail "a run that moved between gates surfaced as parked: $(cat "$out")" + [ ! -s "$out" ] || fail "a changed gate printed a wake reason: $(cat "$out")" + [ "$(cat "$state/.park-$key" 2>/dev/null || true)" = 'parked at fix_review: 1 finding(s)' ] \ + || fail "the sweep did not advance to the newly observed gate" + + # The run left the gate entirely: the sweep forgets it, so a later park starts + # its own two-sweep count instead of surfacing on the first sighting. + printf 'parked at fix_review: 1 finding(s)' > "$state/.park-surfaced-$key" + FM_FAKE_CREW_STATE='state: working · source: run-step · validating (running)' + ! park_sweep_once "$dir" "$window" "$out" || fail "a working run surfaced from the park sweep: $(cat "$out")" + [ ! -e "$state/.park-$key" ] || fail "the sweep kept park state for a run that is no longer parked" + [ ! -e "$state/.park-surfaced-$key" ] || fail "the sweep kept surfaced state for a run that is no longer parked" + unset FM_FAKE_CREW_STATE + pass "the park sweep stays silent while the run keeps moving, and forgets a run that leaves its gate" +} + +test_park_scan_can_be_switched_off() { + local dir state out window key gate + window="test:fm-capped"; gate='parked at review: 2 finding(s)' + dir=$(park_case park-capped "$window" capped); state="$dir/state"; out="$dir/watch.out" + key=$(printf '%s' "$window" | tr ':/.' '___') + export FM_FAKE_CREW_STATE="state: parked · source: run-step · $gate" + # An already-seen gate that would surface on this sweep. This wake class is the + # only one that adds wakes, so it has to be switchable off without a code edit. + printf '%s' "$gate" > "$state/.park-$key" + PARK_MAX=0 park_sweep_once "$dir" "$window" "$out" \ + && fail "the park sweep ran with its cap at zero: $(cat "$out")" + [ ! -s "$out" ] || fail "a disabled park sweep still surfaced: $(cat "$out")" + [ ! -e "$state/.park-surfaced-$key" ] || fail "a disabled park sweep still advanced its state" + unset FM_FAKE_CREW_STATE + pass "the park sweep honours FM_PARK_SCAN_MAX and can be switched off entirely" +} + +# The cap alone re-read the same first FM_PARK_SCAN_MAX tasks on every sweep, so +# a fleet larger than the cap left every task past it never park-scanned - the +# silent-gate hole this sweep exists to close, permanently open for exactly the +# fleets big enough to lose a worker in. The persisted cursor rotates the sweep +# window deterministically, so both bounds hold at once: at most FM_PARK_SCAN_MAX +# reads per sweep, and full coverage within ceil(N/cap) sweeps. This drives five +# ship tasks against the default cap of three; it fails against a sweep that +# always restarts at the top of the glob. +test_park_scan_rotates_across_a_fleet_larger_than_the_cap() { + local dir state out i sig key gate cursor surfaced + gate='parked at review: 2 finding(s)' + dir=$(make_case park-rotation); state="$dir/state"; out="$dir/watch.out" + printf 'running the review step... esc to interrupt\n' > "$dir/pane.txt" + for i in 1 2 3 4 5; do + printf 'window=test:fm-p%s\nkind=ship\n' "$i" > "$state/p$i.meta" + printf 'working: handed to validation\n' > "$state/p$i.status" + sig=$(seen_sig "$state/p$i.status"); printf '%s' "$sig" > "$state/.seen-p${i}_status" + done + + # The cap still bounds one sweep. No task is parked, so nothing surfaces and + # the sweep runs to its own limit: the cursor must advance by exactly the cap, + # not by the fleet size. + export FM_FAKE_CREW_STATE='state: working · source: run-step · validating (running)' + ! park_sweep_once "$dir" "test:fm-p1" "$out" || fail "a fleet with no parked run surfaced: $(cat "$out")" + [ "$(cat "$state/.park-scan-cursor" 2>/dev/null || true)" = 3 ] \ + || fail "one sweep did not stop at the cap: cursor is '$(cat "$state/.park-scan-cursor" 2>/dev/null || true)', expected 3" + + # Every task is now parked at a gate already seen once, so whichever task a + # sweep reads first surfaces and ends that sweep. Five sweeps must therefore + # cover all five tasks in glob order, wrapping the cursor back to the start. + export FM_FAKE_CREW_STATE="state: parked · source: run-step · $gate" + printf '0' > "$state/.park-scan-cursor" + for i in 1 2 3 4 5; do + key=$(printf '%s' "test:fm-p$i" | tr ':/.' '___') + printf '%s' "$gate" > "$state/.park-$key" + done + for i in 1 2 3 4 5; do + : > "$out"; : > "$state/.wake-queue" + park_sweep_once "$dir" "test:fm-p1" "$out" \ + || fail "sweep $i did not surface any parked task: cursor '$(cat "$state/.park-scan-cursor" 2>/dev/null || true)'" + grep -F "test:fm-p$i" "$out" >/dev/null \ + || fail "sweep $i surfaced the wrong task - the sweep did not rotate: $(cat "$out")" + done + surfaced=0 + for i in 1 2 3 4 5; do + key=$(printf '%s' "test:fm-p$i" | tr ':/.' '___') + [ -e "$state/.park-surfaced-$key" ] && surfaced=$((surfaced + 1)) + done + [ "$surfaced" = 5 ] \ + || fail "only $surfaced of 5 ship tasks were ever park-scanned - tasks past the cap are starved" + cursor=$(cat "$state/.park-scan-cursor" 2>/dev/null || true) + [ "$cursor" = 0 ] || fail "the cursor did not wrap modulo the ship-window count: '$cursor'" + + # A corrupt or out-of-range cursor is only a hint: it must degrade to + # restarting coverage, never to skipping the sweep or indexing off the end. + printf 'not-a-number' > "$state/.park-scan-cursor" + : > "$out"; : > "$state/.wake-queue" + for i in 1 2 3 4 5; do + key=$(printf '%s' "test:fm-p$i" | tr ':/.' '___') + rm -f "$state/.park-surfaced-$key" + printf '%s' "$gate" > "$state/.park-$key" + done + park_sweep_once "$dir" "test:fm-p1" "$out" || fail "a corrupt cursor stopped the park sweep entirely" + grep -F "test:fm-p1" "$out" >/dev/null || fail "a corrupt cursor did not restart coverage at the top: $(cat "$out")" + unset FM_FAKE_CREW_STATE + pass "the park sweep rotates its bounded window so every ship task is covered within ceil(N/cap) sweeps" +} + test_nonterminal_stale_repairs_missing_or_corrupt_timer() { local dir state fakebin out capture_file window key pane_hash sig pid since dir=$(make_case nonterminal-stale-timer-repair); state="$dir/state"; fakebin="$dir/fakebin" @@ -1261,7 +1632,9 @@ test_afk_paused_changed_pane_hands_off_plain_stale() { FM_CHECK_INTERVAL=999999 FM_HEARTBEAT=999999 "$WATCH" > "$out" & pid=$! wait_for_exit "$pid" 40 || fail "AFK paused changed pane did not hand off a stale wake" - grep -Fx "stale: $window" "$out" >/dev/null || fail "AFK paused stale did not preserve its plain window identity: $(cat "$out")" + grep -Fx "stale: $window [branch=afk]" "$out" >/dev/null || fail "AFK paused stale did not preserve its plain window identity: $(cat "$out")" + [ "$(stale_reason_window "$(cat "$out")")" = "$window" ] \ + || fail "AFK handoff reason no longer yields its window through the shared extractor: $(cat "$out")" grep -F "awaiting external" "$out" >/dev/null && fail "AFK watcher decorated a stale identity instead of handing it to the daemon" [ ! -e "$state/.paused-$key" ] || fail "AFK watcher recorded normal-mode pause tracking instead of handing off" FM_STATE_OVERRIDE="$state" "$DRAIN" > "$drain_out" 2>/dev/null || fail "drain after AFK paused stale failed" @@ -1270,6 +1643,75 @@ test_afk_paused_changed_pane_hands_off_plain_stale() { pass "AFK changed paused panes hand off plain stale identities for daemon-owned pause triage" } +# --- stale wake reasons carry the branch that produced them ------------------- +# Six paths emit a "stale:" wake and all of them used to open with an identical +# "stale: ", so no consumer could tell which rule fired. The tag closes +# that, but it also decorates reasons that were previously bare, so the window +# must still be recoverable: bin/fm-supervise-daemon.sh backs a window out of the +# reason on every away-mode wake and used a bare prefix strip, which was already +# silently wrong for the decorated wedge and pause reasons and would now be wrong +# for all six. stale_reason_window is the one owner of that extraction. +test_stale_reason_branch_tags() { + local out arm_out arm_state + [ "$(stale_reason nonterminal 'test:fm-a')" = 'stale: test:fm-a [branch=nonterminal]' ] \ + || fail "undecorated stale reason did not render its branch tag" + [ "$(stale_reason wedge 'test:fm-a' 'idle 300s, possible wedge, escalation 2')" \ + = 'stale: test:fm-a (idle 300s, possible wedge, escalation 2) [branch=wedge]' ] \ + || fail "decorated stale reason did not render detail and branch tag" + + # Extraction: tagged, detailed, both, and the bare legacy form a daemon test or + # an older watcher can still produce. + [ "$(stale_reason_window 'stale: test:fm-a [branch=nonterminal]')" = 'test:fm-a' ] \ + || fail "branch tag was not stripped from a stale reason" + [ "$(stale_reason_window 'stale: test:fm-a (idle 300s, possible wedge, escalation 2) [branch=wedge]')" = 'test:fm-a' ] \ + || fail "detail and branch tag were not stripped from a stale reason" + [ "$(stale_reason_window 'stale: test:fm-a (paused 3600s, awaiting external - declared pause)')" = 'test:fm-a' ] \ + || fail "an untagged but detailed stale reason did not yield its window" + [ "$(stale_reason_window 'stale: test:fm-a')" = 'test:fm-a' ] \ + || fail "a bare stale reason did not yield its window" + [ "$(stale_reason_window 'test:fm-a')" = 'test:fm-a' ] \ + || fail "a plain window was not returned unchanged" + + # The arm layer's lifecycle ledger is the only durable per-wake record, so the + # branch has to reach it for actionable wakes to be countable per rule. The arm + # script's runtime stops at its source guard, but sourcing it still pulls in + # bin/fm-wake-lib.sh, which resolves and creates its own STATE and rebinds the + # suite-wide STATE/TRIAGE_LOG/FM_WAKE_QUEUE/WATCH. This test runs first, so + # every later test would inherit that. Call the classifier in a subshell with + # its own state dir instead: same assertions, no suite-wide mutation and no + # directory written into the working tree. + arm_state=$(mktemp -d "$TMP_ROOT/arm-state.XXXXXX") + arm_reason_type() { # -> ledger classification + local line=$1 + printf '%s\n' "$line" > "$arm_out" + ( + FM_STATE_OVERRIDE="$arm_state" + export FM_STATE_OVERRIDE + # shellcheck source=/dev/null + . "$ROOT/bin/fm-watch-arm.sh" + watch_output_reason_type "$arm_out" + ) + } + arm_out=$(mktemp "$TMP_ROOT/arm-reason.XXXXXX") + out=$(arm_reason_type 'stale: test:fm-a (idle 300s, possible wedge, escalation 2) [branch=wedge]') + [ "$out" = 'actionable-stale-wedge' ] \ + || fail "cycle ledger did not record the stale branch: $out" + [ "$(arm_reason_type 'stale: test:fm-a [branch=pause-resurface]')" = 'actionable-stale-pause-resurface' ] \ + || fail "cycle ledger did not record a hyphenated stale branch" + # An untagged reason keeps the classification it has always had, so a watcher + # and an arm layer at different versions cannot produce an unreadable row. + [ "$(arm_reason_type 'stale: test:fm-a')" = 'actionable-stale' ] \ + || fail "an untagged stale reason lost its ledger classification" + # A malformed tag must not leak arbitrary text into a ledger field. + [ "$(arm_reason_type 'stale: test:fm-a [branch=NOT A BRANCH]')" = 'actionable-stale' ] \ + || fail "a malformed branch tag was copied into the ledger" + [ "$(arm_reason_type "signal: $TMP_ROOT/a.status")" = 'actionable-signal' ] \ + || fail "signal classification changed" + rm -rf "$arm_out" "$arm_state" + pass "stale wake reasons carry, and give back, the classification branch that produced them" +} + +test_stale_reason_branch_tags test_signal_reason_is_actionable_classifier test_stale_is_terminal_classifier test_scan_captain_relevant_statuses_classifier @@ -1288,9 +1730,12 @@ test_stale_terminal_status_overridden_by_active_run test_nonterminal_stale_provably_working_absorbed_then_escalated test_wedge_escalation_marks_demand_deep_inspection_after_threshold test_wedge_escalation_resets_when_pane_becomes_active +test_wedge_escalation_resets_when_the_pipeline_advances +test_wedge_escalation_unreadable_progress_still_escalates test_nonterminal_stale_not_working_surfaced test_nonterminal_stale_paused_absorbed_then_resurfaced test_exited_declared_pause_is_bounded_but_live_gate_surfaces +test_live_declared_pause_surfaces_once_per_pause_window test_secondmate_paused_resurfaces_in_normal_mode test_secondmate_nonpaused_stale_remains_suppressed test_secondmate_unpause_clears_pause_tracking @@ -1298,6 +1743,10 @@ test_nonterminal_stale_pause_transitions_reclassify_unchanged_hash test_nonterminal_paused_rechecks_authoritative_state test_paused_authoritative_working_preserves_wedge_timer test_nonterminal_stale_repairs_missing_or_corrupt_timer +test_park_scan_surfaces_an_unanswered_gate +test_park_scan_stays_silent_when_the_run_moves +test_park_scan_can_be_switched_off +test_park_scan_rotates_across_a_fleet_larger_than_the_cap test_triage_log_size_cap_accepts_spaced_wc_counts test_heartbeat_no_change_absorbed test_heartbeat_backstop_surfaces_unsurfaced_status diff --git a/tests/wake-helpers.sh b/tests/wake-helpers.sh index dd0277c1d8..8dd61346dc 100644 --- a/tests/wake-helpers.sh +++ b/tests/wake-helpers.sh @@ -100,13 +100,39 @@ SH # A per-id override FM_FAKE_CREW_STATE_ wins; otherwise the shared # FM_FAKE_CREW_STATE; otherwise an unknown verdict (NOT provably working), the # safe default so a test that forgets to set one surfaces rather than absorbs. +# The fake also answers `--progress` with FM_FAKE_CREW_PROGRESS (per-id override +# FM_FAKE_CREW_PROGRESS_), the progress fingerprint the wedge +# escalation compares across checks. Its default is a FIXED string, not the state +# line and not anything derived from the clock: an unchanging fingerprint means +# "no evidence of progress", which is the behaviour every pre-existing wedge test +# was written against, so those tests keep asserting what they always did. make_fake_crew_state() { # local fakebin=$1 cat > "$fakebin/fm-crew-state.sh" <<'SH' #!/usr/bin/env bash set -u -id=${1:-} +id="" +mode=state +for a in "$@"; do + case "$a" in + --progress) mode=progress ;; + -*) ;; + *) [ -n "$id" ] || id=$a ;; + esac +done key=$(printf '%s' "$id" | tr -c 'A-Za-z0-9' '_') +if [ "$mode" = progress ]; then + # Set-but-empty is meaningful here and must not fall through to the default: + # it is how a test drives the unreadable-fingerprint case, which has to keep + # escalating rather than absorb. + var="FM_FAKE_CREW_PROGRESS_$key" + if [ -n "${!var+set}" ]; then val=${!var} + elif [ -n "${FM_FAKE_CREW_PROGRESS+set}" ]; then val=${FM_FAKE_CREW_PROGRESS} + else val='0/fake/fake/fake/fake' + fi + printf '%s\n' "$val" + exit 0 +fi var="FM_FAKE_CREW_STATE_$key" val=${!var:-${FM_FAKE_CREW_STATE:-}} printf '%s\n' "${val:-state: unknown · source: none · fake default}"