Long payment time

[thejokoono]

Was trying out our Breez SDK integration and ran into a long payment time (~30s) again. Paid the same vendor with Phoenix within 2-3s. Node is fresh, created just a week ago. The app was open for a minute before, so the GL node should have been ready.

Unfortunately I don't have the transaction info besides the date, which was the 10th of May (only payment that day).

GL Node pubkey: 025f79af8e5961e050686029572a187b515d377056aa00837060f558c932327ae4

[cdecker]

I found 4 payments for that node, only one of them was >30s, the others were 8s, 9s, 13s, 26s, and 30s. So we'll debug the payment in session_id=7194693179805696 (the 30s one):

• 2024-05-10T15:42:06+02:00 Node scheduled in slot
  • 1 channel established
• 2024-05-10T15:42:07+02:00 Node startup completed
• 2024-05-10T15:42:09+02:00 Signer attaches, triggering reconnection
• 2024-05-10T15:42:10+02:00 Gossip sync complete
• 2024-05-10T15:42:14+02:00 Channel re-established and ready to be used
• 2024-05-10T15:43:09+02:00 Blockchain sync completes
• 2024-05-10T15:43:12+02:00 pay called, no wait required, can be let through right away
  • 2024-05-10T15:43:19+02:00 Found a rather long route 842701x1594x0 -> 828159x1405x0 -> 832222x1049x0 -> 758164x1507x1 -> 841129x787x0 -> 819140x2281x1
  • 2024-05-10T15:43:28+02:00 First HTLC fails: Intermediate node 03e691f81f08c56fa876cc4ef5c9e8b727bd682cf35605be25d48607a802526053 reported 1007 (WIRE_TEMPORARY_CHANNEL_FAILURE) at 841129x787x0 on route 842701x1594x0 -> 828159x1405x0 -> 832222x1049x0 -> 758164x1507x1 -> 841129x787x0 -> 819140x2281x1
  • New attempt with route 842701x1594x0 -> 828159x1405x0 -> 832222x1049x0 -> 758164x1507x1 -> 743343x1383x1 -> 783460x3048x4 -> 819140x2281x1
  • 2024-05-10T15:43:41+02:00 Second HTLC succeeds and is fulfilled.

One thing to note is that between the pay call and us actually having a route we spend 7 seconds waiting for the signer to preapprove the invoice:

2024-05-10T15:43:13+02:00 {} stdout: DEBUG   plugin-pay: cmd 34 partid 0: Calling preapproveinvoice on signer for payment=0
2024-05-10T15:43:18+02:00 {} 2024-05-10T13:43:18.832030Z TRACE gl_nodelet: Plugin bus message PluginNotification { notification_type: Some(RpcCall(RpcCall { methodname: "/greenlight.Node/RespondHsmRequest" })) }

So I'm tempted to blame a slow signer in this case. That in addition with a failed first attempt, and the very long routes, suffice to explain the very long payment time.

We can look into why we chose such long routes, which may be incomplete gossip, but we will always have these outliers. Notice that this is to be expected, and that comparing with fully self-contained nodes we will always we slower. The simple fact that we actually have a network hop in-between the signer and the node should make that abundantly clear. That being said, 30s is definitely outside of our target range.

We target <10s for the 99th percentile eventually, but are still quite removed from that, and are concentrating most of our energy on getting the success rates up, because time to completion becomes secondary if you have certainty that a payment will succeed.