Channel unusable: FAILURE_REASON_INSUFFICIENT_BALANCE

[rkfg]

Background

I just opened a channel but can't balance it with lncli sendpayment because no payment through it could be made, every attempt quickly fails with error Payment status: FAILED, reason: FAILURE_REASON_INSUFFICIENT_BALANCE. My local balance is fine, however, the local max_pending_amt_msat parameter is weird (unusually high, in hex it's 0xFFFFFFFFFFFFFFFF so -1 int64 I assume?). Here's the channel info as reported by my node:

        {
            "active": true,
            "remote_pubkey": "02fe153690061fa27049bae0faa236ddb95df98c514416a350449c24a8018851dc",
            "channel_point": "bbbc88139224f18246f646df7504e18f3be5a705283c54ae5a1781242f4e3889:1",
            "chan_id": "758268298569842689",
            "capacity": "1000000",
            "local_balance": "989855",
            "remote_balance": "0",
            "commit_fee": "10145",
            "commit_weight": "600",
            "fee_per_kw": "14013",
            "unsettled_balance": "0",
            "total_satoshis_sent": "0",
            "total_satoshis_received": "0",
            "num_updates": "1",
            "pending_htlcs": [
            ],
            "csv_delay": 144,
            "private": false,
            "initiator": true,
            "chan_status_flags": "ChanStatusDefault",
            "local_chan_reserve_sat": "10000",
            "remote_chan_reserve_sat": "10000",
            "static_remote_key": true,
            "commitment_type": "STATIC_REMOTE_KEY",
            "lifetime": "186",
            "uptime": "186",
            "close_address": "",
            "push_amount_sat": "0",
            "thaw_height": 0,
            "local_constraints": {
                "csv_delay": 144,
                "chan_reserve_sat": "10000",
                "dust_limit_sat": "573",
                "max_pending_amt_msat": "18446744073709551615",
                "min_htlc_msat": "0",
                "max_accepted_htlcs": 30
            },
            "remote_constraints": {
                "csv_delay": 144,
                "chan_reserve_sat": "10000",
                "dust_limit_sat": "546",
                "max_pending_amt_msat": "990000000",
                "min_htlc_msat": "1",
                "max_accepted_htlcs": 483
            }
        },

I opened it using Ride-The-Lightning, took a while because the block rate suddenly dropped and fees skyrocketed but after three hours it got confirmed and the channel became active. But I can't send any sats through it to the other side and back to myself.

Your environment

• version of lnd: 0.13-beta (originally built from 20ef37d)
• which operating system (uname -a on *Nix): Linux 5.10.46-v7l+ #1432 SMP Fri Jul 2 21:17:20 BST 2021 armv7l GNU/Linux (RaspberryPi 4 B)
• version of btcd, bitcoind, or other backend: bitcoind 0.21.1

Steps to reproduce

Opened a channel using RTL. Try to pay to yourself using lncli sendpayment --amp -d 021c3ec6432d2b9b5abcb01dd64b3a8f2afe3ba7d8c021f63ffd0a994cd3bc9b88 --allow_self_payment -a 10000 --outgoing_chan_id 758268298569842689

Expected behaviour

I should be able to use the channel to at least balance it to 50/50

Actual behaviour

rebalance.py fails with ✘ Could not find any suitable route, lncli sendpayment fails with FAILURE_REASON_INSUFFICIENT_BALANCE. Log:

Jul 04 23:02:47 fullnode lnd[22879]: 2021-07-04 23:02:47.464 [WRN] CRTR: Failed to find route for payment fda26e4f9ab2b7669b273d1e53013575e73fa2197b0ee978d0b94e4ddcbce940: insufficient local balance
Jul 04 23:02:47 fullnode lnd[22879]: 2021-07-04 23:02:47.482 [ERR] CRTR: Payment fda26e4f9ab2b7669b273d1e53013575e73fa2197b0ee978d0b94e4ddcbce940 failed: insufficient_balance       

I experienced some system instability, probably due to the power issues (SSD freezes) so the channel issue might be caused by a database corruption. I checked the channel.db and other database files with bolt and it hasn't found any errors so might not be it in the end.

I have another channel with this -1 max_pending_amt_msat, the peer in question connects and disconnects instantly so that channel doesn't work because the peer is always offline. However, the peer in this report above connects normally and the channel was opened after the latest hardware issue. I also opened other channels before today and they work fine, only this one misbehaves.

[guggero]

Hmm, something's definitely weird here. I think the max_pending_amt_msat is not allowed to be larger than the channel capacity. It's even validated when opening a channel. So this does sound like a case of data corruption.

