Payment failed after about 15 min

[AlexanderVNovikov]

Issue and Steps to Reproduce

I tried to pay to Bitrefill without direct channel to this node.

lightning-cli pay lnbc1050u1pd...  hang for 15 min and failed with message { "code" : 207, "message" : "Invoice expired", "data" : { "now" : 1521921011, "expiry" : 1521921009, "getroute_tries" : 119, "sendpay_tries" : 119 } }

from logs :

2018-03-24T19:50:11.621Z lightningd(1): lightning_channeld-02dcdd7e18b80dc7fd51af34e871901c13f574e4b82325dc74c0beeada5771e8e9 chan #12: No commits outstanding after recv revoke_and_ack
2018-03-24T19:50:11.622Z lightningd(1): lightning_channeld-02dcdd7e18b80dc7fd51af34e871901c13f574e4b82325dc74c0beeada5771e8e9 chan #12: HTLC 2518[LOCAL] => RCVD_REMOVE_ACK_REVOCATION
2018-03-24T19:50:11.622Z lightningd(1): lightning_channeld-02dcdd7e18b80dc7fd51af34e871901c13f574e4b82325dc74c0beeada5771e8e9 chan #12: Sending master 1022
2018-03-24T19:50:11.622Z lightningd(1): lightning_channeld-02dcdd7e18b80dc7fd51af34e871901c13f574e4b82325dc74c0beeada5771e8e9 chan #12: UPDATE WIRE_CHANNEL_GOT_REVOKE
2018-03-24T19:50:11.622Z lightningd(1): 02dcdd7e18b80dc7fd51af34e871901c13f574e4b82325dc74c0beeada5771e8e9 chan #12: got revoke 5053: 1 changed
2018-03-24T19:50:11.622Z lightningd(1): 02dcdd7e18b80dc7fd51af34e871901c13f574e4b82325dc74c0beeada5771e8e9 chan #12: HTLC out 2518 SENT_REMOVE_ACK_COMMIT->RCVD_REMOVE_ACK_REVOCATION
2018-03-24T19:50:11.622Z lightningd(1): 02dcdd7e18b80dc7fd51af34e871901c13f574e4b82325dc74c0beeada5771e8e9 chan #12: Removing out HTLC 2518 state RCVD_REMOVE_ACK_REVOCATION REMOTEFAIL
2018-03-24T19:50:11.623Z lightningd(1): 02dcdd7e18b80dc7fd51af34e871901c13f574e4b82325dc74c0beeada5771e8e9 chan #12: htlc 2518 failed from 0th node with code 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE)
2018-03-24T19:50:11.623Z lightningd(1): Reporting route failure to gossipd: 0x1007 (WIRE_TEMPORARY_CHANNEL_FAILURE) node 02dcdd7e18b80dc7fd51af34e871901c13f574e4b82325dc74c0beeada5771e8e9 channel 511147:1361:1 update 01028ba59e7dbae1f4d750cf488a74945dba87c9a6f06e1fb5ba28b9a2e6ae971b2f37ea1c7627acbd8a39565718b758e69a34b2bf5752b2a71ff42f6d9482abca236fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d619000000000007ccab00055100015ab66f490000000e0000000000000000000003e80000000a
2018-03-24T19:50:11.623Z lightningd(1): pay(0x40e8290): Try another route
2018-03-24T19:50:11.623Z lightningd(1):jcon fd 15: Failing: Invoice expired

getinfo output

{ "id" : "0233eee439d71420e339d40f36fa66c41fe719d4b851361e63dbd9116ba1c91bfd", "port" : 9735, "address" : 
	[ 
		{ "type" : "ipv4", "address" : "XXXXXXXXX", "port" : 9735 } ], "version" : "v0.5.2-2016-11-21-2315-gf9bc035", "blockheight" : 515100, "network" : "bitcoin" }

[cdecker]

It tried 119 times to perform the payment, and when it finally reached bitrefill, the invoice was already timed out. The gossip in the network is currently rather unreliable, hence the many attempts, we are working on improving the situation.

[AlexanderVNovikov]

I tried to pay several times with the same result.
A week ago it tried 1500 times and failed too.

