Skip to content

neutrino node loses connection to single btcd node #1060

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
weaklysubjective opened this issue Apr 9, 2018 · 8 comments
Closed

neutrino node loses connection to single btcd node #1060

weaklysubjective opened this issue Apr 9, 2018 · 8 comments

Comments

@weaklysubjective
Copy link

Background

LND Running on two separate iOS devices. One device peered with the other. Upon successful connect the connecting device opened a channel. Channel successfully opened, stayed on for 3 days. (channel / query routes details below). BTCD was shutdown for a day (yesterday). Both lnd instances were started up intermittently without btcd and neutrino connect ip was invalid (didn't pay attention to this due to some other ongoing testing)

LND won't startup and crashes. To the extent I can glean from the trace it appears an attempt is made to spend some output , even though no more than 5 blocks were mined on the 'simnet'
(CSV Delay is the usual 144 blocks and Total time lock is 7485 )

Your environment

  • two separate ios devices running their respective LND
  • remote btcd on simnet
  • lnd connected to btcd via neutrino
  • version of lnd
  • which operating system (uname -a on *Nix)
  • iOS 11.2.6
  • version of btcd, bitcoind, or other backend
  • btcd version 0.12.0-beta
  • any other relevant environment details

**Query Routes Response

Found routes [.Lnrpc_Route:

total_time_lock: 7485

total_amt: 2000

hops {

chan_id: 8217749906063360

chan_capacity: 142857

amt_to_forward: 2000

expiry: 7485

}

]**

Channel details

**channels = (

            {

        capacity = 142857;

        "chan_id" = 8217749906063360;

        "channel_point" = "4ca44c64e3823c7c2ce3e878eef8998e522887e5dbead63566f0aa9d7acd75dc:0";

        "commit_fee" = 9050;

        "commit_weight" = 600;

        "csv_delay" = 144;

        "fee_per_kw" = 12500;

        "local_balance" = 133807;

        "remote_pubkey" = 03d417911988ccbf6422863c77636f8fdaf4a687fdc677c2754bc4fea23f754ad2;

    }

);**

CRASH LOG (TRACE) (IP's replaced with xx.xx.xx.xx)

2018-04-09 18:40:31.164 [DBG] BTCN: Received version (agent /btcwire:0.5.0/btcd:0.12.0/, pver 70013, block 7476) from xx.xx.xx.xx:18555 (outbound)
2018-04-09 18:40:31.164 [TRC] BTCN: (*wire.MsgVersion)(0x1e42980d0)({
ProtocolVersion: (int32) 70013,
Services: (wire.ServiceFlag) SFNodeNetwork|SFNodeBloom|SFNodeWitness|SFNodeCF,
Timestamp: (time.Time) 2018-04-09 18:40:31 +0000 UTC,
AddrYou: (wire.NetAddress) {
Timestamp: (time.Time) 0001-01-01 00:00:00 +0000 UTC,
Services: (wire.ServiceFlag) SFNodeNetwork,
IP: (net.IP) (len=16 cap=16) xx.xx.xx.xx,
Port: (uint16) 49897
},
AddrMe: (wire.NetAddress) {
Timestamp: (time.Time) 0001-01-01 00:00:00 +0000 UTC,
Services: (wire.ServiceFlag) SFNodeNetwork|SFNodeBloom|SFNodeWitness|SFNodeCF,
IP: (net.IP) (len=16 cap=16) ::,
Port: (uint16) 0
},
Nonce: (uint64) 3266537728035451740,
UserAgent: (string) (len=27) "/btcwire:0.5.0/btcd:0.12.0/",
LastBlock: (int32) 7476,
DisableRelayTx: (bool) false
})

2018-04-09 18:40:31.165 [TRC] BTCN: ([]uint8) (len=113 cap=113) {
00000000 7d 11 01 00 4d 00 00 00 00 00 00 00 9f b3 cb 5a |}...M..........Z|
00000010 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 00 |................|
00000020 00 00 00 00 00 00 ff ff 47 cc 82 08 c2 e9 4d 00 |........G.....M.|
00000030 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
00000040 00 00 00 00 00 00 00 00 5c f3 f6 bc c1 12 55 2d |.............U-|
00000050 1b 2f 62 74 63 77 69 72 65 3a 30 2e 35 2e 30 2f |./btcwire:0.5.0/|
00000060 62 74 63 64 3a 30 2e 31 32 2e 30 2f 34 1d 00 00 |btcd:0.12.0/4...|
00000070 01 |.|
}

2018-04-09 18:40:31.165 [DBG] BTCN: Negotiated protocol version 70013 for peer xx.xx.xx.xx:18555 (outbound)
2018-04-09 18:40:31.165 [DBG] BTCN: Added time sample of 0s (total: 1)
2018-04-09 18:40:31.165 [DBG] BTCN: Connected to xx.xx.xx.xx:18555
2018-04-09 18:40:31.165 [INF] BTCN: New valid peer xx.xx.xx.xx:18555 (outbound) (/btcwire:0.5.0/btcd:0.12.0/)
2018-04-09 18:40:31.165 [WRN] BTCN: No sync peer candidates available
2018-04-09 18:40:31.165 [DBG] BTCN: Received verack from xx.xx.xx.xx:18555 (outbound)
2018-04-09 18:40:31.165 [TRC] BTCN: (*wire.MsgVerAck)(0x1065792a0)({
})

2018-04-09 18:40:31.165 [TRC] BTCN: ([]uint8) {
}

2018-04-09 18:40:31.165 [DBG] BTCN: Sending verack to xx.xx.xx.xx:18555 (outbound)
2018-04-09 18:40:31.166 [TRC] BTCN: (*wire.MsgVerAck)(0x1065792a0)({
})

2018-04-09 18:40:31.166 [TRC] BTCN: ([]uint8) (len=24 cap=64) {
00000000 16 1c 14 12 76 65 72 61 63 6b 00 00 00 00 00 00 |....verack......|
00000010 00 00 00 00 5d f6 e0 e2 |....]...|
}

