From d543ff581149b924fc6be2ed07b0eddb5cce0a77 Mon Sep 17 00:00:00 2001 From: Wilmer Paulino Date: Wed, 23 May 2018 01:45:55 -0400 Subject: [PATCH 1/6] lntest: wait until channel is active within AssertChannelExists In this commit, we fix a race condition where at times we open a channel between two parties and immediately try to send payments over it. At times this would fail due to the channel link not being fully registered in the HTLC switch. --- lntest/harness.go | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/lntest/harness.go b/lntest/harness.go index 455154670..600c7b02f 100644 --- a/lntest/harness.go +++ b/lntest/harness.go @@ -998,8 +998,8 @@ func (n *NetworkHarness) WaitForChannelClose(ctx context.Context, } } -// AssertChannelExists asserts that an active channel identified by -// channelPoint is known to exist from the point-of-view of node.. +// AssertChannelExists asserts that an active channel identified by the +// specified channel point exists from the point-of-view of the node. func (n *NetworkHarness) AssertChannelExists(ctx context.Context, node *HarnessNode, chanPoint *wire.OutPoint) error { @@ -1015,7 +1015,7 @@ func (n *NetworkHarness) AssertChannelExists(ctx context.Context, for _, channel := range resp.Channels { if channel.ChannelPoint == chanPoint.String() { - return true + return channel.Active } } From d8325e29fd00736f53f20cca783d454d4a282f37 Mon Sep 17 00:00:00 2001 From: Wilmer Paulino Date: Thu, 24 May 2018 02:54:12 -0400 Subject: [PATCH 2/6] test: use graph notifications to receive node announcement In this commit, we rewrite the node announcement integration test to no longer depend on a sleep interval. Instead, we use graph topology updates in order to be notified exactly when we receive the node announcement. --- lnd_test.go | 72 +++++++++++++++++++++++++++++------------------------ 1 file changed, 40 insertions(+), 32 deletions(-) diff --git a/lnd_test.go b/lnd_test.go index 7105676e7..87c9b24d1 100644 --- a/lnd_test.go +++ b/lnd_test.go @@ -5513,15 +5513,17 @@ func testGraphTopologyNotifications(net *lntest.NetworkHarness, t *harnessTest) // announced to the network and reported in the network graph. func testNodeAnnouncement(net *lntest.NetworkHarness, t *harnessTest) { ctxb := context.Background() + aliceUpdates, quit := subscribeGraphNotifications(t, ctxb, net.Alice) + defer close(quit) - ipAddresses := map[string]bool{ - "192.168.1.1:8333": true, - "[2001:db8:85a3:8d3:1319:8a2e:370:7348]:8337": true, + advertisedAddrs := []string{ + "192.168.1.1:8333", + "[2001:db8:85a3:8d3:1319:8a2e:370:7348]:8337", } var lndArgs []string - for address := range ipAddresses { - lndArgs = append(lndArgs, "--externalip="+address) + for _, addr := range advertisedAddrs { + lndArgs = append(lndArgs, "--externalip="+addr) } dave, err := net.NewNode("Dave", lndArgs) @@ -5541,43 +5543,49 @@ func testNodeAnnouncement(net *lntest.NetworkHarness, t *harnessTest) { ctxt, t, net, net.Bob, dave, 1000000, 0, false, ) - // When Alice now connects with Dave, Alice will get his node announcement. + // When Alice now connects with Dave, Alice will get his node + // announcement. if err := net.ConnectNodes(ctxb, net.Alice, dave); err != nil { t.Fatalf("unable to connect bob to carol: %v", err) } - time.Sleep(time.Second * 1) - req := &lnrpc.ChannelGraphRequest{} - chanGraph, err := net.Alice.DescribeGraph(ctxb, req) - if err != nil { - t.Fatalf("unable to query for alice's routing table: %v", err) - } + assertAddrs := func(addrsFound []string, targetAddrs ...string) { + addrs := make(map[string]struct{}, len(addrsFound)) + for _, addr := range addrsFound { + addrs[addr] = struct{}{} + } - for _, node := range chanGraph.Nodes { - if node.PubKey == dave.PubKeyStr { - for _, address := range node.Addresses { - addrStr := address.String() - - // parse the IP address from the string - // representation of the TCPAddr - parts := strings.Split(addrStr, "\"") - if ipAddresses[parts[3]] { - delete(ipAddresses, parts[3]) - } else { - if !strings.HasPrefix(parts[3], - "127.0.0.1:") { - t.Fatalf("unexpected IP: %v", - parts[3]) - } - } + for _, addr := range targetAddrs { + if _, ok := addrs[addr]; !ok { + t.Fatalf("address %v not found in node "+ + "announcement", addr) } } } - if len(ipAddresses) != 0 { - t.Fatalf("expected IP addresses not in channel "+ - "graph: %v", ipAddresses) + + waitForAddrsInUpdate := func(graphUpdates <-chan *lnrpc.GraphTopologyUpdate, + nodePubKey string, targetAddrs ...string) { + + for { + select { + case graphUpdate := <-graphUpdates: + for _, update := range graphUpdate.NodeUpdates { + if update.IdentityKey == nodePubKey { + assertAddrs( + update.Addresses, + targetAddrs..., + ) + return + } + } + case <-time.After(20 * time.Second): + t.Fatalf("did not receive node ann update") + } + } } + waitForAddrsInUpdate(aliceUpdates, dave.PubKeyStr, advertisedAddrs...) + // Close the channel between Bob and Dave. ctxt, _ = context.WithTimeout(ctxb, timeout) closeChannelAndAssert(ctxt, t, net, net.Bob, chanPoint, false) From 11c315cffef05702c8d34ee6b051925c27e0b539 Mon Sep 17 00:00:00 2001 From: Wilmer Paulino Date: Thu, 24 May 2018 17:57:20 -0400 Subject: [PATCH 3/6] test: modify waitForTxInMempool to expect only one tx in the mempool --- lnd_test.go | 45 +++++++++++++++------------------------------ 1 file changed, 15 insertions(+), 30 deletions(-) diff --git a/lnd_test.go b/lnd_test.go index 87c9b24d1..b14205f6c 100644 --- a/lnd_test.go +++ b/lnd_test.go @@ -4009,38 +4009,23 @@ func copyFile(dest, src string) error { return d.Close() } +// waitForTxInMempool polls until finding one transaction in the provided +// miner's mempool. An error is returned if *one* transaction isn't found within +// the given timeout. func waitForTxInMempool(miner *rpcclient.Client, timeout time.Duration) (*chainhash.Hash, error) { - var txid *chainhash.Hash - breakTimeout := time.After(timeout) - ticker := time.NewTicker(50 * time.Millisecond) - defer ticker.Stop() -poll: - for { - select { - case <-breakTimeout: - return nil, errors.New("no tx found in mempool") - case <-ticker.C: - mempool, err := miner.GetRawMempool() - if err != nil { - return nil, err - } - - if len(mempool) == 0 { - continue - } - - txid = mempool[0] - break poll - } + txs, err := waitForNTxsInMempool(miner, 1, timeout) + if err != nil { + return nil, err } - return txid, nil + + return txs[0], err } // waitForNTxsInMempool polls until finding the desired number of transactions -// in the provided miner's mempool. An error is returned if the this number is -// not met after the given timeout. +// in the provided miner's mempool. An error is returned if this number is not +// met after the given timeout. func waitForNTxsInMempool(miner *rpcclient.Client, n int, timeout time.Duration) ([]*chainhash.Hash, error) { @@ -4054,7 +4039,7 @@ func waitForNTxsInMempool(miner *rpcclient.Client, n int, select { case <-breakTimeout: return nil, fmt.Errorf("wanted %v, found %v txs "+ - "in mempool", n, len(mempool)) + "in mempool: %v", n, len(mempool), mempool) case <-ticker.C: mempool, err = miner.GetRawMempool() if err != nil { @@ -6441,7 +6426,7 @@ func testMultiHopHtlcLocalTimeout(net *lntest.NetworkHarness, t *harnessTest) { } _, err = waitForTxInMempool(net.Miner.Node, time.Second*10) if err != nil { - t.Fatalf("unable to find bob's sweeping transaction") + t.Fatalf("unable to find bob's sweeping transaction: %v", err) } // Next, we'll mine a final block that should confirm the second-layer @@ -6669,7 +6654,7 @@ func testMultiHopReceiverChainClaim(net *lntest.NetworkHarness, t *harnessTest) // We should have a new transaction in the mempool. _, err = waitForTxInMempool(net.Miner.Node, time.Second*10) if err != nil { - t.Fatalf("unable to find bob's sweeping transaction") + t.Fatalf("unable to find bob's sweeping transaction: %v", err) } // Finally, if we mine an additional block to confirm these two sweep @@ -7355,7 +7340,7 @@ func testMultiHopHtlcLocalChainClaim(net *lntest.NetworkHarness, t *harnessTest) _, err = waitForTxInMempool(net.Miner.Node, time.Second*10) if err != nil { - t.Fatalf("unable to find bob's sweeping transaction") + t.Fatalf("unable to find bob's sweeping transaction: %v", err) } // At this point, Bob should detect that he has no pending channels @@ -7542,7 +7527,7 @@ func testMultiHopHtlcRemoteChainClaim(net *lntest.NetworkHarness, t *harnessTest _, err = waitForNTxsInMempool(net.Miner.Node, 1, time.Second*15) if err != nil { - t.Fatalf("unable to find bob's sweeping transaction") + t.Fatalf("unable to find bob's sweeping transaction: %v", err) } // We'll now mine another block, this should confirm the sweep From a3e0c9ca0bbae5e155b1f72d986982d788324cfd Mon Sep 17 00:00:00 2001 From: Wilmer Paulino Date: Thu, 24 May 2018 23:44:11 -0400 Subject: [PATCH 4/6] test: expect sweep txs for both sides in the mempool after csv delay --- lnd_test.go | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/lnd_test.go b/lnd_test.go index b14205f6c..bc838e215 100644 --- a/lnd_test.go +++ b/lnd_test.go @@ -7332,23 +7332,25 @@ func testMultiHopHtlcLocalChainClaim(net *lntest.NetworkHarness, t *harnessTest) } assertTxInBlock(t, block, secondLevelHash) - // If we then mine 4 additional blocks, Bob should pull the output - // destined for him. + // If we then mine 4 additional blocks, Bob and Carol should sweep the + // outputs destined for them. if _, err := net.Miner.Node.Generate(defaultCSV); err != nil { t.Fatalf("unable to generate block: %v", err) } - _, err = waitForTxInMempool(net.Miner.Node, time.Second*10) + sweepTxs, err := waitForNTxsInMempool(net.Miner.Node, 2, time.Second*10) if err != nil { - t.Fatalf("unable to find bob's sweeping transaction: %v", err) + t.Fatalf("unable to find sweeping transactions: %v", err) } // At this point, Bob should detect that he has no pending channels // anymore, as this just resolved it by the confirmation of the sweep // transaction we detected above. - if _, err := net.Miner.Node.Generate(1); err != nil { - t.Fatalf("unable to generate block: %v", err) + block = mineBlocks(t, net, 1)[0] + for _, sweepTx := range sweepTxs { + assertTxInBlock(t, block, sweepTx) } + err = lntest.WaitPredicate(func() bool { pendingChanResp, err := net.Bob.PendingChannels( ctxb, pendingChansRequest, From 84fcf5b12fa19c1a01ffd359cd49a6caec5efb01 Mon Sep 17 00:00:00 2001 From: Wilmer Paulino Date: Thu, 24 May 2018 22:40:56 -0400 Subject: [PATCH 5/6] test: detect funding output sweep tx after force close In this commit, we address an existing flake that would be triggered when testing HTLC timeouts. After force closing a channel and generating enough blocks to expire an HTLC, we would wait for a transaction to arrive in the mempool and assumed it was the timeout transaction. Instead, we'd detect the funding output sweep transaction and attempt to proceed with the test with the incorrect assumption of the timeout transaction being broadcast. --- lnd_test.go | 88 +++++++++++++++++++++++++++++++++++------------------ 1 file changed, 59 insertions(+), 29 deletions(-) diff --git a/lnd_test.go b/lnd_test.go index bc838e215..ed9f0ad7a 100644 --- a/lnd_test.go +++ b/lnd_test.go @@ -6264,6 +6264,7 @@ func testMultiHopHtlcLocalTimeout(net *lntest.NetworkHarness, t *harnessTest) { dustHtlcAmt = btcutil.Amount(100) htlcAmt = btcutil.Amount(30000) finalCltvDelta = 40 + csvDelay = 4 ) alicePayStream, err := net.Alice.SendPayment(ctxb) if err != nil { @@ -6353,15 +6354,20 @@ func testMultiHopHtlcLocalTimeout(net *lntest.NetworkHarness, t *harnessTest) { t.Fatalf("htlc mismatch: %v", predErr) } - // TODO(roasbeef): need to fix utxn so it can accept incubation for - // timeout that has already past - // - // * remove after solved - time.Sleep(time.Second * 5) + // We'll mine csvDelay blocks in order to generate the sweep transaction + // of Bob's funding output. + if _, err := net.Miner.Node.Generate(csvDelay); err != nil { + t.Fatalf("unable to generate blocks: %v", err) + } + + _, err = waitForTxInMempool(net.Miner.Node, 10*time.Second) + if err != nil { + t.Fatalf("unable to find bob's funding output sweep tx: %v", err) + } // We'll now mine the remaining blocks to cause the HTLC itself to // timeout. - if _, err := net.Miner.Node.Generate(defaultBroadcastDelta); err != nil { + if _, err := net.Miner.Node.Generate(defaultBroadcastDelta - csvDelay); err != nil { t.Fatalf("unable to generate blocks: %v", err) } @@ -6712,6 +6718,7 @@ func testMultiHopLocalForceCloseOnChainHtlcTimeout(net *lntest.NetworkHarness, // to Carol. As Carol is in hodl mode, she won't settle this HTLC which // opens up the base for out tests. const ( + csvDelay = 4 finalCltvDelta = 40 htlcAmt = btcutil.Amount(30000) ) @@ -6786,9 +6793,20 @@ func testMultiHopLocalForceCloseOnChainHtlcTimeout(net *lntest.NetworkHarness, t.Fatalf(predErr.Error()) } + // We'll mine csvDelay blocks in order to generate the sweep transaction + // of Bob's funding output. + if _, err := net.Miner.Node.Generate(csvDelay); err != nil { + t.Fatalf("unable to generate blocks: %v", err) + } + + _, err = waitForTxInMempool(net.Miner.Node, 10*time.Second) + if err != nil { + t.Fatalf("unable to find bob's funding output sweep tx: %v", err) + } + // We'll now mine enough blocks for the HTLC to expire. After this, Bob // should hand off the now expired HTLC output to the utxo nursery. - if _, err := net.Miner.Node.Generate(finalCltvDelta); err != nil { + if _, err := net.Miner.Node.Generate(finalCltvDelta - csvDelay - 1); err != nil { t.Fatalf("unable to generate blocks: %v", err) } @@ -6830,16 +6848,15 @@ func testMultiHopLocalForceCloseOnChainHtlcTimeout(net *lntest.NetworkHarness, // We should also now find a transaction in the mempool, as Bob should // have broadcast his second layer timeout transaction. - _, err = waitForTxInMempool(net.Miner.Node, time.Second*10) + timeoutTx, err := waitForTxInMempool(net.Miner.Node, 10*time.Second) if err != nil { - t.Fatalf("unable to find bob's sweeping transaction") + t.Fatalf("unable to find bob's htlc timeout tx: %v", err) } // Next, we'll mine an additional block. This should serve to confirm // the second layer timeout transaction. - if _, err := net.Miner.Node.Generate(1); err != nil { - t.Fatalf("unable to generate block: %v", err) - } + block := mineBlocks(t, net, 1)[0] + assertTxInBlock(t, block, timeoutTx) // With the second layer timeout transaction confirmed, Bob should have // cancelled backwards the HTLC that carol sent. @@ -6888,19 +6905,21 @@ func testMultiHopLocalForceCloseOnChainHtlcTimeout(net *lntest.NetworkHarness, } // We'll now mine 4 additional blocks. This should be enough for Bob's - // CSV timelock to expire, and the sweeping transaction to be - // confirmed. - if _, err := net.Miner.Node.Generate(4); err != nil { + // CSV timelock to expire and the sweeping transaction of the HTLC to be + // broadcast. + if _, err := net.Miner.Node.Generate(csvDelay); err != nil { t.Fatalf("unable to mine blocks: %v", err) } - time.Sleep(time.Second * 3) + sweepTx, err := waitForTxInMempool(net.Miner.Node, 10*time.Second) + if err != nil { + t.Fatalf("unable to find bob's htlc sweep tx: %v", err) + } // We'll then mine a final block which should confirm this second layer // sweep transaction. - if _, err := net.Miner.Node.Generate(1); err != nil { - t.Fatalf("unable to mine blocks: %v", err) - } + block = mineBlocks(t, net, 1)[0] + assertTxInBlock(t, block, sweepTx) // At this point, Bob should no longer show any channels as pending // close. @@ -6939,7 +6958,7 @@ func testMultiHopLocalForceCloseOnChainHtlcTimeout(net *lntest.NetworkHarness, // channel, then we properly timeout the HTLC on *their* commitment transaction // once the timeout has expired. Once we sweep the transaction, we should also // cancel back the initial HTLC. -func testMultHopRemoteForceCloseOnChainHtlcTimeout(net *lntest.NetworkHarness, +func testMultiHopRemoteForceCloseOnChainHtlcTimeout(net *lntest.NetworkHarness, t *harnessTest) { timeout := time.Duration(time.Second * 15) @@ -6954,6 +6973,7 @@ func testMultHopRemoteForceCloseOnChainHtlcTimeout(net *lntest.NetworkHarness, // to Carol. As Carol is in hodl mode, she won't settle this HTLC which // opens up the base for out tests. const ( + csvDelay = 4 finalCltvDelta = 40 htlcAmt = btcutil.Amount(30000) ) @@ -7021,10 +7041,21 @@ func testMultHopRemoteForceCloseOnChainHtlcTimeout(net *lntest.NetworkHarness, t.Fatalf(predErr.Error()) } + // We'll mine csvDelay blocks in order to generate the sweep transaction + // of Bob's funding output. + if _, err := net.Miner.Node.Generate(csvDelay); err != nil { + t.Fatalf("unable to generate blocks: %v", err) + } + + _, err = waitForTxInMempool(net.Miner.Node, 10*time.Second) + if err != nil { + t.Fatalf("unable to find bob's funding output sweep tx: %v", err) + } + // Next, we'll mine enough blocks for the HTLC to expire. At this // point, Bob should hand off the output to his internal utxo nursery, // which will broadcast a sweep transaction. - if _, err := net.Miner.Node.Generate(finalCltvDelta - 1); err != nil { + if _, err := net.Miner.Node.Generate(finalCltvDelta - csvDelay - 1); err != nil { t.Fatalf("unable to generate blocks: %v", err) } @@ -7067,7 +7098,7 @@ func testMultHopRemoteForceCloseOnChainHtlcTimeout(net *lntest.NetworkHarness, // Bob's sweeping transaction should now be found in the mempool at // this point. - _, err = waitForTxInMempool(net.Miner.Node, time.Second*10) + sweepTx, err := waitForTxInMempool(net.Miner.Node, time.Second*10) if err != nil { // If Bob's transaction isn't yet in the mempool, then due to // internal message passing and the low period between blocks @@ -7078,18 +7109,17 @@ func testMultHopRemoteForceCloseOnChainHtlcTimeout(net *lntest.NetworkHarness, if _, err := net.Miner.Node.Generate(1); err != nil { t.Fatalf("unable to generate block: %v", err) } - _, err = waitForTxInMempool(net.Miner.Node, time.Second*10) + sweepTx, err = waitForTxInMempool(net.Miner.Node, time.Second*10) if err != nil { - t.Fatalf("unable to find bob's sweeping "+ - "transaction: %v", err) + t.Fatalf("unable to find bob's sweeping transaction: "+ + "%v", err) } } // If we mine an additional block, then this should confirm Bob's // transaction which sweeps the direct HTLC output. - if _, err := net.Miner.Node.Generate(1); err != nil { - t.Fatalf("unable to generate block: %v", err) - } + block := mineBlocks(t, net, 1)[0] + assertTxInBlock(t, block, sweepTx) // Now that the sweeping transaction has been confirmed, Bob should // cancel back that HTLC. As a result, Alice should not know of any @@ -9140,7 +9170,7 @@ var testsCases = []*testCase{ // bob: outgoing their commit watch and see timeout // carol: incoming our commit watch and see timeout name: "test multi-hop remote force close on-chain htlc timeout", - test: testMultHopRemoteForceCloseOnChainHtlcTimeout, + test: testMultiHopRemoteForceCloseOnChainHtlcTimeout, }, { // bob: outgoing our commit watch and see, they sweep on chain From 3e7c69e596555f35f9af1e0b9bb3e929cd66a401 Mon Sep 17 00:00:00 2001 From: Wilmer Paulino Date: Thu, 24 May 2018 22:55:13 -0400 Subject: [PATCH 6/6] Revert "test: account for block race by mining additional block in remote htlc force close test" Before the previous commit, we assumed the HTLC's timeout transaction would be the only transaction in the mempool. In reality, after mining some blocks for the HTLC to expire and waiting for the timeout transaction to arrive in the mempool, at times we would instead detect the funding output's sweeping transaction and proceed the test with this assumption, leading to the case where we would have to mine extra blocks to include the HTLC sweeping transaction. This has been resolved in the previous commit, so this fix is no longer needed. This reverts commit e54f1ea4dbe59b2e53a94774995ae1711746c2f8. --- lnd_test.go | 15 ++------------- 1 file changed, 2 insertions(+), 13 deletions(-) diff --git a/lnd_test.go b/lnd_test.go index ed9f0ad7a..b9d188ba9 100644 --- a/lnd_test.go +++ b/lnd_test.go @@ -7127,20 +7127,9 @@ func testMultiHopRemoteForceCloseOnChainHtlcTimeout(net *lntest.NetworkHarness, nodes = []*lntest.HarnessNode{net.Alice} err = lntest.WaitPredicate(func() bool { return assertNumActiveHtlcs(nodes, 0) - }, time.Second*8) + }, time.Second*15) if err != nil { - // It may be the case that due to a race, Bob's sweeping - // transaction hasn't yet been confirmed, so we'll mine another - // block to nudge it in. If after this it still Alice will has - // an HTLC, then it's actually a test failure. - if _, err := net.Miner.Node.Generate(1); err != nil { - t.Fatalf("unable to generate block: %v", err) - } - if err = lntest.WaitPredicate(func() bool { - return assertNumActiveHtlcs(nodes, 0) - }, time.Second*8); err != nil { - t.Fatalf("alice's channel still has active htlc's") - } + t.Fatalf("alice's channel still has active htlc's") } // Now we'll check Bob's pending channel report. Since this was Carol's