Due to failed reconnection, paying an invoice incurs unnecessary fees.

[dscotese]

I have two nodes. I created an invoice on one and paid it from the other. I paid it from Eclair Desktop. There is a channel (575638x611x1) from my Eclair node to my other node (MemeracingLN). Eclair says MemeracingLN is offline. However, MemeracingLN was the target of the payment and the invoice has been settled on the MemeracingLN node.

Eclair (Desktop, v 0.3) paid an invoice to a node without using its direct channel to that node because the node is recorded in EClair as offline.

If we are paying a node to which we have a channel then use the channel, and if the channel is offline, try a simple connection to it, and if that doesn't work, ask the user.

I have not attempted to reproduce. I would expect the code is written to have the behavior I got, simply because the reliability of the OFFLINE indication was assumed to be high. It isn't, so I propose the following solution:

Before finding a route to the receiving node, check if we have a channel to it and if so, do not route. Instead:

1. Is the channel online?
   1. Yes - negotiate the payment with the channel.
   2. No - Attempt a "simple connection" to the receiving node. Did it succeed?
      1. Yes - Go back to step 1.
      2. No - Return an error: "Receiving node is OFFLINE." - Optionally, allow the user to have Eclair route the payment anyway.

I am on Windows 10 using JDK 11.

[araspitzu]

Hi, how about investigating why the node was seen offline by your eclair desktop? Eclair will try to reconnect to a known peer and if it can't then it's worth investigating why, perhaps the MemeracingLN node change its IP address? Note that if the receiving node is really OFFLINE you won't be able to pay anyway.

[dscotese]

TL;DR: The connection was closed at 01:14:18,669, re-established at 08:50:53,868 and then the peer closed it at 08:50:53,991, and then "got new transport while already connected, switching to new transport" at 08:50:53,995, but ultimately lost the connection at 08:50:53,996. After that last loss there are NO attempts to re-establish the connection.

Here are the log entries containing the node ID of the receiver before the payment was attempted:

2019-05-13 01:14:18,669 INFO  f.a.e.c.TransportHandler  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - connection closed: PeerClosed
2019-05-13 01:14:18,670 INFO  fr.acinq.eclair.io.Peer  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - lost connection to 0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab
2019-05-13 01:14:19,679 INFO  f.acinq.eclair.io.Client  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - connecting to 172.81.183.236:9735
(entry not containing receiving node ID)
2019-05-13 01:14:20,980 INFO  f.acinq.eclair.io.Client  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - connection failed to 172.81.183.236:9735
(entries not containing receiving node ID)
2019-05-13 01:14:30,700 INFO  f.acinq.eclair.io.Client  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - connecting to 172.81.183.236:9735
2019-05-13 01:14:31,973 INFO  f.acinq.eclair.io.Client  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - connection failed to 172.81.183.236:9735

Several repeats of the attempt and failure entries for seven hours or so, and then success:

2019-05-13 08:50:53,868 INFO  f.acinq.eclair.io.Server  - connected to /172.81.183.236:52996
2019-05-13 08:50:53,991 INFO  f.a.e.io.Authenticator  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - connection authenticated with 0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab@172.81.183.236:52996 direction=incoming
2019-05-13 08:50:53,991 INFO  f.a.e.c.TransportHandler  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - connection closed: PeerClosed
2019-05-13 08:50:53,995 INFO  fr.acinq.eclair.io.Peer  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - got new transport while already connected, switching to new transport
2019-05-13 08:50:53,996 INFO  fr.acinq.eclair.io.Peer  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - using globalFeatures= and localFeatures=10001010
2019-05-13 08:50:53,996 WARN  fr.acinq.eclair.io.Peer  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - lost connection to 0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab

My connection is kind of spotty (as you see automatic connection failed for seven hours). There are no other log entries with that node ID until several (I assume) normal log entries (regarding sending through the channel we have open) and then this:

