From 6a3c0f9207eda2d136046a367049160f0386cd8b Mon Sep 17 00:00:00 2001 From: Aditya Maru Date: Tue, 17 May 2022 10:56:02 -0400 Subject: [PATCH] tracing: fix inconsistent lock ordering when notifying event listeners This change fixes an inconsistent lock ordering that was caught in #81361. As per the lock ordering convention between a parent, and a child span we now notify the parent of StructuredEvents recorded by the child outside of the child span's lock. Additionally, we now notify the event listeners without holding the span's mutex. This is to protect against deadlocks if the `Notify` method were to call methods on the tracing span which acquire the span's mutex. One can imagine `Notify` calling `SetLazyTag` on the same tracing span as the one that has the event listener. Fixes: #81361 Release note: None --- pkg/util/tracing/crdbspan.go | 39 ++++++++++++++++++++++++++++------- pkg/util/tracing/span.go | 10 ++++----- pkg/util/tracing/span_test.go | 23 +++++++++++++++++++++ pkg/util/tracing/tracer.go | 2 +- 4 files changed, 60 insertions(+), 14 deletions(-) diff --git a/pkg/util/tracing/crdbspan.go b/pkg/util/tracing/crdbspan.go index f4d8857ca919..792c51e2d45c 100644 --- a/pkg/util/tracing/crdbspan.go +++ b/pkg/util/tracing/crdbspan.go @@ -56,6 +56,10 @@ type crdbSpan struct { // tag's key to a user. logTags *logtags.Buffer + // eventListeners is a list of registered EventListener's that are notified + // whenever a Structured event is recorded by the span and its children. + eventListeners []EventListener + // Locking rules: // - If locking both a parent and a child, the parent must be locked first. In // practice, children don't take the parent's lock. @@ -124,10 +128,6 @@ type crdbSpanMu struct { // lazyTags are tags whose values are only string-ified on demand. Each lazy // tag is expected to implement either fmt.Stringer or LazyTag. lazyTags []lazyTag - - // eventListeners is a list of registered EventListener's that are notified - // whenever a Structured event is recorded by the span and its children. - eventListeners []EventListener } type lazyTag struct { @@ -233,7 +233,6 @@ func (s *crdbSpan) finish() bool { return false } s.mu.finished = true - s.mu.eventListeners = nil if s.recordingType() != RecordingOff { duration := timeutil.Since(s.startTime) @@ -566,15 +565,39 @@ func (s *crdbSpan) getLazyTagLocked(key string) (interface{}, bool) { // notifyEventListeners recursively notifies all the EventListeners registered // with this span and any ancestor spans in the Recording, of a StructuredEvent. +// +// If s has a parent, then we notify the parent of the StructuredEvent outside +// the child (our current receiver) lock. This is as per the lock ordering +// convention between parents and children. func (s *crdbSpan) notifyEventListeners(item Structured) { s.mu.Lock() - defer s.mu.Unlock() + + // Check if the span has been finished concurrently with this notify call. + // This can happen when the signal comes from a child span; in that case the + // child calls into the parent without holding the child's lock, so the call + // can race with parent.Finish(). + if s.mu.finished { + s.mu.Unlock() + return + } + + // Pass the event to the parent, if necessary. if s.mu.recording.notifyParentOnStructuredEvent { parent := s.mu.parent.Span.i.crdb + // Take a reference of s' parent before releasing the mutex. This ensures + // that if the parent were to be Finish()ed concurrently then the span does + // not get reused until we release the reference. + parentRef := makeSpanRef(s.mu.parent.Span) + defer parentRef.release() + s.mu.Unlock() parent.notifyEventListeners(item) + } else { + s.mu.Unlock() } - for _, listener := range s.mu.eventListeners { + // We can operate on s' eventListeners without holding the mutex because the + // slice is only written to once during span creation. + for _, listener := range s.eventListeners { listener.Notify(item) } } @@ -960,7 +983,7 @@ func (s *crdbSpan) withLock(f func()) { // WithEventListeners(...) or the span has been configured to notify its parent // span on a StructuredEvent recording. func (s *crdbSpan) wantEventNotificationsLocked() bool { - return len(s.mu.eventListeners) != 0 || s.mu.recording.notifyParentOnStructuredEvent + return len(s.eventListeners) != 0 || s.mu.recording.notifyParentOnStructuredEvent } // setGoroutineID updates the span's goroutine ID. diff --git a/pkg/util/tracing/span.go b/pkg/util/tracing/span.go index 781663db408a..b2c123e84dce 100644 --- a/pkg/util/tracing/span.go +++ b/pkg/util/tracing/span.go @@ -619,6 +619,10 @@ func (sp *Span) reset( c.operation = operation c.startTime = startTime c.logTags = logTags + if len(c.eventListeners) != 0 { + panic(fmt.Sprintf("unexpected event listeners in span being reset: %v", c.eventListeners)) + } + c.eventListeners = eventListeners { // Nobody is supposed to have a reference to the span at this point, but let's // take the lock anyway to protect against buggy clients accessing the span @@ -639,9 +643,6 @@ func (sp *Span) reset( if c.mu.recording.logs.Len() != 0 { panic("unexpected logs in span being reset") } - if len(c.mu.eventListeners) != 0 { - panic(fmt.Sprintf("unexpected event listeners in span being reset: %v", c.mu.eventListeners)) - } h := sp.helper c.mu.crdbSpanMu = crdbSpanMu{ @@ -652,8 +653,7 @@ func (sp *Span) reset( logs: makeSizeLimitedBuffer(maxLogBytesPerSpan, nil /* scratch */), structured: makeSizeLimitedBuffer(maxStructuredBytesPerSpan, h.structuredEventsAlloc[:]), }, - tags: h.tagsAlloc[:0], - eventListeners: eventListeners, + tags: h.tagsAlloc[:0], } if kind != oteltrace.SpanKindUnspecified { diff --git a/pkg/util/tracing/span_test.go b/pkg/util/tracing/span_test.go index c0dce3fc739b..d240102d8b52 100644 --- a/pkg/util/tracing/span_test.go +++ b/pkg/util/tracing/span_test.go @@ -703,10 +703,14 @@ func TestWithRemoteParentFromTraceInfo(t *testing.T) { type mockEventListener struct { eventsSeen int + notifyImpl func() } func (f *mockEventListener) Notify(_ Structured) { f.eventsSeen++ + if f.notifyImpl != nil { + f.notifyImpl() + } } var _ EventListener = &mockEventListener{} @@ -766,3 +770,22 @@ func TestEventListener(t *testing.T) { require.Equal(t, 7, rootEventListener.eventsSeen) childSp2.Finish() } + +func TestEventListenerNotifiedWithoutHoldingSpanMutex(t *testing.T) { + tr := NewTracer() + rootEventListener := &mockEventListener{} + sp := tr.StartSpan("root", WithRecording(RecordingStructured), + WithEventListeners([]EventListener{rootEventListener})) + defer sp.Finish() + + // Set the EventListeners Notify() method to acquire the span's mutex. + rootEventListener.notifyImpl = func() { + sp.i.crdb.mu.Lock() + defer sp.i.crdb.mu.Unlock() + } + + // Record a StructuredEvent, if Notify() were called holding the span's mutex + // this would deadlock. + sp.RecordStructured(&types.Int32Value{Value: 5}) + require.Equal(t, 1, rootEventListener.eventsSeen) +} diff --git a/pkg/util/tracing/tracer.go b/pkg/util/tracing/tracer.go index d4024e8766e4..48ebefe6c096 100644 --- a/pkg/util/tracing/tracer.go +++ b/pkg/util/tracing/tracer.go @@ -1013,6 +1013,7 @@ func (t *Tracer) releaseSpanToPool(sp *Span) { // We'll zero-out the spanAllocHelper, though, to make all the elements // available for GC. c := sp.i.crdb + c.eventListeners = nil // Nobody is supposed to have a reference to the span at this point, but let's // take the lock anyway to protect against buggy clients accessing the span // after Finish(). @@ -1020,7 +1021,6 @@ func (t *Tracer) releaseSpanToPool(sp *Span) { c.mu.openChildren = nil c.mu.recording.finishedChildren = nil c.mu.tags = nil - c.mu.eventListeners = nil c.mu.recording.logs.Discard() c.mu.recording.structured.Discard() c.mu.Unlock()