test(telemetry): deliver an attempt before letting the paused clock kill it - #1219
Merged
Merged
Conversation
…ill it `no_response_after_a_header_less_response_is_dropped_at_once` fails about two runs in five when the whole `aisix` binary test set runs together — `left: 2, right: 3`, "the batch that met no response was not re-sent". It passes every time in isolation, which is what makes it look like nothing. The two halves of these tests run on different clocks. `posts` is pushed by the wiremock responder, on wiremock's own runtime, in real time. The sender's 10-second request timeout runs on the paused clock the test advances itself, in instant steps. `STEP_WHILE_UNREACHABLE` is one second, so an attempt gets ten polls — microseconds of wall clock — to cross a real socket and reach a real wiremock thread before its own timeout cuts it off. Sometimes it makes it; sometimes the request is cancelled before the responder ever runs, and then the attempt is never recorded at all. `STEP_WHILE_SERVING` is ten milliseconds and gives the same exchange a thousand polls, which is why every phase that already used it is reliable. So a phase that needs the server to have RECEIVED an attempt cannot run on the big step. The two tests that did now reach that point on the small step and only then switch to seconds to blow the timeout — the same two-phase shape one of them already used for its first exchange, applied to the boundary that actually needs it. A third test asserts an exact attempt count that includes stalled attempts; its wait now covers the count as well, which it can do safely because it already steps in milliseconds throughout. Waiting for the attempt count is what pins "a stalling batch is re-sent at all", so the `attempts > 2` assertion that followed it is gone rather than left as a check that can no longer fail; the exact-count and same-batch assertions stay, and still carry the upper bound. The four other waits that are followed by an assertion on `posts` are left alone: three wait on a counter that only an ANSWERED attempt can advance, and a response cannot exist unless the responder ran and recorded the post first; the fourth asserts that nothing was ever sent, which no wait can establish. Measured on this machine, full binary test set: 2 failures in 5 runs before, 0 in 25 after.
|
Navigate logical layers of code changes, visualize relationships, and explore their blast radius. Warning Review limit reached
This review includes 1 billable file and costs up to $0.25.
Reviews can continue after your included limit without a manual trigger. An admin must approve usage-based billing. Or wait 45 minutes for your next included review. View limit detailsLimit details: You’ve used all 2 included reviews currently available. Your 59 included PR review attempts over the past 7 days set your current allowance at 2 reviews per hour. Review configuration: ⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Essentials Run ID: 📒 Files selected for processing (1)
No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Essentials Run ID: 📒 Files selected for processing (1)
Included review availability: Your plan provides up to 5 included reviews per hour; 0 remain after this review. 📝 WalkthroughWalkthroughTelemetry retry tests now synchronize wiremock request receipt before coarse virtual-time advancement. They also verify that recorded retries preserve the batch and include stalled attempts in retry-count checks. ChangesTelemetry retry test synchronization
Priority: ⬇️ Low Estimated code review effort: 2 (Simple) | ~10 minutes Change: Other Merge Risk: ⚪ Minimal · up to This change improves telemetry test determinism without modifying production behavior or introducing user-facing impact. 🚥 Pre-merge checks | ✅ 6✅ Passed checks (6 passed)
✨ Finishing Touches📝 Generate docstrings
🧪 Generate unit tests (beta)
Comment |
…ded wait Review findings on the flake fix. The `drive_until` doc had a duplicated summary line left over from the rewrite, and framed the rule as "a `posts` condition and a metric condition are not interchangeable". That is the symptom. The rule is about the STEP: at one second an attempt gets ten polls to cross a real socket before its own timeout cancels it, and a cancelled request is never recorded at all — so a phase that has to end with the server having received an attempt belongs on the small step whatever its condition is written in terms of. The comment on the budget test's new wait named the wrong attempt: the script stalls from attempt 2, which the preceding wait had already delivered, so the new one takes attempt 3. `assert_identical_resends(&posts, attempts)` with `attempts` read from `posts.len()` one statement earlier asserted a length against itself — no upper bound, contrary to what the comment beside it claimed — and took the lock twice, so a recording landing in between failed the test on a count that disagreed with itself. The same-batch check, which is the part with content, now runs under one lock. And the wait that folded the give-up metric together with the attempt count is two waits again. Folded, a recording that never arrived spent the full wall-clock deadline and then reported that the batch was never given up on — which it was; the missing recording was the defect, and it now says so. Full binary test set: 12 further runs green (37 in total on this change).
The wait for the attempt count said "a stalled attempt was never recorded", which is the symptom. What the test guards is that a stalled attempt does not consume the give-up cap, and that is exactly what a short count means: the sender gave up before its fifteenth attempt. The message says that now. And the step's margin is stated as margin. One delivery takes 14 to 21 iterations of the drive loop, against ten at the big step and a thousand at the small one — two orders of magnitude, which is why one is reliable and the other is a coin flip, but neither is an invariant. Making it one would mean synchronising on a server-side event rather than a poll budget; nothing here needs that yet.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Problem
telemetry::tests::no_response_after_a_header_less_response_is_dropped_at_oncefails about two runs in five when the wholeaisixbinary test set runs together:It passes every time in isolation, which is what makes it look like nothing. Measured on unmodified
mainat4875c2d3: 2 failures in 5 full-suite runs; the same test 6 for 6 green when run alone. It is load-sensitive, so CI — where the suite runs undercargo llvm-covinstrumentation — is where it shows up.Cause
The two halves of these tests run on different clocks.
postsis pushed by the wiremock responder, which runs on wiremock's own runtime, in real time. The sender's 10-second request timeout runs on the paused clock the test advances itself, in instant steps.STEP_WHILE_UNREACHABLEis one second, so an attempt gets ten polls — microseconds of wall clock — to cross a real socket and reach a real wiremock thread before its own timeout cuts it off. Sometimes it makes it; sometimes the request is cancelled before the responder ever runs, and the attempt is then never recorded at all.STEP_WHILE_SERVINGis ten milliseconds and gives the same exchange a thousand polls, which is why every phase that already used it is reliable.Measured in isolation on the same shape — paused clock, 10s client timeout, a wiremock that never answers, the same poll/advance/yield loop:
One delivery takes 14 to 21 iterations of that loop (min/median/max over 30). Ten is structurally short of it; a thousand is two orders of magnitude clear. The small step is margin rather than an invariant, and the
drive_untildoc now says so.So a phase that needs the server to have received an attempt cannot run on the big step.
Change
The two tests that did now reach that point on the small step and only then switch to seconds to blow the timeout — the same two-phase shape one of them already used for its first exchange, applied to the boundary that actually needs it. A third test asserts an exact attempt count that includes stalled attempts; its wait now covers the count as well, which it can do safely because it already steps in milliseconds throughout.
Waiting for the attempt count is what pins "a stalling batch is re-sent at all", so the
attempts > 2assertion that followed it is removed rather than left as a check that can no longer fail. The exact-count and same-batch assertions stay, and still carry the upper bound.drive_untilandSTEP_WHILE_UNREACHABLEnow state the rule, since neither said anything about delivery and that is the assumption that produced this.Sites deliberately left alone
Four other waits are followed by an assertion on
postsand are not exposed:a_dedup_header_with_an_unknown_value_does_not_allow_a_re_senda_non_retryable_status_is_dropped_even_when_dedup_is_supporteda_batch_answered_and_refused_eight_times_is_given_up_onA second thing it fixes
In the header-less test,
advance(FLUSH_INTERVAL)moves the clock five seconds while attempt 2 is still on the wire. On the one-second step that left five polls — so attempt 2 could be judged a no-response failure, which would keepdedup_seenset and run the scenario backwards from what the test claims to cover. On the small step it gets five hundred.Verification
Full
aisixbinary test set, this machine:No product code changes —
crates/aisix-server/src/telemetry.rstest module only.🤖 Generated with Claude Code