Repository navigation
balancer/ringhash: fix flaky TestRingHash_RequestHashKeyConnecting - #9329
Conversation
Fixes grpc#9030 `TestRingHash_RequestHashKeyConnecting` counts connection attempts in the same loop that resumes the blocked one, so it can count an attempt that its own `Resume()` caused. Resuming makes the endpoint READY, ring_hash publishes a picker with `hasEndpointInConnectingState` false, and the queued RPCs pick again and start a connection to one idle endpoint along the ring walk, which is what gRFC A76 asks for (picker.go:93-115). If the loop is still scanning when that dial reaches the blocking dialer it counts that attempt and the test fails. Both failures linked from the issue show the second subchannel being created after the resume, never before it. The fix orders the phase so the assertion cannot observe something the test itself caused: 1. First RPC in a goroutine, wait for a hold to be entered. 2. Count all 20 holds, want exactly 1. 3. Second RPC on the test goroutine, short deadline, `WaitForReady(true)`, want `DeadlineExceeded`. 4. Count all 20 holds again, want exactly 1. 5. Only then resume the single started hold. Both counts precede any `Resume()`. Only two pickers can exist before that point and a pick against either cannot start a second connection attempt, so `at most 1` is tightened to `exactly 1` and the fixed 10ms sleep is removed. I proved this with a throwaway instrument that forces the CI interleaving deterministically (current loop fails 100 of 100, this change 0 of 100), and also reproduced the flake organically under core pinning (current 2 of 300, this change 0 of 2000). The CI log ordering, the picker state argument and the full numbers are in the first comment. ### Relation to grpc#9079 grpc#9079 split the counting loop from the resume loop and made the second RPC synchronous. Both are right and both are kept here. Its stated cause was that the second RPC could reach the picker before the balancer had recorded the endpoint as connecting; I could not reproduce that and I do not think it can happen, for the reasons in the first comment. The `AwaitState(ctx, t, cc, connectivity.Connecting)` it added is not carried over, because `exitIdleMode` sets the channel to CONNECTING before the resolver is started (clientconn.go:402), so that wait is already satisfied while ring_hash has reported nothing. grpc#9079 was closed by its author saying the test has multiple race conditions that cannot all be fixed, and that other tests in this file are flaky too. I am not claiming otherwise. This addresses the one mechanism that both linked failures show and that reproduces locally. I have not tried to make the file as a whole race free. ### Also in this diff The one remaining background RPC reports through a buffered channel instead of calling `t.Errorf`, matching lines 1945-1964 of this file, since a `t.Fatalf` in the test goroutine could otherwise produce a log from the background goroutine after the test finished. The doc comment now describes what the test checks. ### One review point The check that the second RPC blocked in the picker matches on the message substring from picker_wrapper.go:129. The idiom is used elsewhere in the repo (test/roundrobin_test.go:125), but the string belongs to another package. Nothing in the fix depends on it, so it can be dropped if unwanted. RELEASE NOTES: n/a
|
Detail behind the description, kept out of the commit message. The interleaving in the two CI failuresThe failure line carries no relative timestamp, so the last row is the next logged event after it.
Intercept to resume is 11.03ms and 10.43ms, which is the Why the second RPC cannot see a stale picker#9079's stated cause was that the second RPC could reach the picker before ring_hash had recorded the first endpoint as connecting. Reading the path, that ordering is foreclosed:
The Why the count is now deterministicBefore the resume the channel can hold only two pickers:
No third picker can appear: the held dial keeps that endpoint in CONNECTING, no other endpoint changes state, and The short deadline on the second RPC is not a tolerance. Whether the test passes no longer depends on its length, because How it was provenThe flake does not reproduce on an unloaded workstation, so I wrote a throwaway instrument that blocks the counting loop immediately after
The middle row is 67 rather than 100 because the current loop never revisits an index it has passed, so it sees the extra dial only when that endpoint sits at a higher index than the resumed one. A variant that observes every extra dial showed one extra dial in 26 runs and two in 74, since both queued RPCs pick again and each may probe an idle endpoint. Feeding that mix into the index model predicts a 60% failure rate for the unmodified loop, close to the 67 of 100 measured. With this change the number of started holds at assertion time was exactly 1 on all 600 instrumented runs, never 0 and never 2. Organic reproductionPinning the test binary to one core while leaving
The two failures carry the CI text, Two failures in 300 is a noisy rate and it would be easy to overstate what the 2000 clean runs prove. At the point estimate of 0.67% they would be a one in 600000 coincidence, but at the low end of the 95% interval on that rate (0.18%) Rest of the file#9079's closing comment said other tests in this file are flaky too, so I looked. The same sleep-then-count shape appears in Also runThe changed test 200 times without instrumentation, and I have not run this at the 100K scale used on this issue in April. If someone ca kick that off before merging, it would be worth having. |
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## master #9329 +/- ##
==========================================
+ Coverage 83.26% 87.61% +4.34%
==========================================
Files 423 430 +7
Lines 35236 30705 -4531
==========================================
- Hits 29341 26901 -2440
+ Misses 4402 3803 -599
+ Partials 1493 1 -1492 🚀 New features to boost your workflow:
|
| // of racing the assertions below. Since there is already an endpoint in | ||
| // Connecting state, the picker must queue the RPC rather than trigger | ||
| // another connection attempt, so the RPC fails with DeadlineExceeded. | ||
| sCtx, sCancel := context.WithTimeout(ctx, defaultTestShortTimeout) |
There was a problem hiding this comment.
I ran this for 100K times and it failed for around 40 - 60 times with the error :
[grpc/balancer/ringhash/ringhash_e2e_test.go:3034]: EmptyCall(): got error "context deadline exceeded", want it to contain "while waiting for connections to become ready"
So basically since the second RPC has a very short deadline, it is failing because the context expired before reaching the pick. We can increase the timeout of the second RPC.
We will also need to remove the grpc.WithConnectParams(fastConnectParams) which is also causing the test to fail if the test is going slow.
To fix the race between Resume() and checking the connections , why cant we first check the number of connections attempted and after that call Resume() on the connection? This seems like a simpler and cleaner fix.
With this too , the test flakes 1/300K times with Connection attempt timed out because of the connection time being very low and the last go routine going slow. But after removing the grpc.WithConnectParams(fastConnectParams) this fix seems to work seemlessly.
The approach here works too, but it could still be flaky based on the timeout we decide for the second RPC.
Let me know what you think.
There was a problem hiding this comment.
You are right, 10ms is too tight there.
I will increase the second RPC's timeout and drop grpc.WithConnectParams(fastConnectParams) here.
On the ordering, I think we may be describing the same shape: both counts already run before any Resume(), at lines 2884 and 2917, with the single Resume() at 2925. If you are seeing a case where that still races, could you point me at it?
|
This PR is labeled as requiring an update from the reporter, and no update has been received after 6 days. If no update is provided in the next 7 days, this issue will be automatically closed. |
|
This PR is labeled as requiring an update from the reporter, and no update has been received after 6 days. If no update is provided in the next 7 days, this issue will be automatically closed. |
The second RPC in TestRingHash_RequestHashKeyConnecting used defaultTestShortTimeout (10ms) as its deadline. Under load the context can expire before newAttemptLocked checks it, so the RPC fails with a plain "context deadline exceeded" instead of the picker's "while waiting for connections to become ready" and the test fails. Reviewer stress runs hit this in about 50 of 100K iterations. Use a 100ms deadline local to this test, which is what defaultTestShortTimeout already is in several other packages. The worst pre-pick delay I measured with -race on an oversubscribed core was 40ms. Also drop grpc.WithConnectParams(fastConnectParams) from this test. Its 100ms MinConnectTimeout expires while the dial is held, the subchannel fails and reconnects, and the test then counts a second connection attempt. Nothing in this test fails a connection on purpose, so the backoff settings had no other effect. With -race, pinned to one core alongside 20 busy loops, the previous version failed 93 of 1500 runs: 4 with the plain context error, 89 with extra connection attempts or RPCs routed to another backend after the held dial timed out. This version passed 1500 of 1500 under the same load.
|
Raised the second RPC's deadline to 100ms with a const local to this test (the shared 10ms With 100ms is also the value |
If the test goroutine is descheduled for longer than secondRPCTimeout right after the context is created, the RPC fails at the ctx check in newAttemptLocked with a plain "context deadline exceeded". The message check then fails the test. Such an RPC never calls Pick, so it cannot change the balancer state and sending another one is safe. As suggested in review, loop until an RPC fails with the picker's "while waiting for connections to become ready", bounded by the test context. To exercise the retry path I gave the first two attempts of every run a 1ns deadline. All 200 of those attempts ended with the plain context error and all 100 runs passed, including the check after the loop that exactly 1 connection attempt was made. With the normal deadline the test passed 200 of 200 runs and go test -race ./balancer/ringhash/... passed.
eshitachandwani
left a comment
eshitachandwani
left a comment
There was a problem hiding this comment.
LGTM. Adding @mbissa as a second reviewer.
Fixes #9030
TestRingHash_RequestHashKeyConnectingcounts connection attempts in the same loop that resumes the blocked one, so it can count an attempt that its ownResume()caused. Resuming makes the endpoint READY, ring_hash publishes apicker with
hasEndpointInConnectingStatefalse, and the queued RPCs pick again and start a connection to one idle endpoint along the ring walk, which is what gRFC A76 asks for (picker.go:93-115). If the loop is still scanning when thatdial reaches the blocking dialer it counts that attempt and the test fails. Both failures linked from the issue show the second subchannel being created after the resume, never before it.
The fix orders the phase so the assertion cannot observe something the test itself caused:
WaitForReady(true), wantDeadlineExceeded.Both counts precede any
Resume(). Only two pickers can exist before that point and a pick against either cannot start a second connection attempt, soat most 1is tightened toexactly 1and the fixed 10ms sleep is removed. I proved thiswith a throwaway instrument that forces the CI interleaving deterministically (current loop fails 100 of 100, this change 0 of 100), and also reproduced the flake organically under core pinning (current 2 of 300, this change 0 of 2000).
The CI log ordering, the picker state argument and the full numbers are in the first comment.
Relation to #9079
#9079 split the counting loop from the resume loop and made the second RPC synchronous. Both are right and both are kept here. Its stated cause was that the second RPC could reach the picker before the balancer had recorded the endpoint
as connecting; I could not reproduce that and I do not think it can happen, for the reasons in the first comment. The
AwaitState(ctx, t, cc, connectivity.Connecting)it added is not carried over, becauseexitIdleModesets the channel to CONNECTING before the resolver is started (clientconn.go:402), so that wait is already satisfied while ring_hash has reported nothing.#9079 was closed by its author saying the test has multiple race conditions that cannot all be fixed, and that other tests in this file are flaky too. I am not claiming otherwise. This addresses the one mechanism that both linked failures
show and that reproduces locally. I have not tried to make the file as a whole race free.
Also in this diff
The one remaining background RPC reports through a buffered channel instead of calling
t.Errorf, matching lines 1945-1964 of this file, since at.Fatalfin the test goroutine could otherwise produce a log from the background goroutine after the test finished. The doc comment now describes what the test checks.One review point
The check that the second RPC blocked in the picker matches on the message substring from picker_wrapper.go:129. The idiom is used elsewhere in the repo (test/roundrobin_test.go:125), but the string belongs to another package. Nothing
in the fix depends on it, so it can be dropped if unwanted.
RELEASE NOTES: n/a