Itest: proper connect/disconnect miner #4589

yyforyongyu · 2020-09-03T11:50:02Z

This PR tries to make it easier to catch flakes in itest. It,

catches error when miner tears down.
caches error when chain backend cleans up.
disables chain backend retrying connection to the miner.

The last one is somewhat tricky. Before this fix, the btcd chain backend automatically retries connecting to the miner on several occasions,

during the test setup, when miner was not ready, it tried to connect and failed, then it would retry it in 5s, as shown in the log,
```
2020-08-29 16:24:04.980 [DBG] CMGR: Retrying connection to 127.0.0.1:11160 (reqid 1) in 5s
```
in the test testOpenChannelAfterReorg, we manually disconnected the chain backend and the miner. Still, the chain backend retried in 5s and succeeded.
and other occasions, which can be found in the logs.

The miner ended with multiple connections with the chain backend, which makes debugging difficult.

And a recent change in btcd validates the not found message and disconnects the peer when needed.

When this InvTypeWitnessTx is receieved by the chainbackend, it's considered invalid and the miner will be disconnected. Currently, due to the permanent connection, the chainbackend will retry connection in 5 seconds. This is more clear in the following log, notice that the miner and chainbackend logs are combined and ordered by time,

# miner started processing the transaction.
2020-09-08 09:50:42.155 ["miner"] TXMP: Processing transaction 2d7ae05ad86da2585de25e9ab274dbc673088415e553133d974de7287419c003
2020-09-08 09:50:42.301 ["miner"] TXMP: Accepted transaction 2d7ae05ad86da2585de25e9ab274dbc673088415e553133d974de7287419c003 (pool size: 4)
2020-09-08 09:50:42.368 ["miner"] PEER: Sending inv (tx 2d7ae05ad86da2585de25e9ab274dbc673088415e553133d974de7287419c003) to 127.0.0.1:59724-"chainbackend" (inbound)

# miner was asked to generate 10 more blocks, this would clean the mempool.
2020-09-08 09:50:43.533 ["miner"] TXMP: Accepted transaction d0fc68e689ba5eb76a82b19fc3642605072af24cfe390bce40d9dc781924ff32 (pool size: 20)
2020-09-08 09:50:43.536 ["miner"] RPCS: Received command <generate> from 127.0.0.1:46164-"itest"
2020-09-08 09:50:43.537 ["miner"] MINR: Generating 10 blocks
2020-09-08 09:50:43.538 ["miner"] MINR: Considering 20 transactions for inclusion to new block

# the chainbackend tried to fetch the transaction, since it was not in the mempool, the miner would send
# a notfound message.
2020-09-08 09:50:44.318 ["chainbackend"] PEER: Received inv (tx 2d7ae05ad86da2585de25e9ab274dbc673088415e553133d974de7287419c003) from 127.0.0.1:23460-"miner" (outbound)
2020-09-08 09:50:44.348 ["miner"] MINR: Adding tx 2d7ae05ad86da2585de25e9ab274dbc673088415e553133d974de7287419c003 (priority 6166666666.67, feePerKB %!f(int64=6418918))
2020-09-08 09:50:44.430 ["chainbackend"] PEER: Sending getdata (witness tx 2d7ae05ad86da2585de25e9ab274dbc673088415e553133d974de7287419c003) to 127.0.0.1:23460-"miner" (outbound)
2020-09-08 09:50:45.214 ["miner"] PEER: Received getdata (witness tx 2d7ae05ad86da2585de25e9ab274dbc673088415e553133d974de7287419c003) from 127.0.0.1:59724-"chainbackend" (inbound)
2020-09-08 09:50:45.215 ["miner"] PEER: Unable to fetch tx 2d7ae05ad86da2585de25e9ab274dbc673088415e553133d974de7287419c003 from transaction pool: transaction is not in the pool
2020-09-08 09:50:45.217 ["miner"] PEER: Sending notfound (witness tx 2d7ae05ad86da2585de25e9ab274dbc673088415e553133d974de7287419c003) to 127.0.0.1:59724-"chainbackend" (inbound)
2020-09-08 09:50:45.224 ["chainbackend"] PEER: Received notfound (witness tx 2d7ae05ad86da2585de25e9ab274dbc673088415e553133d974de7287419c003) from 127.0.0.1:23460-"miner" (outbound)
2020-09-08 09:50:45.225 ["chainbackend"] PEER: Invalid inv type '1073741825' in notfound message from 127.0.0.1:23460-"miner" (outbound)
2020-09-08 09:50:45.226 ["chainbackend"] PEER: Disconnecting 127.0.0.1:23460-"miner" (outbound)
2020-09-08 09:50:45.226 ["chainbackend"] SYNC: Lost peer 127.0.0.1:23460-"miner" (outbound)

The ending 1073741825 is a type,

InvTypeWitnessTx     InvType = InvTypeTx | InvWitnessFlag

The above log happened during test setup, right after this line. After generating the blocks, we would wait for the balance to be synced. It wouldn't happen though, as the miner was disconnected and later the sync would time out.
Detailed logs can be found here.

Current itest won't pass, blocked by this fix in btcd btcsuite/btcd#1625

