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

@@ -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.

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 {

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

pkg/util/tracing/tracer.go

@@ -1013,14 +1013,14 @@ 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().
 	c.mu.Lock()
 	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()