Multiple established connections, likely done by Kademlia behavior

[b-zee]

I have a bit of a general question. We're using a combination of Kademlia, Identify, AutoNAT and a custom request/response behavior.

We're starting to see connections getting established multiple times, even 50-100 times, to the same peer. We do not manually dial much except initially during bootstrap. During this bootstrap we specify PeerCondition::NotDialing which prevents from dialing the same peer multiple times simultaneously. However, this doesn't seem to be happening with e.g. Kademlia.

I do wonder what a good way is to debug this, as the events and logs are not really helpful so far. It's not entirely clear what behavior does the dialing or why.

My first thought is that multiplexing should be so that we have one outgoing connection and one incoming connection per peer. Not more than that. I know there is a connection_limits behavior, but that doesn't allow me to specify it that way.

[mxinden]

Thank you for reporting this @b-zee!

We're starting to see connections getting established multiple times, even 50-100 times

Do I understand correctly that these 100 connection attempts are ~simultaneous, i.e. that all of them are spawned before the first connection is fully established?

I wonder why we use Disconnected instead of NotDialing as a default.

rust-libp2p/swarm/src/dial_opts.rs

Lines 311 to 325 in 1246d83

	#[derive(Debug, Copy, Clone, Default)]
	pub enum PeerCondition {
	/// A new dialing attempt is initiated _only if_ the peer is currently
	/// considered disconnected, i.e. there is no established connection
	/// and no ongoing dialing attempt.
	#[default]
	Disconnected,
	/// A new dialing attempt is initiated _only if_ there is currently
	/// no ongoing dialing attempt, i.e. the peer is either considered
	/// disconnected or connected but without an ongoing dialing attempt.
	NotDialing,
	/// A new dialing attempt is always initiated, only subject to the
	/// configured connection limits.
	Always,
	}

Can you test with NotDialing as the default in your setup? I.e. can you test with the diff below?

