search

lightningnetwork / lnd

Lightning Network Daemon ⚡️
MIT License
7.67k stars 2.07k forks source link

Unable to establish Gossip syncer with CLN channel peer, causing a loop of disconnections #6658

Closed TrezorHannes closed 2 years ago

TrezorHannes commented 2 years ago

Background

For 7 days, my node can't establish a healthy connection to a peer running CLN (presumably).

Your environment

I have the outdated channel-state with a few peers, since a reboot 2 days ago. It started with 20 peers / 117 with a stale last_update flag, and plenty of reboots or lncli reconnects with the peer didn't help. 26hrs later, 50% of channels got back. Now, 40hrs later, I have

peers disabling to me: 6

left with an old channel-state. What's worth mentioning: I changed locale globally 2 weeks before, and this reboot was the first restart since that change. I'm unsure if the local change could have caused a timestamp issue for gossip, but to be seen. First, suggest focusing on one channel.

Steps to reproduce

1) Compare my command with the same one on your node on mainnet, and see if the last_update flag of peer2 is as outdated as mine is

admin ~ ฿ lncli getchaninfo 812312593594384392
{
    "channel_id": "812312593594384392",
    "chan_point": "c6a6ee11cf5c8e2271de900613d9d570f26e66e2471ae5ca1d375d5706db9f4e:8",
    "last_update": 1655814213,
    "node1_pub": "037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3",
    "node2_pub": "0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c",
    "capacity": "5000000",
    "node1_policy": {
        "time_lock_delta": 40,
        "min_htlc": "1000",
        "fee_base_msat": "0",
        "fee_rate_milli_msat": "180",
        "disabled": false,
        "max_htlc_msat": "4950000",
        "last_update": 1655814213
    },
    "node2_policy": {
        "time_lock_delta": 34,
        "min_htlc": "1",
        "fee_base_msat": "0",
        "fee_rate_milli_msat": "0",
        "disabled": true,
        "max_htlc_msat": "4950000000",
        "last_update": 1655288297
    }
}
admin ~ ฿ date -d @1655288297
Wed Jun 15 12:18:17 CEST 2022
admin ~ ฿ date -d @1655814213
Tue Jun 21 14:23:33 CEST 2022

2) Logfiles excerpt, this is going on forever this way. Notable is 2022-06-22 08:30:56.100 [INF] PEER: unable to read message from 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736: read tcp 192.168.255.10:60428->54.38.159.246:9736: use of closed network connection

2022-06-22 08:27:46.539 [INF] SRVR: Disconnecting from 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736
2022-06-22 08:27:46.539 [INF] PEER: disconnecting 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736, reason: server: disconnecting peer 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736
2022-06-22 08:27:46.539 [INF] PEER: unable to read message from 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736: read tcp 192.168.255.10:58784->54.38.159.246:9736: use of closed network connection
2022-06-22 08:27:46.647 [INF] SRVR: Established connection to: 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736
2022-06-22 08:27:46.647 [INF] SRVR: Finalizing connection to 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736, inbound=false
2022-06-22 08:27:46.689 [INF] PEER: NodeKey(0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c) loading ChannelPoint(c6a6ee11cf5c8e2271de900613d9d570f26e66e2471ae5ca1d375d5706db9f4e:8)
2022-06-22 08:27:46.689 [INF] PEER: Negotiated chan series queries with 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c
2022-06-22 08:27:46.740 [INF] DISC: Removing GossipSyncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c
2022-06-22 08:27:46.851 [WRN] DISC: Gossip syncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c not found
2022-06-22 08:27:47.152 [INF] SRVR: Disconnecting from 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736
2022-06-22 08:27:47.152 [INF] PEER: disconnecting 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736, reason: server: disconnecting peer 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736
2022-06-22 08:27:47.152 [INF] PEER: unable to read message from 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736: read tcp 192.168.255.10:60410->54.38.159.246:9736: use of closed network connection
2022-06-22 08:27:47.240 [INF] SRVR: Established connection to: 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736
2022-06-22 08:27:47.240 [INF] SRVR: Finalizing connection to 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736, inbound=false
2022-06-22 08:27:47.285 [INF] PEER: NodeKey(0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c) loading ChannelPoint(c6a6ee11cf5c8e2271de900613d9d570f26e66e2471ae5ca1d375d5706db9f4e:8)
2022-06-22 08:27:47.285 [INF] PEER: Negotiated chan series queries with 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c
2022-06-22 08:27:47.285 [INF] DISC: Creating new GossipSyncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c
2022-06-22 08:27:47.453 [INF] DISC: Removing GossipSyncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c
2022-06-22 08:28:07.674 [WRN] RPCS: Gossip syncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c not found
2022-06-22 08:28:28.649 [WRN] RPCS: Gossip syncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c not found
2022-06-22 08:28:49.660 [WRN] RPCS: Gossip syncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c not found
2022-06-22 08:29:10.657 [WRN] RPCS: Gossip syncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c not found
2022-06-22 08:29:31.657 [WRN] RPCS: Gossip syncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c not found
2022-06-22 08:29:52.689 [WRN] RPCS: Gossip syncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c not found
2022-06-22 08:30:13.666 [WRN] RPCS: Gossip syncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c not found
2022-06-22 08:30:34.646 [WRN] RPCS: Gossip syncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c not found
2022-06-22 08:30:55.664 [WRN] RPCS: Gossip syncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c not found
2022-06-22 08:30:56.100 [INF] SRVR: Disconnecting from 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736
2022-06-22 08:30:56.100 [INF] PEER: disconnecting 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736, reason: server: disconnecting peer 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736
2022-06-22 08:30:56.100 [INF] PEER: unable to read message from 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736: read tcp 192.168.255.10:60428->54.38.159.246:9736: use of closed network connection
2022-06-22 08:30:56.195 [INF] SRVR: Established connection to: 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736
2022-06-22 08:30:56.195 [INF] SRVR: Finalizing connection to 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736, inbound=false
2022-06-22 08:30:56.235 [INF] PEER: NodeKey(0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c) loading ChannelPoint(c6a6ee11cf5c8e2271de900613d9d570f26e66e2471ae5ca1d375d5706db9f4e:8)
2022-06-22 08:30:56.235 [INF] PEER: Negotiated chan series queries with 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c
2022-06-22 08:30:56.235 [INF] DISC: Creating new GossipSyncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c
2022-06-22 08:30:56.301 [INF] DISC: Removing GossipSyncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c
2022-06-22 08:30:56.402 [WRN] DISC: Gossip syncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c not found

