Payment failures after start

[breez]

Payment failures after start

[roeierez]

To me it sounds like the node didn't accomplish its peer connection to the LSP. @cdecker does it sound like the issue here? We can ask @dangeross for logs if needed.
Also @cdecker what do you think is the preferred way to solve this? We could poll for the LSP peer connection and block the pay attempt until it is established but just wondering if it make sense to do something on the plugin side. For example the plugin can have some grace period for the peers to connect (at least one connection) before attempting to pay (we know it is going to fail without connected peers).

[roeierez]

2023-04-12T09:36:41.937Z [DEBUG] SessionStore: SAT070 paySessionInvoice: pr=lnbc32907300p1pjrv7afpp5eultr29pdl0tdxqdy9uql6vumgv2wgtz7zx3sd083rz7p00lcw3qdz22dshg6tdda6x7w3qxajnxdphvg6njtt9xesnytf5xcukytfe8qux2tf5xd3rjc33vejrgdr9vccqzpgxqrrsssp5w96h9w5840p8n7hdk6j6cxvm97ch3pndauv07u8qa5sjv4elwj6q9qyyssqup5a02fvwqrheu9tp8nvx0ylucldz373h6mxedqnlwr5l4elns5rjk3yt60u3xrtzcsnxhzk886869frcpmetaejz882xmr00dakcasp5t2fvm sig=rdrp81s7wgdksdqoxtcyhgmsoymtya6bzzif4yg6zt39wkbgguda1w99di4bb4nkuitw33ckzcwsx8qwtc5dzkkmgiw4pr9x6r1dhfj6
2023-04-12T09:36:43.775Z [DEBUG] LightningStore: SAT0062: paymentFailed : {"bolt11":{"routingHints":[],"timestamp":1681292201,"paymentHash":"cf3eb1a8a16fdeb6980d21780fe99cda18a72162f08d1835e788c5e0bdffc3a2","expiry":3600,"descriptionHash":null,"description":"Satimoto: 7e347b59-e6a2-469b-988e-43b9b1fd44ef","payeePubkey":"0272910e9cbc98295093d3e4490a4c89c00f024e08cec7cf75d635a6005eefa2b5","paymentSecret":[113,117,114,186,135,171,194,121,250,237,182,165,172,25,155,47,177,120,134,109,239,24,255,112,224,237,33,38,87,63,116,180],"amountMsat":3290730,"bolt11":"lnbc32907300p1pjrv7afpp5eultr29pdl0tdxqdy9uql6vumgv2wgtz7zx3sd083rz7p00lcw3qdz22dshg6tdda6x7w3qxajnxdphvg6njtt9xesnytf5xcukytfe8qux2tf5xd3rjc33vejrgdr9vccqzpgxqrrsssp5w96h9w5840p8n7hdk6j6cxvm97ch3pndauv07u8qa5sjv4elwj6q9qyyssqup5a02fvwqrheu9tp8nvx0ylucldz373h6mxedqnlwr5l4elns5rjk3yt60u3xrtzcsnxhzk886869frcpmetaejz882xmr00dakcasp5t2fvm"},"nodeId":"0272910e9cbc98295093d3e4490a4c89c00f024e08cec7cf75d635a6005eefa2b5","error":"status: Internal, message: "error calling RPC: RPC error response: RpcError { code: 210, message: \"Destination 0272910e9cbc98295093d3e4490a4c89c00f024e08cec7cf75d635a6005eefa2b5 is not reachable directly and all routehints were unusable.\", data: None }", details: [], metadata: MetadataMap { headers: {"content-type": "application/grpc", "date": "Wed, 12 Apr 2023 09:36:43 GMT", "content-length": "0"} }"}
...
2023-04-12T09:37:42.389Z [DEBUG] SessionStore: SAT070 paySessionInvoice: pr=lnbc65875760p1pjrv7l9pp5zrq29zrnck6aaeqw2y50tdu7nvlfxpsvytfxj7evllp8jl6r669qdz22dshg6tdda6x7w3qxajnxdphvg6njtt9xesnytf5xcukytfe8qux2tf5xd3rjc33vejrgdr9vccqzpgxqrrsssp5lvxf4j7s63z65vke60sy22ch46udn6wa4fy0zh5nglctmzwq7qzq9qyyssqukqtryqd3lygfjpa4f0fv72srnphxag872fhk2kusjtnnr69hgtpklzewfav54c8gm2x7dzfw3sz49ys7puy20ea4d9jm3aqevcknesq0h2zy3 sig=rngg468bqpuqaom15t1jekazafwykc879unxgntn4kec7s5m1ybue61czhatk8nf5jna3xf95nktws9r9mrx3b4t85yybnzkc68uim5i
2023-04-12T09:37:44.287Z [DEBUG] LightningStore: SAT0062: paymentFailed : {"bolt11":{"routingHints":[],"timestamp":1681292261,"paymentHash":"10c0a28873c5b5dee40e5128f5b79e9b3e93060c22d2697b2cffc2797f43d68a","expiry":3600,"descriptionHash":null,"description":"Satimoto: 7e347b59-e6a2-469b-988e-43b9b1fd44ef","payeePubkey":"0272910e9cbc98295093d3e4490a4c89c00f024e08cec7cf75d635a6005eefa2b5","paymentSecret":[251,12,154,203,208,212,69,170,50,217,211,224,69,43,23,174,184,217,233,221,170,72,241,94,147,71,240,189,137,192,240,4],"amountMsat":6587576,"bolt11":"lnbc65875760p1pjrv7l9pp5zrq29zrnck6aaeqw2y50tdu7nvlfxpsvytfxj7evllp8jl6r669qdz22dshg6tdda6x7w3qxajnxdphvg6njtt9xesnytf5xcukytfe8qux2tf5xd3rjc33vejrgdr9vccqzpgxqrrsssp5lvxf4j7s63z65vke60sy22ch46udn6wa4fy0zh5nglctmzwq7qzq9qyyssqukqtryqd3lygfjpa4f0fv72srnphxag872fhk2kusjtnnr69hgtpklzewfav54c8gm2x7dzfw3sz49ys7puy20ea4d9jm3aqevcknesq0h2zy3"},"nodeId":"0272910e9cbc98295093d3e4490a4c89c00f024e08cec7cf75d635a6005eefa2b5","error":"status: Internal, message: "error calling RPC: RPC error response: RpcError { code: 210, message: \"Destination 0272910e9cbc98295093d3e4490a4c89c00f024e08cec7cf75d635a6005eefa2b5 is not reachable directly and all routehints were unusable.\", data: None }", details: [], metadata: MetadataMap { headers: {"content-type": "application/grpc", "date": "Wed, 12 Apr 2023 09:37:43 GMT", "content-length": "0"} }"}
...
2023-04-12T09:38:42.661Z [DEBUG] SessionStore: SAT070 paySessionInvoice: pr=lnbc32924450p1pjrvlpppp59za907hkpy5jhwr6nf995c9wehczasgj9y5un8xv5pkvsn3pwwysdz22dshg6tdda6x7w3qxajnxdphvg6njtt9xesnytf5xcukytfe8qux2tf5xd3rjc33vejrgdr9vccqzpgxqrrsssp54ws73eqxd0h64f2s7m69qasu8sctf6fvg5vw4ghrvtsfxgsqwkws9qyyssqgqucq3yzehzpc4af48zfcgzygu8kjv2g7lxtmaekcagr5wg74jdr2hs496pawyy77uukr2x3af0yga4df32r98wqg3e3hs65j9zlwmqp7kxcp4 sig=rdi61yxy7y9t6sythysfx7tio3drd39snzkpqnjsq5aeary63gfrgecrn7zoji8txp7o7s8tikj9pjtn5zhy3b6i4s6pcgwi4oapyadz
2023-04-12T09:38:44.323Z [DEBUG] LightningStore: SAT0062: paymentFailed : {"bolt11":{"routingHints":[],"timestamp":1681292321,"paymentHash":"28ba57faf609292bb87a9a4a5a60aecdf02ec1122929c99ccca06cc84e217389","expiry":3600,"descriptionHash":null,"description":"Satimoto: 7e347b59-e6a2-469b-988e-43b9b1fd44ef","payeePubkey":"0272910e9cbc98295093d3e4490a4c89c00f024e08cec7cf75d635a6005eefa2b5","paymentSecret":[171,161,232,228,6,107,239,170,165,80,246,244,80,118,28,60,48,180,233,44,69,24,234,162,227,98,224,147,34,0,117,157],"amountMsat":3292445,"bolt11":"lnbc32924450p1pjrvlpppp59za907hkpy5jhwr6nf995c9wehczasgj9y5un8xv5pkvsn3pwwysdz22dshg6tdda6x7w3qxajnxdphvg6njtt9xesnytf5xcukytfe8qux2tf5xd3rjc33vejrgdr9vccqzpgxqrrsssp54ws73eqxd0h64f2s7m69qasu8sctf6fvg5vw4ghrvtsfxgsqwkws9qyyssqgqucq3yzehzpc4af48zfcgzygu8kjv2g7lxtmaekcagr5wg74jdr2hs496pawyy77uukr2x3af0yga4df32r98wqg3e3hs65j9zlwmqp7kxcp4"},"nodeId":"0272910e9cbc98295093d3e4490a4c89c00f024e08cec7cf75d635a6005eefa2b5","error":"status: Internal, message: "error calling RPC: RPC error response: RpcError { code: 210, message: \"Destination 0272910e9cbc98295093d3e4490a4c89c00f024e08cec7cf75d635a6005eefa2b5 is not reachable directly and all routehints were unusable.\", data: None }", details: [], metadata: MetadataMap { headers: {"content-type": "application/grpc", "date": "Wed, 12 Apr 2023 09:38:44 GMT", "content-length": "0"} }"}
...

On a second look on these 3 log lines I see the failure happens after two minutes of the node running so I am not sure what I said about the LSP connection is the case here.
@dangeross all invoices are paying to the same peer?

[dangeross]

Paying to the same node, the node is peered/has a channel with the breezc node.

[roeierez]

@dangeross Can you elaborate on that destination node? is the destination node is running the sdk? Or is it running on a desktop always connected?

[dangeross]

@roeierez it's running on voltage, so should be always online

[dangeross]

You can filter Satimoto entries with : SAT otherwise entries are from the SDK. You should find 4 or 5 payment attempts of the same invoice over 4 or 5 minutes, all resulting in failures: Ran out of routes to try after 32 attempts

com.satimoto.debug-2023-04-18.1.log
com.satimoto.debug-2023-04-18.2.log
com.satimoto.debug-2023-04-18.3.log
com.satimoto.debug-2023-04-18.4.log
com.satimoto.debug-2023-04-18.5.log
com.satimoto.debug-2023-04-18.6.log
com.satimoto.debug-2023-04-18.7.log
com.satimoto.debug-2023-04-18.8.log
com.satimoto.debug-latest.log

[dangeross]

First successful payment came though today after closing the direct LSP channel (a week ago). I'm not sure if it's related to the original issue, but its looking better

[roeierez]

Thanks for the update. @cdecker has updated in the greenlight issue that the graph is catching up so maybe this is the result of this. We will test ourselves as well.

[cdecker]

Indeed the "Destination xyz is not directly reachable and we don't have any usable routehints" error is usually indicative of an incomplete view of the network, and likely due to the gossip view being incomplete or not done at the time of the pay call. Should most likely have been partially addressed by Blockstream/greenlight#122 and will be fully fixed by a small delay that waits for gossip sync to complete addressing Blockstream/greenlight#126

[ok300]

@dangeross does it now work for paying to Voltage?

I'm seeing similar behavior (Ran out of routes to try after XYZ tries) even when trying to send to Breez mobile.

[dangeross]

Yes, payments are going through now since @cdecker started to run a gossipd to keep the graph in sync. This github issue is related to when the node is started and even though it is synced, the node and LSP channel is not quite ready for sending payments.

[ok300]

Thanks. How long does it take the node to be ready, in your experience? From the moment it's started and sync-ed, until it can reliably send payments?

[dangeross]

In the tests in the logs above it was taking 9-16 minutes before a successful payment. Thats when the node was offline of several hours before. Not sure if something changed since then but I'll try to do a retest on my side next week.

[dangeross]

Well, just zapped someone after 20 seconds of opening the app, so 🤷. Node was offline since Friday.

[roeierez]

In the tests in the logs above it was taking 9-16 minutes before a successful payment. Thats when the node was offline of several hours before. Not sure if something changed since then but I'll try to do a retest on my side next week.

minutes or seconds?

[dangeross]

Minutes. You can see in the first comment above

[ok300]

I see, thanks.

For me, sending small amounts works almost immediately (tested 5k). But sending anything 50k sats or above fails even 30 minutes later, and even after an explicit sync. Funny part is, sending up to 50k works (like 49k).

It cannot be the liquidity of the recipient node, because sending 50k to the same node (WoS) from Breez mobile works.