lncli payinvoice fails to return after > 1 hour with Payment status: IN_FLIGHT

Background

Sometimes a payment doesn't go through and lncli payinvoice doesn't ever return.

Your environment

version of lnd: lnd version 0.13.1-beta commit=v0.13.1-beta
which operating system (uname -a on *Nix): Linux [redacted] 5.10.17-v7l+ [hash]1421 SMP Thu May 27 14:00:13 BST 2021 armv7l GNU/Linux
version of btcd, bitcoind, or other backend: Bitcoin Core version v0.21.1
hardware: Rpi4
network; tor as well as direct ip4 behind nat

Steps to reproduce

lncli payinvoice lnbc1500n1pssp9g5pp5x22x29d3869u2hs5zqt7ryck48v6j52r64yqxe878nk33zwkq45qdqqcqzpgxqyz5vqsp5fxl8wudn7a92v8cypr5wrnlhtfa5veh5xgsfm2830653fm62my7s9qyyssqgqsq2u89286m9kjj4xhg5m4xax45jxfj3gqz3tans2qm3zsvz5dq9476p2yr6mjfklzcamerls95e2t93gasx8jh20r08tx5z48dh4sqylf4hg --outgoing_chan_id 761420598380789760

Expected behaviour

It should either:

Successfully pay
Exit with some error message after a "reasonable" time
Give ongoing status updates if it is waiting or retrying

I realize "reasonable" is debatable but suggest that >1 hour is not reasonable.

Actual behaviour

Payment hash: 32946515b13e8bc55e141017e19316a9d9a95143d5480364fe3ced1889d60568
Description:
Amount (in satoshis): 150
Fee limit (in satoshis): 150
Destination: 037cc5f9f1da20ac0d60e83989729a204a33cc2d8e80438969fadf35c1c5f1233b
Confirm payment (yes/no): yes
+------------+--------------+--------------+--------------+-----+----------+----------+-------+
| HTLC_STATE | ATTEMPT_TIME | RESOLVE_TIME | RECEIVER_AMT | FEE | TIMELOCK | CHAN_OUT | ROUTE |
+------------+--------------+--------------+--------------+-------+----------+--------------------+-------------------------------------------------------------------------------------------------------------------+
| HTLC_STATE | ATTEMPT_TIME | RESOLVE_TIME | RECEIVER_AMT | FEE   | TIMELOCK | CHAN_OUT           | ROUTE                                                                                                             |
+------------+--------------+--------------+--------------+-------+----------+--------------------+-------------------------------------------------------------------------------------------------------------------+
| IN_FLIGHT  |        1.658 |            - | 150          | 1.118 |   693618 | 761420598380789760 | Turgidson-Plebnet->PLEBNET.org - South Africa->Lightning.Watch->BliksemKnooppunt->SilentBob->037cc5f9f1da20ac0d60 |
+------------+--------------+--------------+--------------+-------+----------+--------------------+-------------------------------------------------------------------------------------------------------------------+
Amount + fee:   0 + 0 sat
Payment hash:   32946515b13e8bc55e141017e19316a9d9a95143d5480364fe3ced1889d60568
Payment status: IN_FLIGHT

Invoice was created at 1627428116 and I 'immediately' (less than a few minutes) tried to pay it.

The time is now 1627434264 and the lncli payinvoice has still not returned.

Log for the time range don't show anything interesting related to this attempted payment.