I would advise you to try and coop-close those two channels while the fees are low and try again. Or even start over completely by closing all channels and restarting the node on a new SSD (it freezing can be a sign of hardware failure too).

[rkfg]

I opened a new channel and it yet again shows incorrect information and doesn't allow to send sats due to insufficient local balance:

        {
            "active": true,
            "remote_pubkey": "03baa70886d9200af0ffbd3f9e18d96008331c858456b16e3a9b41e735c6208fef",
            "channel_point": "950c3ad3b0dd18e5b8db9d9066918cc53cbbb76d87bb5d1534dadf41bcb96888:1",
            "chan_id": "758369453673480193",
            "capacity": "2500000",
            "local_balance": "2498398",
            "remote_balance": "0",
            "commit_fee": "1602",
            "commit_weight": "600",
            "fee_per_kw": "2214",
            "unsettled_balance": "0",
            "total_satoshis_sent": "0",
            "total_satoshis_received": "0",
            "num_updates": "0",
            "pending_htlcs": [
            ],
            "csv_delay": 144,
            "private": false,
            "initiator": true,
            "chan_status_flags": "ChanStatusDefault",
            "local_chan_reserve_sat": "25000",
            "remote_chan_reserve_sat": "25000",
            "static_remote_key": true,
            "commitment_type": "STATIC_REMOTE_KEY",
            "lifetime": "1143",
            "uptime": "1143",
            "close_address": "",
            "push_amount_sat": "0",
            "thaw_height": 0,
            "local_constraints": {
                "csv_delay": 144,
                "chan_reserve_sat": "25000",
                "dust_limit_sat": "573",
                "max_pending_amt_msat": "18446744073709551615",
                "min_htlc_msat": "0",
                "max_accepted_htlcs": 30
            },
            "remote_constraints": {
                "csv_delay": 300,
                "chan_reserve_sat": "25000",
                "dust_limit_sat": "546",
                "max_pending_amt_msat": "2475000000",
                "min_htlc_msat": "1",
                "max_accepted_htlcs": 483
            }
        },

The logs:

Jul 05 12:03:43 fullnode lnd[22879]: 2021-07-05 12:03:43.685 [INF] NTFN: New block: height=689735, sha=0000000000000000000edbebedcd49e11be9c22806d80034691b3135ff425922
Jul 05 12:03:43 fullnode lnd[22879]: 2021-07-05 12:03:43.687 [INF] NTFN: Dispatching 3 confirmation notification for txid=950c3ad3b0dd18e5b8db9d9066918cc53cbbb76d87bb5d1534dadf41bcb96888
Jul 05 12:03:43 fullnode lnd[22879]: 2021-07-05 12:03:43.687 [INF] UTXN: Attempting to graduate height=689735: num_kids=0, num_babies=0
Jul 05 12:03:43 fullnode lnd[22879]: 2021-07-05 12:03:43.692 [INF] FNDG: ChannelPoint(950c3ad3b0dd18e5b8db9d9066918cc53cbbb76d87bb5d1534dadf41bcb96888:1) is now active: ChannelID(8868b9bc41dfda34155dbb876db7bb3cc58c9166909ddbb8e518ddb0d33a0c94)
Jul 05 12:03:43 fullnode lnd[22879]: 2021-07-05 12:03:43.799 [ERR] FNDG: unable to report short chan id: link 8868b9bc41dfda34155dbb876db7bb3cc58c9166909ddbb8e518ddb0d33a0c94 not found
Jul 05 12:03:43 fullnode lnd[22879]: 2021-07-05 12:03:43.801 [INF] CHBU: Updating on-disk multi SCB backup: num_old_chans=28, num_new_chans=28
Jul 05 12:03:43 fullnode lnd[22879]: 2021-07-05 12:03:43.861 [INF] FNDG: Peer(03baa70886d9200af0ffbd3f9e18d96008331c858456b16e3a9b41e735c6208fef) is online, sending FundingLocked for ChannelID(8868b9bc41dfda34155dbb876db7bb3cc58c9166909ddbb8e518ddb0d33a0c94)
...
Jul 05 12:04:01 fullnode lnd[22879]: 2021-07-05 12:04:01.348 [INF] PEER: New channel active ChannelPoint(950c3ad3b0dd18e5b8db9d9066918cc53cbbb76d87bb5d1534dadf41bcb96888:1) with Node
Key(03baa70886d9200af0ffbd3f9e18d96008331c858456b16e3a9b41e735c6208fef)
Jul 05 12:04:01 fullnode lnd[22879]: 2021-07-05 12:04:01.355 [INF] HSWC: Removing channel link with ChannelID(8868b9bc41dfda34155dbb876db7bb3cc58c9166909ddbb8e518ddb0d33a0c94)
Jul 05 12:04:01 fullnode lnd[22879]: 2021-07-05 12:04:01.357 [INF] HSWC: ChannelLink(689733:1719:1): starting
Jul 05 12:04:01 fullnode lnd[22879]: 2021-07-05 12:04:01.363 [INF] HSWC: Trimming open circuits for chan_id=689733:1719:1, start_htlc_id=0
Jul 05 12:04:01 fullnode lnd[22879]: 2021-07-05 12:04:01.365 [INF] HSWC: Adding live link chan_id=8868b9bc41dfda34155dbb876db7bb3cc58c9166909ddbb8e518ddb0d33a0c94, short_chan_id=689733:1719:1
Jul 05 12:04:01 fullnode lnd[22879]: 2021-07-05 12:04:01.365 [INF] CNCT: Attempting to update ContractSignals for ChannelPoint(950c3ad3b0dd18e5b8db9d9066918cc53cbbb76d87bb5d1534dadf41bcb96888:1)
Jul 05 12:04:01 fullnode lnd[22879]: 2021-07-05 12:04:01.365 [INF] HSWC: ChannelLink(689733:1719:1): HTLC manager started, bandwidth=2473017000 mSAT

