test(ci): make queue guard harness deterministic (#1062)

Co-authored-by: be-coder-08 <[email protected]>

docs/scratchpads/1019-zero-timeout-harness.md

@@ -0,0 +1,71 @@
+# #1019 — Zero-timeout queue-guard harness race
+
+- **Issue:** #1019 (parent status remains `believed-fixed, pending jarvis validation`; do not close)
+- **Branch:** `fix/1019-ci-queue-timeout-harness`
+- **Owner:** `be-coder-08`
+- **Base:** `origin/main` at `5916aeefd6ed12bcac086c6834c7f6c4ae38e1bc`
+- **Charter:** `/home/hermes/agent-work/tl-mosaic/CHARTER-1019-HARNESS-FIX.md`
+
+## Objective
+
+Make `test-ci-queue-wait-tristate.sh` deterministic without changing any asserted outcome. Remove the indiscriminate zero-timeout race, require every status-classification case to prove the provider was observed, and prove the harness-controlled virtual clock is active.
+
+## Scope
+
+- In scope: `packages/mosaic/framework/tools/git/test-ci-queue-wait-tristate.sh` only, plus this evidence scratchpad.
+- Out of scope: guard parsers, D2/D3 behavior, installer/reseed staleness, PR #1060, and issue closure.
+
+## Acceptance criteria
+
+1. RED deterministically reproduces deadline pre-emption before the provider call.
+2. Every case that intends status classification positively proves provider observation.
+3. Pending observes `pending` before deterministic virtual-time expiration.
+4. The virtual clock has a positive interception control; a broken-clock mutant makes the suite red.
+5. The exact CI-base image passes the final harness repeatedly with zero failures.
+6. Baseline gates, independent code/security review, exact-head CI, and coordinator-authorized squash merge pass.
+
+## Plan
+
+1. Add deterministic RED instrumentation for the known merge/provider-unreachable pre-emption.
+2. Replace global `-t 0` with a nonzero timeout interpreted under an event-driven virtual clock; stub sleep without wall waiting.
+3. Add provider-observation and virtual-clock positive controls without changing outcome assertions.
+4. Run focused shell checks, repeat in exact CI-base image, baseline gates, and independent reviews.
+5. Commit with both identity layers, queue-guard plus direct Woodpecker terminal-state verification, push, self-post PR, verify poster/head/CI, obtain coordinator merge authorization, then squash merge without closing #1019.
+
+## Budget
+
+- No explicit token cap supplied. Keep scope to one harness file and one scratchpad; stop/report at the charter's 60% context gate.
+
+## Evidence
+
+- RED, deterministic pre-provider expiry: `evidence/1019-harness-fix/red-pre-provider-expiry.log` — rc 1; merge/provider-unreachable got rc 124 instead of 75, omitted CANNOT_ASSERT, did not observe the status provider, and wrote no additional audit record (four named failures).
+- GREEN host focused harness: `evidence/1019-harness-fix/green-host.log` — rc 0, all outcome classes passed.
+- Load-bearing clock negative control: a temporary same-directory mutant replaced the virtual `date` body with `/bin/date`; `evidence/1019-harness-fix/red-clock-not-intercepted.log` — rc 1 with named `virtual clock interception did not run` failures. The mutant file was removed after the run.
+- Exact CI-base repeat: `git.mosaicstack.dev/mosaicstack/stack/ci-base:latest`, repository mounted read-only, harness work under container `/tmp`; `evidence/1019-harness-fix/ci-image-repeat/summary.log` — **100 pass / 0 fail / 100 total**.
+- Synchronization design: provider-status observation creates the event marker; virtual time is 1000 before the event and 1002 afterward. Pending alone reaches the stubbed no-op sleep and a post-observation deadline check. `-t 1` is uniquely load-bearing because removing it restores the 900-second default deadline at virtual time 1900, which 1002 does not cross. The numeric timeout is subject semantics under virtual time, not a wall-clock synchronization duration.
+
+## Review remediation — semantic timeout vs. liveness bound
+
+Security review found that virtual time remained at 1000 forever before provider observation and stubbed sleep never waited. A regression looping before the status endpoint—or blocking in the first provider call—therefore could prevent `run_guard` from returning, so the post-return provider assertion could never fire.
+
+**General rule:** A timeout usually serves two purposes: semantics and liveness. Removing wall time from semantic synchronization can silently remove the only independent hang bound. Preserve deterministic virtual time for subject semantics, but provide a separately implemented real-clock liveness watchdog and prove that watchdog fires.
+
+Remediation:
+
+- Every guard subject invocation is launched by absolute `/usr/bin/python3` in a new session. Python's internal monotonic `wait(timeout=...)` provides real-clock liveness independently of PATH; expiry kills the entire isolated process group, so neither PATH-front shims nor a blocked provider descendant can retain the capture pipe.
+- Watchdog expiry returns distinct harness rc 90 plus `FAIL HANG watchdog`, separate from subject timeout rc 124.
+- A first attempt using absolute `/usr/bin/timeout -s KILL` passed on GNU coreutils but failed in the exact Alpine CI-base image: BusyBox killed the immediate wrapper while the guard/provider descendants survived and retained the command-substitution pipe. The process-group kill is therefore required behavior, not portability polish.
+- A committed positive control hangs the branch-provider stub before the status endpoint. It must terminate through the watchdog, emit the hang-specific diagnostic, return rc 90, and prove the status provider was never reached.
+- RED before remediation: a temporary ordinary-success mutant hung before provider observation; only an external control could kill the suite (rc 137), and there was no internal hang-specific diagnostic (`red-watchdog-absent.log`).
+- The watchdog mutant/control is load-bearing: removing the internal watchdog leaves the control unable to produce its required rc 90 and diagnostic.
+
+Post-review evidence:
+
+- Host focused harness with process-group watchdog: rc 0 (`green-watchdog-process-group-host.log`).
+- Exact Alpine CI-base focused harness with process-group watchdog: rc 0 (`green-watchdog-ci-image.log`).
+- Hanging ordinary-success mutant: suite rc 1; success returned rc 90, emitted `FAIL HANG watchdog`, and loudly reported that provider/clock observation did not occur (`red-watchdog-fires.log`).
+- Removed-`-t 1` mutant: suite rc 1; pending was terminated by the watchdog instead of producing `ASSERTED_NOT_READY`, proving the explicit timeout is load-bearing (`red-timeout-argument-removed.log`).
+
+## 60% context hold
+
+Stopped before baseline/review/commit as required by the charter. Remaining: inspect final diff, shell/static/baseline gates, independent code/security review, remediation if any, identity-bound commit/trailer verification, mandatory queue guard plus direct terminal Woodpecker `mosaic` enumeration, push, self-posted PR/provider poster read-back, exact-head terminal-green CI, coordinator merge authorization, squash merge, main CI verification, and leave #1019 unclosed as `believed-fixed, pending jarvis validation`.

packages/mosaic/framework/tools/git/test-ci-queue-wait-tristate.sh

@@ -9,10 +9,51 @@ WORK_DIR="${MOSAIC_TEST_WORK_DIR:-$PWD/.mosaic-test-work/ci-queue-wait-tristate}
 REPO_DIR="$WORK_DIR/repo"
 STUB_DIR="$WORK_DIR/stubs"
 AUDIT_LOG="$WORK_DIR/audit/ci-queue-wait.jsonl"
+STATUS_OBSERVED="$WORK_DIR/status-observed"
+CLOCK_LOG="$WORK_DIR/clock.log"
+WATCHDOG_PYTHON="/usr/bin/python3"
+WATCHDOG_SCRIPT="$WORK_DIR/real-clock-watchdog.py"
+WATCHDOG_TIMEOUT_SEC=5
+WATCHDOG_EXIT=90
 FEATURE_BRANCH="fix/rm-03-fixture"
 
+if [[ ! -x "$WATCHDOG_PYTHON" ]]; then
+    echo "FAIL setup: required real-clock watchdog runtime is unavailable at $WATCHDOG_PYTHON" >&2
+    exit 1
+fi
+
 rm -rf "$WORK_DIR"
 mkdir -p "$REPO_DIR" "$STUB_DIR"
+cat > "$WATCHDOG_SCRIPT" <<'PY'
+import os
+import signal
+import subprocess
+import sys
+
+if len(sys.argv) < 3:
+    raise SystemExit(2)
+
+timeout_seconds = float(sys.argv[1])
+process = subprocess.Popen(sys.argv[2:], start_new_session=True)
+try:
+    return_code = process.wait(timeout=timeout_seconds)
+except subprocess.TimeoutExpired:
+    try:
+        os.killpg(process.pid, signal.SIGKILL)
+    except ProcessLookupError:
+        pass
+    process.wait()
+    print(
+        f"FAIL HANG watchdog: subject exceeded {timeout_seconds:g}s "
+        "before completing its intended path",
+        file=sys.stderr,
+    )
+    raise SystemExit(90)
+
+if return_code < 0:
+    raise SystemExit(128 - return_code)
+raise SystemExit(return_code)
+PY
 git -C "$REPO_DIR" init -q
 git -C "$REPO_DIR" checkout -q -b "$FEATURE_BRANCH"
 git -C "$REPO_DIR" remote add origin https://git.example.test/acme/widgets.git
@@ -33,6 +74,9 @@ printf '%s\n' "$url" >> "${MOSAIC_STUB_URL_LOG:?}"
 
 case "$url" in
     */branches/*)
+        if [[ "${MOSAIC_STUB_BRANCH_MODE:-ok}" == "hang-before-provider" ]]; then
+            while :; do :; done
+        fi
         if [[ "${MOSAIC_STUB_BRANCH_MODE:-ok}" == "unreachable" ]]; then
             exit 7
         fi
@@ -44,6 +88,7 @@ case "$url" in
         fi
         ;;
     */status)
