test: assert pool-saturation fail-fast by behaviour, not by a stopwatch

[morozsm]

Squash-merge body must use this description, not the individual commit bodies. Commit cd608214's body carries a rationale that review refuted. e9267dde rewrote it; fe1c7617 deleted it instead, per the owner's ruling below. Use the text on this page.

What

test_pool_saturation_fails_fast_instead_of_queuing timed await driver.start_rx(...) against the saturated pool and required elapsed < _TEST_TIMEOUT_S / 2 (25 ms). It now asserts the behaviour that bound was standing in for.

Why the bound could not hold

A wall-clock bound on this call never isolated the saturation decision. That decision is one counter comparison (_inflight_opens >= _CAPTURE_OPEN_MAX_WORKERS); everything else the call costs is the preamble every start_rx() runs before it — device enumeration, which on macOS reaches _get_uid_map → rigplane.audio._macos_uid.get_device_uid_map, a CoreAudio lookup with no caching (no decorator on _get_uid_map).

Measured with time.thread_time() alongside time.perf_counter() around the probe open: wall = 21.12 ms, event-loop-thread CPU = 10.55 ms — half the window is real work on the loop thread, not descheduling. None of the path's three await points (_rx_lock enter/exit, await self._open_stream) yields: an asyncio.sleep(0) ticker advanced 0 times during the call, so the preamble cost and any descheduling land in one uninterrupted window.

The pre-change assertion went red at elapsed = 0.032s on an idle host, before any load was injected.

What replaces it

The fail-fast branch closes the open coroutine rather than submitting it, so the probe's handle is never started; an open that queued behind the wedged workers is started as soon as one frees. The test releases the gate, waits for the pool to drain (all eight wedged handles closed), then reads the probe. A queued probe sits ahead of those closes in the same FIFO _work_queue, so once the closes land it would necessarily have started — that ordering is what makes the read conclusive rather than merely prompt.

How each claim was established

Direction	Result
Reworked test, healthy product, deterministic 30 ms stall injected into the measured region	PASS
Pre-change shape, identical stall (control)	FAIL — elapsed=0.161s; the stall is potent and the difference is the assertion, not the driver
Product mutation disabling the saturation check	FAIL on the message assertion
Same mutation, message assertion neutralised	FAIL on the drain assertion alone — it discriminates on its own

Full suite (Mac mini, Python 3.11) at cd608214: 11631 passed, 126 skipped, 48 xfailed, 0 failures. ruff check, ruff format --check, mypy --strict src/rigplane/web clean at both commits. One file, well inside the 6-file/600-line soft threshold; git diff main...HEAD --shortstat gives the current figure.

The other named test

TestRadioPoller::test_poller_broadcasts_meter_readings was already converted to a wait-for-the-condition shape in #2897 (commit 36c4b162), which is merged. No change was needed here.

Class survey

Other tests do share both shapes — the check the request asked for came back positive.

The enumerated list that stood here has been deleted rather than corrected, per the owner's ruling of 2026-08-31. It was wrong in four places, and one of its entries went stale inside this PR: deleting nine comment lines shifted a cited line number. A list of file:line rows in a document nobody re-runs is precisely the text that makes the next reader stop checking. Re-run the search and you get a correct list; read this one and you would have trusted a wrong one.

Two things from it are worth carrying, and neither is a line number:

• The tightest instance of the sleep-then-count shape is in tests/test_poller.py, which demands three poll ticks inside a 50 ms sleep — tighter than the case that actually failed.
• A separate, inverse defect lives in this very file: test_normal_rx_open_timing_unaffected and test_normal_tx_open_timing_unaffected assert elapsed < 0.5 under the docstring "a well-behaved (non-blocking) open must not pay a meaningful penalty". The penalty named is _TEST_TIMEOUT_S, which is 0.05. An open that paid the full timeout still lands ten times inside the bound, so neither test can fail for the reason it exists. Independent review confirmed this. It deserves its own ticket and is not fixed here.

Review history

Reviewed independently and BLOCKED at cd608214: the added comment claimed a wall-clock bound on the fail-fast path measured "only" OS descheduling. It does not — time.thread_time() against time.perf_counter() around the probe open gives wall 21.12 ms with 10.55 ms of event-loop-thread CPU. That review also found four errors in the survey above, all fixed here.

