Race from batch cancellation

[jharveyb]

Have seen this intermittently in CI. Latest logs:

2023-10-10 23:32:44.669 [INF] GRDN: BatchCaretaker(022db6e8c5b69ca112471ec2fd70a2ed8cb3c5b145acb2af73567bb19c7155fed8): transition states: BatchStateBroadcast -> BatchStateBroadcast
2023-10-10 23:32:44.723 [INF] GRDN: Cancelling MintingBatch(key=022db6e8c5b69ca112471ec2fd70a2ed8cb3c5b145acb2af73567bb19c7155fed8, num_assets=5)
panic: test timed out after 20m0s
running tests:
	TestBatchedAssetIssuance (19m59s)
	TestBatchedAssetIssuance/minting_with_cancellation (19m56s)

goroutine 1260 [running]:
testing.(*M).startAlarm.func1()
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:2259 +0x1fc
created by time.goFunc
	/opt/hostedtoolcache/go/1.21.0/x64/src/time/sleep.go:176 +0x45

goroutine 1 [chan receive, 19 minutes]:
testing.(*T).Run(0xc000418ea0, {0x234ae71, 0x18}, 0x24a2460)
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1649 +0x856
testing.runTests.func1(0x0?)
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:2054 +0x85
testing.tRunner(0xc000418ea0, 0xc0004e5b08)
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1595 +0x239
testing.runTests(0xc000430500?, {0x336fb40, 0x5, 0x5}, {0x1c?, 0x4add79?, 0x339f5a0?})
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:2052 +0x897
testing.(*M).Run(0xc000430500)
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1925 +0xb58
main.main()
	_testmain.go:57 +0x2be

goroutine 7 [chan receive, 20 minutes]:
testing.(*T).Parallel(0xc000419040)
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1403 +0x570
github.com/lightninglabs/taproot-assets/tapgarden.TestWatchProofs(0xc000419040)
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/re-org_watcher_test.go:111 +0x3f
testing.tRunner(0xc000419040, 0x24a2450)
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1595 +0x239
created by testing.(*T).Run in goroutine 1
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1648 +0x82b

goroutine 8 [chan receive, 20 minutes]:
testing.(*T).Parallel(0xc000419380)
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1403 +0x570
github.com/lightninglabs/taproot-assets/tapgarden_test.TestCustodianNewAddr(0xc000419380)
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/custodian_test.go:232 +0x3f
testing.tRunner(0xc000419380, 0x24a2468)
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1595 +0x239
created by testing.(*T).Run in goroutine 1
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1648 +0x82b

goroutine 230 [chan receive, 19 minutes]:
testing.(*T).Parallel(0xc0007c64e0)
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1403 +0x570
github.com/lightninglabs/taproot-assets/tapgarden_test.TestAddrMatchesAsset(0x0?)
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/custodian_test.go:333 +0x3f
testing.tRunner(0xc0007c64e0, 0x24a2458)
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1595 +0x239
created by testing.(*T).Run in goroutine 1
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1648 +0x82b

goroutine 483 [select, 19 minutes]:
github.com/lightninglabs/taproot-assets/tapgarden.(*ChainPlanter).gardener(0xc0002e3680)
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/planter.go:480 +0x3af
created by github.com/lightninglabs/taproot-assets/tapgarden.(*ChainPlanter).Start.func1 in goroutine 260
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/planter.go:310 +0x5eb

goroutine 231 [chan receive, 19 minutes]:
testing.(*T).Run(0xc0007c6680, {0x234c6db, 0x19}, 0xc0007f4000)
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1649 +0x856
github.com/lightninglabs/taproot-assets/tapgarden_test.TestBatchedAssetIssuance(0xc0007c6680)
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/planter_test.go:1000 +0x71
testing.tRunner(0xc0007c6680, 0x24a2460)
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1595 +0x239
created by testing.(*T).Run in goroutine 1
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1648 +0x82b

goroutine 838 [select]:
github.com/lightningnetwork/lnd/ticker.NewForce.func1()
	/home/runner/work/go/pkg/mod/github.com/lightningnetwork/lnd/ticker@v1.1.1/force.go:44 +0x17d
created by github.com/lightningnetwork/lnd/ticker.NewForce in goroutine 837
	/home/runner/work/go/pkg/mod/github.com/lightningnetwork/lnd/ticker@v1.1.1/force.go:40 +0x25d

goroutine 232 [select, 19 minutes]:
database/sql.(*DB).connectionOpener(0xc000400410, {0x26e4938, 0xc00057b7c0})
	/opt/hostedtoolcache/go/1.21.0/x64/src/database/sql/sql.go:1218 +0xed
created by database/sql.OpenDB in goroutine 231
	/opt/hostedtoolcache/go/1.21.0/x64/src/database/sql/sql.go:791 +0x2f0