Any debugging ideas?

Also, I grepped the source and couldn't find any limitations for max_pending_amt_msat (which corresponds to the MaxPendingAmount field if I'm not mistaken). There are indeed checks that other values aren't greater than it but for the value itself I've found no bounds.

[rkfg]

I opened two more small channels:

• to 02fe153690061fa27049bae0faa236ddb95df98c514416a350449c24a8018851dc, 50k sats, same bug
• to 026d1de80e59f3fe2b27aa3dc8012f4437165bf99971bd9b7d8afedb066f92d695, 20k sats, it works fine

I don't think it's data corruption at this point. Both 03baa70886d9200af0ffbd3f9e18d96008331c858456b16e3a9b41e735c6208fef and 02fe153690061fa27049bae0faa236ddb95df98c514416a350449c24a8018851dc somehow trigger this bug on my side. However, another peer that I never connected before works as expected. Of course, I already restarted lnd many times during these experiments. I'll try to open more channels to other nodes. There's no information about the software implementation that second buggy node runs.

[guggero]

Do you see the high max_pending_amt_msat for the other buggy channel as well? Did you open all channels through RTL?

[rkfg]

Yes, all buggy channels have 0xFFFFFFFFFFFFFFFF max_pending_amt_msat set. These two small channels were opened manually with lncli just in case it might be an RTL's fault. It seems not to be the case. The working small channel looks like this:

        {
            "active": true,
            "remote_pubkey": "026d1de80e59f3fe2b27aa3dc8012f4437165bf99971bd9b7d8afedb066f92d695",
            "channel_point": "e11d4d6df475eb0a64c03497d36d4cf80d12071736e18767b5e917bb30292233:0",
            "chan_id": "758378249787604992",
            "capacity": "20000",
            "local_balance": "9737",
            "remote_balance": "9743",
            "commit_fee": "520",
            "commit_weight": "724",
            "fee_per_kw": "718",
            "unsettled_balance": "0",
            "total_satoshis_sent": "9743",
            "total_satoshis_received": "0",
            "num_updates": "6",
            "pending_htlcs": [
            ],
            "csv_delay": 144,
            "private": false,
            "initiator": true,
            "chan_status_flags": "ChanStatusDefault",
            "local_chan_reserve_sat": "573",
            "remote_chan_reserve_sat": "573",
            "static_remote_key": true,
            "commitment_type": "STATIC_REMOTE_KEY",
            "lifetime": "1838",
            "uptime": "1838",
            "close_address": "",
            "push_amount_sat": "0",
            "thaw_height": 0,
            "local_constraints": {
                "csv_delay": 144,
                "chan_reserve_sat": "573",
                "dust_limit_sat": "573",
                "max_pending_amt_msat": "19800000",
                "min_htlc_msat": "1",
                "max_accepted_htlcs": 483
            },
            "remote_constraints": {
                "csv_delay": 144,
                "chan_reserve_sat": "573",
                "dust_limit_sat": "573",
                "max_pending_amt_msat": "19800000",
                "min_htlc_msat": "1",
                "max_accepted_htlcs": 483
            }
        },

