route not found, but there should be many

[fiatjaf]

Basically any payment outgoing from https://lntxbot.com/ is failing with this route not found error.

-- That's because you have no channels, you moron! -- you might be wanting to say!

But look at this filtered output from `channels` I have here:

[
  {
    "peer": "02e9046555a9665145b0dbd7f135744598418df7d61d3660659641886ef1274844",
    "toLocal": 5368897959,
    "toRemote": 141102041
  },
  {
    "peer": "0260fab633066ed7b1d9b9b8a0fac87e1579d1709e874d28a0d171a1f5c43bb877",
    "toLocal": 6696121,
    "toRemote": 225009879
  },
  {
    "peer": "02fdcdd2c33f22126693dfbaad22a938608c44d746d515657e2d628f243a430d74",
    "toLocal": 1995130149,
    "toRemote": 21233851
  },
  {
    "peer": "034a7b1ac1239ff2ac8438ce0a7ade1048514b77d4322f514e96918e6c13944861",
    "toLocal": 408494496,
    "toRemote": 1591505504
  },
  {
    "peer": "02c16cca44562b590dd279c942200bdccfd4f990c3a69fad620c10ef2f8228eaff",
    "toLocal": 3586276653,
    "toRemote": 1185733347
  },
  {
    "peer": "03a3c59c4081ec3f0f5b889ca16c8193d22d1c4aec94d1e6e3873e95c9c3592763",
    "toLocal": 346805406,
    "toRemote": 153194594
  },
  {
    "peer": "02f4ea71bed46a92595925d399bdd1aea17569b6c31d2af1ffa71525400a915af2",
    "toLocal": 117728756,
    "toRemote": 105530323
  },
  {
    "peer": "03d6b14390cd178d670aa2d57c93d9519feaae7d1e34264d8bbb7932d47b75a50d",
    "toLocal": 267302989,
    "toRemote": 1625504011
  },
  {
    "peer": "0230a5bca558e6741460c13dd34e636da28e52afd91cf93db87ed1b0392a7466eb",
    "toLocal": 1604163241,
    "toRemote": 15173051759
  },
  {
    "peer": "022bd0aa893db4ac890e457cca8c83f112518d6941bf9153dab4bf904620503a78",
    "toLocal": 981715309,
    "toRemote": 247518691
  },
  {
    "peer": "0377f626255c4b6938becd925bcc422cf2662bfa03df7008b5dfd7356db50d2bef",
    "toLocal": 1409065784,
    "toRemote": 8364229546
  },
  {
    "peer": "03bce1b91fce34ed76c35d599688b620cd0043b04416a9bb6cb7871bfbf4560591",
    "toLocal": 1561459501,
    "toRemote": 6438540499
  },
  {
    "peer": "03e6976fed1f872ebf5b9aab13f27a770a69e596dbef093da1fdabbc1e25491b34",
    "toLocal": 24703490,
    "toRemote": 120296510
  },
  {
    "peer": "036faa89b86b8a46777ce213f17384c9c40f5b6630b9e8ee5caf066a1e55eedb7b",
    "toLocal": 388703156,
    "toRemote": 80733844
  },
  {
    "peer": "021e7ea08e31a576b4fd242761d701452a8ac98113eac3074c153db85d2dcc7d27",
    "toLocal": 1040693176,
    "toRemote": 13959306824
  },
  {
    "peer": "02cd1b7bc418fac2dc99f0ba350d60fa6c45fde5ab6017ee14df6425df485fb1dd",
    "toLocal": 93147818,
    "toRemote": 906852182
  },
  {
    "peer": "03e7d88bb91d92982a711ef56fef6f95f89c484b866086a7d0c1ef08e5b144758a",
    "toLocal": 20000000,
    "toRemote": 1729960749
  },
  {
    "peer": "02e5544cda426d1dac8e5237e32eec59cbf93b88b76ef94ee7ecf8f76a5358fbbf",
    "toLocal": 107039980,
    "toRemote": 1892960020
  },
  {
    "peer": "03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f",
    "toLocal": 113592709,
    "toRemote": 10858260291
  },
  {
    "peer": "0377f4de9bb4a46f5acd9a26e3135df90c61c79b9341d6d4e2ca36fd0e468ccd16",
    "toLocal": 1204226897,
    "toRemote": 1795773103
  },
  {
    "peer": "035e3aa81503b67d61589270c043bcf6dcf083e40bc8630eeeeb08f85570be0fc9",
    "toLocal": 31967890,
    "toRemote": 1968032110
  },
  {
    "peer": "02875ac2c27835990ef62e5755c34264b2c39f51a41525adc5e52a7f94b3a19f8b",
    "toLocal": 1698659241,
    "toRemote": 44961759
  },
  {
    "peer": "0283e14a98c3cf2917d18d8c2732935f7191a67b294c0d668756bb71bc8df9eda2",
    "toLocal": 52239329,
    "toRemote": 4947760671
  },
  {
    "peer": "0283e14a98c3cf2917d18d8c2732935f7191a67b294c0d668756bb71bc8df9eda2",
    "toLocal": 443012721,
    "toRemote": 9556987279
  }
]

