Stop two CI gates reporting someone else's failure as ours

Two unrelated harness defects with the same shape: the run's verdict
names something other than what actually went wrong.

The nostr publish/consume suite treats a dead relay as a product
failure. strfry is a third-party container and it has segfaulted
mid-run, twelve milliseconds after both nodes connected; everything
below that was a correct report of a dead relay, and the run failed on
the peer-count wait with the only evidence of the real cause sitting in
one container-log line ninety lines above the summary. Add a relay
verdict that states the relay's own condition — gone, not running,
restarted, or faulted per its log — and print it at the head of every
diagnostics dump, which is what every failure path already goes
through. A relay whose state or log cannot be read is reported as
unestablished rather than as healthy. The verdict does not decide the
run: a relay that faulted while the assertions still passed is noted
and left passing, since the suite proved what it set out to prove.

The setup-bucket refill test raced its own precondition. It delivered
exactly three forged setups against a 50/s refill and asserted one had
been refused, which holds only if all three finish inside one 20 ms
window; on a loaded runner the bucket refilled mid-loop, the third
setup was admitted, and the precondition failed on arrangement rather
than on behaviour. Under the CI retry policy that reports as green with
a flaky count, so nothing surfaced it. Drain against a 2/s refill,
which a delivery would have to take 500 ms to outrun, and deliver until
a refusal is actually observed rather than assuming three is enough,
with a cap that says what a runner slow enough to reach it means. The
refill half then waits out a full burst from empty.

(cherry picked from commit ec0fadfd136e0f6a64551fab61d042e486861842)
This commit is contained in:
Johnathan Corgan
2026-08-25 20:50:12 +01:00
parent be8159ce49
commit 242e619169
3 changed files with 105 additions and 9 deletions
+28 -9
View File
@@ -4276,19 +4276,38 @@ async fn test_forged_setups_from_one_link_peer_stop_creating_session_entries_onc
#[tokio::test]
async fn test_a_drained_setup_bucket_refills_and_admits_the_next_legitimate_setup() {
// Fast refill: the point is that the denial is transient, and that the
// initiator's own msg1 resend schedule covers a window this short.
let mut nodes = make_setup_limited_pair(2, 50.0).await;
// The refill has to be slow enough that the draining loop below cannot be
// outrun by the refill it is draining against. At the 50/s this test used
// to run at, a token returned every 20 ms, so on a loaded runner the loop
// outlived its own window, the third setup was admitted, and the
// precondition failed on arrangement rather than on behaviour. At 2/s a
// delivery would have to take 500 ms to lose that race.
let mut nodes = make_setup_limited_pair(2, 2.0).await;
for _ in 0..3 {
// Deliver until one is actually refused, rather than assuming three is
// enough: a delivery the refill absorbs costs one more iteration and
// nothing else. The cap is what a runner slow enough to lose even this
// race trips, and it says so rather than reporting a drained bucket that
// was never drained.
let before = nodes[1].node.stats().session.setup_rate_limited;
let mut delivered = 0;
while nodes[1].node.stats().session.setup_rate_limited == before {
assert!(
delivered < 50,
"the bucket must actually be drained before the refill is tested; \
50 forged setups drew no refusal, so each delivery is outlasting \
the 500 ms refill interval"
);
deliver_forged_setup_over_link(&mut nodes).await;
delivered += 1;
}
assert!(
nodes[1].node.stats().session.setup_rate_limited > 0,
"the bucket must actually be drained before the refill is tested"
);
tokio::time::sleep(Duration::from_millis(100)).await;
// A full burst back from empty at 2/s, so the legitimate setup below meets
// the same bucket however many tokens the drain left behind. The point
// being made is that the denial is transient and clears on its own; the
// length of the window is a function of the configured rate, not of the
// claim.
tokio::time::sleep(Duration::from_millis(1200)).await;
establish_pair_session(&mut nodes).await;
cleanup_nodes(&mut nodes).await;
+8
View File
@@ -37,6 +37,14 @@ ALLOWED = {
"ERROR": "tracing's own level token, produced by the subscriber's formatter",
" ERROR ": "tracing's own level token, produced by the subscriber's formatter",
" WARN ": "tracing's own level token, produced by the subscriber's formatter",
"caught a signal": (
"read from the strfry relay container's log, not the fips daemon's — "
"strfry's own crash handler writes it"
),
"terminate called": (
"read from the strfry relay container's log, not the fips daemon's — "
"the C++ runtime writes it on an uncaught exception"
),
"Bootstrapped 100%": (
"read from the tor-daemon container's log, not the fips daemon's — "
"Tor's own bootstrap progress line"
+69
View File
@@ -85,7 +85,69 @@ 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
echo ""
echo "=== nostr publish/consume diagnostics ==="
for c in "$NODE_A" "$NODE_B" "$RELAY_CONTAINER"; do
@@ -397,6 +459,13 @@ run_test() {
return 1
fi
# 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
echo "NOTE: the assertions above passed despite that." >&2
fi
cleanup
echo "nostr-relay-test passed"
}