2018-04-09 18:40:31.165 [DBG] BTCN: New peer xx.xx.xx.xx:18555 (outbound)
2018-04-09 18:40:32.070 [INF] LNWL: Opened wallet
2018-04-09 18:40:33.103 [INF] LNWL: The wallet has been unlocked without a time limit
2018-04-09 18:40:33.103 [INF] LTND: LightningWallet opened
2018-04-09 18:40:33.107 [INF] LNWL: Started rescan from block 75266f292708056dbf9d9d0ab80cccc8b645ac1bca2a44e038ac7890335248c0 (height 7479) for 51 addresses
2018-04-09 18:40:33.107 [TRC] BTCN: Starting rescan from known block 7479 (75266f292708056dbf9d9d0ab80cccc8b645ac1bca2a44e038ac7890335248c0)
2018-04-09 18:40:33.107 [TRC] BTCN: Rescan became current at 7479 (75266f292708056dbf9d9d0ab80cccc8b645ac1bca2a44e038ac7890335248c0), subscribing to block notifications
2018-04-09 18:40:33.107 [INF] LNWL: Catching up block hashes to height 7479, this might take a while
2018-04-09 18:40:33.107 [TRC] BTCN: Starting rescan from known block 7479 (75266f292708056dbf9d9d0ab80cccc8b645ac1bca2a44e038ac7890335248c0)
2018-04-09 18:40:33.107 [TRC] BTCN: Rescan became current at 7479 (75266f292708056dbf9d9d0ab80cccc8b645ac1bca2a44e038ac7890335248c0), subscribing to block notifications
2018-04-09 18:40:33.111 [INF] HSWC: Restoring in-memory circuit state from disk
2018-04-09 18:40:33.111 [INF] LNWL: Done catching up block hashes
2018-04-09 18:40:33.111 [INF] LNWL: Finished rescan for 51 addresses (synced to block 75266f292708056dbf9d9d0ab80cccc8b645ac1bca2a44e038ac7890335248c0, height 7479)
2018-04-09 18:40:33.111 [INF] HSWC: Payment circuits loaded: num_pending=0, num_open=0
2018-04-09 18:40:33.120 [INF] HSWC: Trimming open circuits for chan_id=7474:1:0, start_htlc_id=0
2018-04-09 18:40:33.126 [TRC] FNDG: Funding manager running
2018-04-09 18:40:33.135 [TRC] FNDG: Loading pending ChannelPoint(0e22d67a090d02cc7cc40e7be58a585426e854c3594503bf6b5315c87532f774:0), creating chan barrier
2018-04-09 18:40:57.117 [DBG] LNWL: Resent unmined transaction 1d64950c96cde03906f572b2c42cf5b7a5a1bd458d78cd54a2d8648eecf0de9a
2018-04-09 18:40:57.152 [TRC] FNDG: Loading pending ChannelPoint(b0325de9919bb2849f8f24f5695c9fe6de14b7e37c8547f81d32b8cdaa4a4ff7:0), creating chan barrier
2018-04-09 18:41:09.120 [DBG] LNWL: Resent unmined transaction b0325de9919bb2849f8f24f5695c9fe6de14b7e37c8547f81d32b8cdaa4a4ff7
2018-04-09 18:41:09.256 [DBG] FNDG: channel (dc75cd7a9daaf06635d6eadbe58728528e99f8ee78e8e32c7c3c82e3644ca44c) with opening state 2 found
2018-04-09 18:41:09.257 [DBG] FNDG: Will announce channel 8217749906063360 after ChannelPoint(b0325de9919bb2849f8f24f5695c9fe6de14b7e37c8547f81d32b8cdaa4a4ff7:0) has gotten 6 confirmations
2018-04-09 18:41:09.260 [INF] RPCS: RPC server listening on 127.0.0.1:10009
2018-04-09 18:41:09.264 [TRC] BTCN: Starting rescan from known block 7479 (75266f292708056dbf9d9d0ab80cccc8b645ac1bca2a44e038ac7890335248c0)
2018-04-09 18:41:09.265 [TRC] BTCN: Rescan became current at 7479 (75266f292708056dbf9d9d0ab80cccc8b645ac1bca2a44e038ac7890335248c0), subscribing to block notifications
2018-04-09 18:41:09.265 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080
2018-04-09 18:41:09.266 [INF] NTFN: New block epoch subscription
2018-04-09 18:41:09.266 [INF] NTFN: New block epoch subscription
2018-04-09 18:41:09.266 [INF] NTFN: New block epoch subscription
2018-04-09 18:41:09.266 [INF] NTFN: New confirmations subscription: txid=b0325de9919bb2849f8f24f5695c9fe6de14b7e37c8547f81d32b8cdaa4a4ff7, numconfs=6, height_hint=7476
2018-04-09 18:41:09.267 [INF] FNDG: Waiting for funding tx (0e22d67a090d02cc7cc40e7be58a585426e854c3594503bf6b5315c87532f774) to reach 3 confirmations
2018-04-09 18:41:09.267 [INF] NTFN: New confirmations subscription: txid=0e22d67a090d02cc7cc40e7be58a585426e854c3594503bf6b5315c87532f774, numconfs=3, height_hint=7067
2018-04-09 18:41:09.292 [INF] NTFN: New confirmations subscription: txid=1d64950c96cde03906f572b2c42cf5b7a5a1bd458d78cd54a2d8648eecf0de9a, numconfs=3, height_hint=7476
2018-04-09 18:41:09.292 [INF] FNDG: Waiting for funding tx (1d64950c96cde03906f572b2c42cf5b7a5a1bd458d78cd54a2d8648eecf0de9a) to reach 3 confirmations
2018-04-09 18:41:09.293 [INF] NTFN: New confirmations subscription: txid=b0325de9919bb2849f8f24f5695c9fe6de14b7e37c8547f81d32b8cdaa4a4ff7, numconfs=3, height_hint=7476
2018-04-09 18:41:09.293 [INF] FNDG: Waiting for funding tx (b0325de9919bb2849f8f24f5695c9fe6de14b7e37c8547f81d32b8cdaa4a4ff7) to reach 3 confirmations
2018-04-09 18:41:09.294 [INF] NTFN: New block epoch subscription
2018-04-09 18:41:09.294 [INF] HSWC: Starting HTLC Switch
2018-04-09 18:41:09.336 [TRC] UTXN: Starting UTXO nursery
2018-04-09 18:41:09.337 [INF] NTFN: New block epoch subscription
2018-04-09 18:41:09.337 [TRC] CNCT: Starting ChainArbitrator
2018-04-09 18:41:09.372 [INF] CNCT: Creating ChannelArbitrators for 4 active channels
2018-04-09 18:41:09.372 [DBG] CNCT: New ChainEventSubscription(id=0) for ChannelPoint(0e22d67a090d02cc7cc40e7be58a585426e854c3594503bf6b5315c87532f774:0)
2018-04-09 18:41:09.372 [TRC] CNCT: Creating ChannelArbitrator for ChannelPoint(0e22d67a090d02cc7cc40e7be58a585426e854c3594503bf6b5315c87532f774:0)
2018-04-09 18:41:09.372 [DBG] CNCT: New ChainEventSubscription(id=0) for ChannelPoint(1d64950c96cde03906f572b2c42cf5b7a5a1bd458d78cd54a2d8648eecf0de9a:0)
2018-04-09 18:41:09.373 [TRC] CNCT: Creating ChannelArbitrator for ChannelPoint(1d64950c96cde03906f572b2c42cf5b7a5a1bd458d78cd54a2d8648eecf0de9a:0)
2018-04-09 18:41:09.372 [INF] NTFN: New block epoch subscription
2018-04-09 18:41:09.373 [INF] NTFN: New block epoch subscription
2018-04-09 18:41:09.373 [DBG] CNCT: New ChainEventSubscription(id=0) for ChannelPoint(4ca44c64e3823c7c2ce3e878eef8998e522887e5dbead63566f0aa9d7acd75dc:0)
2018-04-09 18:41:09.373 [TRC] CNCT: Creating ChannelArbitrator for ChannelPoint(4ca44c64e3823c7c2ce3e878eef8998e522887e5dbead63566f0aa9d7acd75dc:0)
2018-04-09 18:41:09.373 [DBG] CNCT: New ChainEventSubscription(id=0) for ChannelPoint(b0325de9919bb2849f8f24f5695c9fe6de14b7e37c8547f81d32b8cdaa4a4ff7:0)
2018-04-09 18:41:09.373 [TRC] CNCT: Creating ChannelArbitrator for ChannelPoint(b0325de9919bb2849f8f24f5695c9fe6de14b7e37c8547f81d32b8cdaa4a4ff7:0)
2018-04-09 18:41:09.373 [INF] NTFN: New block epoch subscription
2018-04-09 18:41:09.374 [INF] NTFN: New block epoch subscription
2018-04-09 18:41:09.374 [DBG] CNCT: Starting chain watcher for ChannelPoint(0e22d67a090d02cc7cc40e7be58a585426e854c3594503bf6b5315c87532f774:0)
2018-04-09 18:41:09.374 [INF] NTFN: New spend notification for outpoint=0e22d67a090d02cc7cc40e7be58a585426e854c3594503bf6b5315c87532f774:0, height_hint=7067
2018-04-09 18:41:09.374 [TRC] BTCN: Starting scan for output spend from known block 7479 (75266f292708056dbf9d9d0ab80cccc8b645ac1bca2a44e038ac7890335248c0) back to block 7067 (28923b6e4ce549dae1ed7f32722a93744c2bc7e5d0f0af0da71f89cd7c7c4a97)
2018-04-09 18:41:09.386 [DBG] CNCT: Starting chain watcher for ChannelPoint(1d64950c96cde03906f572b2c42cf5b7a5a1bd458d78cd54a2d8648eecf0de9a:0)
2018-04-09 18:41:09.386 [INF] NTFN: New spend notification for outpoint=1d64950c96cde03906f572b2c42cf5b7a5a1bd458d78cd54a2d8648eecf0de9a:0, height_hint=7476
2018-04-09 18:41:09.386 [TRC] BTCN: Starting scan for output spend from known block 7479 (75266f292708056dbf9d9d0ab80cccc8b645ac1bca2a44e038ac7890335248c0) back to block 7476 (66d733e198f4c9699002681fa10edb233afbfdcacafbc7c026b677d0abcb3bbe)
2018-04-09 18:41:09.386 [INF] NTFN: New spend subscription: utxo=0e22d67a090d02cc7cc40e7be58a585426e854c3594503bf6b5315c87532f774:0, height_hint=7067
2018-04-09 18:41:09.387 [INF] NTFN: New spend subscription: utxo=1d64950c96cde03906f572b2c42cf5b7a5a1bd458d78cd54a2d8648eecf0de9a:0, height_hint=7476
2018-04-09 18:41:09.387 [DBG] CNCT: Starting chain watcher for ChannelPoint(4ca44c64e3823c7c2ce3e878eef8998e522887e5dbead63566f0aa9d7acd75dc:0)
2018-04-09 18:41:09.387 [INF] NTFN: New spend notification for outpoint=4ca44c64e3823c7c2ce3e878eef8998e522887e5dbead63566f0aa9d7acd75dc:0, height_hint=7474
2018-04-09 18:41:09.387 [TRC] BTCN: Starting scan for output spend from known block 7479 (75266f292708056dbf9d9d0ab80cccc8b645ac1bca2a44e038ac7890335248c0) back to block 7474 (50cc126872a8a361fa64a48cf25acecb3f73fa8917b50de77e4db1e9cdf55d41)
2018-04-09 18:41:09.386 [INF] CNCT: Close observer for ChannelPoint(0e22d67a090d02cc7cc40e7be58a585426e854c3594503bf6b5315c87532f774:0) active
2018-04-09 18:41:09.387 [INF] CNCT: Close observer for ChannelPoint(1d64950c96cde03906f572b2c42cf5b7a5a1bd458d78cd54a2d8648eecf0de9a:0) active
2018-04-09 18:41:21.388 [ERR] SRVR: unable to start server: Couldn't retrieve block 50cc126872a8a361fa64a48cf25acecb3f73fa8917b50de77e4db1e9cdf55d41 from network

