[bug]: cannot connect to peer - "failing link: unable to handle upstream settle with error: invalid update", "unknown channel ID"

[xmrk-btc]

Background

I had a channel, but could not connect to the peer, always getting disconnected with logs like this:

2023-10-29 07:05:42.433 [INF] PEER: Peer(031c8b9e52039af6892015702bab9b7e13b46979a519497ad8b6674bfe88ea7c27): Loading ChannelPo
int(e16ae8e1bab76288c800e02d31d8e6cceab3da6145e62bcfa2291fd0b8b57d05:1), isPending=false
2023-10-29 07:05:42.434 [INF] HSWC: ChannelLink(e16ae8e1bab76288c800e02d31d8e6cceab3da6145e62bcfa2291fd0b8b57d05:1): starting
2023-10-29 07:05:42.434 [INF] HSWC: Trimming open circuits for chan_id=812226:2620:1, start_htlc_id=18712
2023-10-29 07:05:42.434 [INF] HSWC: Adding live link chan_id=057db5b8d01f29a2cf2be64561dab3eacce6d8312de000c88862b7bae1e86ae0, 
short_chan_id=812226:2620:1
2023-10-29 07:05:42.434 [INF] HSWC: ChannelLink(e16ae8e1bab76288c800e02d31d8e6cceab3da6145e62bcfa2291fd0b8b57d05:1): HTLC manag
er started, bandwidth=2316950 mSAT
2023-10-29 07:05:42.434 [INF] HSWC: ChannelLink(e16ae8e1bab76288c800e02d31d8e6cceab3da6145e62bcfa2291fd0b8b57d05:1): attempting
 to re-synchronize
2023-10-29 07:05:42.434 [INF] PEER: Peer(031c8b9e52039af6892015702bab9b7e13b46979a519497ad8b6674bfe88ea7c27): Negotiated chan s
eries queries
2023-10-29 07:05:42.434 [INF] DISC: Creating new GossipSyncer for peer=031c8b9e52039af6892015702bab9b7e13b46979a519497ad8b6674b
fe88ea7c27
2023-10-29 07:05:42.434 [INF] NTFN: New block epoch subscription
2023-10-29 07:05:42.434 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(e16ae8e1bab76288c800e02d31d8e6cceab3d
a6145e62bcfa2291fd0b8b57d05:1)
2023-10-29 07:05:42.705 [INF] HSWC: ChannelLink(e16ae8e1bab76288c800e02d31d8e6cceab3da6145e62bcfa2291fd0b8b57d05:1): received r
e-establishment message from remote side
2023-10-29 07:05:42.713 [ERR] HSWC: ChannelLink(e16ae8e1bab76288c800e02d31d8e6cceab3da6145e62bcfa2291fd0b8b57d05:1): failing li
nk: unable to handle upstream settle with error: invalid update
2023-10-29 07:05:42.713 [ERR] HSWC: ChannelLink(e16ae8e1bab76288c800e02d31d8e6cceab3da6145e62bcfa2291fd0b8b57d05:1): link faile
d, exiting htlcManager
2023-10-29 07:05:42.713 [INF] HSWC: ChannelLink(e16ae8e1bab76288c800e02d31d8e6cceab3da6145e62bcfa2291fd0b8b57d05:1): exited
2023-10-29 07:05:42.713 [INF] HSWC: ChannelLink(e16ae8e1bab76288c800e02d31d8e6cceab3da6145e62bcfa2291fd0b8b57d05:1): stopping
2023-10-29 07:05:42.713 [INF] HSWC: Removing channel link with ChannelID(057db5b8d01f29a2cf2be64561dab3eacce6d8312de000c88862b7bae1e86ae0)
2023-10-29 07:05:42.726 [ERR] PEER: Peer(031c8b9e52039af6892015702bab9b7e13b46979a519497ad8b6674bfe88ea7c27): Unknown channel ID: 057db5b8d01f29a2cf2be64561dab3eacce6d8312de000c88862b7bae1e86ae0 found in received msg=UpdateAddHTLC
2023-10-29 07:05:42.726 [ERR] PEER: Peer(031c8b9e52039af6892015702bab9b7e13b46979a519497ad8b6674bfe88ea7c27): Unknown channel ID: 057db5b8d01f29a2cf2be64561dab3eacce6d8312de000c88862b7bae1e86ae0 found in received msg=CommitSig
2023-10-29 07:05:42.726 [ERR] PEER: Peer(031c8b9e52039af6892015702bab9b7e13b46979a519497ad8b6674bfe88ea7c27): Unknown channel ID: 057db5b8d01f29a2cf2be64561dab3eacce6d8312de000c88862b7bae1e86ae0 found in received msg=RevokeAndAck