2019-05-13 17:13:42,218 INFO  f.a.e.channel.Channel  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab c:29ebf754f2915b61112aa7946c5b4c50e0a81ad3bc34d2be3b298132b69a75f8 - rejecting htlc request in state=OFFLINE
2019-05-13 17:13:42,218 INFO  f.a.e.channel.Channel  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab c:29ebf754f2915b61112aa7946c5b4c50e0a81ad3bc34d2be3b298132b69a75f8 - updating channel_update announcement (reason=disabled)
2019-05-13 17:13:42,224 INFO  f.a.e.channel.Channel  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab c:29ebf754f2915b61112aa7946c5b4c50e0a81ad3bc34d2be3b298132b69a75f8 - emitting channel_update=ChannelUpdate(ByteVector(71 bytes, 0x304402204ee0a6c65e377a5225a95f2544c49434c49fec48e89c33ef48d1ca140dd64ed102204abcb3a9846a76e125178b3882ea7be1b944116bd6def416089679a9aa9e5d8801),6fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d6190000000000,575638x611x1,1557792822,1,2,144,1000,3,1,Some(5000000000)) enabled=false 
2019-05-13 17:13:42,224 INFO  f.a.e.channel.Channel  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab c:29ebf754f2915b61112aa7946c5b4c50e0a81ad3bc34d2be3b298132b69a75f8 - rejecting htlc request in state=OFFLINE
2019-05-13 17:13:42,263 ERROR f.a.e.channel.Channel  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab c:29ebf754f2915b61112aa7946c5b4c50e0a81ad3bc34d2be3b298132b69a75f8 - cannot add htlc with origin=Local(0fb2594a-9129-47bd-a096-f956d45a34e8,Some(Actor[akka://eclair-node-gui/user/$n/payment-initiator/$a#-213881032])) reason=channel is unavailable (offline or closing) while processing cmd=CMD_ADD_HTLC in state=OFFLINE

...and then, 14 minutes later, because I manually asked to open a simple connection:

2019-05-13 17:27:41,974 INFO  f.a.eclair.gui.Handlers  - opening a connection to nodeUri=0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab@172.81.183.236:9735
2019-05-13 17:27:41,980 INFO  f.acinq.eclair.io.Client  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - connecting to 172.81.183.236:9735
2019-05-13 17:27:42,098 INFO  f.acinq.eclair.io.Client  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - connected to 172.81.183.236:9735
2019-05-13 17:27:42,212 INFO  f.a.e.io.Authenticator  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - connection authenticated with 0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab@172.81.183.236:9735 direction=outgoing
2019-05-13 17:27:42,212 INFO  fr.acinq.eclair.io.Peer  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - using globalFeatures= and localFeatures=10001010
2019-05-13 17:27:42,328 INFO  fr.acinq.eclair.io.Peer  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - peer is using globalFeatures= and localFeatures=10000001
2019-05-13 17:27:42,328 INFO  fr.acinq.eclair.io.Peer  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - 0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab has features: initialRoutingSync=false channelRangeQueriesOptional=true channelRangeQueriesMandatory=false
2019-05-13 17:27:42,330 INFO  fr.acinq.eclair.io.Peer  n:0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab - rebroadcast will be delayed by 27 seconds
2019-05-13 17:27:42,330 INFO  f.a.eclair.gui.Handlers  - connection to 0352a8d174efa5a2be99748e135d451617a5d50ead71d9b045d28915ad86b5d4ab@172.81.183.236:9735 successful

So, YES, there is a good reason that the receiver was offline (the sender's connection to it was spotty), but after the connection loss at 2019-05-13 08:50:53,996, there is no log entry with the receiving node's ID (which I interpret to mean no attempt to re-establish a connection).

From this I interpret one bug:

1. Getting "new transport" around the same time as authentication and then losing a connection doesn't result in attempts to re-establish the connection.

... and one possible enhancement to handle the situation where:

1. Eclair is waiting to try to re-establish a connection to an existing channel partner
2. The user attempts to send to that partner before the connection is re-established.

[araspitzu]

Eclair tries to reconnect to the peers of which it knows the address and only if there are non-closed channel with them, the reconnection attempt happens at increasingly large delays (max delay is 60s). Unfortunately when the connection is initiated by remote then eclair doesn't store the IP address, looking at your logs i see eclair trying to connect to remote until 2019-05-13 08:50:53,868 the first line of your second log, here the connection is initiated by remote and after it fails (spotty connection?) eclair won't try anymore because it lost the address of the peer. This is a known behavior and we're aiming at improving it, namely reading the peer's address from the node_announcement messages.

[dscotese]

I don't know how long you'd have to wait to get a node_announcement message, but if the eclair database local_channels table had a "connection" field, then we would have every existing local channel's connection info (IP and port) so that channels could be maintained under spotty connection situations even if the remote initiated the failed connection. This relatively small amount of data (18 bytes per channel) seems a small price to pay for the benefit. Lightning wallets should be able to use the channels to their favorite services without incurring fees even if they are spotty connections. Here's what I found:

eclair-core/src/main/scala/fr/acinq/eclair/db/sqlite/SqliteChannelsDb.scala:
Line 38 migration12() ALTERs local_channels.
Line 57 addOrUpdateChannel() INSERTs to and UPDATEs local_channels.

eclair-core/src/test/scala/fr/acinq/eclair/db/SqliteChannelsDbSpec.scala
Lines 53 and 54 call addOrUpdateChannel - how best to include connection info? Part of channel?
Line 83 INSERTs into local_channels.

eclair-core/src/main/scala/fr/acinq/eclair/db/sqlite/SqlitePendingRelayDb.scala
local_channels is only in this file in a comment on line 34.

I searched for addOrUpdateChannel to identify callers that would have to pass in the connection info:
eclair-core/src/main/scala/fr/acinq/eclair/db/ChannelsDb.scala
Line 24 passes in "HasCommitments" (something that has a nodeID and also has Commitments).

eclair-core/src/test/scala/fr/acinq/eclair/db/BackupHandlerSpec.scala
Line 38 passes "ChannelStateSpec.normal" to it.

eclair-core/src/main/scala/fr/acinq/eclair/channel/Channel.scala
Line 2124 calls it.

I hunted around a bit more to see about adding (if it's not already there) the connection info to a channel. I found that the thing passed around (for example to addOrUpdateChannel) is a "hasCommitments" which has a nodeID and Commitments. Well, Commitments has a RemoteParams property which is a subclass of NodeParams which has a list of publicAddresses. The code can get the connection info from the hasCommitments and store it in the local_channels table. When, as in my case, an existing "OFFLINE" channel is best for a payment and hasn't been re-established because the remote node is the one that last initiated the connection, the connection info can be read from the database and the payment made directly.

[viaj3ro]

I have he same issue of offline channels even though they are actually online and my node should have all the necessary information to reconnect.

My channel with Zigzag.io https://yalls.org/network/570892x1080x0 has this issue a lot even though it's a highly active channels that is routing a lot of payments as long as it is online. Unfortunately I have to manually reconnect every other day. The channel is outgoing, and according to 1ml they never had an IP address change, so my node should be able to automatically reconnect any time.

@pm47 mentioned in the chat that @araspitzu is already working on a solution so I just want to provide my logs, in case it is of any help.

This is when the connection was lost yesterday:

2019-05-16 23:49:00,492 INFO  f.a.eclair.router.Router  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - validating shortChannelId=565766x922x0
2019-05-16 23:49:00,493 INFO  f.a.eclair.router.Router  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - validating shortChannelId=565980x493x0
2019-05-16 23:49:00,495 INFO  f.a.eclair.router.Router  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - validating shortChannelId=566096x596x0
2019-05-16 23:49:00,496 INFO  f.a.eclair.router.Router  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - validating shortChannelId=566149x509x0
2019-05-16 23:49:00,497 INFO  f.a.eclair.router.Router  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - validating shortChannelId=566194x974x0
2019-05-16 23:49:00,498 INFO  f.a.eclair.router.Router  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - validating shortChannelId=566214x966x1
2019-05-16 23:49:00,500 INFO  f.a.eclair.router.Router  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - validating shortChannelId=566245x668x1
2019-05-16 23:49:00,501 INFO  f.a.eclair.router.Router  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - validating shortChannelId=566623x1406x1
2019-05-16 23:49:00,589 INFO  f.acinq.eclair.io.Server  - connected to /178.128.202.182:35218
2019-05-16 23:49:00,725 INFO  f.a.e.io.Authenticator  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - connection authenticated with 0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf@178.128.202.182:35218 direction=incoming
2019-05-16 23:49:00,726 INFO  fr.acinq.eclair.io.Peer  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - got new transport while already connected, switching to new transport
2019-05-16 23:49:00,726 INFO  fr.acinq.eclair.io.Peer  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - using globalFeatures= and localFeatures=10001010
2019-05-16 23:49:00,839 INFO  f.a.e.c.TransportHandler  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - connection closed: ErrorClosed(Eine vorhandene Verbindung wurde vom Remotehost geschlossen)
2019-05-16 23:49:00,839 WARN  fr.acinq.eclair.io.Peer  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - lost connection to 0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf

This morning upon checking my node I saw the channel being offline and manually reconnected. There was no attempt to reconnect or any other communication whatsoever in between.

2019-05-17 09:32:38,002 INFO  f.a.eclair.gui.Handlers  - opening a connection to nodeUri=0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf@178.128.202.182:9735
2019-05-17 09:32:38,003 INFO  f.acinq.eclair.io.Client  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - connecting to 178.128.202.182:9735
2019-05-17 09:32:38,033 INFO  f.acinq.eclair.io.Client  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - connected to 178.128.202.182:9735
2019-05-17 09:32:38,060 INFO  f.a.e.io.Authenticator  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - connection authenticated with 0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf@178.128.202.182:9735 direction=outgoing
2019-05-17 09:32:38,065 INFO  fr.acinq.eclair.io.Peer  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - using globalFeatures= and localFeatures=10001010
2019-05-17 09:32:38,078 INFO  fr.acinq.eclair.io.Peer  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - peer is using globalFeatures= and localFeatures=10000001
2019-05-17 09:32:38,078 INFO  fr.acinq.eclair.io.Peer  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - 0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf has features: initialRoutingSync=false channelRangeQueriesOptional=true channelRangeQueriesMandatory=false
2019-05-17 09:32:38,079 INFO  fr.acinq.eclair.io.Peer  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - rebroadcast will be delayed by 49 seconds
2019-05-17 09:32:38,079 INFO  f.a.eclair.router.Router  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - sending query_channel_range=QueryChannelRange(6fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d6190000000000,0,2147483647)
2019-05-17 09:32:38,079 INFO  f.a.eclair.gui.Handlers  - connection to 0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf@178.128.202.182:9735 successful
2019-05-17 09:32:38,079 INFO  f.a.eclair.Diagnostics  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf c:07fb8dd973cc7d5107b9d79a5775a58ddd8ba16a1a74848697309361ff6a5e6e - OUT msg=ChannelReestablish(07fb8dd973cc7d5107b9d79a5775a58ddd8ba16a1a74848697309361ff6a5e6e,295,294,Some(aa2411fdef9c1499c6f801f1137c84f0596b2d0c6173945a921e67e23ef36e04),Some(02a65b477db849349a72cb6f0ae5eaf4730f2763bb9ad7af8383c91402f33a8a4d))
2019-05-17 09:32:38,089 INFO  f.a.eclair.Diagnostics  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf c:07fb8dd973cc7d5107b9d79a5775a58ddd8ba16a1a74848697309361ff6a5e6e - IN msg=ChannelReestablish(07fb8dd973cc7d5107b9d79a5775a58ddd8ba16a1a74848697309361ff6a5e6e,295,294,Some(779288f8a8269c99fae549b83aca913062d90fcb79417de4838506b3e9377ab9),Some(03e8f50970c906a70efd09ee6cc92e67d3ee680aee1562b9c449427f17dad2a15f))
2019-05-17 09:32:38,090 INFO  f.a.eclair.router.Router  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - received query_channel_range=QueryChannelRange(6fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d6190000000000,576264,4294391031)
2019-05-17 09:32:38,098 INFO  f.a.eclair.router.Router  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - sending back reply_channel_range with 179 items for range=(576264, 4294391031)
2019-05-17 09:32:38,256 INFO  f.a.eclair.router.Router  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - received reply_channel_range, we're missing 30 channel announcements/updates, format=0 useGzip=false
2019-05-17 09:32:38,317 INFO  f.acinq.eclair.io.Client  n:0256fdaf3b0b505b13fefc2dde22f4388abcc9f778f79a2ddfc59091d19923ec35 - connecting to 85.221.49.80:9735
2019-05-17 09:32:38,341 INFO  f.a.eclair.router.Router  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - received reply_channel_range, we're missing 29 channel announcements/updates, format=0 useGzip=false
2019-05-17 09:32:38,424 INFO  f.a.eclair.router.Router  n:0232e20e7b68b9b673fb25f48322b151a93186bffe4550045040673797ceca43cf - received reply_channel_range, we're missing 25 channel announcements/updates, format=0 useGzip=false

According to yall's, it was the Zigzag.io node that terminated the connection. No idea why. My nodes connection is VERY stable (cable) and usually only has very short outages every couple of months. In fact, it was relaying a couple of payments pretty much every hour via other channels in that 10h time period when the Zigzag.io channel was offline. So it doesn't seem like my node had any connection issues.

I understand that when a peer terminates the connection it is up to the peer to reconnect right now? No Idea why Zigzag.io doesn't try to reconnect but I see no reason why my node can't give it a try itself.

[viaj3ro]

Peer's addresses are known only when the user initiated the connection providing a destination address, in case of incoming connection the peer's address is blanked out and we can't reconnect.

is there an explanation for my reconnection issue to the Zigzag.io node mentioned above? If I read the description of your pull request right, reconnecting outgoing channels to nodes that didn't have an IP address change shouldn't be a issue even without this new fix?!