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.
This commit is contained in:
Johnathan Corgan
2026-09-19 09:11:46 +00:00
parent 0ddb206703
commit 5a5faa0857
7 changed files with 160 additions and 65 deletions
+5 -1
View File
@@ -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
+85
View File
@@ -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 <relay-container>
#
# 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
}
+2 -1
View File
@@ -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`
+20 -1
View File
@@ -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
+26
View File
@@ -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
+5 -61
View File
@@ -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
+17 -1
View File
@@ -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)"