Lnd: Channel transitions back to pending after it is opened.

Created on 5 Nov 2019  路  19Comments  路  Source: lightningnetwork/lnd

Background

When a channel is opened from B to A and then a payment is received on A the channel is transitioned back to "pending" state while only restart brings it back to "open" state.

Your environment

*lnd 0.8.0 using neutrino.

Steps to reproduce

  1. Start a local LND node, let a remote node open a channel to the local node.
  2. When the channel is confirmed on-chain and marked open in the local node, create an invoice and receive a payment.

Expected behaviour

Channel should stay in "open" state.

Actual behaviour

Channel is transitioned to "pending" state as can be seen by lncli pendingchannels & lncli listchannels

Analysis:
The problem resides in updating old state (pending) to the database when updating the commitment transaction as a result of a payment.
When the channel is confirmed on-chain the fundingManager updates correctly the state to IsPending=false which is committed to the db here: https://github.com/lightningnetwork/lnd/blob/4592f870334d80d705d79febfac69e07ef653106/fundingmanager.go#L2059
A few lines later it reports back to the switch to load the new short channel id here: ReportShortChanID
The link indeed refreshes the short channel id: https://github.com/lightningnetwork/lnd/blob/cc159decf5ab967af4168ddb977d2a324bcc4b6c/channeldb/channel.go#L599 and transition the link to live link but the IsPending of the internal channel is not refreshed and stays true.
Later on when a payment is received the commitment is updated: https://github.com/lightningnetwork/lnd/blob/7ecb7136cfb1a62e6367a0cc1e4962c00c58477f/htlcswitch/link.go#L1774 saving the channel with the old state to the db making it pending again.

It looks like that at the time we refresh the short channel id (due to a funding tx confirmation) we should refresh the IsPending value as well.

P2 bug channels commitments funding
Source
picture roeierez

Most helpful comment

@Crypt-iQ I believe I finally found the missing piece.
The addLink is called also from https://github.com/lightningnetwork/lnd/blob/9710134f70338d0660476ce3497ea0b4bd2b3d1a/peer.go#L364
which is called on peer.Start.
I was able to repro this on mobile and I guess without noticing the peer was disconnected and connected while the channel was in pending state (very common on mobile when going to background).
This has made the link to be created with IsPending=true (same as on restart), which I just verified.
So I guess the scenario involves disconnecting/connecting to the peer (or restart).

picture roeierez on 6 Nov 2019
👍2

All 19 comments

With the steps you described, the issue doesn't happen. Only when you restart the local (or remote) node before confirmation. Then the link is added to the switch and has an old channel state.

Crypt-iQ picture Crypt-iQ on 6 Nov 2019

With the steps you described, the issue doesn't happen. Only when you restart the local (or remote) node before confirmation. Then the link is added to the switch and has an old channel state.

@Crypt-iQ The channel that is opened should be configured to require 1 confirmations. With this setting I consistently reproduce without restart.

roeierez picture roeierez on 6 Nov 2019

@roeierez I tried that it didn't reproduce the issue - only when I went up and down on either node so that the link was loaded with old channel data. Though it doesn't matter since I've seen the issue and your fix works :)

Crypt-iQ picture Crypt-iQ on 6 Nov 2019

@Crypt-iQ I went over the code again and indeed I see it is racy. The race is between the FundingManager.handleFundingConfirmation which is triggered by on-chain confirmation & the fundingMgr.processFundingLocked which is triggered by the peer.
In your case probably the the handleFundingConfirmation is executed first and results in the new state in the db before the later is executed and load the live link with the up to date state.
As you said I think for both cases (with/without restart) the fix is valid.
Thanks for the input, forced me to take another look.

roeierez picture roeierez on 6 Nov 2019

@roeierez It is possible for those two functions to race, but it is very unlikely. I say this because in the normal case, handleFundingLocked will always wait for the localDiscoverySignal to be closed by the handleFundingConfirmation function. Because of this, AddNewChannel in handleFundingLocked cannot be called with an old state. This makes me curious how you are able to trigger this bug and if maybe I am missing something (another race?).

I cannot trigger the race since it seems very unlikely to happen, but it seems to me that if handleFundingLocked is called while there is no localDiscoverySignal and at the same time either handleFundingCreated or handleFundingSigned sets up the localDiscoverySignal and then creates the channel in the database via SyncPending but before the handleFundingLocked call to FindChannel, it is possible for AddNewChannel to be called with a pending channel state. However, like I said, this is very unlikely but would result in the behavior you're describing.

Crypt-iQ picture Crypt-iQ on 6 Nov 2019

@Crypt-iQ what you say makes sense. I will repro again to be sure.

