`lightning-cli pay` and `lightning-cli keysend` hangs

[cjc21]

Issue and Steps to Reproduce

Just started running a CLN node using the Ubuntu 22.04 precompiled binary. Was able to send onchain to the node and open a channel to a LND node. Currently there is only one channel on the node.

However lightning-cli pay and lightning-cli keysend both hangs. This is what is shown in the logs for the keysend command. Both operations seems to always end with Can't send commit: nothing to send, feechange wanted

2022-12-07T19:24:00.580Z DEBUG   plugin-keysend: cmd 99 partid 0: Added a channel hint for 766213x507x0/0: enabled true, estimated capacity 86744000msat
2022-12-07T19:24:00.581Z DEBUG   plugin-keysend: cmd 99 partid 0: Found a direct channel (766213x507x0/0) with sufficient capacity, skipping route computation.
2022-12-07T19:24:00.581Z DEBUG   plugin-keysend: cmd 99 partid 0: Created outgoing onion for route: 766213x507x0
2022-12-07T19:24:00.582Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: NEW:: HTLC LOCAL 10 = SENT_ADD_HTLC/RCVD_ADD_HTLC 
2022-12-07T19:24:00.582Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: Adding HTLC 10 amount=10000msat cltv=766360 gave CHANNEL_ERR_ADD_OK
2022-12-07T19:24:00.582Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: peer_out WIRE_UPDATE_ADD_HTLC
2022-12-07T19:24:00.582Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: REPLY WIRE_CHANNELD_OFFER_HTLC_REPLY with 0 fds
2022-12-07T19:24:00.592Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: Trying commit
2022-12-07T19:24:00.592Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: htlc 10: SENT_ADD_HTLC->SENT_ADD_COMMIT
2022-12-07T19:24:00.592Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: htlc added REMOTE: local 88456000 remote 0
2022-12-07T19:24:00.592Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: -> local 88446000 remote 0
2022-12-07T19:24:00.593Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: sending_commit: HTLC LOCAL 10 = SENT_ADD_COMMIT/RCVD_ADD_COMMIT 
2022-12-07T19:24:00.594Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2022-12-07T19:24:00.594Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: Creating commit_sig signature 12 30440220568498c8419347c164c656f2808c26a414694074c50148b8d5b460aa1f5934c902204a784bc2e8e2c508d1b01e8cd46913de9021e0a3898d4a73ea6d1e0f9c92e03b01 for tx 020000000116a914420ba4237d48905178253f24de4888ee6cfc322f83b2e0a02a928dac0800000000006925fb80021027000000000000220020acd301ddec0c3c22e2e88f873d84ef9e6bf6bfbdd57f51dc7a4eb945de6ce350784d0100000000001600142b4f7878ecab0c87179510296c7e368d55aa589649e45a20 wscript 522102a02ba41441bd8f5be4d1bf96dced972f0d4f6040d30adb7aa474ab5e4843f71e2103f94b65db0ece83d7ba2489f1ccea884b5916ba782846f5bfc4633add5da5eecf52ae key 02a02ba41441bd8f5be4d1bf96dced972f0d4f6040d30adb7aa474ab5e4843f71e
2022-12-07T19:24:00.594Z DEBUG   hsmd: Client: Received message 19 from client
2022-12-07T19:24:00.594Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: Creating HTLC signature 304402202641742ffcaef05e107fce38836169a0d0067b470acfc1c2017bb82fc745f8c702206b22e98f81e1d500a6bb58ef0e8335ea2b50a36fe86c9dedba2af613f1ec0ab901 for tx 0200000001ee3f3c3651c8230c1396ee0b1e10c528e78fd9d27ab8f06cc138a98f3f019f4100000000000000000001a11d00000000000022002006fce034f20b6d802a634b6565b96f73a14eade946908d4ff8202fc290196eb100000000 wscript 76a914cb518310ebd23bf0897d9d619ad38e8b0ffdf9f08763ac6721026c811cc14aab5a0b4dd6c13d67ea4ef7a2cbc338b0c4dd46de757050ccf677037c8201208763a914f32bbb58dd7038ded414c4def83ecfa84e7ca91e88527c21036ef9fcbba204110478e942e3d32793959e3b1df1e02e89da16451abf8afdbf1652ae67750393b10bb175ac6868 key 026c811cc14aab5a0b4dd6c13d67ea4ef7a2cbc338b0c4dd46de757050ccf67703
2022-12-07T19:24:00.594Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-hsmd: Got WIRE_HSMD_SIGN_REMOTE_HTLC_TX
2022-12-07T19:24:00.594Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: Telling master we're about to commit...
2022-12-07T19:24:00.595Z DEBUG   hsmd: Client: Received message 20 from client
2022-12-07T19:24:00.595Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: Sending master 1020
2022-12-07T19:24:00.595Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-chan#2: HTLC out 10 SENT_ADD_HTLC->SENT_ADD_COMMIT
2022-12-07T19:24:00.601Z DEBUG   lightningd: Payment part 0/0/0 status 0
2022-12-07T19:24:00.601Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: ... , awaiting 1120
2022-12-07T19:24:00.602Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: Got it!
2022-12-07T19:24:00.602Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: Sending commit_sig with 1 htlc sigs
2022-12-07T19:24:00.602Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: peer_out WIRE_COMMITMENT_SIGNED
2022-12-07T19:24:00.813Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-hsmd: Got WIRE_HSMD_VALIDATE_REVOCATION
2022-12-07T19:24:00.813Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: peer_in WIRE_REVOKE_AND_ACK
2022-12-07T19:24:00.813Z DEBUG   hsmd: Client: Received message 36 from client
2022-12-07T19:24:00.814Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: Received revoke_and_ack
2022-12-07T19:24:00.814Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: htlc 10: SENT_ADD_COMMIT->RCVD_ADD_REVOCATION
2022-12-07T19:24:00.814Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: rcvd_revoke_and_ack: HTLC LOCAL 10 = RCVD_ADD_REVOCATION/SENT_ADD_REVOCATION 
2022-12-07T19:24:00.814Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: Commits outstanding after recv revoke_and_ack
2022-12-07T19:24:00.814Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: HTLC 10[LOCAL] => RCVD_ADD_REVOCATION
2022-12-07T19:24:00.814Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: Sending master 1022
2022-12-07T19:24:00.814Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-chan#2: got revoke 11: 1 changed
2022-12-07T19:24:00.815Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-chan#2: HTLC out 10 SENT_ADD_COMMIT->RCVD_ADD_REVOCATION
2022-12-07T19:24:00.820Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: ... , awaiting 1122
2022-12-07T19:24:00.821Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: Got it!
2022-12-07T19:24:00.821Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: revoke_and_ack LOCAL: remote_per_commit = 032347fb95a6114088bd852787d23d7c3c036b0f5f9fa0c7b467b6c04f3699a201, old_remote_per_commit = 03b6d28a095643e64cf0c43ac836330915031ccf2595bb0b0452f89aa4046b32e7
2022-12-07T19:24:00.821Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: Trying commit
2022-12-07T19:24:00.821Z DEBUG   03d74a559bb3841a11a882d7f93b4bdd3610eaf430bb468a67af3d9cfa0e96e2bf-channeld-chan#2: Can't send commit: nothing to send, feechange wanted ({ RCVD_ADD_REVOCATION:3436 SENT_ADD_ACK_REVOCATION:253 }) blockheight not wanted ({ SENT_ADD_ACK_REVOCATION:0 })