e9267dde replaced the refuted sentence with a narrower, verified one. That was the wrong move: under the owner's repo-wide ruling of 2026-08-31, a wrong or stale comment is deleted, not fixed, narrowed, qualified or rewritten — a replacement is justified only when removing the text breaks something structural. Nothing here did. fe1c7617 deletes it.

The measurement is not lost by that deletion; it lives on this page and in git history, which is where a measured number belongs. A number pinned in a comment has nothing that fails when it stops being true.

Two comment paragraphs are kept because neither is wrong and both were established rather than assumed: the one describing what the assertions check, and the FIFO-ordering one explaining why the drain wait is the right condition — review confirmed the latter against ThreadPoolExecutor._work_queue and the two submit sites in usb_driver.py (_open_stream, _close_late_stream).

Re-review pending at fe1c7617.

[morozsm]

Agent Review: BLOCKED cd60821

Independent review. The test logic is sound and the mutation kills reproduce in
both directions — I re-ran them rather than trusting the transcript. One prose
claim in the diff is refuted by measurement, and prose in the diff only a commit
can fix, so this is BLOCKED on a comment reword and nothing else.

Blocking finding (in the diff — needs a commit)

tests/test_usb_audio_capture_open_timeout_mor1438.py:396-399

The whole fail-fast path through start_rx() has no await points, so a timing
bound on it measures only whether the OS descheduled this process mid-call
(observed: 32ms on an idle host against a 25ms bound), which is machine speed
rather than driver behaviour.

Two problems, one of them measurably false.

(a) "measures only whether the OS descheduled this process mid-call" — REFUTED.
Most of the elapsed time is genuine on-CPU work inside start_rx, not
descheduling. Measured with time.thread_time() alongside time.perf_counter()
around the 9th start_rx on an idle host (script in scratch, product untouched):

	wall	thread CPU
standalone script, 8 samples	7.6–9.0 ms	6.1–7.2 ms
under pytest, 18 samples	4.5–57.3 ms	3.7–16.2 ms

CPU is 70–85% of wall in the typical run. cProfile over 20 fail-fast calls
attributes ~97% of that CPU to usb_driver.py: UsbAudioDriver.start_rx →
_ensure_selected_devices → _devices_from_backend → _get_uid_map →
_macos_uid.py: get_device_uid_map — a ctypes/CoreAudio device-UID enumeration
that runs on the event-loop thread on every start_rx, including the
saturated one. The saturation branch itself is 0.05–0.07 ms; the preamble ahead
of it is the whole cost. So the removed bound measured how fast this host runs a
real synchronous device enumeration, plus descheduling — not descheduling alone.
In a module whose entire subject is "capture open must never block the event
loop", a comment asserting that this path costs nothing measurable is the kind
of rationale that replicates silently, because nothing executes it.

(b) "has no await points" — NARROWED. start_rx has three: async with self._rx_lock (__aenter__ and __aexit__) and await self._open_stream(...).
What is true, and what I did reproduce, is that none of them yields: an
asyncio.sleep(0) ticker — the most sensitive detector available — advanced
0 times across the call. Please state the property that is true.

Note the conclusion (drop the stopwatch) is right, and I confirmed it
independently: 2 of 20 runs of the pre-change assertion went red on this
idle host at elapsed = 28.163 ms and 31.079 ms against the 25 ms bound. That
also corroborates the magnitude of the "32ms" figure. Only the stated mechanism
is wrong.

Required fix (one commit, comment only): narrow the sentence to what is
established — e.g. that the path never yields to the event loop (ticker: 0
iterations), and that a stopwatch on it therefore measures the cost of
start_rx's synchronous preamble (_ensure_selected_devices enumerates
CoreAudio device UIDs on every call) plus any descheduling, which on an idle
host already consumed 4–16 ms of the 25 ms bound. Keep the observed-red figure
only if you name how it was established. Per CLAUDE.md § Testing, narrow before
you delete, and do not substitute a second specific mechanism you have not
measured.

