From 242e619169ed4b72883a0e48b419fe81207104fc Mon Sep 17 00:00:00 2001 From: Johnathan Corgan Date: Tue, 25 Aug 2026 20:31:06 +0100 Subject: [PATCH] Stop two CI gates reporting someone else's failure as ours MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- src/node/tests/session.rs | 37 +++++++++---- testing/check-log-strings.py | 8 +++ testing/nat/scripts/nostr-relay-test.sh | 69 +++++++++++++++++++++++++ 3 files changed, 105 insertions(+), 9 deletions(-) diff --git a/src/node/tests/session.rs b/src/node/tests/session.rs index 56e02382..4e0255e6 100644 --- a/src/node/tests/session.rs +++ b/src/node/tests/session.rs @@ -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; diff --git a/testing/check-log-strings.py b/testing/check-log-strings.py index 7a597f9f..d230eea5 100755 --- a/testing/check-log-strings.py +++ b/testing/check-log-strings.py @@ -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" diff --git a/testing/nat/scripts/nostr-relay-test.sh b/testing/nat/scripts/nostr-relay-test.sh index 2c321011..7f2e1ce2 100755 --- a/testing/nat/scripts/nostr-relay-test.sh +++ b/testing/nat/scripts/nostr-relay-test.sh @@ -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" }