modified   swarm/src/dial_opts.rs
@@ -313,11 +313,11 @@ pub enum PeerCondition {
     /// A new dialing attempt is initiated _only if_ the peer is currently
     /// considered disconnected, i.e. there is no established connection
     /// and no ongoing dialing attempt.
-    #[default]
     Disconnected,
     /// A new dialing attempt is initiated _only if_ there is currently
     /// no ongoing dialing attempt, i.e. the peer is either considered
     /// disconnected or connected but without an ongoing dialing attempt.
+    #[default]
     NotDialing,
     /// A new dialing attempt is always initiated, only subject to the
     /// configured connection limits.

[b-zee]

Thanks for the pointer! I will try!

Just a quick note: a thought I had before is that I can't specify two conditions simultaneously. We'd both not want to dial when we are already dialing, but also if we are already connected. However, because of NAT, we still always want to make sure we can dial outwards.

[b-zee]

Do I understand correctly that these 100 connection attempts are ~simultaneous, i.e. that all of them are spawned before the first connection is fully established?

Yes, it happens in mere milliseconds. With a local test, I have 3-4 interfaces it binds to, so I get tens of connections for each interface (192.168.1.x, 10.0.0.x, 127.0.0.1, etc). That seems to just highlight the problem more though, it's not having to do with the problem itself I think.

(Still with the original code, will try patching today probably.)

Example logs

``` [2023-07-11T09:16:29.519084Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/127.0.0.1/tcp/37870) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=3 [2023-07-11T09:16:29.519115Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/10.0.0.2/tcp/60038) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=4 [2023-07-11T09:16:29.519145Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/10.0.0.2/tcp/60022) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=5 [2023-07-11T09:16:29.519178Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.251/tcp/56764) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=6 [2023-07-11T09:16:29.519205Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/127.0.0.1/tcp/37866) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=7 [2023-07-11T09:16:29.520071Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/127.0.0.1/tcp/37876) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=8 [2023-07-11T09:16:29.520312Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.247/tcp/49032) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=9 [2023-07-11T09:16:29.520527Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/10.0.0.2/tcp/60072) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=10 [2023-07-11T09:16:29.520562Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/127.0.0.1/tcp/37896) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=11 [2023-07-11T09:16:29.520588Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.251/tcp/56780) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=12 [2023-07-11T09:16:29.520626Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/10.0.0.2/tcp/60046) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=13 [2023-07-11T09:16:29.520664Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.247/tcp/49030) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=14 [2023-07-11T09:16:29.520892Z TRACE sn_networking::event] KademliaEvent ignored: InboundRequest { request: FindNode { num_closer_peers: 8 } } [2023-07-11T09:16:29.521021Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.247/tcp/49024) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=15 [2023-07-11T09:16:29.521079Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/10.0.0.2/tcp/60074) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=16 [2023-07-11T09:16:29.521101Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/10.0.0.2/tcp/60098) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=17 [2023-07-11T09:16:29.521118Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.247/tcp/49066) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=18 [2023-07-11T09:16:29.521170Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/127.0.0.1/tcp/37932) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=19 [2023-07-11T09:16:29.521245Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/10.0.0.2/tcp/60140) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=20 [2023-07-11T09:16:29.521272Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/127.0.0.1/tcp/37936) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=21 [2023-07-11T09:16:29.521298Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.247/tcp/49048) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=22 [2023-07-11T09:16:29.521357Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/127.0.0.1/tcp/37920) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=23 [2023-07-11T09:16:29.521382Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/127.0.0.1/tcp/37902) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=24 [2023-07-11T09:16:29.521451Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.251/tcp/56792) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=25 [2023-07-11T09:16:29.521470Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/10.0.0.2/tcp/60122) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=26 [2023-07-11T09:16:29.521489Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.247/tcp/49034) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=27 [2023-07-11T09:16:29.521539Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/10.0.0.2/tcp/60086) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=28 [2023-07-11T09:16:29.521580Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/127.0.0.1/tcp/37960) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=29 [2023-07-11T09:16:29.521606Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/10.0.0.2/tcp/60106) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=30 [2023-07-11T09:16:29.521647Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/127.0.0.1/tcp/37948) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=31 [2023-07-11T09:16:29.521681Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.247/tcp/49052) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=32 [2023-07-11T09:16:29.521708Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.251/tcp/56796) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=33 [2023-07-11T09:16:29.521758Z TRACE sn_networking::event] KademliaEvent ignored: InboundRequest { request: FindNode { num_closer_peers: 8 } } [2023-07-11T09:16:29.521919Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/10.0.0.2/tcp/60142) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=34 [2023-07-11T09:16:29.521946Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.251/tcp/56838) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=35 [2023-07-11T09:16:29.522042Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.251/tcp/56770) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=36 [2023-07-11T09:16:29.522072Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.251/tcp/56790) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=37 [2023-07-11T09:16:29.522100Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/10.0.0.2/tcp/60130) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=38 [2023-07-11T09:16:29.522124Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/10.0.0.2/tcp/60060) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=39 [2023-07-11T09:16:29.522142Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/127.0.0.1/tcp/37916) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=40 [2023-07-11T09:16:29.522160Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.251/tcp/56822) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=41 [2023-07-11T09:16:29.522184Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/127.0.0.1/tcp/37880) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=42 [2023-07-11T09:16:29.522214Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/127.0.0.1/tcp/37886) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=43 [2023-07-11T09:16:29.522984Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.247/tcp/49072) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=44 [2023-07-11T09:16:29.523010Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.251/tcp/56808) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=45 [2023-07-11T09:16:29.523061Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.251/tcp/56798) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=46 [2023-07-11T09:16:29.523082Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/192.168.1.251/tcp/56834) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=47 [2023-07-11T09:16:29.523105Z DEBUG sn_networking::event] ConnectionEstablished: incoming (/ip4/127.0.0.1/tcp/37966) peer_id=12D3KooWMbTwut6ZoPtDwkcNmvTUJMK2Bcaw4mn4Bwb7m6worhC3 num_established=48 ```

[b-zee]

Looks like your suggested patch does wonders. I got a maximum num_established of 7, compared to 50-100.

I have submitted it as a PR: #4185
Let's discuss that specific change there.

[mxinden]

With #4224 merged I consider the immediate issue resolved. #4225 is tracked in the v0.53.0 milestone.

Thanks everyone for the fruitful discussion.