Skip to content

Commit 9bd777f

Browse files
committed
fix(network): remove goroutine leak in transfer-metadata lookup wait
LookupTransferMetadataKey waited for its lookupListener by spawning a goroutine parked on sync.WaitGroup.Wait(). On the timeout path the function returns and its deferred RemoveLookupListener tears the listener down, so OnStatus/OnError -- the only callers of wg.Done() -- never fire and the goroutine is parked for the life of the process. ScanForPreImage uses a 5 minute timeout, so every HTLC pre-image that is never revealed stranded one goroutine. Buffering the channel does not help: the goroutine blocked on wg.Wait(), not on a channel send, and the send it replaced was a close(), which never blocks. Remove the goroutine instead. lookupListener now owns a done channel that the first matching notification closes, and the waiter selects on it against a timer. With nothing parked on the notification there is nothing to leak. Closing exactly once also removes the "negative WaitGroup counter" panic a duplicate notification could trigger, and the timer is explicitly stopped so a lookup that completes early no longer retains one for the rest of its timeout. The timeout is reported as a plain error naming the key rather than a bare context sentinel: a lookup that does not complete in time is an expected outcome here, and surfacing context.DeadlineExceeded would make it indistinguishable from caller cancellation to errors.Is-based retry logic. The context parameter is dropped rather than left dead -- neither driver.Network.LookupTransferMetadataKey nor htlc.ScanForPreImage carries a context, so the only caller could pass nothing but context.Background(). The tests are rewritten to actually reproduce the bug: they never release the listener, since releasing it also let the leaked goroutine exit, which is why the previous ones passed against the unfixed code. Verified that goleak flags the pre-fix implementation under these assertions and passes the new one. Fixes #2124 Signed-off-by: AkramBitar <akram@il.ibm.com>
1 parent 5655709 commit 9bd777f

3 files changed

Lines changed: 165 additions & 27 deletions

File tree