Expected behaviour

The channel, Gossip syncer is staying connected and more recent.

Actual behaviour

The channel is unhealthy, continuing reconnections, and hence unusable

2022-06-22 06:37:13.110 ⛔ disconnected from noserver4u | CLN 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c 

2022-06-22 06:37:13.202 💚 connected to noserver4u | CLN 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c 

2022-06-22 06:40:22.086 ⛔ disconnected from noserver4u | CLN 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c 

2022-06-22 06:40:22.170 💚 connected to noserver4u | CLN 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c 

2022-06-22 06:43:31.125 ⛔ disconnected from noserver4u | CLN 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c 

2022-06-22 06:43:31.215 💚 connected to noserver4u | CLN 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c 

2022-06-22 06:46:40.127 ⛔ disconnected from noserver4u | CLN 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c 

2022-06-22 06:46:40.225 💚 connected to noserver4u | CLN 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c 

2022-06-22 06:47:52.726 📣 local update for peer noserver4u | CLN 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c (online) 
    is_disabled: 0 -> 1
    updated_at: 2022-06-21T12:23:33.000Z -> 2022-06-22T06:47:52.469Z 

2022-06-22 06:49:48.088 ⛔ disconnected from noserver4u | CLN 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c 

2022-06-22 06:49:48.172 💚 connected to noserver4u | CLN 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c

Conclusion

While I could just close the channel and reopen, since I know other peers with that node don't have that issue, I wonder if that is a

TrezorHannes commented 2 years ago

Adding some interesting facts. The channel state is outdated for other nodes, too. This might be a CLN / LND gossip syncer connection issue?

To verify, call these two commands from your mainnet node:

The latter shows an delay in update to the gossip of > 2 days, the former / mine > 7 days.

daywalker90 commented 2 years ago

Hi, it's me the cln 0.11.1, bitcoind v23, debian bullseye node.