The buggy one:

        {
            "active": true,
            "remote_pubkey": "02fe153690061fa27049bae0faa236ddb95df98c514416a350449c24a8018851dc",
            "channel_point": "2a33de080ce7bdba21dcf3c962c41e0457bbc83555eca14e16c64f3c400a76bc:1",
            "chan_id": "758378249785114625",
            "capacity": "50000",
            "local_balance": "49481",
            "remote_balance": "0",
            "commit_fee": "519",
            "commit_weight": "600",
            "fee_per_kw": "718",
            "unsettled_balance": "0",
            "total_satoshis_sent": "0",
            "total_satoshis_received": "0",
            "num_updates": "0",
            "pending_htlcs": [
            ],
            "csv_delay": 144,
            "private": false,
            "initiator": true,
            "chan_status_flags": "ChanStatusDefault",
            "local_chan_reserve_sat": "573",
            "remote_chan_reserve_sat": "546",
            "static_remote_key": true,
            "commitment_type": "STATIC_REMOTE_KEY",
            "lifetime": "1434",
            "uptime": "1433",
            "close_address": "",
            "push_amount_sat": "0",
            "thaw_height": 0,
            "local_constraints": {
                "csv_delay": 144,
                "chan_reserve_sat": "573",
                "dust_limit_sat": "573",
                "max_pending_amt_msat": "18446744073709551615",
                "min_htlc_msat": "0",
                "max_accepted_htlcs": 30
            },
            "remote_constraints": {
                "csv_delay": 144,
                "chan_reserve_sat": "546",
                "dust_limit_sat": "546",
                "max_pending_amt_msat": "49500000",
                "min_htlc_msat": "1",
                "max_accepted_htlcs": 483
            }
        },

[rkfg]

Oh, and now something funny happened: someone forwarded four payments through my node and they all went out of that buggy channel just fine! So I can't send sats from it but other users can.

[rkfg]

Opened another 50k channel with a previously unseen node and it's broken.

        {
            "active": true,
            "remote_pubkey": "02e389d861acd9d6f5700c99c6c33dd4460d6f1e2f6ba89d1f4f36be85fc60f8d7",
            "channel_point": "0b138ce36d3a54e33eb13a97aa1349bd80f958c81fbaf8562387a52634584cc8:0",
            "chan_id": "758387045833441280",
            "capacity": "50000",
            "local_balance": "49234",
            "remote_balance": "0",
            "commit_fee": "766",
            "commit_weight": "600",
            "fee_per_kw": "1059",
            "unsettled_balance": "0",
            "total_satoshis_sent": "0",
            "total_satoshis_received": "0",
            "num_updates": "0",
            "pending_htlcs": [
            ],
            "csv_delay": 144,
            "private": false,
            "initiator": true,
            "chan_status_flags": "ChanStatusDefault",
            "local_chan_reserve_sat": "573",
            "remote_chan_reserve_sat": "546",
            "static_remote_key": true,
            "commitment_type": "STATIC_REMOTE_KEY",
            "lifetime": "212",
            "uptime": "212",
            "close_address": "",
            "push_amount_sat": "0",
            "thaw_height": 0,
            "local_constraints": {
                "csv_delay": 144,
                "chan_reserve_sat": "573",
                "dust_limit_sat": "573",
                "max_pending_amt_msat": "18446744073709551615",
                "min_htlc_msat": "0",
                "max_accepted_htlcs": 30
            },
            "remote_constraints": {
                "csv_delay": 144,
                "chan_reserve_sat": "546",
                "dust_limit_sat": "546",
                "max_pending_amt_msat": "49500000",
                "min_htlc_msat": "1",
                "max_accepted_htlcs": 483
            }
        },

[rkfg]

Opened a working channel with Blixt Wallet node, I chose it on 1ml.com going through the owned nodes list (just looked through the channels to the 1ml alpha node one by one) because the owner says it runs lnd specifically. The channel is completely normal and I'm able to send through it back to myself, the constraints are also okay.

At this point may I ask you, @guggero, to try to open channels to the nodes that I marked as buggy? Using the latest lnd build from master, of course. I'd like to get to the root of this issue, reopening and balancing 25 channels due to a supposed database corruption would be a significant inconvenience, especially if it's really an lnd bug after all. Maybe it won't happen on your setup but a bug is a bug and fixing it is a great good. So far I can reproduce it pretty reliably and it seems to happen only with some nodes.

Meanwhile I'll try to carefully add some logging around the parts that cause the insufficient balance error and see why it happens exactly.

[guggero]

Interesting, this does start to sound like an interop problem with c-lightning. Will try as soon as I find the time.

[rkfg]

