fix(test): preserve relay close logs in interop rounds

quest/m1/README.md

@@ -45,6 +45,7 @@ session outcomes, and embedder refusals inside session outcomes.
 
 ## Required
 
+- [Interop close logs](/quest/m1/interop-close-log.md) - logging fix landed; delete once the required Interop run is green
 - [One max_age meaning](/quest/m1/cache-max-age.md) - a superseded group goes stale on wall clock since its successor arrived or on media time, whichever is first, in Rust and js/net; fixes the untimed failover stall
 - [FETCH max-delay](/quest/m1/fetch-max-delay.md) - historical readers obey publisher max-age and an optional tighter reader budget, including while holding a group
 - [Upstream position regression](/quest/m1/largest-regression.md) - a relay copy that sees upstream's largest group go backwards on moq-transport or epochless lite-07 fails loud instead of serving the old instance's cache
@@ -199,7 +200,6 @@ session outcomes, and embedder refusals inside session outcomes.
 - [moqsrc reconnect](/quest/m1/moqsrc-reconnect.md) - `moqsrc` redials after losing its relay and resumes on the same pads
 - [moq fetch closes cleanly](/quest/m1/moq-fetch-close.md) - `moq fetch` closes its session before exiting instead of leaving the relay to time it out
 - [Terminal dial errors](/quest/m1/moq-tokio-terminal-errors.md) - moq-tokio's reconnect loop stops on errors that can never succeed
-- [Interop close log](/quest/m1/interop-close-log.md) - the interop idle-out check reads the relay close log at a pinned level
 
 ## Related
 

quest/m1/interop-close-log.md

@@ -20,3 +20,7 @@ the round loudly when the relay log shows no connection for it, so a filter
 that hides the `conn{id=...}` and close lines can't pass as nothing open.
 
 Public API: none. Wire: none.
