diff --git a/bin/fm-classify-lib.sh b/bin/fm-classify-lib.sh index 4ef23286934..0f69bb18a5d 100755 --- a/bin/fm-classify-lib.sh +++ b/bin/fm-classify-lib.sh @@ -815,7 +815,7 @@ _fm_decision_key_transition_allowed() { # _fm_is_pending_reply_escalation() { # case "$1" in pending-reply-*) ;; *) return 1 ;; esac case "$2" in - pending-reply-missed:*|pending-reply-delivery-unknown:*|pending-reply-recovery-delivery-failed:*|pending-reply-recovery-delivery-unknown:*) return 0 ;; + pending-reply-missed:*|pending-reply-delivery-unknown:*|pending-reply-unread:*|pending-reply-recovery-delivery-failed:*|pending-reply-recovery-delivery-unknown:*) return 0 ;; *) return 1 ;; esac } diff --git a/bin/fm-pending-reply-lib.sh b/bin/fm-pending-reply-lib.sh index a4821c24af9..da72dce5750 100755 --- a/bin/fm-pending-reply-lib.sh +++ b/bin/fm-pending-reply-lib.sh @@ -71,6 +71,63 @@ # missed-report escalation, are eligible - measured # from the relevant turn's completion (request or # recovery), never from delivery or send time +# unread_detail= the inbox facts an unread escalation reported +# unread_escalated_epoch= when that one unread escalation was raised +# delivery_checked_epoch= last undelivered-record inbox check that got an answer +# (throttle; a failed read does not set it) +# delivery_read_failed_epoch= when the last inbox read of an undelivered record +# failed; the next read waits the short read-retry +# spacing from it, and a read that answers clears it +# delivery_reconcile= landed | resent | absent once an undelivered record +# was checked against the mate's inbox; landed and +# absent end the checking +# delivery_resend_epoch= when the one automatic same-correlation resend ran +# A remote send whose delivery stayed unknown also keeps its pre-marker request +# text in state/pending-replies/.undelivered-text- (mode 600) until the +# record is delivered, discarded, or reconciled, so that one resend can repeat +# the exact original body (see the inbox reconciliation note below). A +# --resolve-key answer keeps none: only fm-send's printed resend closes its +# keys, so the tracker never reconciles a record without stored text. +# +# Inbox reconciliation (parent-owned, read-only on the mate's side): the +# tracker reads where a request's record stands in the mate's steering inbox - +# the parent's own state/.inbox for a local mate, or the remote leg's +# `fm-remote-secondmate-control.sh inbox-status` for a remote one +# (fm_pending_reply_inbox_status_report owns that format). Three uses: +# - An idle observation is NOT a completed turn while the request's record +# (or its recovery record) is still unhandled, whatever busy was seen: a +# mate that never read it is not a mate that took its turn, including one +# that was already busy on other work when the request landed. +# - A remote request still unhandled FM_PENDING_REPLY_UNREAD_SECS after +# delivery (or after the recovery send) escalates ONCE as +# pending-reply-unread, naming its age, the composer verdict, and the +# fm-peek / --key Enter remedy; the record keeps tracking, so a later +# missed-report escalation reuses the same decision key. A local mate's +# unread record is the parent watcher's re-ring ladder's to escalate. +# - An undelivered record (delivery_unknown, or a delivery-unknown +# escalation) with stored text, or whose one resend already ran, is +# checked once the mate is reachable, at most every +# FM_PENDING_REPLY_DELIVERY_RECHECK_SECS: a record that landed is marked +# delivered; an absent one gets exactly one automatic resend under the same +# correlation through fm-send's FM_PENDING_REPLY_EXISTING_CORR contract, +# only while it is younger than +# FM_PENDING_REPLY_RESEND_MAX_AGE_SECS, because a stale instruction must +# not land unannounced. Once delivery is known either way, the open +# delivery-unknown decision is closed with the via=delivery-reconciled +# note (a landed record is marked delivered only after that close, and a +# resent one's failed close is retried every pass until it is recorded in +# escalation_closed_epoch); the request itself keeps waiting for its +# correlated report. +# An inbox read that fails (an unreachable host, or a remote copy without the +# inbox-status leg) changes nothing about the record's delivery state, and it +# does not start the long recheck spacing: the next read of that record waits +# only FM_PENDING_REPLY_DELIVERY_READ_RETRY_SECS from the failure, so a host +# that is back is found promptly while a down or incapable one is not dialed on +# every watcher pass. Every remote inbox read is also bounded to +# FM_PENDING_REPLY_INBOX_READ_BUDGET seconds so a silent host cannot hold the +# watcher. +# These helpers read the inbox through bin/fm-task-inbox-lib.sh, sourced on +# first use when the caller has not already loaded it. # # Escalation lifecycle: an escalation is not just a message, it OPENS a durable # keyed decision in the parent status log, and bin/fm-classify-lib.sh's fold is @@ -118,6 +175,15 @@ # FM_PENDING_REPLY_SEND_HOOK optional command template for recovery delivery # (tests); receives task_id and full message as args # FM_PENDING_REPLY_NOW optional fixed epoch for deterministic tests +# FM_PENDING_REPLY_UNREAD_SECS default 300; remote unread-escalation age +# FM_PENDING_REPLY_DELIVERY_RECHECK_SECS default 600; undelivered inbox check +# spacing per record +# FM_PENDING_REPLY_DELIVERY_READ_RETRY_SECS default 60; spacing between reads +# of one undelivered record after a failed read +# FM_PENDING_REPLY_INBOX_READ_BUDGET default 30; hard bound in seconds on one +# remote inbox-status ssh round trip +# FM_PENDING_REPLY_RESEND_MAX_AGE_SECS default 7200; oldest request the one +# automatic undelivered resend may repeat # This directive does double duty: it also binds _FM_PENDING_REPLY_LIB_DIR as # the bin/ source prefix so the deliberately undirected lazy sources below @@ -140,6 +206,11 @@ _FM_PENDING_REPLY_LIB_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd 2>/dev/n FM_PENDING_REPLY_SCHEMA='fm-pending-reply.v1' FM_PENDING_REPLY_CORR_RE='corr=[A-Fa-f0-9]{16}' FM_PENDING_REPLY_GRACE_DEFAULT=120 +FM_PENDING_REPLY_UNREAD_DEFAULT=300 +FM_PENDING_REPLY_DELIVERY_RECHECK_DEFAULT=600 +FM_PENDING_REPLY_RESEND_MAX_AGE_DEFAULT=7200 +FM_PENDING_REPLY_DELIVERY_READ_RETRY_DEFAULT=60 +FM_PENDING_REPLY_INBOX_READ_BUDGET_DEFAULT=30 fm_pending_reply_now() { if [ -n "${FM_PENDING_REPLY_NOW:-}" ]; then @@ -157,6 +228,11 @@ fm_pending_reply_grace_secs() { printf '%s' "$g" } +# A non-negative integer tunable, or its default. +fm_pending_reply_tunable() { # + case "$1" in ''|*[!0-9]*) printf '%s' "$2" ;; *) printf '%s' "$1" ;; esac +} + # Directory holding durable pending-reply records for . fm_pending_reply_dir() { # local state=$1 @@ -458,12 +534,27 @@ _fm_pending_reply_confirm_delivery_locked() { # now=$(fm_pending_reply_now) fm_pending_reply_write_delivery_confirmation "$state" "$corr" confirmed "$now" || return 1 if fm_pending_reply_mark_delivered "$state" "$corr" "$now"; then - rm -f "$marker" 2>/dev/null || true + rm -f "$marker" "$(fm_pending_reply_undelivered_text_path "$state" "$corr")" 2>/dev/null || true return 0 fi return 2 } +fm_pending_reply_undelivered_text_path() { # + printf '%s/.undelivered-text-%s' "$(fm_pending_reply_dir "$1")" "$2" +} + +# Keep the pre-marker request text of a remote send whose delivery stayed +# unknown, for the one automatic same-correlation resend. Best-effort. +fm_pending_reply_store_undelivered_text() { # + local path tmp + path=$(fm_pending_reply_undelivered_text_path "$1" "$2") + tmp="$path.tmp.$$" + ( umask 077; printf '%s' "$3" > "$tmp" ) 2>/dev/null && mv -f "$tmp" "$path" 2>/dev/null && return 0 + rm -f "$tmp" 2>/dev/null + return 1 +} + # Preserve an expectation when a remote transport disconnect makes delivery # completion unknowable. This never resolves or retries the request; it moves # the existing prepared record to the owner's explicit unknown-delivery path. @@ -591,7 +682,7 @@ fm_pending_reply_discard_undelivered() { # delivered=$(fm_pending_reply_get "$rec" delivered_epoch) [ -z "$delivered" ] || return 1 marker=$(fm_pending_reply_delivery_confirmation_path "$state" "$corr") - rm -f "$marker" 2>/dev/null || true + rm -f "$marker" "$(fm_pending_reply_undelivered_text_path "$state" "$corr")" 2>/dev/null || true rm -f "$rec" } @@ -726,7 +817,7 @@ _fm_pending_reply_try_resolve_locked() { # [status-file-o fm_pending_reply_set "$rec" phase resolved || return 1 if [ -z "$delivered" ]; then fm_pending_reply_mark_delivered "$state" "$corr" "$now" || return 1 - rm -f "$marker" 2>/dev/null || true + rm -f "$marker" "$(fm_pending_reply_undelivered_text_path "$state" "$corr")" 2>/dev/null || true fi fm_pending_reply_set "$rec" resolved_epoch "$now" || return 1 fm_pending_reply_set "$rec" resolved_via "$via" || return 1 @@ -1153,6 +1244,11 @@ fm_pending_reply_escalation_payload() { # delivery-unknown) token=pending-reply-delivery-unknown ;; + unread) + printf 'pending-reply-unread: task=%s pending-reply-id=%s %s request=%s' \ + "$task_id" "$corr" "$(fm_pending_reply_get "$rec" unread_detail)" "$summary" + return 0 + ;; recovery-delivery) outcome=$(fm_pending_reply_get "$rec" recovery_delivery_outcome) case "$outcome" in failed|unknown) ;; *) return 1 ;; esac @@ -1175,7 +1271,7 @@ fm_pending_reply_escalation_line() { # while IFS= read -r line || [ -n "$line" ]; do [ "$(status_line_verb "$line")" = blocked ] || continue _fm_status_untimed "$line" untimed - for kind in missed delivery-unknown recovery-delivery; do + for kind in missed delivery-unknown unread recovery-delivery; do payload=$(fm_pending_reply_escalation_payload "$rec" "$kind") || continue case "$untimed" in "blocked [key=$own_key]: $payload"|"blocked: $payload") found=$line; break ;; @@ -1213,15 +1309,38 @@ fm_pending_reply_close_escalation() { # } _fm_pending_reply_close_escalation_locked() { # - local state=$1 corr=$2 rec escalated closed parent_status escalation key note - local open_line open_key open_note now close_line close_rc _task _via + local state=$1 corr=$2 rec escalated closed now phase via reconcile rec=$(fm_pending_reply_path "$state" "$corr") [ -f "$rec" ] || return 1 - [ "$(fm_pending_reply_get "$rec" phase)" = resolved ] || return 0 escalated=$(fm_pending_reply_get "$rec" escalated_epoch) [ -n "$escalated" ] || return 0 closed=$(fm_pending_reply_get "$rec" escalation_closed_epoch) [ -z "$closed" ] || return 0 + phase=$(fm_pending_reply_get "$rec" phase) + if [ "$phase" = resolved ]; then + via=$(fm_pending_reply_get "$rec" resolved_via) + else + # A delivery-unknown escalation whose request the inbox reconciliation + # since found delivered (landed or resent). A later unread or missed + # escalation is not this one and stays open until the report resolves it. + reconcile=$(fm_pending_reply_get "$rec" delivery_reconcile) + case "$reconcile" in landed|resent) ;; *) return 0 ;; esac + [ -n "$(fm_pending_reply_get "$rec" delivered_epoch)" ] \ + && [ -z "$(fm_pending_reply_get "$rec" unread_escalated_epoch)" ] \ + && [ "$phase" != escalated ] || return 0 + via="delivery-reconciled $reconcile" + fi + _fm_pending_reply_close_open_escalation_locked "$rec" "$corr" "$via" || return 1 + now=$(fm_pending_reply_now) + fm_pending_reply_set "$rec" escalation_closed_epoch "$now" +} + +# Append the reserved-key close for 's escalation decision while that +# exact decision is still open; a no-op otherwise. The record keeps its phase: +# the resolve close above and the delivery reconciliation both call this. +_fm_pending_reply_close_open_escalation_locked() { # + local rec=$1 corr=$2 via=$3 parent_status escalation key note + local open_line open_key open_note close_line close_rc _task parent_status=$(fm_pending_reply_get "$rec" parent_status) [ -n "$parent_status" ] || return 1 escalation=$(fm_pending_reply_escalation_line "$parent_status" "$rec" "$corr") @@ -1241,8 +1360,7 @@ _fm_pending_reply_close_escalation_locked() { # # wrappers) and does not wake the home that wrote it; the escalation # OPEN above stays a plain append because a new blocker must wake. _task=$(fm_pending_reply_get "$rec" task_id) - _via=$(fm_pending_reply_get "$rec" resolved_via) - close_line="resolved [key=${key}]: $(fm_pending_reply_resolved_note "$_task" "$corr" "$_via")" + close_line="resolved [key=${key}]: $(fm_pending_reply_resolved_note "$_task" "$corr" "$via")" close_rc=0 fm_wake_status_append_self_announced "${parent_status%/*}" "$parent_status" "$close_line" \ 2>/dev/null || close_rc=$? @@ -1252,8 +1370,7 @@ _fm_pending_reply_close_escalation_locked() { # $(status_open_decisions "$parent_status") EOF fi - now=$(fm_pending_reply_now) - fm_pending_reply_set "$rec" escalation_closed_epoch "$now" + return 0 } # Escalate once after a missed recovery report or failed delivery outcome. @@ -1360,11 +1477,307 @@ _fm_pending_reply_maybe_escalate_locked() { # printf '%s\n' "$(status_stamp_line "$line")" >> "$parent_status" 2>/dev/null || return 1 fi now=$(fm_pending_reply_now) + # A new decision is open, so an earlier delivery-reconciled close no longer + # describes it. + [ -z "$(fm_pending_reply_get "$rec" escalation_closed_epoch)" ] \ + || fm_pending_reply_set "$rec" escalation_closed_epoch "" || return 1 fm_pending_reply_set "$rec" escalated_epoch "$now" || return 1 fm_pending_reply_set "$rec" phase escalated || return 1 return 0 } +# Load bin/fm-task-inbox-lib.sh once. Its bin/fm-wake-lib.sh assigns lock +# globals when sourced, so they are local here for the reason +# fm_pending_reply_close_escalation documents. +_fm_pending_reply_need_task_inbox() { + declare -F fm_task_inbox_body >/dev/null && return 0 + local STATE FM_WAKE_QUEUE FM_WAKE_QUEUE_LOCK + # Deliberately undirected: bin/fm-task-inbox-lib.sh is a canonical lint root. + . "$_FM_PENDING_REPLY_LIB_DIR/fm-task-inbox-lib.sh" +} + +# Where 's request stands in one steering inbox: unhandled while any +# record carrying its corr= token (the request or its recovery repost) awaits +# acknowledgement, handled once only acknowledged copies remain, else absent. +fm_pending_reply_inbox_corr_state() { # + local dir=$1 corr=$2 f body + _fm_pending_reply_need_task_inbox || return 1 + for f in "$dir"/*.msg; do + [ -f "$f" ] || continue + body=$(fm_task_inbox_body "$f" 2>/dev/null) || continue + if fm_pending_reply_text_has_corr "$body" "$corr"; then + printf 'unhandled' + return 0 + fi + done + for f in "$dir"/handled/*.msg; do + [ -f "$f" ] || continue + body=$(fm_task_inbox_body "$f" 2>/dev/null) || continue + if fm_pending_reply_text_has_corr "$body" "$corr"; then + printf 'handled' + return 0 + fi + done + printf 'absent' +} + +# The one inbox-status format, printed by the remote leg on the mate's host and +# computed directly for a local mate. key=value lines: +# schema=fm-inbox-status.v1 +# unhandled= +# oldest_age= +# corr_state= only when is given +# composer= +fm_pending_reply_inbox_status_report() { # [corr_id] [composer] + local state=$1 task=$2 corr=${3-} composer=${4:-unknown} summary count=0 oldest='' age='' + _fm_pending_reply_need_task_inbox || return 1 + if summary=$(fm_task_inbox_unhandled_summary "$state" "$task"); then + read -r count oldest age <'s inbox status for : on the mate's host for a remote +# target, directly from this home's state for a local one. Fails, printing +# nothing, when the remote read fails or answers in another format. +fm_pending_reply_inbox_status() { # + local out + if fm_pending_reply_target_is_remote "$1" "$2"; then + local budget + budget=$(fm_pending_reply_tunable "${FM_PENDING_REPLY_INBOX_READ_BUDGET:-}" "$FM_PENDING_REPLY_INBOX_READ_BUDGET_DEFAULT") + [ "$budget" -gt 0 ] || budget=$FM_PENDING_REPLY_INBOX_READ_BUDGET_DEFAULT + # Bounded here, not in fm-on.sh: only the tracker's reads must never hold + # the watcher, and fm-send already bounds its own legs the same way. + out=$(fm_run_timed "$budget" "$_FM_PENDING_REPLY_LIB_DIR/fm-on.sh" "$2" \ + fm-remote-secondmate-control.sh inbox-status "$2" "$3" < /dev/null 2>/dev/null) || return 1 + case "$out" in schema=fm-inbox-status.v1*) ;; *) return 1 ;; esac + printf '%s\n' "$out" + return 0 + fi + fm_pending_reply_inbox_status_report "$1" "$2" "$3" +} + +fm_pending_reply_inbox_field() { # + printf '%s\n' "$1" | sed -n "s/^$2=//p" | head -1 +} + +# 0 when an idle observation for must not count as a completed +# turn: no completion is recorded and the request is still unhandled in the +# mate's inbox, whatever busy was seen (a request that lands on an already busy +# mate stays unread through that turn). On that path a remote record also gets +# its one unread escalation once it is old enough. An unreadable inbox returns +# 1, so the idle counts exactly as it did before. +fm_pending_reply_idle_unread() { # + local state=$1 rec=$2 phase completed start task_id corr status now age + phase=$(fm_pending_reply_get "$rec" phase) + case "$phase" in + awaiting_report) + completed=$(fm_pending_reply_get "$rec" request_turn_completed_epoch) + start=$(fm_pending_reply_get "$rec" delivered_epoch) + ;; + recovery_sent) + completed=$(fm_pending_reply_get "$rec" recovery_turn_completed_epoch) + start=$(fm_pending_reply_get "$rec" recovery_sent_epoch) + ;; + *) return 1 ;; + esac + [ -z "$completed" ] || return 1 + task_id=$(fm_pending_reply_get "$rec" task_id) + corr=$(fm_pending_reply_get "$rec" corr_id) + status=$(fm_pending_reply_inbox_status "$state" "$task_id" "$corr") || return 1 + [ "$(fm_pending_reply_inbox_field "$status" corr_state)" = unhandled ] || return 1 + if fm_pending_reply_target_is_remote "$state" "$task_id" \ + && [ -z "$(fm_pending_reply_get "$rec" unread_escalated_epoch)" ]; then + case "$start" in ''|*[!0-9]*) return 0 ;; esac + now=$(fm_pending_reply_now) + age=$((now - start)) + if [ "$age" -ge "$(fm_pending_reply_tunable "${FM_PENDING_REPLY_UNREAD_SECS:-}" "$FM_PENDING_REPLY_UNREAD_DEFAULT")" ]; then + fm_pending_reply_escalate_unread "$state" "$corr" "$age" "$status" || true + fi + fi + return 0 +} + +# Escalate once that a delivered request sits unread in a remote mate's inbox. +fm_pending_reply_escalate_unread() { # + local state=$1 corr=$2 lock rc=0 + local STATE FM_WAKE_QUEUE FM_WAKE_QUEUE_LOCK + STATE=$state + lock="$state/.pending-reply-$corr.lock" + # Deliberately undirected: see fm_pending_reply_maybe_escalate. + . "$_FM_PENDING_REPLY_LIB_DIR/fm-wake-lib.sh" + fm_lock_acquire_wait "$lock" || return 1 + _fm_pending_reply_escalate_unread_locked "$@" || rc=$? + fm_lock_release "$lock" + return "$rc" +} + +_fm_pending_reply_escalate_unread_locked() { # + local state=$1 corr=$2 age=$3 status=$4 rec phase parent_status task_id detail oldest payload line now + rec=$(fm_pending_reply_path "$state" "$corr") + [ -f "$rec" ] || return 1 + phase=$(fm_pending_reply_get "$rec" phase) + case "$phase" in awaiting_report|recovery_sent) ;; *) return 1 ;; esac + [ -z "$(fm_pending_reply_get "$rec" unread_escalated_epoch)" ] || return 0 + parent_status=$(fm_pending_reply_get "$rec" parent_status) + [ -n "$parent_status" ] || return 1 + if _fm_pending_reply_try_resolve_locked "$state" "$corr" "$parent_status"; then + return 0 + fi + task_id=$(fm_pending_reply_get "$rec" task_id) + oldest=$(fm_pending_reply_inbox_field "$status" oldest_age) + case "$oldest" in ''|*[!0-9]*) oldest=$age ;; esac + detail="landed $((age / 60))m ago, unread ($(fm_pending_reply_inbox_field "$status" unhandled) unhandled, oldest $((oldest / 60))m; composer $(fm_pending_reply_inbox_field "$status" composer)); remedy: fm-peek.sh $task_id, then fm-send.sh $task_id --key Enter" + fm_pending_reply_set "$rec" unread_detail "$detail" || return 1 + payload=$(fm_pending_reply_escalation_payload "$rec" unread) || return 1 + mkdir -p "$(dirname "$parent_status")" 2>/dev/null || return 1 + line="blocked [key=$(fm_pending_reply_escalation_key "$corr")]: $payload" + if ! status_event_recorded "$parent_status" "$line"; then + printf '%s\n' "$(status_stamp_line "$line")" >> "$parent_status" 2>/dev/null || return 1 + fi + now=$(fm_pending_reply_now) + [ -z "$(fm_pending_reply_get "$rec" escalation_closed_epoch)" ] \ + || fm_pending_reply_set "$rec" escalation_closed_epoch "" || return 1 + fm_pending_reply_set "$rec" unread_escalated_epoch "$now" || return 1 + fm_pending_reply_set "$rec" escalated_epoch "$now" +} + +# True while the record is an undelivered one that reconciliation still owns. +_fm_pending_reply_undelivered_open() { # + local rec=$1 + [ -f "$rec" ] || return 1 + [ -z "$(fm_pending_reply_get "$rec" delivered_epoch)" ] || return 1 + case "$(fm_pending_reply_get "$rec" phase)" in delivery_unknown|escalated) ;; *) return 1 ;; esac + case "$(fm_pending_reply_get "$rec" delivery_reconcile)" in landed|absent) return 1 ;; esac +} + +# Reconcile an undelivered record against the mate's inbox (see the header's +# inbox reconciliation note). Returns 0 only after it changed the record. +fm_pending_reply_reconcile_undelivered() { # + local state=$1 corr=$2 rec task_id checked now recheck status corr_state text_path + local created max_age lock rc=0 parent_home text failed read_retry read_ok=1 + local STATE FM_WAKE_QUEUE FM_WAKE_QUEUE_LOCK + rec=$(fm_pending_reply_path "$state" "$corr") + _fm_pending_reply_undelivered_open "$rec" || return 1 + text_path=$(fm_pending_reply_undelivered_text_path "$state" "$corr") + [ -f "$text_path" ] || [ -n "$(fm_pending_reply_get "$rec" delivery_resend_epoch)" ] || return 1 + now=$(fm_pending_reply_now) + checked=$(fm_pending_reply_get "$rec" delivery_checked_epoch) + recheck=$(fm_pending_reply_tunable "${FM_PENDING_REPLY_DELIVERY_RECHECK_SECS:-}" "$FM_PENDING_REPLY_DELIVERY_RECHECK_DEFAULT") + case "$checked" in ''|*[!0-9]*) ;; *) [ $((now - checked)) -ge "$recheck" ] || return 1 ;; esac + failed=$(fm_pending_reply_get "$rec" delivery_read_failed_epoch) + read_retry=$(fm_pending_reply_tunable "${FM_PENDING_REPLY_DELIVERY_READ_RETRY_SECS:-}" "$FM_PENDING_REPLY_DELIVERY_READ_RETRY_DEFAULT") + case "$failed" in ''|*[!0-9]*) ;; *) [ $((now - failed)) -ge "$read_retry" ] || return 1 ;; esac + task_id=$(fm_pending_reply_get "$rec" task_id) + # Only a read that answered counts as a check, so a failed one (host down) is + # retried after the short read-retry spacing rather than the full recheck + # spacing - and not on every pass, which would dial a down or incapable host + # at the watcher's poll rate. + status=$(fm_pending_reply_inbox_status "$state" "$task_id" "$corr") || read_ok=0 + STATE=$state + lock="$state/.pending-reply-$corr.lock" + # Deliberately undirected: see fm_pending_reply_maybe_escalate. + . "$_FM_PENDING_REPLY_LIB_DIR/fm-wake-lib.sh" + # The read ran unlocked, so the reply handler may have settled the record + # meanwhile: recheck it under the per-correlation lock before writing. + fm_lock_acquire_wait "$lock" || return 1 + if ! _fm_pending_reply_undelivered_open "$rec"; then + fm_lock_release "$lock" + return 1 + fi + if [ "$read_ok" -eq 0 ]; then + fm_pending_reply_set "$rec" delivery_read_failed_epoch "$now" || true + fm_lock_release "$lock" + return 1 + fi + if [ -n "$failed" ]; then + fm_pending_reply_set "$rec" delivery_read_failed_epoch "" || true + fi + if ! fm_pending_reply_set "$rec" delivery_checked_epoch "$now"; then + fm_lock_release "$lock" + return 1 + fi + corr_state=$(fm_pending_reply_inbox_field "$status" corr_state) + case "$corr_state" in + unhandled|handled) + _fm_pending_reply_reconcile_landed_locked "$state" "$corr" "$now" || rc=$? + fm_lock_release "$lock" + return "$rc" + ;; + absent) ;; + *) fm_lock_release "$lock"; return 1 ;; + esac + created=$(fm_pending_reply_get "$rec" created_epoch) + max_age=$(fm_pending_reply_tunable "${FM_PENDING_REPLY_RESEND_MAX_AGE_SECS:-}" "$FM_PENDING_REPLY_RESEND_MAX_AGE_DEFAULT") + parent_home=$(fm_pending_reply_get "$rec" parent_home) + if [ -n "$(fm_pending_reply_get "$rec" delivery_resend_epoch)" ] \ + || [ -z "$parent_home" ] || [ ! -d "$parent_home" ] \ + || case "$created" in ''|*[!0-9]*) true ;; *) [ $((now - created)) -gt "$max_age" ] ;; esac; then + # Never landed and no resend is due: stop checking. The open escalation + # keeps the request in front of firstmate, whose manual resend command + # still reuses this correlation. + fm_pending_reply_set "$rec" delivery_reconcile absent || rc=$? + fm_lock_release "$lock" + [ "$rc" -ne 0 ] || rm -f "$text_path" 2>/dev/null || true + return "$rc" + fi + # Byte-exact: a bare $(cat) would drop the body's trailing newlines, and the + # mate's inbox dedup compares the whole body. + if ! text=$(cat "$text_path" 2>/dev/null && printf x) \ + || ! fm_pending_reply_set "$rec" delivery_resend_epoch "$now" \ + || ! fm_pending_reply_set "$rec" delivery_reconcile resent; then + fm_lock_release "$lock" + return 1 + fi + text=${text%x} + fm_lock_release "$lock" + # fm-send owns the outcome: success confirms delivery on the record, and an + # unknown transport marks it delivery_unknown again for the next check. A + # definite failure leaves it awaiting_report with no marker, which is + # returned to delivery_unknown so the record stays tracked and escalates. + env FM_HOME="$parent_home" FM_PENDING_REPLY_EXISTING_CORR="$corr" \ + "$_FM_PENDING_REPLY_LIB_DIR/fm-send.sh" "$task_id" "$text" >/dev/null 2>&1 || true + fm_lock_acquire_wait "$lock" || return 1 + if [ -z "$(fm_pending_reply_get "$rec" delivered_epoch)" ]; then + if [ "$(fm_pending_reply_get "$rec" phase)" = awaiting_report ] \ + && [ ! -e "$(fm_pending_reply_delivery_confirmation_path "$state" "$corr")" ]; then + fm_pending_reply_set "$rec" phase delivery_unknown || rc=$? + fi + fm_lock_release "$lock" + return "$rc" + fi + _fm_pending_reply_close_escalation_locked "$state" "$corr" || rc=$? + fm_lock_release "$lock" + return "$rc" +} + +_fm_pending_reply_reconcile_landed_locked() { # + local state=$1 corr=$2 now=$3 rec phase escalated + rec=$(fm_pending_reply_path "$state" "$corr") + [ -f "$rec" ] || return 1 + [ -z "$(fm_pending_reply_get "$rec" delivered_epoch)" ] || return 0 + phase=$(fm_pending_reply_get "$rec" phase) + case "$phase" in delivery_unknown|escalated) ;; *) return 0 ;; esac + # Close before marking delivered: a failed close leaves the record + # undelivered, so the next check retries it. + escalated=$(fm_pending_reply_get "$rec" escalated_epoch) + if [ -n "$escalated" ]; then + _fm_pending_reply_close_open_escalation_locked "$rec" "$corr" "delivery-reconciled landed" || return 1 + fi + fm_pending_reply_set "$rec" delivered_epoch "$now" || return 1 + fm_pending_reply_set "$rec" delivery_reconcile landed || return 1 + fm_pending_reply_set "$rec" phase awaiting_report || return 1 + rm -f "$(fm_pending_reply_delivery_confirmation_path "$state" "$corr")" \ + "$(fm_pending_reply_undelivered_text_path "$state" "$corr")" 2>/dev/null || true + [ -z "$escalated" ] || fm_pending_reply_set "$rec" escalation_closed_epoch "$now" +} + # Detect a correlated report written under the secondmate home (wrong home) # without treating it as acknowledgement. A remote route's # parent-replies.status is its parent channel, not a stranded self-home file. @@ -1599,11 +2012,18 @@ fm_pending_reply_tick() { # if [ -z "$delivered" ]; then case "$phase" in delivery_unknown|escalated) + # A landed or resent record is tracked as delivered from next tick. + fm_pending_reply_reconcile_undelivered "$state" "$corr" || true + [ -z "$(fm_pending_reply_get "$rec" delivered_epoch)" ] || continue fm_pending_reply_tick_one "$state" "$corr" unknown "" || true ;; esac continue fi + # Retries a delivery-reconciled close that failed on a status write. + case "$(fm_pending_reply_get "$rec" delivery_reconcile)" in + landed|resent) fm_pending_reply_close_escalation "$state" "$corr" || true ;; + esac case "$phase" in awaiting_report|recovery_sending) if [ -n "$(fm_pending_reply_get "$rec" recovery_attempted_epoch)" ]; then @@ -1678,6 +2098,9 @@ fm_pending_reply_tick() { # observation_values+=("$observation") fi busy=$(fm_pending_reply_busy_state_from_observation "$rec" "$observation") + if [ "$busy" = idle ] && fm_pending_reply_idle_unread "$state" "$rec"; then + busy=unknown + fi fi fi fm_pending_reply_tick_one "$state" "$corr" "$busy" "$sm_home" || true diff --git a/bin/fm-remote-secondmate-control.sh b/bin/fm-remote-secondmate-control.sh index ee91f8ae152..ffa08232b4d 100755 --- a/bin/fm-remote-secondmate-control.sh +++ b/bin/fm-remote-secondmate-control.sh @@ -11,6 +11,7 @@ # fm-remote-secondmate-control.sh key # fm-remote-secondmate-control.sh capture [lines] # fm-remote-secondmate-control.sh observe +# fm-remote-secondmate-control.sh inbox-status [] # fm-remote-secondmate-control.sh sync [] # fm-remote-secondmate-control.sh update # fm-remote-secondmate-control.sh retire [--force] @@ -63,7 +64,7 @@ CONTROL_DATA="$TARGET_HOME/data/.parent-route" REMOTE_HERDR_SESSION=fm-remote die() { printf 'error: %s\n' "$1" >&2; exit 1; } -usage() { sed -n '2,24p' "$0" | sed 's/^# \{0,1\}//'; exit 2; } +usage() { sed -n '2,25p' "$0" | sed 's/^# \{0,1\}//'; exit 2; } validate_id() { case "$1" in ''|*[!A-Za-z0-9._-]*) die "invalid secondmate id: $1" ;; esac; } # Sourcing fm-wake-lib.sh through the libraries below creates "$FM_HOME/state", @@ -365,6 +366,29 @@ cmd_observe() { printf '\n' } +# Read-only delivery facts for the parent's reply tracker: how many records sit +# unhandled in this secondmate's host-local steering inbox and how old the +# oldest is, where one correlated request stands there (unhandled, handled, or +# absent), and the recorded pane's composer verdict. The parent cannot read this +# inbox itself; bin/fm-pending-reply-lib.sh owns the output format and what the +# tracker does with it. An unreadable endpoint reports composer=unknown rather +# than failing, because the inbox facts stand on their own. +cmd_inbox_status() { + local id=$1 corr=${2:-} composer=unknown + validate_id "$id" + case "$corr" in + '') ;; + *[!0-9a-f]*) die "invalid correlation id: $corr" ;; + *) [ "${#corr}" -eq 16 ] || die "invalid correlation id: $corr" ;; + esac + validate_home "$id" + if [ -f "$(meta_path "$id")" ] && remote_endpoint_load "$id"; then + composer=$(fm_backend_composer_state "$REMOTE_ENDPOINT_BACKEND" "$REMOTE_ENDPOINT_TARGET" "fm-$id" 2>/dev/null) \ + || composer=unknown + fi + fm_pending_reply_inbox_status_report "$CONTROL_STATE" "$id" "$corr" "$composer" +} + # Make readable in this home's own object store without moving any other # checkout. Ordered by cost: already present, then this host's Firstmate copy (a # read-only fetch of that one commit, which never advances that copy's HEAD), then @@ -465,6 +489,7 @@ case "${1:-}" in key) shift; [ "$#" -eq 2 ] || usage; cmd_key "$@" ;; capture) shift; [ "$#" -ge 1 ] && [ "$#" -le 2 ] || usage; cmd_capture "$@" ;; observe) shift; [ "$#" -eq 1 ] || usage; cmd_observe "$@" ;; + inbox-status) shift; [ "$#" -ge 1 ] && [ "$#" -le 2 ] || usage; cmd_inbox_status "$@" ;; sync) shift; [ "$#" -ge 1 ] && [ "$#" -le 2 ] || usage; cmd_sync "$@" ;; update) shift; [ "$#" -eq 1 ] || usage; cmd_update "$@" ;; retire) shift; [ "$#" -ge 1 ] && [ "$#" -le 2 ] || usage; cmd_retire "$@" ;; diff --git a/bin/fm-send.sh b/bin/fm-send.sh index 7974b64d32d..32e1c479c22 100755 --- a/bin/fm-send.sh +++ b/bin/fm-send.sh @@ -145,10 +145,12 @@ # seconds (default 30, and any override must be a positive integer): a bound # hit is completion-unknown and exits through this same unconfirmed contract # instead of waiting out a busy remote queue. -# The remote host runs no re-ring ladder of its own: a swallowed ordinary -# doorbell surfaces through the parent's pending-reply recovery and escalation, -# whose recovery request re-rings the remote doorbell when it is enqueued; -# fire-and-forget delivery deliberately arms neither mechanism. Internal +# The remote host runs no re-ring ladder of its own: the mate's own watcher +# wakes its session for any unhandled record there (bin/fm-watch.sh +# parent_inbox_tick), and a still-unread ordinary request surfaces through the +# parent's pending-reply tracker, which reads the remote inbox and escalates it +# as unread (bin/fm-pending-reply-lib.sh); a delivery left unknown here is +# reconciled against that inbox the same way once the mate is reachable. Internal # semantic callers may set FM_SEND_EXPECTED_SPAWN_GEN or # FM_SEND_EXPECTED_REMOTE_HOST to require that sampled identity to still match # during the final locked remote-route validation; unset or empty guards do not @@ -999,6 +1001,12 @@ else fi if [ -n "$PENDING_REPLY_CORR" ]; then fm_pending_reply_mark_delivery_unknown "$STATE" "$PENDING_REPLY_CORR" || true + # Kept for the tracker's one same-correlation resend once the mate is + # reachable and its inbox proves the record never landed. A keyed + # answer stores none: only the printed resend closes its keys, so the + # tracker leaves that record to it. + [ -n "$RESOLVE_KEYS" ] || + fm_pending_reply_store_undelivered_text "$STATE" "$PENDING_REPLY_CORR" "$RESOLVE_ANSWER_TEXT" || true fi if [ "$remote_rc" -eq 255 ]; then echo "error: steer to remote secondmate $TARGET_REMOTE_ID is unconfirmed (transport lost twice; remote completion unknown). Only the correlation-reusing resend below is idempotent and lands on the same remote inbox record:" >&2 diff --git a/bin/fm-task-inbox-lib.sh b/bin/fm-task-inbox-lib.sh index 7d4368bce1f..204b6d6fb7a 100644 --- a/bin/fm-task-inbox-lib.sh +++ b/bin/fm-task-inbox-lib.sh @@ -33,6 +33,10 @@ # so later polls suppress another escalation # .inbox/.retry-ring name of a fire-and-forget record still owed its # one retry ring (fm_task_inbox_mark_retry) +# .inbox/.ring-log bounded diagnostic log of every ring decision: +# "\t\t\t", decision one +# of rang, unconfirmed, skipped:other-text, +# skipped:busy, failed, dead (fm_task_inbox_ring) # # Record format (fm_task_inbox_write / fm_task_inbox_body): # schema=fm-task-inbox.v1 @@ -80,7 +84,8 @@ # without this retry the record could sit unread until a checkpoint. A pending ordinary record's # ladder rings the same inbox, so the retry waits behind it, and an # acknowledged record drops its mark. The remote steer leg has no watcher -# ladder and owes no retry. +# ladder and owes no retry; there the receiving mate's own watcher wakes its +# session for any unhandled record instead (bin/fm-watch.sh parent_inbox_tick). # # Inbox names containing bytes outside printable ASCII are unsupported. The # doorbell refuses them rather than sending terminal control bytes to a pane. @@ -115,6 +120,13 @@ fm_task_inbox_grace_secs() { printf '%s' "$g" } +# The watcher poll interval the ladder runs at (bin/fm-watch.sh FM_POLL). +fm_task_inbox_poll_secs() { + local p=${FM_POLL:-15} + case "$p" in ''|*[!0-9]*|0) p=15 ;; esac + printf '%s' "$p" +} + fm_task_inbox_ring_max() { local m=${FM_TASK_INBOX_RING_MAX:-$FM_TASK_INBOX_RING_MAX_DEFAULT} case "$m" in ''|*[!0-9]*) m=$FM_TASK_INBOX_RING_MAX_DEFAULT ;; esac @@ -386,24 +398,44 @@ fm_task_inbox_doorbell_line() { # # whose Enter never landed, so on an agent not reported busy it is submitted # rather than skipped; skipping it would block every later ring. On both paths # a lost first Enter gets one confirmed retry. +# Every decision is appended to the inbox's .ring-log (see the header), because +# no caller records why a ring was skipped and a stuck doorbell is otherwise +# undiagnosable after the fact; the log never changes the return value. fm_task_inbox_ring() { # [expected-label] - local backend=$1 target=$2 rec=$3 label=${4:-} line cstate verdict - case "$(fm_backend_agent_state "$backend" "$target" 2>/dev/null || true)" in - dead|missing) return 3 ;; + local backend=$1 target=$2 rec=$3 label=${4:-} line cstate verdict astate + astate=$(fm_backend_agent_state "$backend" "$target" 2>/dev/null || true) + case "$astate" in + dead|missing) _fm_task_inbox_ring_log "$rec" dead "agent=$astate"; return 3 ;; esac if ! line=$(fm_task_inbox_doorbell_line "$rec"); then + _fm_task_inbox_ring_log "$rec" failed "doorbell-line-refused" return 2 fi cstate=$(fm_backend_composer_state "$backend" "$target" "$label" 2>/dev/null) || cstate=unknown case "$cstate" in pending) - fm_task_inbox_composer_holds "$backend" "$target" "$line" "$label" \ - && [ "$(fm_backend_busy_state "$backend" "$target" 2>/dev/null)" != busy ] \ - || return 1 - fm_backend_send_key "$backend" "$target" Enter "$label" >/dev/null 2>&1 || return 2 + if ! fm_task_inbox_composer_holds "$backend" "$target" "$line" "$rec" "$label"; then + _fm_task_inbox_ring_log "$rec" skipped:other-text "composer=pending" + return 1 + fi + if [ "$(fm_backend_busy_state "$backend" "$target" 2>/dev/null)" = busy ]; then + _fm_task_inbox_ring_log "$rec" skipped:busy "composer=own-doorbell" + return 1 + fi + if ! fm_backend_send_key "$backend" "$target" Enter "$label" >/dev/null 2>&1; then + _fm_task_inbox_ring_log "$rec" failed "composer=own-doorbell enter" + return 2 + fi sleep 0.3 - fm_task_inbox_composer_holds "$backend" "$target" "$line" "$label" || return 0 - fm_backend_send_key "$backend" "$target" Enter "$label" >/dev/null 2>&1 || return 2 + if ! fm_task_inbox_composer_holds "$backend" "$target" "$line" "$rec" "$label"; then + _fm_task_inbox_ring_log "$rec" rang "composer=own-doorbell submitted" + return 0 + fi + if ! fm_backend_send_key "$backend" "$target" Enter "$label" >/dev/null 2>&1; then + _fm_task_inbox_ring_log "$rec" failed "composer=own-doorbell second-enter" + return 2 + fi + _fm_task_inbox_ring_log "$rec" unconfirmed "composer=own-doorbell second-enter" return 0 ;; esac @@ -412,19 +444,94 @@ fm_task_inbox_ring() { # [expected-label] # shell only a suffix; the `: ` prefix protects complete lines only. Do not # add process-bound atomic delivery here unless an incident reopens this. if ! verdict=$(fm_backend_send_text_submit "$backend" "$target" "$line" 2 0.4 0.3 "$label" 2>/dev/null); then + _fm_task_inbox_ring_log "$rec" failed "composer=$cstate submit" return 2 fi # The verdict is read only to report a failed keystroke; every other value # (empty, pending, unknown, ...) is deliberately ignored, never proof. - [ "$verdict" != send-failed ] || return 2 + if [ "$verdict" = send-failed ]; then + _fm_task_inbox_ring_log "$rec" failed "composer=$cstate verdict=send-failed" + return 2 + fi + if [ "$verdict" = empty ]; then + _fm_task_inbox_ring_log "$rec" rang "composer=$cstate verdict=empty" + else + _fm_task_inbox_ring_log "$rec" unconfirmed "composer=$cstate verdict=${verdict:-none}" + fi + return 0 +} + +# Append one ring decision to the inbox's .ring-log, best-effort and bounded +# (trimmed to its newest 200 lines past 64 KiB). Never fails its caller. +_fm_task_inbox_ring_log() { # [detail] + local dir=${1%/*} log sz + dir=${dir%/handled} + [ -d "$dir" ] || return 0 + log="$dir/.ring-log" + printf '%s\t%s\t%s\t%s\n' "$(date -u +%Y-%m-%dT%H:%M:%SZ)" "${1##*/}" "$2" "${3:-}" \ + >> "$log" 2>/dev/null || return 0 + sz=$(wc -c < "$log" 2>/dev/null | tr -d '[:space:]') + case "$sz" in ''|*[!0-9]*) return 0 ;; esac + if [ "$sz" -ge 65536 ]; then + tail -n 200 "$log" > "$log.tmp.$$" 2>/dev/null && mv -f "$log.tmp.$$" "$log" 2>/dev/null + rm -f "$log.tmp.$$" 2>/dev/null + fi return 0 } -# Whether the composer's content, ignoring line wrapping, is exactly . -fm_task_inbox_composer_holds() { # [expected-label] +# Whether a Herdr composer read is our own doorbell for +# : equal to it ignoring whitespace and wrapping, or the shape +# Claude leaves when it collapses the burst typed by the Herdr typing path - one +# bare `[Pasted text #N]` placeholder, optionally followed by a literal tail that +# is the end of . A placeholder hides its content, so an operator's paste +# has the same shape: it is recognised only while the inbox's .ring-log already +# shows a recent earlier ring of this record that typed the doorbell (rang or +# unconfirmed). A `+M lines` placeholder or several placeholders are an +# operator's paste, not a single-line doorbell, and are never recognised. +_fm_task_inbox_herdr_holds_doorbell() { # + local line=$1 held=$2 rec=$3 rest dir now window cutoff + fm_composer_normalize_spaces_var line + fm_composer_normalize_spaces_var held + line=${line//[$' \t\r\n\v\f']/} + line=${line//$'\xE2\x81\xA3'/} + held=${held//[$' \t\r\n\v\f']/} + held=${held//$'\xE2\x81\xA3'/} + [ -n "$line" ] && [ -n "$held" ] || return 1 + [ "$held" = "$line" ] && return 0 + [[ $held =~ ^\[Pastedtext#[0-9]+\](.*)$ ]] || return 1 + rest=${BASH_REMATCH[1]} + case "$rest" in *'[Pastedtext#'*) return 1 ;; esac + [ -z "$rest" ] || [[ $line == *"$rest" ]] || return 1 + dir=${rec%/*} + dir=${dir%/handled} + # Recent means within one re-ring spacing (the inbox grace) plus three watcher + # passes (FM_POLL, default 15 s): the next re-ring of a doorbell whose Enter + # was lost falls inside it, an operator paste long after the last ring does + # not. The log's UTC stamps sort as text. + now=$(date +%s) + window=$(( $(fm_task_inbox_grace_secs) + 3 * $(fm_task_inbox_poll_secs) )) + cutoff=$(date -u -r "$((now - window))" +%Y-%m-%dT%H:%M:%SZ 2>/dev/null \ + || date -u -d "@$((now - window))" +%Y-%m-%dT%H:%M:%SZ 2>/dev/null) || return 1 + awk -F '\t' -v msg="${rec##*/}" -v cutoff="$cutoff" ' + $2 == msg && ($3 == "rang" || $3 == "unconfirmed") && $1 >= cutoff { found = 1; exit } + END { exit(found ? 0 : 1) } + ' "$dir/.ring-log" 2>/dev/null +} + +# Whether the composer's content is exactly , ignoring line wrapping. +# Herdr reads its composer with the same visible-viewport reader its typing +# path uses (fm_backend_herdr_composer_content), so a doorbell that path typed +# - wrapped, or collapsed into a placeholder - is recognised as our own rather +# than skipped as someone else's draft. Other backends compare a plain capture. +fm_task_inbox_composer_holds() { # [expected-label] local cap held fm_backend_source "$1" || return 1 - cap=$(fm_backend_capture "$1" "$2" "$FM_COMPOSER_CAPTURE_LINES" "${4:-}" 2>/dev/null) || return 1 + if [ "$1" = herdr ]; then + held=$(fm_backend_herdr_composer_content "$2" 2>/dev/null) || return 1 + _fm_task_inbox_herdr_holds_doorbell "$3" "$held" "$4" + return + fi + cap=$(fm_backend_capture "$1" "$2" "$FM_COMPOSER_CAPTURE_LINES" "${5:-}" 2>/dev/null) || return 1 held=$(fm_composer_extract_selected_content styled=0 "$cap") || return 1 [ -n "$held" ] && [ "$(printf '%s' "$held" | tr -d '[:space:]')" = "$(printf '%s' "$3" | tr -d '[:space:]')" ] } @@ -442,6 +549,27 @@ fm_task_inbox_is_fire_and_forget() { # ' "$rec" } +# Every unhandled record, ordinary and fire-and-forget alike: prints +# " " with the oldest chosen by +# sequence, or fails when the inbox holds none. The receiving side's own +# watcher (bin/fm-watch.sh parent_inbox_tick) and the parent's reply tracker +# (bin/fm-pending-reply-lib.sh, through the remote inbox-status leg) read it. +fm_task_inbox_unhandled_summary() { # + local dir best='' best_n=0 count=0 f n + dir=$(fm_task_inbox_dir "$1" "$2") + for f in "$dir"/*.msg; do + [ -e "$f" ] || continue + n=$(fm_task_inbox_seq_of "${f##*/}") || continue + count=$((count + 1)) + if [ -z "$best" ] || [ "$n" -lt "$best_n" ]; then + best=$f + best_n=$n + fi + done + [ -n "$best" ] || return 1 + printf '%s %s %s' "$count" "${best##*/}" "$(fm_path_age "$best")" +} + # Oldest escalation-tracked unhandled record, or fail when none is due. fm_task_inbox_oldest_unhandled() { # local dir best='' best_n=0 f n diff --git a/bin/fm-teardown.sh b/bin/fm-teardown.sh index 98ad53fadb2..6e843d03ef3 100755 --- a/bin/fm-teardown.sh +++ b/bin/fm-teardown.sh @@ -1090,8 +1090,8 @@ remote_recovery_paths_validate() { } # Remove every parent pending-reply record for $ID, plus its delivery -# confirmation when present. Shared by local and remote secondmate retirement -# after the home/route is safely gone. +# confirmation and saved undelivered text when present. Shared by local and +# remote secondmate retirement after the home/route is safely gone. pending_replies_cleanup_for_task() { local pending_dir=$1 expected_real=${2-} rec base corr task_id [ -d "$pending_dir" ] || return 0 @@ -1109,7 +1109,7 @@ pending_replies_cleanup_for_task() { printf '%s' "$base" | grep -Eq '^[a-f0-9]{16}$' || exit 1 corr=$(fm_meta_get "$rec" corr_id) [ -z "$corr" ] || [ "$corr" = "$base" ] || exit 1 - rm -f -- "./.delivery-confirmed-$base" "$rec" || exit 1 + rm -f -- "./.delivery-confirmed-$base" "./.undelivered-text-$base" "$rec" || exit 1 done ) } diff --git a/bin/fm-test-run.sh b/bin/fm-test-run.sh index a6803f46015..5ec0e719809 100755 --- a/bin/fm-test-run.sh +++ b/bin/fm-test-run.sh @@ -839,7 +839,7 @@ tests/fm-on.test.sh 11473 tests/fm-opencode-primary-live-e2e.test.sh 47 tests/fm-operational-input.test.sh 2404 tests/fm-peek-remote.test.sh 1082 -tests/fm-pending-reply.test.sh 41090 +tests/fm-pending-reply.test.sh 46200 tests/fm-pi-branch-extension.test.sh 77218 tests/fm-pi-branch-live-e2e.test.sh 48 tests/fm-pi-branch-responsiveness-live-e2e.test.sh 12834 @@ -889,7 +889,7 @@ tests/fm-secondmate-sync.test.sh 55501 tests/fm-send-agy-confirm.test.sh 4440 tests/fm-send-inbox-doorbell-live-e2e.test.sh 108 tests/fm-send-inbox.test.sh 41713 -tests/fm-send-remote-delivery.test.sh 31964 +tests/fm-send-remote-delivery.test.sh 66000 tests/fm-send-resolve-key.test.sh 47317 tests/fm-send-secondmate-marker-herdr-e2e.test.sh 80 tests/fm-send-secondmate-marker.test.sh 7574 @@ -919,7 +919,7 @@ tests/fm-supervision-host-park.test.sh 329326 tests/fm-supervision-host.test.sh 435581 tests/fm-tangle-guard.test.sh 8501 tests/fm-task-delivery.test.sh 32789 -tests/fm-task-inbox.test.sh 31965 +tests/fm-task-inbox.test.sh 35000 tests/fm-tasks-axi.test.sh 2293 tests/fm-teardown-endpoint-safety.test.sh 40851 tests/fm-teardown.test.sh 202132 diff --git a/bin/fm-watch.sh b/bin/fm-watch.sh index cc2d643358c..5f3aa0fedbc 100755 --- a/bin/fm-watch.sh +++ b/bin/fm-watch.sh @@ -169,6 +169,13 @@ # inbox and a fresh child beacon are not idle proof; # the foreign queue itself stays read-only, and one # parent notification covers each no-progress episode +# check: parent instruction waiting: unhandled in , oldest s; ... +# this home is a secondmate and its own steering inbox +# from its parent (state/parent-route/.inbox, or a +# local mate's $FM_TASK_INBOX) holds a record older than +# FM_TASK_INBOX_GRACE_SECS; queued once per oldest record +# so a parked mate session wakes and reads it without +# depending on a typed doorbell (parent_inbox_tick) # check: secondmate auto-relaunched after () # the liveness tick probed a registered secondmate's # recorded endpoint, got the recovery-grade `dead` or @@ -1115,6 +1122,50 @@ EOF return 0 } +# A secondmate's own watcher is a wake source for the steering inbox its parent +# writes: a parked mate session wakes on that queued check exactly as it does +# for a child event, so reading a parent instruction never depends on composer +# typing (a doorbell whose Enter never lands leaves an idle mate deaf, and the +# remote host runs no re-ring ladder). The inbox is the remote placement's +# state/parent-route/.inbox in this home, else a local mate's own +# $FM_TASK_INBOX when it names this home's id. Every unhandled record counts, +# fire-and-forget included, once the oldest is past the inbox grace; one wake +# per oldest record (.parent-inbox-woken), queued before that marker is written +# so a crash can only duplicate a wake, never lose one. The inbox itself stays +# read-only here: reading and acknowledging records is the woken session's job. +parent_inbox_tick() { + local id inbox_state summary count oldest age woken_marker="$STATE/.parent-inbox-woken" + local key reason queued + [ -f "$FM_HOME/.fm-secondmate-home" ] && [ ! -L "$FM_HOME/.fm-secondmate-home" ] || return 0 + id=$(cat "$FM_HOME/.fm-secondmate-home" 2>/dev/null || true) + case "$id" in ''|*[!A-Za-z0-9._-]*) return 0 ;; esac + inbox_state="$STATE/parent-route" + if [ ! -d "$(fm_task_inbox_dir "$inbox_state" "$id")" ]; then + case "${FM_TASK_INBOX:-}" in + /*/"$id.inbox") [ -d "$FM_TASK_INBOX" ] || return 0; inbox_state=${FM_TASK_INBOX%/*} ;; + *) return 0 ;; + esac + fi + if ! summary=$(fm_task_inbox_unhandled_summary "$inbox_state" "$id"); then + rm -f "$woken_marker" 2>/dev/null || true + return 0 + fi + read -r count oldest age </dev/null || true)" != "$oldest" ] || return 0 + key="parent-inbox-$id-${oldest%.msg}" + reason="check: parent instruction waiting: $count unhandled in $(fm_task_inbox_dir "$inbox_state" "$id"), oldest ${age}s; read and act on each in numeric order, then mv each into its handled/" + queued=$(fm_wake_queued_keys check) + if ! printf '%s\n' "$queued" | grep -Fx "$key" >/dev/null 2>&1; then + fm_wake_append check "$key" "$reason" || return 1 + fi + printf '%s\n' "$oldest" > "$woken_marker" || return 1 + wake "$reason" +} + # The ordinary-supervision half of the secondmate liveness guarantee, paired # with bin/fm-bootstrap.sh's session-start sweep over the shared library in # bin/fm-secondmate-liveness-lib.sh (which owns the state contract, the remote @@ -3731,6 +3782,12 @@ while :; do exit 1 } + # A secondmate home wakes its own session for an unread parent instruction. + parent_inbox_tick || { + echo "watcher: parent-route inbox wake could not be recorded" >&2 + exit 1 + } + # Process-to-event liveness repair. This never discovers a result by polling: # each registered source has its own child blocking on that source, and this # only republishes results already captured durably and restarts a source diff --git a/docs/configuration.md b/docs/configuration.md index abb1e41c445..11724df25d8 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -3223,7 +3223,7 @@ FM_HEARTBEAT_MAX=7200 # heartbeat backoff cap FM_INACTIVE_RECONCILE_SECS=900 # 60..1800-second watcher cadence and inactivity threshold; locked session start also requests an immediate scan in the deferred worker FM_INACTIVE_RECONCILE_BUDGET_SECS=10 # 1..30-second scan deadline; wedged-scan kill backstop follows one second later FM_CHECK_INTERVAL=300 # seconds between slow checks (authenticated merge polls, custom checks, or Relay dispatch) -FM_TASK_INBOX_GRACE_SECS=90 # seconds an unhandled steering-inbox message may sit before the watcher attempts doorbell delivery on an idle endpoint; also the minimum spacing between attempts +FM_TASK_INBOX_GRACE_SECS=90 # seconds an unhandled steering-inbox message may sit before the watcher attempts doorbell delivery on an idle endpoint; also the minimum spacing between attempts, and the age a secondmate's own parent-route inbox record must pass before its watcher queues the one `check: parent instruction waiting` wake FM_TASK_INBOX_RING_MAX=3 # watcher delivery attempts without an acknowledgement before the task surfaces as a stale wake for recovery FM_TASK_INBOX_BUSY_MAX=2 # consecutive busy-deferred due polls before a stuck-busy stale wake; 1..999999999, at most 9 decimal digits, otherwise 2; policy: bin/fm-task-inbox-lib.sh FM_CHECK_TIMEOUT=30 # seconds allowed per slow check script @@ -3335,6 +3335,11 @@ FM_SEND_RETRIES=3 # fm-send typed-plane Enter-retry attempts after typing FM_SEND_SLEEP=0.4 # seconds between fm-send typed-plane submit checks FM_SEND_SETTLE=1 # seconds fm-send waits after a successful typed-plane submit; 0 disables FM_PENDING_REPLY_GRACE_SECS=120 # seconds after the request turn completes without a correlated parent report before its one recovery repost is eligible, and after the recovery turn completes before the missed-report escalation is eligible; never counted from delivery +FM_PENDING_REPLY_UNREAD_SECS=300 # seconds after delivery (or the recovery send) a remote request may sit unhandled in the mate's inbox before it escalates once as pending-reply-unread +FM_PENDING_REPLY_DELIVERY_RECHECK_SECS=600 # minimum spacing between inbox checks of one delivery-unknown remote record, which is marked delivered when it landed or resent once when it did not +FM_PENDING_REPLY_DELIVERY_READ_RETRY_SECS=60 # spacing between inbox reads of one delivery-unknown remote record after a read that failed (host down, or no inbox-status leg); a read that answers clears it +FM_PENDING_REPLY_INBOX_READ_BUDGET=30 # hard bound in seconds on one remote inbox-status ssh round trip made by the reply tracker, so a silent host cannot hold the watcher +FM_PENDING_REPLY_RESEND_MAX_AGE_SECS=7200 # oldest delivery-unknown request that one automatic same-correlation resend may repeat; older records stay open # sub-supervisor (bin/fm-supervise-daemon.sh); presence-gated via /afk FM_SUPERVISOR_BACKEND= # optional supervisor endpoint backend override; see "Away-mode supervisor backend" for supported backends and detection FM_SUPERVISOR_TARGET= # optional supervisor endpoint target override; tmux uses the exact forms owned by fm_backend_target_exists in bin/fm-backend.sh, herdr uses :, t3code uses the thread id, otherwise auto-detected diff --git a/docs/remote-secondmates.md b/docs/remote-secondmates.md index 1fd485e6a6a..3b50c3efafc 100644 --- a/docs/remote-secondmates.md +++ b/docs/remote-secondmates.md @@ -494,13 +494,17 @@ If delivery remains unconfirmed, only the exact `FM_PENDING_REPLY_EXISTING_CORR= That command preserves the request body and lets the remote enqueue deduplicate onto the same record. A plain rerun mints a different correlation and is not idempotent. When deduplication finds that the worker already moved the matching record into `handled/`, the resend exits successfully without ringing the doorbell again. +Once the mate is reachable again, the parent's reply tracker checks the remote inbox for an unconfirmed request itself: a record that landed is marked delivered, and a recent one that never landed is resent once under the same correlation. +An unconfirmed `--resolve-key` answer is left to its printed resend command, which is what closes the answered keys. +The [`fm-pending-reply-lib.sh` header](../bin/fm-pending-reply-lib.sh) owns that reconciliation and its age bound. ### Swallowed doorbells The remote host runs no doorbell re-ring ladder of its own. -A swallowed doorbell for an ordinary reply-bearing request surfaces through the parent's pending-reply recovery and escalation. -Its recovery request rings the doorbell again when it is enqueued. -A fire-and-forget record, such as a reconcile ask, gets its single retry ring only on the local plane, and only when `config/wait-no-turns` is present: the remote steer leg owes no re-ring, so a swallowed remote doorbell for one waits for the next ring into that inbox, and a remote-side retry is known follow-up scope. +Instead the mate's own watcher wakes its session for any record that sits unhandled in its parent-route inbox past the inbox grace, so a parked mate reads the instruction even when its doorbell's Enter never landed. +A still-unread ordinary reply-bearing request also surfaces at the parent: its reply tracker reads the remote inbox through `fm-remote-secondmate-control.sh inbox-status`, never counts a quiet mate as having taken a turn while the request is unread, and escalates it once as unread with the composer verdict and the `fm-peek` then `--key Enter` remedy. +Each ring decision, on every leg, is appended to the inbox's `.ring-log`, so a skipped or unconfirmed doorbell can be diagnosed afterwards. +A fire-and-forget record, such as a reconcile ask, gets its single retry ring only on the local plane, and only when `config/wait-no-turns` is present; on the remote host the mate's own watcher wake covers it. ### Remote reads diff --git a/tests/fm-pending-reply.test.sh b/tests/fm-pending-reply.test.sh index 3e513f0785b..a9a9282df02 100755 --- a/tests/fm-pending-reply.test.sh +++ b/tests/fm-pending-reply.test.sh @@ -38,6 +38,10 @@ # the decision; a retry while that decision is still open appends nothing # 19. A request summary keeps accented letters, drops control characters, and # caps at 120 characters without splitting one under any caller locale +# 20. The inbox-status format reports the unhandled count, the oldest age, the +# composer verdict and an unhandled, handled or absent correlation state +# 21. A local mate's unread request raises no tracker escalation (the remote +# reconciliation scenarios live in tests/fm-send-remote-delivery.test.sh) set -u # shellcheck source=tests/lib.sh @@ -2123,6 +2127,110 @@ test_summary_keeps_accents_and_caps_by_character() { pass "the summary keeps accented letters, drops control characters, and caps by character" } +# Write one record into 's steering inbox for through the +# production owner (bin/fm-task-inbox-lib.sh). +inbox_write() { # + FM_STATE_OVERRIDE="$1" bash -c '. "$1"; fm_task_inbox_write "$2" "$3" "$4"' \ + _ "$ROOT/bin/fm-task-inbox-lib.sh" "$1" "$2" "$3" >/dev/null +} + +# The inbox-status format and the correlation states the reply tracker reads. +test_inbox_status_reports_unhandled_handled_and_absent() { + local home state inbox out corr_a corr_b corr_c + home=$(setup_parent inbox-status) + state="$home/state" + inbox="$state/t1.inbox" + corr_a=aaaaaaaaaaaaaaaa; corr_b=bbbbbbbbbbbbbbbb; corr_c=cccccccccccccccc + + [ "$(fm_pending_reply_inbox_corr_state "$inbox" "$corr_a")" = absent ] \ + || fail "an inbox that does not exist holds no record" + out=$(fm_pending_reply_inbox_status_report "$state" t1 "$corr_a") + [ "$(printf '%s\n' "$out" | head -1)" = "schema=fm-inbox-status.v1" ] \ + || fail "the status must lead with its schema line: $out" + assert_contains "$out" "unhandled=0" "an absent inbox has no unhandled records" + assert_contains "$out" "corr_state=absent" "an absent inbox does not hold the correlation" + assert_contains "$out" "composer=unknown" "the composer verdict defaults to unknown" + + inbox_write "$state" t1 "[fm] corr=$corr_a first" + inbox_write "$state" t1 "[fm] corr=$corr_b second" + mv "$inbox/002.msg" "$inbox/handled/002.msg" + [ "$(fm_pending_reply_inbox_corr_state "$inbox" "$corr_a")" = unhandled ] \ + || fail "a waiting record must read unhandled" + [ "$(fm_pending_reply_inbox_corr_state "$inbox" "$corr_b")" = handled ] \ + || fail "an acknowledged record must read handled" + [ "$(fm_pending_reply_inbox_corr_state "$inbox" "$corr_c")" = absent ] \ + || fail "a correlation never written must read absent" + + # A recovery repost carries the same token: unhandled wins over handled. + inbox_write "$state" t1 "[fm] corr=$corr_b repost" + [ "$(fm_pending_reply_inbox_corr_state "$inbox" "$corr_b")" = unhandled ] \ + || fail "an unhandled repost of an acknowledged request must read unhandled" + + out=$(fm_pending_reply_inbox_status_report "$state" t1 "$corr_a" busy) + assert_contains "$out" "unhandled=2" "both waiting records must be counted" + assert_contains "$out" "corr_state=unhandled" "the asked correlation state must be reported" + assert_contains "$out" "composer=busy" "the given composer verdict must be reported" + printf '%s\n' "$out" | grep -Eq '^oldest_age=[0-9]+$' \ + || fail "the oldest unhandled age must be a number of seconds: $out" + out=$(fm_pending_reply_inbox_status_report "$state" t1) + assert_not_contains "$out" "corr_state=" "no correlation asked means no correlation state" + pass "inbox status: schema, unhandled count and age, and the unhandled/handled/absent correlation states" +} + +# A local mate has no unread escalation of its own here: the parent watcher's +# re-ring ladder owns that, so the tracker must stay quiet however old it is. +test_local_unread_request_raises_no_unread_escalation() { + local home state corr rec status + home=$(setup_parent local-unread) + state="$home/state" + status="$state/t1.status" + corr=$(FM_PENDING_REPLY_NOW=20000 fm_pending_reply_create "$home" "$state" t1 "local unread") + rec=$(fm_pending_reply_path "$state" "$corr") + FM_PENDING_REPLY_NOW=20000 fm_pending_reply_mark_delivered "$state" "$corr" + inbox_write "$state" t1 "[fm] corr=$corr local unread" + + FM_PENDING_REPLY_NOW=29999 fm_pending_reply_idle_unread "$state" "$rec" \ + || fail "an idle never-busy mate with an unhandled local request is not a completed turn" + [ ! -s "$status" ] || fail "a local mate must raise no unread escalation: $(cat "$status")" + [ -z "$(fm_pending_reply_get "$rec" unread_escalated_epoch)" ] \ + || fail "a local mate must not record an unread escalation" + + mv "$state/t1.inbox/001.msg" "$state/t1.inbox/handled/001.msg" + if FM_PENDING_REPLY_NOW=29999 fm_pending_reply_idle_unread "$state" "$rec"; then + fail "a handled local request makes the idle an ordinary completed turn" + fi + pass "a local mate's unread request raises no tracker escalation and a handled one counts as a turn" +} + +# The inbox read runs unlocked, so a reply handler can settle the record while +# it is in flight. The older view must never replace the settled record. +test_undelivered_reconcile_never_reopens_a_record_settled_during_the_read() { + local home state corr rec + home=$(setup_parent reconcile-race) + state="$home/state" + corr=$(FM_PENDING_REPLY_NOW=20000 fm_pending_reply_create "$home" "$state" t1 "raced request") + rec=$(fm_pending_reply_path "$state" "$corr") + fm_pending_reply_store_undelivered_text "$state" "$corr" "raced request" + fm_pending_reply_mark_delivery_unknown "$state" "$corr" + inbox_write "$state" t1 "[fm] corr=$corr raced request" + + ( + # The reply handler settles the record while the inbox read is in flight. + fm_pending_reply_inbox_status() { + fm_pending_reply_set "$rec" phase resolved + fm_pending_reply_inbox_status_report "$@" + } + FM_PENDING_REPLY_NOW=30000 fm_pending_reply_reconcile_undelivered "$state" "$corr" + ) && fail "reconciliation reported a change to a record settled during its read" + [ "$(phase_of "$state" "$corr")" = resolved ] \ + || fail "a record settled during the inbox read was reopened as $(phase_of "$state" "$corr")" + [ -z "$(fm_pending_reply_get "$rec" delivery_checked_epoch)" ] \ + || fail "reconciliation wrote undelivered fields onto a settled record" + [ -z "$(fm_pending_reply_get "$rec" delivered_epoch)" ] \ + || fail "reconciliation marked a settled record delivered" + pass "reconciling an undelivered record never replaces one settled during the inbox read" +} + # --- run -------------------------------------------------------------------- test_normal_correlated_reply_resolves_once @@ -2174,5 +2282,8 @@ test_local_parent_replies_is_wrong_home_evidence test_escalated_undelivered_correlation_stays_retryable test_same_kind_escalation_reopens_after_operator_close test_summary_keeps_accents_and_caps_by_character +test_inbox_status_reports_unhandled_handled_and_absent +test_local_unread_request_raises_no_unread_escalation +test_undelivered_reconcile_never_reopens_a_record_settled_during_the_read printf 'ok - all pending-reply tests passed\n' diff --git a/tests/fm-secondmate-lifecycle-e2e.test.sh b/tests/fm-secondmate-lifecycle-e2e.test.sh index 0d3a00cd4ea..2a6565bb498 100755 --- a/tests/fm-secondmate-lifecycle-e2e.test.sh +++ b/tests/fm-secondmate-lifecycle-e2e.test.sh @@ -238,6 +238,13 @@ phase_teardown() { ' _ "$ROOT/bin/fm-pending-reply-lib.sh" "$HOME_DIR") \ || fail "could not seed leftover resolved pending-reply" leftover_rec="$HOME_DIR/state/pending-replies/$leftover" + FM_HOME="$HOME_DIR" bash -c ' + . "$1" + fm_pending_reply_store_undelivered_text "$2/state" "$3" "unconfirmed request body" + ' _ "$ROOT/bin/fm-pending-reply-lib.sh" "$HOME_DIR" "$leftover" \ + || fail "could not seed saved undelivered text" + assert_present "$HOME_DIR/state/pending-replies/.undelivered-text-$leftover" \ + "undelivered text seed was not saved" # Settle every parent pending-reply for this mate (earlier send/handoff # phases leave open records) so non-forced retirement mirrors a clean # captain-approved close rather than hitting the unresolved-reply refuse. @@ -327,6 +334,8 @@ phase_teardown() { assert_absent "$HOME_DIR/state/.secondmate-liveness-design.lock" \ "teardown left the liveness lock it took to retire relaunch state" assert_absent "$leftover_rec" "teardown left a resolved pending-reply for the retired secondmate" + assert_absent "$HOME_DIR/state/pending-replies/.undelivered-text-$leftover" \ + "teardown left the saved undelivered request text of the retired secondmate" assert_no_grep '- design ' "$HOME_DIR/data/secondmates.md" "teardown did not remove the registry route" # The parent's source projects are untouched (no write through a parent home). assert_present "$HOME_DIR/projects/alpha" "teardown disturbed a parent project" diff --git a/tests/fm-send-remote-delivery.test.sh b/tests/fm-send-remote-delivery.test.sh index f0c8dab0c36..2d34fbd51c4 100755 --- a/tests/fm-send-remote-delivery.test.sh +++ b/tests/fm-send-remote-delivery.test.sh @@ -29,6 +29,12 @@ # slash) keeps its exit-3 delivered-unconfirmed contract, never closes a # --resolve-key decision unconfirmed, and keeps a marked expectation # armed. +# 9. The parent's reply tracker reads the remote inbox through the real +# inbox-status leg (scenarios observed live on PR #7369): an unread +# request escalates once, a lost-reply record that landed is marked +# delivered without a resend, an unlanded record is resent once under its +# correlation with a failed read never delaying the recheck, and the +# resend's acknowledgement resolves the record. set -u # shellcheck source=tests/lib.sh @@ -132,6 +138,25 @@ while IFS= read -r -d '' a; do rargs+=("$a"); done \ < <(perl -MMIME::Base64=decode_base64 -e 'print decode_base64($ARGV[0])' "$argv_b64") cmd=${rargs[0]} rc=0 +# FM_FAKE_SSH_FAIL_SUBCMD makes one host-local leg unreachable while the rest +# of the transport answers (or fail outright with FM_FAKE_SSH_FAIL_SUBCMD_RC), and FM_FAKE_SSH_USAGE_SUBCMD makes one leg answer +# as a remote copy that does not have it. A mate that cannot take a turn has no herdr pane in +# this fixture, so its busy/idle observation is the one thing the fixture +# answers itself. +if [ -n "${FM_FAKE_SSH_FAIL_SUBCMD:-}" ] && [ "${rargs[1]:-}" = "$FM_FAKE_SSH_FAIL_SUBCMD" ]; then + exit "${FM_FAKE_SSH_FAIL_SUBCMD_RC:-255}" +fi +# A remote copy that predates a leg answers it with the script's usage text +# and exit 2, and no schema line. +if [ -n "${FM_FAKE_SSH_USAGE_SUBCMD:-}" ] && [ "${rargs[1]:-}" = "$FM_FAKE_SSH_USAGE_SUBCMD" ]; then + printf 'fm-remote-secondmate-control.sh ...\n' + exit 2 +fi +if [ -n "${FM_FAKE_SSH_OBSERVE:-}" ] && [ "${rargs[0]}" = fm-remote-secondmate-control.sh ] \ + && [ "${rargs[1]:-}" = observe ]; then + printf '%s\n' "$FM_FAKE_SSH_OBSERVE" + exit 0 +fi env FM_HOME="$remote_home" FM_ROOT_OVERRIDE="$FM_REMOTE_CODE_ROOT" \ "$FM_REMOTE_CODE_ROOT/bin/$cmd" "${rargs[@]:1}" < "$stdin_file" || rc=$? if [ "${FM_FAKE_SSH_AMBIGUOUS:-0}" = 1 ] \ @@ -818,6 +843,682 @@ test_local_pending_does_not_close_resolve_key() { pass "fm-send local: an unconfirmed submit still never closes a --resolve-key decision" } +# --- reply tracker against the remote inbox (live-evidence scenarios) -------- +# Each test below reproduces one scenario observed on a real ssh + fm-on hop +# (PR kunchenguid/firstmate#7369): the tracker reads the mate's host-local +# inbox through the real inbox-status leg and acts on what it finds. Time is +# the FM_PENDING_REPLY_NOW seam; transport faults are the fake ssh's, as in +# the tests above. + +# One tracker pass over 's pending replies at epoch . +tracker_pass() { # [extra env...] + local fb=$1 home=$2 ssh_log=$3 now=$4 + shift 4 + # The script is expanded by the inner shell, not this one. + # shellcheck disable=SC2016 + send_env "$fb" "$home" "$ssh_log" FM_PENDING_REPLY_NOW="$now" "$@" \ + bash -c '. "$1/bin/fm-pending-reply-lib.sh"; fm_pending_reply_tick "$FM_HOME/state"' _ "$ROOT" \ + >/dev/null 2>&1 +} + +# The tracker's own inbox-status read of at epoch . +tracker_inbox_status() { # + local fb=$1 home=$2 ssh_log=$3 now=$4 corr=$5 + # The script is expanded by the inner shell, not this one. + # shellcheck disable=SC2016 + send_env "$fb" "$home" "$ssh_log" FM_PENDING_REPLY_NOW="$now" \ + bash -c '. "$1/bin/fm-pending-reply-lib.sh"; fm_pending_reply_inbox_status "$FM_HOME/state" rsm "$2"' \ + _ "$ROOT" "$corr" +} + +# A request sent to the remote mate at epoch ; prints its correlation id. +send_remote_request() { # [extra env...] + local fb=$1 home=$2 ssh_log=$3 now=$4 text=$5 before rec + shift 5 + # A home can already hold earlier records, and find's order is the + # filesystem's: report the record this send created, not the first listed. + before=$(find "$home/state/pending-replies" -maxdepth 1 -type f ! -name '.*' 2>/dev/null) + send_env "$fb" "$home" "$ssh_log" FM_PENDING_REPLY_NOW="$now" "$@" \ + "$SEND" rsm "$text" >/dev/null 2>&1 || true + rec=$(find "$home/state/pending-replies" -maxdepth 1 -type f ! -name '.*' 2>/dev/null \ + | grep -vxF -e "${before:-/nonexistent}" | head -1) + fm_pending_reply_get "$rec" corr_id +} + +# Scenario 1: a delivered request the parked mate never reads. +test_remote_unread_request_escalates_once() { + local dir fb ssh_log home rhome corr rec status lines open + dir="$TMP_ROOT/remote-unread"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-unread) + home=$(setup_remote_parent_home remote-unread "$rhome") + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 10000 "please append one line") + [ -n "$corr" ] || fail "the request did not leave a pending-reply record" + rec=$(fm_pending_reply_path "$home/state" "$corr") + status="$home/state/rsm.status" + + # The mate idles without ever being seen busy and the record is still + # unhandled in its inbox: that is not a completed turn, and 299 s is under + # the unread bound. + tracker_pass "$fb" "$home" "$ssh_log" 10299 FM_FAKE_SSH_OBSERVE=idle + [ ! -s "$status" ] || fail "an unread request escalated before the unread bound: $(cat "$status")" + [ -z "$(fm_pending_reply_get "$rec" request_turn_completed_epoch)" ] \ + || fail "an idle never-busy mate with an unhandled request must not count as a completed turn" + [ "$(fm_pending_reply_get "$rec" phase)" = awaiting_report ] \ + || fail "the unread request must keep awaiting its report: $(cat "$rec")" + + tracker_pass "$fb" "$home" "$ssh_log" 10300 FM_FAKE_SSH_OBSERVE=idle + lines=$(grep -c 'pending-reply-unread' "$status" || true) + [ "$lines" = 1 ] || fail "expected exactly one pending-reply-unread escalation at the bound, got $lines: $(cat "$status")" + grep -F "blocked [key=pending-reply-$corr]" "$status" | grep -qF 'landed 5m ago, unread (1 unhandled' \ + || fail "the escalation must name the age and the unhandled count under the record's key: $(cat "$status")" + grep -F 'pending-reply-unread' "$status" | grep -qF 'remedy: fm-peek.sh rsm, then fm-send.sh rsm --key Enter' \ + || fail "the escalation must carry the fm-peek / --key Enter remedy: $(cat "$status")" + [ "$(fm_pending_reply_get "$rec" unread_escalated_epoch)" = 10300 ] \ + || fail "the unread escalation epoch was not recorded: $(cat "$rec")" + open=$(status_open_decisions "$status" | cut -f1) + [ "$open" = "pending-reply-$corr" ] || fail "the unread escalation must open its keyed decision, got '$open'" + + tracker_pass "$fb" "$home" "$ssh_log" 10900 FM_FAKE_SSH_OBSERVE=idle + lines=$(grep -c 'pending-reply-unread' "$status" || true) + [ "$lines" = 1 ] || fail "a later pass must not escalate the same unread request twice, got $lines" + [ "$(fm_pending_reply_get "$rec" phase)" = awaiting_report ] \ + || fail "an unread escalation must leave the record tracking its report: $(cat "$rec")" + pass "fm-pending-reply remote: an unread request escalates exactly once with age, count and remedy" +} + +# Scenario 1, busy at delivery: a request that lands while the mate is already +# working on other work stays unread through that whole turn, so the busy flag +# set by that turn must not make the next idle count as the request's turn. +test_remote_unread_request_delivered_to_a_busy_mate_still_escalates() { + local dir fb ssh_log home rhome corr rec status lines + dir="$TMP_ROOT/remote-unread-busy"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-unread-busy) + home=$(setup_remote_parent_home remote-unread-busy "$rhome") + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 10000 "please append one line") + rec=$(fm_pending_reply_path "$home/state" "$corr") + status="$home/state/rsm.status" + + tracker_pass "$fb" "$home" "$ssh_log" 10010 FM_FAKE_SSH_OBSERVE=busy + [ "$(fm_pending_reply_get "$rec" turn_seen_busy)" = 1 ] \ + || fail "the busy observation was not recorded: $(cat "$rec")" + tracker_pass "$fb" "$home" "$ssh_log" 10400 FM_FAKE_SSH_OBSERVE=busy + + tracker_pass "$fb" "$home" "$ssh_log" 10500 FM_FAKE_SSH_OBSERVE=idle + [ -z "$(fm_pending_reply_get "$rec" request_turn_completed_epoch)" ] \ + || fail "an idle after a busy turn must not complete a request still unhandled in the inbox: $(cat "$rec")" + lines=$(grep -c 'pending-reply-unread' "$status" || true) + [ "$lines" = 1 ] || fail "expected one pending-reply-unread escalation past the bound, got $lines: $(cat "$status" 2>/dev/null)" + + mv "$rhome/state/parent-route/rsm.inbox"/*.msg "$rhome/state/parent-route/rsm.inbox/handled/" + tracker_pass "$fb" "$home" "$ssh_log" 10600 FM_FAKE_SSH_OBSERVE=idle + [ -n "$(fm_pending_reply_get "$rec" request_turn_completed_epoch)" ] \ + || fail "once the request is handled an idle mate is a completed turn: $(cat "$rec")" + pass "fm-pending-reply remote: a request delivered to a busy mate that stays unread still escalates" +} + +# Scenario 1, other half: once the mate has handled the request the same idle +# observation is an ordinary completed turn. +test_remote_handled_request_idle_counts_as_a_completed_turn() { + local dir fb ssh_log home rhome corr rec status + dir="$TMP_ROOT/remote-unread-handled"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-unread-handled) + home=$(setup_remote_parent_home remote-unread-handled "$rhome") + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 10000 "please append one line") + rec=$(fm_pending_reply_path "$home/state" "$corr") + status="$home/state/rsm.status" + + mv "$rhome/state/parent-route/rsm.inbox"/*.msg "$rhome/state/parent-route/rsm.inbox/handled/" + tracker_pass "$fb" "$home" "$ssh_log" 10400 FM_FAKE_SSH_OBSERVE=idle + [ ! -s "$status" ] || fail "a handled request must never be reported unread: $(cat "$status")" + [ -n "$(fm_pending_reply_get "$rec" request_turn_completed_epoch)" ] \ + || fail "once the request is handled an idle mate is a completed turn: $(cat "$rec")" + pass "fm-pending-reply remote: a handled request's idle observation is a completed turn" +} + +# An inbox that cannot be read changes nothing: the idle observation counts +# exactly as it did before the tracker consulted the inbox. +test_remote_unreadable_inbox_leaves_the_idle_counting_as_before() { + local dir fb ssh_log home rhome corr rec status + dir="$TMP_ROOT/remote-unread-unreadable"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-unread-unreadable) + home=$(setup_remote_parent_home remote-unread-unreadable "$rhome") + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 10000 "please append one line") + rec=$(fm_pending_reply_path "$home/state" "$corr") + status="$home/state/rsm.status" + + tracker_pass "$fb" "$home" "$ssh_log" 10400 FM_FAKE_SSH_OBSERVE=idle FM_FAKE_SSH_FAIL_SUBCMD=inbox-status + [ ! -s "$status" ] || fail "an unreadable inbox must not escalate anything: $(cat "$status")" + [ -z "$(fm_pending_reply_get "$rec" unread_escalated_epoch)" ] \ + || fail "an unreadable inbox must not record an unread escalation" + [ -n "$(fm_pending_reply_get "$rec" request_turn_completed_epoch)" ] \ + || fail "with the inbox unreadable the idle must count as a completed turn, as before: $(cat "$rec")" + pass "fm-pending-reply remote: an unreadable inbox changes nothing about how an idle counts" +} + +# Scenario 2: the reply to the send was lost but the record landed. +test_remote_lost_reply_reconciles_as_landed() { + local dir fb ssh_log home rhome corr rec status count + dir="$TMP_ROOT/remote-reconcile-landed"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-reconcile-landed) + home=$(setup_remote_parent_home remote-reconcile-landed "$rhome") + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 11000 "please append one line" FM_FAKE_SSH_AMBIGUOUS=1) + rec=$(fm_pending_reply_path "$home/state" "$corr") + status="$home/state/rsm.status" + [ "$(fm_pending_reply_get "$rec" phase)" = delivery_unknown ] \ + || fail "a send whose reply was lost twice must be delivery_unknown: $(cat "$rec")" + [ -f "$(fm_pending_reply_undelivered_text_path "$home/state" "$corr")" ] \ + || fail "an unconfirmed remote send must keep its request text for the one resend" + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 1 ] \ + || fail "both attempts must have landed on one remote record" + + tracker_pass "$fb" "$home" "$ssh_log" 11016 + [ "$(fm_pending_reply_get "$rec" delivered_epoch)" = 11016 ] \ + || fail "a record found in the remote inbox must be marked delivered: $(cat "$rec")" + [ "$(fm_pending_reply_get "$rec" delivery_reconcile)" = landed ] \ + || fail "the reconciliation must be recorded as landed: $(cat "$rec")" + [ "$(fm_pending_reply_get "$rec" phase)" = awaiting_report ] \ + || fail "a landed request must await its report: $(cat "$rec")" + [ ! -e "$(fm_pending_reply_undelivered_text_path "$home/state" "$corr")" ] \ + || fail "a landed request must drop its stored text" + count=$(remote_inbox_records "$rhome" | grep -c . || true) + [ "$count" = 1 ] || fail "a landed request must never be resent, found $count remote records" + if [ -s "$status" ]; then + fail "no escalation was open, so reconciliation must write nothing: $(cat "$status")" + fi + pass "fm-pending-reply remote: a record that landed behind a lost reply is marked delivered without a resend" +} + +# Scenario 2 with the delivery-unknown decision already open: landing closes it. +test_remote_landed_reconciliation_closes_the_delivery_unknown_decision() { + local dir fb ssh_log home rhome corr rec status open + dir="$TMP_ROOT/remote-reconcile-closes"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-reconcile-closes) + home=$(setup_remote_parent_home remote-reconcile-closes "$rhome") + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 11000 "please append one line" FM_FAKE_SSH_AMBIGUOUS=1) + rec=$(fm_pending_reply_path "$home/state" "$corr") + status="$home/state/rsm.status" + + # While the host is down the tracker cannot read the inbox, so the unknown + # delivery is escalated as a durable keyed decision. + tracker_pass "$fb" "$home" "$ssh_log" 11010 FM_FAKE_SSH_RC=255 + [ "$(fm_pending_reply_get "$rec" phase)" = escalated ] \ + || fail "an unknown delivery with an unreadable inbox must escalate: $(cat "$rec")" + open=$(status_open_decisions "$status" | cut -f1) + [ "$open" = "pending-reply-$corr" ] || fail "the delivery-unknown decision must be open, got '$open'" + + tracker_pass "$fb" "$home" "$ssh_log" 11070 + [ "$(fm_pending_reply_get "$rec" delivery_reconcile)" = landed ] \ + || fail "the reachable host must reconcile the record as landed: $(cat "$rec")" + [ -z "$(status_open_decisions "$status")" ] \ + || fail "landing must close the delivery-unknown decision: $(status_open_decisions "$status")" + grep -F "resolved [key=pending-reply-$corr]" "$status" | grep -qF 'via=delivery-reconciled landed' \ + || fail "the close must say it was a delivery reconciliation: $(cat "$status")" + [ "$(fm_pending_reply_get "$rec" phase)" = awaiting_report ] \ + || fail "a landed request must go back to awaiting its report: $(cat "$rec")" + pass "fm-pending-reply remote: landing closes an open delivery-unknown decision with via=delivery-reconciled" +} + +# Scenario 3 and finding 2: nothing landed because the host was down. +test_remote_unlanded_record_is_resent_once_and_recheck_is_not_delayed_by_a_failed_read() { + local dir fb ssh_log home rhome corr rec status count resend_epoch + dir="$TMP_ROOT/remote-resend"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-resend) + home=$(setup_remote_parent_home remote-resend "$rhome") + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 12000 "please append one line" FM_FAKE_SSH_RC=255) + rec=$(fm_pending_reply_path "$home/state" "$corr") + status="$home/state/rsm.status" + [ "$(fm_pending_reply_get "$rec" phase)" = delivery_unknown ] \ + || fail "a send refused twice must be delivery_unknown: $(cat "$rec")" + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 0 ] \ + || fail "nothing may have landed while the host was down" + + # First check, host still down: the read fails, the decision is escalated, + # and the failed read must not start the recheck spacing. + tracker_pass "$fb" "$home" "$ssh_log" 12040 FM_FAKE_SSH_RC=255 + [ "$(fm_pending_reply_get "$rec" phase)" = escalated ] \ + || fail "an unreadable inbox must leave the delivery-unknown escalation: $(cat "$rec")" + [ -z "$(fm_pending_reply_get "$rec" delivery_checked_epoch)" ] \ + || fail "a failed inbox read must not count as a check: $(cat "$rec")" + [ "$(fm_pending_reply_get "$rec" delivery_read_failed_epoch)" = 12040 ] \ + || fail "a failed inbox read must be recorded for the short backoff: $(cat "$rec")" + [ "$(grep -c 'pending-reply-delivery-unknown' "$status" || true)" = 1 ] \ + || fail "expected one delivery-unknown escalation: $(cat "$status")" + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 0 ] \ + || fail "an unreadable inbox must not trigger a resend" + + # The host is back and the short read-retry spacing (60 s) has passed - far + # inside the 600 s recheck spacing: the next pass reads the inbox, finds the + # record absent, and resends it once under the same correlation. + tracker_pass "$fb" "$home" "$ssh_log" 12100 + count=$(remote_inbox_records "$rhome" | grep -c . || true) + [ "$count" = 1 ] || fail "the reachable host must receive exactly one resend, found $count records" + grep -qF "corr=$corr" "$(remote_inbox_records "$rhome" | head -1)" \ + || fail "the resend must reuse the original correlation" + [ "$(fm_pending_reply_get "$rec" delivery_reconcile)" = resent ] \ + || fail "the reconciliation must be recorded as resent: $(cat "$rec")" + resend_epoch=$(fm_pending_reply_get "$rec" delivery_resend_epoch) + [ "$resend_epoch" = 12100 ] || fail "the resend epoch was not recorded: $(cat "$rec")" + [ -n "$(fm_pending_reply_get "$rec" delivered_epoch)" ] \ + || fail "a resend that lands must confirm delivery: $(cat "$rec")" + [ "$(fm_pending_reply_get "$rec" phase)" = awaiting_report ] \ + || fail "a resent request must await its report: $(cat "$rec")" + [ -z "$(status_open_decisions "$status")" ] \ + || fail "the resend must close the delivery-unknown decision: $(status_open_decisions "$status")" + grep -F "resolved [key=pending-reply-$corr]" "$status" | grep -qF 'via=delivery-reconciled resent' \ + || fail "the close must say the record was resent: $(cat "$status")" + + # No second resend on any later pass. + tracker_pass "$fb" "$home" "$ssh_log" 12700 + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 1 ] \ + || fail "a later pass must not resend again" + [ "$(fm_pending_reply_get "$rec" delivery_resend_epoch)" = "$resend_epoch" ] \ + || fail "a later pass must not touch the resend epoch: $(cat "$rec")" + pass "fm-pending-reply remote: an unlanded record is resent once, the first failed read does not delay it, and no second resend follows" +} + +# Scenario 3, byte-exact: the remote inbox dedups on the whole body, so the +# resend carries the stored request with its trailing newline intact. +test_remote_resend_keeps_the_request_body_byte_exact() { + local dir fb ssh_log home rhome corr text body + dir="$TMP_ROOT/remote-resend-exact"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-resend-exact) + home=$(setup_remote_parent_home remote-resend-exact "$rhome") + text=$'please append one line\n' + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 12000 "$text" FM_FAKE_SSH_RC=255) + [ "$(cat "$(fm_pending_reply_undelivered_text_path "$home/state" "$corr")"; printf x)" = "${text}x" ] \ + || fail "the unconfirmed send must store its request byte-exact" + tracker_pass "$fb" "$home" "$ssh_log" 12040 FM_FAKE_SSH_RC=255 + tracker_pass "$fb" "$home" "$ssh_log" 12100 + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 1 ] \ + || fail "the reachable host must receive exactly one resend" + body=$(fm_task_inbox_body "$(remote_inbox_records "$rhome" | head -1)"; printf x) + case "$body" in + *"corr=$corr"*"$text"x) ;; + *) fail "the resent body must end with the request's trailing newline: $(printf '%q' "$body")" ;; + esac + case "$body" in *$'\n\n'x) fail "the resend must not add a newline: $(printf '%q' "$body")" ;; esac + pass "fm-pending-reply remote: the one resend keeps the stored request's trailing newline" +} + +# Scenario 2 and 3, a close that cannot be written: the delivery-unknown +# decision is closed on a later pass instead of staying open for the task. +test_remote_failed_reconciliation_close_is_retried() { + local dir fb ssh_log home rhome corr rec status + dir="$TMP_ROOT/remote-close-retry"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + + # Landed: the record stays undelivered until the close lands. + rhome=$(setup_remote_secondmate_home remote-close-retry-landed) + home=$(setup_remote_parent_home remote-close-retry-landed "$rhome") + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 11000 "please append one line" FM_FAKE_SSH_AMBIGUOUS=1) + rec=$(fm_pending_reply_path "$home/state" "$corr") + status="$home/state/rsm.status" + tracker_pass "$fb" "$home" "$ssh_log" 11010 FM_FAKE_SSH_RC=255 + [ "$(status_open_decisions "$status" | cut -f1)" = "pending-reply-$corr" ] \ + || fail "the delivery-unknown decision must be open: $(cat "$status")" + chmod a-w "$status" + tracker_pass "$fb" "$home" "$ssh_log" 11070 + chmod u+w "$status" + [ -z "$(fm_pending_reply_get "$rec" delivered_epoch)" ] \ + || fail "a landed record whose close failed must stay undelivered: $(cat "$rec")" + [ -n "$(status_open_decisions "$status")" ] || fail "the failed close must not have written" + tracker_pass "$fb" "$home" "$ssh_log" 11670 + [ "$(fm_pending_reply_get "$rec" delivery_reconcile)" = landed ] \ + || fail "the next check must reconcile the record as landed: $(cat "$rec")" + [ -z "$(status_open_decisions "$status")" ] \ + || fail "the retried check must close the decision: $(status_open_decisions "$status")" + [ -n "$(fm_pending_reply_get "$rec" escalation_closed_epoch)" ] \ + || fail "the close must be recorded: $(cat "$rec")" + + # Resent: delivery is confirmed by fm-send, and a later pass retries the close. + rhome=$(setup_remote_secondmate_home remote-close-retry-resent) + home=$(setup_remote_parent_home remote-close-retry-resent "$rhome") + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 12000 "please append one line" FM_FAKE_SSH_RC=255) + rec=$(fm_pending_reply_path "$home/state" "$corr") + status="$home/state/rsm.status" + tracker_pass "$fb" "$home" "$ssh_log" 12040 FM_FAKE_SSH_RC=255 + chmod a-w "$status" + tracker_pass "$fb" "$home" "$ssh_log" 12100 + chmod u+w "$status" + [ "$(fm_pending_reply_get "$rec" delivery_reconcile)" = resent ] \ + && [ -n "$(fm_pending_reply_get "$rec" delivered_epoch)" ] \ + || fail "the resend must have landed and confirmed delivery: $(cat "$rec")" + [ -n "$(status_open_decisions "$status")" ] && [ -z "$(fm_pending_reply_get "$rec" escalation_closed_epoch)" ] \ + || fail "the failed close must leave the decision open and unrecorded: $(cat "$rec")" + tracker_pass "$fb" "$home" "$ssh_log" 12160 + [ -z "$(status_open_decisions "$status")" ] \ + || fail "a later pass must close the decision: $(status_open_decisions "$status")" + grep -F "resolved [key=pending-reply-$corr]" "$status" | grep -qF 'via=delivery-reconciled resent' \ + || fail "the retried close must say the record was resent: $(cat "$status")" + [ -n "$(fm_pending_reply_get "$rec" escalation_closed_epoch)" ] \ + || fail "the retried close must be recorded: $(cat "$rec")" + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 1 ] || fail "the retry must not resend" + pass "fm-pending-reply remote: a delivery-reconciled close that could not be written is retried on a later pass" +} + +# Scenario 3 bounds: the recheck spacing, the stored text, and the age limit. +test_remote_undelivered_check_honours_spacing_text_and_age_limits() { + local dir fb ssh_log home rhome corr rec before + dir="$TMP_ROOT/remote-resend-bounds"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-resend-bounds) + home=$(setup_remote_parent_home remote-resend-bounds "$rhome") + + # Spacing: a successful check ends the checking when it finds the record, so + # the spacing is visible on a record whose last check is recent. + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 13000 "spaced request" FM_FAKE_SSH_RC=255) + rec=$(fm_pending_reply_path "$home/state" "$corr") + fm_pending_reply_set "$rec" delivery_checked_epoch 13100 + before=$(cat "$ssh_log.count") + tracker_pass "$fb" "$home" "$ssh_log" 13699 + [ "$(cat "$ssh_log.count")" = "$before" ] \ + || fail "a check inside the 600 s spacing must not touch the host" + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 0 ] \ + || fail "a check inside the spacing must not resend" + tracker_pass "$fb" "$home" "$ssh_log" 13700 + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 1 ] \ + || fail "a check at the end of the spacing must resend the unlanded record" + + # Without the stored text the record is left to the printed resend command. + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 14000 "textless request" FM_FAKE_SSH_RC=255) + rec=$(fm_pending_reply_path "$home/state" "$corr") + rm -f "$(fm_pending_reply_undelivered_text_path "$home/state" "$corr")" + tracker_pass "$fb" "$home" "$ssh_log" 14001 + [ -z "$(fm_pending_reply_get "$rec" delivery_reconcile)" ] \ + || fail "a record without stored text must not be reconciled: $(cat "$rec")" + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 1 ] \ + || fail "a record without stored text must not be resent" + + # A stale instruction must not land unannounced. + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 15000 "stale request" FM_FAKE_SSH_RC=255) + rec=$(fm_pending_reply_path "$home/state" "$corr") + tracker_pass "$fb" "$home" "$ssh_log" 22201 + [ "$(fm_pending_reply_get "$rec" delivery_reconcile)" = absent ] \ + || fail "a request older than the resend limit must end as absent: $(cat "$rec")" + [ ! -e "$(fm_pending_reply_undelivered_text_path "$home/state" "$corr")" ] \ + || fail "an abandoned resend must drop its stored text" + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 1 ] \ + || fail "a request older than the resend limit must not be resent" + pass "fm-pending-reply remote: the undelivered check honours its spacing, needs stored text, and stops at the age limit" +} + +# Scenario 3, "once": a resend that itself fails is not repeated on the next +# check, even though the host is reachable again by then. +test_remote_failed_resend_is_never_repeated() { + local dir fb ssh_log home rhome corr rec + dir="$TMP_ROOT/remote-resend-once"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-resend-once) + home=$(setup_remote_parent_home remote-resend-once "$rhome") + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 17000 "please append one line" FM_FAKE_SSH_RC=255) + rec=$(fm_pending_reply_path "$home/state" "$corr") + + # The inbox can be read but the send leg is lost: the one resend is spent. + tracker_pass "$fb" "$home" "$ssh_log" 17001 FM_FAKE_SSH_FAIL_SUBCMD=send-stdin + [ "$(fm_pending_reply_get "$rec" delivery_resend_epoch)" = 17001 ] \ + || fail "the failed resend must still count as the one resend: $(cat "$rec")" + [ -z "$(fm_pending_reply_get "$rec" delivered_epoch)" ] \ + || fail "a resend that was lost must not claim delivery: $(cat "$rec")" + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 0 ] \ + || fail "the lost resend must not have landed" + + # Reachable again and past the spacing: the record is still absent, but no + # second resend is made; checking just stops. + tracker_pass "$fb" "$home" "$ssh_log" 17700 + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 0 ] \ + || fail "a record whose one resend failed must not be resent again" + [ "$(fm_pending_reply_get "$rec" delivery_reconcile)" = absent ] \ + || fail "the second check must end the checking as absent: $(cat "$rec")" + pass "fm-pending-reply remote: a resend that failed is never repeated" +} + +# Scenario 3, definite failure: a resend the remote leg refuses outright keeps +# the record tracked and escalates it as delivery-unknown. +test_remote_definitely_failed_resend_stays_tracked_and_escalates() { + local dir fb ssh_log home rhome corr rec status open + dir="$TMP_ROOT/remote-resend-refused"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-resend-refused) + home=$(setup_remote_parent_home remote-resend-refused "$rhome") + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 18000 "please append one line" FM_FAKE_SSH_RC=255) + rec=$(fm_pending_reply_path "$home/state" "$corr") + status="$home/state/rsm.status" + [ "$(fm_pending_reply_get "$rec" phase)" = delivery_unknown ] \ + || fail "a send refused twice must be delivery_unknown: $(cat "$rec")" + + # The first check reads the inbox, finds nothing, and the one resend is + # refused by the remote leg with a definite error. + tracker_pass "$fb" "$home" "$ssh_log" 18001 FM_FAKE_SSH_FAIL_SUBCMD=send-stdin FM_FAKE_SSH_FAIL_SUBCMD_RC=1 + [ "$(fm_pending_reply_get "$rec" delivery_resend_epoch)" = 18001 ] \ + || fail "the refused resend must still count as the one resend: $(cat "$rec")" + [ -z "$(fm_pending_reply_get "$rec" delivered_epoch)" ] \ + || fail "a refused resend must not claim delivery: $(cat "$rec")" + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 0 ] \ + || fail "the refused resend must not have landed" + [ "$(fm_pending_reply_get "$rec" phase)" = escalated ] \ + || fail "a refused resend must leave the record escalated, not orphaned: $(cat "$rec")" + [ "$(grep -c 'pending-reply-delivery-unknown' "$status" || true)" = 1 ] \ + || fail "a refused resend must escalate as delivery-unknown: $(cat "$status" 2>/dev/null)" + open=$(status_open_decisions "$status" | cut -f1) + [ "$open" = "pending-reply-$corr" ] || fail "the delivery-unknown decision must be open, got '$open'" + + # The next check still finds it absent and ends the checking without a + # second resend; the decision stays open for firstmate. + tracker_pass "$fb" "$home" "$ssh_log" 18700 + [ "$(fm_pending_reply_get "$rec" delivery_reconcile)" = absent ] \ + || fail "the next check must end the checking as absent: $(cat "$rec")" + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 0 ] \ + || fail "a record whose one resend was refused must not be resent again" + [ ! -e "$(fm_pending_reply_undelivered_text_path "$home/state" "$corr")" ] \ + || fail "ending the checking must drop the stored text" + open=$(status_open_decisions "$status" | cut -f1) + [ "$open" = "pending-reply-$corr" ] || fail "the delivery-unknown decision must stay open, got '$open'" + pass "fm-pending-reply remote: a resend refused outright stays tracked and escalates as delivery-unknown" +} + +# A --resolve-key answer whose transport was lost twice is left to its printed +# resend command, the only send that closes the answered key: the tracker +# neither resends it nor closes its delivery-unknown decision. +test_remote_unconfirmed_resolve_key_answer_is_left_to_the_printed_resend() { + local dir fb ssh_log home rhome corr rec status open + dir="$TMP_ROOT/remote-resend-keyed"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-resend-keyed) + home=$(setup_remote_parent_home remote-resend-keyed "$rhome") + status="$home/state/rsm.status" + printf 'needs-decision [key=upgrade-window]: tonight or the weekend\n' > "$status" + send_env "$fb" "$home" "$ssh_log" FM_PENDING_REPLY_NOW=19000 FM_FAKE_SSH_RC=255 \ + "$SEND" rsm --resolve-key upgrade-window "the weekend, freeze Friday" >/dev/null 2>&1 || true + corr=$(fm_pending_reply_get "$(pending_record "$home")" corr_id) + [ -n "$corr" ] || fail "the keyed answer did not leave a pending-reply record" + rec=$(fm_pending_reply_path "$home/state" "$corr") + [ "$(fm_pending_reply_get "$rec" phase)" = delivery_unknown ] \ + || fail "a keyed answer refused twice must be delivery_unknown: $(cat "$rec")" + + tracker_pass "$fb" "$home" "$ssh_log" 19010 FM_FAKE_SSH_RC=255 + [ "$(fm_pending_reply_get "$rec" phase)" = escalated ] \ + || fail "the unknown keyed answer must escalate: $(cat "$rec")" + + # Reachable again and past every spacing: still no reconciliation. + tracker_pass "$fb" "$home" "$ssh_log" 19700 + tracker_pass "$fb" "$home" "$ssh_log" 20400 + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 0 ] \ + || fail "the tracker must not resend a keyed answer" + [ -z "$(fm_pending_reply_get "$rec" delivery_reconcile)" ] \ + || fail "the tracker must not reconcile a keyed answer: $(cat "$rec")" + [ -z "$(fm_pending_reply_get "$rec" delivered_epoch)" ] \ + || fail "a keyed answer that never landed must not claim delivery: $(cat "$rec")" + [ "$(fm_pending_reply_get "$rec" phase)" = escalated ] \ + || fail "the keyed answer's record must stay escalated: $(cat "$rec")" + open=$(status_open_decisions "$status" | cut -f1 | sort | tr '\n' ' ') + [ "$open" = "pending-reply-$corr upgrade-window " ] \ + || fail "the answered key and the delivery-unknown decision must both stay open, got '$open'" + pass "fm-pending-reply remote: an unconfirmed --resolve-key answer is left to its printed resend" +} + +# Review finding on the finding-2 fix: a failed read must be retried soon, but +# not on every watcher pass. +test_remote_failed_inbox_read_retries_after_the_short_backoff_only() { + local dir fb ssh_log home rhome corr rec before + dir="$TMP_ROOT/remote-read-backoff"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-read-backoff) + home=$(setup_remote_parent_home remote-read-backoff "$rhome") + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 18000 "please append one line" FM_FAKE_SSH_RC=255) + rec=$(fm_pending_reply_path "$home/state" "$corr") + + tracker_pass "$fb" "$home" "$ssh_log" 18010 FM_FAKE_SSH_RC=255 + [ "$(fm_pending_reply_get "$rec" delivery_read_failed_epoch)" = 18010 ] \ + || fail "a failed read must record when it failed: $(cat "$rec")" + + # The host is back, but the watcher passes inside the backoff do not read. + before=$(cat "$ssh_log.count") + tracker_pass "$fb" "$home" "$ssh_log" 18025 + tracker_pass "$fb" "$home" "$ssh_log" 18069 + [ "$(cat "$ssh_log.count")" = "$before" ] \ + || fail "a pass inside the read-retry backoff must not touch the host" + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 0 ] \ + || fail "a pass inside the backoff must not resend" + + # At the end of the backoff the read happens, the record is found absent, and + # the answered read clears the failure. + tracker_pass "$fb" "$home" "$ssh_log" 18070 + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 1 ] \ + || fail "the first pass after the backoff must read the inbox and resend" + [ -z "$(fm_pending_reply_get "$rec" delivery_read_failed_epoch)" ] \ + || fail "an answered read must clear the recorded failure: $(cat "$rec")" + [ "$(fm_pending_reply_get "$rec" delivery_checked_epoch)" = 18070 ] \ + || fail "an answered read is a check: $(cat "$rec")" + pass "fm-pending-reply remote: a failed inbox read is retried after the short backoff and not before" +} + +# A remote copy without the inbox-status leg answers every read with a usage +# error: it is probed at the short spacing, not on every pass. +test_remote_copy_without_the_inbox_status_leg_is_probed_at_the_short_spacing() { + local dir fb ssh_log home rhome corr rec before pass_epoch + dir="$TMP_ROOT/remote-no-leg"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-no-leg) + home=$(setup_remote_parent_home remote-no-leg "$rhome") + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 19000 "please append one line" FM_FAKE_SSH_RC=255) + rec=$(fm_pending_reply_path "$home/state" "$corr") + + before=$(cat "$ssh_log.count") + for pass_epoch in 19010 19025 19040 19055; do + tracker_pass "$fb" "$home" "$ssh_log" "$pass_epoch" FM_FAKE_SSH_USAGE_SUBCMD=inbox-status + done + [ "$(( $(cat "$ssh_log.count") - before ))" = 1 ] \ + || fail "four watcher passes inside 60 s must make one probe, made $(( $(cat "$ssh_log.count") - before ))" + tracker_pass "$fb" "$home" "$ssh_log" 19070 FM_FAKE_SSH_USAGE_SUBCMD=inbox-status + [ "$(( $(cat "$ssh_log.count") - before ))" = 2 ] \ + || fail "the pass after the spacing must probe again" + [ -z "$(fm_pending_reply_get "$rec" delivered_epoch)" ] \ + || fail "a usage error must never claim delivery: $(cat "$rec")" + [ -z "$(fm_pending_reply_get "$rec" delivery_checked_epoch)" ] \ + || fail "a usage error is not an answered read: $(cat "$rec")" + [ "$(remote_inbox_records "$rhome" | grep -c . || true)" = 0 ] \ + || fail "a usage error must not trigger a resend" + pass "fm-pending-reply remote: a remote copy without the inbox-status leg is probed at the short spacing" +} + +# A host that accepts the connection and then says nothing cannot hold the +# watcher past the read budget. +test_remote_silent_host_cannot_hold_the_tracker_past_the_read_budget() { + local dir fb ssh_log home rhome corr rec start elapsed + dir="$TMP_ROOT/remote-read-budget"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-read-budget) + home=$(setup_remote_parent_home remote-read-budget "$rhome") + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 20000 "please append one line" FM_FAKE_SSH_RC=255) + rec=$(fm_pending_reply_path "$home/state" "$corr") + + start=$SECONDS + tracker_pass "$fb" "$home" "$ssh_log" 20010 FM_FAKE_SSH_HANG=25 FM_PENDING_REPLY_INBOX_READ_BUDGET=1 + elapsed=$((SECONDS - start)) + [ "$elapsed" -lt 15 ] || fail "a silent host held the tracker for ${elapsed}s despite a 1 s read budget" + [ "$(fm_pending_reply_get "$rec" delivery_read_failed_epoch)" = 20010 ] \ + || fail "a read that hit its budget is a failed read: $(cat "$rec")" + pass "fm-pending-reply remote: a silent host is cut off at the inbox read budget" +} + +# Scenario 4: the resend is a real record in the mate's inbox; once the mate +# acknowledges it and reports, the parent's record resolves. +test_remote_resend_lands_and_acknowledgement_resolves_the_record() { + local dir fb ssh_log home rhome corr rec status inbox status_out + dir="$TMP_ROOT/remote-resend-ack"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-resend-ack) + home=$(setup_remote_parent_home remote-resend-ack "$rhome") + inbox="$rhome/state/parent-route/rsm.inbox" + corr=$(send_remote_request "$fb" "$home" "$ssh_log" 16000 "please append one line" FM_FAKE_SSH_RC=255) + rec=$(fm_pending_reply_path "$home/state" "$corr") + status="$home/state/rsm.status" + tracker_pass "$fb" "$home" "$ssh_log" 16001 + + [ -f "$inbox/001.msg" ] || fail "the resend must land as the first record in the remote inbox" + grep -qF "corr=$corr please append one line" "$inbox/001.msg" \ + || fail "the resent record must carry the original marker, correlation and text: $(cat "$inbox/001.msg")" + status_out=$(tracker_inbox_status "$fb" "$home" "$ssh_log" 16002 "$corr") + assert_contains "$status_out" "unhandled=1" "the inbox status must count the landed resend" + assert_contains "$status_out" "corr_state=unhandled" "the inbox status must report the resend unhandled" + + # The mate acknowledges it: handled/ and a correlated report on its channel. + mv "$inbox/001.msg" "$inbox/handled/001.msg" + status_out=$(tracker_inbox_status "$fb" "$home" "$ssh_log" 16003 "$corr") + assert_contains "$status_out" "unhandled=0" "an acknowledged record must leave the unhandled count" + assert_contains "$status_out" "corr_state=handled" "an acknowledged record must report handled" + printf 'done corr=%s at=16004: read and appended\n' "$corr" >> "$status" + tracker_pass "$fb" "$home" "$ssh_log" 16005 + [ "$(fm_pending_reply_get "$rec" phase)" = resolved ] \ + || fail "the correlated acknowledgement must resolve the parent record: $(cat "$rec")" + [ "$(fm_pending_reply_get "$rec" resolved_via)" = status ] \ + || fail "the record must resolve through the status line: $(cat "$rec")" + pass "fm-pending-reply remote: the resend lands in the remote inbox and the acknowledgement resolves the record" +} + +# The inbox-status leg itself: its schema, the three correlation states, and a +# malformed correlation refused before anything is read. +test_remote_inbox_status_leg_reports_states_and_rejects_bad_corr() { + local dir fb ssh_log home rhome out rc + dir="$TMP_ROOT/remote-inbox-status"; mkdir -p "$dir" + fb=$(make_stubs "$dir"); ssh_log="$dir/ssh.log"; : > "$ssh_log" + rhome=$(setup_remote_secondmate_home remote-inbox-status) + home=$(setup_remote_parent_home remote-inbox-status "$rhome") + leg() { # [corr] + send_env "$fb" "$home" "$ssh_log" "$ROOT/bin/fm-on.sh" rsm \ + fm-remote-secondmate-control.sh inbox-status rsm "$@" /dev/null + fm_task_inbox_write "$rhome/state/parent-route" rsm "[fm] corr=cccccccccccccccc second" >/dev/null + mv "$rhome/state/parent-route/rsm.inbox/002.msg" "$rhome/state/parent-route/rsm.inbox/handled/" + out=$(leg bbbbbbbbbbbbbbbb) + assert_contains "$out" "unhandled=1" "one record is still unhandled" + assert_contains "$out" "corr_state=unhandled" "a waiting record reports unhandled" + out=$(leg cccccccccccccccc) + assert_contains "$out" "corr_state=handled" "an acknowledged record reports handled" + + rc=0 + out=$(leg 'not-a-corr' 2>&1) || rc=$? + [ "$rc" -ne 0 ] || fail "a malformed correlation must be refused" + assert_contains "$out" "invalid correlation id" "the refusal must name the correlation" + pass "fm-remote-secondmate-control inbox-status: schema, unhandled count, three correlation states, bad correlation refused" +} + test_remote_large_steer_uses_stdin test_remote_steer_lands_in_remote_inbox test_remote_rerun_is_idempotent @@ -835,5 +1536,23 @@ test_remote_send_budget_bounds_busy_lane test_local_pending_reports_delivered_unconfirmed test_local_pending_does_not_close_resolve_key test_local_secondmate_pending_keeps_expectation_armed +test_remote_unread_request_escalates_once +test_remote_unread_request_delivered_to_a_busy_mate_still_escalates +test_remote_handled_request_idle_counts_as_a_completed_turn +test_remote_unreadable_inbox_leaves_the_idle_counting_as_before +test_remote_lost_reply_reconciles_as_landed +test_remote_landed_reconciliation_closes_the_delivery_unknown_decision +test_remote_unlanded_record_is_resent_once_and_recheck_is_not_delayed_by_a_failed_read +test_remote_resend_keeps_the_request_body_byte_exact +test_remote_failed_reconciliation_close_is_retried +test_remote_undelivered_check_honours_spacing_text_and_age_limits +test_remote_failed_resend_is_never_repeated +test_remote_definitely_failed_resend_stays_tracked_and_escalates +test_remote_unconfirmed_resolve_key_answer_is_left_to_the_printed_resend +test_remote_failed_inbox_read_retries_after_the_short_backoff_only +test_remote_copy_without_the_inbox_status_leg_is_probed_at_the_short_spacing +test_remote_silent_host_cannot_hold_the_tracker_past_the_read_budget +test_remote_resend_lands_and_acknowledgement_resolves_the_record +test_remote_inbox_status_leg_reports_states_and_rejects_bad_corr echo "all fm-send-remote-delivery tests passed" diff --git a/tests/fm-task-inbox.test.sh b/tests/fm-task-inbox.test.sh index f08d529a248..1c633e34126 100644 --- a/tests/fm-task-inbox.test.sh +++ b/tests/fm-task-inbox.test.sh @@ -29,6 +29,9 @@ # 7. A fire-and-forget record stays outside the ladder, but one whose first # ring did not land gets exactly one retry ring and never escalates. The # retry waits while the worker has an open decision of its own. +# 8. Every ring decision is appended to the inbox's bounded .ring-log, and a +# secondmate's own watcher queues one wake per oldest unhandled parent +# record past the grace (parent_inbox_tick). set -u # shellcheck source=tests/wake-helpers.sh @@ -1372,6 +1375,209 @@ test_watcher_dead_pane_ignores_stale_busy_state() { pass "watcher: dead-pane recovery overrides stale busy state" } +# The ring log records every decision, including the skipped ones that left a +# parked mate's doorbell unrung (live scenario: a pending composer holding +# other text), and stays bounded. +test_ring_log_records_each_decision_and_stays_bounded() { + local dir state rec log composer drops doorbell lines + dir="$TMP_ROOT/ring-log" + state="$dir/state" + mkdir -p "$state" + make_composer_stub "$dir" + rec=$(inbox_lib "$state" fm_task_inbox_write "$state" t1 "please continue") + doorbell=$(inbox_lib "$state" fm_task_inbox_doorbell_line "$rec") + log="$dir/send.log"; composer="$dir/composer"; drops="$dir/drops" + ring() { + PATH="$dir/fakebin:$PATH" FM_SEND_LOG="$log" FM_FAKE_COMPOSER="$composer" \ + FM_FAKE_DROP_ENTERS="$drops" inbox_lib "$state" fm_task_inbox_ring tmux sess:fm-t1 "$rec" fm-t1 + } + : > "$log"; : > "$composer" + + printf '%s' 'a half-typed draft' > "$composer" + ring || true + lines=$(cat "$state/t1.inbox/.ring-log") + printf '%s\n' "$lines" | grep -Eq '^[0-9]{4}-[0-9]{2}-[0-9]{2}T[0-9:]{8}Z 001.msg skipped:other-text composer=pending$' \ + || fail "a skipped ring must log the record, decision and composer verdict: $lines" + + printf '%s' "$doorbell" > "$composer" + ring || true + [ "$(wc -l < "$state/t1.inbox/.ring-log" | tr -d ' ')" = 2 ] \ + || fail "every ring decision must append one line: $(cat "$state/t1.inbox/.ring-log")" + tail -1 "$state/t1.inbox/.ring-log" | grep -Eq ' 001.msg rang composer=own-doorbell submitted$' \ + || fail "a submitted stuck doorbell must log rang: $(tail -1 "$state/t1.inbox/.ring-log")" + + : > "$composer" + ring || true + tail -1 "$state/t1.inbox/.ring-log" | grep -Eq ' 001.msg rang ' \ + || fail "a clean ring must log rang: $(tail -1 "$state/t1.inbox/.ring-log")" + + # Past 64 KiB the log is trimmed to its newest 200 lines. + awk 'BEGIN { for (i = 0; i < 1000; i++) printf "2020-01-01T00:00:00Z\told.msg\trang\tfiller-%s-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx\n", i }' \ + > "$state/t1.inbox/.ring-log" + printf '%s' 'a half-typed draft' > "$composer" + ring || true + [ "$(wc -l < "$state/t1.inbox/.ring-log" | tr -d ' ')" = 200 ] \ + || fail "an oversized ring log must be trimmed to 200 lines, got $(wc -l < "$state/t1.inbox/.ring-log")" + tail -1 "$state/t1.inbox/.ring-log" | grep -q 'skipped:other-text' \ + || fail "the trim must keep the newest decision: $(tail -1 "$state/t1.inbox/.ring-log")" + pass "inbox: the ring log records each ring decision and trims itself past 64 KiB" +} + +# A dead agent's refusal is logged too, so a record that never got a doorbell +# can be told apart from one whose doorbell was swallowed. +test_ring_log_records_a_dead_agent() { + local dir state rec log + dir="$TMP_ROOT/ring-log-dead" + state="$dir/state" + mkdir -p "$state" + make_watch_stubs "$dir" >/dev/null + rec=$(inbox_lib "$state" fm_task_inbox_write "$state" t1 "please continue") + log="$dir/send.log"; : > "$log" + PATH="$dir/fakebin:$PATH" FM_SEND_LOG="$log" FM_FAKE_TMUX_AGENT=zsh \ + inbox_lib "$state" fm_task_inbox_ring tmux sess:fm-t1 "$rec" fm-t1 || true + grep -Eq ' 001.msg dead agent=dead$' "$state/t1.inbox/.ring-log" \ + || fail "a dead agent's refusal must be logged: $(cat "$state/t1.inbox/.ring-log")" + pass "inbox: the ring log records a dead agent's refusal" +} + +# The secondmate's own watcher wakes its parked session for an unread parent +# instruction (live scenario: the remote watcher queued the wake at 100 s). +# Sourced like the unit cases in tests/fm-watch-inbox-meta.test.sh; the wake +# callback is the seam the production watcher documents for tests. +parent_tick() { # + FM_HOME="$1" FM_STATE_OVERRIDE="$1/state" FM_TASK_INBOX_GRACE_SECS=90 WAKE_LOG="$2" \ + bash -c ' + . "$1" + wake() { printf "%s\n" "$1" >> "$WAKE_LOG"; } + parent_inbox_tick + ' _ "$WATCH" +} + +test_parent_inbox_tick_wakes_a_parked_mate_once_per_oldest_record() { + local home state inbox wakes first second queue + home="$TMP_ROOT/parent-tick" + state="$home/state" + inbox="$state/parent-route/rsm.inbox" + mkdir -p "$state/parent-route" + printf 'rsm\n' > "$home/.fm-secondmate-home" + wakes="$home/wakes.log"; : > "$wakes" + first=$(inbox_lib "$state/parent-route" fm_task_inbox_write "$state/parent-route" rsm "first instruction") + + parent_tick "$home" "$wakes" + [ ! -s "$wakes" ] || fail "a record inside the inbox grace must not wake the mate: $(cat "$wakes")" + [ ! -s "$state/.wake-queue" ] || fail "a record inside the grace must queue nothing" + + touch -d '101 seconds ago' "$first" + parent_tick "$home" "$wakes" + [ "$(wc -l < "$wakes" | tr -d ' ')" = 1 ] || fail "an aged record must wake the mate once: $(cat "$wakes")" + assert_contains "$(cat "$wakes")" "check: parent instruction waiting: 1 unhandled in $inbox, oldest 10" \ + "the wake must name the count, the inbox and the oldest age (101 s, give or take the second boundary)" + queue=$(cat "$state/.wake-queue") + case "$queue" in + *" check parent-inbox-rsm-001 check: parent instruction waiting: 1 unhandled"*) : ;; + *) fail "the wake must be queued durably under the oldest record's key: $queue" ;; + esac + [ "$(cat "$state/.parent-inbox-woken")" = 001.msg ] || fail "the woken marker must name the oldest record" + + # The same oldest record never wakes twice, even with a newer one beside it. + second=$(inbox_lib "$state/parent-route" fm_task_inbox_write "$state/parent-route" rsm "second instruction") + touch -d '200 seconds ago' "$second" + parent_tick "$home" "$wakes" + [ "$(wc -l < "$wakes" | tr -d ' ')" = 1 ] || fail "the same oldest record must not wake twice: $(cat "$wakes")" + [ "$(wc -l < "$state/.wake-queue" | tr -d ' ')" = 1 ] || fail "the same oldest record must not queue twice" + + # Handling the oldest moves the wake to the next record; an empty inbox + # clears the marker so a later record wakes again. + mv "$first" "$inbox/handled/" + parent_tick "$home" "$wakes" + [ "$(wc -l < "$wakes" | tr -d ' ')" = 2 ] || fail "the next oldest aged record must wake the mate: $(cat "$wakes")" + assert_contains "$(tail -1 "$wakes")" "1 unhandled" "only the remaining record is counted" + mv "$second" "$inbox/handled/" + parent_tick "$home" "$wakes" + [ ! -e "$state/.parent-inbox-woken" ] || fail "an emptied inbox must clear the woken marker" + first=$(inbox_lib "$state/parent-route" fm_task_inbox_write "$state/parent-route" rsm "third instruction") + touch -d '120 seconds ago' "$first" + parent_tick "$home" "$wakes" + [ "$(wc -l < "$wakes" | tr -d ' ')" = 3 ] || fail "a new aged record after an empty inbox must wake again: $(cat "$wakes")" + pass "watcher: a secondmate's own watcher wakes its session once per oldest unhandled parent record past the grace" +} + +test_parent_inbox_tick_is_silent_outside_a_secondmate_home() { + local home state wakes rec + home="$TMP_ROOT/parent-tick-primary" + state="$home/state" + mkdir -p "$state/parent-route" + wakes="$home/wakes.log"; : > "$wakes" + rec=$(inbox_lib "$state/parent-route" fm_task_inbox_write "$state/parent-route" rsm "stray instruction") + touch -d '500 seconds ago' "$rec" + parent_tick "$home" "$wakes" + [ ! -s "$wakes" ] || fail "a home that is not a secondmate must never wake for a parent inbox: $(cat "$wakes")" + [ ! -s "$state/.wake-queue" ] || fail "a home that is not a secondmate must queue nothing" + pass "watcher: a home without a secondmate identity ignores a parent-route inbox" +} + +# On Herdr a bare `[Pasted text #N]` hides its content, so an operator's own +# paste looks like our collapsed doorbell. It is submitted only once the ring +# log shows an earlier ring of this record typed the doorbell; a first ring +# that meets it skips without Enter. The Herdr pane I/O (agent, composer and +# busy reads, key sends) is a fixture over a composer file; the ring decision +# and the doorbell match are the production code. +herdr_ring() { # + FM_STATE_OVERRIDE="$1" FM_FAKE_COMPOSER="$3" FM_SEND_LOG="$4" bash -c ' + . "$1" + fm_backend_source herdr + fm_backend_herdr_agent_state() { printf alive; } + fm_backend_herdr_busy_state() { printf idle; } + fm_backend_herdr_composer_state() { if [ -s "$FM_FAKE_COMPOSER" ]; then printf pending; else printf empty; fi; } + fm_backend_herdr_composer_content() { cat "$FM_FAKE_COMPOSER"; } + fm_backend_herdr_send_key() { printf "%s\n" "$2" >> "$FM_SEND_LOG"; : > "$FM_FAKE_COMPOSER"; } + fm_task_inbox_ring herdr default:w1:p2 "$2" + ' _ "$ROOT/bin/fm-task-inbox-lib.sh" "$2" +} + +test_herdr_bare_placeholder_needs_an_earlier_typed_ring() { + local dir state rec composer keys doorbell rc + dir="$TMP_ROOT/herdr-placeholder" + state="$dir/state" + mkdir -p "$state" + rec=$(inbox_lib "$state" fm_task_inbox_write "$state" t1 "please continue") + doorbell=$(inbox_lib "$state" fm_task_inbox_doorbell_line "$rec") + composer="$dir/composer"; keys="$dir/keys"; : > "$keys" + + printf '[Pasted text #1]' > "$composer" + rc=0; herdr_ring "$state" "$rec" "$composer" "$keys" || rc=$? + [ "$rc" = 1 ] || fail "a first ring meeting a bare placeholder must skip, got rc=$rc" + [ ! -s "$keys" ] || fail "a bare placeholder with no earlier typed ring must not get Enter: $(cat "$keys")" + [ "$(cat "$composer")" = '[Pasted text #1]' ] || fail "the operator's paste must stay in the composer" + tail -1 "$state/t1.inbox/.ring-log" | grep -q ' 001.msg skipped:other-text ' \ + || fail "the skip must be logged as other text: $(cat "$state/t1.inbox/.ring-log")" + printf '[Pasted text #1]%s' "${doorbell: -12}" > "$composer" + rc=0; herdr_ring "$state" "$rec" "$composer" "$keys" || rc=$? + [ "$rc" = 1 ] && [ ! -s "$keys" ] || fail "a placeholder plus doorbell tail with no earlier typed ring must skip, rc=$rc" + + # Exact whole-line equality is our doorbell without any log entry. + printf '%s' "$doorbell" > "$composer" + rc=0; herdr_ring "$state" "$rec" "$composer" "$keys" || rc=$? + [ "$rc" = 0 ] && [ "$(cat "$keys")" = Enter ] || fail "an exact doorbell must be submitted once, rc=$rc keys=$(cat "$keys")" + + # Right after a ring of this record that typed the doorbell, its collapsed form is ours. + : > "$keys" + printf '[Pasted text #2]' > "$composer" + rc=0; herdr_ring "$state" "$rec" "$composer" "$keys" || rc=$? + [ "$rc" = 0 ] && [ "$(cat "$keys")" = Enter ] \ + || fail "a placeholder after an earlier typed ring must be submitted, rc=$rc keys=$(cat "$keys")" + + # The same earlier ring, long ago: an operator paste now is not our doorbell. + awk -F '\t' -v OFS='\t' '{ $1 = "2020-01-01T00:00:00Z"; print }' "$state/t1.inbox/.ring-log" \ + > "$state/t1.inbox/.ring-log.new" && mv "$state/t1.inbox/.ring-log.new" "$state/t1.inbox/.ring-log" + : > "$keys" + printf '[Pasted text #3]' > "$composer" + rc=0; herdr_ring "$state" "$rec" "$composer" "$keys" || rc=$? + [ "$rc" = 1 ] && [ ! -s "$keys" ] \ + || fail "a placeholder whose only earlier typed ring is old must skip without Enter, rc=$rc keys=$(cat "$keys")" + pass "inbox: a Herdr bare paste placeholder is submitted only after a recent ring of the record typed the doorbell" +} + test_write_is_durable_and_exact test_doorbell_is_a_shell_noop test_doorbell_rejects_terminal_controls @@ -1423,3 +1629,8 @@ test_watcher_retry_keeps_a_newer_mark test_watcher_escalates_once_after_budget test_watcher_dead_pane_escalates_once_without_ringing test_watcher_dead_pane_ignores_stale_busy_state +test_ring_log_records_each_decision_and_stays_bounded +test_ring_log_records_a_dead_agent +test_parent_inbox_tick_wakes_a_parked_mate_once_per_oldest_record +test_parent_inbox_tick_is_silent_outside_a_secondmate_home +test_herdr_bare_placeholder_needs_an_earlier_typed_ring