go.mod

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,7 @@ require (
2626
github.com/tidwall/gjson v1.19.0
2727
go.opentelemetry.io/otel/trace v1.44.0
2828
go.uber.org/dig v1.19.0
29+
go.uber.org/goleak v1.3.0
2930
go.uber.org/zap v1.28.0
3031
go.yaml.in/yaml/v3 v3.0.4
3132
golang.org/x/crypto v0.54.0
Lines changed: 126 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,126 @@
1+
/*
2+
Copyright IBM Corp. All Rights Reserved.
3+
4+
SPDX-License-Identifier: Apache-2.0
5+
*/
6+
7+
package fabric
8+
9+
import (
10+
"context"
11+
"strconv"
12+
"sync"
13+
"testing"
14+
"time"
15+
16+
"github.com/hyperledger-labs/fabric-smart-client/pkg/utils/errors"
17+
"github.com/stretchr/testify/assert"
18+
"github.com/stretchr/testify/require"
19+
"go.uber.org/goleak"
20+
)
21+
22+
const testKey = "transfer-metadata-key"
23+
24+
// TestLookupListenerWaitOnStatus verifies the happy path: the value reported by the
25+
// lookup manager is returned to the waiter.
26+
func TestLookupListenerWaitOnStatus(t *testing.T) {
27+
l := newLookupListener(testKey)
28+
29+
go l.OnStatus(context.Background(), testKey, []byte("pre-image"))
30+
31+
value, err := l.wait(5 * time.Second)
32+
require.NoError(t, err)
33+
assert.Equal(t, []byte("pre-image"), value)
34+
}
35+
36+
// TestLookupListenerWaitOnError verifies that a failure reported by the lookup manager
37+
// is surfaced to the waiter.
38+
func TestLookupListenerWaitOnError(t *testing.T) {
39+
l := newLookupListener(testKey)
40+
expected := errors.New("scan failed")
41+
42+
go l.OnError(context.Background(), testKey, expected)
43+
44+
value, err := l.wait(5 * time.Second)
45+
require.ErrorIs(t, err, expected)
46+
assert.Nil(t, value)
47+
}
48+
49+
// TestLookupListenerIgnoresOtherKeys verifies that notifications for a different key do
50+
// not release the waiter, which must still time out.
51+
func TestLookupListenerIgnoresOtherKeys(t *testing.T) {
52+
l := newLookupListener(testKey)
53+
54+
l.OnStatus(context.Background(), "some-other-key", []byte("not mine"))
55+
l.OnError(context.Background(), "some-other-key", errors.New("not mine either"))
56+
57+
_, err := l.wait(20 * time.Millisecond)
58+
require.ErrorContains(t, err, "timed out")
59+
}
60+
61+
// TestLookupListenerFirstNotificationWins verifies that done is closed exactly once, so a
62+
// duplicate or racing notification neither panics nor overwrites the reported result.
63+
func TestLookupListenerFirstNotificationWins(t *testing.T) {
64+
l := newLookupListener(testKey)
65+
66+
l.OnStatus(context.Background(), testKey, []byte("first"))
67+
l.OnStatus(context.Background(), testKey, []byte("second"))
68+
l.OnError(context.Background(), testKey, errors.New("late failure"))
69+
70+
value, err := l.wait(5 * time.Second)
71+
require.NoError(t, err)
72+
assert.Equal(t, []byte("first"), value)
73+
}
74+
75+
// TestLookupListenerConcurrentNotifications verifies that concurrent notifications for the
76+
// same key are safe. Run with -race, this covers the close-once path under contention.
77+
func TestLookupListenerConcurrentNotifications(t *testing.T) {
78+
l := newLookupListener(testKey)
79+
80+
var wg sync.WaitGroup
81+
for i := range 16 {
82+
wg.Go(func() {
83+
if i%2 == 0 {
84+
l.OnStatus(context.Background(), testKey, []byte(strconv.Itoa(i)))
85+
} else {
86+
l.OnError(context.Background(), testKey, errors.New(strconv.Itoa(i)))
87+
}
88+
})
89+
}
90+
wg.Wait()
91+
92+
_, err := l.wait(5 * time.Second)
93+
// Which notification won is undefined; not panicking and not blocking is the point.
94+
_ = err
95+
}
96+
97+
// TestLookupListenerWaitTimeoutDoesNotLeak is the regression test for issue #2124.
98+
//
99+
// The waiter is abandoned exactly as LookupTransferMetadataKey abandons it in production:
100+
// the timeout fires and the listener is never notified, because the deferred
101+
// RemoveLookupListener has torn it down, so OnStatus/OnError will never be called.
102+
//
103+
// The test deliberately does NOT release the listener afterwards. That is what made the
104+
// original tests vacuous — releasing the signal also let the leaked goroutine exit, so they
105+
// passed against the buggy implementation. goleak fails here if anything is still parked.
106+
func TestLookupListenerWaitTimeoutDoesNotLeak(t *testing.T) {
107+
defer goleak.VerifyNone(t, goleak.IgnoreCurrent())
108+
109+
l := newLookupListener(testKey)
110+
111+
_, err := l.wait(20 * time.Millisecond)
112+
require.ErrorContains(t, err, "timed out")
113+
require.ErrorContains(t, err, testKey, "the timeout error should name the key being looked up")
114+
}
115+
116+
// TestLookupListenerRepeatedTimeoutsDoNotLeak covers the accumulating case from #2124: every
117+
// unrevealed HTLC pre-image used to strand one goroutine for the life of the process. As
118+
// above, no listener is ever notified.
119+
func TestLookupListenerRepeatedTimeoutsDoNotLeak(t *testing.T) {
120+
defer goleak.VerifyNone(t, goleak.IgnoreCurrent())
121+
122+
for range 32 {
123+
_, err := newLookupListener(testKey).wait(time.Millisecond)
124+
require.ErrorContains(t, err, "timed out")
125+
}
126+
}

token/services/network/fabric/network.go

Lines changed: 38 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -407,9 +407,7 @@ func (n *Network) LookupTransferMetadataKey(namespace string, key string, timeou
407407
return nil, errors.Wrapf(err, "failed to generate transfer action metadata key from [%s]", key)
408408
}
409409
logger.Debugf("lookup transfer metadata key [%s] from [%s] in namespace [%s]", key, transferMetadataKey, namespace)
410-
wg := &sync.WaitGroup{}
411-
wg.Add(1)
412-
l := &lookupListener{wg: wg, key: transferMetadataKey}
410+
l := newLookupListener(transferMetadataKey)
413411
if err := n.llm.AddLookupListener(namespace, transferMetadataKey, l); err != nil {
414412
return nil, errors.Wrapf(err, "failed to add lookup listener")
415413
}
@@ -418,12 +416,10 @@ func (n *Network) LookupTransferMetadataKey(namespace string, key string, timeou
418416
logger.Debugf("failed to remove lookup listener [%s]: %v", transferMetadataKey, err)
419417
}
420418
}()
421-
if err := waitTimeout(wg, timeout); err != nil {
422-
return nil, err
423-
}
424-
logger.Debugf("lookup transfer metadata key [%s] from [%s] in namespace [%s], done, result [%s][%s]", key, transferMetadataKey, namespace, l.value, l.err)
419+
value, err := l.wait(timeout)
420+
logger.Debugf("lookup transfer metadata key [%s] from [%s] in namespace [%s], done, result [%s][%v]", key, transferMetadataKey, namespace, value, err)
425421

