test(eventhubs): de-flake multiple_token_refresh - #4639
test(eventhubs): de-flake multiple_token_refresh#4639Johnathan W (j7nw4r) wants to merge 3 commits into
Conversation
35367da to
d9815f4
Compare
There was a problem hiding this comment.
Pull request overview
This PR de-flakes the multiple_token_refresh test in the Event Hubs authorizer module. The original test read the mock credential's token-get count at fixed wall-clock instants and asserted on it, which raced against the refresh scheduler's boundary behavior (a refresh only lands when the real timer overshoots its scheduled instant, so the landing time drifts under CPU load). The change introduces a bounded-polling helper so scheduler latency delays the test rather than failing it. It is test-only; no product code is modified.
Changes:
- Adds a
wait_for_token_count(credential, target, timeout)helper that polls the count every 100ms until the target is reached or a generous timeout elapses, returning the last observed count. - Replaces the two fixed
sleep-then-read assertions with polling calls (12s and 20s timeouts), widening the acceptance window without changing happy-path runtime. - Strengthens the first assertion from the trivially-true
>= 2to>= 3to match its documented intent of verifyingtoken_refresh_1was refreshed.
d9815f4 to
312da23
Compare
Heath Stewart (heaths)
left a comment
There was a problem hiding this comment.
Nice! Thank you so much! Did you also make sure the tests were un-ignored? Larry Osterman (@LarryOsterman) and I disabled a couple I believe. Or maybe we only talked about it. Would be good to audit any #[ignore tests.
The test read the mock credential's token-get count at fixed wall-clock instants and asserted on it. The final assertion fired only ~1.5-2.5s after the earliest moment the second token's refresh can complete, so under CPU contention the refresh task's wakeup slipped past the deadline, the test observed the stale pre-refresh count, and it panicked. Replace the fixed sleep-then-read assertions with bounded polling (wait_for_token_count): wait up to a generous timeout for the count to reach the expected value. This widens the acceptance window from ~2s to ~10s without changing happy-path runtime, and still fails fast if a refresh never happens. Also strengthen the first assertion from the trivially-true >= 2 to >= 3 to match its documented intent.
The sibling test `token_refresh` was ignored in Azure#3691 for "frequent off-by-one issues in dev loop". That is the same flakiness class this branch fixes: the test read the mock credential's token-get count at a fixed instant after a 13-second sleep, and the refresh it waits for lands 8 to 12 seconds in. The margin was about one second, so scheduler latency pushed the refresh past the read. Replace the fixed sleep and read with `wait_for_token_count`, then remove the `#[ignore]`.
312da23 to
d0c8223
Compare
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 1 out of 1 changed files in this pull request and generated no new comments.
Suppressed comments (2)
sdk/eventhubs/azure_messaging_eventhubs/src/common/authorizer.rs:980
- This 20-second window overlaps
token_refresh_1's next refresh, which the comments above place 13–15 seconds from the first wait. Iftoken_refresh_2is never refreshed,token_refresh_1can still increment the shared credential count from 3 to 4 and make this assertion pass, especially under the scheduler delays this change targets. Please wait on a per-path signal (for example,path2's cached token/expiry advancing), or otherwise keep the acceptance window disjoint fromtoken_refresh_1's next refresh.
let final_count = wait_for_token_count(&mock_credential, 4, Duration::seconds(20)).await;
sdk/eventhubs/azure_messaging_eventhubs/src/common/authorizer.rs:742
- Use a monotonic clock for this elapsed-time deadline.
OffsetDateTime::now_utc()follows the system wall clock, so a clock correction can make this helper time out early or wait longer than the promised bound, reintroducing timing flakiness. Tokio'sInstantuses the same monotonic timer domain astokio::time::sleep.
let deadline = OffsetDateTime::now_utc() + timeout;
loop {
let count = credential.get_token_get_count();
if count >= target || OffsetDateTime::now_utc() >= deadline {
Two points from the Copilot review. The second wait in multiple_token_refresh spans about 20 seconds, which is wide enough to cover path1's next refresh. The get_token count is shared by both paths, so path1 could raise the count to 4 on its own and satisfy the assertion even if path2 never refreshed. A probe of the real schedule measured path2 refreshing 15.1s in and path1 refreshing again 20.7s in, both inside that window. Add a test-only peek_token hook and a wait_for_token_refresh helper that watches one path's cached expiry. A refresh replaces the entry in place and only ever advances expires_on, so each assertion now names the path it tests. Also measure both timeouts with tokio::time::Instant instead of the wall clock, so a clock correction cannot end a wait early or stretch it past the stated bound.
There was a problem hiding this comment.
Pull request overview
Copilot reviewed 1 out of 1 changed files in this pull request and generated no new comments.
Suppressed comments (1)
sdk/eventhubs/azure_messaging_eventhubs/src/common/authorizer.rs:998
- The fixed 10-second setup sleep can itself overshoot under scheduler contention, allowing path1 to refresh before this authorization runs. In that case the exact
current_count == initial_count + 2assertion immediately below observes 3 and the test remains flaky—the same latency this PR is intended to tolerate. Keep the lower-bound check (both initial authorizations occurred) without rejecting an early background refresh.
let path2_expiry = authorizer
.authorize_path(&recoverable_connection, &path2)
.await
.unwrap()
.expires_on;
Summary
common::authorizer::tests::multiple_token_refreshfails intermittently when run locally, taking several seconds to surface the failure. This replaces its fixed-instant count assertions with bounded polling so scheduler latency delays the test rather than failing it. Its siblingtoken_refresh, which was ignored for the same reason, gets the same treatment and is enabled again.Motivation
The test drives the token refresh scheduler with a 20-second mock token and a 5-second (±0.5s) refresh bias, then reads the mock credential's token-get count at fixed wall-clock instants and asserts on it. The final assertion (
final_count >= 4, the panic atauthorizer.rs:658:9) fires only ~1.5-2.5s after the earliest moment the second token's refresh can complete (~25s in). The refresh scheduler sleeps until exactlyexpires_on - biasand then gates the refresh onexpires_on >= now + bias, which sits on the boundary; a refresh only lands because the real timer overshoots, and a miss re-sleeps with freshly rolled jitter. Under CPU contention the refresh task's wakeup slips past the assertion's fixed deadline, so the test observes the stale pre-refresh count and panics.token_refreshhas the same defect and was disabled in #3691 with the reason "frequent off-by-one issues in dev loop". It sleeps a fixed 13 seconds for a refresh that lands 8 to 12 seconds in, so its margin is about one second. Measured under a saturated CPU, that refresh lands between 8.1s and 11.9s, which puts the old fixed deadline inside the observed spread.Widening a wait window introduces a second problem. The mock credential's call count is shared by every path, so a count target cannot say which path was refreshed. A probe of the real schedule, timed from the moment the second path is authorized, measured path1 refreshing at 5.3s, path2 at 15.1s, and path1 again at 20.7s. A 20-second wait that starts at 5.3s therefore covers path1's second refresh, so path1 alone can raise the count to 4 and satisfy the second assertion even when path2 never refreshes.
Changes
Add a
wait_for_token_count(credential, target, timeout)test helper that polls the count until it reaches the target or a generous timeout elapses. Replace the fixedsleep-then-read assertions inmultiple_token_refreshandtoken_refreshwith bounded waits, and remove the#[ignore]fromtoken_refreshso both timing tests run again. This widens the acceptance window while leaving happy-path runtime unchanged (a wait returns as soon as its condition holds), and a refresh that never happens still fails fast at the timeout.Add a
#[cfg(test)]peek_tokenhook and await_for_token_refreshhelper that watches one path's cached expiry, then use it for both waits inmultiple_token_refresh. A refresh replaces the cache entry in place and only ever advancesexpires_on(a credential that returns the same expiry is marked non-refreshable instead), so each assertion is now tied to the path it names rather than to a counter shared with the other path. The first assertion is also strengthened from the trivially-true>= 2to>= 3.Measure both timeouts with
tokio::time::Instantrather thanOffsetDateTime::now_utc(), so a wall-clock correction cannot end a wait early or stretch it past the stated bound.Apart from the test-only
peek_tokenhook, there are no product code changes: the scheduler's boundary behavior is harmless at the production 6-minute bias.Test plan
cargo fmt,cargo clippy --all-features --all-targetsunder-Dwarnings, andcspellover the changed file are clean.cargo test -p azure_messaging_eventhubs --libpasses: 145 passed, 0 failed, including both timing tests.#[ignore]in the repository was audited. All of them are structural rather than flakiness suppression: doc-example compile checks, live or environment-gated tests, resource-heavy stress tests, the macro-generated live and playback skips, and one attached to issue [TypeSpec] Date-time parsing assumes UTC format #1982.token_refreshwas the only test disabled for timing flakiness.#[tokio::test]clones of both test bodies, because a#[recorded::test]binary run directly cannot start its test-proxy. Each clone was built once and run as concurrent processes with the CPU saturated: 20/20 passes before the per-path change and 16/16 after it. The temporary clones and the schedule probe were then removed.