Checks to run after the fix: uv run pytest tests/test_usb_audio_capture_open_timeout_mor1438.py -q and uv run ruff format --check tests/. No product code is involved.

Claim verdicts

C1 — the removed assertion measured machine speed, not driver behaviour, and
the fail-fast path never yields. CONFIRMED, with a NARROWED mechanism. Ticker
with await asyncio.sleep(0) around the 9th start_rx: 0 iterations,
re-derived myself. Elapsed 19.1 ms on that same call — so the elapsed is real
synchronous work, which is where the author's stated mechanism goes wrong (see
the blocking finding). The conclusion that the bound was machine-dependent is
CONFIRMED, and stronger than claimed: I reproduced the pre-change assertion
going red twice in 20 runs.

C2 — the new test still fails when the guarded behaviour breaks. CONFIRMED.
Mutation applied at import time from a throwaway pytest plugin
(PYTHONPATH=<scratch> uv run pytest -p mut_no_saturation), pinning
UsbAudioDriver._inflight_opens to 0 via a class-level property so
if self._inflight_opens >= _CAPTURE_OPEN_MAX_WORKERS: in _open_stream never
fires. _inflight_opens is read nowhere else (grep -rn _inflight_opens src tests → usb_driver.py only), so the mutation reinstates exactly the removed
bug. Result: 1 failed at line 387 with
AudioCaptureOpenTimeoutError('RX capture open timed out after 0.05s.').
Restored, git status --short clean, 13 passed.

C3 — the drain assertion discriminates on its own. CONFIRMED. Second plugin
kept the mutation and additionally forced
AudioCaptureOpenTimeoutError.__str__ to contain "saturated", so the
pre-existing message assertion is satisfied and only the new assertion can
catch the regression. Result: fails at line 419, assert 1 == 0,
probe.started_count == 1. It does not ride on the message check.

C4 — robust, not hollow. CONFIRMED. I went through the trivially-true
routes:

• Index: backend.rx_streams[len(wedged)]. len(wedged) == 8 and
  len(rx_streams) == 9 after the probe, measured. open_rx appends before
  _open_stream runs, so the probe handle exists on the fail-fast path; if it
  ever stopped existing the test would IndexError (red), not pass.
• Never-started object: under the mutation the same handle reaches
  started_count == 1, so the counter is reachable.
• Skipped assertion: both asserts are inside try:; nothing swallows them.
• Early break: the loop condition is re-asserted after the loop, so a
  deadline expiry fails with "pool never drained".
• Race producing a false green: mutated run repeated 15×, failed 15/15;
  unmutated file repeated 15×, 13 passed 15/15. No false green, no false red.
• Control direction: a legitimate nearby change (reword the saturation warning
  and exception text, move start_coro.close() ahead of the log) leaves the
  file 13 passed — the check does not punish correct work.

One non-blocking brittleness, reported not required: the probe is located
positionally, so a later refactor that moved the saturation check ahead of
self._backend.open_rx(...) — a plausible improvement, since a saturated pool
currently still opens a device handle and logs an INFO line — would make this
test IndexError rather than pass. It fails loudly, so it is not a false green.

C5 — the drain-wait ordering argument. CONFIRMED.
ThreadPoolExecutor._work_queue is a queue.SimpleQueue (FIFO, verified via
inspect.getsource), submit puts and _adjust_thread_count spawns no 9th
thread at max_workers=8, and grep -n _open_executor src/rigplane/audio/usb_driver.py
returns exactly two submit sites — the open (_open_stream) and the late close
(_close_late_stream) — both the same pool. So a queued probe is dequeued
before any close, which is submitted only after the loop thread runs the
future's done-callback. Strictly, "necessarily have started" is an argument
about dequeue order, not about which counter increment retires first; that
residual window is microscopic and 15/15 mutated runs caught it. Sound.

C6 — added prose. NARROWED (see the blocking finding). True and tied:
"the fail-fast path never reaches the pool: it closes the open coroutine
instead of submitting it" (matches _open_stream: start_coro.close() then
raise, before run_in_executor); "an open that QUEUED ... is started as soon
as one of them frees" (reproduced, started_count == 1); the drain comment and
both assertion messages (the failure text printed under mutation is exactly the
diagnosis it promises). False: the two clauses quoted above. On "(observed: 32ms
on an idle host against a 25ms bound)" — I would not block on it: I reproduced
28.2 ms and 31.1 ms reds on the pre-change shape, so the magnitude is real.
But it is an untethered historical number in a committed comment with no
statement of how it was established; if it is kept, name the method.