Couldn't retrieve block 50cc126872a8a361fa64a48cf25acecb3f73fa8917b50de77e4db1e9cdf55d41 from network

Steps to reproduce

Realize this may be hard to reproduce as the env is iOS. Happy to provide further details if possible.

Expected behaviour

Not sure ....makes sense that LND stops if the block hash is not in the neutrino bucket ..Thinking this might be a 'neutrino' issue ?

Once fixed or worked around , hope is that LND will not crash

Actual behaviour

LND Crashes
@Roasbeef
Copy link
Member

Roasbeef commented Apr 9, 2018 

2018-04-09 18:41:09.387 [INF] CNCT: Close observer for ChannelPoint(1d64950c96cde03906f572b2c42cf5b7a5a1bd458d78cd54a2d8648eecf0de9a:0) active
2018-04-09 18:41:21.388 [ERR] SRVR: unable to start server: Couldn't retrieve block 50cc126872a8a361fa64a48cf25acecb3f73fa8917b50de77e4db1e9cdf55d41 from network

Check the connection to your btcd node? I'm not sure this is an lnd issue, but may be an issue with your set up.

@weaklysubjective
Copy link
Author

I tend to agree with you , that it may not be lnd. I will mine a few blocks and see if anything changes. But to answer your q - peer connects , and loses connection immediately following the crash