The channel has been force-closed a day later, to claim the incoming HTLC I guess. The channel was working and forwarding at least until 28/Oct/2023 22:54 (the last recorded forward according to my node). I have / had 3-4 other channels with the same problem, at least in one case the complaints about unknown channel ID stopped, without restarting lnd and without closing that channel.

At the very least, this problem makes a channel unusable. And sounds a bit scary, did one of the nodes lose some data? How can a node suddenly stop recognizing its channel?

Your environment

• version of lnd: 0.17 (both peers). I use boltdb, peer probably postgres (on raspiblitz).
• which operating system: Debian 12.1
• version of bitcoind: v25.1rc1

Steps to reproduce

No idea.

Expected behaviour

Should be able to connect.

[bitromortac]

Could you look up the hash of the HTLC and grep for logs? It seems that your node force closed, could you verify that?

[xmrk-btc]

Could you look up the hash of the HTLC and grep for logs? It seems that your node force closed, could you verify that?

No, according to my logs the peer closed:

2023-10-30 21:09:34.630 [INF] NTFN: New block: height=814568, sha=0000000000000000000179adcc9d73d93126623f3c12a77e47244725868d9
399
2023-10-30 21:09:34.631 [INF] NTFN: Dispatching confirmed spend notification for outpoint=e16ae8e1bab76288c800e02d31d8e6cceab3da6145e62bcfa2291fd0b8b57d05:1, script=0 e25d26d0f38c5bf0b0dbc9ffd98347b50032410ca5d4a2783a6b5fb7c101ac85 at current height=814568: 8ed69f86be442d45d196943c2650e0f4c7e4a542b580224cc8ef12829c758f2b[0] spending e16ae8e1bab76288c800e02d31d8e6cceab3da6145e62bcfa2291fd0b8b57d05:1 at height=814568
2023-10-30 21:09:34.632 [INF] CNCT: Remote party broadcast pending set, commit_num=96435
2023-10-30 21:09:34.632 [INF] CNCT: Unilateral close of ChannelPoint(e16ae8e1bab76288c800e02d31d8e6cceab3da6145e62bcfa2291fd0b8b57d05:1) detected
2023-10-30 21:09:34.633 [INF] CNCT: ChannelArbitrator(e16ae8e1bab76288c800e02d31d8e6cceab3da6145e62bcfa2291fd0b8b57d05:1): remote party has closed channel out on-chain

Shortly after this, regarding the HTLC:

2023-10-30 21:09:34.769 [INF] HSWC: Received outside contract resolution, mapping to: (*htlcswitch.htlcPacket)(0xc029f69ef0)({
 incomingChanID: (lnwire.ShortChannelID) 0:0:0,
 outgoingChanID: (lnwire.ShortChannelID) 812226:2620:1,
 incomingHTLCID: (uint64) 0,
 outgoingHTLCID: (uint64) 18711,
 sourceRef: (*channeldb.AddRef)(<nil>),
 destRef: (*channeldb.SettleFailRef)(<nil>),
 incomingAmount: (lnwire.MilliSatoshi) 0 mSAT,
 amount: (lnwire.MilliSatoshi) 0 mSAT,
 htlc: (*lnwire.UpdateFailHTLC)(0xc03c444d20)({
  ChanID: (lnwire.ChannelID) (len=32 cap=32) 0000000000000000000000000000000000000000000000000000000000000000,
  ID: (uint64) 0,
  Reason: (lnwire.OpaqueReason) <nil>,
  ExtraData: (lnwire.ExtraOpaqueData) <nil>
 }),
 obfuscator: (hop.ErrorEncrypter) <nil>,
 localFailure: (bool) false,
 linkFailure: (*htlcswitch.LinkError)(<nil>),
 convertedError: (bool) false,
 hasSource: (bool) false,
 isResolution: (bool) true,
 circuit: (*htlcswitch.PaymentCircuit)(<nil>),
 incomingTimeout: (uint32) 0,
 outgoingTimeout: (uint32) 0,
 customRecords: (record.CustomSet) <nil>,
 originalOutgoingChanID: (lnwire.ShortChannelID) 0:0:0
})

The channel is still in pendingchannels (not closedchannels), the htlc is:

            "pending_htlcs": [
                {
                    "incoming": true,
                    "amount": "34159",
                    "outpoint": "8ed69f86be442d45d196943c2650e0f4c7e4a542b580224cc8ef12829c758f2b:3",
                    "maturity_height": 814775,
                    "blocks_til_maturity": 68,
                    "stage": 1
                }
            ],

[bitromortac]

Are you in contact with the peer? If so it would be helpful if they could share logs (can do that privately, dm on slack perhaps).

[ziggie1984]

Maybe we should add a log here:https://github.com/lightningnetwork/lnd/blob/master/htlcswitch/link.go#L1752. Because I am curious what HTLC did you Peer try to settle with you.
Apart from that, I am a bit confused can you please let me know @xmrk-btc which output belonged to your after the force-close (not the htlc but the other). Normally when your peer force-closed it should be this one:https://mempool.space/tx/d1fb33a0d629e5d2cd3eb7e55ba6ea4e41d73ad4c42f486d5a37be5de5a26591. Because what confuses me although your peer force-closed according to your logs the htlc which got resolved onchain could only belong to the person who was the owner of the force-close (because it got swept with the second-level timeout covenant). So it is important to know which of the other outputs of the FC belonged to you.

[xmrk-btc]

Maybe we should add a log here:https://github.com/lightningnetwork/lnd/blob/master/htlcswitch/link.go#L1752. Because I am curious what HTLC did you Peer try to settle with you. Apart from that, I am a bit confused can you please let me know @xmrk-btc which output belonged to your after the force-close (not the htlc but the other). Normally when your peer force-closed it should be this one:https://mempool.space/tx/d1fb33a0d629e5d2cd3eb7e55ba6ea4e41d73ad4c42f486d5a37be5de5a26591. Because what confuses me although your peer force-closed according to your logs the htlc which got resolved onchain could only belong to the person who was the owner of the force-close (because it got swept with the second-level timeout covenant). So it is important to know which of the other outputs of the FC belonged to you.

