trace: fix race condition #279
Merged
Conversation
This file contains 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
k8s-ci-robot
added
kind/bug
k8s-ci-robot
added
the
size/S
dims
reviewed
Apr 5, 2023
trace/trace.go
Outdated
| t.lock.RLock() | ||
| } | ||
|
|
||
| func (t *Trace) runlock() { |
There was a problem hiding this comment.
my eye/brain reads this as "run lock" :(
Found with `go test -race -run=TestPatchConflicts ./test/integration/apiserver`
in Kubernetes.
writeTraceSteps gets called while the mutex of t is locked, so iterating over
t.traceItems is fine. But then it calls stepOrTrace.time = Trace.time of
another instance. Retrieving that time is done without locking the mutex of
that other instance and thus races with setting the end time of that trace in
End.
WARNING: DATA RACE
Write at 0x00c009fed898 by goroutine 124291:
k8s.io/kubernetes/vendor/k8s.io/utils/trace.(*Trace).Log()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/utils/trace/trace.go:175 +0xc4
k8s.io/kubernetes/vendor/k8s.io/utils/trace.(*Trace).LogIfLong()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/utils/trace/trace.go:194 +0xc4
k8s.io/kubernetes/vendor/k8s.io/component-base/tracing.(*Span).End()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/component-base/tracing/tracing.go:67 +0x8f
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/storage/etcd3.(*store).GuaranteedUpdate.func2()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/storage/etcd3/store.go:384 +0x3e
runtime.deferreturn()
/home/prow/go/src/k8s.io/kubernetes/_output/local/.gimme/versions/go1.20.2.linux.amd64/src/runtime/panic.go:476 +0x32
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/storage/cacher.(*Cacher).GuaranteedUpdate()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/storage/cacher/cacher.go:839 +0x1cc
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry.(*DryRunnableStorage).GuaranteedUpdate()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry/dryrun.go:93 +0x321
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry.(*Store).Update()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry/store.go:559 +0x858
k8s.io/kubernetes/pkg/registry/core/secret/storage.(*REST).Update()
<autogenerated>:1 +0xfe
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers.(*patcher).patchResource.func2()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/patch.go:666 +0x1f1
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers.(*patcher).patchResource.func3()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/patch.go:672 +0x57
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/finisher.finishRequest.func1()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/finisher/finisher.go:117 +0xfa
Previous read at 0x00c009fed898 by goroutine 124286:
k8s.io/kubernetes/vendor/k8s.io/utils/trace.(*Trace).time()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/utils/trace/trace.go:110 +0x3e
k8s.io/kubernetes/vendor/k8s.io/utils/trace.(*Trace).writeTraceSteps()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/utils/trace/trace.go:235 +0x17a
k8s.io/kubernetes/vendor/k8s.io/utils/trace.(*Trace).logTrace()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/utils/trace/trace.go:216 +0x4c7
k8s.io/kubernetes/vendor/k8s.io/utils/trace.(*Trace).Log()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/utils/trace/trace.go:179 +0x118
k8s.io/kubernetes/vendor/k8s.io/utils/trace.(*Trace).LogIfLong()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/utils/trace/trace.go:194 +0xc4
k8s.io/kubernetes/vendor/k8s.io/component-base/tracing.(*Span).End()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/component-base/tracing/tracing.go:67 +0x8f
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers.PatchResource.func1.1()
/home/prow/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/endpoints/handlers/patch.go:69 +0x3e
...
pohly
force-pushed
the
test-integration-race-detection-trace
branch
from
f561d93 to
43193cd
Compare
|
/approve thanks @pohly |
k8s-ci-robot
added
the
lgtm
|
[APPROVALNOTIFIER] This PR is APPROVED This pull-request has been approved by: dims, pohly The full list of commands accepted by this bot can be found here. The pull request process is described here
Needs approval from an approver in each of these files:
Approvers can indicate their approval by writing |
k8s-ci-robot
added
the
approved
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
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.
What type of PR is this?
/kind bug
What this PR does / why we need it:
writeTraceSteps gets called while the mutex of t is locked, so iterating over t.traceItems is fine. But then it calls stepOrTrace.time = Trace.time of another instance. Retrieving that time is done without locking the mutex of that other instance and thus races with setting the end time of that trace in End.
Which issue(s) this PR fixes:
Special notes for your reviewer:
Found with
go test -race -run=TestPatchConflicts ./test/integration/apiserverin Kubernetes.Release note: