Connection between peers fails with BrokenPipe

[MitchTurner]

Hey.

We're continuing the process of updating our libp2p code from 0.50.0 to 0.53.1. We've been able to troubleshoot a lot of our problems but this one seems a bit too opaque to get good info. I was hoping to get some ideas on how to troubleshoot this.

We are trying to get our tests passing again. In at least one of these tests the nodes are unable to connect fully and runs indefinitly. With some instrumentation we were able to see the cause is most likely this BrokenPipe we see in a swarm event:

DialFailure(DialFailure { peer_id: Some(PeerId("16Uiu2HAmUxqDWMjipWW9viFFML6CTWxEjzi7oJzvpHBX2z382yYN")), error: Transport([("/ip4/127.0.0.1/tcp/41905/p2p/16Uiu2HAmUxqDWMjipWW9viFFML6CTWxEjzi7oJzvpHBX2z382yYN", Other(Custom { kind: Other, error: Other(Right(Select(ProtocolError(IoError(Os { code: 32, kind: BrokenPipe, message: "Broken pipe" }))))) }))]), connection_id: ConnectionId(96) })

Not much to go off of. It seems like it is most likely happening in the DNS Transport code. We are using Tokio + WS + TCP in the tests.

I'm going to keep digging into this but I figured y'all might have some ideas. LMK if you have questions about our setup.

Here is the WIP PR of our changes if that could be useful: FuelLabs/fuel-core#1379

[thomaseizinger]

The ProtocolError bit hints that there is a problem during the initial handshake of the multistream-select protocols. Can you turn up the log-level to debug / trace and perhaps find anything through there? Note that v0.53.0 is using tracing so you'll need to initialize a tracing_subscriber.

[MitchTurner]

I've been looking at this for a while, reading through the tracing output and trying to use the debugger to get some more insight.

