Why does btcd/unannounced_channels test case "always" fail on my machine ?

[mohamedawnallah]

Description

Currently, everytime I run make check the btcd/unannounced_channels test case fails with the following error:

=== RUN   TestLightningNetworkDaemon/tranche00/39-of-142/btcd/unannounced_channels
    harness_assertion.go:276:
        	Error Trace:	/Users/mohamedawnallah/Desktop/lnd/lntest/harness_assertion.go:276
        	            				/Users/mohamedawnallah/Desktop/lnd/itest/lnd_channel_graph_test.go:244
        	            				/Users/mohamedawnallah/Desktop/lnd/lntest/harness.go:353
        	            				/Users/mohamedawnallah/Desktop/lnd/itest/lnd_test.go:139
        	Error:      	Received unexpected error:
        	            	Alice: assert num of channel edges failed: want 0, got: -1, total: 0, previously had: 1
        	Test:       	TestLightningNetworkDaemon/tranche00/39-of-142/btcd/unannounced_channels
        	Messages:   	timeout while checking for edges
    harness.go:406: finished test: unannounced_channels, start height=1947, end height=1949, mined blocks=2
    harness.go:412: test failed, skipped cleanup

but if running it alone it gives no error ?

=== RUN   TestLightningNetworkDaemon/tranche00/01-of-1/btcd/unannounced_channels
    harness.go:406: finished test: unannounced_channels, start height=440, end height=447, mined blocks=7
=== NAME  TestLightningNetworkDaemon
    lnd_test.go:155: =========> tests finished for tranche: 0, tested 1 cases, end height: 447
--- PASS: TestLightningNetworkDaemon (23.50s)
    --- PASS: TestLightningNetworkDaemon/tranche00/01-of-1/btcd/unannounced_channels (9.77s)
PASS

Context

branch: master
commit: 5cb4811
device: Mac M1
Architecture: arm64

[guggero]

Not sure, could be arm64 related... This test passes for me on Linux amd64...
Can you please check if you find a corresponding error in Alice's log file? Should be itest/.logs-tranche0/0-unannounced_channels-Alice-XXXXX.log?

[mohamedawnallah]

@guggero The error in 0-unannounced_channels-Alice-038b3a03.log Alice file (~8MB). It seems a connection error e.g port collision from the previous test cases not released? I also found no process running on this port while running the test cases by running on this port lsof -i :6057.