roeierez picture roeierez on 6 Nov 2019

@Crypt-iQ I believe I finally found the missing piece.
The addLink is called also from https://github.com/lightningnetwork/lnd/blob/9710134f70338d0660476ce3497ea0b4bd2b3d1a/peer.go#L364
which is called on peer.Start.
I was able to repro this on mobile and I guess without noticing the peer was disconnected and connected while the channel was in pending state (very common on mobile when going to background).
This has made the link to be created with IsPending=true (same as on restart), which I just verified.
So I guess the scenario involves disconnecting/connecting to the peer (or restart).

roeierez picture roeierez on 6 Nov 2019
👍2

Great thanks for checking up on this @roeierez , glad there wasn't another race :)

Crypt-iQ picture Crypt-iQ on 6 Nov 2019

One nasty side effect of this is if either node restarts after the buggy flow described above, then the fundingmanager for that node will see that the channel is pending and then setup a channel barrier which will prohibit any htlc forwarding through that channel. Great catch!

Crypt-iQ picture Crypt-iQ on 7 Nov 2019

I have now pending channel which was opened from my side (i was initiator)
Now the channel in "pending_open_channels" list and has balances which that indicates that there was payment(s). @wpaulino, Is it this case too (i have 0.8.0-beta version)? Here pendingchannels info logs:

    "pending_open_channels": [
        {
            "channel": {
                "remote_node_pub": "020f0d93c700cf5cf556e61828fab473a5c30ee6eb927ae36a130cc1c57326d21a",
                "channel_point": "954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1",
                "capacity": "14998000",
                "local_balance": "10686643",
                "remote_balance": "4307529",
                "local_chan_reserve_sat": "149980",
                "remote_chan_reserve_sat": "149980"
            },
            "confirmation_height": 0,
            "commit_fee": "3827",
            "commit_weight": "724",
            "fee_per_kw": "5286"
        },

And logs about this channel:

$ grep -E '954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08|602780:2054:1|30383766646665343831393366636361323831666532353863613039393163626565383630356533653031326430643666316238633863656263366634613934|766edc27837f5000fea1d07ec33be5aeb39c31c1d5d0f0e1a74080b08f44176b' ~/.lnd/mainnet-lnd-run.log 

2019-11-07 13:30:15.037 [INF] FNDG: Target commit tx sat/kw for pendingID(766edc27837f5000fea1d07ec33be5aeb39c31c1d5d0f0e1a74080b08f44176b): 6748
2019-11-07 13:30:15.037 [INF] FNDG: Starting funding workflow with 77.71.254.98:51419 for pendingID(766edc27837f5000fea1d07ec33be5aeb39c31c1d5d0f0e1a74080b08f44176b), tweakless=false
2019-11-07 13:30:15.690 [INF] FNDG: Recv'd fundingResponse for pendingID(766edc27837f5000fea1d07ec33be5aeb39c31c1d5d0f0e1a74080b08f44176b)
2019-11-07 13:30:15.707 [INF] FNDG: pendingChan(766edc27837f5000fea1d07ec33be5aeb39c31c1d5d0f0e1a74080b08f44176b): remote party proposes num_confs=5, csv_delay=1802
2019-11-07 13:30:15.707 [INF] FNDG: Generated ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1) for pendingID(766edc27837f5000fea1d07ec33be5aeb39c31c1d5d0f0e1a74080b08f44176b)
2019-11-07 13:30:15.918 [INF] FNDG: Broadcasting funding tx for ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): (*wire.MsgTx)(0xc0114c33c0)({
2019-11-07 13:30:15.919 [INF] LNWL: Inserting unconfirmed transaction 954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08
2019-11-07 13:30:15.930 [INF] CNCT: Creating new ChannelArbitrator for ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1)
2019-11-07 13:30:15.930 [INF] CNCT: ChannelArbitrator(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): starting state=StateDefault
2019-11-07 13:30:15.932 [INF] NTFN: New spend subscription: spend_id=438, outpoint=954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1, height_hint=602723
2019-11-07 13:30:15.954 [INF] FNDG: Finalizing pendingID(766edc27837f5000fea1d07ec33be5aeb39c31c1d5d0f0e1a74080b08f44176b) over ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1), waiting for channel open on-chain
2019-11-07 13:30:15.954 [INF] CNCT: Close observer for ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1) active
2019-11-07 13:30:15.954 [INF] NTFN: New confirmation subscription: conf_id=66, txid=954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08, num_confs=5 height_hint=602723
2019-11-07 13:30:15.954 [INF] FNDG: Waiting for funding tx (954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08) to reach 5 confirmations
2019-11-07 14:02:45.397 [INF] PEER: NodeKey(020f0d93c700cf5cf556e61828fab473a5c30ee6eb927ae36a130cc1c57326d21a) loading ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1)
2019-11-07 14:02:45.399 [WRN] PEER: Unable to find our forwarding policy for channel 954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1, using default values
2019-11-07 14:02:45.400 [INF] HSWC: ChannelLink(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1) is starting
2019-11-07 14:02:45.400 [INF] HSWC: HTLC manager for ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1) started, bandwidth=14843135000 mSAT
2019-11-07 14:02:45.400 [INF] HSWC: Attempting to re-resynchronize ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1)
2019-11-07 14:02:48.754 [INF] HSWC: Received re-establishment message from remote side for channel(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1)
2019-11-07 16:31:08.690 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 7445 sat/kw sat/kw
2019-11-07 16:43:23.715 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 7437 sat/kw sat/kw
2019-11-07 17:34:11.854 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 7447 sat/kw sat/kw
2019-11-07 17:44:21.628 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 7448 sat/kw sat/kw
2019-11-07 18:08:05.167 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 7448 sat/kw sat/kw
2019-11-07 18:48:57.621 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 7811 sat/kw sat/kw
2019-11-07 19:00:48.457 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 8104 sat/kw sat/kw
2019-11-07 19:50:32.400 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 8583 sat/kw sat/kw
2019-11-07 20:21:17.188 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 9014 sat/kw sat/kw
2019-11-07 20:43:37.374 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 9502 sat/kw sat/kw
2019-11-07 21:05:59.177 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 9502 sat/kw sat/kw
2019-11-07 21:45:23.076 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 9025 sat/kw sat/kw
2019-11-07 22:09:54.912 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 9026 sat/kw sat/kw
2019-11-07 22:47:43.638 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 9026 sat/kw sat/kw
2019-11-07 23:46:35.838 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 8600 sat/kw sat/kw
2019-11-07 23:59:57.087 [INF] LNWL: Marking unconfirmed transaction 954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08 mined in block 602780
2019-11-08 00:10:35.001 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 8114 sat/kw sat/kw
2019-11-08 00:30:45.285 [INF] NTFN: Dispatching 5 confirmation notification for txid=954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08
2019-11-08 00:30:45.285 [INF] FNDG: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1) is now active: ChannelID(30383766646665343831393366636361323831666532353863613039393163626565383630356533653031326430643666316238633863656263366634613934)
2019-11-08 00:30:45.314 [INF] HSWC: ChannelLink(0:0:0) Updating to short_chan_id=602780:2054:1 for chan_id=087fdfe48193fcca281fe258ca0991cbee8605e3e012d0d6f1b8c8cebc6f4a94
2019-11-08 00:30:45.315 [INF] HSWC: Updated short_chan_id for ChannelLink(087fdfe48193fcca281fe258ca0991cbee8605e3e012d0d6f1b8c8cebc6f4a94): old=0:0:0, new=602780:2054:1
2019-11-08 00:30:45.315 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1)
2019-11-08 00:30:45.532 [INF] NTFN: New confirmation subscription: conf_id=67, txid=954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08, num_confs=6 height_hint=602780
2019-11-08 00:30:48.986 [INF] PEER: Already have ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1), ignoring.
2019-11-08 00:30:48.986 [INF] PEER: Processing retransmitted FundingLocked for ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1)
2019-11-08 00:31:20.491 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 8116 sat/kw sat/kw
2019-11-08 00:54:14.790 [INF] NTFN: Dispatching 6 confirmation notification for txid=954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08
2019-11-08 00:54:14.790 [INF] FNDG: Announcing ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1), short_chan_id=602780:2054:1
2019-11-08 00:54:14.791 [INF] DISC: Received new local channel announcement for 602780:2054:1
2019-11-08 00:54:14.923 [INF] DISC: Received new remote channel announcement for 602780:2054:1
2019-11-08 08:56:50.519 [INF] HSWC: ChannelLink(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1) is stopping
2019-11-08 08:56:50.619 [INF] HSWC: ChannelLink(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1) has exited
2019-11-08 08:56:50.625 [INF] PEER: NodeKey(020f0d93c700cf5cf556e61828fab473a5c30ee6eb927ae36a130cc1c57326d21a) loading ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1)
2019-11-08 08:56:50.627 [INF] HSWC: ChannelLink(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1) is starting
2019-11-08 08:56:50.627 [INF] HSWC: Trimming open circuits for chan_id=602780:2054:1, start_htlc_id=0
2019-11-08 08:56:50.627 [INF] HSWC: Adding live link chan_id=087fdfe48193fcca281fe258ca0991cbee8605e3e012d0d6f1b8c8cebc6f4a94, short_chan_id=602780:2054:1
2019-11-08 08:56:50.627 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1)
2019-11-08 08:56:50.627 [INF] HSWC: HTLC manager for ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1) started, bandwidth=14842145000 mSAT
2019-11-08 08:56:50.627 [INF] HSWC: Attempting to re-resynchronize ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1)
2019-11-08 08:56:53.352 [INF] DISC: Received new remote channel announcement for 602780:2054:1
2019-11-08 08:56:53.352 [INF] HSWC: Received re-establishment message from remote side for channel(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1)
2019-11-08 11:43:47.139 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 0
2019-11-08 11:43:47.139 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 0
2019-11-08 12:05:11.805 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 1
2019-11-08 12:05:11.805 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 1
2019-11-08 12:10:37.323 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 2
2019-11-08 12:10:37.323 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 2
2019-11-08 13:56:20.861 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 3
2019-11-08 13:56:20.861 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 3
2019-11-08 16:32:36.225 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 4
2019-11-08 16:32:36.225 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 4
2019-11-08 16:33:20.051 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 5
2019-11-08 16:33:20.051 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 5
2019-11-08 16:33:56.932 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 6
2019-11-08 16:33:56.932 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 6
2019-11-08 16:34:30.870 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 7
2019-11-08 16:34:30.870 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 7
2019-11-08 16:40:04.168 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 8
2019-11-08 16:40:04.168 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 8
2019-11-08 16:41:01.144 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 9
2019-11-08 16:41:01.144 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 9
2019-11-08 20:49:37.551 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 18
2019-11-08 20:49:37.551 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 18
2019-11-08 23:44:23.620 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 22
2019-11-08 23:44:23.620 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 22
2019-11-09 00:41:06.085 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 9024 sat/kw sat/kw
2019-11-09 01:02:44.108 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 35
2019-11-09 01:02:44.108 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 35
2019-11-09 01:04:36.244 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 36
2019-11-09 01:04:36.245 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 36
2019-11-09 01:07:15.197 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 37
2019-11-09 01:07:15.197 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 37
2019-11-09 01:09:23.103 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 38
2019-11-09 01:09:23.104 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 38
2019-11-09 01:09:55.698 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 39
2019-11-09 01:09:55.699 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 39
2019-11-09 01:10:24.207 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 40
2019-11-09 01:10:24.207 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 40
2019-11-09 01:12:51.073 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 41
2019-11-09 01:12:51.073 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 41
2019-11-09 01:13:39.473 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 42
2019-11-09 01:13:39.473 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 42
2019-11-09 04:48:32.804 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 43
2019-11-09 04:48:32.804 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 43
2019-11-09 06:32:08.899 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 7815 sat/kw sat/kw
2019-11-09 09:06:14.575 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 8626 sat/kw sat/kw
2019-11-09 19:36:34.246 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 44
2019-11-09 19:36:34.246 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 44
2019-11-09 21:16:19.621 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 46
2019-11-09 21:16:19.621 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 46
2019-11-10 00:04:33.815 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 47
2019-11-10 00:04:33.815 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 47
2019-11-10 00:09:12.866 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 48
2019-11-10 00:09:12.866 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 48
2019-11-10 00:14:22.165 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 49
2019-11-10 00:14:22.165 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 49
2019-11-10 00:23:08.219 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 50
2019-11-10 00:23:08.220 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 50
2019-11-10 05:05:57.961 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 51
2019-11-10 05:05:57.961 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 51
2019-11-10 05:22:40.357 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 52
2019-11-10 05:22:40.358 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 52
2019-11-10 08:02:05.388 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 53
2019-11-10 08:02:05.388 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 53
2019-11-10 13:28:51.546 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 7452 sat/kw sat/kw
2019-11-10 22:32:18.913 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 57
2019-11-10 22:32:18.913 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 57
2019-11-10 23:51:53.573 [ERR] HSWC: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 58
2019-11-10 23:51:53.573 [ERR] HSWC: ChannelLink(602780:2054:1) unhandled error while forwarding htlc packet over htlcswitch: Unable to find target channel for HTLC settle/fail: channel ID = 602780:2054:1, HTLC ID = 58
2019-11-11 01:39:22.476 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 6453 sat/kw sat/kw
2019-11-11 09:04:39.766 [INF] HSWC: ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1): updating commit fee to 5286 sat/kw sat/kw

