Skip to content

test: stop the voice budget test racing the CI scheduler - #378

Merged
kshivang merged 1 commit into
masterfrom
fix/voice-budget-flaky-test
Aug 27, 2026
Merged

test: stop the voice budget test racing the CI scheduler#378
kshivang merged 1 commit into
masterfrom
fix/voice-budget-flaky-test

Conversation

@kshivang

Copy link
Copy Markdown
Owner

The flake

VoiceToolSafetyTest > approval spends the tool's budget rather than adding to it, macOS only, never Ubuntu or Windows:

commit Build & Test
47b61bc4 (Aug 24, before the latency work) ❌ this test
cacaba54
ae378765 (#376 merge) ❌ this test
ea28e085 (#377 merge, current master)

Pre-existing and unrelated to either merge - it predates both. It fails at the assertFailsWith line, meaning no exception at all, not the wrong one.

Cause

The test sleeps delay(250) inside the approver, against an approval slice of min(APPROVAL_MS, 400) = 400 ms. That leaves ~150 ms of headroom to cover two withContext(Dispatchers.IO) hops plus whatever the runner is doing.

When the headroom runs out on a loaded box, withTimeoutOrNull around the approval returns null, confirmationRefusal answers with the refusal payload, the tool call never runs, nothing throws, and assertFailsWith fails. The test was asserting on the scheduler rather than on the executor.

Fix

CompositeVoiceToolExecutor already takes an injectable clock - added with the comment "Injected so a slow approval can be exercised without one". The test simply never used it.

The approver now returns immediately while reporting that it spent 250 ms, which is exactly the input the property is about. The fixture gains a nowMs parameter to pass it through.

Deterministic in the direction that matters: the approval reports 250 ms of a 400 ms budget, so the call runs under withTimeoutOrNull(150) while sleeping 250 ms. delay can overshoot but never finish early, so the timeout always wins. The remaining sleep is 250-vs-150, where overshoot only strengthens the assertion - rather than 250-vs-400, where overshoot inverted the outcome.

Still catches the bug it exists for

Mutating remainingMs = budgetMs - (nowMs() - startedAtMs) to = budgetMs (a fresh budget for the call - the exact bug the test was written for) makes it fail. Verified.

Swept for the same shape

The other delays in these tests are all delay(60_000) against small budgets, where overshoot can only make the timeout more certain. No other instance of a sleep sized close to the budget it races.

What I did not do

I did not try to prove this with local load testing. The flake is macOS-CI-specific, and a green loop on a developer machine is exactly what let it look fine while it was failing in CI. This PR's own CI run is the evidence, and re-running it a few times is the honest way to build confidence.

Test-only change: 2 files, +32/-2.

VoiceToolSafetyTest > "approval spends the tool's budget rather than adding to
it" has failed twice in four days, macOS only, never on Ubuntu or Windows:

  47b61bc  2026-08-24  failure   (before any of the latency work)
  cacaba5              success
  ae37876  2026-08-27  failure
  ea28e08              success

It is a genuine flake, not a regression from either merge, and it fails at the
assertFailsWith line - no exception at all rather than the wrong one.

Cause. The test sleeps delay(250) inside the approver, against an approval slice
of min(APPROVAL_MS, 400) = 400 ms. That leaves ~150 ms of headroom to cover two
withContext(Dispatchers.IO) hops and whatever the runner's scheduler is doing. On
a loaded macOS box the headroom runs out, so withTimeoutOrNull around the approval
returns null, confirmationRefusal answers with the refusal payload, the tool call
never runs, nothing throws, and assertFailsWith fails. The test was asserting on
the scheduler, not on the executor.

Fix. CompositeVoiceToolExecutor already takes an injectable clock, added with the
comment "Injected so a slow approval can be exercised without one" - the test just
never used it. The approver now returns immediately while REPORTING that it spent
250 ms, which is exactly the input the property is about. The fixture gains a
nowMs parameter to pass it through.

Why this is now deterministic in the direction that matters: the approval reports
250 ms of a 400 ms budget, so the call runs under withTimeoutOrNull(150) while
sleeping 250 ms. delay can overshoot but never finish early, so the timeout always
wins. The remaining sleep is 250-vs-150, where overshoot only strengthens the
assertion, rather than 250-vs-400 where overshoot inverted the outcome.

The test keeps its full discriminating power: reintroducing the bug it exists for
(hand the call a fresh budget instead of the remainder) makes it fail, verified by
mutating `remainingMs = budgetMs - (nowMs() - startedAtMs)` to `= budgetMs`.

Swept the rest of the voice tests for the same shape. The other delays are all
delay(60_000) against small budgets, where overshoot can only make the timeout
more certain. No other instance of a sleep sized close to the budget it races.

Deliberately not verified by local load testing: the flake is macOS-CI-specific
and a green loop on a developer machine is what made this look fine for months.
CI is the only venue that can confirm it.
@claude

claude Bot commented Aug 27, 2026

Copy link
Copy Markdown

Review

Test-only change, and the diagnosis holds up against CompositeVoiceToolExecutor.kt:198-223. Walking the new fixture through it:

  • budgetMs = 400, startedAtMs = nowMs() = 0
  • hit.gatedapprove runs, clockMs += 250, returns true immediately (the approval slice min(APPROVAL_MS, 400) is now irrelevant — nothing sleeps inside it, which is exactly the headroom that ran out on macOS)
  • remainingMs = 400 - (250 - 0) = 150withTimeoutOrNull(150) around a delay(250) → null → VoiceToolException("… timed out")

And the mutation you describe (remainingMs = budgetMs) gives withTimeoutOrNull(400) around delay(250), which completes and throws nothing. So the test still fails on the bug it exists for. The nowMs default in the fixture matches the production default, so no other composite(...) call site changes behaviour. Good use of a seam that was built for this and never wired up.

Three things worth considering, one of them substantive.

1. "timed out" is thrown from two branches, so this can still go green for the wrong reason

Tool $name timed out is emitted at both CompositeVoiceToolExecutor.kt:205 (remainingMs <= 0, tool never invoked) and :223 (result == null, tool invoked and cut off). The assertion only matches the string, so a future regression in the other direction — the approval being charged twice, or the approval slice subtracted on top of the elapsed time — would leave remainingMs <= 0, skip the call entirely, throw the identical message, and this test would pass.

One line closes it:

assertTrue(failure.message!!.contains("timed out"), failure.message!!)
assertEquals(1, source.calls.size, "the call never got its remaining slice")

FakeToolSource.call records into calls before onCall runs (VoiceToolSourceFixtures.kt:91), so this fires even though the call is cancelled. It also makes the test name true in both directions: it spends the budget, but doesn't spend all of it. The sibling test at VoiceToolSafetyTest.kt:719 already asserts the mirror image (source.calls.isEmpty()), so the shape is established.

2. Cheap coverage now that the clock is injectable: the remainingMs <= 0 branch

Nothing currently exercises "the modal ate the whole budget" — the early throw at :205. With this PR's wiring that's a fully deterministic test with no delay anywhere:

policy = VoiceToolPolicy(approve = { _, _ -> clockMs += 400L; true }),
// … callTimeoutMs = 400L, nowMs = { clockMs }
// expect: VoiceToolException("timed out") AND source.calls.isEmpty()

That's the boundary the "spends rather than adds" property is actually protecting — an approval that overruns must not hand the tool a fresh or negative budget — and it costs 0 ms of wall clock. Worth adding while the wiring is fresh.

3. The residual real-time coupling is 100 ms, and you can't widen it the obvious way (low priority)

The surviving race is delay(250) vs withTimeoutOrNull(150). Your argument is right — delay can't finish early, and both timers sit in the same deadline-ordered queue, so the 150 ms one is processed first even if the timer thread is starved. Nothing to fix.

Flagging the trap for the next person, though: the obvious "make it safer" move of bumping the sleep to delay(60_000) (matching line 709) would silently destroy the mutation detection — under the bug the call gets a fresh 400 ms, and 60 s still exceeds that, so the test would pass either way. The 250 is load-bearing precisely because it is under 400. If more slack is ever wanted, the whole triple has to scale together: budget 4 000 / approval reports 2 500 / call sleeps 2 500 gives 1 s of margin, still goes red under the mutation, and costs ~1.5 s of runtime. Probably not worth it — but one clause in the comment saying "250 < 400 is what makes the mutation detectable" would stop someone tuning it away.

Smaller notes

  • var clockMs mutated inside a suspend approver on Dispatchers.IO and read from the executor's coroutine is safe here, because withContext (:252) establishes happens-before in both directions — worth knowing it's the withContext boundary doing that work, not the var. It also matches the var clock = 1_000L convention in VoiceCallServiceTest and HostVoiceCallControllerTest, so no change wanted.
  • The closing comment sits after the final assertion but explains a setup decision. Folding it into the preamble block would put the whole rationale in one place, ahead of the code it justifies.
  • Sweep claim checked and accurate: VoiceToolSafetyTest has exactly two delay(...) calls, and the other is delay(60_000) against a 200 ms budget, where overshoot only makes the timeout more certain. Nothing elsewhere in the voice test package sizes a sleep near the budget it races.
  • Agreed on not chasing this with local load testing — a green loop on a dev box is what let the original look fine. CI re-runs are the honest evidence.

No blocking concerns, and no production code is touched, so there is no security or performance surface here. Item 1 is the one I'd want before merge; 2 is a nice-to-have.

@kshivang
kshivang merged commit 15874db into master Aug 27, 2026
5 checks passed
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.

1 participant