Skip to content

Commit 8c6fee9

Browse files
committed
refactor(eventbus): cleanup removeSink
use slices.DeleteFunc ensure draining goroutine returns don't use metrics tracer to test behavior Assisted-By: Claude Fable 5
1 parent 4aab499 commit 8c6fee9

6 files changed

Lines changed: 159 additions & 180 deletions

File tree

p2p/host/eventbus/basic.go

Lines changed: 39 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,9 @@ package eventbus
33
import (
44
"errors"
55
"fmt"
6+
"log/slog"
67
"reflect"
8+
"slices"
79
"sync"
810
"sync/atomic"
911
"time"
@@ -25,6 +27,7 @@ type basicBus struct {
2527
nodes map[reflect.Type]*node
2628
wildcard *wildcardNode
2729
metricsTracer MetricsTracer
30+
log *slog.Logger
2831
}
2932

3033
var _ event.Bus = (*basicBus)(nil)
@@ -65,7 +68,8 @@ func (e *emitter) Close() error {
6568
func NewBus(opts ...Option) event.Bus {
6669
bus := &basicBus{
6770
nodes: map[reflect.Type]*node{},
68-
wildcard: &wildcardNode{},
71+
wildcard: &wildcardNode{log: log},
72+
log: log,
6973
}
7074
for _, opt := range opts {
7175
opt(bus)
@@ -78,7 +82,7 @@ func (b *basicBus) withNode(typ reflect.Type, cb func(*node), async func(*node))
7882

7983
n, ok := b.nodes[typ]
8084
if !ok {
81-
n = newNode(typ, b.metricsTracer)
85+
n = newNode(typ, b.metricsTracer, b.log)
8286
b.nodes[typ] = n
8387
}
8488

@@ -334,6 +338,7 @@ type wildcardNode struct {
334338
nSinks atomic.Int32
335339
sinks []*namedSink
336340
metricsTracer MetricsTracer
341+
log *slog.Logger
337342
}
338343

339344
func (n *wildcardNode) addSink(sink *namedSink) {
@@ -348,22 +353,36 @@ func (n *wildcardNode) addSink(sink *namedSink) {
348353
}
349354

350355
func (n *wildcardNode) removeSink(ch chan any) {
351-
go func() {
352-
// drain the event channel, will return when closed and drained.
353-
// this is necessary to unblock publishes to this channel.
354-
for range ch {
356+
// Drain the event channel to unblock stalled emits, which hold the read
357+
// lock; without this the Lock below would deadlock against them.
358+
done := make(chan struct{})
359+
var wg sync.WaitGroup
360+
wg.Go(func() {
361+
for {
362+
select {
363+
case <-ch:
364+
case <-done:
365+
// The write lock has been acquired: the sink is invisible to new
366+
// emits and in-flight ones have completed, so only buffered
367+
// events remain. Sweep them and exit.
368+
for {
369+
select {
370+
case <-ch:
371+
default:
372+
return
373+
}
374+
}
375+
}
355376
}
356-
}()
377+
})
357378
n.nSinks.Add(-1) // ok to do outside the lock
358379
n.Lock()
359-
for i := 0; i < len(n.sinks); i++ {
360-
if n.sinks[i].ch == ch {
361-
n.sinks[i], n.sinks[len(n.sinks)-1] = n.sinks[len(n.sinks)-1], nil
362-
n.sinks = n.sinks[:len(n.sinks)-1]
363-
break
364-
}
365-
}
380+
n.sinks = slices.DeleteFunc(n.sinks, func(s *namedSink) bool { return s.ch == ch })
366381
n.Unlock()
382+
// We could close ch itself here, which would also end the subscriber's
383+
// Out() range like typed subs do.
384+
close(done)
385+
wg.Wait()
367386
}
368387

369388
var wildcardType = reflect.TypeOf(event.WildcardSubscription)
@@ -383,7 +402,7 @@ func (n *wildcardNode) emit(evt any) {
383402
select {
384403
case sink.ch <- evt:
385404
default:
386-
emitAndLogError(wildcardType, evt, sink)
405+
emitAndLogError(n.log, wildcardType, evt, sink)
387406
}
388407
}
389408
n.RUnlock()
@@ -403,12 +422,14 @@ type node struct {
403422

404423
sinks []*namedSink
405424
metricsTracer MetricsTracer
425+
log *slog.Logger
406426
}
407427

408-
func newNode(typ reflect.Type, metricsTracer MetricsTracer) *node {
428+
func newNode(typ reflect.Type, metricsTracer MetricsTracer, log *slog.Logger) *node {
409429
return &node{
410430
typ: typ,
411431
metricsTracer: metricsTracer,
432+
log: log,
412433
}
413434
}
414435

@@ -431,13 +452,13 @@ func (n *node) emit(evt any) {
431452
select {
432453
case sink.ch <- evt:
433454
default:
434-
emitAndLogError(n.typ, evt, sink)
455+
emitAndLogError(n.log, n.typ, evt, sink)
435456
}
436457
}
437458
n.lk.Unlock()
438459
}
439460

440-
func emitAndLogError(typ reflect.Type, evt any, sink *namedSink) {
461+
func emitAndLogError(log *slog.Logger, typ reflect.Type, evt any, sink *namedSink) {
441462
// Slow consumer. Log a warning if stalled for the timeout
442463
timer := time.NewTimer(slowConsumerWarningTimeout)
443464
defer timer.Stop()

p2p/host/eventbus/basic_synctest_test.go

Lines changed: 106 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -24,21 +24,15 @@ import (
2424
// synctest gives us a fake clock, so the one-second warning timeout fires
2525
// instantly and deterministically instead of relying on real sleeps.
2626
func TestWildcardSlowConsumerNoDeadlock(t *testing.T) {
27-
// Capture log output to confirm the slow-consumer path actually ran.
28-
defer func(orig *slog.Logger) { log = orig }(log)
29-
logs := &mockLogger{}
30-
log = slog.New(slog.NewTextHandler(logs, nil))
31-
3227
synctest.Test(t, func(t *testing.T) {
3328
const emitters = 3
3429

35-
bus := NewBus()
30+
// Capture log output to confirm the slow-consumer path actually ran.
31+
logs := &mockLogger{}
32+
bus := NewBus(withLogger(slog.New(slog.NewTextHandler(logs, nil))))
3633
sub, err := bus.Subscribe(event.WildcardSubscription, BufSize(1))
3734
require.NoError(t, err)
38-
// The wildcard subscription is intentionally left open: wildcardSub.Close
39-
// starts a drain goroutine that only returns once the subscription channel
40-
// closes, which never happens for wildcard subs. Closing it here would
41-
// leave that goroutine running and trip synctest's end-of-test check.
35+
defer sub.Close()
4236

4337
em, err := bus.Emitter(new(EventB))
4438
require.NoError(t, err)
@@ -95,3 +89,105 @@ func TestWildcardSlowConsumerNoDeadlock(t *testing.T) {
9589
}
9690
})
9791
}
92+
93+
// TestWildcardSubCloseReleasesDrainGoroutine checks that closing a wildcard
94+
// subscription does not leak the drain goroutine started by removeSink. If the
95+
// drainer is still blocked when the bubble ends, synctest reports a deadlock.
96+
func TestWildcardSubCloseReleasesDrainGoroutine(t *testing.T) {
97+
synctest.Test(t, func(t *testing.T) {
98+
bus := NewBus()
99+
sub, err := bus.Subscribe(event.WildcardSubscription)
100+
require.NoError(t, err)
101+
require.NoError(t, sub.Close())
102+
})
103+
}
104+
105+
// TestWildcardCloseUnblocksStalledEmit covers the slow-consumer safety valve: an
106+
// emit stalled on a full wildcard subscriber, holding the node read lock, must
107+
// be released when the subscription is closed. wildcardNode.removeSink starts
108+
// draining the channel before it takes the write lock; were the order reversed,
109+
// Close would deadlock against the read lock the stalled emit still holds.
110+
func TestWildcardCloseUnblocksStalledEmit(t *testing.T) {
111+
synctest.Test(t, func(t *testing.T) {
112+
// The stalled emit warns as part of this test; keep it out of the output.
113+
bus := NewBus()
114+
115+
// An unbuffered subscriber has nowhere to put the event, so the emit below
116+
// stalls immediately without a fill step.
117+
sub, err := bus.Subscribe(event.WildcardSubscription, BufSize(0))
118+
require.NoError(t, err)
119+
120+
em, err := bus.Emitter(new(EventB))
121+
require.NoError(t, err)
122+
defer em.Close()
123+
124+
emitReturned := make(chan struct{})
125+
go func() {
126+
em.Emit(EventB(0))
127+
close(emitReturned)
128+
}()
129+
130+
// Sleep past the warning timeout: the emit stalls, warns, and is now in
131+
// the deepest stall state — a bare send with no timeout escape, still
132+
// holding the node read lock.
133+
time.Sleep(slowConsumerWarningTimeout + time.Millisecond)
134+
synctest.Wait()
135+
136+
// Close must free the stalled emit; synctest reports a deadlock if not.
137+
require.NoError(t, sub.Close())
138+
<-emitReturned
139+
})
140+
}
141+
142+
func TestEmitLogsErrorOnStall(t *testing.T) {
143+
synctest.Test(t, func(t *testing.T) {
144+
ml := mockLogger{}
145+
logger := slog.New(slog.NewTextHandler(&ml, nil))
146+
147+
bus1 := NewBus(withLogger(logger))
148+
bus2 := NewBus(withLogger(logger))
149+
150+
eventSub, err := bus1.Subscribe(new(EventA))
151+
if err != nil {
152+
t.Fatal(err)
153+
}
154+
155+
wildcardSub, err := bus2.Subscribe(event.WildcardSubscription)
156+
if err != nil {
157+
t.Fatal(err)
158+
}
159+
160+
testCases := []event.Subscription{eventSub, wildcardSub}
161+
eventBuses := []event.Bus{bus1, bus2}
162+
163+
for i, sub := range testCases {
164+
bus := eventBuses[i]
165+
em, err := bus.Emitter(new(EventA))
166+
if err != nil {
167+
t.Fatal(err)
168+
}
169+
defer em.Close()
170+
171+
go func() {
172+
for i := 0; i < subSettingsDefault.buffer+2; i++ {
173+
em.Emit(EventA{})
174+
}
175+
}()
176+
177+
time.Sleep(3 * time.Second)
178+
logs := ml.Logs()
179+
found := false
180+
for _, log := range logs {
181+
if strings.Contains(log, "slow consumer") {
182+
found = true
183+
break
184+
}
185+
}
186+
require.True(t, found, "expected to find slow consumer log")
187+
ml.Clear()
188+
189+
// Close the subscriber so the worker can finish.
190+
sub.Close()
191+
}
192+
})
193+
}

p2p/host/eventbus/basic_test.go

Lines changed: 0 additions & 113 deletions
Original file line numberDiff line numberDiff line change
@@ -3,9 +3,7 @@ package eventbus
33
import (
44
"context"
55
"fmt"
6-
"log/slog"
76
"reflect"
8-
"strings"
97
"sync"
108
"sync/atomic"
119
"testing"
@@ -160,62 +158,6 @@ func (m *mockLogger) Clear() {
160158
m.logs = nil
161159
}
162160

163-
func TestEmitLogsErrorOnStall(t *testing.T) {
164-
oldLogger := log
165-
defer func() {
166-
log = oldLogger
167-
}()
168-
ml := mockLogger{}
169-
log = slog.New(slog.NewTextHandler(&ml, nil))
170-
171-
bus1 := NewBus()
172-
bus2 := NewBus()
173-
174-
eventSub, err := bus1.Subscribe(new(EventA))
175-
if err != nil {
176-
t.Fatal(err)
177-
}
178-
179-
wildcardSub, err := bus2.Subscribe(event.WildcardSubscription)
180-
if err != nil {
181-
t.Fatal(err)
182-
}
183-
184-
testCases := []event.Subscription{eventSub, wildcardSub}
185-
eventBuses := []event.Bus{bus1, bus2}
186-
187-
for i, sub := range testCases {
188-
bus := eventBuses[i]
189-
em, err := bus.Emitter(new(EventA))
190-
if err != nil {
191-
t.Fatal(err)
192-
}
193-
defer em.Close()
194-
195-
go func() {
196-
for i := 0; i < subSettingsDefault.buffer+2; i++ {
197-
em.Emit(EventA{})
198-
}
199-
}()
200-
201-
require.EventuallyWithT(t, func(collect *assert.CollectT) {
202-
logs := ml.Logs()
203-
found := false
204-
for _, log := range logs {
205-
if strings.Contains(log, "slow consumer") {
206-
found = true
207-
break
208-
}
209-
}
210-
assert.True(collect, found, "expected to find slow consumer log")
211-
}, 3*time.Second, 500*time.Millisecond)
212-
ml.Clear()
213-
214-
// Close the subscriber so the worker can finish.
215-
sub.Close()
216-
}
217-
}
218-
219161
func TestEmitOnClosed(t *testing.T) {
220162
bus := NewBus()
221163

@@ -769,58 +711,3 @@ func BenchmarkSubscribeAndEmitter(b *testing.B) {
769711
}
770712
}
771713
}
772-
773-
// queueSignalTracer is a no-op MetricsTracer that reports when an emit has
774-
// reached the point of queuing an event on a sink. At that point the wildcard
775-
// emit already holds the node read lock, which is the state the close-during-
776-
// stall test needs before it closes the subscription.
777-
type queueSignalTracer struct {
778-
queued chan struct{}
779-
}
780-
781-
func (queueSignalTracer) EventEmitted(reflect.Type) {}
782-
func (queueSignalTracer) AddSubscriber(reflect.Type) {}
783-
func (queueSignalTracer) RemoveSubscriber(reflect.Type) {}
784-
func (queueSignalTracer) SubscriberQueueLength(string, int) {}
785-
func (queueSignalTracer) SubscriberQueueFull(string, bool) {}
786-
func (t queueSignalTracer) SubscriberEventQueued(string) {
787-
select {
788-
case t.queued <- struct{}{}:
789-
default:
790-
}
791-
}
792-
793-
// TestWildcardCloseUnblocksStalledEmit covers the slow-consumer safety valve: an
794-
// emit stalled on a full wildcard subscriber, holding the node read lock, must
795-
// be released when the subscription is closed. wildcardNode.removeSink starts
796-
// draining the channel before it takes the write lock; were the order reversed,
797-
// Close would deadlock against the read lock the stalled emit still holds.
798-
func TestWildcardCloseUnblocksStalledEmit(t *testing.T) {
799-
queued := make(chan struct{}, 1)
800-
bus := NewBus(WithMetricsTracer(queueSignalTracer{queued: queued}))
801-
802-
// An unbuffered subscriber has nowhere to put the event, so the emit below
803-
// stalls immediately without a fill step.
804-
sub, err := bus.Subscribe(event.WildcardSubscription, BufSize(0))
805-
require.NoError(t, err)
806-
807-
em, err := bus.Emitter(new(EventB))
808-
require.NoError(t, err)
809-
defer em.Close()
810-
811-
emitReturned := make(chan struct{})
812-
go func() {
813-
em.Emit(EventB(0))
814-
close(emitReturned)
815-
}()
816-
817-
<-queued // the emit now holds the read lock and is stalled on the send
818-
819-
require.NoError(t, sub.Close())
820-
821-
select {
822-
case <-emitReturned:
823-
case <-time.After(5 * time.Second):
824-
t.Fatal("Close did not unblock the stalled emit")
825-
}
826-
}

0 commit comments

Comments
 (0)