search

lightningnetwork / lnd

Lightning Network Daemon ⚡️
MIT License
7.73k stars 2.09k forks source link

Stuck "pending_force_closing_channels" #2276

Closed kornpow closed 5 years ago

kornpow commented 5 years ago

Background

I am having trouble getting back access to funds that were in a channel. I did not close the channel myself, I came back to my node to find my channel in this state.

Your environment

Steps to reproduce

pendingchannels { "total_limbo_balance": "0", "pending_open_channels": [ ], "pending_closing_channels": [ ], "pending_force_closing_channels": [ { "channel": { "remote_node_pub": "02f24b1e34fd87719377d6aa74864988e23d7b0c80dc6a631f7afd3979fb09949e", "channel_point": "ce46a3ccbc04bf5bd39ba20db5604f26cc297637b9b18ab933242bb30ca19905:1", "capacity": "75000", "local_balance": "73072", "remote_balance": "0" }, "closing_txid": "fdd8f64efaf5d553bec681597d72bae6784265d18abcbd6ff9c490c1df4e613d", "limbo_balance": "0", "maturity_height": 0, "blocks_til_maturity": 0, "recovered_balance": "0", "pending_htlcs": [ ] } ], "waiting_close_channels": [ ] }

lnd.log Attempting automatic RPC configuration to bitcoind Automatically obtained bitcoind's RPC credentials 2018-12-04 21:14:58.103 [INF] LTND: Version: 0.5.1-beta commit=, build=production, logging=default 2018-12-04 21:14:58.103 [INF] LTND: Active chain: Bitcoin (network=mainnet) 2018-12-04 21:14:58.103 [INF] CHDB: Checking for schema update: latest_version=7, db_version=7 2018-12-04 21:14:58.114 [INF] RPCS: password gRPC proxy started at 127.0.0.1:8080 2018-12-04 21:14:58.115 [INF] RPCS: password RPC server listening on 127.0.0.1:10009 2018-12-04 21:14:58.115 [INF] LTND: Waiting for wallet encryption password. Uselncli createto create a wallet,lncli unlockto unlock an existing wallet, orlncli changepasswordto change the password of an existing wallet and unlock it. 2018-12-04 21:15:07.404 [INF] LNWL: Opened wallet 2018-12-04 21:15:07.502 [INF] LTND: Primary chain is set to: bitcoin 2018-12-04 21:15:07.547 [INF] LTND: Initializing bitcoind backed fee estimator 2018-12-04 21:15:07.547 [INF] LNWL: Started listening for bitcoind block notifications via ZMQ on tcp://127.0.0.1:28332 2018-12-04 21:15:07.547 [INF] LNWL: Started listening for bitcoind transaction notifications via ZMQ on tcp://127.0.0.1:28333 2018-12-04 21:15:08.418 [INF] LNWL: The wallet has been unlocked without a time limit 2018-12-04 21:15:08.420 [INF] LTND: LightningWallet opened 2018-12-04 21:15:08.510 [INF] HSWC: Restoring in-memory circuit state from disk 2018-12-04 21:15:08.513 [INF] LNWL: Started rescan from block 000000000000000000249c2d8927de641d0b35915cb77f9645cbd1347a367296 (height 552585) for 20 addresses 2018-12-04 21:15:08.514 [INF] LNWL: Starting rescan from block 000000000000000000249c2d8927de641d0b35915cb77f9645cbd1347a367296 2018-12-04 21:15:08.518 [INF] LNWL: Rescan finished at 552585 (000000000000000000249c2d8927de641d0b35915cb77f9645cbd1347a367296) 2018-12-04 21:15:08.518 [INF] LNWL: Catching up block hashes to height 552585, this might take a while 2018-12-04 21:15:08.573 [INF] HSWC: Payment circuits loaded: num_pending=1, num_open=1 2018-12-04 21:15:08.577 [INF] HSWC: Trimming open circuits for chan_id=551807:348:1, start_htlc_id=0 2018-12-04 21:15:08.577 [INF] HSWC: Trimming open circuits for chan_id=551807:353:1, start_htlc_id=0 2018-12-04 21:15:08.577 [INF] HSWC: Trimming open circuits for chan_id=552057:2251:1, start_htlc_id=0 2018-12-04 21:15:08.577 [INF] HSWC: Trimming open circuits for chan_id=551807:351:1, start_htlc_id=0 2018-12-04 21:15:08.577 [INF] HSWC: Trimming open circuits for chan_id=551807:347:1, start_htlc_id=0 2018-12-04 21:15:08.577 [INF] HSWC: Trimming open circuits for chan_id=552054:955:0, start_htlc_id=0 2018-12-04 21:15:08.591 [INF] LNWL: Done catching up block hashes 2018-12-04 21:15:08.591 [INF] LNWL: Finished rescan for 20 addresses (synced to block 000000000000000000249c2d8927de641d0b35915cb77f9645cbd1347a367296, height 552585) 2018-12-04 21:15:08.631 [INF] SRVR: Scanning local network for a UPnP enabled device 2018-12-04 21:15:12.899 [INF] SRVR: Automatically set up port forwarding using UPnP to advertise external IP 2018-12-04 21:15:13.025 [INF] RPCS: RPC server listening on 127.0.0.1:10009 2018-12-04 21:15:13.025 [INF] RPCS: gRPC proxy started at 127.0.0.1:8080 2018-12-04 21:15:13.028 [INF] LTND: Waiting for chain backend to finish sync, start_height=552585 2018-12-04 21:15:13.033 [INF] LTND: Chain backend is fully synced (end_height=552585)! 2018-12-04 21:15:13.051 [INF] HSWC: Starting HTLC Switch 2018-12-04 21:15:13.051 [INF] NTFN: New block epoch subscription 2018-12-04 21:15:13.051 [INF] NTFN: New block epoch subscription 2018-12-04 21:15:13.302 [INF] NTFN: New block epoch subscription 2018-12-04 21:15:13.325 [INF] CNCT: Creating ChannelArbitrators for 6 active channels 2018-12-04 21:15:13.325 [INF] NTFN: New block epoch subscription 2018-12-04 21:15:13.325 [INF] NTFN: New block epoch subscription 2018-12-04 21:15:13.325 [INF] NTFN: New block epoch subscription 2018-12-04 21:15:13.325 [INF] NTFN: New block epoch subscription 2018-12-04 21:15:13.325 [INF] NTFN: New block epoch subscription 2018-12-04 21:15:13.325 [INF] NTFN: New block epoch subscription 2018-12-04 21:15:13.327 [INF] CNCT: Creating ChannelArbitrators for 1 closing channels 2018-12-04 21:15:13.327 [INF] NTFN: New block epoch subscription 2018-12-04 21:15:13.327 [INF] NTFN: New spend subscription: spend_id=1, outpoint=eade3780e51fd1abd794a3015ca3a6c063a75945c26cb7b710125ee003d79c9a:1, height_hint=551807 2018-12-04 21:15:13.327 [INF] NTFN: New spend subscription: spend_id=6, outpoint=7492797abb29358a72f78f66bb6da601fbc638e1f7b617c951dc6018e6930331:0, height_hint=552054 2018-12-04 21:15:13.327 [INF] NTFN: New spend subscription: spend_id=4, outpoint=24f45480a62c51785ec8109cee32ab9ac5073f9b7989fb314e3207bb068e8032:1, height_hint=551807 2018-12-04 21:15:13.327 [INF] NTFN: New spend subscription: spend_id=3, outpoint=62f4b3a346dfdd78c057ee778bf5466de6af532ee9c3e9f9c6b21baf6102dfa6:1, height_hint=552057 2018-12-04 21:15:13.327 [INF] NTFN: New spend subscription: spend_id=5, outpoint=19715bfd530eb4988cdaef531ecc571e1050e7b97b8fc2065bca399b44722960:1, height_hint=551807 2018-12-04 21:15:13.327 [INF] NTFN: New spend subscription: spend_id=2, outpoint=5dda2cca7829d0065235aef197346c2cb5ceec180453dfa79fb33c884abdffb7:1, height_hint=551807 2018-12-04 21:15:13.413 [INF] CNCT: Close observer for ChannelPoint(eade3780e51fd1abd794a3015ca3a6c063a75945c26cb7b710125ee003d79c9a:1) active 2018-12-04 21:15:13.479 [INF] CNCT: Close observer for ChannelPoint(62f4b3a346dfdd78c057ee778bf5466de6af532ee9c3e9f9c6b21baf6102dfa6:1) active 2018-12-04 21:15:13.557 [INF] CNCT: Close observer for ChannelPoint(19715bfd530eb4988cdaef531ecc571e1050e7b97b8fc2065bca399b44722960:1) active 2018-12-04 21:15:13.623 [INF] CNCT: Close observer for ChannelPoint(7492797abb29358a72f78f66bb6da601fbc638e1f7b617c951dc6018e6930331:0) active 2018-12-04 21:15:13.701 [INF] CNCT: Close observer for ChannelPoint(24f45480a62c51785ec8109cee32ab9ac5073f9b7989fb314e3207bb068e8032:1) active 2018-12-04 21:15:13.768 [INF] CNCT: Close observer for ChannelPoint(5dda2cca7829d0065235aef197346c2cb5ceec180453dfa79fb33c884abdffb7:1) active 2018-12-04 21:15:13.768 [INF] CNCT: ChannelArbitrator(24f45480a62c51785ec8109cee32ab9ac5073f9b7989fb314e3207bb068e8032:1): starting state=StateDefault 2018-12-04 21:15:13.770 [INF] CNCT: ChannelArbitrator(62f4b3a346dfdd78c057ee778bf5466de6af532ee9c3e9f9c6b21baf6102dfa6:1): starting state=StateDefault 2018-12-04 21:15:13.772 [INF] CNCT: ChannelArbitrator(5dda2cca7829d0065235aef197346c2cb5ceec180453dfa79fb33c884abdffb7:1): starting state=StateDefault 2018-12-04 21:15:13.774 [INF] CNCT: ChannelArbitrator(19715bfd530eb4988cdaef531ecc571e1050e7b97b8fc2065bca399b44722960:1): starting state=StateDefault 2018-12-04 21:15:13.775 [INF] CNCT: ChannelArbitrator(7492797abb29358a72f78f66bb6da601fbc638e1f7b617c951dc6018e6930331:0): starting state=StateDefault 2018-12-04 21:15:13.777 [INF] CNCT: ChannelArbitrator(ce46a3ccbc04bf5bd39ba20db5604f26cc297637b9b18ab933242bb30ca19905:1): starting state=StateWaitingFullResolution 2018-12-04 21:15:13.778 [INF] CNCT: ChannelArbitrator(ce46a3ccbc04bf5bd39ba20db5604f26cc297637b9b18ab933242bb30ca19905:1): still awaiting contract resolution 2018-12-04 21:15:13.778 [INF] CNCT: ChannelArbitrator(ce46a3ccbc04bf5bd39ba20db5604f26cc297637b9b18ab933242bb30ca19905:1): relaunching 1 contract resolvers 2018-12-04 21:15:13.778 [INF] CNCT: ChannelArbitrator(eade3780e51fd1abd794a3015ca3a6c063a75945c26cb7b710125ee003d79c9a:1): starting state=StateDefault 2018-12-04 21:15:13.778 [INF] NTFN: New confirmation subscription: txid=fdd8f64efaf5d553bec681597d72bae6784265d18abcbd6ff9c490c1df4e613d, numconfs=1 2018-12-04 21:15:13.783 [INF] DISC: Authenticated Gossiper is starting 2018-12-04 21:15:13.783 [INF] NTFN: New block epoch subscription 2018-12-04 21:15:13.783 [INF] BRAR: Starting contract observer, watching for breaches. 2018-12-04 21:15:13.802 [INF] CRTR: FilteredChainView starting 2018-12-04 21:15:13.857 [INF] CRTR: Filtering chain using 12406 channels active 2018-12-04 21:15:13.858 [INF] CRTR: Prune tip for Channel Graph: height=552585, hash=000000000000000000249c2d8927de641d0b35915cb77f9645cbd1347a367296 2018-12-04 21:15:13.867 [INF] NTFN: Dispatching 1 conf notification for fdd8f64efaf5d553bec681597d72bae6784265d18abcbd6ff9c490c1df4e613d 2018-12-04 21:15:13.930 [INF] SWPR: Creating sweep transaction for 1 inputs (0 CSV, 0 CLTV) using 3557 sat/kw 2018-12-04 21:15:13.930 [ERR] CNCT: ChannelArbitrator(ce46a3ccbc04bf5bd39ba20db5604f26cc297637b9b18ab933242bb30ca19905:1): unable to progress resolver: account 3 not found 2018-12-04 21:15:13.966 [INF] CMGR: Server listening on [::]:9735 2018-12-04 21:15:14.001 [INF] SRVR: Initializing peer network bootstrappers! 2018-12-04 21:15:14.001 [INF] SRVR: Creating DNS peer bootstrapper with seeds: [[nodes.lightning.directory soa.nodes.lightning.directory]] 2018-12-04 21:15:14.002 [INF] DISC: Attempting to bootstrap with: Authenticated Channel Graph 2018-12-04 21:15:14.004 [INF] DISC: Obtained 3 addrs to bootstrap network with 2018-12-04 21:15:14.035 [INF] SRVR: Established connection to: 213.174.156.78:9735 2018-12-04 21:15:14.035 [INF] SRVR: Finalizing connection to 022755c3ff4e5a1d71f573cda4b315887fc00a9e5c9ea9a847d939f3e517e69a70, inbound=false 2018-12-04 21:15:14.037 [INF] SRVR: Established connection to: 213.174.156.76:9735 2018-12-04 21:15:14.037 [INF] SRVR: Finalizing connection to 039edc94987c8f3adc28dab455efc00dea876089a120f573bd0b03c40d9d3fb1e1, inbound=false 2018-12-04 21:15:14.044 [INF] SRVR: Established connection to: 46.229.165.142:9735 2018-12-04 21:15:14.044 [INF] SRVR: Finalizing connection to 03da1c27ca77872ac5b3e568af30673e599a47a5e4497f85c7b5da42048807b3ed, inbound=false 2018-12-04 21:15:14.062 [INF] PEER: NodeKey(022755c3ff4e5a1d71f573cda4b315887fc00a9e5c9ea9a847d939f3e517e69a70) loading ChannelPoint(eade3780e51fd1abd794a3015ca3a6c063a75945c26cb7b710125ee003d79c9a:1) 2018-12-04 21:15:14.063 [INF] HSWC: Removing channel link with ChannelID(9a9cd703e05e1210b7b76cc24559a763c0a6a35c01a394d7abd11fe58037deeb) 2018-12-04 21:15:14.063 [INF] HSWC: ChannelLink(eade3780e51fd1abd794a3015ca3a6c063a75945c26cb7b710125ee003d79c9a:1) is starting 2018-12-04 21:15:14.063 [INF] PEER: NodeKey(039edc94987c8f3adc28dab455efc00dea876089a120f573bd0b03c40d9d3fb1e1) loading ChannelPoint(5dda2cca7829d0065235aef197346c2cb5ceec180453dfa79fb33c884abdffb7:1) 2018-12-04 21:15:14.064 [INF] PEER: NodeKey(03da1c27ca77872ac5b3e568af30673e599a47a5e4497f85c7b5da42048807b3ed) loading ChannelPoint(19715bfd530eb4988cdaef531ecc571e1050e7b97b8fc2065bca399b44722960:1) 2018-12-04 21:15:14.064 [INF] HSWC: Trimming open circuits for chan_id=551807:348:1, start_htlc_id=0 2018-12-04 21:15:14.064 [INF] HSWC: Adding live link chan_id=9a9cd703e05e1210b7b76cc24559a763c0a6a35c01a394d7abd11fe58037deeb, short_chan_id=551807:348:1 2018-12-04 21:15:14.064 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(eade3780e51fd1abd794a3015ca3a6c063a75945c26cb7b710125ee003d79c9a:1) 2018-12-04 21:15:14.064 [INF] SRVR: Negotiated chan series queries with 022755c3ff4e5a1d71f573cda4b315887fc00a9e5c9ea9a847d939f3e517e69a70 2018-12-04 21:15:14.064 [INF] DISC: Creating new gossipSyncer for peer=022755c3ff4e5a1d71f573cda4b315887fc00a9e5c9ea9a847d939f3e517e69a70 2018-12-04 21:15:14.064 [INF] HSWC: HTLC manager for ChannelPoint(eade3780e51fd1abd794a3015ca3a6c063a75945c26cb7b710125ee003d79c9a:1) started, bandwidth=0 mSAT 2018-12-04 21:15:14.064 [INF] HSWC: Attempting to re-resynchronize ChannelPoint(eade3780e51fd1abd794a3015ca3a6c063a75945c26cb7b710125ee003d79c9a:1) 2018-12-04 21:15:14.064 [INF] DISC: gossipSyncer(022755c3ff4e5a1d71f573cda4b315887fc00a9e5c9ea9a847d939f3e517e69a70): requesting new chans from height=552436 and 4294414859 blocks after 2018-12-04 21:15:14.064 [INF] HSWC: Received re-establishment message from remote side for channel(eade3780e51fd1abd794a3015ca3a6c063a75945c26cb7b710125ee003d79c9a:1) 2018-12-04 21:15:14.064 [INF] DISC: gossipSyncer(022755c3ff4e5a1d71f573cda4b315887fc00a9e5c9ea9a847d939f3e517e69a70): filtering chan range: start_height=552436, num_blocks=4294414859 2018-12-04 21:15:14.064 [INF] DISC: gossipSyncer(022755c3ff4e5a1d71f573cda4b315887fc00a9e5c9ea9a847d939f3e517e69a70): sending final chan range chunk, size=172 2018-12-04 21:15:14.065 [INF] HSWC: Removing channel link with ChannelID(b7ffbd4a883cb39fa7df530418ecceb52c6c3497f1ae355206d02978ca2cda5c) 2018-12-04 21:15:14.065 [INF] HSWC: ChannelLink(5dda2cca7829d0065235aef197346c2cb5ceec180453dfa79fb33c884abdffb7:1) is starting 2018-12-04 21:15:14.065 [INF] HSWC: Trimming open circuits for chan_id=551807:351:1, start_htlc_id=0 2018-12-04 21:15:14.065 [INF] HSWC: Adding live link chan_id=b7ffbd4a883cb39fa7df530418ecceb52c6c3497f1ae355206d02978ca2cda5c, short_chan_id=551807:351:1 2018-12-04 21:15:14.065 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(5dda2cca7829d0065235aef197346c2cb5ceec180453dfa79fb33c884abdffb7:1) 2018-12-04 21:15:14.065 [INF] SRVR: Negotiated chan series queries with 039edc94987c8f3adc28dab455efc00dea876089a120f573bd0b03c40d9d3fb1e1 2018-12-04 21:15:14.065 [INF] DISC: Creating new gossipSyncer for peer=039edc94987c8f3adc28dab455efc00dea876089a120f573bd0b03c40d9d3fb1e1 2018-12-04 21:15:14.065 [INF] HSWC: HTLC manager for ChannelPoint(5dda2cca7829d0065235aef197346c2cb5ceec180453dfa79fb33c884abdffb7:1) started, bandwidth=0 mSAT 2018-12-04 21:15:14.065 [INF] HSWC: Attempting to re-resynchronize ChannelPoint(5dda2cca7829d0065235aef197346c2cb5ceec180453dfa79fb33c884abdffb7:1) 2018-12-04 21:15:14.065 [INF] HSWC: Received re-establishment message from remote side for channel(5dda2cca7829d0065235aef197346c2cb5ceec180453dfa79fb33c884abdffb7:1) 2018-12-04 21:15:14.065 [INF] DISC: gossipSyncer(039edc94987c8f3adc28dab455efc00dea876089a120f573bd0b03c40d9d3fb1e1): requesting new chans from height=552436 and 4294414859 blocks after 2018-12-04 21:15:14.065 [INF] DISC: gossipSyncer(039edc94987c8f3adc28dab455efc00dea876089a120f573bd0b03c40d9d3fb1e1): filtering chan range: start_height=552436, num_blocks=4294414859 2018-12-04 21:15:14.065 [INF] DISC: gossipSyncer(039edc94987c8f3adc28dab455efc00dea876089a120f573bd0b03c40d9d3fb1e1): sending final chan range chunk, size=172 2018-12-04 21:15:14.065 [INF] HSWC: Removing channel link with ChannelID(602972449b39ca5b06c28f7bb9e750101e57cc1e53efda8c98b40e53fd5b7118) 2018-12-04 21:15:14.065 [INF] HSWC: ChannelLink(19715bfd530eb4988cdaef531ecc571e1050e7b97b8fc2065bca399b44722960:1) is starting 2018-12-04 21:15:14.066 [INF] HSWC: Trimming open circuits for chan_id=551807:347:1, start_htlc_id=0 2018-12-04 21:15:14.066 [INF] HSWC: Adding live link chan_id=602972449b39ca5b06c28f7bb9e750101e57cc1e53efda8c98b40e53fd5b7118, short_chan_id=551807:347:1 2018-12-04 21:15:14.066 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(19715bfd530eb4988cdaef531ecc571e1050e7b97b8fc2065bca399b44722960:1)