426-
return l.value, l.err
422+
return value, err
427423
}
428424

429425
// Ledger returns direct access to the ledger querying layer.
@@ -552,44 +548,59 @@ func (n *Network) createCleanupManager(tmsID token2.TMSID) (*cleanup.Manager, er
552548
return manager, nil
553549
}
554550

551+
// lookupListener waits for the lookup manager to report the value of a single key.
552+
//
553+
// Completion is signalled by closing done, so a waiter that gives up on timeout leaves
554+
// nothing behind: there is no goroutine parked on the notification (#2124). done is closed
555+
// exactly once, which also makes a duplicate or racing notification harmless.
555556
type lookupListener struct {
556557
key string
557-
wg *sync.WaitGroup
558+
done chan struct{}
559+
once sync.Once
558560
value []byte
559561
err error
560562
}
561563

564+
// newLookupListener returns a listener waiting for the passed key.
565+
func newLookupListener(key string) *lookupListener {
566+
return &lookupListener{key: key, done: make(chan struct{})}
567+
}
568+
562569
func (l *lookupListener) OnStatus(ctx context.Context, key string, value []byte) {
563570
logger.DebugfContext(ctx, "lookup transfer metadata key [%s], got value [%s][%v]", l.key, key, value)
564-
if l.key == key {
565-
l.value = value
566-
l.wg.Done()
567-
571+
if l.key != key {
568572
return
569573
}
574+
l.once.Do(func() {
575+
l.value = value
576+
close(l.done)
577+
})
570578
}
571579

572580
func (l *lookupListener) OnError(ctx context.Context, key string, err error) {
573581
logger.DebugfContext(ctx, "lookup transfer metadata key [%s], got error [%s][%s]", l.key, key, err)
574-
if l.key == key {
575-
l.err = err
576-
l.wg.Done()
577-
582+
if l.key != key {
578583
return
579584
}
585+
l.once.Do(func() {
586+
l.err = err
587+
close(l.done)
588+
})
580589
}
581590

582-
func waitTimeout(wg *sync.WaitGroup, timeout time.Duration) error {
583-
c := make(chan struct{})
584-
go func() {
585-
defer close(c)
586-
wg.Wait()
587-
}()
591+
// wait blocks until the listener has been notified or the timeout expires, and returns
592+
// whatever the lookup manager reported for the key. The timeout is reported as a plain
593+
// error rather than a context sentinel: a lookup that does not complete in time is an
594+
// expected outcome here, not a cancellation of the caller.
595+
func (l *lookupListener) wait(timeout time.Duration) ([]byte, error) {
596+
timer := time.NewTimer(timeout)
597+
defer timer.Stop()
598+
588599
select {
589-
case <-c:
590-
return nil
591-
case <-time.After(timeout):
592-
return errors.Errorf("context done")
600+
case <-l.done:
601+
return l.value, l.err
602+
case <-timer.C:
603+
return nil, errors.Errorf("timed out after [%s] waiting for lookup of key [%s]", timeout, l.key)
593604
}
594605
}
595606

0 commit comments

Comments
 (0)