@wpaulino , what will happen with remote_balance? The channel as pending_open_channels and shuold not have any payments before. What will happen if the channel will be closed?

LNBIG-COM picture LNBIG-COM on 11 Nov 2019

@wpaulino , what will happen with remote_balance? The channel as pending_open_channels and shuold not have any payments before. What will happen if the channel will be closed?

$ l fwdinghistory --start_time 0 --max_events -1|grep 662763619125428225|wc -l
32

$ l fwdinghistory --start_time 0 --max_events -1|grep 662763619125428225
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",
            "chan_id_out": "662763619125428225",

Although I looked - 32 payments went to that channel.

LNBIG-COM picture LNBIG-COM on 11 Nov 2019

What is interesting - if i sum up all the amounts sent to the channel (from fwdinghistory) and compare with the balance of the remote side - i get a difference of 13 satoshi (all payments go out to that channel - i checked). This is normal? Perhaps this is due to rounding (millisatoshis -> satoshis)?

$ l fwdinghistory --start_time 0 --max_events -1|grep -A 2 662763619125428225|grep amt_out|sed -r -e 's/^.*"([0-9]+)".*/\1/'|awk 'BEGIN{sum=0}{sum += $1}END{print sum}'
4307516

4307516 vs 4307529 (in remote_balance)