goroutine 910 [chan send, 19 minutes]:
github.com/lightninglabs/taproot-assets/tapgarden.(*BatchCaretaker).assetCultivator(0xc00038c620)
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/caretaker.go:314 +0x4b2
created by github.com/lightninglabs/taproot-assets/tapgarden.(*BatchCaretaker).Start.func1 in goroutine 843
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/caretaker.go:157 +0xc5

goroutine 561 [select, 19 minutes]:
github.com/lightninglabs/taproot-assets/tapgarden.(*ChainPlanter).gardener(0xc000408240)
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/planter.go:480 +0x3af
created by github.com/lightninglabs/taproot-assets/tapgarden.(*ChainPlanter).Start.func1 in goroutine 555
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/planter.go:310 +0x5eb

goroutine 1109 [select, 19 minutes]:
github.com/lightninglabs/taproot-assets/tapgarden.(*BatchCaretaker).assetCultivator(0xc000234b60)
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/caretaker.go:331 +0x6fd
created by github.com/lightninglabs/taproot-assets/tapgarden.(*BatchCaretaker).Start.func1 in goroutine 843
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/caretaker.go:157 +0xc5

goroutine 556 [select]:
github.com/lightningnetwork/lnd/ticker.NewForce.func1()
	/home/runner/work/go/pkg/mod/github.com/lightningnetwork/lnd/ticker@v1.1.1/force.go:44 +0x17d
created by github.com/lightningnetwork/lnd/ticker.NewForce in goroutine 555
	/home/runner/work/go/pkg/mod/github.com/lightningnetwork/lnd/ticker@v1.1.1/force.go:40 +0x25d

goroutine 803 [select, 19 minutes]:
database/sql.(*DB).connectionOpener(0xc000400c30, {0x26e4938, 0xc0009815e0})
	/opt/hostedtoolcache/go/1.21.0/x64/src/database/sql/sql.go:1218 +0xed
created by database/sql.OpenDB in goroutine 231
	/opt/hostedtoolcache/go/1.21.0/x64/src/database/sql/sql.go:791 +0x2f0

goroutine 837 [chan send, 19 minutes]:
github.com/lightninglabs/taproot-assets/tapgarden.(*MockChainBridge).SendConfNtfn(...)
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/mock.go:263
github.com/lightninglabs/taproot-assets/tapgarden_test.(*mintingTestHarness).assertConfReqSent.func1()
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/planter_test.go:581 +0x217
github.com/lightninglabs/taproot-assets/tapgarden_test.testMintingCancelFinalize(0xc0001f61b0)
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/planter_test.go:953 +0x952
github.com/lightninglabs/taproot-assets/tapgarden_test.TestBatchedAssetIssuance.func1(0x0?)
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/planter_test.go:1004 +0x68
testing.tRunner(0xc00069a1a0, 0xc0007f4000)
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1595 +0x239
created by testing.(*T).Run in goroutine 231
	/opt/hostedtoolcache/go/1.21.0/x64/src/testing/testing.go:1648 +0x82b

goroutine 843 [select, 19 minutes]:
github.com/lightninglabs/taproot-assets/tapgarden.(*ChainPlanter).gardener(0xc0004087e0)
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/planter.go:480 +0x3af
created by github.com/lightninglabs/taproot-assets/tapgarden.(*ChainPlanter).Start.func1 in goroutine 837
	/home/runner/work/taproot-assets/taproot-assets/tapgarden/planter.go:310 +0x5eb

goroutine 516 [select, 19 minutes]:
database/sql.(*DB).connectionOpener(0xc000400ea0, {0x26e4938, 0xc000980460})
	/opt/hostedtoolcache/go/1.21.0/x64/src/database/sql/sql.go:1218 +0xed
created by database/sql.OpenDB in goroutine 231
	/opt/hostedtoolcache/go/1.21.0/x64/src/database/sql/sql.go:791 +0x2f0

goroutine 261 [select, 19 minutes]:
github.com/lightningnetwork/lnd/ticker.NewForce.func1()
	/home/runner/work/go/pkg/mod/github.com/lightningnetwork/lnd/ticker@v1.1.1/force.go:44 +0x17d
created by github.com/lightningnetwork/lnd/ticker.NewForce in goroutine 260
	/home/runner/work/go/pkg/mod/github.com/lightningnetwork/lnd/ticker@v1.1.1/force.go:40 +0x25d
FAIL	github.com/lightninglabs/taproot-assets/tapgarden	1200.308s
FAIL

Not sure if this is plausible outside of the unit test harness.

[Roasbeef]

Just ran into this. It's actually a deadlock, as all goroutines were locked (other than w/e ticker, so not all for 20 mins.

[Roasbeef]

Diff run, same instance: https://paste.sh/lLANIv1H#YtmmnfQRRBVTe_DBkIkVUKC6

[jharveyb]

Dupe of #360

[jharveyb]

Draft PR: #693

[guggero]

Fixed by #693.