Skip to content

fix(vault): read test responses in full - #452

Open
LKSNDRTMLKV wants to merge 1 commit into
mainfrom
fix/vault-test-stall-336
Open

LKSNDRTMLKV wants to merge 1 commit into
mainfrom
fix/vault-test-stall-336

Conversation

@LKSNDRTMLKV

Copy link
Copy Markdown
Member

Fixes #336.

What was wrong

publish_serve_cycle, textile and suspension hung on the request sent straight after POST …/publish — about one run in a thousand on Linux — until the client timeout. It was never in the vault. It was the test client.

  • The publish response is ~10 KiB (Server::encode status=200, body=Known(10037)). hyper reads a socket 8 KiB at a time, so when the headers arrive ~2 KiB are still unread, and the reqwest::Response owns its connection until someone reads them or drops it.
  • The tests assert on resp.status() and then write let resp = … for the next call. A shadowed binding is not dropped, so the publish response lives to the end of the test.
  • Usually the next request gets a different connection and nothing happens. In a narrow race hyper-util's pool hands the same still-busy connection to the next request, which queues behind a body nobody is going to read while the test waits for it. Nothing is running anywhere.

This matches every sighting: all were the request right after a publish, and in the first one the machine was idle for the last ~114 s (380 of 381 tests had finished at 02:42:26; the hung one was killed at 02:44:20).

Evidence

Reproduced on Linux (rust:1.96.0-bookworm, 4 CPUs, shared postgres:17), running test_suspension_flow as fresh processes four at a time: 3 hits in ~3,700 runs. With hyper's own tracing on, the failing run shows the mechanism directly:

.166302  decode; state=Length(10037)            publish response head parsed
.166410  pool: put; add idle connection          pool re-offers the connection 0.1 ms later
.166930  flushed(client): reading: Body(Length(2022)), writing: KeepAlive   …still mid-body
.171888  pool: reuse idle connection             given to the next request (suspend)
   … 45 s …
:28.225  body receiver dropped before eof        only at unwind, after the test panicked

A diagnostic added for this run reported, at the timeout: router has no request in flight; last answered POST /dpp → 201, POST …/publish → 200; server-side socket empty; client-side socket holding 2,022 unread bytes (10,214 sent − 8,192 read). The suspend request never reached the router.

The change

  • TestClient reads every response to the end before returning it, so a test cannot hold a response that still owns a connection. It returns an ordinary reqwest::Response over the buffered bytes; no test changed (the suite only uses status, json, text, headers).
  • The timeout note said "the server accepted the request and never answered". A total timeout cannot know that, and here it was the opposite of true; it sent two rounds of investigation after the pool and the database. It now says whether the connect (own 10 s timeout) or the response timed out, and for a response lists what the router has in flight and the last requests it answered.
  • tests/test_client.rs pins the invariant: a server sends the head and the first 8 KiB, pauses, then sends the rest; get() must not return before the tail arrives. It fails (in 3.8 ms) with the buffering removed and passes with it.

Verification — and what is not done

  • just check rc=0 (1,487 unit tests), just lint-integration rc=0, vault integration tier 476 passed / 12 skipped.
  • The new test was seen to fail without the fix.
  • Post-fix soak is incomplete. The same Linux loop ran 4,138 runs with 0 failures, then Docker Desktop stopped answering (the throwaway Postgres had accumulated ~9,000 databases) before the 15,000-run target. At the pre-fix rate, 4,138 clean runs happen by chance ~4% of the time, so this number alone is not conclusive; the mechanism trace and the failing-then-passing test carry the claim. Not run on GitHub's runners.
  • Not established: whether hyper-util re-offering a mid-body connection is intended behaviour or a defect. The harness no longer depends on it.

Not covered

dpp-node/tests/smoke.rs and dpp-resolver/tests/resolver_e2e.rs build their own shared reqwest::Clients and shadow let resp the same way. They may carry the same latent hang; unconfirmed, and out of scope for #336 (vault tier).

Picking this up

  1. Merge, then watch the vault integration tier. A recurrence will now say where it stopped (connecting vs no response in 45s; <router state>), which is what the old message could not.
  2. To finish the soak: build suspension and textile in a 4-CPU rust:1.96.0-bookworm container, point ODAL_TEST_PG_ADMIN_URL at a Postgres with --shm-size=512m, and run --exact test_suspension_flow as fresh processes 4 at a time. Recreate that Postgres every few thousand runs — it does not drop per-test databases. Unfixed, a hit takes ~5–10 minutes.
  3. Follow-up: the two suites above.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

publish_serve_cycle intermittently hangs to the 120s nextest timeout

1 participant