2018-04-09 18:40:31.149 [INF] BMGR: New valid peer xx.xx.xx.xx:49897 (inbound) (/btcwire:0.5.0/neutrino:0.0.1-alpha/)
2018-04-09 18:41:21.439 [INF] BMGR: Lost peer xx.xx.xx.xx:49897 (inbound)

@Roasbeef
Copy link
Member

Roasbeef commented Apr 9, 2018

But to answer your q - peer connects , and loses connection immediately following the crash

You only had a single peer. That peer disconnected, so it wasn't able to get the block.

@Roasbeef Roasbeef changed the title Lnd crash neutrino node loses connection to single btcd node Apr 9, 2018
@weaklysubjective
Copy link
Author

so for a few days , even though the remote peer wasn't online, the channel was still open and lnd started without issue.
When you say disconnected , is there a way to know when it disconnected ? What happens to the open channel ?

@weaklysubjective
Copy link
Author

To ask the q another way, would the outcome be different if it were connected to multiple peers , still on a single node simnet ?

@Roasbeef
Copy link
Member

Roasbeef commented Apr 9, 2018

would the outcome be different if it were connected to multiple peers , still on a single node simnet ?

Yes. It would have multiple peers to connect to.

@Roasbeef
Copy link
Member

Roasbeef commented Apr 9, 2018

It isn't a crash, the node tried to restart, but didn't have any nodes to connect to, so it actually can't do anything.

@weaklysubjective
Copy link
Author

its slowly sinking in - that in this experiment, the iOS node was trying to be an "island" in a world of peer-to-peer
To sum up my understanding

  1. If the iOS node had connected to other peers, those peers would have known of the block in question ?
  2. Perhaps a segue to ask for an improvement - a polling RPC call to inform of the status of LND i.e. starting, ending , so that a client app could act on those events. At present it knows LND started only based on say a getinfo polling or some such.

@Roasbeef thank you for the discussion ...appreciate your thoughts on #1/#2 ..
I'll close out the ticket if you feel there is nothing more to be said here.

@Roasbeef Roasbeef closed this as completed Apr 9, 2018
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@Roasbeef @weaklysubjective