Could be, even though I must be pretty unlucky to hit this many c-lightning nodes in a row but who knows. So I added some debug logging and found a bit of interesting information that might help to solve the issue. First of all, here we get 0 from bandwidthHints. It's populated elsewhere in this function. Specifically this check fails (the error is not logged anywhere at any level so it's not easy to see what's wrong). It fails during the validation of whether we can add another HTLC. A mock HTLC is added here and since our local config is borked an HTLC with zero amount is added, the check then fails right here. The broken HTLC appears when remoteChain=true.

Here's the relevant pieces of my log (enhanced to see the internals, I removed a lot of zeroes in the OnionBlob field):

Jul 05 19:32:37 fullnode lnd[14912]: 2021-07-05 19:32:37.278 [INF] LNWL: ChannelPoint(0b138ce36d3a54e33eb13a97aa1349bd80f958c81fbaf8562387a52634584cc8:0): Remote side: true, entry: {
RHash:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] RPreimage:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Timeout:0 Amount:0 mSAT LogIndex:1
 HtlcIndex:0 ParentIndex:0 SourceRef:<nil> DestRef:<nil> OpenCircuitKey:(Chan ID=0:0:0, HTLC ID=0) ClosedCircuitKey:<nil> localOutputIndex:0 remoteOutputIndex:0 sig:<nil> addCommitHeightRemote:0 addCommitHeightLocal:0 removeCommitHeightRemote:0 removeCommitHeightLocal:0 OnionBlob:[0 0 0 0 0 0 ... 0 0 0 0 0] ShaOnionBlob:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] 
FailReason:[] FailCode:<unknown> ourPkScript:[] ourWitnessScript:[] theirPkScript:[] theirWitnessScript:[] EntryType:Add isForwarded:false}
Jul 05 19:32:37 fullnode lnd[14912]: 2021-07-05 19:32:37.281 [INF] LNWL: ChannelPoint(0b138ce36d3a54e33eb13a97aa1349bd80f958c81fbaf8562387a52634584cc8:0): entry amount is zero
Jul 05 19:32:37 fullnode lnd[14912]: 2021-07-05 19:32:37.281 [WRN] SRVR: Link to 63383463353833343236613538373233353666386261316663383538663938306264343931336161393733616231336565333
534336136646533386331333062 can't add outgoing htlc: proposed HTLC value must be positive

Next, another (working) channel that doesn't throw any errors:

Jul 05 19:32:37 fullnode lnd[14912]: 2021-07-05 19:32:37.275 [INF] LNWL: ChannelPoint(e11d4d6df475eb0a64c03497d36d4cf80d12071736e18767b5e917bb30292233:0): Remote side: false, entry: 
{RHash:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] RPreimage:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Timeout:0 Amount:1 mSAT LogIndex:
5 HtlcIndex:3 ParentIndex:0 SourceRef:<nil> DestRef:<nil> OpenCircuitKey:(Chan ID=0:0:0, HTLC ID=0) ClosedCircuitKey:<nil> localOutputIndex:0 remoteOutputIndex:0 sig:<nil> addCommitHeightRemote:0 addCommitHeightLocal:0 removeCommitHeightRemote:0 removeCommitHeightLocal:0 OnionBlob:[0 0 0 0 0 0 ... 0 0 0 0 0] ShaOnionBlob:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
 FailReason:[] FailCode:<unknown> ourPkScript:[] ourWitnessScript:[] theirPkScript:[] theirWitnessScript:[] EntryType:Add isForwarded:false}

Now the reason of it not working is pretty clear, the local config isn't properly populated so we get weird default values that say that we may route 0 sat HTLCs and this self-test catches it before the payment is made (no matter the amount in it). I don't know how the wire protocol works so I'll leave it to the developers who know exactly where these values are filled (LocalChanCfg.MinHTLC in particular).

PS: opened another channel with ACINQ, works just fine. They use their own Eclair implementation so that was the sole reason for the test. The C-lightning theory gains ground.

[guggero]

I just opened a channel to 02e389d861acd9d6f5700c99c6c33dd4460d6f1e2f6ba89d1f4f36be85fc60f8d7 and can confirm I have the same symptoms (using v0.13.1-beta.rc1):

            "local_constraints": {
                "csv_delay": 144,
                "chan_reserve_sat": "1000",
                "dust_limit_sat": "573",
                "max_pending_amt_msat": "18446744073709551615",
                "min_htlc_msat": "0",
                "max_accepted_htlcs": 30
            },

And then FAILED, reason: FAILURE_REASON_INSUFFICIENT_BALANCE when trying to use the channel.

Definitely something up here. Thanks for the debugging work too! This should be helpful.