C7 — the PR body's class survey. NARROWED. Correct where I checked
line-by-line: test_poller.py:169 (sleep(0.05), assert >= 3 at 172),
test_reconnect.py:189 (sleep(0.35), assert >= 2 at 190),
test_handlers_coverage.py:1208/1217/1233/1245 (exact, all four),
the :178/:210 inverse-problem finding (assert elapsed < 0.5 against
_TEST_TIMEOUT_S = 0.05, so a full-timeout penalty lands 10× inside the bound —
confirmed, and worth the separate ticket), and the #2897 / 36c4b162
claim (git log -1 36c4b162 matches; tests/test_web_server.py:3334 is now the
wait-for-condition shape). Four rows are wrong — details under REQUIRED BEFORE
MERGE below.

MANDATORY SQUASH-BODY CORRECTION (commit message — does not need a commit)

cd608214's body carries the same refuted sentence: "That whole fail-fast path
has no await points ... so the bound measures only whether the OS descheduled
this process mid-call, not what the driver did." This repo squash-merges with
COMMIT_MESSAGES, so it lands on main; replace it at merge time with the
narrowed version, matching whatever the fixed comment says.

REQUIRED BEFORE MERGE (PR body edits — head SHA unaffected)

1. "the only thing that can inflate its wall clock is the OS descheduling the
   process" — same refuted claim as the blocking one; correct it here too.
2. tests/test_serial_backend_smoke.py:553 is not a member of the class as
   described. The >= 2 after that sleep is
   assert receiver_count >= 2, "IC-7610 mock is dual-RX" (line 557), reading
   server._get_profile().receiver_count — a static profile property, not an
   event count. The sleep there guards status["observed"] is True, a
   different shape. This row was matched textually, not by meaning.
3. tests/test_usb_audio_capture_open_timeout_mor1438.py:512 — the
   sleep(0.05) at 512 does not gate progressed: the ticker is stopped at
   509–510, before it. The fixed window progressed >= 3 actually counts
   against is the driver's own 0.05 s capture-open timeout. And the survey
   misses the identical sibling in the file under review: the same
   assert progressed >= 3 at line 105
   (test_rx_open_timeout_keeps_event_loop_free).
4. tests/test_managed_ptt_lifecycle.py:177,310 are the
   elapsed = time.monotonic() - before lines; the assert elapsed < 0.2
   assertions are at 179 and 313.
5. "Searched all of tests/ for both shapes": grep -rn "assert .*elapsed\b" tests/ returns 16 sites; the survey lists 8. Excluding the loose ones under
   "tight" is defensible, but tests/test_icom7610_serial_radio.py:620
   (assert elapsed >= 0.04) is a lower-bound shape that neither listed
   category covers. Others omitted: test_radio_poller_coverage.py:4272,4357, 5144,5330, test_radio_connect.py:322,
   test_mor1427_rate_limiter_coalesce.py:534,
   test_managed_tx_effect_service.py:295.

Gates (re-run here, not taken from the PR body)

• uv run pytest tests/test_usb_audio_capture_open_timeout_mor1438.py -q — 13 passed (and 15/15 across repeats)
• uv run ruff check src/ tests/ — All checks passed!
• uv run ruff format --check src/ tests/ — 701 files already formatted
• uv run mypy --strict src/rigplane/web — Success: no issues found in 26 source files
• CI at this head: quick pass (1m37s), grep-gate pass, Agent Review Gate red pending this comment. Full suite not run locally — repo policy restricts it to the remote testbed; the PR body's Mac mini figures are unverified by me.

Not verified

• The PR body's "deterministic 30 ms stall injected into the measured region"
  harness and its elapsed=0.161s control. I reached the same conclusion by a
  different route (20 runs of the pre-change assertion, 2 red at 28/31 ms), so
  I did not rebuild theirs.
• The Mac mini full-suite counts.

Guardrails

