Delayed status updates with `pay` and `listpays` (gRPC)

[theborakompanioni]

Currently observed this behaviour while testing an application that sends out payments via pay (gRPC) and another service polling these payments via listpays (gRPC). There is a rather long delay before listpays reports the correct state after the pay request either returns COMPLETE or FAILED.

Initiating he pay request:

2023-06-12T08:39:08.724Z  WARN: Payment '70ab8e36814...' with amount '16777215001 msat' resulted in error: UNKNOWN: Error calling method Pay: RpcError { code: Some(210), message: "Ran out of routes to try after 31 attempts: see `paystatus`" }

Subequently polling the listpays gRPC endpoint, which will report PENDING for more than 70 seconds.

2023-06-12T08:39:09.699Z DEBUG: Checking payment 70ab8e36814… resulted in: PENDING.
2023-06-12T08:39:10.761Z DEBUG: Checking payment 70ab8e36814… resulted in: PENDING.
2023-06-12T08:39:11.833Z DEBUG: Checking payment 70ab8e36814… resulted in: PENDING.
[...] # polling every second (same output)
2023-06-12T08:40:18.181Z DEBUG: Checking payment 70ab8e36814… resulted in: PENDING.
2023-06-12T08:40:19.194Z DEBUG: Checking payment 70ab8e36814… resulted in: PENDING.
2023-06-12T08:40:20.228Z  INFO: Checking payment 70ab8e36814… resulted in: FAILED.

It is not big issue per se, rather an inconvenience (albeit it has real impact on UX). If this could be somehow configured, it would also massively speed up the test suite runs. I tried a few things, but to no avail.. e.g. reducing retry_for to a small number (i.e. 2 seconds) does not influence the delay.

The docs say:

You can monitor the progress and retries of a payment using the lightning-paystatus(7) command.

However, paystatus does not seem to be exposed via gRPC..

Any ideas? Is there a way to speed things up?
Any and all feedback is highly appreciated 🙏

Edit: Same happened for successful payments in previous versions, but with v23.05, it seems to update the state to COMPLETE quite quickly 🚀 (However, I might just have been lucky a few times?)

Issue and Steps to Reproduce

1. Initiate a payment via pay gRPC endpoint (e.g. one that is definitely failing)
2. Watch pay reporting the payment as FAILED
3. Start polling listpays
4. Watch listpays return PENDING for quite a while
5. Wait till listpays reports the payment as FAILED

getinfo output

Using CLN v23.05 on regtest:

$ lightning-cli --network=regtest getinfo
{
   "id": "0213c5927a0045bcf53c3c8ea04cf3e230ee3f066ca6ea3b2fcce95e8da471d191",
   "alias": "cln1-integration-test",
   "color": "0213c5",
   "num_peers": 1,
   "num_pending_channels": 0,
   "num_active_channels": 1,
   "num_inactive_channels": 0,
   "address": [],
   "binding": [
      {
         "type": "ipv6",
         "address": "::",
         "port": 19846
      },
      {
         "type": "ipv4",
         "address": "0.0.0.0",
         "port": 19846
      }
   ],
   "version": "v23.05",
   "blockheight": 123,
   "network": "regtest",
   "fees_collected_msat": 0,
   "lightning-dir": "/home/clightning/.lightning/regtest",
   "our_features": {
      "init": "08a0000a0269a2",
      "node": "88a0000a0269a2",
      "channel": "",
      "invoice": "02000002024100"
   }
}

[vincenzopalazzo]

Ok I am updating my answer because it was wrong :)

I do not know the correct way to speed up the tests, but from the docs looks like there is another parameter other than retry_for that is maxdelay. Maybe you can set it to 0? or 1.

Until retry_for seconds passes (default: 60), the command will keep finding routes and retrying the payment. However, a payment may be delayed for up to maxdelay blocks by another node; clients should be prepared for this worst case.

Edit: Same happened for successful payments in previous versions, but with v23.05, it seems to update the state to COMPLETE quite quickly rocket (However, I might just have been lucky a few times?)

Yeah pay command is not deterministic so in here may be involved luck imho

[theborakompanioni]

Ok I am updating my answer because it was wrong :)

