fix(manifestutil): report one message when the CRD wait is cancelled - #3742
Conversation
WaitForCRDsEstablished reported a cancelled context two different ways. The check at the top of the poll loop returned a message with no CRD name; the select at the bottom named the CRD the poll had stopped on. Which one ran was left to the scheduler: when the deadline and a tick come ready in the same instant, a select picks between the ready cases at random, so one cancellation reached the operator either way. Build the message in one place and return it from both exits, so the two are indistinguishable by construction. The name is carried across iterations, since a cancellation noticed at the top of the loop has no poll of its own to take one from, and starts as the first CRD of the set for a wait cancelled before any poll observed anything. Keeping the check at the top is what makes carrying the name worthwhile. A client refuses Get on a dead context at the first name in the list whichever CRD is actually lagging, so a loop that re-entered and polled anyway would overwrite the name its last poll settled on. The check closes that window and no more than that: a context dying part-way through a poll still records the first Get to fail, because this branch cannot tell a refused request from a CRD status. Assisted-By: Claude <[email protected]> Signed-off-by: Aleksei Sviridkin <[email protected]>
|
No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configurationConfiguration used: Path: .coderabbit.yaml Review profile: CHILL Plan: Pro Plus Run ID: 📒 Files selected for processing (2)
📝 WalkthroughWalkthrough
ChangesCRD cancellation handling
Estimated code review effort: 3 (Moderate) | ~20 minutes Suggested reviewers: 🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✨ Finishing Touches📝 Generate docstrings
🧪 Generate unit tests (beta)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
IvanHunters
left a comment
There was a problem hiding this comment.
LGTM. Verified the fix end-to-end on the PR head, not just by reading the rationale.
What I checked
- Built,
go vet,golangci-lint: clean. - Full package suite green, including under
-race(relevant since this is about a scheduler race). - Non-vacuity of all four new tests via mutation testing: reverting the top-of-loop exit to the old unnamed message reddens
cancelledBeforeFirstPollandcancelledOnLoopReentryKeepsName; dropping the in-pollpendingCRDtracking reddenscancelledMidPollNamesUncheckedCRDandcancelledAfterPollKeepsName. Each test kills a distinct mutation; none is theatre. - Both callers (
crdinstall,fluxinstall) wrap this asCRDs not established after apply, and thecrdinstalltest matches only on that wrapper, so changing the inner message breaks nothing. Caller tests green.
The change is strictly an improvement: the old top-of-loop exit reported no CRD name at all, and pendingCRD was reset every iteration. Unifying both exits into one closure makes the two indistinguishable by construction.
Non-blocking notes (not requesting changes):
- When the context is already dead before any poll observes the set, the message names
crdNames[0]as the laggard, which is a stand-in rather than an observation. The code comment is honest about it, but the operator only sees the message; a cancelled install where CRD #7 is actually stuck will name CRD #1. Still a net improvement over the previous no-name behavior. Worth considering a distinct wording (or a count) for the never-polled case. - Pre-existing (not introduced here, and already annotated by the new comment): a
Geterror from RBAC denial, a connection failure, or aNotFoundis indistinguishable from "not established" and surfaces only as the cancellation message at the deadline. A follow-up could log theGeterror at V(1) alongside the existing "Waiting for CRD" line. - The
reenteringContextdouble assumes exactly oneDone()read per loop iteration; a future reader added inside the loop would silently shift the script toward a false-green. The PR body already documents this well.
… CRD wait is cancelled (#4475) Backport of #3742 to `release-1.6`. `TestWaitForCRDsEstablished_timeout` fails `Unit & controller tests` on this branch at random, last time on #4402: `error should mention stuck CRD name, got: context cancelled while waiting for CRDs to be established: context deadline exceeded`. `WaitForCRDsEstablished` here still has two cancellation exits with different messages, and when the deadline and a ticker tick are ready together the select picks one of them at random. I ran the timeout test as 16 concurrent processes to get the timing jitter CI has: 3 failures out of 160 runs on the current branch, 0 out of 320 with this change. Cherry-picked clean with `-x`. ### Testing - stress run above, plus `make unit-tests` and `make test-controllers` green, POSIX sh sweep clean. ```release-note fix(manifestutil): a CRD wait cut short by a cancelled context now reports one error naming the CRD it was waiting on, where before the name was present or missing depending on which of two exits the scheduler happened to pick ```
What this PR does
WaitForCRDsEstablishedreported a cancelled context two different ways. The check at the top of the poll loop returned a message with no CRD name, theselectat the bottom named the CRD the poll had stopped on. When a tick and the deadline come ready in the same instant,selectpicks between the ready cases at random, so one cancellation reached the operator either way.Both callers wrap this as
CRDs not established after apply, so the CRD name is what makes that log line actionable, and whether it is there was a coin toss.TestWaitForCRDsEstablished_timeoutasserts on the name, which is where this surfaced: its 2s deadline is an exact multiple of the 500ms ticker, so the two channels come ready together on the fourth tick and the assertion failed at random.The message is now built in one place and returned from both exits, so the two are indistinguishable by construction rather than by inspection. The name is carried across iterations, because a cancellation noticed at the top of the loop has no poll of its own to take one from, and it starts as the first CRD of the set for a wait cancelled before any poll observed anything. That start value is a stand-in rather than an observation, and the comment on it says so; the alternative, an empty name and a second phrasing for it, would leave the loop-top message with nothing to assert against and no test able to catch its return to the unnamed form.
Deleting the top check instead, so there is literally one exit, is the smaller diff and it moves the name to the head of the list in the very interleaving this PR is about. A client refuses
Geton a dead context at the first name in the list whichever CRD is actually lagging, so a poll entered on a cancelled context renames the report to that first name. That premise is about the production client,client.Newatcmd/cozystack-operator/main.go:176, uncached, so the request is rejected before it is issued, and it is worth saying that nothing in the test surface pins it: replacing thectxpassed toGetwithcontext.Background()survives the whole package, and the fixtures that need a context-honouring client checkctx.Err()by hand. That line predates this change and is untouched by it. Measured with a client that honours the context: with the check, a wait that re-enters the loop after the deadline keeps the name its last poll settled on; without it, the report moves to the head of the list. The check closes that window and no more than that. A context that dies part-way through a poll still records the firstGetto fail, exactly as merge base does, because this branch cannot tell a refused request from a CRD status. That is unchanged here and written up separately.Four tests cover the ways this wait can end on a cancelled context: before any poll has observed the set, cut off inside a poll, cancelled while waiting for the next tick, and re-entering the loop on a context that died during that wait. Two of them are red on merge base and are the regression pins for the defect above, both deterministically rather than by repetition: merge base answers a wait that starts cancelled, and a wait that re-enters the loop cancelled, with the unnamed message every time. Its loop-top exit is a
selectwhoseDonecase is ready, and a ready case always beatsdefault. The middle two are green on merge base, which gets those cases right; they are here because each catches a specific way of breaking the fix. Every one of the four is the sole killer of at least one mutation, which is the property worth having: it says none of them is redundant. They compare the whole message rather than searching it for a name, because a second exit that happens to carry a name is still the defect being fixed here, and a test that only looks for the name cannot see it.The re-entry test needs the bottom
selectto take the tick while cancellation is already pending, which against a real context is the same coin toss the bug rides on. The double it uses hands out an openDonefor the single read thatselectmakes in that iteration and a closed one for every read after, so the tick wins by construction and the next iteration sees a context cancelled through bothDoneandErr, the way a real one is. That pairing is guaranteed rather than incidental:cancelCtx.Errreads<-c.Done()before returning a non-nil error, so a double that reported cancellation throughErralone would be modelling a state no context can be in, and would pin the shape of the check rather than its behaviour. One property of that double is worth knowing before editing the loop: it hands out its open and closed channels per read, so aDone()read added inside the poll would consume the open one and leave the bottomselecta closed channel, quietly turning this into a second bottom-exit test that still passes. The failure direction there is false-green, which is the worse half, and the cheap guard is a lower bound on elapsed time inside that test, a run that leaves through the loop top spends a ticker interval getting there, one that leaves at the bottom of the first iteration does not. Not done here, because the test is correct today and provably kills the mutation it exists for, so the hazard is conditional on a future edit.The timeout test does reproduce locally under load: 6 failures across 400 runs on the unfixed code while I was measuring, spread over five batches, the last of which saw none. #3719 reports that it does not reproduce locally, so this is worth writing down before someone spends an evening re-testing that. That spread is also why the number is an order of magnitude and not a rate.
TestInstall_crdNotEstablishedininternal/crdinstallhas the same 2s deadline against the same 500ms ticker. It asserts on theCRDs not establishedwrapper the caller adds, and both messages carried that wrapper, so this coin flip could not reach it and nothing here touches it.I left the 2s deadline where it is. Moving it off the tick boundary would have hidden the coin flip and left the second message in place. The new tests catch a reintroduced second message deterministically, which is what that job now rests on rather than the timeout test's roughly one-in-sixty.
Screenshots
Downstream repositories
Release note
Summary by CodeRabbit
Bug Fixes
Tests