Tell us how to reproduce this issue. Please provide stacktraces and links to code in question.

Expected behaviour

Once the channel has closed, and the transaction has been mined, funds should appear in my wallet, using walletbalance

Actual behaviour

I am just getting the stuck transaction in my pending channels list. From researching this issue, I haven't found anything like this for a number of months. Also the "maturity_height" is 0, and not negative like many others. Finally many of the other posts mention this persisting for months so I thought I'd create the issue. Let me know if I can help you obtain more info. Thanks

Roasbeef commented 5 years ago

lncli --network=mainnet unlock --recovery_window 10000

Just curious, why'd you manually set the recovery window?

Roasbeef commented 5 years ago

So this looks to be the issue:

12-04 21:15:13.930 [ERR] CNCT: ChannelArbitrator(ce46a3ccbc04bf5bd39ba20db5604f26cc297637b9b18ab933242bb30ca19905:1): unable to progress resolver: account 3 not found 2018-12-04 21:15:13.966

It's attempting to create an address, at the 3rd account for some reason, when we only ever use account 0.

Roasbeef commented 5 years ago

(This is the latest release, it doesnt say a commit hash?)

If you don't use make build, then the commit hash won't be specified.

kornpow commented 5 years ago

In an earlier install, when I knew slightly less about what I was doing, I deleted my wallet, so I recovered it with that command, I just tried --recovery_window again to see if it found the output in an address it didnt expect. Ill be around the computer all night in a bit, excited to some satoshis back so I can keep playing with lnd.