Please excuse the late response.

I do not know the correct way to speed up the tests, but from the docs looks like there is another parameter other than retry_for that is maxdelay. Maybe you can set it to 0? or 1.

Yeah pay command is not deterministic so in here may be involved luck imho

I am testing on a local regtest network and can basically control everything. I exclusively invoke commands via gRPC if that makes any difference.

Setting maxdelay does not seem to have any effect on the behaviour. Generally I thought I somewhat knew what the param was doing but from the description alone I am not totally sure anymore.
I assumed it is the maximum acceptable cltv expiry delta for the selected route?

The behaviour described in the issue was at the very beginning of bootstrapping a regtest network (using CLN nodes exclusively) in an integration test suite.
The steps are always the same: Mine blocks to nodes that open channels, mature the blocks, open the channels, mature the channels, wait for block synchronization (btw. this alone takes quite a while for such a small network as CLN seems to take rather long syncing to the chain tip, as opposed to LND which is quite fast in this regard).

This the network that is created:

flowchart TB
   app -->|16_777_215 sat| alice
   app -->|8_388_607 sat| bob
   bob -->|4_194_303 sat| charlie
   app ~~~ dave
   alice ~~~ dave
   bob ~~~ dave
   charlie ~~~ dave

Loading

Then attempt a payment greater than any single outgoing channel (16_777_215_001 msat) from node APP.

I first assumed the problems stem from not having given the network enough time to sync the channel graph. The setup can now optionally wait till a route from APP to CHARLIE is available.

Having said that, the behaviour is different, when I am trying to pay to a peer I am not directly connected (i.e. from APP to CHARLIE):

At first, it will respond with "Destination X is not reachable directly and all routehints were unusable." and no entry in listPays (error code 210).

Payment with hash 'a40f7c5d....' and amount '16777215001 msat' resulted in error: UNKNOWN: Error calling method Pay: RpcError { code: Some(210), message: "Destination 027b586c6... is not reachable directly and all routehints were unusable." }

.. but after some time, I assume, when the channel graph is synced, it responds with "Ran out of routes to try after X attempts: see paystatus" and with an corresponding entry when calling listPays:

Payment with hash '76c7693...' and amount '16777215001 msat' resulted in error: UNKNOWN: Error calling method Pay: RpcError { code: Some(210), message: "Ran out of routes to try after 31 attempts: see `paystatus`" }

Then, the state is switched to FAILED rather quickly in listPays (less than 3 seconds!).
Note: paystatus is not available via gRPC.. : (

I guess one can argue, that this is expected behaviour till here, right?

However, if I do the same for a direct channel partner (i.e. from APP to ALICE), the behaviour is different:
The amount is too much to be sent via the channel, it responds with "Ran out of routes to try after X attempts: see paystatus" and with an corresponding entry when calling listPays:

Payment with hash '7dea44d...' and amount '16777215001 msat' resulted in error: UNKNOWN: Error calling method Pay: RpcError { code: Some(210), message: "Ran out of routes to try after X attempts: see `paystatus`" }

Here, the state will be reported as PENDING and takes a rather long time to switch to FAILED (>70 seconds).

After some time - again, I assume when the channel graph is synced - it will still do the same, i.e. respond with "Ran out of routes to try after X attempts: see paystatus" and take a lot of time to switch from PENDING to FAILED (>70 seconds).

So tl;dr:

• Peers without direct channel (graph not synced): "Destination not reachable"; without entry in listPays
• Peers without direct channel (graph synced): "Ran out of routes"; with entry in listPays; fast switching from PENDING to FAILED
• Peers with direct channel (graph not synced): "Ran out of routes"; with entry in listPays; slow switching from PENDING to FAILED
• Peers with direct channel (graph synced): "Ran out of routes"; with entry in listPays; slow switching from PENDING to FAILED

Direct channel?	Graph synced?	Entry in listPays?	Speed of state update
No	No	No	-
No	Yes	Yes	Fast
Yes	No	Yes	Slow (>70s)
Yes	Yes	Yes	Slow (>70s)

I can't really make sense of the different behavior with direct channel partners yet.. Do you know what is going on?