LNBIG-COM picture LNBIG-COM on 11 Nov 2019

@LNBIG-COM Seems to be the same case:

2019-11-07 14:02:45.397 [INF] PEER: NodeKey(020f0d93c700cf5cf556e61828fab473a5c30ee6eb927ae36a130cc1c57326d21a) loading ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1)

This line indicates that the peer was disconnected and connected again during the channel was in pending which is the case this issue is about and what made the "link" be created with pending state.

2019-11-07 23:59:57.087 [INF] LNWL: Marking unconfirmed transaction 954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08 mined in block 602780

This line shows that only later the channel was confirmed on-chain so according to the issue the following payments should have marked this channel as pending again.

Restart should make the channels open again.

roeierez picture roeierez on 11 Nov 2019

@LNBIG-COM Seems to be the same case:

2019-11-07 14:02:45.397 [INF] PEER: NodeKey(020f0d93c700cf5cf556e61828fab473a5c30ee6eb927ae36a130cc1c57326d21a) loading ChannelPoint(954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08:1)

This line indicates that the peer was disconnected and connected again during the channel was in pending which is the case this issue is about and what made the "link" be created with pending state.

2019-11-07 23:59:57.087 [INF] LNWL: Marking unconfirmed transaction 954a6fbccec8b8f1d6d012e0e30586eecb9109ca58e21f28cafc9381e4df7f08 mined in block 602780