lightning-cli listchannels 738794x965x8
{
   "channels": [
      {
         "source": "037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3",
         "destination": "0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c",
         "short_channel_id": "738794x965x8",
         "public": true,
         "satoshis": 5000000,
         "amount_msat": "5000000000msat",
         "message_flags": 1,
         "channel_flags": 0,
         "active": true,
         "last_update": 1655888338,
         "base_fee_millisatoshi": 0,
         "fee_per_millionth": 180,
         "delay": 40,
         "htlc_minimum_msat": "1000msat",
         "htlc_maximum_msat": "4950000msat",
         "features": ""
      },
      {
         "source": "0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c",
         "destination": "037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3",
         "short_channel_id": "738794x965x8",
         "public": true,
         "satoshis": 5000000,
         "amount_msat": "5000000000msat",
         "message_flags": 1,
         "channel_flags": 1,
         "active": true,
         "last_update": 1655177350,
         "base_fee_millisatoshi": 0,
         "fee_per_millionth": 0,
         "delay": 34,
         "htlc_minimum_msat": "1msat",
         "htlc_maximum_msat": "4950000000msat",
         "features": ""
      }
   ]
}
2022-06-22T08:14:49.299Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-connectd: destroy_subd: 1 subds, to_peer conn (nil), read_to_die = 0
2022-06-22T08:14:49.299Z INFO    037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: Peer connection lost
2022-06-22T08:14:49.299Z INFO    037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-chan#50: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)
2022-06-22T08:14:49.299Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-lightningd: Will try reconnect in 1 seconds
2022-06-22T08:14:49.300Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-connectd: disconnect
2022-06-22T08:14:49.300Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-connectd: peer_conn_closed
2022-06-22T08:14:49.300Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-lightningd: peer_disconnect_done
2022-06-22T08:14:49.300Z DEBUG   plugin-funder: Cleaning up inflights for peer id 037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3
2022-06-22T08:14:49.332Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-connectd: Connect IN
2022-06-22T08:14:49.485Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-connectd: peer_out WIRE_INIT
2022-06-22T08:14:49.485Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-connectd: peer_in WIRE_INIT
2022-06-22T08:14:49.485Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-gossipd: seeker: starting gossip
2022-06-22T08:14:49.486Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-chan#50: Peer has reconnected, state CHANNELD_NORMAL: telling connectd to make active
2022-06-22T08:14:49.486Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-connectd: Handed peer, entering loop
2022-06-22T08:14:49.486Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-connectd: Activating for message WIRE_CHANNEL_REESTABLISH
2022-06-22T08:14:49.490Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: pid 3942791, msgfd 123
2022-06-22T08:14:49.490Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-chan#50: Already have funding locked in (and ready to announce)
2022-06-22T08:14:49.491Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-chan#50: attempting update blockheight 4e9fdb06575d371dcae51a47e2666ef270d5d9130690de71228e5ccf11eea6ce
2022-06-22T08:14:49.491Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-connectd: peer_out WIRE_GOSSIP_TIMESTAMP_FILTER
2022-06-22T08:14:49.492Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: option_static_remotekey = 1, option_anchor_outputs = 0
2022-06-22T08:14:49.492Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: init LOCAL: remote_per_commit = 035e370014d7717fe959119ac7a520c8bf153e7a8a43a4f9cdb5d44bfbd930d2dd, old_remote_per_commit = 03cc7a6e4f704ce302b0f524c66563fa15c8f03f49ad47f313e1875563609144d6 next_idx_local = 77074 next_idx_remote = 77098 revocations_received = 77096 feerates { SENT_ADD_COMMIT:503 SENT_ADD_ACK_REVOCATION:582 } range 253-37583 blockheights { SENT_ADD_ACK_REVOCATION:0 }, our current 741831
2022-06-22T08:14:49.492Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-06-22T08:14:49.492Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-06-22T08:14:49.493Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: peer_out WIRE_CHANNEL_REESTABLISH
2022-06-22T08:14:49.493Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
2022-06-22T08:14:49.493Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: billboard: Sent reestablish, waiting for theirs
2022-06-22T08:14:49.493Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: peer_in WIRE_CHANNEL_REESTABLISH
2022-06-22T08:14:49.493Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: Got reestablish commit=77097 revoke=77073
2022-06-22T08:14:49.494Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: next_revocation_number = 77073
2022-06-22T08:14:49.494Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-hsmd: Got WIRE_HSMD_SIGN_REMOTE_COMMITMENT_TX
2022-06-22T08:14:49.494Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: option_static_remotekey: fields are correct
2022-06-22T08:14:49.494Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: Retransmitting commitment, feerate LOCAL=582 REMOTE=503, blockheight LOCAL=0 REMOTE=0
2022-06-22T08:14:49.494Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-hsmd: Got WIRE_HSMD_CANNOUNCEMENT_SIG_REQ
2022-06-22T08:14:49.494Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: peer_out WIRE_UPDATE_FEE
2022-06-22T08:14:49.494Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: Creating commit_sig signature 77097 304402204fa038b66fd88ce9fa27bf0d983e6d2c33e383514e7d23229259cf4dfcd53ad10220741ced8c119da70c547cc7dc1c12bda4685aa1761ab2bcdaf92a672a103f0e5501 for tx 02000000014e9fdb06575d371dcae51a47e2666ef270d5d9130690de71228e5ccf11eea6c60800000000d80c848002fb20030000000000220020df9c12a59f339339a00bd5d4813b4df73d3714430e53517fa205d320f2071ab9d828490000000000160014aa78656d6f085dc0196b05adafdfe72c0d841ec10b4b5b20 wscript 522102127b9da18851feaedcc2d5f030394696ef4a80260c0621722ee078324266286321038fd64f9ed8c65d00d66ac40400320e7b0aa3552d1e05d2a213e9e8221957c53e52ae key 02127b9da18851feaedcc2d5f030394696ef4a80260c0621722ee0783242662863
2022-06-22T08:14:49.495Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: peer_out WIRE_COMMITMENT_SIGNED
2022-06-22T08:14:49.495Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: billboard perm: Reconnected, and reestablished.
2022-06-22T08:14:49.495Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: Exchanging announcement signatures.
2022-06-22T08:14:49.495Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: peer_out WIRE_ANNOUNCEMENT_SIGNATURES
2022-06-22T08:14:49.495Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: billboard: Funding transaction locked. Channel announced.
2022-06-22T08:14:49.525Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: billboard: Funding transaction locked. Channel announced.
Roasbeef commented 2 years ago