+        : > "${MOSAIC_STUB_STATUS_OBSERVED:?}"
         case "${MOSAIC_STUB_STATUS_MODE:?}" in
             success)   printf '%s' '{"state":"success","statuses":[{"status":"success"}]}' ;;
             pending)   printf '%s' '{"state":"pending","statuses":[{"status":"pending","context":"ci/test"}]}' ;;
@@ -63,7 +108,31 @@ case "$url" in
     *) echo "unexpected curl URL: $url" >&2; exit 2 ;;
 esac
 SH
-chmod +x "$STUB_DIR/curl"
+
+cat > "$STUB_DIR/date" <<'SH'
+#!/usr/bin/env bash
+set -euo pipefail
+
+if [[ "$#" -ne 1 || "$1" != "+%s" ]]; then
+    echo "unexpected date invocation: $*" >&2
+    exit 2
+fi
+
+if [[ -e "${MOSAIC_STUB_STATUS_OBSERVED:?}" ]]; then
+    printf 'date-phase=after-status\n' >> "${MOSAIC_STUB_CLOCK_LOG:?}"
+    printf '1002\n'
+else
+    printf 'date-phase=before-status\n' >> "${MOSAIC_STUB_CLOCK_LOG:?}"
+    printf '1000\n'
+fi
+SH
+
+cat > "$STUB_DIR/sleep" <<'SH'
+#!/usr/bin/env bash
+set -euo pipefail
+printf 'sleep-after-status=%s\n' "$*" >> "${MOSAIC_STUB_CLOCK_LOG:?}"
+SH
+chmod +x "$STUB_DIR/curl" "$STUB_DIR/date" "$STUB_DIR/sleep"
 
 run_guard() {
     local status_mode="$1"
@@ -83,13 +152,46 @@ run_guard() {
             export GITEA_URL=https://git.example.test
             export MOSAIC_STUB_STATUS_MODE="$status_mode"
         fi
+        rm -f "$STATUS_OBSERVED" "$CLOCK_LOG"
         export MOSAIC_STUB_URL_LOG="$WORK_DIR/urls.log"
+        export MOSAIC_STUB_STATUS_OBSERVED="$STATUS_OBSERVED"
+        export MOSAIC_STUB_CLOCK_LOG="$CLOCK_LOG"
         export MOSAIC_CI_QUEUE_AUDIT_LOG="$audit_log"
-        "$SCRIPT_DIR/ci-queue-wait.sh" --purpose "${MOSAIC_TEST_PURPOSE:-push}" -t 0 -i 0 "$@"
+        # Provider observation is the synchronization event. The one-second
+        # timeout is subject semantics under virtual time, never a wall wait.
+        # The absolute Python runtime uses an internal monotonic wait and kills
+        # the subject's isolated process group. Neither operation can resolve
+        # to the virtual date/sleep stubs at the front of PATH.
+        local subject_rc
+        if "$WATCHDOG_PYTHON" "$WATCHDOG_SCRIPT" "$WATCHDOG_TIMEOUT_SEC" \
+            "$SCRIPT_DIR/ci-queue-wait.sh" --purpose "${MOSAIC_TEST_PURPOSE:-push}" -t 1 -i 1 "$@"; then
+            subject_rc=0
+        else
+            subject_rc=$?
+        fi
+        return "$subject_rc"
     )
 }
 
 failures=0