1 file, 43 changed lines (36 additions / 7 deletions). Far inside both the soft
threshold (6 / 600) and the hard ceiling (10 / 1000). Product code untouched:
git diff main...HEAD -- src/ is empty. Worktree left byte-identical —
git status --short clean, git rev-parse HEAD still cd60821.

[morozsm]

Agent Review: PASS fe1c761

Round 2 (third head). The round-1 blocking finding is resolved by deletion, and
nothing was substituted in its place — I verified that rather than taking it
from the description. Every sentence remaining in the diff is one I have checked
against the tree. The defects I found this round are all in the PR body, which
never enters the repository and is editable without moving the head, so they are
listed as REQUIRED BEFORE MERGE rather than blocking.

The two judgement calls you asked me to attack

1. Does the ruling reach the two kept paragraphs? No — and I would push back if
you deleted them. The ruling as relayed is conditional: wrong or stale text
is deleted rather than rewritten. Neither paragraph is wrong or stale, and I
have the receipts from round 1 plus a re-check at this head:

• "The fail-fast path never reaches the pool: it closes the open coroutine
  instead of submitting it" — usb_driver.py: UsbAudioDriver._open_stream, the
  saturation branch calls start_coro.close() and raises before
  loop.run_in_executor. Read at this head; git diff main...fe1c7617 -- src/
  is empty, so the product it describes is the product on main.
• "so the probe's handle is never started ... whereas an open that QUEUED ... is
  started as soon as one of them frees" — both halves reproduced: 0 in the
  healthy run, 1 under the mutation.
• The FIFO/drain paragraph — C5, confirmed against queue.SimpleQueue and the
  two self._open_executor submit sites (_open_stream and
  _close_late_stream).

Stretching "absence beats bad text" to correct text would cost the only in-tree
explanation of why started_count == 0 is conclusive rather than merely
prompt — the one non-obvious thing about this test, and the thing a reader
cannot work out by opening the code, because it depends on ThreadPoolExecutor
internals rather than on anything in this repo. The ruling's own justification
("the next reader opens the code and works it out") does not hold for that
paragraph. Keep both.

2. Is "not as a stopwatch reading" now dangling? No. I tested it as a
reference: there is nothing to resolve — no "see above", no symbol, no pointer
to deleted text. grep -n "stopwatch\|descheduled\|25ms\|_get_uid_map\|uncached"
on the file returns line 391 alone, so no other fragment of the removed
paragraph survives to be orphaned. And the clause is true of the code at this
head: the assertions below it are behavioural (probe.started_count == 0), not
timing, and the file contains no timing assertion in this test. A sentence that
accurately describes the code beneath it is not stale, whatever it contrasts
with.

Optional, not required, and explicitly not a round: if the owner reads the
contrast itself as a reference to deleted code, the minimal true version is
# "Fails fast" is asserted as behaviour. Both versions are true, so choosing
between them is taste, and I do not block on taste. Fold it into a later touch
if you want it.

Verified at this head

• No executable change since my C2–C5 confirmations. Tokenised both
  revisions with tokenize, dropping COMMENT/NL/NEWLINE/INDENT/DEDENT: the
  streams for cd608214 and fe1c7617 are identical. I forced a
  one-token sentinel first and confirmed the comparison flags it, so
  "identical" is a measurement, not a silently-broken compare. The deletion
  touched comment lines only.
• Mutations re-pinned at fe1c7617, not inferred: saturation check
  neutralised (_inflight_opens pinned to 0 from a throwaway pytest plugin) →
  red at :387; same mutation with the message assertion satisfied →
  red at :415, assert 1 == 0 (the drain assertion discriminates alone);
  legitimate reword/reorder of the saturation branch → 13 passed (the check
  does not punish correct work); unmutated → 13 passed.
• Full-suite reuse is legitimate. The body cites the Mac mini run at
  cd608214; the token identity above is exactly the "code unchanged since the
  last recorded full run" condition in CLAUDE.md § Testing, so reusing it is
  correct rather than a gap.

REQUIRED BEFORE MERGE — PR body edits (no commit, head SHA unaffected)

