Merge pull request #106 from dan-claude-bot/fix/ufw-test-flake

fix: the fresh-UFW test block no longer flakes on a missing log

CHANGELOG.md

@@ -34,6 +34,44 @@ which records not just what changed but what each drill run proved.
 
 ### Fixed
 
+- **`box-firewall` could hand a UFW host the no-UFW firewall, ~2% of the
+  time** (#102) — filed as an intermittent test flake (`test/cli.sh`'s
+  fresh-UFW block going four-assertions-red on an unmodified `main`,
+  measured here at 5 failing runs in 40), it was not one. The branch that
+  decides the host's entire firewall stance read
+  `ufw status | grep -q "Status: active"`, and `Status: active` is the FIRST
+  line ufw prints: `grep -q` matches it and exits immediately, closing the
+  pipe while ufw is still writing the rest of the table, so ufw dies of
+  SIGPIPE. `grep` returned 0, but under this script's `set -o pipefail` the
+  PIPELINE returns 141 — the `if` reads false and a host with UFW plainly
+  active takes the nft-fallback branch, never building the DNS carve-out its
+  persisted rules depend on. A pure scheduling race, isolated at ~2% per
+  invocation (`PIPESTATUS` = `141 0`; a draining reader flakes 0/2000, a
+  reader whose match is on the last line flakes 0/2000). Real ufw is a
+  slower, longer writer than the test shim, so production had no reason to
+  be safer. `ufw status` is now read ONCE into a variable and matched with
+  `[[ ]]` — no reader, no race — and the stale-rule scan reads that same
+  snapshot, so the branch decision and the converge loop can no longer
+  disagree. **`host/teardown-host.sh` carried the same live defect** and is
+  fixed with it: that file does set `pipefail` (line 12), so its UFW
+  crumb-removal branch could read a plainly-active UFW as inactive and skip
+  silently, leaving stale `boxnet`/`claudenet` rules on a host the operator
+  was told is clean — and its numbered-delete loop had the same early-exit
+  reader as its condition, so it could end while rules remained. Both now
+  read captures. The sibling calls in `drill/wipe.sh` and `drill/doctor.sh`
+  are the same shape but set only `set -u`, so the SIGPIPE is discarded
+  there and the branch holds — latent, not live, until either gains
+  `pipefail`.
+- **A missing firewall log now diagnoses itself** (#102) — the four greps
+  reading `$WFW/*.log` used to fail together with empty output when the
+  driving run took the wrong branch, a signature that looks specific and
+  says nothing (#102 was filed reading it as "the log is not written";
+  the log existed, the mutations did not, and that distinction *was* the
+  diagnosis). `test/cli.sh` now asserts the precondition explicitly before
+  the content greps and, on failure, prints the contents of `$WFW`, the log
+  itself, and the stderr of the run that should have written it. It also
+  keeps `an agreeing UFW host deletes nothing` honest: that check asserts an
+  absence, which a run that did nothing at all passes for the wrong reason.
 - **`box grant` provisions an `incus-admin` member instead of refusing them**
   (#99) — the refusal read "they already have the admin tier; there is
   nothing tighter to grant", which is true about *permission* and silent
@@ -108,6 +146,7 @@ which records not just what changed but what each drill run proved.
   opens as them, and dropping `incus-admin` leaves them in their own project
   with no re-grant.
 
+
 ## 0.7.0 — 2026-07-19
 
 ### Added

host/box-firewall.sh

@@ -19,7 +19,35 @@ NET=boxnet
 # ('|| true': under pipefail an absent bridge would kill the script here.)
 GW="$(ip -4 -o addr show dev "$NET" 2>/dev/null | awk '{ split($4, a, "/"); print a[1]; exit }' || true)"
 
-if command -v ufw >/dev/null && ufw status 2>/dev/null | grep -q "Status: active"; then
+# Read `ufw status` ONCE, into a variable, instead of piping it at a matcher.
+# The pipe it replaces — `ufw status | grep -q "Status: active"` — was a latent
+# branch-flipper, and the branch it flips is the whole firewall. "Status:
+# active" is the FIRST line ufw prints, so `grep -q` matches it and exits
+# immediately, closing the read end while ufw is still writing the rest of the
+# table; ufw then dies of SIGPIPE (141). `grep` reported 0, but under the
+# `set -o pipefail` at the top of this file the PIPELINE reports 141, so the
+# `if` reads false and a host with UFW plainly active takes the no-UFW branch
+# below — installing the nft fallback table and never building the DNS
+# carve-out its persisted rules are counting on. It is a pure scheduling race
+# between two processes, which is the worst possible property for a decision
+# this load-bearing: measured at ~2% per invocation under test/cli.sh's shims
+# (#102, where it surfaced as an intermittent four-assertions-red test and got
+# read as flakiness for exactly as long as it was cheaper to re-run than to
+# diagnose). Real ufw is a Python program with a slower, longer write than the
+# shim's single printf, so there is no reason to think production is safer.
+# A variable has no reader that can exit early, so the race cannot exist.
+# The capture doubles as the snapshot the converge loop below reads, so the
+# branch decision and the stale-rule scan are made against the same text
+# rather than two reads that could disagree across an intervening change.
+# ('|| true': ufw exits non-zero when it cannot read its config, and under
+# pipefail+errexit that would kill the script instead of falling through to
+# the nft branch, which is the correct answer for "ufw is not usable here".)
+UFW_STATUS=""
+if command -v ufw >/dev/null; then
+  UFW_STATUS="$(ufw status 2>/dev/null || true)"
+fi
+
+if [[ "$UFW_STATUS" == *"Status: active"* ]]; then
   if [ -z "$GW" ]; then
     echo "box-firewall: $NET has no address yet — UFW DNS carve-out left as-is (no rule beats a wrong one; the persisted rules survive boots, and setup-host or a service restart converges them once the bridge is addressed)" >&2
   else
@@ -32,7 +60,9 @@ if command -v ufw >/dev/null && ufw status 2>/dev/null | grep -q "Status: active
     # anywhere else, then ensure the live set: ufw skips a rule that already
     # exists, so the re-run is a no-op and a fresh host gets exactly the
     # rules it always did.
-    for stale in $(ufw status | awk -v net="$NET" -v gw="$GW" '
+    # Scanned off the same $UFW_STATUS snapshot the branch was decided from —
+    # see the capture above for why this is not a second `ufw status` call.
+    for stale in $(printf '%s\n' "$UFW_STATUS" | awk -v net="$NET" -v gw="$GW" '
         $2 ~ /^53\// && $3 == "on" && $4 == net && $1 != gw { print $1 }' | sort -u); do
       ufw delete allow in on "$NET" to "$stale" port 53 proto tcp || true
       ufw delete allow in on "$NET" to "$stale" port 53 proto udp || true

host/teardown-host.sh

@@ -57,10 +57,37 @@ sudo systemctl daemon-reload
 
 # Firewall crumbs — UFW rules mentioning either network (numbers shift after
 # each delete, so re-scan and remove the first match until none remain)
-if command -v ufw >/dev/null && sudo ufw status 2>/dev/null | grep -q "Status: active"; then
+# Every ufw read is CAPTURED before it is matched, never piped into a reader
+# that can exit early — the same discipline box-firewall.sh now uses, and for
+# the same measured reason (#102). This file sets `pipefail` (line 12), so
+# `ufw status | grep -q "Status: active"` returns the WRITER's exit: grep
+# matches on the first line ufw prints, closes the pipe, ufw takes SIGPIPE,
+# and the pipeline yields 141. A plainly-active UFW then reads as inactive
+# and this entire block silently skips, leaving stale boxnet/claudenet rules
+# on a host the operator was told is clean. It is a branch condition, so
+# errexit never fires — there is no error to see, which is exactly why it
+# went unnoticed here while the same shape was being measured next door.
+#
+# The numbered loop had the same defect for a different reason: its condition
+# was also an early-exit reader, so it could end while rules remained. It now
+# reads one capture per iteration and breaks on absence — the re-scan is still
+# per-delete (numbers shift after each removal), just no longer racing.
+ufw_status=""
+if command -v ufw >/dev/null; then
+  # '|| true': ufw exits non-zero when it cannot read its config, and under
+  # pipefail+errexit that would kill a teardown instead of correctly deciding
+  # "no usable ufw here, nothing to clean".
+  ufw_status="$(sudo ufw status 2>/dev/null || true)"
+fi
+
+if [[ "$ufw_status" == *"Status: active"* ]]; then
   for net in boxnet claudenet; do
-    while sudo ufw status numbered | grep -q "on $net"; do
-      n="$(sudo ufw status numbered | grep -m1 "on $net" | sed -E 's/^\[ *([0-9]+)\].*/\1/')"
+    while :; do
+      numbered="$(sudo ufw status numbered 2>/dev/null || true)"
+      line="$(printf '%s\n' "$numbered" | grep -m1 "on $net" || true)"
+      [ -n "$line" ] || break
+      n="$(printf '%s\n' "$line" | sed -E 's/^\[ *([0-9]+)\].*/\1/')"
+      [ -n "$n" ] || break
       sudo ufw --force delete "$n"
     done
   done

test/cli.sh

@@ -1255,10 +1255,57 @@ SHIM
 chmod +x "$UFWSHIM/ufw" "$FWSHIM/nft" "$FWSHIM/sysctl" "$FWSHIM/iptables"
 
 runfw() { # runfw <ufw|noufw> [VAR=val ...] — the real box-firewall, under shims
-  local mode="$1" p; shift
+  local mode="$1" p rc=0; shift
   p="$FWSHIM:$SHIMDIR:$PATH"
   [ "$mode" = ufw ] && p="$UFWSHIM:$p"
-  env PATH="$p" "$@" bash "$ROOT/host/box-firewall.sh"
+  # Stderr is captured to a file AND re-emitted, rather than only passed
+  # through. The driving `check` swallows the output of a run that passes, so
+  # when a later grep over the log fails there is nothing left to read — which
+  # is precisely the hole #102 fell into. Keeping a copy on disk lets
+  # fwlog_ready below show what the run actually said. Overwritten per call by
+  # design: every fwlog_ready sits immediately after its own runfw, so "the
+  # last run" is always the run being diagnosed.
+  env PATH="$p" "$@" bash "$ROOT/host/box-firewall.sh" 2>"$WFW/last-run.err" || rc=$?
+  cat "$WFW/last-run.err" >&2
+  return "$rc"
+}
+
+# fwlog_ready <log> — the shimmed ufw actually logged mutations to <log>.
+#
+# Why this exists (#102): every grep in the blocks below reads a log written by
+# the shimmed ufw during the driving `runfw` check. When something stops the
+# UFW branch of box-firewall.sh from running at all, that log is missing — or,
+# as it turned out, present but holding nothing except the `ufw status` probe.
+# The greps then fail four-at-a-time with empty output: a signature that looks
+# alarmingly specific and carries no information whatsoever. #102 was filed
+# reading it as "the log is not written", which was a reasonable inference from
+# four blank failures and was also wrong; the file was there, the mutations
+# were not, and that distinction is the entire diagnosis. So assert the
+# precondition explicitly, before the content greps, and on failure print what
+# IS in $WFW, what the log itself holds, and what the run wrote to stderr. The
+# fix below should mean this never fires — it is here for the next cause, not
+# this one, and its whole job is to hand over the evidence instead of making
+# the next person re-derive it from a re-run loop.
+fwlog_ready() {
+  local log="$1" muts
+  if [ -f "$log" ]; then
+    muts="$(grep -vc "^ufw status" "$log")"
+    [ "$muts" -gt 0 ] && return 0
+    echo "DIAGNOSIS: $log exists but logs no ufw MUTATION (only 'ufw status')."
+    echo "  => box-firewall.sh took its no-UFW branch; the UFW carve-out never ran."
+  else
+    echo "DIAGNOSIS: $log does not exist — the shimmed ufw was never invoked."
+  fi
+  echo "  \$WFW ($WFW) holds:"
+  # shellcheck disable=SC2012  # a human-read diagnostic dump, not parsed: `ls -la`
+  # shows sizes and mtimes, which is the whole point here (a zero-byte log and a
+  # log that was never created are different failures). $WFW is our own mktemp -d.
+  ls -la "$WFW" 2>&1 | sed 's/^/    /'
+  echo "  contents of $(basename "$log"):"
+  { [ -f "$log" ] && cat "$log" || echo "(absent)"; } 2>&1 | sed 's/^/    /'
+  echo "  stderr of the run that should have written it:"
+  { [ -s "$WFW/last-run.err" ] && cat "$WFW/last-run.err" || echo "(empty)"; } 2>&1 | sed 's/^/    /'
+  return 1
 }
 
 # Canned `ufw status` tables, modeled on the real output shape.
@@ -1287,6 +1334,7 @@ BX89='5: boxnet    inet 10.89.0.1/24 scope global boxnet'
 # 10.88's carve-out — the stale allows go, the live gateway's land.
 check "box-firewall: a remapped bridge CONVERGES the UFW carve-out" 0 "" \
   runfw ufw FAKE_IP4_BOXNET="$BX89" FAKE_UFW_STATUS="$U_OLDGW" FAKE_UFW_LOG="$WFW/remap.log"
+check "box-firewall: ...the run logged ufw mutations at all" 0 "" fwlog_ready "$WFW/remap.log"
 check "box-firewall: ...the stale tcp allow is deleted" 0 "" \
   grep -qF 'ufw delete allow in on boxnet to 10.88.0.1 port 53 proto tcp' "$WFW/remap.log"
 check "box-firewall: ...and the stale udp allow" 0 "" \
@@ -1302,12 +1350,17 @@ check "box-firewall: ...the live gateway's rules are never deleted" 1 "" \
 # (ufw itself skips the re-adds as existing rules).
 check "box-firewall: an agreeing UFW host deletes nothing" 0 "" \
   runfw ufw FAKE_IP4_BOXNET="$BX89" FAKE_UFW_STATUS="$U_LIVEGW" FAKE_UFW_LOG="$WFW/agree.log"
+# This one matters more than it looks: "no delete was issued" is an ASSERT-ABSENT
+# check, so a run that issued nothing at all passes it for the wrong reason.
+# fwlog_ready is what keeps the absence meaningful.
+check "box-firewall: ...the run logged ufw mutations at all" 0 "" fwlog_ready "$WFW/agree.log"
 check "box-firewall: ...no delete was issued" 1 "" grep -qF ' delete ' "$WFW/agree.log"
 
 # The fresh host: no boxnet rules yet — exactly the five historical commands,
 # aimed at the live gateway, and nothing else (unchanged behavior).
 check "box-firewall: a fresh UFW host runs clean" 0 "" \
   runfw ufw FAKE_IP4_BOXNET="$BX88" FAKE_UFW_STATUS="$U_FRESH" FAKE_UFW_LOG="$WFW/fresh.log"
+check "box-firewall: ...the run logged ufw mutations at all" 0 "" fwlog_ready "$WFW/fresh.log"
 check "box-firewall: ...the deny lands" 0 "" \
   grep -qF 'ufw insert 1 deny in on boxnet' "$WFW/fresh.log"
 check "box-firewall: ...the DNS allows aim at the live gateway" 0 "" \
@@ -1642,6 +1695,27 @@ check "teardown-host: honors --yes/BOX_YES (CI runs it unattended)" 0 "" \
   grep -qF 'BOX_YES' "$ROOT/host/teardown-host.sh"
 check "teardown-host: points at box uninstall when done" 0 "" \
   grep -qF "box uninstall" "$ROOT/host/teardown-host.sh"
+
+# #102's race, in the one other file that sets pipefail. A daemon-free run
+# cannot exercise a UFW teardown, so the shape is pinned instead: no `ufw
+# status` may be piped into an early-exit reader here, because under this
+# file's pipefail the reader's match closes the pipe, ufw takes SIGPIPE, and
+# the branch silently reads false — skipping crumb removal on a host the
+# operator was told is clean. Both directions: the racing shape absent, the
+# capture present.
+# Comment lines are stripped before matching: the fix's own commentary quotes
+# the racing shape to explain it, and a pin that cannot tell prose from code
+# would fail on the very comment documenting why it exists.
+# shellcheck disable=SC2016  # "$1" is the subshell's positional, passed below
+check "teardown-host: no 'ufw status' piped into an early-exit reader" 0 "" \
+  bash -c 'grep -vE "^[[:space:]]*#" "$1" | grep -qE "ufw status[^|]*\| *grep" && exit 1; exit 0' \
+    _ "$ROOT/host/teardown-host.sh"
+# shellcheck disable=SC2016  # the $-strings are literals in the target file
+check "teardown-host: the UFW branch reads a captured snapshot" 0 "" \
+  grep -qF 'if [[ "$ufw_status" == *"Status: active"* ]]; then' "$ROOT/host/teardown-host.sh"
+# shellcheck disable=SC2016  # ditto
+check "teardown-host: the numbered-delete loop breaks on absence, not on a pipe" 0 "" \
+  grep -qF '[ -n "$line" ] || break' "$ROOT/host/teardown-host.sh"
 check "drill: reads the installed tree through current/" 0 "" \
   grep -qF '.local/share/box/current/VERSION' "$ROOT/drill/drill.sh"