I think it is d1fb33 tx you mention, this is the full lncli closedchannels info for that channel:

        {
            "channel_point": "e16ae8e1bab76288c800e02d31d8e6cceab3da6145e62bcfa2291fd0b8b57d05:1",
            "chan_id": "893051931553693697",
            "chain_hash": "000000000019d6689c085ae165831e934ff763ae46a2a6c172b3f1b60a8ce26f",
            "closing_tx_hash": "8ed69f86be442d45d196943c2650e0f4c7e4a542b580224cc8ef12829c758f2b",
            "remote_pubkey": "031c8b9e52039af6892015702bab9b7e13b46979a519497ad8b6674bfe88ea7c27",
            "capacity": "3000000",
            "close_height": 814568,
            "settled_balance": "32316",
            "time_locked_balance": "0",
            "close_type": "REMOTE_FORCE_CLOSE",
            "open_initiator": "INITIATOR_REMOTE",
            "close_initiator": "INITIATOR_REMOTE",
            "resolutions": [
                {
                    "resolution_type": "COMMIT",
                    "outcome": "CLAIMED",
                    "outpoint": {
                        "txid_bytes": "2b8f759c8212efc84c2280b542a5e4c7f4e050263c9496d1452d44be869fd68e",
                        "txid_str": "8ed69f86be442d45d196943c2650e0f4c7e4a542b580224cc8ef12829c758f2b",
                        "output_index": 2
                    },
                    "amount_sat": "32316",
                    "sweep_txid": "d1fb33a0d629e5d2cd3eb7e55ba6ea4e41d73ad4c42f486d5a37be5de5a26591"
                },
                {
                    "resolution_type": "INCOMING_HTLC",
                    "outcome": "TIMEOUT",
                    "outpoint": {
                        "txid_bytes": "2b8f759c8212efc84c2280b542a5e4c7f4e050263c9496d1452d44be869fd68e",
                        "txid_str": "8ed69f86be442d45d196943c2650e0f4c7e4a542b580224cc8ef12829c758f2b",
                        "output_index": 3
                    },
                    "amount_sat": "34159",
                    "sweep_txid": ""
                }
            ],
            "alias_scids": [],
            "zero_conf_confirmed_scid": "0"
        },

[xmrk-btc]

Are you in contact with the peer? If so it would be helpful if they could share logs (can do that privately, dm on slack perhaps).

Sorry for horribly late reply, the original peer told he had logs for past 30 minutes, so I assumed he did not have anything when you asked.

But as mentioned, had the same problem with other peers, contacted one of them - KnockOnWood / 039e05e271f537cfa1c060d2364b960b85bd509ac89bae524e4a01948a07b3e8d1 . In this case the outage only lasted for 15 minutes. From my side:

2023-10-30 09:15:08.315 [ERR] PEER: Peer(039e05e271f537cfa1c060d2364b960b85bd509ac89bae524e4a01948a07b3e8d1): Unknown channel ID: fa17a30abdba5fde99d1f8a53dd7dabd40f95ff0b05e9472c354a53eb762fa2b found in received msg=UpdateFailHTLC
2023-10-30 09:30:24.629 [ERR] PEER: Peer(039e05e271f537cfa1c060d2364b960b85bd509ac89bae524e4a01948a07b3e8d1): Unknown channel ID: fa17a30abdba5fde99d1f8a53dd7dabd40f95ff0b05e9472c354a53eb762fa2b found in received msg=UpdateAddHTLC
...
2023-10-30 09:31:28.182 [INF] HSWC: Adding live link chan_id=fa17a30abdba5fde99d1f8a53dd7dabd40f95ff0b05e9472c354a53eb762fa2b, short_chan_id=802214:510:0

They wrote:

at that time, :15 and even :14, there are no hits for your pubkey, while searching for funding txid I got these, both at :15 and at :14

[WRN] HSWC: ChannelLink(2bfa62b73ea554c372945eb0f05ff940bddad73da5f8d199de5fbabd0aa317fa:0): outgoing htlc(130000e748d4288914dab97588bbb0ef661d4b5fe485fd39d444b68902ad26a0) has insufficient fee: expected 633, got 356
[WRN] HSWC: ChannelLink(2bfa62b73ea554c372945eb0f05ff940bddad73da5f8d199de5fbabd0aa317fa:0): outgoing htlc(ab4dbd9e498e91a02e8b13db1ae64b0fe125e9cd862d0b32038a58ce1ba2ce42) has insufficient fee: expected 729, got 409
[WRN] HSWC: ChannelLink(2bfa62b73ea554c372945eb0f05ff940bddad73da5f8d199de5fbabd0aa317fa:0): outgoing htlc(03576574dcd8df691e90c0ff9dc875ec94f96459ac04f9e3ab00b539c22981a0) has insufficient fee: expected 369, got 209
[WRN] HSWC: ChannelLink(2bfa62b73ea554c372945eb0f05ff940bddad73da5f8d199de5fbabd0aa317fa:0): outgoing htlc(759b62a683b109ae3a1e906741448878631a35eb7c1565d0e298cc7b6daf31e4) has insufficient fee: expected 99, got 69

