mirror of
https://github.com/block/buzz.git
synced 2026-11-06 17:31:19 +00:00
a22ff133b4
## Summary Three tests asserted on outcomes that depended on how fast something unordered happened. The first depended on dial latency inside a 150 ms acquire budget, the second on whether two aux-page replies landed in one poll, and the third on whether NIP-42 admission auto-joined the joiner before the invite claim did. Each test now sets up the state it asserts before the racing actor can run: it fills the reader warm floor first, pauses the writer's proxy after the first aux page, or claims the invite before the joiner connects. Only tests change. No assertions are loosened, and no sleeps, retries or timeouts are added. ### test(db): fill the reader warm floor outside the acquire budget first #### Problem `reader_warm_at_production_budget_ends_partial_when_dials_stall` failed on main at reader_pool_postgres_tests.rs:177, "one partial wave, then one wave that opens nothing": left (15, 0, 5), right (15, 3, 7). Postgres lanes run with no retries. - main (d3a4909cc): - https://github.com/block/buzz/actions/runs/41693681008/job/126127000284 The test is unchanged on current main. #### Cause The test builds the reader pool with the production constructor, so every warm acquire, dial included, gets the 150 ms `READER_ACQUIRE_TIMEOUT`. It relayed the proxy's first 3 sessions and stalled the rest, so it needed the first wave's 3 relayed dials (TCP through the proxy, backend fork, SCRAM, `after_connect`) to finish inside that budget. On a loaded runner (4 vCPUs, nextest test-threads=8) none did. All 5 first-wave acquires missed, and the pass ended after one empty wave as the product should, which gives (15, 0, 5). The warm pass was correct, but the test's outcome depended on dial latency. The session counts had a second race. The proxy accepts connections on the test's current-thread runtime. If that thread is descheduled past the budget, the timed-out acquires and the listener's readiness are handled in the same tick. So `proxy.sessions() == 10`, checked right after the pass, could miss a stalled dial still waiting to be accepted. #### Fix Fill the warm floor before stalling anything, as boot does. `Db::read_pool_boot_ping_once` closes its probe connection, and sqlx's floor maintenance then dials the 3 floor connections under its own 300 s deadline, outside the acquire budget. The test waits for them with `await_idle_floor`, then stalls every session from the recorded baseline (`proxy.stall_from(proxy.sessions())`) instead of a hardcoded 3. Wave 1 now holds the 3 idle connections without dialing, and its 2 dials stall. Wave 2's 5 dials stall, so it makes no progress and the pass ends. That gives (15, 3, 7) at any dial latency. The session count is now relative to the baseline and asserted once, after the existing settle. That single check covers both "the pass stops dialing" and "nothing re-dials". The report assertion, the `elapsed < 2s` bound and the production pool are unchanged. Only the test changes. The setup still needs one of the boot ping's five attempts (spaced over about 4 s by `READER_BOOT_PROBE_BACKOFF`) to dial within 150 ms, the same exposure as `reader_boot_ping_warms_pool_to_min_connections`. Before, all 3 concurrent first-wave dials had to make it on their first try. #### Validation Local Linux workstation, on a private postgres:17-alpine. The test processes and Postgres shared 4 pinned CPUs, with 8 parallel workers. "Before" is the test as on main. - CPU stress, no busy loops: before, 2/40 failed with (15, 0, 5) at :177, the CI signature. After, 120/120 passed. - Plus 4 busy loops on those CPUs: before, 80/80 failed with (15, 0, 5). After, 80/80 passed. In 80 more instrumented runs (all passed), the boot ping retried 16 times: 15 runs needed 2 attempts and 1 needed 3. - Adversarial latency, using a temporary, uncommitted proxy hook that delays chosen sessions' first server reply by 200 ms (past the budget), 10 runs each: - every relayed session slow: before, 10/10 (15, 0, 5). After, 10/10 failed at "boot ping must reach the reader", the bound above. - the first 4 sessions slow: before, 10/10 (15, 0, 5). After, 10/10 passed, with the ping succeeding on its 5th attempt. - every session but the first slow: before, 10/10 (15, 1, 9). After, 10/10 passed. - Production mutations, each of which fails the test: dropping the no-progress break gives (15, 3, 27). A 2 s acquire budget fails the elapsed bound at 4.0 s. Closing the warmed connections instead of releasing them leaves the floor at 0 idle. - All 7 `reader_pool_postgres_tests` pass. `cargo fmt --check`, `cargo clippy -p buzz-db --all-targets -- -D warnings` and `git diff --check` are clean. A green run doesn't prove the flake is gone. Hosted CI covers broad validation. **Rebased onto origin/main `64d12e297` (this branch):** Linux workstation, private `postgres:16` container with the desired-state schema applied as in the PostgreSQL lane (pgschema plus the reconcile script). - `cargo test -p buzz-db`: 191 lib, 21 `observability_source` and 5 doc tests passed. - `cargo test -p buzz-db --lib reader_pool_postgres_tests -- --ignored --test-threads=1`: 7/7 passed. `reader_warm_at_production_budget_ends_partial_when_dials_stall` alone: 20/20 passed. - `cargo clippy -p buzz-db -p buzz-relay -p buzz-test-client --all-targets -- -D warnings`, `cargo fmt -p buzz-db -p buzz-relay -p buzz-test-client -- --check` and `git diff --check` are clean. ### test(relay): hold the writer's second aux page too #### Problem `thread_window_batch_discards_earlier_windows_after_revocation` failed on main at failure_postgres_tests.rs:55, "barrier must precede closure completion": left 2, right 1. Postgres lanes run with no retries. - main (d3a4909cc): - https://github.com/block/buzz/actions/runs/41693681008/job/126127000284 The test and the code it covers are unchanged on current main. #### Cause This is the race #8740 (322fdbf08) fixed for the replica test only. `pause_after_aux_page` polls the request until a `thread_window_aux` span closes, then expects exactly one closed. `query` runs the closure's two aux hops (reactions and edits, then their deletions) back to back, one span each. On the writer, each hop is a pool acquire with its idle ping, BEGIN, two SET LOCALs, the SELECT and ROLLBACK. #8740 left the writer callers on `None`, so only the request returning Pending on a reply that had not arrived yet held hop 2. sqlx tries each read before it waits for readiness, and tokio leaves the socket marked readable after the previous reply, so a reply Postgres has already sent is consumed in the same poll. If each of hop 2's replies lands before the test thread reads it, for example when a loaded runner deschedules that thread after its writes, hop 2 closes in the poll that closed hop 1 and the barrier counts 2. `assert_aux_access_change`, behind the grant and revocation tests, uses the same `None` path. #### Fix `proxied_state` gives the paused request a copy of the fixture's state whose production writer connects through a `PausingProxy`. `production_db_at` is `production_db` with a URL override. `AuxPages` pauses the proxy when hop 1's span closes. That runs inside the request's poll, before hop 2's first bytes are written, so hop 2 stays pending however fast Postgres answers. Each test resumes the proxy after its access change, just before `request.await`. Only the request uses the proxied state: `assert_aux_access_change` reads through the fixture's direct `state.db` while the request is held, and through the proxy that read would deadlock. No caller passes `None` any more, so the `Option` goes. Only tests change. No assertions are loosened, and no sleeps, retries or timeouts are added. Draft #8991 (BUZZ-512) also edits `AuxPages` and `pause_after_aux_page`, adding a waker for its detached HTTP handler. It also moves these two callers onto a proxy, through its own `proxy_request_pool`, which replaces `f.state.db` with a raw pool. Rebasing it onto this keeps its waker on the non-`Option` proxy field and can use `proxied_state` for those two callers. #### Validation Local Linux workstation, Postgres 17 in docker, one test per process as nextest runs them. "Before" is the test as on main. - Adversarial ordering, using a temporary, uncommitted change as in #8740: after the barrier, ten more polls of the request over 500 ms, then the barrier's count assertion. Before, the batch, grant and revocation tests failed 30/30 at that assertion with left 2, right 1, the CI signature, and the replica test passed 10/10. After, 40/40 passed. - Natural contention: the three tests and a private postgres:17-alpine shared 2 pinned CPUs with 4 busy loops, 3 processes at a time. Before, 450/450 passed, so the same-poll burst did not occur locally. After, 450/450 passed. - Production mutation: skipping `query_batch`'s final implicit access-set check fails all three tests with 200 instead of 503. - All 19 `api::bridge::thread_window` Postgres tests pass, run serially against one database. `cargo fmt --check`, `cargo clippy -p buzz-relay --all-targets -- -D warnings` (1.98.1), `git diff --check` and `check-postgres-test-discovery.py` are clean. Running several of these tests in one libtest process can fail them at :41 with no aux span seen, on main too. tracing-core builds a new callsite's interest from the registering thread's default while only one scoped dispatcher exists. nextest runs one test per process, so CI is not exposed. The runs above use one process per test. A green run doesn't prove the flake is gone. Hosted CI covers broad validation. **Rebased onto origin/main `64d12e297` (this branch):** same database setup as above. - Each of the 19 `api::bridge::thread_window` Postgres tests ran in its own process and its own database cloned from the desired-state template, as nextest runs them: 19/19 passed. - The batch, grant, revocation and replica tests, 5 more runs each in the same way: 20/20 passed. ### test(relay): claim the invite before the joiner connects #### Problem `test_invite_claim_auto_joins_default_channel` (crates/buzz-test-client/tests/e2e_relay.rs) failed in "Relay and PostgreSQL / Relay E2E" at :363 with "recv kind:44100 notification for the default channel: Timeout". Two of the three reruns passed. - run 41568808045 attempt 1 (rerun passed): - https://github.com/block/buzz/actions/runs/41568808045/job/125701098947 - run 41657074260: - https://github.com/block/buzz/actions/runs/41657074260/job/125997465078 - run 41716543775 attempt 1 (rerun passed): - https://github.com/block/buzz/actions/runs/41716543775/job/126206390776 #### Cause The e2e relay runs without `BUZZ_REQUIRE_RELAY_MEMBERSHIP`, so every human NIP-42 admission spawns `auto_join_never_joined_channels` (handlers/auth.rs). The test connected the joiner and sent its kind:44100 REQ before minting and claiming the invite. The admission therefore joined the joiner to the flagged channel before the claim did. The claim's `auto_join_default_channels` then got `AlreadyMember` and emitted nothing, so the admission notice was the only kind:44100. All three relay logs show this. The joiner's "auto-joined default channel on admission" appears 39, 52 and 106 ms after its NIP-42 auth, before "relay member added via v2 invite". The claim logs no join for the joiner. When the admission notice reached the client before EOSE, `collect_until_eose` consumed it, and the test discarded that result. The test then waited 5 s for a live event that never came. When the notice arrived after EOSE, the test passed, but on the admission path. Either way, the test never covered the claim-time auto-join it is named for. #### Fix Only the test changes. The joiner opens no WebSocket until the claim returns. Over NIP-98, the claim awaits the join, the kind:39002 roster and the kind:44100 before its 200. The test now: - checks the roster before the joiner connects, so only the claim can have joined them; - then connects and REQs kind:44100 `#p=joiner` with `since` taken before the claim (minus the file's usual 5 s margin); - asserts that the events `collect_until_eose` returns hold exactly one notice for the channel, signed by the relay's NIP-11 `self` key. Nothing depends on EOSE-vs-live ordering any more. The admission that follows skips the channel, because the claim already added a member row. No timeouts change, no retries are added, and no assertions are loosened. The repeat-claim and cleanup steps are unchanged. No open PR touches this test. Draft #9045 (default-channel recovery) changes invites.rs, but not this test or this ordering. #### Validation Local Linux workstation, fresh database, relay started by scripts/start-relay-for-tests.sh. Redis was the host's own, and `BUZZ_METRICS_PORT` was moved off 9102, which bloxlet owns. Each iteration ran CI's `e2e_relay invite` selection (8 tests in parallel). - Unmodified test: 12/60 failed at :363 with the CI message. - Adversarial ordering, using temporary, uncommitted changes: a 500 ms sleep between connect and REQ, plus logging of what `collect_until_eose` returned. 20/20 failed with the CI signature, and each time `collect_until_eose` had returned the channel's notice. In the relay log, the admission join came 28 ms after auth, the REQ queued one event, and the claim emitted nothing. - Fixed test: 100/100 passed. With the same 500 ms sleep: 30/30 passed, each with exactly one notice, from the claim. Four concurrent loops of 25: 100/100 passed. - Falsifiability, using a temporary relay build without the claim-time `auto_join_default_channels` call: the fixed test failed 10/10 at the roster assertion (`None`). The old test passed 18/20 against that build; its two failures were its own :363 flake. - The full CI "Relay E2E tests" step list passed once. - `cargo fmt --check`, `cargo clippy -p buzz-test-client --tests -D warnings`, `just file-size-check` and `git diff --check` are clean. A green run doesn't prove the flake is gone. Hosted CI covers broad validation. **Rebased onto origin/main `64d12e297` (this branch):** the relay was built from this branch with `--profile ci` (its relay code is identical to main) and run with CI's environment. It used a fresh desired-state database with the deployment community seeded, the host's Redis, and a private MinIO-compatible container (the image docker-compose pins) for the startup git probe. `BUZZ_METRICS_PORT` was moved off 9102. - CI's `e2e_relay invite` selection: 30/30 iterations passed, 8 tests each. - CI's full "Relay E2E tests" step list, once: 10 of 11 steps passed. `test_nip29_announce_channel_wire` failed at e2e_relay.rs:3862: the kind:39000 metadata still carried `auto_join` right after the relay owner cleared it. This branch doesn't touch that test or any relay code. Run alone against the same relay, that test failed 8 of 20 times. Re-running the whole step against one database isn't meaningful, because `test_nip29_announce_channel_wire_overlong_name_is_refused_before_storage` reuses a fixed channel name. ## Coordination - #8991 ("BUZZ-512: Track session application and drain") edits `AuxPages` and `pause_after_aux_page` in `crates/buzz-relay/src/api/bridge/thread_window/postgres_tests/failure_postgres_tests.rs`, and `git merge-tree` shows a conflict there. #8991 already conflicts with main in 15 files, so it needs a rebase anyway. The second commit's message describes that rebase: keep #8991's waker on the non-`Option` proxy field, and use `proxied_state` for the two callers it moves onto a proxy. - #6642 and #7569 touch `crates/buzz-test-client/tests/e2e_relay.rs` and merge cleanly with this branch. - #7852 touches `thread_window/postgres_tests.rs` and `e2e_relay.rs`. It already conflicts with main, and this branch adds no new conflicted file to it. Older open PRs that touch `e2e_relay.rs` also already conflict with main, and none gains a new conflict from this branch. 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Signed-off-by: mtoohey <mtoohey@squareup.com> Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>