1. "1 file, 53 changed lines" is wrong at this head. git diff main...fe1c7617 --shortstat → 32 insertions, 7 deletions = 39 changed
   lines. 53 was additions-of-commit-1 plus additions-of-commit-2; the
   guardrail is measured on the head diff. Still far inside both thresholds, so
   nothing material turns on it — but a size figure that does not match the head
   is the number a future guardrail argument would be built from.
2. :512 is now stale — and the deletion is what staled it. The nine
   removed lines shifted everything below them. At this head the two ticker
   sites are :105 and :510, and the sleep the note describes is at
   :508 (grep -n "progressed >= 3" → 105, 510). The substance of the
   note ("the sleep runs after stop.set() and does not gate progressed")
   is still correct — only the number moved. :178/:210 in the same file are
   unaffected and still exact, since they precede the edit.
3. "There are 16 such assertion sites" is an undercount, and its qualifier is
   vacuous. The count comes from the variable name elapsed, so it is blind
   to bounds written as a bare timer expression. Two more, both outside the
   benchmark files: tests/test_fake_rigctld.py:154 —
   assert loop.time() - started_at < 0.5, and
   tests/test_raw_civ_transaction.py:481 —
   assert time.monotonic() - started >= radio._civ_get_timeout. So ≥18, not
   16. Separately, "outside the benchmark files" excludes nothing: I grepped
   each of the three files in test: mark wall-clock profiling as benchmarks instead of gates #2899 individually and all three contain 0
   elapsed assertions. Worth noting that test_fake_rigctld.py:154 sits
   directly after asyncio.wait_for(server.stop(), timeout=0.5) — the
   wait_for raises before the bound can trip, so it is another instance of
   the inverse defect this PR already reports for :178/:210. The proxy
   missed a member of the class the survey itself names.
4. Shape A is missing a site. Independent sweep (every
   asyncio.sleep(>0) followed within six lines by assert ... >= N, N≥2)
   returns six candidates; after filtering the one you correctly dropped
   (test_serial_backend_smoke.py:553, a static profile property) and the
   meter-poller test already fixed in test: wait for the meter polls instead of counting a fixed window #2897, one listed nowhere remains:
   tests/test_rigctld_ptt_reread.py:139 (assert samples > 20) and :144
   (assert len(calls) >= 2). Both count events accumulated over a fixed
   wall-clock window (PTT_REREAD_INTERVAL_SECONDS * 2.0 plus a
   _PTT_TTL_SECONDS * 2.5 deadline loop with no break-on-condition), which is
   the shape exactly. A finding is an instance until its class is swept.

Squash body — no force-push needed

Your PR-body directive is sufficient; do not rewrite cd608214's body.
gh api repos/rigplane/rigplane-core returns
squash_merge_commit_message: "COMMIT_MESSAGES", which only pre-fills the
squash body from the commit messages — the merger replaces it in the merge
dialog, so the correction needs neither a commit nor a history rewrite. Buying
a force-push and an owner approval for something the merge dialog fixes for
free would be the wrong trade.

Gates (re-run here at fe1c7617)

• uv run pytest tests/test_usb_audio_capture_open_timeout_mor1438.py -q — 13 passed
• uv run ruff check src/ tests/ — All checks passed!
• uv run ruff format --check src/ tests/ — 701 files already formatted
• uv run mypy --strict src/rigplane/web — Success: no issues found in 26 source files
• CI at this head: quick pass (1m35s), grep-gate pass, Agent Review
  Gate red pending this comment.

Not verified

The Mac mini full-suite counts (11631 passed, 126 skipped, 48 xfailed) — repo
policy keeps full runs off this machine; I established only that reusing the
cd608214 result at this head is legitimate. The PR body's 30 ms-stall harness
and its elapsed=0.161s control — I reached the same conclusion by a different
route in round 1 (20 runs of the pre-change assertion, 2 red at 28.2 ms and
31.1 ms on an idle host) and did not rebuild theirs.

Guardrails

1 file, 39 changed lines (32 additions / 7 deletions) at the head. Inside the
soft threshold (6 / 600) and the hard ceiling (10 / 1000). Product untouched:
git diff main...fe1c7617 -- src/ is empty. Worktree left byte-identical —
git status --short clean, HEAD still fe1c7617.