This line shows that only later the channel was confirmed on-chain so according to the issue the following payments should have marked this channel as pending again.

Restart should make the channels open again.

It depends, if IsPending was persisted to the DB, the channels won't open again and a channel barrier will be setup in the fundingmanager which would prevent forwarding through

Crypt-iQ picture Crypt-iQ on 11 Nov 2019

It depends, if IsPending was persisted to the DB, the channels won't open again and a channel barrier will be setup in the fundingmanager which would prevent forwarding through

@Crypt-iQ maybe I am missing something here cause I saw the fundingManager always advancing the state of channels from pending to open (if confirmed) on startup: https://github.com/lightningnetwork/lnd/blob/b222b6e6250be0adea1d880800fde60f6b8695d1/fundingmanager.go#L785

roeierez picture roeierez on 11 Nov 2019

@roeierez I think we're both right. The fundingmanager should mark the channel open again if it's pending, but here the new chan barrier is setup which prohibits the peer from forwarding through (or even replying with a revocation to our commit sig). However, after it's marked open another restart should fix the issue (so... 2 restarts I believe). https://github.com/lightningnetwork/lnd/blob/b222b6e6250be0adea1d880800fde60f6b8695d1/fundingmanager.go#L517

Crypt-iQ picture Crypt-iQ on 11 Nov 2019

We're running into this as well on 2 of our channels. Seems to have started occurring quite recently.

tdickman picture tdickman on 27 Nov 2019

Got same issue with 0.8.1, I have ~70 confirmations at the time of writing, but channel is still under "pending_open_channels".

Talkless picture Talkless on 27 Nov 2019

Fixed in https://github.com/lightningnetwork/lnd/commit/8b3dd9415ef6b5f83505068231557d275b65db53.

wpaulino picture wpaulino on 2 Dec 2019
Was this page helpful?
0 / 5 - 0 ratings

Related issues

BitBargain picture BitBargain  路  3Comments
AnthonyRonning picture AnthonyRonning  路  3Comments
Richard87 picture Richard87  路  3Comments
hxsquid picture hxsquid  路  3Comments
Roasbeef picture Roasbeef  路  3Comments