[BUG] Improve IP Address detection when hostname is given in config

[petzsch]

Issue and Steps to Reproduce

When using a DNS name (i.e. pay.4sats.net) it now resolves to the first IPv4 it gets back from the local dns resolver. However in my case (VM from Contabo with Ubuntu 22.04) it got returned a local IP address (together with a public IPv4):

root@pay:~# host pay.4sats.net
pay.4sats.net has address 127.0.1.1 // it only announce this one
pay.4sats.net has address 89.117.59.102
pay.4sats.net has IPv6 address 2a02:c206:3010:4506::1

My desired behaviour would be for the announcement to:

• exclude any local IP subnets (since they can't be reached from any other node anyway)
• announe the one (maybe there are more) public IPv4
• also announce the public IPv6

current workarround: comment out the local IP from /etc/hosts and life with missing ipv6.
Using the fix provided in #5795

getinfo output

{
   "id": "03bf73fb1e44cb60b13edd4fa3e81e1e9709fd9871af0b6cf8f847dfa0bfe5791c",
   "alias": "4sats.net Core-Lightning",
   "color": "03bf73",
   "num_peers": 1,
   "num_pending_channels": 0,
   "num_active_channels": 1,
   "num_inactive_channels": 0,
   "address": [
      {
         "type": "ipv4",
         "address": "127.0.1.1",
         "port": 9735
      },
      {
         "type": "torv3",
         "address": "65dbner57zrmrixqahke5usmk3wsguk4ctwe5unva5ougxhzrjgeijad.onion",
         "port": 9735
      }
   ],
   "binding": [
      {
         "type": "ipv4",
         "address": "0.0.0.0",
         "port": 9735
      }
   ],
   "version": "basedon-v22.11-2-modded",
   "blockheight": 766448,
   "network": "bitcoin",
   "msatoshi_fees_collected": 0,
   "fees_collected_msat": "0msat",
   "lightning-dir": "/root/.lightning/bitcoin",
   "our_features": {
      "init": "08a0800a0269a2",
      "node": "88a0800a0269a2",
      "channel": "",
      "invoice": "02000002024100"
   }
}

[cdecker]

We are trying to get beyond announcing IP addresses, which is what you observed here (resolving locally), and instead announce the domain name, and have peers resolve it, so their resolution is actually the IP they can connect to.

This is currently disabled, since lnd drops announcements on the floor that contain address types they don't recognize. This is explicitly cautioned against in the spec, exactly because it makes introducing a new address type hard. But they seem to be remediating, and we will soon be able to stop resolvign locally and have the peer resolve the symbolic name instead.

@m-schmoock is much more up to date on the current state of the network, and we're listening to him for the all-clear that we can arm this feature ^^

[petzsch]

Thanks for clarifying.

I'm still seeing major problems with with opening channels towards LND nodes. Any idea what could be causing this?

The connection comes back once every 5 minutes for about 30 seconds and then drops. It's the same with the Einundzwanzig and a random LNBIG node. Channels per se open normally, it's just the node connection that gets lost, putting the channel in inactive state shortly after opening.

Let me know if, I can provide any more logs or should include listpeers here.

here the container logs from CLN:

2022-12-08T18:21:37.398Z INFO    03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-chan#2: Peer transient failure in CHANNELD_NORMAL: Disconnected
2022-12-08T18:22:41.463Z INFO    03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-channeld-chan#2: Peer connection lost
2022-12-08T18:22:41.463Z INFO    03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-chan#2: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2022-12-08T18:24:37.783Z INFO    03a09f56bba3d2c200cc55eda2f1f069564a97c1fb74345e1560e2868a8ab3d7d0-chan#1: Peer transient failure in CHANNELD_NORMAL: Disconnected
2022-12-08T18:25:41.522Z INFO    03a09f56bba3d2c200cc55eda2f1f069564a97c1fb74345e1560e2868a8ab3d7d0-channeld-chan#1: Peer connection lost
2022-12-08T18:25:41.522Z INFO    03a09f56bba3d2c200cc55eda2f1f069564a97c1fb74345e1560e2868a8ab3d7d0-chan#1: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2022-12-08T18:27:37.957Z INFO    03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-chan#2: Peer transient failure in CHANNELD_NORMAL: Disconnected
2022-12-08T18:28:41.635Z INFO    03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-channeld-chan#2: Peer connection lost
2022-12-08T18:28:41.635Z INFO    03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-chan#2: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2022-12-08T18:30:37.757Z INFO    03a09f56bba3d2c200cc55eda2f1f069564a97c1fb74345e1560e2868a8ab3d7d0-chan#1: Peer transient failure in CHANNELD_NORMAL: Disconnected
2022-12-08T18:31:41.718Z INFO    03a09f56bba3d2c200cc55eda2f1f069564a97c1fb74345e1560e2868a8ab3d7d0-channeld-chan#1: Peer connection lost
2022-12-08T18:31:41.720Z INFO    03a09f56bba3d2c200cc55eda2f1f069564a97c1fb74345e1560e2868a8ab3d7d0-chan#1: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2022-12-08T18:33:37.681Z INFO    03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-chan#2: Peer transient failure in CHANNELD_NORMAL: Disconnected
2022-12-08T18:34:41.840Z INFO    03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-channeld-chan#2: Peer connection lost
2022-12-08T18:34:41.840Z INFO    03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-chan#2: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2022-12-08T18:36:37.320Z INFO    03a09f56bba3d2c200cc55eda2f1f069564a97c1fb74345e1560e2868a8ab3d7d0-chan#1: Peer transient failure in CHANNELD_NORMAL: Disconnected
2022-12-08T18:36:42.465Z INFO    03a09f56bba3d2c200cc55eda2f1f069564a97c1fb74345e1560e2868a8ab3d7d0-channeld-chan#1: Peer connection lost
2022-12-08T18:36:42.465Z INFO    03a09f56bba3d2c200cc55eda2f1f069564a97c1fb74345e1560e2868a8ab3d7d0-chan#1: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2022-12-08T18:39:38.096Z INFO    03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-chan#2: Peer transient failure in CHANNELD_NORMAL: Disconnected
2022-12-08T18:40:42.050Z INFO    03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-channeld-chan#2: Peer connection lost
2022-12-08T18:40:42.050Z INFO    03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-chan#2: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2022-12-08T18:41:38.820Z INFO    03a09f56bba3d2c200cc55eda2f1f069564a97c1fb74345e1560e2868a8ab3d7d0-chan#1: Peer transient failure in CHANNELD_NORMAL: Disconnected
2022-12-08T18:42:42.070Z INFO    03a09f56bba3d2c200cc55eda2f1f069564a97c1fb74345e1560e2868a8ab3d7d0-channeld-chan#1: Peer connection lost
2022-12-08T18:42:42.070Z INFO    03a09f56bba3d2c200cc55eda2f1f069564a97c1fb74345e1560e2868a8ab3d7d0-chan#1: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)

[m-schmoock]

A peerid filtered Log debug could helpful to find that out

[petzsch]

I've configured loglevel debug and filtered the output by the nodeID from the Einundzwanzig and lnbig remote peers.
Thank you already for looking into this.

einundzwanzig.txt
lnbig.txt

[NicolasDorier]

@cdecker we know about the DNS peer announcement, this is actually what happen in 22.11 vanilla when we set the announce-addr. This was a breaking change for our merchants, so we decided to apply the patch #5796 which @rustyrussell did.

So now, it is core lightning that is resolving the domain passed in announce-addr, and it doesn't show DNS peer anymore (which is what we wanted). The problem is that it is taking the local IP rather than the public IP.

It is probably a breaking change as @petzsch didn't had this issue before. (0.10.2)

So we would expect core lightning to prefer public ips rather than local one, probably like it did before.

[petzsch]

Not sure that there was a breaking change between 0.10.2 and the current way host resolution is handled:

advertising local IP address ranges is problematic, but I can't say how it was in the 0.10.2 version as there I had a computer hostname different then the btcpayserver domain / announceable host. (moving from a home rpi node to a VPS again).

[m-schmoock]

@petzsch I looked into the logfiles a bit. The disconnects connectd: peer_out WIRE_WARNING seem to happen whenever status_peer_io(LOG_IO_OUT, &peer->id, ...) is called, most likely this is called by inject_peer_msg(peer, msg). Since we don't have a concrete message, rather than "WIRE_WARNING" the paths that can call/raise these are the ping/pong logic or 'send_custom_msg'.

Unfortunately this is all I can say just now.

• Does it happen for all LND peers?
• Do you have plugins that do custom messages?
• Do you have plugins that call rpc pings?

[petzsch]

So far I've only tested with Einundzwanzig (LND) and LNBIG (LND)... gotta put some more funds in the on-chain wallet to test some more. Next I would test with the Breez node which is afaik also LND.

I didn't enable any plugins, so just whats there by default, which according to the debug log below, is quite a bit of plugins.

How could I disable any of these plugins if they where causing the problem?

root@pay:~# docker logs btcpayserver_clightning_bitcoin | grep plugin-manager
2022-12-09T07:56:05.329Z DEBUG   plugin-manager: started(16) /usr/local/libexec/c-lightning/plugins/autoclean
2022-12-09T07:56:05.343Z DEBUG   plugin-manager: started(17) /usr/local/libexec/c-lightning/plugins/chanbackup
2022-12-09T07:56:05.359Z DEBUG   plugin-manager: started(18) /usr/local/libexec/c-lightning/plugins/bcli
2022-12-09T07:56:05.376Z DEBUG   plugin-manager: started(19) /usr/local/libexec/c-lightning/plugins/commando
2022-12-09T07:56:05.406Z DEBUG   plugin-manager: started(20) /usr/local/libexec/c-lightning/plugins/fetchinvoice
2022-12-09T07:56:05.433Z DEBUG   plugin-manager: started(21) /usr/local/libexec/c-lightning/plugins/funder
2022-12-09T07:56:05.461Z DEBUG   plugin-manager: started(22) /usr/local/libexec/c-lightning/plugins/topology
2022-12-09T07:56:05.479Z DEBUG   plugin-manager: started(23) /usr/local/libexec/c-lightning/plugins/keysend
2022-12-09T07:56:05.508Z DEBUG   plugin-manager: started(24) /usr/local/libexec/c-lightning/plugins/offers
2022-12-09T07:56:05.529Z DEBUG   plugin-manager: started(25) /usr/local/libexec/c-lightning/plugins/pay
2022-12-09T07:56:05.550Z DEBUG   plugin-manager: started(26) /usr/local/libexec/c-lightning/plugins/txprepare
2022-12-09T07:56:05.564Z DEBUG   plugin-manager: started(27) /usr/local/libexec/c-lightning/plugins/spenderp
2022-12-09T07:56:05.597Z DEBUG   plugin-manager: started(28) /usr/local/libexec/c-lightning/plugins/cln-grpc
2022-12-09T07:56:05.617Z DEBUG   plugin-manager: started(29) /usr/local/libexec/c-lightning/plugins/bookkeeper
2022-12-09T07:56:05.678Z DEBUG   plugin-manager: started(31) /root/.lightning/plugins/invoicewithdescriptionhash

[petzsch]

Just an observation:

I had lnbits running in a custom docker fragment and accessing /data/.lightning/lightning-rpc
Since I disabled that fragment and restarted the btcpay stack, the connection to lnbig seems to be running uninterrupted.
Einundzwanzig still doesn't accept my reconnect attempts... maybe I have a bad reputation with them now.

I will monitor the situation and update here if I find out anything new. (Maybe I'm eventually allowed to connect to Einundzwanzig again) If LNBits was the problem, then I'll write them a ticket.

[m-schmoock]

If you have an unfiltered debug log you might be able to find out the rpc calls (if any) that cause that. I suspect it doing pings more than allowed or something

[petzsch]

unfiltered log:
unfiltered.txt

Einundzwanzig still loosing connection quite often, LNBIG still running stable.
Should I try to re-enable lnbits and see if LNBIG causes me trouble again then? (for science)

[petzsch]

another unfiltered debug log:
unfiltered2.txt

not sure why, but a channel opened from remote (another lnbig one) doesn't transition it's state after 6 confirmations: (I think another lnbig one did that after I restarted clightning... that's not really acceptable)

https://mempool.space/de/tx/ec1d7d5bc2c37aac2cdb594d289362dd0eaa324b57ba734c159f8488a40c2e30

[cdecker]

Sounds like the channel not activating is due to lnd not sending the funding_locked when we expect it. We've tried to debug or reproduce that for the longest time. The good news is that disconnecting and reconnecting usually addresses it, and we'll be looking through the logs to see if something can help us to repro it.

[petzsch]

disconnecting and reconnecting the peer isn't possible via RTL:
Peer Has (at Least One) Channel In State Channeld_awaiting_lockin

The Einundzwanzig channel is now open without interruption. If I'd have to guess I would say it had to do with an overload of Gosipping to get the graph synced on my fresh node.

Gonna try my luck once more with running lnbits ... just to see if it is causing disconnects. Some parts just don't add up for me, yet.

[cdecker]

Filtering through the logs I get the following:

2022-12-09T12:29:45.955Z DEBUG   033e9ce4e8f0e68f7db49ffb6b9eecc10605f3f3fcb3c630545887749ab515b9c7-chan#4: Got depth change 1->2 for ec1d7d5bc2c37aac2cdb594d289362dd0eaa324b57ba734c159f8488a40c2e30
033e9ce4e8f0e68f7db49ffb6b9eecc10605f3f3fcb3c630545887749ab515b9c7-chan#4: Funding tx ec1d7d5bc2c37aac2cdb594d289362dd0eaa324b57ba734c159f8488a40c2e30 depth 2 of 3
...
2022-12-09T12:48:56.835Z DEBUG   033e9ce4e8f0e68f7db49ffb6b9eecc10605f3f3fcb3c630545887749ab515b9c7-channeld-chan#4: peer_in WIRE_CHANNEL_READY
2022-12-09T12:48:56.835Z DEBUG   033e9ce4e8f0e68f7db49ffb6b9eecc10605f3f3fcb3c630545887749ab515b9c7-channeld-chan#4: Stashing early WIRE_CHANNEL_READY msg!
...
2022-12-09T12:49:17.176Z DEBUG   033e9ce4e8f0e68f7db49ffb6b9eecc10605f3f3fcb3c630545887749ab515b9c7-chan#4: Got depth change 2->3 for ec1d7d5bc2c37aac2cdb594d289362dd0eaa324b57ba734c159f8488a40c2e30
2022-12-09T12:49:17.176Z DEBUG   033e9ce4e8f0e68f7db49ffb6b9eecc10605f3f3fcb3c630545887749ab515b9c7-chan#4: Funding tx ec1d7d5bc2c37aac2cdb594d289362dd0eaa324b57ba734c159f8488a40c2e30 depth 3 of 3
2022-12-09T12:49:17.180Z DEBUG   033e9ce4e8f0e68f7db49ffb6b9eecc10605f3f3fcb3c630545887749ab515b9c7-chan#4: attempting update blockheight 302e0ca488849f154c73ba574b32aa0edd6293284d59db2cac7ac3c25b7d1ded
...
2022-12-09T13:07:18.309Z DEBUG   033e9ce4e8f0e68f7db49ffb6b9eecc10605f3f3fcb3c630545887749ab515b9c7-chan#4: Got depth change 3->4 for ec1d7d5bc2c37aac2cdb594d289362dd0eaa324b57ba734c159f8488a40c2e30
2022-12-09T13:07:18.309Z DEBUG   033e9ce4e8f0e68f7db49ffb6b9eecc10605f3f3fcb3c630545887749ab515b9c7-chan#4: Funding tx ec1d7d5bc2c37aac2cdb594d289362dd0eaa324b57ba734c159f8488a40c2e30 depth 4 of 3
...
2022-12-09T13:13:49.024Z DEBUG   033e9ce4e8f0e68f7db49ffb6b9eecc10605f3f3fcb3c630545887749ab515b9c7-chan#4: Got depth change 4->5 for ec1d7d5bc2c37aac2cdb594d289362dd0eaa324b57ba734c159f8488a40c2e30
2022-12-09T13:13:49.025Z DEBUG   033e9ce4e8f0e68f7db49ffb6b9eecc10605f3f3fcb3c630545887749ab515b9c7-chan#4: Funding tx ec1d7d5bc2c37aac2cdb594d289362dd0eaa324b57ba734c159f8488a40c2e30 depth 5 of 3
2022-12-09T13:13:49.025Z DEBUG   03a09f56bba3d2c200cc55eda2f1f069564a97c1fb74345e1560e2868a8ab3d7d0-chan#1: attempting update blockheight a90955ea6424540bbd4e1d3cca08c062d71fadb86d9562f54f9cccc253bc40e6
2022-12-09T13:13:49.025Z DEBUG   03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-chan#2: attempting update blockheight b69b078c58bf5e884675f6c864b975a364d80b4b0858c478ce1fac8933ba7ba1
2022-12-09T13:13:49.025Z DEBUG   03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-chan#3: attempting update blockheight b89e51f4c7d9d997d4da5241cbd8cc3f25b2950f44489a486051d637217a4c7b
2022-12-09T13:13:49.025Z DEBUG   033e9ce4e8f0e68f7db49ffb6b9eecc10605f3f3fcb3c630545887749ab515b9c7-chan#4: attempting update blockheight 302e0ca488849f154c73ba574b32aa0edd6293284d59db2cac7ac3c25b7d1ded
...
2022-12-09T13:21:19.836Z DEBUG   033e9ce4e8f0e68f7db49ffb6b9eecc10605f3f3fcb3c630545887749ab515b9c7-chan#4: Got depth change 5->6 for ec1d7d5bc2c37aac2cdb594d289362dd0eaa324b57ba734c159f8488a40c2e30
2022-12-09T13:21:19.836Z DEBUG   033e9ce4e8f0e68f7db49ffb6b9eecc10605f3f3fcb3c630545887749ab515b9c7-chan#4: Funding tx ec1d7d5bc2c37aac2cdb594d289362dd0eaa324b57ba734c159f8488a40c2e30 depth 6 of 3
2022-12-09T13:21:19.836Z DEBUG   03a09f56bba3d2c200cc55eda2f1f069564a97c1fb74345e1560e2868a8ab3d7d0-chan#1: attempting update blockheight a90955ea6424540bbd4e1d3cca08c062d71fadb86d9562f54f9cccc253bc40e6
2022-12-09T13:21:19.836Z DEBUG   03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-chan#2: attempting update blockheight b69b078c58bf5e884675f6c864b975a364d80b4b0858c478ce1fac8933ba7ba1
2022-12-09T13:21:19.836Z DEBUG   03e5ea100e6b1ef3959f79627cb575606b19071235c48b3e7f9808ebcd6d12e87d-chan#3: attempting update blockheight b89e51f4c7d9d997d4da5241cbd8cc3f25b2950f44489a486051d637217a4c7b
2022-12-09T13:21:19.837Z DEBUG   033e9ce4e8f0e68f7db49ffb6b9eecc10605f3f3fcb3c630545887749ab515b9c7-chan#4: attempting update blockheight 302e0ca488849f154c73ba574b32aa0edd6293284d59db2cac7ac3c25b7d1ded

So it appears the remote end sees the new block first, we stash their channel_ready and then forget to re-apply it once we see the block ourselves? @rustyrussell that seems strange, because if that were true then we should see this way more often, shouldn't we?