...
2024-03-13 06:34:36.674 [DBG] SWPR: Sweep ticker ticks, attempt sweeping...
2024-03-13 06:34:36.762 [DBG] CMGR: Attempting to connect to 03b965dd92319625a57a8a99178391a021a66d90315b83e88b5b1b3746c7c5946d@127.0.0.1:6057 (reqid 1)
2024-03-13 06:34:36.763 [DBG] CMGR: Failed to connect to 03b965dd92319625a57a8a99178391a021a66d90315b83e88b5b1b3746c7c5946d@127.0.0.1:6057 (reqid 1): dial tcp 127.0.0.1:6057: connect: connection refused
2024-03-13 06:34:36.763 [DBG] CMGR: Retrying connection to 03b965dd92319625a57a8a99178391a021a66d90315b83e88b5b1b3746c7c5946d@127.0.0.1:6057 (reqid 1) in 15s
2024-03-13 06:34:36.788 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:36.991 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:37.194 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:37.397 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:37.601 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:37.804 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:38.008 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:38.212 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:38.416 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:38.620 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:38.824 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:39.028 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:39.231 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:39.435 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:39.639 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:39.843 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:40.047 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:40.250 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:40.453 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:40.656 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:40.861 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:41.065 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:41.268 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:41.470 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:41.674 [DBG] SWPR: Sweep ticker ticks, attempt sweeping...
2024-03-13 06:34:41.674 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:41.877 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:42.081 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:42.285 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:42.487 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:42.690 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:42.894 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:43.097 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:43.301 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:43.504 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:43.708 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:43.912 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:44.116 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:44.319 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:44.523 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:44.727 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:44.931 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:45.135 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:45.338 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:45.543 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:45.746 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:45.950 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:46.154 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:46.356 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:46.560 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:46.673 [DBG] SWPR: Sweep ticker ticks, attempt sweeping...
2024-03-13 06:34:46.767 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:46.971 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:47.175 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:47.380 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:47.584 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:47.787 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:47.992 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:48.196 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:48.401 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:48.605 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:48.807 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:49.010 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:49.214 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:49.418 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:49.620 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:49.825 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:50.029 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:50.233 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:50.437 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:50.640 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:50.844 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:51.048 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:34:51.252 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:21.074 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:21.134 [DBG] SWPR: Sweep ticker ticks, attempt sweeping...
2024-03-13 06:52:21.224 [DBG] CMGR: Attempting to connect to 03b965dd92319625a57a8a99178391a021a66d90315b83e88b5b1b3746c7c5946d@127.0.0.1:6057 (reqid 1)
2024-03-13 06:52:21.225 [DBG] CMGR: Failed to connect to 03b965dd92319625a57a8a99178391a021a66d90315b83e88b5b1b3746c7c5946d@127.0.0.1:6057 (reqid 1): dial tcp 127.0.0.1:6057: connect: connection refused
2024-03-13 06:52:21.225 [DBG] CMGR: Retrying connection to 03b965dd92319625a57a8a99178391a021a66d90315b83e88b5b1b3746c7c5946d@127.0.0.1:6057 (reqid 1) in 20s
2024-03-13 06:52:21.277 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:21.477 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:21.679 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:21.883 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:22.087 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:22.290 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:22.494 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:22.695 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:22.898 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:23.102 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:23.304 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:23.508 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:23.712 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:23.914 [DBG] RPCS: [/lnrpc.Lightning/DescribeGraph] requested
2024-03-13 06:52:24.320 [DBG] RPCS: [/lnrpc.Lightning/StopDaemon] requested
2024-03-13 06:52:24.320 [INF] LTND: Received shutdown request.
2024-03-13 06:52:24.320 [INF] LTND: Shutting down...
2024-03-13 06:52:24.320 [INF] LTND: Gracefully shutting down.
2024-03-13 06:52:24.321 [INF] NANN: Channel Status Manager shutting down...
2024-03-13 06:52:24.321 [DBG] NANN: Channel Status Manager shutdown complete
2024-03-13 06:52:24.321 [INF] HSWC: HTLC Switch shutting down...
2024-03-13 06:52:24.321 [INF] NTFN: Cancelling epoch notification, epoch_id=5
2024-03-13 06:52:24.321 [INF] HSWC: Removing channel link with ChannelID(be30e502b5526a9b0f58e8f2e0c8e503e9510f0e5af2ceb484feb7c88d4321ae)
2024-03-13 06:52:24.321 [INF] HSWC: ChannelLink(ae21438dc8b7fe84b4cef25a0e0f51e903e5c8e0f2e8580f9b6a52b502e530be:0): stopping
2024-03-13 06:52:24.321 [INF] HSWC: ChannelLink(ae21438dc8b7fe84b4cef25a0e0f51e903e5c8e0f2e8580f9b6a52b502e530be:0): exited
2024-03-13 06:52:24.323 [DBG] HSWC: HTLC Switch shutdown complete
2024-03-13 06:52:24.323 [INF] HSWC: Onion processor shutting down...
2024-03-13 06:52:24.327 [INF] HSWC: Decaying hash log received shutdown request
2024-03-13 06:52:24.328 [INF] NTFN: Cancelling epoch notification, epoch_id=10
2024-03-13 06:52:24.328 [DBG] HSWC: Onion processor shutdown complete
2024-03-13 06:52:24.328 [INF] INVC: InvoiceRegistry shutting down...
2024-03-13 06:52:24.331 [INF] NTFN: Cancelling epoch notification, epoch_id=9
2024-03-13 06:52:24.331 [DBG] INVC: InvoiceRegistry shutdown complete
2024-03-13 06:52:24.332 [INF] CRTR: Channel Router shutting down...
2024-03-13 06:52:24.332 [INF] CRTR: FilteredChainView stopping
2024-03-13 06:52:24.332 [DBG] CRTR: Channel Router shutdown complete
2024-03-13 06:52:24.332 [INF] CNCT: ChainArbitrator shutting down...
2024-03-13 06:52:24.332 [DBG] CNCT: Stopping ChannelArbitrator(ae21438dc8b7fe84b4cef25a0e0f51e903e5c8e0f2e8580f9b6a52b502e530be:0)
2024-03-13 06:52:24.332 [INF] NTFN: Cancelling epoch notification, epoch_id=7
2024-03-13 06:52:24.332 [DBG] CNCT: ChainArbitrator shutdown complete
2024-03-13 06:52:24.332 [INF] FNDG: Funding manager shutting down...
2024-03-13 06:52:24.332 [ERR] FNDG: Unable to advance state(ae21438dc8b7fe84b4cef25a0e0f51e903e5c8e0f2e8580f9b6a52b502e530be:0): error sending channel announcement: funding manager shutting down, stopping funding flow for ChannelPoint(ae21438dc8b7fe84b4cef25a0e0f51e903e5c8e0f2e8580f9b6a52b502e530be:0)
...

Also here is the 1-unannounced_channels-Bob-031ec627.log Bob file (~6MB)

[mohamedawnallah]

Also here are the log files wen running btcd/unannounced_channels test case alone. No errors found:
0-unannounced_channels-Alice-03a9d494.log Alice File (~200KB).

1-unannounced_channels-Bob-03f7fbc3.log Bob File (~200KB).

[guggero]

So when running all tests, it looks like Alice cannot connect to the node that's on p2p port 6057 (might be another port for each run). Can you check which node that is by grepping for the port in the logs? Then see if that node for some reason doesn't start up properly? It might be a port collision, it might be something else.