flaky: loser-release seller test spends its 5s claim budget on NIP-42 relay auth

[orveth]

Symptom

seller_node::run::tests::a_losing_open_pool_claimant_releases_its_slot_when_it_sees_the_award
fails intermittently in the Money-path tests job:

thread '...a_losing_open_pool_claimant_releases_its_slot_when_it_sees_the_award' panicked at
crates/maxplayer-core/src/seller_node/run.rs:8311:17:
the loser must claim the open-pool offer
test result: FAILED. 967 passed; 1 failed; 1 ignored

The assertion is a wall-clock-bounded poll:

pump_offers_until(&loser, &mut loser_notifs,
    std::time::Instant::now() + Duration::from_secs(5),
    |r| r.node.store().claim_row_state(&job_id).ok().flatten().is_some())

Mechanism (primary)

The 5s budget is spent on relay NIP-42 auth latency, not on the behaviour under test. Both
seller nodes in the failing run logged a 20-second auth stall, twice, immediately before the
panic — inside the failing test's own captured output:

23:28:45Z seller node WARN: no NIP-42 challenge within 20s; proceeding (auto-auth stays ON ...)
23:29:05Z seller node WARN: no NIP-42 challenge within 20s; proceeding ...

Two 20s stalls against a 5s claim budget. The winner reserved its slot; the loser had no budget
left to claim within the deadline. The test asserts a liveness property ("the loser also
claims") but bounds it with a latency deadline that includes relay auth, so it measures the
relay's auth responsiveness as much as the claim logic.

Evidence that it is non-deterministic, not a code defect

Two CI runs on fix/774-delivery-store-compaction, consecutive, ~21 minutes apart:

	a128e8ca (23:02Z)	c679dbf3 (23:23Z)
Money-path	success (run 31752342167)	failure (run 31753646179)
result	968 passed; 0 failed; 1 ignored	967 passed; 1 failed; 1 ignored
duration	214.07s	218.46s
no NIP-42 challenge within 20s	0	2

The full a128e8ca..c679dbf3 diff is 16 lines, all inside a single /// doc block, zero
executable change. Identical executable semantics produced opposite outcomes, and the relay-auth
stall is present only in the failing run.

Open question — suite-load hypothesis

#779 adds fd-pressure legs that drive 80 deliveries each. An open question is whether that added
suite load raises this test's flake probability relative to base main.

Weighing the evidence honestly: the pass/fail pair above does not settle this either way. Both
shas carry #779's full added load, so load was constant across the pair — which isolates
non-determinism at that load level, but is neutral on whether that load level flakes more often
than main's. A rate hypothesis needs a rate measurement (many runs at each load), not two samples
at the same load. Recorded here as an open question, not a blocker.

Suggested directions (not prescriptions)

1. Exclude relay auth from the budget — await NIP-42 completion (or disable auth in the fixture)
   before starting the claim deadline.
2. Raise the bound. This is a liveness assertion; a 5s wall-clock cap encodes a latency SLO nobody
   intended.
3. Drive the wait off the awaited event rather than a wall-clock poll.

Artifacts

• failing job: https://github.com/MakePrisms/maxplayerai/actions/runs/31753646179/job/94624681531
• passing job: https://github.com/MakePrisms/maxplayerai/actions/runs/31752342167/job/94620625194
• failing job log preserved at /srv/forge/share/mobee/779-moneypath-flake-c679dbf3.log (171,954 B)

Test introduced in dc9e034 (#530). Filed from the #779 review; #779 does not touch
seller_node/run.rs.

[orveth]

Third data point — re-run at the identical sha

Re-ran only the Money-path job at c679dbf3 with no code change (job 94627291140):

• test result: ok. 968 passed; 0 failed; 1 ignored — 214.81s
• seller_node::run::tests::a_losing_open_pool_claimant_releases_its_slot_when_it_sees_the_award ... ok
• no NIP-42 challenge within 20s occurrences: 0

Tally across three runs whose executable code is identical (the only inter-sha diff is a /// block):

run	sha	NIP-42 20s stalls	outcome
31752342167	a128e8ca	0	pass — 968/0/1
31753646179	c679dbf3	2	fail — 967/1/1
94627291140 (re-run)	c679dbf3	0	pass — 968/0/1

The stall count is the only variable that tracks the outcome across all three runs. That moves the
mechanism from "correlated within the failing run" to "the sole factor that varied across three runs
of identical code" — worth recording, because it is stronger evidence than the report originally had.

This does not move the load hypothesis in either direction: all three runs carry #779's added
suite load, so the comparison still holds load constant and still cannot measure a rate difference
against base main. That question remains open exactly as written above.

[orveth]

Still live, and I have a measurement that I think retires the primary mechanism. Surfaced while running the money-path suite for #907, which does not touch this path.

Still failing, at a different assertion

cargo test -p maxplayer-core --release \
  --features acp,gateway,git-delivery,wallet --locked -j 6

thread '...a_losing_open_pool_claimant_releases_its_slot_when_it_sees_the_award' (2160437) panicked at crates/maxplayer-core/src/seller_node/run.rs:9715:17:
the winner must claim the open-pool offer

test result: FAILED. 1234 passed; 1 failed; 2 ignored; 0 measured; 0 filtered out; finished in 149.73s

Same test, but this is the winner assertion at run.rs:9715, where the report above is the loser assertion at run.rs:8311. Both are pump_offers_until with the same Instant::now() + Duration::from_secs(5) bound, so the tight budget is not specific to one of the two.

The 0-vs-2 NIP-42 comparison cannot carry the mechanism

The table above rests on no NIP-42 challenge within 20s = 0 in the passing job and 2 in the failing one. That difference is produced by cargo test's output capture rather than by the runs differing: stdout is captured and printed only for failing tests, and this issue already notes the warnings appear "inside the failing test's own captured output". A passing run therefore reports 0 by construction, whatever actually happened.

Measured on my own logs — two passing full-suite runs, counting captured-stdout blocks:

moneypath.log      "seller node"=0     "stdout ----" blocks=0
moneypath2.log     "seller node"=0     "stdout ----" blocks=0
mp785.log          "seller node"=6     "stdout ----" blocks=1

The passing logs contain no captured output at all, so their zero is not an observation about NIP-42.

Direct measurement: passing runs emit the same two warnings

--nocapture is the only way to ask the question. Same test, standalone, low load:

RUN1 -> ok, NOCAP_CARGO_RC=0, "no NIP-42 challenge within 20s" x2
RUN2 -> ok, NOCAP_CARGO_RC=0, "no NIP-42 challenge within 20s" x2
failing run                    "no NIP-42 challenge within 20s" x2

Two warnings in every run, passing and failing alike. A passing run's stdout is structurally the same as the failing one:

17:56:37Z seller node reconcile: resumed_jobs=0 expired_outbox=0 pending_outbox=0
17:56:57Z seller node WARN: no NIP-42 challenge within 20s; proceeding (auto-auth stays ON ...)
17:56:57Z seller node execution slots: 1 (claim-lapse timeout 3600s)
17:57:17Z seller node WARN: no NIP-42 challenge within 20s; proceeding (auto-auth stays ON ...)

Both stalls land during node startup, before Instant::now() opens the five-second window, so they cost wall clock without consuming the budget the assertion measures. The test takes ~40s even when it passes; that 40s is baseline.

⇒ Suggested direction 1 — "await NIP-42 completion before starting the claim deadline" — is aimed at a cause this evidence does not establish. Implementing it would likely leave the flake in place. Directions 2 and 3 are untouched by this and still look right; 3 in particular, since the assertion is a liveness property bounded by a latency deadline.

What does discriminate: load

Nine full-suite runs plus two standalone, tree held constant across the first two rows:

branch feat/785-model-select-readback fe19768 @ loadavg 29.50 -> FAIL · FAIL · ok
branch feat/785-model-select-readback fe19768 @ loadavg  5.35 -> ok · ok · ok
pristine main a29f8a8                        @ loadavg  5.10 -> ok · ok · ok
standalone, single test                      @ loadavg ~1.6  -> ok · ok

Rows 1 and 2 alone are confounded — load varied with the tree — so row 2 is the cell that separates "a diff perturbs timing" from "the test is load-fragile". At matched load the two trees are indistinguishable. This is a local box, not CI, so it speaks to the suite-load hypothesis in the open-question section rather than settling it.

What I did not establish

• Pristine main at high load was never run. Every high-load observation is on the feature branch, so "main is equally fragile" is inference from the matched-load rows, not a cell.
• What actually consumes the five seconds is still unknown. Slow relay delivery, slow store writes, and LocalSet scheduler starvation are all consistent with what I have; I did not separate them. I am retiring a candidate, not supplying a replacement.
• I have not ruled out that the auth stalls overlap the claim window in some failing runs. What is ruled out is the 0-vs-2 count as evidence for it.

[orveth]

Refining one point from my previous comment, because the structure explains the "two different assertions" puzzle rather than just noting it.

Both failures live in the same helper, drive_loser_release_on_award at run.rs:9660, and it carries three independent five-second budgets:

9719:  std::time::Instant::now() + Duration::from_secs(5),
9723:      "the winner must claim the open-pool offer"     <- my failure
9729:  std::time::Instant::now() + Duration::from_secs(5),
9733:      "the loser must claim the open-pool offer"      <- this issue's original failure
9778:  std::time::Instant::now() + Duration::from_secs(5),

So the report at the top of this issue and mine are not two different tests, and not even two different code paths — they are sequential assertions in one function, each racing its own fresh timer. Whichever budget loses the race under contention is the one that reports. That is why the failure appears to move between runs, and why fixing one bound would leave the other two.

Line-number caveat, since this issue already has one instance of the problem: the original report cites run.rs:8311 and the same assertion is now at 9733. The durable handles are the function name drive_loser_release_on_award and the assertion strings; the line numbers rot.