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()
      <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
  ...

Author: pohly

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()
 	}
 }