And then just to be very sure I just sent 250000 sats from https://coinos.io/ to https://lntxbot.com/ (which means there is a route, right?, and when sending I shifted satoshis from one side to the other, making almost sure that there is a route on the opposite direction too, right?) and tried to send 50000 from https://lntxbot.com/ to https://coinos.io/, but again,

2021-11-01 13:43:59,835 WARN  f.a.e.p.s.MultiPartPaymentLifecycle PAY n:02868e12f320073cad0c2959c42559fbcfd1aa326fcb943492ed7f02c9820aa399 h:0824b188a53c147addaf98506c5662371e764a32fd3c553ed5a624f3e8b682c3 p:feb34f82 i:feb34f82 - router error: route not found
2021-11-01 13:43:59,853 WARN  f.a.e.p.s.MultiPartPaymentLifecycle PAY n:02868e12f320073cad0c2959c42559fbcfd1aa326fcb943492ed7f02c9820aa399 h:0824b188a53c147addaf98506c5662371e764a32fd3c553ed5a624f3e8b682c3 p:feb34f82 i:feb34f82 - multi-part payment failed

I also tried disabling plugins, and I deleted all the router section from my eclair.conf just to be sure I wasn't doing something weird, there, but the problem persists. Please help me!

My `eclair.conf`, if that helps

eclair {
  chain = "mainnet"
node-alias = "lntxbot.com"

node-color = "ffffff"
server {

port = 9734

public-ips = ["198.251.89.159"]

}
api {

enabled = true

binding-ip = 10.147.17.32

port = 8877

password = "password"

}
bitcoind {

host = "10.147.17.69"

rpcport = 8332

rpcuser = "fiatjaf"

rpcpassword = "fiatjaf"

zmqblock = "tcp://10.147.17.69:28332"

zmqtx = "tcp://10.147.17.69:28333"

wallet = "eclair"

}
trampoline-payments-enable = true
features {

option_static_remotekey = mandatory

trampoline_payment = optional

large_channel_support = optional

}
relay.fees {

public-channels {

fee-base-msat = 1500

fee-proportional-millionths = 0

}

min-trampoline {

fee-base-msat = 1000

fee-proportional-millionths = 100

}

}
on-chain-fees {

close-on-offline-feerate-mismatch = false
feerate-tolerance {
  ratio-low = 0.1
}

}
socks5 {

enabled = true

host = "127.0.0.1"

port = 9050

use-for-ipv4 = false

use-for-ipv6 = false

use-for-tor = true

use-for-watchdogs = false

}
blockchain-watchdog {

sources = [

"bitcoinheaders.net",

"blockstream.info",

"mempool.space"

]

}

}

[t-bast]

That is very surprising...were payments previously going through and then at some point it started failing?
Can you share your logs (privately if needed) and the approximate time when it started failing?

I also tried disabling plugins

What plugins were you using? If they interact with your DB, they might create a persistent issue if they somehow messed up with your graph data.

[fiatjaf]

I tried these changes without success.

Sent you the files on Telegram.

[t-bast]

I've run the repro, and with your data I'm able to find many routes that work, so this is not a path-finding issue.
Looking at your logs, I see many disconnections because of missing Pongs.
I think that the issue is that some of your channels are offline: that's why you're unable to find routes.
Can you use the peers command to check which peers are offline when your payment attempts fail?

Strangely I see that you have some no response to ping logs even with our node.
Could there be something in your setup that would explain connectivity loss?
Otherwise it would be useful to troubleshoot connections in depth between your node and ours, maybe that will let us find an issue in keep-alives?

[t-bast]

Can you add <logger name="fr.acinq.eclair.io.PeerConnection" level="DEBUG" /> to your logback.xml?
No need to restart your node, it will automatically pick up the logging configuration update after a minute or so.

