sweepbatcher: fix race conditions in unit tests #889

starius · 2025-02-26T03:26:05Z

Go 1.24 apparently improved its race detector, so regular go test -race started discovering all of these. Now it passes. Some changes were needed not only in unit tests to make accesses of batcher and batch fields thread safe.

Pull Request Checklist

Update release_notes.md if your PR contains major features, breaking changes or bugfixes

bhandras

Thanks for the fixes! Looks good, just a few questions.

bhandras · 2025-02-26T07:55:19Z

sweepbatcher/sweep_batcher.go


+	// Check if the sweep is already in a batch. If that is the case, we
+	// provide the sweep to that batch and return.
+	for _, batch := range b.batches {


Nice catch!

+1, now I got it :)

bhandras · 2025-02-26T07:57:05Z

sweepbatcher/sweep_batch.go

@@ -412,9 +413,22 @@ func NewBatchFromDB(cfg batchConfig, bk batchKit) (*batch, error) {
 		publishErrorHandler: bk.publishErrorHandler,
 		purger:              bk.purger,
 		store:               bk.store,
-		log:                 bk.log,


Can you elaborate why this caused a race?

Some tests replace the logger with wrappedLogger (defined in sweep_batcher_test.go) to wait for a particular log message.

bhandras · 2025-02-26T08:00:11Z

sweepbatcher/sweep_batch.go

+	// This is used only in unit tests! The reason to have this is to
+	// avoid data races in require.Eventually calls running in parallel
+	// to the event loop. See method testRunInEventLoop().
+	testReqs chan *testRequest


I wonder if we could avoid this by instead using checkpoints in within mocks?

Most of the checks that use this feature access batcher.batches and fields of a batch. The fields (e.g. fee rate, the list of sweeps) are updated in the main code, not in the mocks.

bhandras · 2025-02-26T08:02:44Z

sweepbatcher/log.go

 }

 // UseLogger uses a specified Logger to output package logging info.
 // This should be used in preference to SetLogWriter if the caller is also
 // using btclog.
 func UseLogger(logger btclog.Logger) {
-	log = logger
+	log_.Store(&logger)


Given that we only really call UseLogger once it should not race iiuc?

We call it in runTests function in each test. It increases logging to include debug messages. I caught a race between tests: in one test a sweepbatcher was shutting down and logging something, while another test was calling UseLogger.

bhandras

LGTM 🎉

bhandras · 2025-02-28T14:32:01Z

sweepbatcher/sweep_batch.go

@@ -430,7 +444,7 @@ func (b *batch) addSweep(ctx context.Context, sweep *sweep) (bool, error) {
 	// If the provided sweep is nil, we can't proceed with any checks, so
 	// we just return early.
 	if sweep == nil {
-		b.log.Infof("the sweep is nil")
+		b.log().Infof("the sweep is nil")


To avoid the extra step of calling b.log() we could create log wrappers in the form of:

func (b *batch) Infof(format string, args ...interface{}) { b.log().Infof(...) }

Done. Thanks!

bhandras · 2025-02-28T16:16:19Z

sweepbatcher/sweep_batcher_test.go

 	// When batch is successfully created it will execute it's first step,
 	// which leads to a spend monitor of the primary sweep.
 	<-lnd.RegisterSpendChannel

+	// Eventually request will be consumed and a new batch will spin up.
+	require.Eventually(t, func() bool {
+		return len(getBatches(ctx, batcher)) == 1


Alternatively we could add a Batcher.NumBatches() and a batch.NumSweeps() so most of these repeating checks are easier to write.

Perhaps we could also add a batch.Sweeps() which would return the swap hashes for the sweeps. So then we could completely remove the intrusive check.

I added private methods Batcher.numBatches(ctx), batch.numSweeps(ctx) and batch.snapshot(ctx) and managed to get rid of the majority of testRunInEventLoop calls.

bhandras · 2025-02-28T16:17:48Z

sweepbatcher/sweep_batcher.go

@@ -535,13 +535,15 @@ func (b *Batcher) Run(ctx context.Context) error {
 		case sweepReq := <-b.sweepReqs:
 			sweep, err := b.fetchSweep(runCtx, sweepReq)
 			if err != nil {
-				log.Warnf("fetchSweep failed: %v.", err)
+				log().Warnf("fetchSweep failed: %v.", err)


Same comment as before, although there it's just one function call, but the wrapped log might be a bit nicer.

Added private functions debuf, infof, warnf, and errorf.

bhandras · 2025-02-28T16:18:38Z

.github/workflows/main.yml

@@ -20,7 +20,7 @@ env:

  # If you change this value, please change it in the following files as well:
  # /Dockerfile
-  GO_VERSION: 1.21.10
+  GO_VERSION: 1.24.0


hieblmi

LGTM ✅ Thanks for the fixes, only a few nits.

hieblmi · 2025-02-26T14:42:44Z

sweepbatcher/sweep_batcher.go

 	for _, batch := range b.batches {
-		// This is a check to see if a batch is completed. In that case
-		// we just lazily delete it and continue our scan.
 		if batch.isComplete() {
 			delete(b.batches, batch.id)
 			continue


we can remove the continue here

Fixed. Thanks!

hieblmi · 2025-02-26T14:44:08Z

sweepbatcher/sweep_batcher.go


+	// Check if the sweep is already in a batch. If that is the case, we
+	// provide the sweep to that batch and return.
+	for _, batch := range b.batches {


+1, now I got it :)

hieblmi · 2025-03-04T07:56:12Z

sweepbatcher/sweep_batch.go

-		b.log.Warnf("Method timeout() returned %v. Number of"+
-			" sweeps: %d. It may be an empty batch.",
+		b.Warnf("Method timeout() returned %v. Number of "+
+			"sweeps: %d. It may be an empty batch.",


pls clarify, is there another option to being an empty batch here?

I added the following comment:

if timeout <= 0 { + // This may happen if the batch is empty or if SweepInfo.Timeout + // is not set, may be possible in tests or if there is a bug. b.Warnf("Method timeout() returned %v. Number of "+ "sweeps: %d. It may be an empty batch.",

hieblmi · 2025-03-04T07:56:32Z

sweepbatcher/sweep_batch.go

 				"batchConfTarget")
 		}

-		b.log.Infof("initializing rbf fee rate for conf target=%v",
+		b.Infof("initializing rbf fee rate for conf target=%v",


nit: newline after this

hieblmi · 2025-03-04T07:59:03Z

sweepbatcher/sweep_batcher_test.go

 			return false
 		}

 		// Make sure the batch has proper batchConfTarget.
-		return batch.cfg.batchConfTarget == 123
+		return snapshot.cfg.batchConfTarget == 123


place 123 into var...

hieblmi · 2025-03-04T07:59:11Z

sweepbatcher/sweep_batcher_test.go

-	// Wait for tx to be published.
-	<-lnd.TxPublishChannel
+	batch := getOnlyBatch(t, ctx, batcher).snapshot(ctx)
+	require.Equal(t, int32(123), batch.cfg.batchConfTarget)


...and use it here

hieblmi · 2025-03-04T07:59:21Z

sweepbatcher/sweep_batcher_test.go

 			return false
 		}

 		// Make sure the batch has proper batchConfTarget.
-		return batch.cfg.batchConfTarget == 123
+		return snapshot.cfg.batchConfTarget == 123


... and here

hieblmi · 2025-03-04T07:59:49Z

sweepbatcher/sweep_batcher_test.go

-	require.Equal(t, feeRateMedium, batch.rbfCache.FeeRate)
+	batch := getOnlyBatch(t, ctx, batcher)
+	snapshot := batch.snapshot(ctx)
+	require.Equal(t, 1, len(snapshot.sweeps))


require.Len

hieblmi · 2025-03-04T08:00:00Z

sweepbatcher/sweep_batcher_test.go

-	require.Len(t, batch.sweeps, 2)
-	require.Equal(t, feeRateMedium, batch.rbfCache.FeeRate)
+	snapshot = batch.snapshot(ctx)
+	require.Equal(t, 2, len(snapshot.sweeps))


require.Len

It should use the c variable passed into the lambda, not the parent t. It should use assert, not require package.

Previously, if a completed batch was visited after a batch to which the sweep was added, it was not deleted because the function returned early. This has been separated into two loops: the first one removes completed batches, and the second one adds the sweep to a batch.

This is needed to fix crashes in unit tests under -race.

Several structures were accessed without protection causing crashes under -race.

The code inside require.Eventually runs in parallel with the event loops of the batcher and its batches. Accessing fields of the batcher and batches must be done within an event loop. To address this, testRunInEventLoop methods were added to the Batcher and batch types. Unit tests were then rewritten to use this approach when accessing batcher and batch fields. Additionally, in many cases, receive operations from RegisterSpendChannel were moved before require.Eventually. This prevents testRunInEventLoop from getting stuck in an event loop while blocked on a RegisterSpendChannel send operation.

Try to catch more race conditions in unit tests.

starius requested review from bhandras, sputn1ck and hieblmi February 26, 2025 03:26

starius force-pushed the fix-unit-test-races branch from d319d72 to 565cecd Compare February 26, 2025 04:03

bhandras reviewed Feb 26, 2025

View reviewed changes

starius marked this pull request as ready for review February 26, 2025 13:24

starius requested a review from bhandras February 26, 2025 14:33

levmi assigned starius Feb 27, 2025

bhandras approved these changes Feb 28, 2025

View reviewed changes

starius force-pushed the fix-unit-test-races branch 2 times, most recently from 48b25bd to 51196e7 Compare February 28, 2025 18:23

hieblmi approved these changes Mar 4, 2025

View reviewed changes

starius added 8 commits March 4, 2025 10:25

sweepbatcher: fix race in store_mock

f0f64f8

sweepbatcher: fix usage of EventuallyWithT

a64f461

It should use the c variable passed into the lambda, not the parent t. It should use assert, not require package.

sweepbatcher: replace batch logger atomically

ab59bda

This is needed to fix crashes in unit tests under -race.

sweepbatcher/test: protect mock data with mutex

026890a

Several structures were accessed without protection causing crashes under -race.

sweepbatcher: fix race conditions in UseLogger

a333031

ci, Dockerfile: update Go to 1.24.0

60f4906

Try to catch more race conditions in unit tests.

starius force-pushed the fix-unit-test-races branch from 51196e7 to 60f4906 Compare March 4, 2025 16:45

starius merged commit 800f0e0 into lightninglabs:master Mar 4, 2025
4 checks passed

starius deleted the fix-unit-test-races branch March 4, 2025 17:10

sweepbatcher: fix race conditions in unit tests #889

sweepbatcher: fix race conditions in unit tests #889

Uh oh!

Conversation

starius commented Feb 26, 2025

Pull Request Checklist

Uh oh!

bhandras left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

bhandras left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

hieblmi left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!