+assert_provider_observed() {
+    local name="$1" require_expiration="${2:-0}"
+    if [[ ! -e "$STATUS_OBSERVED" ]]; then
+        echo "FAIL $name: status provider was not observed" >&2
+        failures=$((failures + 1))
+    fi
+    if [[ ! -s "$CLOCK_LOG" ]] || ! grep -q '^date-phase=before-status$' "$CLOCK_LOG"; then
+        echo "FAIL $name: virtual clock interception did not run before provider observation" >&2
+        failures=$((failures + 1))
+    fi
+    if [[ "$require_expiration" -eq 1 ]]; then
+        if ! grep -q '^sleep-after-status=' "$CLOCK_LOG" || ! grep -q '^date-phase=after-status$' "$CLOCK_LOG"; then
+            echo "FAIL $name: pending path did not expire after provider observation" >&2
+            failures=$((failures + 1))
+        fi
+    fi
+}
+
 run_assertion() {
     local name="$1" expected_rc="$2" status_mode="$3" required_text="$4"
     local output rc
@@ -124,6 +226,13 @@ run_assertion() {
         printf '%s\n' "$output" >&2
         failures=$((failures + 1))
     fi
+    if [[ "$status_mode" != "credential-unresolvable" ]]; then
+        if [[ "$status_mode" == "pending" ]]; then
+            assert_provider_observed "$name" 1
+        else
+            assert_provider_observed "$name"
+        fi
+    fi
 }
 
 set -e
@@ -140,6 +249,27 @@ run_assertion large-payload not126 large-success 'state=terminal-success'
 run_assertion credential-unresolvable zero credential-unresolvable 'CANNOT_ASSERT'
 run_assertion provider-unreachable zero unreachable 'CANNOT_ASSERT'
 
+# Positive liveness control: a subject mutant hangs before the branch lookup
+# can reach the status provider. Only the independent real-clock watchdog may
+# terminate it, and its failure must be distinct from subject timeout rc=124.
+set +e
+watchdog_output=$(MOSAIC_STUB_BRANCH_MODE=hang-before-provider run_guard success "$AUDIT_LOG" 2>&1)
+watchdog_rc=$?
+set -e
+if [[ "$watchdog_rc" -ne "$WATCHDOG_EXIT" ]]; then
+    echo "FAIL watchdog-control: expected hang-specific rc=$WATCHDOG_EXIT, got rc=$watchdog_rc" >&2
+    failures=$((failures + 1))
+fi
+if [[ "$watchdog_output" != *"FAIL HANG watchdog:"* ]]; then
+    echo "FAIL watchdog-control: expected distinct hang-specific diagnostic" >&2
+    printf '%s\n' "$watchdog_output" >&2
+    failures=$((failures + 1))
+fi
+if [[ -e "$STATUS_OBSERVED" ]]; then
+    echo "FAIL watchdog-control: hanging mutant unexpectedly reached the status provider" >&2
+    failures=$((failures + 1))
+fi
+
 if [[ ! -s "$AUDIT_LOG" ]] || ! grep -q '"outcome":"CANNOT_ASSERT"' "$AUDIT_LOG"; then
     echo "FAIL provider-unreachable-audit: expected durable CANNOT_ASSERT JSONL record" >&2
     failures=$((failures + 1))
@@ -160,6 +290,7 @@ if [[ "$merge_unreachable_output" != *"CANNOT_ASSERT"* ]]; then
     echo "FAIL merge-provider-unreachable: expected loud CANNOT_ASSERT diagnostic" >&2
     failures=$((failures + 1))
 fi
+assert_provider_observed merge-provider-unreachable
 merge_audit_lines_after=$(wc -l < "$AUDIT_LOG")
 if [[ "$merge_audit_lines_after" -le "$merge_audit_lines_before" ]]; then
     echo "FAIL merge-provider-unreachable: expected an additional audit record" >&2
@@ -223,6 +354,7 @@ if [[ "$audit_failure_output" != *"audit"* ]]; then
     echo "FAIL audit-unavailable: expected loud audit failure diagnostic" >&2
     failures=$((failures + 1))
 fi
+assert_provider_observed audit-unavailable
 
 if [[ "$failures" -ne 0 ]]; then
     echo "ci-queue-wait tri-state regression failed ($failures assertions)" >&2