{ "code" : 207, "message" : "Invoice expired", "data" : { "now" : 1521394217, "expiry" : 1521394215, "getroute_tries" : 1524, "sendpay_tries" : 1524 }

Is it possible to pay now?

[cdecker]

Well it depends on your connections, if there is a path from you to the destination, without channels that are down or otherwise not working, then yes it was always possible to perform a payment.

[AlexanderVNovikov]

getroute always shows me the path.
but payment always failed...

lightning-cli getroute 024a2e265cd66066b78a788ae615acdc84b5b0dec9efac36d7ac87513015eaf6ed 108000000 1

{ "route" : 
	[ 
		{ "id" : "0265fae305778b7cb157365f70cf3a2047d2cad5c1ccc5f550c6d8a033084a8ea5", "channel" : "514010:633:0", "msatoshi" : 108002216, "delay" : 297 }, 
		{ "id" : "025e77156e4c5e1ed62f9ad113ac2115a981ee99fa05d95be9e43add7f785a9b4d", "channel" : "514291:1211:0", "msatoshi" : 108001108, "delay" : 153 }, 
		{ "id" : "024a2e265cd66066b78a788ae615acdc84b5b0dec9efac36d7ac87513015eaf6ed", "channel" : "514089:1298:0", "msatoshi" : 108000000, "delay" : 9 } ] }

[ZmnSCPxj]

getroute does not know if the path will work or not. It only proposes some path that may or may not work.

[AlexanderVNovikov]

How can I find the exact reason why the payment failed?
What can I do to try to pay? Open new channels?

[ZmnSCPxj]

The latest version of c-lightning will display failures in detail, and will limit retrying to only one minute.

Opening a channel direct to payee will let you get to your goal of paying the payee.

But to help the network, if you will run a Lightning Network node, keep it running and do not shut it down. Many failures are caused by nodes that are almost always down, making their channels unuseable to others and leading to TEMPORARY_CHANNEL_FAILURE.

[AlexanderVNovikov]

My node is online 24/7
But most of my channel now "connected" : false.
Here is the grep result for one of peers:

docker logs --tail 10000 lightning | grep "02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083"
2018-03-26T09:07:22.397Z lightningd(1): 02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Got depth change 123->124 for 3ca0e6d7c5bedb36219e0da47776542337d39a111f72d5fc8748162624191044
2018-03-26T09:07:22.452Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Got new message WIRE_ONCHAIN_DEPTH
2018-03-26T09:07:22.453Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: FUNDING_TRANSACTION/FUNDING_OUTPUT->OUR_UNILATERAL depth 124
alex@userv:~$ docker logs --tail 100000 lightning | grep "02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083"
2018-03-26T08:54:19.475Z lightningd(1): 02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Got UTXO spend for f47dff4827a474482fca2ec89c5b584b9643018ac327225ad877db0c119db169:1: 3ca0e6d7c5bedb36219e0da47776542337d39a111f72d5fc8748162624191044
2018-03-26T08:54:19.475Z lightningd(1): 02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Peer permanent failure in ONCHAIN: Funding transaction spent
2018-03-26T08:54:19.480Z lightningd(1): 02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: State changed from ONCHAIN to FUNDING_SPEND_SEEN
2018-03-26T08:54:19.486Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: pid 13100, msgfd 18
2018-03-26T08:54:21.038Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Tracking output 1 of f47dff4827a474482fca2ec89c5b584b9643018ac327225ad877db0c119db169: FUNDING_TRANSACTION/FUNDING_OUTPUT
2018-03-26T08:54:21.039Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Remote per-commit point: 03dccd639f6d844b677f424153b0d3b6f2dffbfcafc699a675f08f720cb5c491ee
2018-03-26T08:54:21.039Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Old remote per-commit point: 02b0ce5447a6abc264d95cc98b0648ee061de0a5f5af4447211e5271ad314ce87e
2018-03-26T08:54:21.040Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: commitnum = 30, revocations_received = 30
2018-03-26T08:54:21.041Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: UPDATE WIRE_ONCHAIN_INIT_REPLY
2018-03-26T08:54:21.041Z lightningd(1): 02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: State changed from FUNDING_SPEND_SEEN to ONCHAIN
2018-03-26T08:54:21.138Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Initial feerate 0 to 3121
2018-03-26T08:54:21.139Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Resolved FUNDING_TRANSACTION/FUNDING_OUTPUT by OUR_UNILATERAL (3ca0e6d7c5bedb36219e0da47776542337d39a111f72d5fc8748162624191044)
2018-03-26T08:54:21.139Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Deconstructing unilateral tx: 30 using keyset:  self_revocation_key: 03a36b7fc2b0a3a818a39c4e3e843acc3443ab20bf2016dfcb93e44c9cf4636f6a self_delayed_payment_key: 03f111fbbef3f0d387fe7d2d8174b2039bebcdae39416bb4db8801ed1fbcd155c3 self_payment_key: 02e9998b70213048541f83a350ee9ba91447737b6da69174534245c0b30d7415db other_payment_key: 026cc1692273cfc6d6438479ccf8d33ad10cadb14625ce44fb80fabca3189dd7cc self_htlc_key: 03ce14bb34f367dfe674835f29b5a5cd998fc445a1388b826d660ecad0af70fa91 other_htlc_key: 03dbfd467fadcde439524b03357384049cb6f9fe01be3c617c796a85d919ab661f
2018-03-26T08:54:21.139Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Script to-me: 144: 0020304c6efdb69a932829cc4682d4af8ddad13063bd1334f3eb24e14dbb2152a8e7 (632103a36b7fc2b0a3a818a39c4e3e843acc3443ab20bf2016dfcb93e44c9cf4636f6a67029000b2752103f111fbbef3f0d387fe7d2d8174b2039bebcdae39416bb4db8801ed1fbcd155c368ac)
2018-03-26T08:54:21.140Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Script to-them: 0014df6f98f43a9efda8219fd0bade12f1a8a3b23ff4
2018-03-26T08:54:21.141Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Output 0: 0020304c6efdb69a932829cc4682d4af8ddad13063bd1334f3eb24e14dbb2152a8e7
2018-03-26T08:54:21.145Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Tracking output 0 of 3ca0e6d7c5bedb36219e0da47776542337d39a111f72d5fc8748162624191044: OUR_UNILATERAL/DELAYED_OUTPUT_TO_US
2018-03-26T08:54:21.146Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Propose handling OUR_UNILATERAL/DELAYED_OUTPUT_TO_US by OUR_DELAYED_RETURN_TO_WALLET (020000000001014410192426164887fcd5721f119ad33723547677a40d9e2136dbbec5d7e6a03c000000000090000000013b81010000000000160014e99efbf8b4c22ab70b99a97ca7c9d001031b27c103473044022059669291ef6684c91b3591ccf9d6d33a14a3f0d2cf74892f621a85b3342b93820220409b2b0c3f3e83fc528ea705f5151af19f146128cea9feca75b7912c93a3ce1101004d632103a36b7fc2b0a3a818a39c4e3e843acc3443ab20bf2016dfcb93e44c9cf4636f6a67029000b2752103f111fbbef3f0d387fe7d2d8174b2039bebcdae39416bb4db8801ed1fbcd155c368ac00000000) after 144 blocks
2018-03-26T08:55:19.914Z lightningd(1): 02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Got depth change 0->1543 for f47dff4827a474482fca2ec89c5b584b9643018ac327225ad877db0c119db169
2018-03-26T08:55:19.914Z lightningd(1): 02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Funding tx f47dff4827a474482fca2ec89c5b584b9643018ac327225ad877db0c119db169 depth 1543 of 3
2018-03-26T08:55:19.915Z lightningd(1): 02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Funding tx confirmed, but channel state ONCHAIN lightning_onchaind
2018-03-26T08:55:19.915Z lightningd(1): 02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Funding tx announce ready, but channel state ONCHAIN owned by lightning_onchaind
2018-03-26T08:55:19.915Z lightningd(1): 02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Got depth change 0->121 for 3ca0e6d7c5bedb36219e0da47776542337d39a111f72d5fc8748162624191044
2018-03-26T08:55:19.988Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Got new message WIRE_ONCHAIN_DEPTH
2018-03-26T08:55:19.988Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Sending 0 missing htlc messages
2018-03-26T08:55:19.989Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: FUNDING_TRANSACTION/FUNDING_OUTPUT->OUR_UNILATERAL depth 121
2018-03-26T09:00:21.118Z lightningd(1): 02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Got depth change 121->122 for 3ca0e6d7c5bedb36219e0da47776542337d39a111f72d5fc8748162624191044
2018-03-26T09:00:21.188Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Got new message WIRE_ONCHAIN_DEPTH
2018-03-26T09:00:21.188Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: FUNDING_TRANSACTION/FUNDING_OUTPUT->OUR_UNILATERAL depth 122
2018-03-26T09:00:51.305Z lightningd(1): 02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Got depth change 122->123 for 3ca0e6d7c5bedb36219e0da47776542337d39a111f72d5fc8748162624191044
2018-03-26T09:00:51.387Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Got new message WIRE_ONCHAIN_DEPTH
2018-03-26T09:00:51.387Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: FUNDING_TRANSACTION/FUNDING_OUTPUT->OUR_UNILATERAL depth 123
2018-03-26T09:07:22.397Z lightningd(1): 02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Got depth change 123->124 for 3ca0e6d7c5bedb36219e0da47776542337d39a111f72d5fc8748162624191044
2018-03-26T09:07:22.452Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: Got new message WIRE_ONCHAIN_DEPTH
2018-03-26T09:07:22.453Z lightningd(1): lightning_onchaind-02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 chan #1: FUNDING_TRANSACTION/FUNDING_OUTPUT->OUR_UNILATERAL depth 124

[ZmnSCPxj]

Yes, as you observe, many times peers shut down, making it difficult to route.

[CubicEarth]

@ZmnSCPxj My understanding is that nodes currently don't try very hard to maintain connections either. If a node I am connected to goes offline, and the comes back on, how would my node know?

[AlexanderVNovikov]

Sorry, but i can't understand this logs... is it my fault or peer's? As I see here https://www.robtex.com/lightning/node/02c119d2fd2e98a88f50d0d2ee4213255b7b8ec2be3a95f9aabd6afb09dd25b083 the peer is online, my node is online too. But "connected" : false in channel info. Restart node didn't solve this connection problem.

[ZmnSCPxj]

Yes, it's problematic that we do not automatically connect in case we get disconnected. We currently assume that nodes that get restarted will reconnect to us if they have a channel to us, but:

1. Some nodes running older code did not reconnect properly.
2. If the reason for losing connection is due to connectivity issue rather than shutdown, we never attempt to reconnect.

Perhaps a simple solution is to have a periodic attempt to reach channeled peers. Once a minute? Once every 5 minutes?