Sounded very strange, I thought my node did try to contact theirs, so would expect my node mentioned, but we have at least some info .

[ziggie1984]

I think it is d1fb33 tx you mention, this is the full lncli closedchannels info for that channel:

Ok that brings a bit light into this problem, so the HTLC which you have in your closedchannels output was not yours and was claimed by your peer. Main question which needs to be answered: Which HTLC was your Peer trying to Settle with you when there were no outgoing HTLCs from your side (you can only settle outgoing HTLCs and the peer had non on the commitment). So very interesting case but without the logs of your peer this will be difficult to debug.

[WRN] HSWC: ChannelLink(2bfa62b73ea554c372945eb0f05ff940bddad73da5f8d199de5fbabd0aa317fa:0): outgoing htlc(759b62a683b109ae3a1e906741448878631a35eb7c1565d0e298cc7b6daf31e4) has insufficient fee: expected 99, got 69

These messages are normal, which basically means the sender of the payment had an old Policy update of your channel and you are rejecting this htlc.

[ziggie1984]

So encountered the exact same problem with another node and I could narrow down the problem. So in case you still have some channels which do not reactive because of a invalid update you could follow the steps laid down below to confirm that the situation is the same for you.

@Roasbeef @yyforyongyu I think you should take a look at this.

What happened to the other noderunner:

He had a channel with 10 htlcs with the following relevant forwarded HTLC:

           {
                "incoming": false,
                "amount": "67047",
                "hash_lock": "5cf6c63902a114e34dcbda08c5c9ad2718c9f172c36d069fc90b80702e0588f4",
                "expiration_height": 818265,
                "htlc_index": "103214",
                "forwarding_channel": "XXXX",
                "forwarding_htlc_index": "XXXXXXX"
            },

Now his peer also an LND node tried to settle this exact HTLC with an UpdateFulfillHTLC msg. So far so good now comes the problem:

He tries to settle the HTLC with the ID:

Received UpdateFulfillHTLC(chan_id=cb6f9d6b9e525f4f393ad0829ffa2696cc244d8b7fd55d3d6bd2d6c1ff31ad3e, id=103214, pre_image=5183dbc0d4da7160aeeb43c19d20910139e18b8468f64c6feb69d1beac67f812) from ....

But somehow his node thinks this HTLC is not locked in:

2023-11-22 10:13:06.966 [ERR] HSWC: ChannelLink(3fad31ffc1d6d26b3d5dd57f8b4d24cc9626fa9f82d03a394f5f529e6b9d6fcb:1): failing link: unable to handle upstream settle with error: invalid update

=> relevant codeline:

lnd/htlcswitch/link.go

Line 1755 in f005b24

"unable to handle upstream settle",

What I think happens is that somehow the hashes of the 2 onionblobs remote and local differ and therefore we do not count this HTLC as an active HTLC which is fully locked in.

=> relevant codeline: https://github.com/lightningnetwork/lnd/blob/master/channeldb/channel.go#L2094-L2120

Looking shortly at this code, I am not sure whether we need this kind of strict check, do we really need to make sure both onion-blobs are the same in the Settle-Case, I mean we can just try whether the preimage is good and if it is we will never need this Onion-Blob anyways.... So I think this check can be loosened up, remains the question how could the two onion-blobs diverge, maybe we need to check in detail whether we do not flush different things in some cases.

Apart from that the related Channel got Force-Closed and the relevant HTLC got swept by the preimage by its peer which is evidence that the peer tried to settle the correct HTLC and the problem lies indeed locally in having a database inconsistency between the remote and the local onionblob.

Sweep of the HTLC by the preimage:

https://mempool.space/tx/9a98fcd342d575dbbd225a8d921b605664eed3b90c6306a4723b56521293f02d

[yyforyongyu]

Could you guys patch #8220 so we can have more info around this area? Thanks!