From 5a5faa0857b6cf5e8e585b5fb65e7474b8f667e5 Mon Sep 17 00:00:00 2001 From: Johnathan Corgan Date: Sat, 19 Sep 2026 09:11:39 +0000 Subject: [PATCH] test(nat): contain strfry relay aborts in the NAT lab The NAT-lab suites (cone, symmetric, lan, STUN faults and nostr publish/consume) share one strfry relay, and it has aborted in several runs. Three things made each abort cost a whole run and a misdirected diagnosis: only the publish/consume suite said what state the relay was in, the relay image moved with upstream's latest tag, and the relay never restarted. State the relay's condition in every NAT-lab suite. relay_verdict moves into testing/lib/relay-verdict.sh, taking the container as an argument, and is called first in every NAT-lab failure dump and on each success path, where a relay event the assertions survived is noted rather than made a failure. Before this, the cone, symmetric and lan dumps named the nodes and the network instead: hundreds of lines of socket tables and router counters, with the relay's crash lines unlabelled in an 80-line log tail. The STUN fault dump now also carries the relay's log, which it did not include. Pin the relay's strfry build. Dockerfile.app takes the strfry image as a build argument, defaulting to the same latest tag, so the user-facing example is unchanged, and the NAT lab's compose file passes the current multi-arch index digest. Which build a run exercised was never recorded before. This stops the drift; it does not select a build that does not abort, since upstream publishes no other tag to choose from. Restart the relay when it aborts. The relay ran with restart "no", so one abort left every suite sharing it without a relay for the rest of the run. It now restarts on failure up to three times, so a relay that keeps aborting still ends up exited and is reported rather than hidden in a crash loop. The restart policy is the containment. The verdict says the relay restarted under that policy and prints the fault lines from its log, which spans restarts of the same container, so a rescued run still names the event. The relay service also gains init: true, only so the restart can be exercised by an injected abort. It changes the relay's PID 1 from strfry (started with exec in the image's entrypoint) to docker's init, with strfry as its child. Without it, a SIGABRT sent with docker kill to strfry as PID 1 logged "caught a signal: SIGABRT" and left the container running with no restart, so that injection could not show the policy working. With the init, strfry signalled from inside the container exits it non-zero, which is what the real aborts did: clients saw the relay vanish. Those real aborts would restart under the policy with or without the init. Injected aborts (strfry signalled from inside the container the moment both cone nodes had connected) restarted the relay once each time; in eight of nine cone runs both nodes reconnected and peered 8 to 16 s after the abort. In the ninth, the initiator's offer went out in the second between its reconnect and the responder's, was lost, and the 30 s answer timeout pushed peering past the 45 s wait, so restart shortens the outage but does not guarantee the run. Without the restart policy the same injection left the relay exited and the cone suite timed out waiting for its peer, with no line in the dump naming the relay. --- examples/sidecar-nostr-relay/Dockerfile.app | 6 +- testing/lib/relay-verdict.sh | 85 +++++++++++++++++++++ testing/nat/README.md | 3 +- testing/nat/docker-compose.yml | 21 ++++- testing/nat/scripts/nat-test.sh | 26 +++++++ testing/nat/scripts/nostr-relay-test.sh | 66 ++-------------- testing/nat/scripts/stun-faults-test.sh | 18 ++++- 7 files changed, 160 insertions(+), 65 deletions(-) create mode 100644 testing/lib/relay-verdict.sh diff --git a/examples/sidecar-nostr-relay/Dockerfile.app b/examples/sidecar-nostr-relay/Dockerfile.app index 5f6348f7..ae59129a 100644 --- a/examples/sidecar-nostr-relay/Dockerfile.app +++ b/examples/sidecar-nostr-relay/Dockerfile.app @@ -5,7 +5,11 @@ # the final stage. Copying the strfry binary into a glibc-based image such as # debian:bookworm-slim causes "not found" at exec time because the musl dynamic # linker (/lib/ld-musl-*.so.1) and its shared libraries are absent there. -FROM ghcr.io/hoytech/strfry:latest AS strfry +# +# STRFRY_IMAGE lets a caller pin the strfry build. The default follows the +# upstream `latest` tag; the NAT test lab passes a digest. +ARG STRFRY_IMAGE=ghcr.io/hoytech/strfry:latest +FROM ${STRFRY_IMAGE} AS strfry FROM alpine:3.18 diff --git a/testing/lib/relay-verdict.sh b/testing/lib/relay-verdict.sh new file mode 100644 index 00000000..90784745 --- /dev/null +++ b/testing/lib/relay-verdict.sh @@ -0,0 +1,85 @@ +#!/bin/bash +# Shared relay verdict for the NAT-lab suites. +# +# Source this file to get relay_verdict(). +# +# Usage: +# source "$ROOT_DIR/testing/lib/relay-verdict.sh" +# relay_verdict +# +# The lab's Nostr relay is a third-party container (strfry), and it has died +# mid-run: once on a SIGSEGV twelve milliseconds after both nodes had +# connected, and several times since on an internal assertion that aborts it +# the instant two clients connect together. Every symptom under that is a +# correct report of a dead relay: subscriptions dropped, no advert consumed, +# empty peer lists, and a run that fails on the peer-count wait. That verdict +# is indistinguishable from a product failure unless the relay's state is +# stated, and the only evidence of the real cause was one container-log line +# far above the summary. relay_verdict says whose failure it was, in a line a +# reader of the output can find. + +# State the relay's own condition, in its own words. +# +# This does not decide the run. It returns 0 when the run had a relay event +# (the relay is gone, not running, restarted, faulted, or its health could not +# be read) and 1 when the relay was running with no fault in its log. Callers +# use it first in a failure dump, and on the success path to note a relay +# event the assertions survived. +# +# A relay whose state or log cannot be read has not been shown to be healthy, +# so that case is reported as unestablished rather than as "not the relay". +relay_verdict() { + local container="$1" + local state="" status="" exit_code="" restarts="" logs="" + local faults="caught a signal|SIGSEGV|SIGABRT|terminate called" + + state="$(docker inspect \ + -f '{{.State.Status}} {{.State.ExitCode}} {{.RestartCount}}' \ + "$container" 2>/dev/null)" || state="" + + if [ -z "$state" ]; then + echo "RELAY FAILURE: $container is gone; whatever this run" \ + "asserted about peering happened without a relay" >&2 + return 0 + fi + + read -r status exit_code restarts <<<"$state" + + if [ "$status" != "running" ]; then + echo "RELAY FAILURE: $container is $status (exit $exit_code);" \ + "the assertions in this run are downstream of that, not of the" \ + "nodes" >&2 + return 0 + fi + + # docker logs spans every restart of the same container, so the fault + # lines of the run that died are still readable here. + if [ "${restarts:-0}" -gt 0 ]; then + echo "RELAY FAILURE: $container restarted $restarts time(s) during" \ + "this run under its restart policy; the nodes lost their" \ + "subscriptions each time and had to reconnect" >&2 + if logs="$(docker logs "$container" 2>&1)"; then + grep -E "$faults" <<<"$logs" >&2 || true + else + echo " (its logs could not be read, so the fault lines are" \ + "not shown)" >&2 + fi + return 0 + fi + + if ! logs="$(docker logs "$container" 2>&1)"; then + echo "RELAY HEALTH NOT ESTABLISHED: could not read" \ + "$container's logs, so a crash cannot be ruled in or out" >&2 + return 0 + fi + + if grep -Eq "$faults" <<<"$logs"; then + echo "RELAY FAILURE: $container faulted during this run:" >&2 + grep -E "$faults" <<<"$logs" >&2 + return 0 + fi + + echo "relay: $container running, no fault in its log — this run's" \ + "verdict is about the nodes" + return 1 +} diff --git a/testing/nat/README.md b/testing/nat/README.md index dca37fa4..1af14b1e 100644 --- a/testing/nat/README.md +++ b/testing/nat/README.md @@ -73,7 +73,8 @@ Run one scenario: - `stun/` - minimal STUN binding responder - `relay/` - - local `strfry` config + - local `strfry` config. The relay image's strfry build is pinned by digest + in `docker-compose.yml` (`STRFRY_IMAGE`); bump it there deliberately. - `scripts/generate-configs.sh` - derives ephemeral identities and writes per-scenario FIPS configs - `scripts/setup-topology.sh` diff --git a/testing/nat/docker-compose.yml b/testing/nat/docker-compose.yml index f3dddb6d..93c2fb39 100644 --- a/testing/nat/docker-compose.yml +++ b/testing/nat/docker-compose.yml @@ -34,8 +34,27 @@ services: build: context: ../.. dockerfile: examples/sidecar-nostr-relay/Dockerfile.app + args: + # Pinned so the relay build does not move underneath the harness. + # Upstream publishes only `latest`; this is its multi-arch index + # digest as of 2026-09-19 (amd64 and arm64 manifests built + # 2026-09-04). Bump it deliberately, reading the new digest with + # `docker buildx imagetools inspect ghcr.io/hoytech/strfry:latest`. + STRFRY_IMAGE: ghcr.io/hoytech/strfry@sha256:36f1886d185a88ca57c66ebe52e6e9e8428dac2486eea0a5d50ff934f18b60c3 container_name: fips-nat-relay${FIPS_CI_NAME_SUFFIX:-} - restart: "no" + # A third-party relay abort should not fail a whole run, so the relay comes + # back on its own; relay_verdict still reports the restart and the fault + # lines. Bounded so a relay that aborts repeatedly ends up exited, and the + # verdict says so, rather than a crash loop hiding it. + # + # `init` is here so the restart can be tested, not for the restart itself. + # It makes docker's init PID 1, with strfry as its child, where strfry was + # PID 1 before. A test SIGABRT sent with `docker kill` to strfry as PID 1 + # ran its handler and left the container running, so it never exercised + # the restart. With an init, strfry signalled from inside the container + # exits it non-zero, as the relay aborts seen in the lab did. + restart: on-failure:3 + init: true volumes: - relay-data:/usr/src/app/strfry-db - ./relay/strfry.conf:/usr/src/app/strfry.conf:ro diff --git a/testing/nat/scripts/nat-test.sh b/testing/nat/scripts/nat-test.sh index cbf7c7dc..aec7aa72 100755 --- a/testing/nat/scripts/nat-test.sh +++ b/testing/nat/scripts/nat-test.sh @@ -9,6 +9,7 @@ BUILD_SCRIPT="$ROOT_DIR/testing/scripts/build.sh" GENERATE_SCRIPT="$SCRIPT_DIR/generate-configs.sh" TOPOLOGY_SCRIPT="$SCRIPT_DIR/setup-topology.sh" WAIT_LIB="$ROOT_DIR/testing/lib/wait-converge.sh" +RELAY_LIB="$ROOT_DIR/testing/lib/relay-verdict.sh" # Must track generate-configs.sh's OUTPUT_DIR and the compose bind-mounts: the # npubs are read back here after the containers are up, so reading a different # directory than the one the generator wrote pings an npub no node owns. @@ -42,6 +43,10 @@ if [ -n "${FIPS_NAT_EXTRA_COMPOSE:-}" ]; then fi source "$WAIT_LIB" +# shellcheck disable=SC1090 +source "$RELAY_LIB" + +RELAY_CONTAINER="fips-nat-relay${FIPS_CI_NAME_SUFFIX:-}" cleanup() { "${COMPOSE[@]}" --profile cone --profile symmetric --profile lan \ @@ -249,6 +254,9 @@ dump_stun_udp_probe() { } dump_cone_diagnostics() { + echo "" + echo "=== relay verdict ===" + relay_verdict "$RELAY_CONTAINER" || true echo "" echo "=== cone diagnostics ===" dump_fips_state fips-nat-cone-a${FIPS_CI_NAME_SUFFIX:-} ${NAT_WAN}.30 7777 ${NAT_WAN}.40 3478 @@ -266,6 +274,9 @@ dump_cone_diagnostics() { } dump_symmetric_diagnostics() { + echo "" + echo "=== relay verdict ===" + relay_verdict "$RELAY_CONTAINER" || true echo "" echo "=== symmetric diagnostics ===" dump_fips_state fips-nat-symmetric-a${FIPS_CI_NAME_SUFFIX:-} ${NAT_WAN}.30 7777 ${NAT_WAN}.40 3478 @@ -277,6 +288,9 @@ dump_symmetric_diagnostics() { } dump_lan_diagnostics() { + echo "" + echo "=== relay verdict ===" + relay_verdict "$RELAY_CONTAINER" || true echo "" echo "=== lan diagnostics ===" dump_fips_state fips-nat-lan-a${FIPS_CI_NAME_SUFFIX:-} ${NAT_LAN}.30 7777 ${NAT_LAN}.40 3478 @@ -434,6 +448,15 @@ ping_peer() { fi } +# A relay that faulted while a scenario's assertions still passed is a finding +# about the relay, not about the scenario, so it is reported and not made a +# failure: the scenario proved what it set out to prove. +note_relay_event() { + if relay_verdict "$RELAY_CONTAINER"; then + echo "NOTE: the assertions above passed despite that." >&2 + fi +} + run_cone() { echo "=== NAT lab: cone ===" cleanup @@ -474,6 +497,7 @@ run_cone() { dump_cone_diagnostics return 1 } + note_relay_event cleanup } @@ -519,6 +543,7 @@ run_symmetric() { dump_symmetric_diagnostics return 1 } + note_relay_event cleanup } @@ -561,6 +586,7 @@ run_lan() { dump_lan_diagnostics return 1 } + note_relay_event # Skip the final teardown when the mesh-lab harness wraps this # script: it needs to docker-logs the containers before teardown, # and will run its own cleanup after capture. Failure paths above diff --git a/testing/nat/scripts/nostr-relay-test.sh b/testing/nat/scripts/nostr-relay-test.sh index a075d05a..8cffbb2c 100755 --- a/testing/nat/scripts/nostr-relay-test.sh +++ b/testing/nat/scripts/nostr-relay-test.sh @@ -21,6 +21,7 @@ ROOT_DIR="$(cd "$NAT_DIR/../.." && pwd)" BUILD_SCRIPT="$ROOT_DIR/testing/scripts/build.sh" GENERATE_SCRIPT="$SCRIPT_DIR/generate-configs.sh" WAIT_LIB="$ROOT_DIR/testing/lib/wait-converge.sh" +RELAY_LIB="$ROOT_DIR/testing/lib/relay-verdict.sh" # Must track generate-configs.sh's OUTPUT_DIR and the compose bind-mounts. CONFIG_DIR="$NAT_DIR/generated-configs${FIPS_CI_NAME_SUFFIX:-}" @@ -52,6 +53,8 @@ RELAY_CONTAINER="fips-nat-relay${FIPS_CI_NAME_SUFFIX:-}" # shellcheck disable=SC1090 source "$WAIT_LIB" +# shellcheck disable=SC1090 +source "$RELAY_LIB" cleanup() { "${COMPOSE[@]}" --profile "$PROFILE" down -v --remove-orphans \ @@ -85,69 +88,10 @@ require_test_image() { "$BUILD_SCRIPT" } -# State the relay's own condition, in its own words, before anything else. -# -# The relay is a third-party container and it has died mid-run before: strfry -# took a SIGSEGV twelve milliseconds after both nodes had connected, and every -# symptom under that was a correct report of a dead relay — subscriptions -# dropped, no advert consumed, empty peer lists, and a run that failed on the -# peer-count wait. That verdict is indistinguishable from a product failure -# unless the relay's state is stated, and the only evidence of the real cause -# was one container-log line ninety lines above the summary. This does not -# decide the run; it says whose failure it was, in a line a reader of the -# output can find. -# -# A relay whose state or log cannot be read has not been shown to be healthy, -# so that case is reported as unestablished rather than as "not the relay". -relay_verdict() { - local state="" status="" exit_code="" restarts="" logs="" - - state="$(docker inspect \ - -f '{{.State.Status}} {{.State.ExitCode}} {{.RestartCount}}' \ - "$RELAY_CONTAINER" 2>/dev/null)" || state="" - - if [ -z "$state" ]; then - echo "RELAY FAILURE: $RELAY_CONTAINER is gone; whatever this run" \ - "asserted about peering happened without a relay" >&2 - return 0 - fi - - read -r status exit_code restarts <<<"$state" - - if [ "$status" != "running" ]; then - echo "RELAY FAILURE: $RELAY_CONTAINER is $status (exit $exit_code);" \ - "the assertions in this run are downstream of that, not of the" \ - "nodes" >&2 - return 0 - fi - - if [ "${restarts:-0}" -gt 0 ]; then - echo "RELAY FAILURE: $RELAY_CONTAINER has restarted $restarts time(s)" \ - "during this run; the nodes lost their subscriptions with it" >&2 - return 0 - fi - - if ! logs="$(docker logs "$RELAY_CONTAINER" 2>&1)"; then - echo "RELAY HEALTH NOT ESTABLISHED: could not read" \ - "$RELAY_CONTAINER's logs, so a crash cannot be ruled in or out" >&2 - return 0 - fi - - if grep -Eq "caught a signal|SIGSEGV|SIGABRT|terminate called" <<<"$logs"; then - echo "RELAY FAILURE: $RELAY_CONTAINER faulted during this run:" >&2 - grep -E "caught a signal|SIGSEGV|SIGABRT|terminate called" <<<"$logs" >&2 - return 0 - fi - - echo "relay: $RELAY_CONTAINER running, no fault in its log — this run's" \ - "verdict is about the nodes" - return 1 -} - dump_diagnostics() { echo "" echo "=== relay verdict ===" - relay_verdict || true + relay_verdict "$RELAY_CONTAINER" || true echo "" echo "=== nostr publish/consume diagnostics ===" for c in "$NODE_A" "$NODE_B" "$RELAY_CONTAINER"; do @@ -572,7 +516,7 @@ run_test() { # A relay that faulted while the assertions still passed is a finding # about the relay, not about this run, so it is reported and not made a # failure: the suite proved what it set out to prove. - if relay_verdict; then + if relay_verdict "$RELAY_CONTAINER"; then echo "NOTE: the assertions above passed despite that." >&2 fi diff --git a/testing/nat/scripts/stun-faults-test.sh b/testing/nat/scripts/stun-faults-test.sh index 5a5fafea..149d5b33 100755 --- a/testing/nat/scripts/stun-faults-test.sh +++ b/testing/nat/scripts/stun-faults-test.sh @@ -29,6 +29,7 @@ NAT_DIR="$(cd "$SCRIPT_DIR/.." && pwd)" ROOT_DIR="$(cd "$NAT_DIR/../.." && pwd)" BUILD_SCRIPT="$ROOT_DIR/testing/scripts/build.sh" GENERATE_SCRIPT="$SCRIPT_DIR/generate-configs.sh" +RELAY_LIB="$ROOT_DIR/testing/lib/relay-verdict.sh" PROFILE="stun-faults" SCENARIO="$PROFILE" @@ -53,6 +54,9 @@ NODE="fips-nat-stun-fault-node${FIPS_CI_NAME_SUFFIX:-}" PEER="fips-nat-stun-fault-peer${FIPS_CI_NAME_SUFFIX:-}" SHIM="fips-nat-stun-fault-shim${FIPS_CI_NAME_SUFFIX:-}" STUN_CONTAINER="fips-nat-stun${FIPS_CI_NAME_SUFFIX:-}" +# The node and peer find each other through this relay's adverts, so a relay +# that died takes the pre-flight down with it; the dump states it first. +RELAY_CONTAINER="fips-nat-relay${FIPS_CI_NAME_SUFFIX:-}" # Claimed per run by ci-local.sh; unset renders the lab's historical address. STUN_HOST="${NAT_LAN_PREFIX:-172.31.10}.40" STUN_PORT=3478 @@ -67,6 +71,9 @@ cleanup() { >/dev/null 2>&1 || true } +# shellcheck disable=SC1090 +source "$RELAY_LIB" + trap 'echo ""; echo "stun-faults-test interrupted"; cleanup; exit 130' INT TERM require_docker_daemon() { @@ -95,9 +102,12 @@ require_test_image() { } dump_diagnostics() { + echo "" + echo "=== relay verdict ===" + relay_verdict "$RELAY_CONTAINER" || true echo "" echo "=== stun-faults diagnostics ===" - for c in "$NODE" "$PEER" "$SHIM" "$STUN_CONTAINER"; do + for c in "$NODE" "$PEER" "$SHIM" "$STUN_CONTAINER" "$RELAY_CONTAINER"; do echo "" echo "--- $c: logs (last 80) ---" docker logs "$c" 2>&1 | tail -80 || true @@ -364,6 +374,12 @@ run_test() { return 1 } + # A relay that faulted while the phases still passed is a finding about + # the relay, not about this run, so it is reported and not made a failure. + if relay_verdict "$RELAY_CONTAINER"; then + echo "NOTE: the assertions above passed despite that." >&2 + fi + cleanup if [ ${#SKIPPED_PHASES[@]} -eq 0 ]; then echo "stun-faults-test passed (3/3 phases ran)"