From 43193cd66311ff568731dd134b98c447c99f49fd Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 31 Mar 2023 19:55:41 +0200 Subject: [PATCH] trace: fix race condition 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() :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 ... --- trace/trace.go | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) diff --git a/trace/trace.go b/trace/trace.go index a0b07a6d..187eb5d8 100644 --- a/trace/trace.go +++ b/trace/trace.go @@ -65,6 +65,11 @@ func durationToMilliseconds(timeDuration time.Duration) int64 { } type traceItem interface { + // rLock must be called before invoking time or writeItem. + rLock() + // rUnlock must be called after processing the item is complete. + rUnlock() + // time returns when the trace was recorded as completed. time() time.Time // writeItem outputs the traceItem to the buffer. If stepThreshold is non-nil, only output the @@ -79,6 +84,10 @@ type traceStep struct { fields []Field } +// rLock doesn't need to do anything because traceStep instances are immutable. +func (s traceStep) rLock() {} +func (s traceStep) rUnlock() {} + func (s traceStep) time() time.Time { return s.stepTime } @@ -106,6 +115,14 @@ type Trace struct { traceItems []traceItem } +func (t *Trace) rLock() { + t.lock.RLock() +} + +func (t *Trace) rUnlock() { + t.lock.RUnlock() +} + func (t *Trace) time() time.Time { if t.endTime != nil { return *t.endTime @@ -231,8 +248,10 @@ func (t *Trace) logTrace() { func (t *Trace) writeTraceSteps(b *bytes.Buffer, formatter string, stepThreshold *time.Duration) { lastStepTime := t.startTime for _, stepOrTrace := range t.traceItems { + stepOrTrace.rLock() stepOrTrace.writeItem(b, formatter, lastStepTime, stepThreshold) lastStepTime = stepOrTrace.time() + stepOrTrace.rUnlock() } }