getinfo output

{
   "id": "0329113eba431be875c52968388316fe2c472b19457ef9cafe0983b0a99c5830fa",
   "alias": "SLEEPYGLEE",
   "color": "032911",
   "num_peers": 1,
   "num_pending_channels": 0,
   "num_active_channels": 1,
   "num_inactive_channels": 0,
   "address": [],
   "binding": [
      {
         "type": "ipv6",
         "address": "::",
         "port": 9735
      },
      {
         "type": "ipv4",
         "address": "0.0.0.0",
         "port": 9735
      }
   ],
   "version": "22.11",
   "blockheight": 766337,
   "network": "bitcoin",
   "msatoshi_fees_collected": 0,
   "fees_collected_msat": "0msat",
   "lightning-dir": "/home/ubuntu/.lightning/bitcoin",
   "our_features": {
      "init": "08a000080269a2",
      "node": "88a000080269a2",
      "channel": "",
      "invoice": "02000000024100"
   }
}

lsb_release -a

Distributor ID:	Ubuntu
Description:	Ubuntu 22.04.1 LTS
Release:	22.04
Codename:	jammy
ubuntu@ip-10-20-128-18

.lighting/config file

network=bitcoin
log-level=debug
log-file=/home/ubuntu/.lightning/cln.log

[cdecker]

These are synchronous calls, i.e., they only return once the entire payment process (multiple parts, potentially retried over a variety of paths) completes. This should usually last for less than 60 seconds (due to the MPP timeout being 60 seconds, and keysend may try longer).

Are you seeing it hang for longer than these 60 seconds? In that case it might be that all HTLCs for the current process have stalled (some downstream node is holding on to them), which we should probably investigate, but can't do much unilaterally.

[cjc21]

I should add that I was trying to pay an invoice generated from a direct peer (LND), so there are no hops.

New datapoints:

1. Today I found out that the only channel I opened yesterday with this LND peer was force closed
2. I reopened another channel with the same peer and tried to pay an invoice from the peer again. It hangs indefinitely
3. Under listpeer, the connected field flip flops between true and false

[cdecker]

Interesting, can you add some more logs to showcase that connection being flaky? I could immagine it could also be something holding on to the HTLC on the remote node, then flaking out the connection.

[whitslack]

I have a pay call that has been hung for about 20 hours now.

In that case it might be that all HTLCs for the current process have stalled (some downstream node is holding on to them)

Is there any way to check this assertion? paystatus says all payment attempts have "completed", yet the pay call still has not returned.

$ lightning-cli paystatus | jq '.pay[] | select(.attempts | any(.state != "completed"))'

(There is no output from the above command because all payment attempts have reached the state "completed".)

[whitslack]

My pay call has now been hung for over 43 hours. Here's the debug log of (only) that pay run…

pay.redacted.log

I'm going to interrupt the lightning-cli process that's waiting for the pay result. No idea what state that'll leave the pay plugin in.