This will only turn on debug logs for the peer connection component, it should flood your logs and would give us valuable debug information.

[fiatjaf]

[
  {
    "nodeId": "021e7ea08e31a576b4fd242761d701452a8ac98113eac3074c153db85d2dcc7d27",
    "state": "CONNECTED",
    "address": "5.9.83.143:36632",
    "channels": 1
  },
  {
    "nodeId": "022bd0aa893db4ac890e457cca8c83f112518d6941bf9153dab4bf904620503a78",
    "state": "CONNECTED",
    "address": "165.227.164.18:49792",
    "channels": 1
  },
  {
    "nodeId": "0230a5bca558e6741460c13dd34e636da28e52afd91cf93db87ed1b0392a7466eb",
    "state": "CONNECTED",
    "address": "176.9.17.121:9735",
    "channels": 1
  },
  {
    "nodeId": "0260fab633066ed7b1d9b9b8a0fac87e1579d1709e874d28a0d171a1f5c43bb877",
    "state": "CONNECTED",
    "address": "54.187.0.23:9735",
    "channels": 1
  },
  {
    "nodeId": "0283e14a98c3cf2917d18d8c2732935f7191a67b294c0d668756bb71bc8df9eda2",
    "state": "DISCONNECTED",
    "channels": 2
  },
  {
    "nodeId": "02875ac2c27835990ef62e5755c34264b2c39f51a41525adc5e52a7f94b3a19f8b",
    "state": "DISCONNECTED",
    "channels": 1
  },
  {
    "nodeId": "02c16cca44562b590dd279c942200bdccfd4f990c3a69fad620c10ef2f8228eaff",
    "state": "DISCONNECTED",
    "channels": 1
  },
  {
    "nodeId": "02cd1b7bc418fac2dc99f0ba350d60fa6c45fde5ab6017ee14df6425df485fb1dd",
    "state": "CONNECTED",
    "address": "134.209.228.207:80",
    "channels": 1
  },
  {
    "nodeId": "02e5544cda426d1dac8e5237e32eec59cbf93b88b76ef94ee7ecf8f76a5358fbbf",
    "state": "CONNECTED",
    "address": "qmn7vpi3zqxxxkhgfdhlhfkeskj25iycz2q67omrdqe63sd3ngsxigqd.onion:9735",
    "channels": 1
  },
  {
    "nodeId": "02e9046555a9665145b0dbd7f135744598418df7d61d3660659641886ef1274844",
    "state": "CONNECTED",
    "address": "31.16.52.37:60209",
    "channels": 1
  },
  {
    "nodeId": "02f4ea71bed46a92595925d399bdd1aea17569b6c31d2af1ffa71525400a915af2",
    "state": "CONNECTED",
    "address": "b5rl3ybovqqmd6ogiobsgmlcfb3wcpxjdbwgvtddb66zdyq6xdszgnad.onion:9735",
    "channels": 1
  },
  {
    "nodeId": "02f96aeb2b9954492eac250fe7c6f3b8e66a49ad55ed7397645cafa5ec0e687c7d",
    "state": "CONNECTED",
    "address": "167.100.73.203:54508",
    "channels": 0
  },
  {
    "nodeId": "02fdcdd2c33f22126693dfbaad22a938608c44d746d515657e2d628f243a430d74",
    "state": "CONNECTED",
    "address": "65.21.156.244:33766",
    "channels": 1
  },
  {
    "nodeId": "034a7b1ac1239ff2ac8438ce0a7ade1048514b77d4322f514e96918e6c13944861",
    "state": "CONNECTED",
    "address": "188.244.4.78:9735",
    "channels": 1
  },
  {
    "nodeId": "035e3aa81503b67d61589270c043bcf6dcf083e40bc8630eeeeb08f85570be0fc9",
    "state": "DISCONNECTED",
    "channels": 1
  },
  {
    "nodeId": "036faa89b86b8a46777ce213f17384c9c40f5b6630b9e8ee5caf066a1e55eedb7b",
    "state": "CONNECTED",
    "address": "198.245.60.96:60181",
    "channels": 1
  },
  {
    "nodeId": "0377f4de9bb4a46f5acd9a26e3135df90c61c79b9341d6d4e2ca36fd0e468ccd16",
    "state": "CONNECTED",
    "address": "tmjlere22ckgmaxnrxxil7vvdv5pr52ilrbokr4ferwew2wsxp3s7fyd.onion:9735",
    "channels": 1
  },
  {
    "nodeId": "0377f626255c4b6938becd925bcc422cf2662bfa03df7008b5dfd7356db50d2bef",
    "state": "DISCONNECTED",
    "channels": 1
  },
  {
    "nodeId": "03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f",
    "state": "CONNECTED",
    "address": "34.239.230.56:9735",
    "channels": 1
  },
  {
    "nodeId": "03a3c59c4081ec3f0f5b889ca16c8193d22d1c4aec94d1e6e3873e95c9c3592763",
    "state": "CONNECTED",
    "address": "tra3uu437goezbrgor7qdyxvavzxhhg6k75i6vjcep2vykx44cb5xnyd.onion:9735",
    "channels": 1
  },
  {
    "nodeId": "03bce1b91fce34ed76c35d599688b620cd0043b04416a9bb6cb7871bfbf4560591",
    "state": "CONNECTED",
    "address": "ynly76neccb6rom4myhhb3dvsw6zf5xehxznqvrh2vl7gwxuyb7hodqd.onion:9735",
    "channels": 1
  },
  {
    "nodeId": "03c3b763ba79eebbf5e875d68806e1cc738298b16b4a521f53b411d85cae511ab0",
    "state": "CONNECTED",
    "address": "mc22ks2bzlw235d3zmsgxt3svggvl2t2b7vpuxamyzf2go7dxiyifmid.onion:9735",
    "channels": 1
  },
  {
    "nodeId": "03d6b14390cd178d670aa2d57c93d9519feaae7d1e34264d8bbb7932d47b75a50d",
    "state": "CONNECTED",
    "address": "75.2.55.32:9735",
    "channels": 1
  },
  {
    "nodeId": "03e6976fed1f872ebf5b9aab13f27a770a69e596dbef093da1fdabbc1e25491b34",
    "state": "CONNECTED",
    "address": "v4s4rr7jxvf5spfx2yviziqxrebqvyv3u5jrwdz5de7ih42qzlazjqad.onion:9735",
    "channels": 1
  },
  {
    "nodeId": "03e7d88bb91d92982a711ef56fef6f95f89c484b866086a7d0c1ef08e5b144758a",
    "state": "CONNECTED",
    "address": "zikrj5rsmlz3l2x2y4jutvfof2h72c3tvwecvla7lxad53luonmlm3qd.onion:9735",
    "channels": 1
  }
]