Roasbeef commented 5 years ago

deleted my wallet, so I recovered it with that command,

You deleted your wallet (WHICH YOU SHOULD NEVER DO!), then unlocked with a recovery window?

kornpow commented 5 years ago

I got it back super easily, because I wrote down my seed. What do you need me to do to change from account 3 to 0?

I used recovery window with initwallet, and also saw it was available for unlock

kornpow commented 5 years ago

I just want to put it out there that this "deleting of the wallet" thing was done before I actually was using channels, so while I imagine some (database) state was in there, all I cared about was the funds held in the wallet that I held a seed phrase for, so I went and got those back. (I was trying to help myself, but this all still isnt easy, yet)

The two biggest things that stick out to me, upgrading from 0.5.1RC to 0.5.1Beta, and I noticed this channel was forcibly closed also after the local ip of my node was changed (from 192.168.2.6 to 192.168.2.2) by my router.

Roasbeef commented 5 years ago

What do you need me to do to change from account 3 to 0?

To clarify, any address that we generate will always use account 0, but somehow it seems that your node is attempting to derive an address using account 3, which doesn't exist at this moment, since we never use it.

Roasbeef commented 5 years ago

Have you modified lnd in any way? Does running git diff in your source code directory display anything?

kornpow commented 5 years ago

I used a release, so I dont have a source directory. lnd is not modified in any way.

kornpow commented 5 years ago

So I continued using lnd. After a few times restarting with sudo systemctl stop lnd ; sudo systemctl start lnd and a week or so of time the pending channel was finally closed, and the funds went back to my wallet. In addition when I restarted I added

autopilot.active=1

so maybe that helped.