publish_serve_cycle intermittently hangs to the 120s nextest timeout

[LKSNDRTMLKV]

dpp-vault::publish_serve_cycle::published_passport_is_served_as_the_payload_its_proof_signed timed out at nextest's 120-second ceiling in run 35048585684, failing the integration tier. 380 of 381 tests passed; this one was the whole failure.

Re-running the same job on the same commit passed. The commit under test (#321) touches only crates/dpp-seal/src/trustlist/, which has no runtime caller — so nothing in the change could reach this test's code path.

It is a hang, not a slow test

Worth separating, because the two want different fixes.

scripts/slow-test-check.sh runs with a 10-second budget and this test is not on the allowlist. It does not appear in the slow-test report on any passing run, so on a normal run it completes inside 10 seconds. On the failing run it was still going at 120.

That is not a test drifting over budget. It is a test that occasionally does not finish at all — twelve times its own normal ceiling, then killed.

The slow-test gate did its job and reported it:

ERROR: tests over the 10s budget:
  120.014s  dpp-vault::publish_serve_cycle::published_passport_is_served_as_the_payload_its_proof_signed

…but that message reads as "make the test faster", which is the wrong instruction here. The fix is to find what it waits on forever.

Where to look

The test is #[tokio::test(flavor = "multi_thread")] and its first three statements each stand something up:

let pg = start_postgres().await;
let vault_url = start_vault(pg.dal.clone()).await;
seed_complete_operator(&pg.dal).await;

then drives the real HTTP surface through TestClient. Candidates, roughly in order of how much they would explain a 120s hang against a 10s norm:

1. start_postgres / start_vault — container or bind contention under a loaded runner. The allowlist's migration_0024 entry notes that start_pg_before boots a server that cannot use the shared template, which implies the shared template is what makes the normal path fast; a fallback or a race around that would fit the timing gap exactly.
2. An HTTP call with no client-side timeout. If TestClient has none, any request that never gets a response parks until nextest kills the process, which is precisely the observed shape — no assertion failure, no panic, just silence.
3. Port or pool exhaustion across the 381 tests in the tier, biting whichever test happens to run last. This one was 381/381.

(2) is worth checking first whatever the cause turns out to be: a test client without a timeout converts every backend stall into a 120-second CI failure with no diagnostic, which is why this run says nothing about what it was waiting for.

Why it is worth fixing rather than re-running

The integration tier is a required status check and merges are strict-up-to-date, so every PR has to pass it and a flake here costs a full ~11-minute cycle each time it fires. It also trains the reflex of re-running a red gate, which is the reflex that eventually merges a real failure.

Found while merging #321; the failure was confirmed unrelated before the re-run rather than after — main was green at 9efa7a4 and this was the only failure in the previous 40 runs.

[LKSNDRTMLKV]

Second sighting, and it narrows the search usefully — different test, same shape.

Run 35084329783 (on #352, which touches none of this):

thread 'test_textile_create_publish_resolve' panicked at crates/dpp-vault/tests/helpers/mod.rs:605:17:
GET http://127.0.0.1:46211/public/dpp/01a0a9be-a894-7ff0-9e05-d299c43b9b03 failed
(timed out — the server accepted the request and never answered):
error sending request for url (...)

403 of 404 passed; this was the whole failure. It passes locally in 5.0 s and it is not on the slow-test allowlist, so the normal path is well inside the 10 s budget.

What is new

Candidate (2) has been closed, and it paid off immediately. TestClient now has a client-side timeout, so this failed at 30.6 s with a diagnostic rather than parking until nextest's 120 s ceiling with silence. That is the whole difference between the first report and this one.

The message rules out the startup candidates. "The server accepted the request and never answered" — the listener was up, the connection was established, the request was delivered. So this is not container startup, not a bind race, and not the shared-template fallback in (1). Those would fail to connect, not accept and stall.

Two different tests, one path. published_passport_is_served_as_the_payload_its_proof_signed and test_textile_create_publish_resolve are unrelated suites with different fixtures, and both hang on a public read after a publish. That is the common factor, and it is a much smaller surface than "the integration tier".

Where that points

Something on the publish → public-read path occasionally blocks inside the handler, holding the request open. Worth looking at, roughly in order:

1. Connection-pool starvation. Publish does several writes and enqueues to whatever outboxes are wired; a connection held across an await that never completes would let the pool drain and park the next acquire() indefinitely. This fits perfectly: no error, no panic, just a request that is never answered.
2. A background drain holding what the read needs — a row lock or an advisory lock taken by a drain task running against the same database.
3. An outbound call with no timeout reached from the read path.

(1) is the one to check first: it explains both sightings, explains the silence, and explains why it is load-dependent and so only ever appears on a loaded runner.

[LKSNDRTMLKV]

Spent a session on this. No fix yet — but two of the three candidates are now eliminated with measurements rather than reasoning, which narrows it considerably.

Reproduced the shape locally

Stood up a shared postgres:17 exactly as the CI job does (ODAL_TEST_PG_ADMIN_URL, per-test databases cloned from the template) and ran the vault tier at 16–32 test threads. Across five runs, 404 tests passed every time — but a different test went SLOW [> 10.000s] on three of them: lifecycle_actions_are_recorded_in_audit_history, a_refused_amendment_leaves_the_predecessor_live, both_routes_retire_a_passport_the_same_way, and two in audience_read_route.

Normally these run in 1–2 s. The victim is different every time, which is itself evidence: it is not a property of any one test.

❌ Candidate 3 is dead — it is not Postgres connection exhaustion

Sampled pg_stat_activity every four seconds through a 24-thread, 666-test run:

6|100      <- connections | max_connections
6|100
... (14 samples, all 6)

Six, against a limit of 100. max_connections(10) on PgPoolOptions is a ceiling, not a floor, and these tests use about one connection each. The server is nowhere near starved, so nothing is queuing for a backend slot.

❌ And it is not pool-level acquire() either

This was my leading hypothesis and it looked strong: sqlx's default acquire_timeout is 30 seconds, and the client gave up at 30.6 s. A request blocked on acquire() for the full timeout fits the observed shape exactly — accepted, silent, ~30 s.

So I dropped acquire_timeout to 2 s locally and reran the stress three times. If the pool were the bottleneck, a rare 30 s hang becomes a frequent fast failure.

Tests still went SLOW [> 10.000s], and not one failed with a pool timeout. Whatever the request is waiting on, it is not a connection.

What is left

• Runner CPU starvation. Several test processes, each with a multi-threaded tokio runtime, a Postgres container, and — in the seal suites — XAdES verification over multi-megabyte documents, on a 4-core runner. A task that simply does not get scheduled for 30 s would present exactly as "accepted and never answered", would pick a random victim, and would only ever appear under load.
• Contention in start_pg itself. Every test clones a database from one template under an advisory lock. That serialises, and it would explain slow setup — but not a request that was accepted and then never answered, so it does not fit the original report.

The first is now the leading candidate and I cannot prove it from outside CI. The next useful step is instrumentation rather than a speculative fix: have the failing request log how long it spent in the handler versus waiting to be polled, so a run that hangs says which.

Worth recording

The client-side timeout that landed since this was filed has already paid for itself. The first sighting was 120 s of silence; the second was a 30.6 s failure with a sentence saying the server accepted the request and never answered — which is what made both eliminations above possible.

#351, the other flake in this tier, is fixed in #355 — unrelated cause (a retry loop that could run out), but it removes one source of red from the same gate.

[LKSNDRTMLKV]

Fresh occurrence today, on #307 (a reqwest 0.13.4 → 0.13.5 bump, rebased onto main at 9c59a5b), in CI rather than locally:

thread 'published_passport_is_served_as_the_payload_its_proof_signed'
  panicked at crates/dpp-vault/tests/helpers/mod.rs:605:
GET http://127.0.0.1:33981/public/dpp/01a0aedc-4334-7e61-bc89-d883a4e6066b failed
  (timed out — the server accepted the request and never answered)

409 of 410 passed; this one test hung. Two details worth adding to the record:

It is the public read that hangs, not the publish. The request that never came back is GET /public/dpp/{id}. The helper's own timeout_hint distinguishes it from a connection failure — the server accepted the connection and then did not answer, which points at the handler or something it awaits rather than at startup or the port.

Ruled out, so nobody re-derives it: #354 landed earlier today and adds a Postgres chain-walk to that same route, which looks like an obvious new suspect. It is not this. That branch only runs for a superseded passport, and this test publishes an active one, so successor_of is never reached — and this issue predates #354 by a day.

Cost of the flake, concretely: it blocked a dependency bump from merging and required a human to decide whether a reqwest bump had broken the HTTP client or whether this was the known hang. Those are not distinguishable from the failure line alone, which is the real tax.

[LKSNDRTMLKV]

Investigated for the 0.14.0 release. Not fixed — #370 narrows it and deliberately does not close this.

Could not reproduce. Eight consecutive local runs against Docker, all green, ~4.7s each against a 10s slow-test budget. It needs CI load.

This issue's title is stale. #340 (6796e87) already gave TestClient a request timeout and named-URL reporting, and said what it was for: "This does not fix a stall. It makes the next one diagnosable." So a stall no longer reaches the 120s nextest ceiling — it fails at thirty with a named URL.

It paid out today, on an unrelated reqwest bump (#307):

GET http://127.0.0.1:33981/public/dpp/01a0aedc-… failed
  (timed out — the server accepted the request and never answered)

Two new facts: it is the public read that stalls, not the publish; and the server had already accepted the connection, which rules out startup, port binding and container readiness — candidate 1 in the issue body.

🚨 And the instrumentation has a flaw that was destroying the evidence. PgDal::connect uses max_connections(10) with no explicit acquire_timeout, so sqlx applies its default — also 30 seconds. The two candidate causes ("the pool had no connection to give" and "the handler is stuck on something else") therefore expired together, and the failure line looked identical either way. Every occurrence cost a CI cycle and distinguished nothing.

#370 raises the client to 45s so they separate: pool starvation now returns a 500 naming the acquire failure while the client is still waiting; anything else still produces the named-URL timeout. Still far under the 120s ceiling.

So the next occurrence is worth something. Leaving this open until one of them happens and says which.