[fiatjaf]

They're basically all connected, but running the same command over and over I see some of them go DISCONNECTED and then CONNECTED again and so on.

The only thing I have in my setup is a firewall thing on the VPS I'm using that blocks all incoming traffic except on ports 9734, 9735, 80 and 443. But this was in place since the DDoS attack which has over a month ago.

Oh, the other thing that changed was really that I upgraded from the 0.6.2-SNAPSHOT-daace53 to 0.6.2 around the time the route errors started happening.

[akumaigorodski]

A few things to note about plugins:

• AlarmBot is pretty benign, basically a single actor which listens to events and does nothing else.
• HC plugin uses its own postgresql database and does not try to do anything with eclair database.
• Node restarted without plugins has the same erroneous behavior.

[akumaigorodski]

Maybe this will be helpful:

there is LNTXBOT -> my node channel, when looking at logs I see these periodic reports:

2021-11-02 18:29:27,203 WARN f.a.e.io.PeerConnection n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - no response to ping=Ping(325,ByteVector(264 bytes, 0x000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000),TlvStream(List(),List())), closing connection

This happens roughly every 3 minutes.

Also, when trying to send a payment from Telegram bot there is this route which should be tried: LNTXBOT -> Motherbase -> my wallet, but I see no related channel messages in logs.

[fiatjaf]

Motherbase = your node

[t-bast]

There is definitely a connection issue, that's the root cause of the path-finding issues (because the channel takes a bit of time to be re-added to the graph). We need to understand why these pings go unanswered, or if they are answered (in which case it's really a network issue).

