From 0e309135916bf8874df6c82ad54329ba67350b5a Mon Sep 17 00:00:00 2001 From: Luke Curley Date: Sat, 10 Oct 2026 09:42:35 -0700 Subject: [PATCH 1/4] quest: claim interop close log Co-Authored-By: GPT-6 From 89aca859ae1fc52c7988634d3a5d617432c3b8e5 Mon Sep 17 00:00:00 2001 From: Luke Curley Date: Sat, 10 Oct 2026 09:54:23 -0700 Subject: [PATCH 2/4] fix(test): preserve relay close logs in interop rounds Co-Authored-By: GPT-6 --- quest/m1/README.md | 1 - quest/m1/interop-close-log.md | 22 ------------- test/interop/interop.sh | 59 ++++----------------------------- test/interop/relay-log.sh | 60 ++++++++++++++++++++++++++++++++++ test/interop/relay-log.test.sh | 27 +++++++++++++++ test/justfile | 1 + 6 files changed, 95 insertions(+), 75 deletions(-) delete mode 100644 quest/m1/interop-close-log.md create mode 100644 test/interop/relay-log.sh create mode 100755 test/interop/relay-log.test.sh diff --git a/quest/m1/README.md b/quest/m1/README.md index 25c59174d5..be2def5216 100644 --- a/quest/m1/README.md +++ b/quest/m1/README.md @@ -203,4 +203,3 @@ ladders. - [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 diff --git a/quest/m1/interop-close-log.md b/quest/m1/interop-close-log.md deleted file mode 100644 index 8268fe0a97..0000000000 --- a/quest/m1/interop-close-log.md +++ /dev/null @@ -1,22 +0,0 @@ -# [XS] The interop idle-out check reads the relay's close log at a fixed level - -## Goal - -The interop harness's idle-out check never misreads a clean close as an open -connection because of the relay's log level. - -## Plan - -Found while merging #5174 (2026-10-10): the relay logs a clean -`connection closed` at info and an error close at warn, and the harness -counts those lines to decide every connection closed. If the interop relay -ever runs at warn, every clean close would read as still open and fail the -round. - -Decided 2026-10-10: pin the harness's relay log filter for the close-log -target to info in `test/interop/interop.sh`, so the product keeps warn for -error closes. Rejected: logging both at one level in moq-relay. Also fail -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. diff --git a/test/interop/interop.sh b/test/interop/interop.sh index 27886383ab..fadaab4558 100755 --- a/test/interop/interop.sh +++ b/test/interop/interop.sh @@ -477,7 +477,10 @@ if [[ -n "${INTEROP_VERSION:-}" ]]; then exit 1 } 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 @@ -485,6 +488,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" + # ── client dispatch ───────────────────────────────────────────────────────── # Encode an endless H.264 Annex-B stream from a synthetic source to stdout. # Paced with -re so the broadcast streams in real time until the reader closes. @@ -572,57 +578,6 @@ relay_next_line() { } # 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 ecf90ca316..f4ded6a5b7 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 From f79f4f3e00baf2cf0deaacf04647a10b24deaf3d Mon Sep 17 00:00:00 2001 From: Luke Curley Date: Sat, 10 Oct 2026 21:29:27 -0700 Subject: [PATCH 3/4] quest: retain close-log validation blocker Co-Authored-By: GPT-6 Astra --- quest/m1/README.md | 2 ++ quest/m1/interop-close-log.md | 26 ++++++++++++++++++++++++++ 2 files changed, 28 insertions(+) create mode 100644 quest/m1/interop-close-log.md diff --git a/quest/m1/README.md b/quest/m1/README.md index 1fd0be36ee..7d576b0dfc 100644 --- a/quest/m1/README.md +++ b/quest/m1/README.md @@ -42,6 +42,8 @@ bench all require its crate. ## Required +- [Interop close logs](/quest/m1/interop-close-log.md) - logging fix validated; required TS validation remains blocked + - [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 diff --git a/quest/m1/interop-close-log.md b/quest/m1/interop-close-log.md new file mode 100644 index 0000000000..f08e8ce5a4 --- /dev/null +++ b/quest/m1/interop-close-log.md @@ -0,0 +1,26 @@ +# [XS] The interop idle-out check reads the relay's close log at a fixed level + +## Goal + +The interop harness's idle-out check never misreads a clean close as an open +connection because of the relay's log level. + +## Plan + +Found while merging #5174 (2026-10-10): the relay logs a clean +`connection closed` at info and an error close at warn, and the harness +counts those lines to decide every connection closed. If the interop relay +ever runs at warn, every clean close would read as still open and fail the +round. + +Decided 2026-10-10: pin the harness's relay log filter for the close-log +target to info in `test/interop/interop.sh`, so the product keeps warn for +error closes. Rejected: logging both at one level in moq-relay. Also fail +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 measured stdin improvement in #5292 does not establish hosted causality. From 4a38015b90470da0668b4547965c0d99589b09d8 Mon Sep 17 00:00:00 2001 From: Luke Curley Date: Sun, 11 Oct 2026 12:07:37 -0700 Subject: [PATCH 4/4] quest(m1): note #5292 merged in interop close-log validation Co-Authored-By: Claude Opus 5.5 --- quest/m1/README.md | 3 +-- quest/m1/interop-close-log.md | 2 +- 2 files changed, 2 insertions(+), 3 deletions(-) diff --git a/quest/m1/README.md b/quest/m1/README.md index 24b06c7f88..75dec138c1 100644 --- a/quest/m1/README.md +++ b/quest/m1/README.md @@ -45,8 +45,7 @@ session outcomes, and embedder refusals inside session outcomes. ## Required -- [Interop close logs](/quest/m1/interop-close-log.md) - logging fix validated; required TS validation remains blocked - +- [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 diff --git a/quest/m1/interop-close-log.md b/quest/m1/interop-close-log.md index f08e8ce5a4..891b8a123e 100644 --- a/quest/m1/interop-close-log.md +++ b/quest/m1/interop-close-log.md @@ -23,4 +23,4 @@ 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 measured stdin improvement in #5292 does not establish hosted causality. +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.