stream reset but libp2p still tries to open a stream

[hivenet-mathieu-lacage]

Hi,

I see the following sequence of logs on one of my client nodes trying to establish a stream to a remote:

2024-12-03T17:48:55.535Z	DEBUG	basichost	basic/basic_host.go:821	host 12D3KooWM5ojZ9SBVn8pt2zH8wdZJqsF6xWiUCJzYjvorH5VgZhw finished dialing QmZj5ngfTRRMnHv7aXFkS74oMtCKM5Nyzm1kQoVLkdehgp

2024-12-03T17:48:55.535Z	DEBUG	swarm2	swarm/swarm.go:475	[12D3KooWM5ojZ9SBVn8pt2zH8wdZJqsF6xWiUCJzYjvorH5VgZhw] opening stream to peer [QmZj5ngfTRRMnHv7aXFkS74oMtCKM5Nyzm1kQoVLkdehgp]

2024-12-03T17:48:55.622Z	DEBUG	basichost	basic/basic_host.go:463	protocol mux failed: stream reset (took 87.684802ms, id:QmZj5ngfTR-17-101, remote peer:QmZj5ngfTRRMnHv7aXFkS74oMtCKM5Nyzm1kQoVLkdehgp, remote addr:/ip4/57.128.35.162/udp/4001/quic-v1/p2p/QmYPwNuMCDMC1QKR6hQZH6XFZkqfwf6ruE4pRECAZh7VAm/p2p-circuit)

2024-12-03T17:48:57.911Z	DEBUG	swarm2	swarm/swarm.go:475	[12D3KooWM5ojZ9SBVn8pt2zH8wdZJqsF6xWiUCJzYjvorH5VgZhw] opening stream to peer [QmZj5ngfTRRMnHv7aXFkS74oMtCKM5Nyzm1kQoVLkdehgp]

2024-12-03T17:48:57.911Z	DEBUG	net/identify	identify/id.go:492	/ipfs/id/1.0.0 sending message to QmZj5ngfTRRMnHv7aXFkS74oMtCKM5Nyzm1kQoVLkdehgp /ip4/57.128.35.162/udp/4001/quic-v1/p2p/QmYPwNuMCDMC1QKR6hQZH6XFZkqfwf6ruE4pRECAZh7VAm/p2p-circuit

I understand this to mean that:

1. the connection is established via the relay, as expected
2. I attempt to open a stream on top of the connection
3. ouch, the remote peer sends a stream reset message (I am still trying to find out why)
4. instead of returning this error to the higher layers of the application, libp2p attempts to open a new stream to the remote.

Now, in general, I like libp2p's willingness to "do what I mean" but in this specific case, the second stream connection attempt is timing out 20 seconds later which is a tad too much: I'd like to make sure the application layer knows about this failure and does something about it quickly. More generally, here, I am surprised that libp2p is doing this silent attempt to open the stream a second time.

If I understood what is going on here, is there a way to disable that behavior ?

[cpeliciari]

Could you provide an example of how you are doing this?
You can pass the context with a timeout to limit the time.

[hivenet-mathieu-lacage]

@cpeliciari I setup a context timeout during connection and stream establishment. then, setup a Deadline timeout on the write call.

Pseudo-code below:

ctx = context.WithTimeout(Ctx, 30*time.Second) 
host.Connect(ctx, ...)
stream = host.NewStream(ctx, ...)
deadline, ok := ctx.Deadline()
stream.SetDeadline(deadline)
// Write blows up 20+s later
stream.Write(...)

[MarcoPolo]

instead of returning this error to the higher layers of the application, libp2p attempts to open a new stream to the remote.

If I'm reading your logs correctly, I think this error is happening while handling a new stream opened from the remote peer, not while you are trying to open a new stream. The log line of basic/basic_host.go:463 protocol mux failed is from here, which happens when a remote peer opens a new stream to us (i.e. we are the server, they are the client). This means that this error happens on a different stream than the one you opened with NewStream.

That said, I'm not sure why you are timing out. Are these streams opened only on the relayed (and limited) connection? If so, do you have WithAllowLimitedConn set on the context? This tells the libp2p you are willing to use a stream that is on top of a limited connection. If you don't set this, and the connection is limited (default behavior by relays to save resources), then NewStream will wait for you to have a direct connection before giving you a new stream (which could happen via hole-punching).

[hivenet-mathieu-lacage]

@MarcoPolo thank you for the hints: they triggered the right chains of thinking on my side to debug this further.

1. you are entirely correct: I misread the source code.
2. yes, I do use WithAllowLimitedConn as follows:

ctx = context.WithTimeout(Ctx, 30*time.Second) 
host.Connect(ctx, ...)
ctx = network.WithAllowLimitedConn(ctx, "enable-relay")
stream = host.NewStream(ctx, ...)
deadline, ok := ctx.Deadline()
stream.SetDeadline(deadline)
// Write blows up 20+s later
stream.Write(...)

Am I correct that this is what you expected ?

Now, after re-reading the go-libp2p source code, I think I never really understood what the above does.

My current understanding of the above is that it tells libp2p that, if the relay allocates a "limited" connection (Stat.Limited = true), that is, if it gives me a reservation with explicit delay and data limits (2mins and 128K by default if I am not mistaken), I am going to use that relayed connection to establish a stream to the remote. If I do not set this flag, libp2p sees the "limited" connection and decides it needs to establish a direct connection first before creating the stream over the direct connection.

Once the "limited" connection is established, the relay monitors my usage and closes the relayed connection if it uses more than 128K bytes or if it lasts for more than 2mins.

Am I correct in my understanding ?

[hivenet-mathieu-lacage]

@MarcoPolo FYI, after debugging this further, it turns out that the bug was on the remote side: the client did successfully establish a connection and a stream to the remote, it sent its data there, and remote received it and started to process it and then... it took forever to process the data which is why my client-side timeouts triggered.

Thank you for taking time to help me.