2021-07-28 07:20:29.965 [INF] NTFN: New block: height=692983, sha=0000000000000000000be7d6640a7dc2226c26dc573ef540152b2a58dedd78ab
2021-07-28 07:20:29.965 [INF] UTXN: Attempting to graduate height=692983: num_kids=0, num_babies=0
2021-07-28 07:22:17.253 [INF] NTFN: New block: height=692984, sha=0000000000000000001096e371423cfd8137f72a35c83df1b239f7cf2cb0978d
2021-07-28 07:22:17.253 [INF] UTXN: Attempting to graduate height=692984: num_kids=0, num_babies=0
2021-07-28 07:23:57.227 [INF] NTFN: New block: height=692985, sha=000000000000000000130c905e68142852c980a6bed401e458443e9712b47b7f
2021-07-28 07:23:57.228 [INF] UTXN: Attempting to graduate height=692985: num_kids=0, num_babies=0
2021-07-28 07:46:09.137 [ERR] RPCS: [/lnrpc.Lightning/GetNodeInfo]: rpc error: code = NotFound desc = unable to find node
2021-07-28 07:53:43.357 [INF] NTFN: New block: height=692986, sha=0000000000000000000a7acf91b3640eaa5554527481cf56cfe6eb7c411071bd
2021-07-28 07:53:43.359 [INF] UTXN: Attempting to graduate height=692986: num_kids=0, num_babies=0
2021-07-28 08:00:18.216 [INF] NTFN: New block: height=692987, sha=0000000000000000000734c1458b94fff6b5e41de339f898047507c6dddea5ce
2021-07-28 08:00:18.217 [INF] UTXN: Attempting to graduate height=692987: num_kids=0, num_babies=0
2021-07-28 08:27:10.128 [INF] NTFN: New block: height=692988, sha=0000000000000000000e294ae4ec1ff342960043cff177a9ddc19f9005db2a16
2021-07-28 08:27:10.128 [INF] UTXN: Attempting to graduate height=692988: num_kids=0, num_babies=0
2021-07-28 08:33:49.658 [INF] NTFN: New block: height=692989, sha=00000000000000000002cc0d5f96069af8b9dcaa0faa8de22e310157ce5ebc13
2021-07-28 08:33:49.660 [INF] UTXN: Attempting to graduate height=692989: num_kids=0, num_babies=0
2021-07-28 08:34:27.939 [INF] NTFN: New block: height=692990, sha=00000000000000000007f4e0c2628c2b76da3981d7bc5f6800386238a003d419
2021-07-28 08:34:27.941 [INF] UTXN: Attempting to graduate height=692990: num_kids=0, num_babies=0
2021-07-28 08:37:10.481 [INF] NTFN: New block: height=692991, sha=000000000000000000018ab58751faa3e57dbeae7800637014fd860b184b4425
2021-07-28 08:37:10.482 [INF] UTXN: Attempting to graduate height=692991: num_kids=0, num_babies=0
2021-07-28 08:44:28.893 [INF] NTFN: New block: height=692992, sha=0000000000000000000c3988bf4f58a374469b6b89ea2d29437675c362d8a3f6
2021-07-28 08:44:28.894 [INF] UTXN: Attempting to graduate height=692992: num_kids=0, num_babies=0

I presume lncli successfully connected to lnd otherwise how did it plan a route.

My network connectivity to tor is bad, and the channel I have specifically set for first hop is tor, therefore it is not suprising or unexpected that a transaction fail.

But I suggest some error, or status, or exit should happen.

If you do listchannels, do you see that pending HTLC for the payment? If so, then there's nothing abnormal here (AFAICT), other than the very long path the HTLC took through the network. If for example, a peer in the path doesn't have a stable connection to their other peers (say due to some weird Tor connectivity issue), then the HTLC would sit there until: they forwarded it, they cancelled it back, someone went on chain to time it out. I'd make sure you also have proper p2p connectivity, as if you can't yourself maintain stable connections, then things may be more unreliable.

As far as the 1 hr thing, there is in fact a default timeout of a few minutes, but that's only hit once we have no active HTLCs. If you send out an HTLC, then the very next hop ends up holding it for 1 hr for some reason, we can't safely considered the payment non-existent since we have an active HTLC for it.

I'm not sure how to interpret the listchannels:

lncli listchannels
{
    "channels": [
        {
            "active": true,
            "remote_pubkey": "033b4b17a264d3a476632224929ec5c7a037b0d2e7daf33a3709aed2177a89976a",
            "channel_point": "432ce4b0659806c382e10ea7f177a2f6e1c066fb4159bd42fe86ebdf33790d65:0",
            "chan_id": "761499763243089920",
            "capacity": "20000",
            "local_balance": "9687",
            "remote_balance": "9129",
            "commit_fee": "1184",
            "commit_weight": "724",
            "fee_per_kw": "1635",
            "unsettled_balance": "0",
            "total_satoshis_sent": "9129",
            "total_satoshis_received": "0",
            "num_updates": "35",
            "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": "46833",
            "uptime": "46830",
            "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
            }
        },
        {
            "active": true,
            "remote_pubkey": "0381de1709efbda38f9afd2d47399caa19a2630c0c795acd24755efa442685fc7d",
            "channel_point": "4d312a3b5e2c8a05bc4d4f188e59cd613424a5c3d6803ef6bfb9ec80151e9403:0",
            "chan_id": "761420598380789760",
            "capacity": "20000",
            "local_balance": "18707",
            "remote_balance": "0",
            "commit_fee": "1293",
            "commit_weight": "600",
            "fee_per_kw": "1787",
            "unsettled_balance": "0",
            "total_satoshis_sent": "0",
            "total_satoshis_received": "0",
            "num_updates": "28",
            "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": "46833",
            "uptime": "46738",
            "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
            }
        },
        {
            "active": false,
            "remote_pubkey": "03e691f81f08c56fa876cc4ef5c9e8b727bd682cf35605be25d48607a802526053",
            "channel_point": "7d011f9e303801794d7ee09d9c80d045eff6530f8bfad8a47adcea80630e28cb:0",
            "chan_id": "761342533114462208",
            "capacity": "20000",
            "local_balance": "7416",
            "remote_balance": "9915",
            "commit_fee": "2009",
            "commit_weight": "1116",
            "fee_per_kw": "1787",
            "unsettled_balance": "0",
            "total_satoshis_sent": "10301",
            "total_satoshis_received": "386",
            "num_updates": "57",
            "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": false,
            "commitment_type": "ANCHORS",
            "lifetime": "46833",
            "uptime": "12710",
            "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
            }
        }
    ]
}

I appreciate that bad connectivity may make strange things happen. It is confusing for the newbie like me to have no status update though. Perhaps it just needs something to indicate that things are still in progress despite the very long time delay.

Perhaps it just needs something to indicate that things are still in progress despite the very long time delay.

Yeah usually you'll see all the updates fly through, assuming different routes are actually being attempted. Looking at this output, there's no active HTLC, and the channel looks to be in a default state.

If you use lncli trackpayment to get the current payment state (for that payment hash), what's it show?


lncli trackpayment  32946515b13e8bc55e141017e19316a9d9a95143d5480364fe3ced1889d60568
+------------+--------------+--------------+--------------+-------+----------+--------------------+-------------------------------------------------------------------------------------------------------------------+
| HTLC_STATE | ATTEMPT_TIME | RESOLVE_TIME | RECEIVER_AMT | FEE   | TIMELOCK | CHAN_OUT           | ROUTE                                                                                                             |
+------------+--------------+--------------+--------------+-------+----------+--------------------+-------------------------------------------------------------------------------------------------------------------+
| IN_FLIGHT  |        1.658 |            - | 150          | 1.118 |   693618 | 761420598380789760 | Turgidson-Plebnet->PLEBNET.org - South Africa->Lightning.Watch->BliksemKnooppunt->SilentBob->037cc5f9f1da20ac0d60 |
+------------+--------------+--------------+--------------+-------+----------+--------------------+-------------------------------------------------------------------------------------------------------------------+
Amount + fee:   0 + 0 sat
Payment hash:   32946515b13e8bc55e141017e19316a9d9a95143d5480364fe3ced1889d60568
Payment status: IN_FLIGHT

Is this related to the other issue re the networking thing that was causing payments to fail?

Closing due to inactivity, appears related to networking issue user was having intermittently that has now been solved (based on a related issue). Will re-open if anything actionable appears (root cause here is peer they were trying to rebalance over wasn't online/connected).

lightningnetwork / lnd