While I could just close the channel and reopen

If you want to close the channel, you can force close it.

These logs make it look like something unexpected happend on the CL side: 

2022-06-22T08:14:49.299Z DEBUG   037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-connectd: destroy_subd: 1 subds, to_peer conn (nil), read_to_die = 0
2022-06-22T08:14:49.299Z INFO    037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-channeld-chan#50: Peer connection lost
2022-06-22T08:14:49.299Z INFO    037f66e84e38fc2787d578599dfe1fcb7b71f9de4fb1e453c5ab85c05f5ce8c2e3-chan#50: Peer transient failure in CHANNELD_NORMAL: channeld: Owning subdaemon channeld died (62208)

These tweets by rusty cause me to believe that it's a CL issue that they're aware of, with a new minor release coming to resolve it (0.11.2):

We didn't make any significant changes to our p2p code in 0.15, though I know CL recently added support for multiple channels to a single peer, and looks like this is the case above (2 chans between the nodes).

TrezorHannes commented 2 years ago

Thanks @Roasbeef coming back to us.

We'll consider the next two steps available (close / reopen or wait and apply the upcoming CLN release) and report back here, for the benefit of others.

TrezorHannes commented 2 years ago

Looks like it stabilized now over time. Clearnet connections now established.

2022-06-26 00:25:44.322 [INF] PEER: unable to read message from 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736: EOF
2022-06-26 00:25:44.322 [INF] PEER: disconnecting 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736, reason: read handler closed
2022-06-26 00:25:44.525 [INF] DISC: Removing GossipSyncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c
2022-06-26 00:25:47.074 [WRN] SRVR: Already have 1 persistent connection requests for 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736, connecting anyway.
2022-06-26 00:28:06.285 [INF] SRVR: Established connection to: 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736
2022-06-26 00:28:06.285 [INF] SRVR: Finalizing connection to 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c@54.38.159.246:9736, inbound=false
2022-06-26 00:28:06.771 [INF] PEER: NodeKey(0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c) loading ChannelPoint(c6a6ee11cf5c8e2271de900613d9d570f26e66e2471ae5ca1d375d5706db9f4e:8)
2022-06-26 00:28:06.773 [INF] PEER: Negotiated chan series queries with 0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c
2022-06-26 00:28:06.773 [INF] DISC: Creating new GossipSyncer for peer=0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c
2022-06-26 06:40:52.517 [INF] DISC: GossipSyncer(0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c): fetching chan anns for 128 chans
2022-06-26 06:45:52.848 [INF] DISC: GossipSyncer(0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c): fetching chan anns for 128 chans
2022-06-26 07:51:57.049 [INF] DISC: GossipSyncer(0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c): filtering chan range: start_height=704308, num_blocks=1024
2022-06-26 07:51:57.050 [INF] DISC: GossipSyncer(0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c): sending final chan range chunk, size=900
2022-06-26 11:35:53.147 [INF] DISC: GossipSyncer(0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c): fetching chan anns for 3942 chans
2022-06-26 11:40:53.604 [INF] DISC: GossipSyncer(0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c): fetching chan anns for 128 chans
2022-06-26 11:58:53.106 [INF] DISC: GossipSyncer(0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c): fetching chan anns for 31 chans
2022-06-26 17:59:17.109 [INF] DISC: GossipSyncer(0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c): applying gossipFilter(start=2022-06-26 17:59:17.10929713 +0200 CEST m=+205256.731936658, end=2158-08-03 00:27:32.10929713 +0200 CEST)
2022-06-26 18:39:17.109 [INF] DISC: GossipSyncer(0380ef0209ff1b46c38a37cd40f613d1dae3eba481a909459d6c1434a0e56e5d8c): applying gossipFilter(start=0001-01-01 00:00:00 +0000 UTC, end=0001-01-01 00:00:00 +0000 UTC)

Closing this for now, but will keep an eye and see if it's happening again.