Related #4553, #4561 and #4563.

lntest/bitcoind.go

lntest/btcd.go

bhandras · 2020-09-04T09:16:26Z

lntest/btcd.go


 		// After shutting down the chain backend, we'll make a copy of
 		// the log file before deleting the temporary log dir.
 		logFile := logDir + "/" + netParams.Name + "/btcd.log"
 		err := CopyFile("./output_btcd_chainbackend.log", logFile)
 		if err != nil {
-			fmt.Printf("unable to copy file: %v\n", err)
+			errStr += fmt.Sprintf("unable to copy file: %v\n", err)


I'd add \n if errStr != ""

Fixed. The newline is added above when the first error appears.

halseth

Thanks for the PR, I definitely agree that having more control over the miner connection will ease debugging.

Left a few small comments. Could you add a more detailed explanation to the PR description how the linked btcd PR is needed for the tests to pass?

lntest/btcd.go

halseth · 2020-09-07T08:10:31Z

lntest/itest/lnd_test.go

@@ -14458,6 +14460,14 @@ func TestLightningNetworkDaemon(t *testing.T) {
 		ht.Fatalf("unable to request transaction notifications: %v", err)
 	}

+	// Connect chainbackend to miner.
+	if chainBackend.Name() != "neutrino" {


could instead make the neutrino ConnectMiner a noop return

yep that's cleaner, changed.

Still not changed?

Oops, my bad, now fixed😂

yyforyongyu

Thanks for the PR, I definitely agree that having more control over the miner connection will ease debugging.

Left a few small comments. Could you add a more detailed explanation to the PR description how the linked btcd PR is needed for the tests to pass?

The description is updated, previous investigation can be found in this issue #4553.

lntest/btcd.go

yyforyongyu · 2020-09-08T11:37:05Z

lntest/itest/lnd_test.go

@@ -14458,6 +14460,14 @@ func TestLightningNetworkDaemon(t *testing.T) {
 		ht.Fatalf("unable to request transaction notifications: %v", err)
 	}

+	// Connect chainbackend to miner.
+	if chainBackend.Name() != "neutrino" {


yep that's cleaner, changed.

halseth · 2020-09-09T17:22:38Z

make/testing_flags.mk

@@ -69,4 +69,4 @@ endif
 # Construct the integration test command with the added build flags.
 ITEST_TAGS := $(DEV_TAGS) $(RPC_TAGS) rpctest $(backend)

-ITEST := rm lntest/itest/*.log; date; $(GOTEST) -v ./lntest/itest -tags="$(ITEST_TAGS)" $(TEST_FLAGS) -logoutput -goroutinedump
+ITEST := rm lntest/itest/*.log; rm -r lntest/itest/.minerlogs; rm -r lntest/itest/.backendlogs; date; $(GOTEST) -v ./lntest/itest -tags="$(ITEST_TAGS)" $(TEST_FLAGS) -logoutput -goroutinedump


is this really needed? Won't they be deleted on shutdown, or alternatively overwritten on next run?

I have doubts too. Normally it would be fine until there are .gz files, which won't be cleaned if a sequence of itest fails consecutively.
It might be more related to a different PR that focuses on fixing .gz files?

Yeah, I would make that a separate PR if it is a problem.

Now removed.

halseth · 2020-09-09T17:24:03Z

Thanks for the PR, I definitely agree that having more control over the miner connection will ease debugging.
Left a few small comments. Could you add a more detailed explanation to the PR description how the linked btcd PR is needed for the tests to pass?

The description is updated, previous investigation can be found in this issue #4553.

Thanks for the detailed explanation, it makes a lot of sense now 👍 We should update our btcd dependency to check whether that will get rid of some of the flakes, but when that is in I think this PR is more or less ready :)

cfromknecht · 2020-09-11T17:45:59Z

@yyforyongyu changes look great! can you add a commit that pulls in the btcd dep so we can get a clean run of the itests?

Previously the chainbackend connected to the miner using a permanent connection, which would retry the connection when it’s disconnected. It would leave multiple connections between the chainbackend and the miner, causing difficulties in debugging. Currently, there are two occasions when disconnection happens. One happens when running the open channel reorg test, the miner is connected/disconnected multiple times on purpose. The other happens when the chainbackend receives a MSG_WITNESS_TX type from the miner, which would be considered as an invalid type and disconnects the miner. With the latter one being fixed in btcd, the chainbackend will still be disconnected from the miner if it reaches the ban score by requesting too many notfound messages in a short time which is why the `--nobanning` flag is added.

yyforyongyu · 2020-09-13T06:26:39Z

@yyforyongyu changes look great! can you add a commit that pulls in the btcd dep so we can get a clean run of the itests?

The btcd version is bumped to github.com/btcsuite/btcd v0.20.1-beta.0.20200903105316-61634447e719.

Initially, I was using github.com/btcsuite/btcd v0.20.1-beta.0.20200908235819-9ef973c282e6, which caused a failure in testSweepAllCoins when running with bitcoind backend.

--- FAIL: TestLightningNetworkDaemon (31.06s)
    lnd_test.go:14526: Running 66 integration tests
    --- FAIL: TestLightningNetworkDaemon/sweep_coins (2.81s)
        lnd_test.go:112: Failed: (sweep coins): exited with error: 
            *errors.errorString unable to sweep coins: rpc error: code = Unknown desc = unable to broadcast sweep transaction: unmatched backend error: -1: sendrawtransaction "hexstring" ( maxfeerate )

Specifically, in this line.

I'm suspecting the change in this commit is causing the problem of using sendrawtransaction in bitcoind. From my observation, reverting the function makeParams to the old version would make the error disappear in lnd's itest.

It's unclear if the bug is in lnd, btcwallet, or btcd. I will dig into it later, currently, the btcd version in this commit seems to have problems with the windows machine which I'm still investigating.

cfromknecht

LGTM 💫

@yyforyongyu do you still want to investigate the windows build? i restarted travis and it passed first time. otherwise i think this is ready to merge

yyforyongyu · 2020-09-24T12:43:45Z

LGTM 💫

@yyforyongyu do you still want to investigate the windows build? i restarted travis and it passed first time. otherwise i think this is ready to merge

Yes, I'm still investigating the test flake. Don't know if it's the best approach, but I've run the itest 10 times for each backend, a total of 30 times. The tests are still flaky, and I'm still investigating. That being said, this PR was meant to fix the miners so feel free to merge. I will open a new PR if I could find anything interesting.

halseth

Great change, thanks again! 🌟

halseth self-requested a review September 3, 2020 11:53

halseth modified the milestone: 0.12.0 Sep 3, 2020

yyforyongyu force-pushed the itest-proper-cleanup branch from 13b2720 to 06ffce6 Compare September 3, 2020 11:57

bhandras reviewed Sep 4, 2020

View reviewed changes

yyforyongyu force-pushed the itest-proper-cleanup branch from 06ffce6 to 62f4441 Compare September 4, 2020 11:14

halseth suggested changes Sep 7, 2020

View reviewed changes

yyforyongyu commented Sep 8, 2020

View reviewed changes

yyforyongyu force-pushed the itest-proper-cleanup branch from 62f4441 to 79a45b4 Compare September 8, 2020 11:57

yyforyongyu requested a review from halseth September 8, 2020 11:59

halseth reviewed Sep 9, 2020

View reviewed changes

yyforyongyu force-pushed the itest-proper-cleanup branch 2 times, most recently from c90653e to 2812dc2 Compare September 10, 2020 12:13

yyforyongyu force-pushed the itest-proper-cleanup branch from 2812dc2 to 6e662a0 Compare September 12, 2020 11:02

yyforyongyu added 3 commits September 12, 2020 20:09

itest: require no error when tearing down miners

933d842

itest: require no error when cleaning up chainbackends

724f6e0

yyforyongyu force-pushed the itest-proper-cleanup branch from 6e662a0 to 2fd236b Compare September 13, 2020 02:53

build: update to btcd version with notfound msg fix

65383a1

yyforyongyu force-pushed the itest-proper-cleanup branch from 2fd236b to 65383a1 Compare September 13, 2020 03:26

cfromknecht reviewed Sep 24, 2020

View reviewed changes

cfromknecht approved these changes Sep 24, 2020

View reviewed changes

cfromknecht requested a review from halseth September 24, 2020 19:09

halseth approved these changes Sep 25, 2020

View reviewed changes

halseth merged commit 74e62e5 into lightningnetwork:master Sep 25, 2020

guggero mentioned this pull request Nov 11, 2020

integration: optimize harness for better itest control, restore bitcoind compatibility btcsuite/btcd#1659

Merged

yyforyongyu deleted the itest-proper-cleanup branch January 6, 2021 00:43

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Itest: proper connect/disconnect miner #4589

Itest: proper connect/disconnect miner #4589

yyforyongyu commented Sep 3, 2020 •

edited

Loading

bhandras Sep 4, 2020

yyforyongyu Sep 4, 2020

halseth left a comment

halseth Sep 7, 2020

yyforyongyu Sep 8, 2020

halseth Sep 9, 2020

yyforyongyu Sep 10, 2020

yyforyongyu left a comment

yyforyongyu Sep 8, 2020

halseth Sep 9, 2020

yyforyongyu Sep 10, 2020

halseth Sep 11, 2020

yyforyongyu Sep 13, 2020

halseth commented Sep 9, 2020

cfromknecht commented Sep 11, 2020

yyforyongyu commented Sep 13, 2020

cfromknecht left a comment

yyforyongyu commented Sep 24, 2020

halseth left a comment

Itest: proper connect/disconnect miner #4589

Itest: proper connect/disconnect miner #4589

Conversation

yyforyongyu commented Sep 3, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

halseth left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

yyforyongyu left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

halseth commented Sep 9, 2020

cfromknecht commented Sep 11, 2020

yyforyongyu commented Sep 13, 2020

cfromknecht left a comment

Choose a reason for hiding this comment

yyforyongyu commented Sep 24, 2020

halseth left a comment

Choose a reason for hiding this comment

yyforyongyu commented Sep 3, 2020 •

edited

Loading