webrtc: opening substreams should time out on inactivity

[haikoschol]

Behavior

This issue surfaced when testing a libp2p dialer with a litep2p listener, running the ping protocol in both directions. The expected behavior is that both sides open a substream, negotiate the ping protocol, send pings, receive pongs and emit an event with the round-trip time. The observed behavior is that this works for the substream from libp2p to litep2p, but fails in the other direction. When testing a libp2p dialer and a libp2p listener, everything works in both directions but there is a delay until the first ping event is emitted on the listener.

Note: In this issue description, "dialer" always refers to the initiator of the connection and "listener" to the peer that accepts the connection, as opposed to the initiator/acceptor of individual substreams. So when "the listener opens a substream", it is the dialer for this substream, but what matters is that it is the peer that accepted the connection on which all substreams are established.

Root cause

The root cause is that the (libp2p) dialer is not ready to accept inbound substreams soon enough. libp2p uses webrtc.rs, which heavily relies on callbacks. The library lets the consumer register a callback for newly opened inbound substreams. In dialers using libp2p, this callback is registered after the first inbound substream is detected by webrtc.rs. Below is a trace log from a libp2p dialer where I added a log statement in libp2p_webrtc::tokio::connection::Connection::register_incoming_data_channels_handler().

2025-12-04T04:37:44.333620Z DEBUG webrtc_sctp::association::association_internal: [] accepted a new stream (streamIdentifier: 1)    
[...]
2025-12-04T04:37:44.334334Z DEBUG Transport::dial{address=/ip4/127.0.0.1/udp/8888/webrtc-direct/certhash/uEiBMHBJIsfmJQLQAr9DNLWohRjpnw3ZD3SbKUPVKbDxTmw/p2p/12D3KooWKWTmDX6bUZFhMQWGzw2GjgFNKGumjBmZooX71QWwTF9S}: libp2p_webrtc::tokio::connection: Registering incoming data channels handler

The handler is registered after a new SCTP stream was detected, so it never gets called for this stream, or, more precisely, the WebRTC data channel opened on this stream.

Timeline (libp2p -> litep2p)

• T0: listener opens substream and RTC data channel
• T1: listener sends multistream-select header and /ipfs/ping/1.0.0 protocol
• T2: dialer confirms opening of RTC data channel (handler would be called here)
• T3: dialer registers on_open_channel handler
• T4: listener waits for negotiation response indefinitely

When using a libp2p listener, this works because libp2p puts a timeout on opening substreams after which they are closed and a new one is opened. This is from a trace log of a libp2p listener:

2025-12-03T14:51:54.235237Z TRACE new_established_connection{remote_addr=/ip4/192.168.1.134/udp/61815/webrtc-direct id=1 peer=12D3KooWDEEXpAxzueSHmpM5SsnTG3o4fv1HstWHSdre2acQuqQ5}:Connection::poll: libp2p_webrtc::tokio::connection: Opening data channel channel=1
2025-12-03T14:51:54.235297Z DEBUG libp2p_webrtc::tokio::connection: Data channel open channel=1
2025-12-03T14:51:54.235402Z TRACE new_established_connection{remote_addr=/ip4/192.168.1.134/udp/61815/webrtc-direct id=1 peer=12D3KooWDEEXpAxzueSHmpM5SsnTG3o4fv1HstWHSdre2acQuqQ5}:Connection::poll: libp2p_webrtc::tokio::connection: Outbound stream stream=1
2025-12-03T14:51:54.235628Z DEBUG new_established_connection{remote_addr=/ip4/192.168.1.134/udp/61815/webrtc-direct id=1 peer=12D3KooWDEEXpAxzueSHmpM5SsnTG3o4fv1HstWHSdre2acQuqQ5}:Connection::poll: multistream_select::dialer_select: Dialer: Proposed protocol protocol=/ipfs/ping/1.0.0
[...]
2025-12-03T14:51:54.239506Z DEBUG new_established_connection{remote_addr=/ip4/192.168.1.134/udp/61815/webrtc-direct id=1 peer=12D3KooWDEEXpAxzueSHmpM5SsnTG3o4fv1HstWHSdre2acQuqQ5}:Connection::poll: webrtc_data::data_channel: Received DATA_CHANNEL_ACK    
[...]
2025-12-03T14:52:04.236555Z DEBUG new_established_connection{remote_addr=/ip4/192.168.1.134/udp/61815/webrtc-direct id=1 peer=12D3KooWDEEXpAxzueSHmpM5SsnTG3o4fv1HstWHSdre2acQuqQ5}:Connection::poll:ConnectionHandler::poll: libp2p_ping::handler: Ping failure: Other { error: Custom { kind: TimedOut, error: "ping protocol negotiation timed out" } }
2025-12-03T14:52:04.236851Z  INFO new_established_connection{remote_addr=/ip4/192.168.1.134/udp/61815/webrtc-direct id=1 peer=12D3KooWDEEXpAxzueSHmpM5SsnTG3o4fv1HstWHSdre2acQuqQ5}:Connection::poll: libp2p_webrtc_utils::stream::drop_listener: Stream dropped without graceful close, sending Reset
[...]
2025-12-03T14:52:04.237352Z TRACE new_established_connection{remote_addr=/ip4/192.168.1.134/udp/61815/webrtc-direct id=1 peer=12D3KooWDEEXpAxzueSHmpM5SsnTG3o4fv1HstWHSdre2acQuqQ5}:Connection::poll: libp2p_webrtc::tokio::connection: Opening data channel channel=3
2025-12-03T14:52:04.237509Z DEBUG libp2p_webrtc::tokio::connection: Data channel open channel=3
[...]
2025-12-03T14:52:04.237667Z TRACE new_established_connection{remote_addr=/ip4/192.168.1.134/udp/61815/webrtc-direct id=1 peer=12D3KooWDEEXpAxzueSHmpM5SsnTG3o4fv1HstWHSdre2acQuqQ5}:Connection::poll: libp2p_webrtc::tokio::connection: Outbound stream stream=3
2025-12-03T14:52:04.237718Z TRACE webrtc_sctp::association::association_internal: [] T3-rtx timer start (pt1)    
2025-12-03T14:52:04.237860Z DEBUG new_established_connection{remote_addr=/ip4/192.168.1.134/udp/61815/webrtc-direct id=1 peer=12D3KooWDEEXpAxzueSHmpM5SsnTG3o4fv1HstWHSdre2acQuqQ5}:Connection::poll: multistream_select::dialer_select: Dialer: Proposed protocol protocol=/ipfs/ping/1.0.0
[...]
2025-12-03T14:52:04.243118Z DEBUG new_established_connection{remote_addr=/ip4/192.168.1.134/udp/61815/webrtc-direct id=1 peer=12D3KooWDEEXpAxzueSHmpM5SsnTG3o4fv1HstWHSdre2acQuqQ5}:Connection::poll: webrtc_data::data_channel: Received DATA_CHANNEL_ACK    
[...]
2025-12-03T14:52:04.245384Z TRACE new_established_connection{remote_addr=/ip4/192.168.1.134/udp/61815/webrtc-direct id=1 peer=12D3KooWDEEXpAxzueSHmpM5SsnTG3o4fv1HstWHSdre2acQuqQ5}:Connection::poll: multistream_select::protocol: Received message Header(V1)
[...]
2025-12-03T14:52:04.245598Z TRACE new_established_connection{remote_addr=/ip4/192.168.1.134/udp/61815/webrtc-direct id=1 peer=12D3KooWDEEXpAxzueSHmpM5SsnTG3o4fv1HstWHSdre2acQuqQ5}:Connection::poll: multistream_select::protocol: Received message Protocol(Protocol("/ipfs/ping/1.0.0"))
2025-12-03T14:52:04.245629Z DEBUG new_established_connection{remote_addr=/ip4/192.168.1.134/udp/61815/webrtc-direct id=1 peer=12D3KooWDEEXpAxzueSHmpM5SsnTG3o4fv1HstWHSdre2acQuqQ5}:Connection::poll: multistream_select::dialer_select: Dialer: Received confirmation for protocol protocol=/ipfs/ping/1.0.0
[...]
2025-12-03T14:52:04.249209Z DEBUG new_established_connection{remote_addr=/ip4/192.168.1.134/udp/61815/webrtc-direct id=1 peer=12D3KooWDEEXpAxzueSHmpM5SsnTG3o4fv1HstWHSdre2acQuqQ5}:Connection::poll:ConnectionHandler::poll: libp2p_ping::handler: ping succeeded rtt=3.438083ms

Timeline (libp2p -> libp2p)

• T0: listener opens substream and RTC data channel (channel 1 in the log)
• T1: listener sends multistream-select header and /ipfs/ping/1.0.0 protocol
• T2: dialer confirms opening of RTC data channel (handler would be called here)
• T3: dialer registers on_open_channel handler
• T4: listener waits for negotiation response until timeout is reached and closes the channel
• T5: listener opens another channel (channel 3 in the log)
• T6: listener sends multistream-select header and /ipfs/ping/1.0.0 protocol
• T7: dialer confirms opening of RTC data channel (handler is called here)
• T8: dialer responds to negotiation -> substream is established
• T9: listener sends ping
• T10: dialer sends pong
• T11: listener emits ping event with RTT

I did not investigate whether it is possible to register the handler for opened channels earlier in libp2p. Instead of doing that, I think litep2p should be modified to have a timeout as well, to increase robustness in case the remote never answers the multistream-select negotiation.

Note: This is probably not WebRTC-specific, i.e. the timeout behavior would likely increase robustness regardless of the transport protocol used.