Can you setup debug logs on PeerConnection on both of your nodes (LNTXBOT and @btcontract's node) as proposed here and let me know what you find? With logs from both sides of the connection it should help us figure out what happens to those ping/pongs.

[fiatjaf]

[fiatjaf]

[fiatjaf]

[fiatjaf]

It's basically an endless flood of pings.
Highlighted is @btcontract's node.

[t-bast]

Can you attach the logs, grepped by node_id? Take your logs where you grep for btcontract's node_id, and take btcontract's logs where you grep by your node_id. Please keep all the results, I want to see all ping traffic between the two of you.

[akumaigorodski]

# tail -f eclair.log | grep 03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315
2021-11-02 19:24:38,750 DEBUG f.a.e.io.PeerConnection SYN n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - sent announcements: channels=0 updates=0 nodes=1
2021-11-02 19:24:48,348 WARN  f.a.e.io.PeerConnection n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - no response to ping=Ping(394,ByteVector(610 bytes, #-931690207),TlvStream(List(),List())), closing connection
2021-11-02 19:24:48,349 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - transport died, stopping
2021-11-02 19:24:55,984 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - connection authenticated with 03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315@198.251.89.159:9734 direction=outgoing
2021-11-02 19:24:55,984 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - using features=option_support_large_channel:optional,gossip_queries_ex:optional,option_data_loss_protect:optional,var_onion_optin:mandatory,option_static_remotekey:mandatory,payment_secret:mandatory,option_shutdown_anysegwit:optional,basic_mpp:optional,gossip_queries:optional (unknown=32973)
2021-11-02 19:24:56,012 DEBUG f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:24:56,012 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - peer is using features=trampoline_payment:optional,option_support_large_channel:optional,gossip_queries_ex:optional,option_data_loss_protect:optional,var_onion_optin:mandatory,option_static_remotekey:mandatory,payment_secret:mandatory,option_shutdown_anysegwit:optional,basic_mpp:optional,gossip_queries:optional (unknown=32973), networks=6fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d6190000000000
2021-11-02 19:24:56,012 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - not syncing with this peer
2021-11-02 19:24:56,012 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - rebroadcast will be delayed by 37 seconds
2021-11-02 19:24:56,017 DEBUG f.a.e.io.PeerConnection n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:24:56,017 DEBUG f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:24:56,062 DEBUG f.a.e.io.PeerConnection n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:25:04,121 DEBUG f.a.e.io.PeerConnection SYN n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:25:04,122 DEBUG f.a.e.io.PeerConnection SYN n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:25:04,122 INFO  f.a.e.io.PeerConnection SYN n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - setting up gossipTimestampFilter=GossipTimestampFilter(6fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d6190000000000,1635877504,2147483647,TlvStream(List(),List()))
2021-11-02 19:25:14,385 DEBUG f.a.e.io.PeerConnection SYN n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:25:54,419 WARN  f.a.e.io.PeerConnection n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - no response to ping=Ping(870,ByteVector(753 bytes, #-1919804557),TlvStream(List(),List())), closing connection
2021-11-02 19:25:54,419 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - transport died, stopping
2021-11-02 19:26:00,410 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - connection authenticated with 03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315@198.251.89.159:9734 direction=outgoing
2021-11-02 19:26:00,410 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - using features=option_support_large_channel:optional,gossip_queries_ex:optional,option_data_loss_protect:optional,var_onion_optin:mandatory,option_static_remotekey:mandatory,payment_secret:mandatory,option_shutdown_anysegwit:optional,basic_mpp:optional,gossip_queries:optional (unknown=32973)
2021-11-02 19:26:00,444 DEBUG f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:26:00,444 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - peer is using features=trampoline_payment:optional,option_support_large_channel:optional,gossip_queries_ex:optional,option_data_loss_protect:optional,var_onion_optin:mandatory,option_static_remotekey:mandatory,payment_secret:mandatory,option_shutdown_anysegwit:optional,basic_mpp:optional,gossip_queries:optional (unknown=32973), networks=6fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d6190000000000
2021-11-02 19:26:00,444 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - not syncing with this peer
2021-11-02 19:26:00,445 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - rebroadcast will be delayed by 31 seconds
2021-11-02 19:26:00,454 DEBUG f.a.e.io.PeerConnection n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:26:00,454 DEBUG f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:26:01,311 DEBUG f.a.e.io.PeerConnection n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:26:31,786 DEBUG f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:26:31,786 DEBUG f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - received pong with latency=458
2021-11-02 19:26:45,947 DEBUG f.a.e.io.PeerConnection SYN n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:26:46,019 DEBUG f.a.e.io.PeerConnection SYN n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:26:46,019 INFO  f.a.e.io.PeerConnection SYN n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - setting up gossipTimestampFilter=GossipTimestampFilter(6fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d6190000000000,1635877605,2147483647,TlvStream(List(),List()))
2021-11-02 19:26:58,429 DEBUG f.a.e.io.PeerConnection SYN n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:27:38,468 WARN  f.a.e.io.PeerConnection n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - no response to ping=Ping(719,ByteVector(814 bytes, #-513563770),TlvStream(List(),List())), closing connection
2021-11-02 19:27:38,469 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - transport died, stopping
2021-11-02 19:27:46,759 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - connection authenticated with 03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315@198.251.89.159:9734 direction=outgoing
2021-11-02 19:27:46,759 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - using features=option_support_large_channel:optional,gossip_queries_ex:optional,option_data_loss_protect:optional,var_onion_optin:mandatory,option_static_remotekey:mandatory,payment_secret:mandatory,option_shutdown_anysegwit:optional,basic_mpp:optional,gossip_queries:optional (unknown=32973)
2021-11-02 19:27:46,805 DEBUG f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:27:46,806 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - peer is using features=trampoline_payment:optional,option_support_large_channel:optional,gossip_queries_ex:optional,option_data_loss_protect:optional,var_onion_optin:mandatory,option_static_remotekey:mandatory,payment_secret:mandatory,option_shutdown_anysegwit:optional,basic_mpp:optional,gossip_queries:optional (unknown=32973), networks=6fe28c0ab6f1b372c1a6a246ae63f74f931e8365e15a089c68d6190000000000
2021-11-02 19:27:46,806 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - not syncing with this peer
2021-11-02 19:27:46,806 INFO  f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - rebroadcast will be delayed by 38 seconds
2021-11-02 19:27:46,850 DEBUG f.a.e.io.PeerConnection CON n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:27:46,850 DEBUG f.a.e.io.PeerConnection n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds
2021-11-02 19:27:47,628 DEBUG f.a.e.io.PeerConnection n:03ee58475055820fbfa52e356a8920f62f8316129c39369dbdde3e5d0198a9e315 - next ping scheduled in 30 seconds

[t-bast]

Please both let the experiment run for 1h or so and then share the results.

[fiatjaf]

https://www.pastery.net/dmyttx/

[akumaigorodski]

um ok, I'll run this for an hour and then paste a file.

[t-bast]

Thanks, I need enough data to see a few disconnections / reconnections.

[akumaigorodski]

log.txt

[t-bast]

Thanks. @fiatjaf can you share your logs for the same time range?

[fiatjaf]

eclair-lntxbot-motherbase-connection-logs.txt

Same time range. Our timezones are different by 5 hours it seems.

[t-bast]

Thanks for the logs. What's interesting in there is that:

• whenever a pong is received, it's received very quickly (usually < 100 ms) so it doesn't seem like a latency issue
• the connection is mostly idle, there aren't that many messages flowing between nodes
• when there is a "no response to ping" there doesn't seem to be any activity on the connection before that

It looks like the connection could actually be dropped by middle boxes (VPS firewall) after less than 30 seconds of inactivity and the sending node isn't notified on the tcp socket. It could even be that some VPS firewalls don't like persistent connections and close them regardless of keep-alive.

I think it's worth seeing what happens if we ping much more frequently to keep the connection alive.

@fiatjaf @btcontract could you both set eclair.peer-connection.ping-interval = 3 seconds, let it run for a while and let me know if you keep seeing disconnections? Don't hesitate to share your logs, that will let me see if something looks fishy.

It will spam a bit your logs, there will likely be many next ping scheduled in 3 seconds lines, but once this experiment is over you can remove the debug logs.

[t-bast]

Thanks, let's see how it behaves if we let it run a bit.

Another possibility would be that the ping messages are correctly sent and received, but eclair's logic actually drops it or doesn't handle it correctly. But the code is very simple, I went through it and didn't see any hole, but still there could be a bug.

If that doesn't solve it, I think I'll setup two nodes on the same local network to be able to observe everything without middle boxes / firewalls. If there is a bug in eclair it should find it, otherwise it will indicate some nasty middle box behavior...

[fiatjaf]

Here are the logs for the last hour:

3s-ping-lntxbot-motherbase-logs.txt

[akumaigorodski]

My side, also about last hour: log.txt

[t-bast]

Thanks, so it doesn't make it better, it actually seems worse, disconnections happen even faster...so you can revert that configuration for now.

What's strange is that fiatjaf seems to correctly receive pongs from btcontract (most of the time), but btcontract almost never receives pongs from fiatjaf. That's really worrying, there may be a bug somewhere in our network stack, it would be surprising if it was your VPS firewall arbitrarily dropping messages like that. I'm creating an issue and we'll setup a repro on testnet.Thanks, so it doesn't make it better, it actually seems worse, disconnections happen even faster...so you can revert that configuration for now.

What's strange is that fiatjaf seems to correctly receive pongs from btcontract (most of the time), but btcontract almost never receives pongs from fiatjaf. That's really worrying, there may be a bug somewhere in our network stack, it would be surprising if it was your VPS firewall arbitrarily dropping messages like that. I'm creating an issue and we'll setup a repro on testnet.

[fiatjaf]

I've asked on the VPS about their firewall things, no one was able to tell me if there is some weird policy of dropping connections (but also no one stated the opposite). I was using a "DDoS-protected IP" which they offer, but I've enabled the normal IP yesterday and made it the default gateway and my node announced IP. But that doesn't seem to have made any difference.

[pm47]

@fiatjaf can you add this line to your eclair.conf and restart your node?

eclair {
...
  sync-whitelist = [ "03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f" ]
...
}

It will make your node only sync its routing table with our node, effectively disabling routing table sync between your node and @btcontract's.

[pm47]

Actually can you use this logging configuration? It will provide DEBUG logs only for the relevant node:

• @fiatjaf: logback.xml.gz
• @btcontract: logback.xml.gz

To use, start eclair with:

gunzip logback.xml.gz
./eclair-node.sh -Dlogback.configurationFile=/full/path/to/logback.xml

Note: need to use a full path to logback.xml.

[akumaigorodski]

Running with this logging configuration.

[fiatjaf]

Sorry, I only got to the computer now. Running with this logging configuration and eclair.sync-whitelist = [ "03864ef025fde8fb587d989186ce6a4a186895ee44a926bfc370e2c366597a3f8f" ].

[fiatjaf]

eclair.log.gz

[pm47]

Thanks but I'll need more logs there is no disconnection with Anton's node in this extract

[akumaigorodski]

Last hour of log, did not grep it for LNTXBOT.
eclair.log.tar.gz

[fiatjaf]

These are remote channels, right? Between which nodes are they?

They are remote channels, yes, not mine. I queried some of these, they are between LNBIG and Blixt, coinos and MilkyWay, lnurl-pay.me and another LNBIG, 1ML and coinos etc.

[akumaigorodski]

FWIW 8,500 payment works when sent through SBW which has singe HC to LNTXBOT, the route is:
SBW -> LNTXBOT -> 699907x495x1 -> 582801x1758x0 -> coinos.

These channels seem to not be tried at all from LNTXBOT, maybe this will be helpful.

[t-bast]

At the very least I can confirm that during last couple of hours Motherbase / LNTXBOT connection has been very stable, there has not been a single disconnect and peers exchange Ping/Pong normally.

This is helpful, that means the disconnection issues are really linked to gossip sync (since you both changed your sync-whitelist config to only sync with our node).

They are remote channels, yes, not mine. I queried some of these, they are between LNBIG and Blixt, coinos and MilkyWay, lnurl-pay.me and another LNBIG, 1ML and coinos etc.

We can't do anything for those, if they are remote errors this isn't a local issue. It could be either connection issues on their side, or liquidity, or anything else.

[fiatjaf]

Tried to pay many times to see if that route would be tried but gave up, none of those two channels seems to show up in the failure logs.

[fiatjaf]

Also made two very large payments to lnbits.com that worked, but then I went to check and I have a direct channel to lnbits.com.

[fiatjaf]

@t-bast @dpad85 do you understand why the errors stopped being route not found and started being channel currently unavailable?

[t-bast]

@t-bast @dpad85 do you understand why the errors stopped being route not found and started being channel currently unavailable?

It think that it's because your connection with btcontract's node is now stable, so your local channels are able to be used and routes are found. Somehow something in the config changes made recently fixed the connection instability, so now the usable graph is bigger.

[pm47]

@fiatjaf can you add this to your eclair.conf :

features {
...
  gossip_queries = disabled
  gossip_queries_ex = disabled
}

This will completely disable routing table sync to all nodes. It shouldn't matter since your node is already up to date and you will still receive the gossip for newer updates. Let's see if this solves the connectivity issue will all peers.

[akumaigorodski]

Does your node connect over tor to lntxbot, or is it plain IP?

Plain IP, Tor is not even running on my server.

Yesterday's log refuses to be grepped normally for some reason so I've attached all disconnects found + grepped today's log in second file.

2021-11-08-disconnects.txt
log.txt

[fiatjaf]

It seems my disconnects have mostly stopped after changing that setting to 20s.
Should I run the debug version with super verbose logs?

[pm47]

Should I run the debug version with super verbose logs?

No you can revert to the previous one.

[fiatjaf]

I was able to pay stacker.news multiple times seamlessly, but large payments to coinos.io are still failing. What else should I test?

[pm47]

What else should I test?

Below was an interesting test. Maybe disabling channel exclusions like we did earlier will change the outcome.

And then just to be very sure I just sent 250000 sats from https://coinos.io/ to https://lntxbot.com/ (which means there is a route, right?, and when sending I shifted satoshis from one side to the other, making almost sure that there is a route on the opposite direction too, right?) and tried to send 50000 from https://lntxbot.com/ to https://coinos.io/, but again,

NB: so far I haven't seen anything abnormal. Payments fail, yes, but that could be due to a liquidity shortage for some destinations. As a matter of fact, we have just added more liquidity towards this very node Coinos today for that reason on our own node. It came up independently from this debug.

[fiatjaf]

I just realized this could be related: ElementsProject/lightning#4698

Maybe not, but letting you know anyway. This has been happening since a long time ago and keeps happening (I'm running a c-lightning node on the same machine). Something about connection to peers being closed?

The problem is that these were happening on the previous VPS I was using, never stopped, but c-lightning still seems to be working fine. And also Eclair didn't have these issues before a week or two ago.

So yes, probably unrelated.

[pm47]

Maybe unrelated, but interesting nonetheless. I don't know what those "subdaemon died" errors mean.

To be clear, regarding disconnections an issue related to your VPS instance or provider is a prime hypothesis. What is your VPS provider? Bastien mentioned a DDOS-protection setting too?

And also Eclair didn't have these issues before a week or two ago.

How do you quantify that? Do you mean that you didn't have sending issues before, or that there were no disconnections? Do you have logs from that time?

[fiatjaf]

I don't have logs from that period anymore, just checked. I only assume that because I didn't have lntxbot users complaining to me at that time about failed payments. I also used to look at the streaming logs on the console and I don't remember seeing a ton of failed pongs and disconnects as I see now. These two pieces of evidence are not very strong, though.

My provider is buyvm.net (same as @btcontract, right?)
I had a "DDoS-protected IP", but I've reenabled the unprotected IP and am using it instead of the DDoS-protected IP now.

[akumaigorodski]

Mine is not buyvm but hetzner.

[thomash-acinq]

Hi @fiatjaf
Do you still get the route not found error? If you know a route that would work and is not found by eclair, can you use the API call allupdates to check that all of the channels of the route are known by eclair?
Since you say that the issue only arises for amounts above 8000 sats, it would be good to use findroute to get a route that works for less than 8000 sats so that we can try to understand why this route doesn't work for larger amounts.

[thomash-acinq]

The solution is actually very simple: You only look for routes that cost less than 5 sats, SearchBoundaries(5000 msat, ...) can be seen on this line:

2021-11-21 11:42:31,051 INFO  f.a.eclair.router.Router PAY h:a9a442b27759dab282c057d8ff368eb54b421d9f3e261f2ef3c0ba648decce11 p:0e32a749 i:0e32a749 - finding routes with randomize=false params=RouteParams(false,SearchBoundaries(5000 msat,5.0E-4,6,CltvExpiryDelta(1008)),Left(WeightRatios(0.0,0.05,0.4,0.55,RelayFees(500 msat,200))),MultiPartParams(15000000 msat,5),control,false)

With fees of 1sat + 0.05% a payment of 8001sats only costs 5sats but a payment of 8002sats costs 5.001sats which is above the limit that you've set.

[thomash-acinq]

I guess that you're using the API with --feeThresholdSat=5. That's a terrible name, we've changed it in the code but we forgot to change it in the API.
I'm renaming it now to something clearer: #2079

[thomash-acinq]

To clarify (because I realize that it is not completely obvious from https://acinq.github.io/eclair/#payinvoice), the fee limit is the maximum of --feeThresholdSat and --maxFeePct * amount / 100, not the minimum. In our case you set the maximum proportional fee to exactly the proportional fee of the routing hint, since that routing hint also has a base fee, there is no way you can find a route with a fee below that limit. So the flat fee limit is the only one that matters here.

[fiatjaf]

You're kidding me.

[fiatjaf]

Indeed this fixes it.
Thank you very much.

I don't think the argument is badly named, I think I misused it badly and it's all my fault. Terrible node operator.