+
+### Validation remaining
+
+The implementation and shell regression are complete in [#5215](https://github.com/moq-dev/moq/pull/5215). Full checks and all-language interop pass with inherited `RUST_LOG=warn`. Keep this quest until the required Interop CI is green: hosted TS captured 3.27/20.06 seconds, and the independent current-main local headroom run stops at a PID 256 decode deadline (0.50/20.06 seconds). Neither failure has been attributed to relay-log accounting. Do not weaken duration or deadline checks. The stdin throughput fix in #5292 has merged; delete this quest once the required Interop run passes with it.

test/interop/interop.sh

@@ -549,14 +549,20 @@ else
     sed -e "s|:4443\"|:${PORT}\"|g" -e "s|http://127.0.0.1:4440/|${AUTH_URL}|" \
         "$INTEROP_DIR/interop.toml" >"$HARNESS_RUN/relay.toml"
 fi
-harness_spawn relay "$HARNESS_RUN/relay.log" "$RELAY" "$HARNESS_RUN/relay.toml"
+# Connection spans and clean closes must survive an inherited warn-only filter.
+harness_spawn relay "$HARNESS_RUN/relay.log" env \
+    "RUST_LOG=${RUST_LOG:+$RUST_LOG,}moq_relay::connection=info,moq_relay::relay=info" \
+    "$RELAY" "$HARNESS_RUN/relay.toml"
 if ! harness_ready "$URL/certificate.sha256" 30 "$HARNESS_PID"; then
     echo "relay never became ready" >&2
     sed 's/^/  relay: /' "$HARNESS_RUN/relay.log" >&2 || true
     exit 1
 fi
 harness_endpoint relay "$URL"
 
+# shellcheck source-path=SCRIPTDIR source=relay-log.sh
+source "$INTEROP_DIR/relay-log.sh"
+
 # ── tokens ──────────────────────────────────────────────────────────────────
 # Print the relay URL carrying a fresh token; the arguments are `moq auth sign`'s
 # (`--publish P`, `--subscribe S`). Compat runs anonymous, so it prints the bare URL.
@@ -702,58 +708,6 @@ relay_next_line() {
     echo $(($(wc -l <"$HARNESS_RUN/relay.log") + 1))
 }
 
-# The relay log from line FROM on, without its ANSI colors.
-relay_log_since() {
-    tail -n +"$1" "$HARNESS_RUN/relay.log" | sed 's/\x1b\[[0-9;]*m//g'
-}
-
-# Print each relay connection that appears from log line FROM on, with how it closed: the
-# relay's close error, "ended" for a close without one, or "open" while it hasn't closed yet.
-# The patterns follow the relay's `conn{id=...}` span and its `connection closed` log
-# (`rs/moq-relay/src/relay.rs`). Only connections opened in the window count, so a straggler
-# from an earlier round closing here isn't blamed on this one.
-relay_connections() {
-    relay_log_since "$1" | awk '
-        match($0, /conn\{id=[0-9]+ /) {
-            id = substr($0, RSTART + 8, RLENGTH - 9)
-            if (!(id in state)) { state[id] = "open"; order[++n] = id }
-        }
-        match($0, /connection closed id=[0-9]+/) {
-            id = substr($0, RSTART + 21, RLENGTH - 21)
-            if (id in state) {
-                rest = substr($0, RSTART + RLENGTH)
-                state[id] = sub(/^ err=/, "", rest) ? rest : "ended"
-            }
-        }
-        END { for (i = 1; i <= n; i++) print order[i], state[order[i]] }
-    '
-}
-
-# Fail the round for every relay connection it opened that idled out rather than closed.
-#
-# The relay times a silent peer out after its 10 s QUIC idle timeout, which can land long
-# after the cell that stalled finished. Every client closes its session on the way out, so
-# each close shows up at once, and an idle-out is a real stall that a reconnect would
-# otherwise hide behind a slow cell. A connection still open after the idle timeout is about
-# to idle out, so it fails the same way.
-check_idle_outs() {
-    local pub="$1" from="$2" deadline=$((SECONDS + 15)) id reason role failed=0
-    # Plain grep, not -q: under pipefail an early exit fails the pipeline on SIGPIPE.
-    while relay_connections "$from" | grep ' open$' >/dev/null && ((SECONDS < deadline)); do
-        sleep 0.2
-    done
-    while read -r id reason; do
-        [[ "$reason" == "open" || "$reason" == *"timed out"* ]] || continue
-        # The relay subscribes upstream only on the publisher's connection.
-        role=subscriber
-        relay_log_since "$from" | grep "conn{id=$id .*::subscriber: subscribe started" >/dev/null && role=publisher
-        echo "  FAIL  $pub round: relay connection $id ($role) idled out instead of closing ($reason)"
-        relay_log_since "$from" | grep -E "conn\{id=$id |connection closed id=$id " | sed 's/^/        /'
-        failed=1
-    done < <(relay_connections "$from")
-    ((failed == 0)) || overall=1
-}
-
 # Run a native-JS subscriber and judge it by the "received N bytes" marker it
 # prints, not its exit code. The @moq/web-transport NAPI addon can segfault
 # during the runtime's exit teardown *after* a frame has arrived (an upstream bug

test/interop/relay-log.sh

@@ -0,0 +1,60 @@
+#!/usr/bin/env bash
+# Relay connection accounting shared with the harness regression.
+# shellcheck disable=SC2034 # overall is the sourcing harness's exit status.
+
+relay_log_since() {
+    tail -n +"$1" "$HARNESS_RUN/relay.log" | sed 's/\x1b\[[0-9;]*m//g'
+}
+
+# Print each relay connection that appears from log line FROM on, with how it closed: the
+# relay's close error, "ended" for a close without one, or "open" while it hasn't closed yet.
+# The patterns follow the relay's `conn{id=...}` span and its `connection closed` log
+# (`rs/moq-relay/src/relay.rs`). Only connections opened in the window count, so a straggler
+# from an earlier round closing here isn't blamed on this one.
+relay_connections() {
+    relay_log_since "$1" | awk '
+        match($0, /conn\{id=[0-9]+ /) {
+            id = substr($0, RSTART + 8, RLENGTH - 9)
+            if (!(id in state)) { state[id] = "open"; order[++n] = id }
+        }
+        match($0, /connection closed id=[0-9]+/) {
+            id = substr($0, RSTART + 21, RLENGTH - 21)
+            if (id in state) {
+                rest = substr($0, RSTART + RLENGTH)
+                state[id] = sub(/^ err=/, "", rest) ? rest : "ended"
+            }
+        }
+        END { for (i = 1; i <= n; i++) print order[i], state[order[i]] }
+    '
+}
+
+# Fail the round for every relay connection it opened that idled out rather than closed.
+#
+# The relay times a silent peer out after its 10 s QUIC idle timeout, which can land long
+# after the cell that stalled finished. Every client closes its session on the way out, so
+# each close shows up at once, and an idle-out is a real stall that a reconnect would
+# otherwise hide behind a slow cell. A connection still open after the idle timeout is about
+# to idle out, so it fails the same way.
+check_idle_outs() {
+    local pub="$1" from="$2" deadline=$((SECONDS + 15)) id reason role failed=0 connections
+    # Plain grep, not -q: under pipefail an early exit fails the pipeline on SIGPIPE.
+    while relay_connections "$from" | grep ' open$' >/dev/null && ((SECONDS < deadline)); do
+        sleep 0.2
+    done
+    connections=$(relay_connections "$from")
+    if [[ -z "$connections" ]]; then
+        echo "  FAIL  $pub round: relay log contains no connections"
+        overall=1
+        return
+    fi
+    while read -r id reason; do
+        [[ "$reason" == "open" || "$reason" == *"timed out"* ]] || continue
+        # The relay subscribes upstream only on the publisher's connection.
+        role=subscriber
+        relay_log_since "$from" | grep "conn{id=$id .*::subscriber: subscribe started" >/dev/null && role=publisher
+        echo "  FAIL  $pub round: relay connection $id ($role) idled out instead of closing ($reason)"
+        relay_log_since "$from" | grep -E "conn\{id=$id |connection closed id=$id " | sed 's/^/        /'
+        failed=1
+    done <<<"$connections"
+    ((failed == 0)) || overall=1
+}

test/interop/relay-log.test.sh

@@ -0,0 +1,27 @@
+#!/usr/bin/env bash
+set -euo pipefail
+# shellcheck source-path=SCRIPTDIR source=relay-log.sh
+source "$(dirname "${BASH_SOURCE[0]}")/relay-log.sh"
+HARNESS_RUN=$(mktemp -d)
+trap 'rm -rf "$HARNESS_RUN"' EXIT
+
+# Connections from an earlier round cannot satisfy the current round's accounting.
+printf '%s\n' 'INFO conn{id=1 remote=localhost}: accepted' 'INFO connection closed id=1' >"$HARNESS_RUN/relay.log"
+overall=0
+check_idle_outs empty 3 >"$HARNESS_RUN/result"
+[[ "$overall" == 1 ]]
+grep 'relay log contains no connections' "$HARNESS_RUN/result"
+
+# A clean close is observed even with ANSI formatting, and an older close is ignored.
+printf '\033[32mINFO\033[0m conn{id=2 remote=localhost}: accepted\nINFO connection closed id=1\nINFO connection closed id=2\n' >>"$HARNESS_RUN/relay.log"
+[[ "$(relay_connections 3)" == '2 ended' ]]
+overall=0
+check_idle_outs clean 3
+[[ "$overall" == 0 ]]
+
+printf '%s\n' 'INFO conn{id=3 remote=localhost}: accepted' 'WARN connection closed id=3 err=timed out' >>"$HARNESS_RUN/relay.log"
+overall=0
+check_idle_outs timeout 6 >"$HARNESS_RUN/result"
+[[ "$overall" == 1 ]]
+grep 'idled out instead of closing' "$HARNESS_RUN/result"
+echo 'relay log regression passed'

test/justfile

@@ -22,6 +22,7 @@ default:
 # which this recipe installs, as the interop and wasm harnesses do.
 harness:
     ./lib/harness.test.sh
+    ./interop/relay-log.test.sh
     cd .. && bun test test/interop/compat/resolve.test.ts
     cd .. && bun install --frozen-lockfile
     cd interop/clients/js && bunx playwright install chromium