diff --git a/quest/m1/README.md b/quest/m1/README.md index 3136b7c6bf..75dec138c1 100644 --- a/quest/m1/README.md +++ b/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 diff --git a/quest/m1/interop-close-log.md b/quest/m1/interop-close-log.md index 8268fe0a97..891b8a123e 100644 --- a/quest/m1/interop-close-log.md +++ b/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. diff --git a/test/interop/interop.sh b/test/interop/interop.sh index 63370628db..7e6db609e8 100755 --- a/test/interop/interop.sh +++ b/test/interop/interop.sh @@ -549,7 +549,10 @@ 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 @@ -557,6 +560,9 @@ if ! harness_ready "$URL/certificate.sha256" 30 "$HARNESS_PID"; then 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 diff --git a/test/interop/relay-log.sh b/test/interop/relay-log.sh new file mode 100644 index 0000000000..bc96ec5ea4 --- /dev/null +++ b/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 +} diff --git a/test/interop/relay-log.test.sh b/test/interop/relay-log.test.sh new file mode 100755 index 0000000000..39254fe905 --- /dev/null +++ b/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' diff --git a/test/justfile b/test/justfile index 30114d289d..ad8a62bfa7 100644 --- a/test/justfile +++ b/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