3.x.x: stop SharedLog losing events whose callsite another test reached first, and order the block-only poll faults after the enqueue (#649)

[kiwidream]

Closes #649.

commit_reconcile_block_only_poll_errors_are_retried_then_unknown was not losing a wall-clock race: its log lost one warning. Another lib test reached the same tracing callsite first, on a thread without a subscriber, and tracing cached the callsite as never. This PR makes SharedLog immune to that, and also orders the test's injected poll failures after the enqueue in the database instead of by wall clock. The change is test-only. No timeout, retry or production code changes, and every original assertion is kept.

Problem

Every recorded failure looks the same: three from 2026-10-01 (PR #643's run, PR #645's worker, #570's work) and one reproduced here at eedf331b. The first disposition poll fails at exactly the 5 s lock_timeout (sqlx logs elapsed=5.000s). The final warning carries phase="poll-error". So the polls did fail and retry well inside the 8 s bound. Only the block-only disposition poll failed; retrying warning is missing from the captured log, so the text.contains(...) assertion fails.

The cause is in tracing-core 0.1.36:

• tracing caches one interest per callsite for the whole process.
• While at most one dispatcher is registered, a callsite's first hit asks only the hitting thread's default (Rebuilder::JustOne → get_default). A thread without a subscriber therefore caches never.
• coordinator::miner_submit::acquire_tests run block-only polls against a minimal schema (no offer_outcome column), so their polls fail and reach the same callsite. They do not take the coordinator TEST_LOCK, and they have no subscriber.
• When that first hit lands while this test's SharedLog is the only registered dispatcher, the callsite is cached never, and the SharedLog silently drops this test's warning.

A temporary diagnostic run at the warning site showed the order: this test submits, then an acquire test's checkout:… share hits the callsite on a thread whose default is the global none (column "offer_outcome" does not exist), then this test's poll fails. At that point the global max level was WARN and the thread's default was this test's scoped dispatcher, so the drop came from the cached interest. That is why the test passes alone and fails only in the full parallel run.

The issue's suspected window was real but was not what failed. The old test took LOCK TABLE only after it saw the candidate pending, so the first poll had to fail by bound − lock_timeout = 3 s after the submit. It never exceeded that in the recorded failures.

Change

• miner_tests/mod.rs: SharedLog::dispatch() first installs a global default subscriber, Undecided, once. Undecided records nothing and answers every callsite sometimes, with an OFF level hint so it never raises the global maximum.
  • With it there are always at least two registered dispatchers, and it is the default of any thread without its own. So no callsite can be cached never, and each event asks the current dispatcher.
  • Only main sets a global default, so no lib test conflicts with it.
• miner_tests/mod.rs: new test shared_log_captures_a_callsite_first_reached_without_a_subscriber. It reaches a fresh callsite on a thread without a subscriber while one SharedLog is live, then again under that SharedLog.
• commit_reconcile_tests.rs: the test no longer takes its table lock after polling for the pending candidate.
  • Before the submit, it wraps qbit_prism_share_probe_floor(), which every disposition poll calls, in the same rename-and-replace way as tests/b574_ack_cap.rs.
  • Once this candidate is committed, each call raises SQLSTATE 55P03 (lock_not_available, the class a lock timeout raises) and counts itself in a sequence. The duplicate probe before the enqueue finds no candidate and passes through.
  • So the database orders the failures after the enqueue's COMMIT. The test asserts at least two failed polls from the database, as well as the logged retry.
  • It still asserts: answered ledger-outcome-unknown (never a fabricated outcome), answered no earlier than the 8 s bound, and credited exactly once by the later confirmation, after the wrapper is removed.

Tests

On a private PostgreSQL 16 (PRISM_TEST_DATABASE_URL set, PRISM_TEST_REQUIRE_INTEGRATION=1 for the single-test runs), one test binary at a time, no synthetic load.

Reproduction.

code	run	result
base eedf331b	cargo test --locked -p qbit-prism-server --lib, full parallel	failed 3 of 3 (one plain run, two with diagnostics): the failed polls were not retried and logged, with phase="poll-error" present and the retry warning absent
Undecided::install() commented out	--exact coordinator::miner_tests::shared_log_captures_a_callsite_first_reached_without_a_subscriber	fails: the SharedLog lost an event whose callsite was first reached elsewhere
this PR	the same unit test	passes
this PR, with a temporary 4 s pg_sleep before the enqueue (beyond the old 3 s window)	--exact …poll_errors_are_retried_then_unknown	passes

Suites (this PR):

• cargo test --locked -p qbit-prism-server --lib, full parallel, 3 runs back to back: 623 passed, 0 failed, 2 ignored each time (113.4 s, 126.1 s, 118.6 s). Host load average about 3.5–4.5.
• --exact coordinator::commit_reconcile_tests::commit_reconcile_block_only_poll_errors_are_retried_then_unknown: 2 of 2 passed, 8.5 s each.
• cargo fmt --all -- --check: clean.
• cargo clippy --locked -p qbit-prism-server --all-targets -- -D warnings: clean.
• python3 scripts/check_prism_pool_acquires.py and python3 scripts/check_gate_env_reads.py: pass.

The PostgreSQL test is already in test/prism-gated-tests.txt. The new unit test needs no database, so the list and test/e2e-scenarios.toml are unchanged.

Not run here and why

The build host has no qbitd and no Docker. Nothing in this change needs either; the lib tests above are the whole affected surface.

Merge notes

• One signed commit on 3.x.x at eedf331b. Test-only, no ordering constraints.
• Not fixed here: d2_below_target_tests.rs has its own SharedLog, which does not install the default. It is protected only when a miner_tests SharedLog has already installed it in the same binary. It can switch to the shared helper in a follow-up.
• Seen in every base failure, not addressed: after this assertion failed, fixture cleanup also reported deadlock detected. It did not occur in the passing runs.

🤖 Generated with Claude Code

---

^{Need help on this PR? Tag @codesmith-bot with what you need. Autofix is disabled.}

[chatgpt-codex-connector]

Codex Review Summary

This comment shows the latest Codex review activity on this pull request.

Review	Status	Commit	Review trigger
📝 Code Review	✅ Completed 2026-10-02T15:07:06.596440Z	916d8e7	PR opened

ℹ️ About Codex in GitHub

Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you

• Open a pull request for review
• Mark a draft as ready
• Comment "@codex review" or "@codex security review".

Codex reacts with 👀 while any review is running, comments if it has suggestions, and reacts with 👍 once all reviews finish with no findings.

[kiwidream]

Re-running CI on the current 3.x.x merge ref: #646 merged after this PR's CI ran, and both touch coordinator/miner_tests/mod.rs.