It looks like the last thing that happens in the communication before failing is it tries specifying yamux as the protocol. Here are some of the tracing outputs (the ones that say ERROR are just the tracing logs I've added in debugging for visibility):

 DEBUG new_incoming_connection{remote_addr=/ip4/127.0.0.1/tcp/39273 id=143}: multistream_select::listener_select: Listener: confirming protocol: /fuel/upgrade/0    
 DEBUG new_incoming_connection{remote_addr=/ip4/127.0.0.1/tcp/39273 id=143}: multistream_select::listener_select: Listener: sent confirmed protocol: /fuel/upgrade/0    
 ERROR new_incoming_connection{remote_addr=/ip4/127.0.0.1/tcp/39273 id=143}: fuel_core_p2p::config::fuel_upgrade: upgrade inbound!
 DEBUG Transport::dial{address=/ip4/127.0.0.1/tcp/40239/p2p/16Uiu2HAmQGaTj3wrhFnEs7arRQRTzyXfjkXWvbaMz2cfnYz4FL1C}: multistream_select::dialer_select: Dialer: Received confirmation for protocol: /fuel/upgrade/0    
 ERROR Transport::dial{address=/ip4/127.0.0.1/tcp/40239/p2p/16Uiu2HAmQGaTj3wrhFnEs7arRQRTzyXfjkXWvbaMz2cfnYz4FL1C}: fuel_core_p2p::config::fuel_upgrade: upgrade outbound!
 DEBUG Transport::dial{address=/ip4/127.0.0.1/tcp/40239/p2p/16Uiu2HAmQGaTj3wrhFnEs7arRQRTzyXfjkXWvbaMz2cfnYz4FL1C}: multistream_select::dialer_select: Dialer: Proposed protocol: /yamux/1.0.0    
 ERROR new_incoming_connection{remote_addr=/ip4/127.0.0.1/tcp/39273 id=143}: fuel_core_p2p::config::fuel_upgrade: Received checksum: [56, 114, 58, 46, 94, 138, 23, 170, 121, 80, 220, 0, 130, 9, 148, 78, 137, 143, 105, 167, 189, 16, 162, 60, 131, 157, 52, 30, 147, 95, 213, 202]
 DEBUG next_event{local_peer_id=16Uiu2HAmQGaTj3wrhFnEs7arRQRTzyXfjkXWvbaMz2cfnYz4FL1C local_address=0.0.0.0}:Swarm::poll: libp2p_swarm: Incoming connection failed: Transport(Other(Custom { kind: Other, error: Other(Right(Select(Failed))) }))
 ERROR next_event{local_peer_id=16Uiu2HAmQGaTj3wrhFnEs7arRQRTzyXfjkXWvbaMz2cfnYz4FL1C local_address=0.0.0.0}:Swarm::poll: fuel_core_p2p::discovery: discovery swarm event: ListenFailure(ListenFailure { local_addr: "/ip4/127.0.0.1/tcp/40239", send_back_addr: "/ip4/127.0.0.1/tcp/39273", error: Transport(Other(Custom { kind: Other, error: Other(Right(Select(Failed))) })), connection_id: ConnectionId(143) })
 ERROR reserved_nodes_reconnect_works:next_event{local_peer_id=16Uiu2HAmKE3TYd7ZVrTUjHbzJyCgB1FnSPGqCw5ENqCTUPHR6ZQx local_address=0.0.0.0}:Swarm::poll: fuel_core_p2p::discovery: discovery swarm event: DialFailure(DialFailure { peer_id: Some(PeerId("16Uiu2HAmQGaTj3wrhFnEs7arRQRTzyXfjkXWvbaMz2cfnYz4FL1C")), error: Transport([("/ip4/127.0.0.1/tcp/40239/p2p/16Uiu2HAmQGaTj3wrhFnEs7arRQRTzyXfjkXWvbaMz2cfnYz4FL1C", Other(Custom { kind: Other, error: Other(Right(Select(ProtocolError(IoError(Os { code: 32, kind: BrokenPipe, message: "Broken pipe" }))))) }))]), connection_id: ConnectionId(142) })
 DEBUG next_event{local_peer_id=16Uiu2HAmQGaTj3wrhFnEs7arRQRTzyXfjkXWvbaMz2cfnYz4FL1C local_address=0.0.0.0}: fuel_core_p2p::p2p_service: event=IncomingConnectionError { connection_id: ConnectionId(143), local_addr: "/ip4/127.0.0.1/tcp/40239", send_back_addr: "/ip4/127.0.0.1/tcp/39273", error: Transport(Other(Custom { kind: Other, error: Other(Right(Select(Failed))) })) }
 DEBUG next_event{local_peer_id=16Uiu2HAmQGaTj3wrhFnEs7arRQRTzyXfjkXWvbaMz2cfnYz4FL1C local_address=0.0.0.0}: fuel_core_p2p::p2p_service: return=None

It's possible some of these are from the other node that is running in the same test as well.

Besides the yamux stuff, the other piece of info we get here is:

libp2p_swarm: Incoming connection failed: Transport(Other(Custom { kind: Other, error: Other(Right(Select(Failed))) }))

which isn't particularly informative, but gives us a little more to go on I guess.

[MitchTurner]

Okay. I just switched to using the SwarmBuilder instead of manually constructing the Swarm. I'm now getting some new, more informative errors:

2023-12-01T04:33:42.607441Z DEBUG reserved_nodes_reconnect_works:next_event{local_peer_id=16Uiu2HAm9eWBdgWagErfWqqrUKgRQtsSkpwWpf92tYnZLcQttRf9 local_address=0.0.0.0}:Swarm::poll: libp2p_swarm: Connection attempt to peer failed with WrongPeerId { obtained: PeerId("12D3KooWE7WwgZzhLByQCfu6U5WpeFvmKk2HavyW8rtcxgWs5nTe"), endpoint: Dialer { address: "/ip4/127.0.0.1/tcp/43061/p2p/16Uiu2HAmNRxmbDkrppso6kaap4fe5CqVPxqnPeAKBH6RmxDsuHSD", role_override: Dialer } }. peer=16Uiu2HAmNRxmbDkrppso6kaap4fe5CqVPxqnPeAKBH6RmxDsuHSD

It's getting late here, so I might pick that up in the morning. I'm also not 100% confident that I'm constructing the SwarmBuilder correctly, but it looks like I'll have more to go on.

[thomaseizinger]

How are you constructing the address that is being dialed? Does it contain /p2p? Does the node in question actually have the stated identity?

[MitchTurner]

Ah. It's because I was explicitly providing a local_peer_id to the SwarmBuilder before. I can just use the one the SwarmBuilder creates for me.

THE TEST IS PASSING NOW. Thank you. Using the modern SwarmBuilder did the trick 🥇