Repository navigation
🐛 priorityqueue: fix data race on []*item in logState - #3588
kubernetes-prow[bot] merged 3 commits into
Conversation
|
|
|
Welcome @lanfix! |
|
Hi @lanfix. Thanks for your PR. I'm waiting for a kubernetes-sigs member to verify that this patch is reasonable to test. If it is, they should reply with Regular contributors should join the org to skip this step. Once the patch is verified, the new status will be reflected by the I understand the commands that are listed here. DetailsInstructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository. |
| // data race. The race can crash the process from within encoding/json when a | ||
| // ReadyAt pointer is observed non-nil and then dereferenced after it went nil: | ||
| // "value method time.Time.MarshalJSON called using nil *Time pointer". | ||
| func (w *priorityqueue[T]) cloneItems() []item[T] { |
There was a problem hiding this comment.
Please add a test for this that validates it copies all fields now and in the future, maybe using randfill or such
| }) | ||
| } | ||
|
|
||
| time.Sleep(500 * time.Millisecond) |
There was a problem hiding this comment.
Use synctest instead of sleeps, please
There was a problem hiding this comment.
Done. The test now runs inside synctest.Test and advances fake time with time.Sleep(10 * time.Second) so that logState's 10s tick fires.
| // TestPriorityQueueCloneItemsCopiesAllFields checks that cloneItems returns items that are | ||
| // equal to the queued ones and share no memory with them. Filling the items with random | ||
| // values keeps both checks valid for fields that are added to item in the future. | ||
| func TestPriorityQueueCloneItemsCopiesAllFields(t *testing.T) { |
There was a problem hiding this comment.
Please factor the code such that this can test only the cloning, not a bunch of unrelated things. Also, the testname is self-explanatory and doesn't require a comment
There was a problem hiding this comment.
Done. Extracted the per-item copy into item.clone() and cloneItems just calls it, so the tests only exercise clone() on a randfill-ed item and don't build a queue anymore. Dropped the comment. The randfill setup lives in newItemFiller, as randfill can't fill time.Time on its own (all its fields are unexported).
| }) | ||
| } | ||
|
|
||
| // Readers: do what logState does - snapshot the queue and serialize it. |
There was a problem hiding this comment.
Can we simply pass in a logger at v5 instead to test what actually does happen rather than imitate it? The race detector will go off if a race could happen, it doesn't require the race to actually happen
There was a problem hiding this comment.
Done. newQueue now accepts Opts and the test passes a funcr logger with Verbosity: 5, so the real logState does the reading. I verified that the race detector reports the old logState implementation with this test (read in logState vs. write of item.ReadyAt in lockedAddWithOpts), and that it is clean with the current one.
| // Writers: churn items through waiting -> ready (handleWaitingItems clears | ||
| // ReadyAt) and through the update path (lockedAddWithOpts reassigns ReadyAt). | ||
| for range 8 { | ||
| wg.Go(func() { |
There was a problem hiding this comment.
I don't think using randomized keys adds anything here, the race happens if the after for the same key gets changed which only happens if its lower, so a simpler version of this would be to just add the same key in a loop with a lowering after, maybe by substracting the loop index from a start value or some such
There was a problem hiding this comment.
Done. The test now re-adds the same key in a loop with a lowering After (time.Hour minus i minutes) and sleeps between the adds so that logState logs the item in between the ReadyAt updates.
| t.Fatalf("cloned items don't match the queued ones: %s", diff) | ||
| } | ||
|
|
||
| // Equal fields are not enough, a clone must not reference the item it was cloned from. |
There was a problem hiding this comment.
If anything, make this its own test please
There was a problem hiding this comment.
Done, split into TestItemCloneCopiesAllFields (cmp.Diff against the original) and TestItemCloneDoesNotShareMemoryWithOriginal (no pointer/map/slice field of the clone may point into the original).
Note that copying the time.Time behind ReadyAt isn't needed for the race itself (the pointee is never mutated in place), it only guards against a future in-place update.
|
/cherrypick release-0.25 |
|
@alvaroaleman: once the present PR merges, I will cherry-pick it on top of DetailsIn response to this:
Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository. |
|
LGTM label has been added. DetailsGit tree hash: 06001486f87eec7d7a9ad5f59d0bc456660a6c3e |
|
[APPROVALNOTIFIER] This PR is APPROVED This pull-request has been approved by: alvaroaleman, lanfix The full list of commands accepted by this bot can be found here. The pull request process is described here DetailsNeeds approval from an approver in each of these files:
Approvers can indicate their approval by writing |
|
@alvaroaleman: new pull request created: #3593 DetailsIn response to this:
Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository. |
|
Thx! Nice fix! /cherry-pick release-0.24 |
|
@sbueringer: new pull request created: #3602 DetailsIn response to this:
Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository. |
What this does
logStatecollected the queue's items into a[]*item[T]underw.lock,released the lock, and then passed those pointers to the logger for
serialization. The pointed-to
item[T]values stay live inw.items/w.waiting/w.readyand keep being mutated by the other queue goroutineswhile the logger walks them, so the snapshot is a data race.
This PR takes a by-value deep copy of every item (including the
*time.Timebehind
ReadyAt) underw.lockand hands that copy to the logger. The lock isheld only for the cheap copy, not for serialization, and the logged payload is
fully detached from the live queue state. Log output is unchanged (
[]item[T]and
[]*item[T]marshal identically;readyAt,omitemptystill works).Why we need it
With a logger that has
V(5)enabled,logStateruns every 10s. The race isobservable via
go test -race, and in production it intermittently crashes thecontroller process: