CHANGELOG.md

@@ -5,6 +5,40 @@ which records not just what changed but what each drill run proved.
 
 ## Unreleased
 
+### 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. The sibling `ufw status | grep -q` calls in `drill/wipe.sh`,
+  `drill/doctor.sh` and `host/teardown-host.sh` are the same shape but do
+  not set `pipefail`, so the SIGPIPE is discarded there and the branch holds.
+- **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.
+
 ### Added
 
 - **Merging the release PR IS the release — and the release re-arms main

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

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 "" \