Skip to content

Unable to open subsequent data channels if the WebRTC Direct initial handshake channel has been closed #5986

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
achingbrain opened this issue Apr 14, 2025 · 7 comments

Comments

@achingbrain
Copy link
Member

achingbrain commented Apr 14, 2025

Summary

The WebRTC Direct spec says:

On success of the authentication handshake, the used datachannel is closed and the plain WebRTC connection is used with its multiplexing capabilities via datachannels.

https://github.com/libp2p/specs/blob/master/webrtc/webrtc-direct.md#connection-security

At the moment the js-libp2p implementation does not close the handshake datachannel, leaving it open for the duration of the connection.

Given that the final data read from the channel during the noise handshake is done by the client, it would be the one to close the connection.

I am trying to update the js-libp2p implementation to close the handshake datachannel as per the spec but if I do, the transport interop tests start to fail against rust-libp2p with Chrome/Firefox/WebKit being the diallers (go & Node.js work fine).

From what I can see, after the handshake channel has been closed, opening the subsequent outbound channel to send the ping message never completes.

Inbound datachannels are still opened correctly as I can see from the logs that rust-libp2p pings js-libp2p during the test.

I believe @sukunrt observed something similar with rust-libp2p while working on go-libp2p, though he elected to just not close the handshake datachannel.

rust-libp2p logs from the test run in Docker are pasted below.

Expected behavior

Outbound datachannels should open correctly after the initial handshake datachannel has been closed.

Actual behavior

Outbound datachannels fail to open after the initial handshake datachannel has been closed.

Relevant log output

Logs from the Docker test run are below (GitHub complains it's too long to be pasted here).

Possible Solution

No response

Version

0.54

Would you like to work on fixing this bug?

I'd like some help resolving it

@achingbrain
Copy link
Member Author

2025-04-14T16:19:06.934377Z  INFO libp2p_swarm: local_peer_id=12D3KooWAv7grb9Z2y3Yahs2M2ojDvhF17ncuhq2e3V4nStm7voy
2025-04-14T16:19:06.934443Z  INFO interop_tests: Running ping test local_peer=12D3KooWAv7grb9Z2y3Yahs2M2ojDvhF17ncuhq2e3V4nStm7voy
2025-04-14T16:19:06.934514Z DEBUG libp2p_core::transport::choice: Failed to listen on address using libp2p_core::transport::dummy::DummyTransport<(libp2p_identity::peer_id::PeerId, libp2p_core::muxing::boxed::StreamMuxerBox)> address=/ip4/0.0.0.0/udp/0/webrtc-direct
2025-04-14T16:19:06.934703Z DEBUG netlink_proto::handle: handle: forwarding new request to connection    
2025-04-14T16:19:06.934733Z  INFO interop_tests: Test instance, listening for incoming connections on address address=/ip4/0.0.0.0/udp/0/webrtc-direct
2025-04-14T16:19:06.934846Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:06.934883Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:06.934896Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:06.934900Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:06.934902Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:06.934946Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:06.935092Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:06.935101Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:06.935110Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:06.935154Z DEBUG Swarm::poll: netlink_proto::protocol::protocol: handling messages (request id = RequestId { sequence_number: 1, port: 0 })    
2025-04-14T16:19:06.935255Z DEBUG Swarm::poll: netlink_proto::protocol::protocol: handling response to request RequestId { sequence_number: 1, port: 0 }    
2025-04-14T16:19:06.935267Z DEBUG Swarm::poll: netlink_proto::protocol::protocol: done handling response to request RequestId { sequence_number: 1, port: 0 }    
2025-04-14T16:19:06.935269Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:06.935272Z DEBUG Swarm::poll: netlink_proto::protocol::protocol: handling messages (request id = RequestId { sequence_number: 1, port: 0 })    
2025-04-14T16:19:06.935273Z DEBUG Swarm::poll: netlink_proto::protocol::protocol: handling response to request RequestId { sequence_number: 1, port: 0 }    
2025-04-14T16:19:06.935274Z DEBUG Swarm::poll: netlink_proto::protocol::protocol: done handling response to request RequestId { sequence_number: 1, port: 0 }    
2025-04-14T16:19:06.935275Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:06.935280Z DEBUG Swarm::poll: netlink_proto::protocol::protocol: handling messages (request id = RequestId { sequence_number: 1, port: 0 })    
2025-04-14T16:19:06.935281Z DEBUG Swarm::poll: netlink_proto::protocol::protocol: handling response to request RequestId { sequence_number: 1, port: 0 }    
2025-04-14T16:19:06.935282Z DEBUG Swarm::poll: netlink_proto::protocol::protocol: done handling response to request RequestId { sequence_number: 1, port: 0 }    
2025-04-14T16:19:06.935282Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:06.935285Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:06.935286Z DEBUG Swarm::poll: netlink_proto::protocol::protocol: handling messages (request id = RequestId { sequence_number: 1, port: 0 })    
2025-04-14T16:19:06.935287Z DEBUG Swarm::poll: netlink_proto::protocol::protocol: handling response to request RequestId { sequence_number: 1, port: 0 }    
2025-04-14T16:19:06.935288Z DEBUG Swarm::poll: netlink_proto::protocol::protocol: done handling response to request RequestId { sequence_number: 1, port: 0 }    
2025-04-14T16:19:06.935289Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:06.935299Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:06.935301Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:06.935306Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:06.935307Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:06.935379Z DEBUG Swarm::poll: libp2p_swarm: New listener address listener=ListenerId(1) address=/ip4/127.0.0.1/udp/33418/webrtc-direct/certhash/uEiBKNUFynkCnPbCTd6PvVCl1iunrQhPKefEueWRcy4rPNw
2025-04-14T16:19:06.935495Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:06.935504Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:06.935506Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:06.935507Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:06.935508Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:06.935508Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:06.935514Z DEBUG Swarm::poll: libp2p_swarm: New listener address listener=ListenerId(1) address=/ip4/172.17.0.3/udp/33418/webrtc-direct/certhash/uEiBKNUFynkCnPbCTd6PvVCl1iunrQhPKefEueWRcy4rPNw
2025-04-14T16:19:06.936726Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:06.936739Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:06.936764Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:06.936766Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:06.936767Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:06.936768Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:06.936770Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:06.936771Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:06.936772Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:06.936773Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:06.936774Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:06.936774Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:11.945727Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:11.945741Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:11.945744Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:11.945745Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:11.945746Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:11.945747Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:11.945880Z DEBUG interop_tests: IncomingConnection { connection_id: ConnectionId(1), local_addr: "/ip4/0.0.0.0/udp/33418/webrtc-direct/certhash/uEiBKNUFynkCnPbCTd6PvVCl1iunrQhPKefEueWRcy4rPNw", send_back_addr: "/ip4/172.17.0.4/udp/46727/webrtc-direct" }
2025-04-14T16:19:11.945913Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:11.945914Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:11.945915Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:11.945916Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:11.945917Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:11.945918Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:11.946038Z DEBUG new_incoming_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1}: libp2p_webrtc::tokio::upgrade: new inbound connection from address address=172.17.0.4:46727 ufrag=libp2p+webrtc+v1/mpchZsyanUXpdTOYiWJQrCoGYPFxOi9X
2025-04-14T16:19:11.946414Z DEBUG new_incoming_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1}: libp2p_webrtc::tokio::upgrade: calculated SDP offer for inbound connection offer=RTCSessionDescription { sdp_type: Offer, sdp: "v=0\no=- 0 0 IN IP4 172.17.0.4\ns=-\nc=IN IP4 172.17.0.4\nt=0 0\n\nm=application 46727 UDP/DTLS/SCTP webrtc-datachannel\na=mid:0\na=ice-options:ice2\na=ice-ufrag:libp2p+webrtc+v1/mpchZsyanUXpdTOYiWJQrCoGYPFxOi9X\na=ice-pwd:libp2p+webrtc+v1/mpchZsyanUXpdTOYiWJQrCoGYPFxOi9X\na=fingerprint:sha-256 FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF\na=setup:actpass\na=sctp-port:5000\na=max-message-size:16384\n", parsed: Some(SessionDescription { version: 0, origin: Origin { username: "-", session_id: 0, session_version: 0, network_type: "IN", address_type: "IP4", unicast_address: "172.17.0.4" }, session_name: "-", session_information: None, uri: None, email_address: None, phone_number: None, connection_information: Some(ConnectionInformation { network_type: "IN", address_type: "IP4", address: Some(Address { address: "172.17.0.4", ttl: None, range: None }) }), bandwidth: [], time_descriptions: [TimeDescription { timing: Timing { start_time: 0, stop_time: 0 }, repeat_times: [] }], time_zones: [], encryption_key: None, attributes: [], media_descriptions: [MediaDescription { media_name: MediaName { media: "application", port: RangedPort { value: 46727, range: None }, protos: ["UDP", "DTLS", "SCTP"], formats: ["webrtc-datachannel"] }, media_title: None, connection_information: None, bandwidth: [], encryption_key: None, attributes: [Attribute { key: "mid", value: Some("0") }, Attribute { key: "ice-options", value: Some("ice2") }, Attribute { key: "ice-ufrag", value: Some("libp2p+webrtc+v1/mpchZsyanUXpdTOYiWJQrCoGYPFxOi9X") }, Attribute { key: "ice-pwd", value: Some("libp2p+webrtc+v1/mpchZsyanUXpdTOYiWJQrCoGYPFxOi9X") }, Attribute { key: "fingerprint", value: Some("sha-256 FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF:FF") }, Attribute { key: "setup", value: Some("actpass") }, Attribute { key: "sctp-port", value: Some("5000") }, Attribute { key: "max-message-size", value: Some("16384") }] }] }) }
2025-04-14T16:19:11.946486Z  INFO new_incoming_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1}: webrtc::peer_connection: signaling state changed to have-remote-offer    
2025-04-14T16:19:11.946602Z  INFO new_incoming_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1}: webrtc_ice::mdns: mDNS is using 224.0.0.251:5353 as dest_addr    
2025-04-14T16:19:11.946872Z  INFO webrtc_mdns::conn: Looping and listening Ok(224.0.0.251:5353)    
2025-04-14T16:19:11.946896Z DEBUG webrtc_ice::agent::agent_internal: Started agent: isControlling? false, remoteUfrag: libp2p+webrtc+v1/mpchZsyanUXpdTOYiWJQrCoGYPFxOi9X, remotePwd: libp2p+webrtc+v1/mpchZsyanUXpdTOYiWJQrCoGYPFxOi9X    
2025-04-14T16:19:11.946912Z  INFO webrtc_ice::agent::agent_internal: [controlled]: Setting new connection state: Checking    
2025-04-14T16:19:11.946970Z  INFO webrtc::peer_connection: ICE connection state changed: checking    
2025-04-14T16:19:11.946967Z DEBUG new_incoming_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1}: libp2p_webrtc::tokio::upgrade: created SDP answer for inbound connection answer=RTCSessionDescription { sdp_type: Answer, sdp: "v=0\r\no=- 2729625061104392353 946578875 IN IP4 0.0.0.0\r\ns=-\r\nt=0 0\r\na=fingerprint:sha-256 4A:35:41:72:9E:40:A7:3D:B0:93:77:A3:EF:54:29:75:8A:E9:EB:42:13:CA:79:F1:2E:79:64:5C:CB:8A:CF:37\r\na=ice-lite:ice-lite\r\na=group:BUNDLE 0\r\nm=application 9 UDP/DTLS/SCTP webrtc-datachannel\r\nc=IN IP4 0.0.0.0\r\na=setup:passive\r\na=mid:0\r\na=sendrecv\r\na=sctp-port:5000\r\na=ice-ufrag:libp2p+webrtc+v1/mpchZsyanUXpdTOYiWJQrCoGYPFxOi9X\r\na=ice-pwd:libp2p+webrtc+v1/mpchZsyanUXpdTOYiWJQrCoGYPFxOi9X\r\n", parsed: Some(SessionDescription { version: 0, origin: Origin { username: "-", session_id: 2729625061104392353, session_version: 946578875, network_type: "IN", address_type: "IP4", unicast_address: "0.0.0.0" }, session_name: "-", session_information: None, uri: None, email_address: None, phone_number: None, connection_information: None, bandwidth: [], time_descriptions: [TimeDescription { timing: Timing { start_time: 0, stop_time: 0 }, repeat_times: [] }], time_zones: [], encryption_key: None, attributes: [Attribute { key: "fingerprint", value: Some("sha-256 4A:35:41:72:9E:40:A7:3D:B0:93:77:A3:EF:54:29:75:8A:E9:EB:42:13:CA:79:F1:2E:79:64:5C:CB:8A:CF:37") }, Attribute { key: "ice-lite", value: Some("ice-lite") }, Attribute { key: "group", value: Some("BUNDLE 0") }], media_descriptions: [MediaDescription { media_name: MediaName { media: "application", port: RangedPort { value: 9, range: None }, protos: ["UDP", "DTLS", "SCTP"], formats: ["webrtc-datachannel"] }, media_title: None, connection_information: Some(ConnectionInformation { network_type: "IN", address_type: "IP4", address: Some(Address { address: "0.0.0.0", ttl: None, range: None }) }), bandwidth: [], encryption_key: None, attributes: [Attribute { key: "setup", value: Some("passive") }, Attribute { key: "mid", value: Some("0") }, Attribute { key: "sendrecv", value: None }, Attribute { key: "sctp-port:5000", value: None }, Attribute { key: "ice-ufrag", value: Some("libp2p+webrtc+v1/mpchZsyanUXpdTOYiWJQrCoGYPFxOi9X") }, Attribute { key: "ice-pwd", value: Some("libp2p+webrtc+v1/mpchZsyanUXpdTOYiWJQrCoGYPFxOi9X") }] }] }) }
2025-04-14T16:19:11.947057Z  INFO new_incoming_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1}: webrtc::peer_connection: signaling state changed to stable    
2025-04-14T16:19:11.947161Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:11.947172Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:11.947174Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:11.947175Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:11.947176Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:11.947176Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:11.947204Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:11.947211Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:11.947212Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:11.947213Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:11.947213Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:11.947214Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.006486Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.006500Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.006502Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.006503Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.006504Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.006505Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.006626Z DEBUG webrtc_ice::agent::agent_internal: [controlled]: adding a new peer-reflexive candidate: 172.17.0.4:46727     
2025-04-14T16:19:12.006699Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.006706Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.006708Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.006709Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.006710Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.006711Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.006750Z DEBUG libp2p_webrtc::tokio::udp_mux: Registered address for connection address=172.17.0.4:46727 connection=libp2p+webrtc+v1/mpchZsyanUXpdTOYiWJQrCoGYPFxOi9X
2025-04-14T16:19:12.006793Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.006807Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.006809Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.006810Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.006811Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.006812Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.006985Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.006992Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.006993Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.006994Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.006995Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.006996Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.007341Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.007360Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.007363Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.007364Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.007365Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.007366Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.007434Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.007443Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.007445Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.007446Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.007447Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.007448Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.070644Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.070663Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.070666Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.070668Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.070670Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.070671Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.070750Z  INFO webrtc_ice::agent::agent_internal: [controlled]: Setting new connection state: Connected    
2025-04-14T16:19:12.070803Z  INFO webrtc::peer_connection: ICE connection state changed: connected    
2025-04-14T16:19:12.070810Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.070912Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.070915Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.070916Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.070918Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.070919Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.071270Z DEBUG webrtc_dtls::flight::flight0: [handshake:server] use cipher suite: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256    
2025-04-14T16:19:12.071415Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.071424Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.071426Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.071427Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.071428Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.071430Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.071572Z DEBUG webrtc_dtls::flight::flight0: [handshake:server] use cipher suite: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256    
2025-04-14T16:19:12.071618Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.071623Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.071625Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.071626Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.071628Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.071630Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.071784Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.071794Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.071796Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.071798Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.071799Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.071800Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.072001Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.072010Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.072012Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.072014Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.072015Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.072016Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.072736Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.072746Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.072748Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.072750Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.072751Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.072752Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.072830Z DEBUG webrtc_dtls::conn: server: CipherSuite not initialized, queuing packet    
2025-04-14T16:19:12.072839Z DEBUG webrtc_dtls::conn: server: received packet of next epoch, queuing packet    
2025-04-14T16:19:12.073146Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.073156Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.073158Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.073159Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.073160Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.073162Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.073331Z  INFO webrtc::peer_connection: peer connection state changed: connected    
2025-04-14T16:19:12.073620Z DEBUG webrtc_sctp::association::association_internal: [] state change: 'Closed' => 'CookieWait'    
2025-04-14T16:19:12.073644Z DEBUG webrtc_sctp::association::association_internal: [] sending INIT    
2025-04-14T16:19:12.073659Z DEBUG webrtc_sctp::association: [] read_loop entered    
2025-04-14T16:19:12.073680Z DEBUG webrtc_sctp::association: [] write_loop entered    
2025-04-14T16:19:12.073820Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.073847Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.073849Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.073851Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.073852Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.073853Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.074605Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.074612Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.074613Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.074614Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.074615Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.074616Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.074680Z DEBUG webrtc_sctp::association: [] recving 44 bytes    
2025-04-14T16:19:12.074708Z DEBUG webrtc_sctp::association::association_internal: [] chunkInit received in state 'CookieWait'    
2025-04-14T16:19:12.074714Z DEBUG webrtc_sctp::association::association_internal: [] use ForwardTSN (on init)    
2025-04-14T16:19:12.074731Z DEBUG webrtc_sctp::association: [] recving 92 bytes    
2025-04-14T16:19:12.074787Z DEBUG webrtc_sctp::association::association_internal: [] chunkInitAck received in state 'CookieWait'    
2025-04-14T16:19:12.074803Z DEBUG webrtc_sctp::association::association_internal: [] initial rwnd=5242880    
2025-04-14T16:19:12.074816Z DEBUG webrtc_sctp::association::association_internal: [] use ForwardTSN (on initAck)    
2025-04-14T16:19:12.074818Z DEBUG webrtc_sctp::association::association_internal: [] sending COOKIE-ECHO    
2025-04-14T16:19:12.074824Z DEBUG webrtc_sctp::association::association_internal: [] state change: 'CookieWait' => 'CookieEchoed'    
2025-04-14T16:19:12.074837Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.074922Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.074924Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.074926Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.074927Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.074928Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.075021Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.075029Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.075031Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.075032Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.075033Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.075034Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.075187Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.075201Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.075203Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.075205Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.075206Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.075207Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.075269Z DEBUG webrtc_sctp::association: [] recving 48 bytes    
2025-04-14T16:19:12.075273Z DEBUG webrtc_sctp::association::association_internal: [] COOKIE-ECHO received in state 'CookieEchoed'    
2025-04-14T16:19:12.075295Z DEBUG webrtc_sctp::association::association_internal: [] state change: 'CookieEchoed' => 'Established'    
2025-04-14T16:19:12.075353Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.075374Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.075376Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.075377Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.075379Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.075380Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.075347Z DEBUG libp2p_webrtc::tokio::connection: Data channel open channel=0
2025-04-14T16:19:12.075548Z DEBUG webrtc_sctp::association: [] recving 16 bytes    
2025-04-14T16:19:12.075571Z DEBUG webrtc_sctp::association::association_internal: [] COOKIE-ACK received in state 'Established'    
2025-04-14T16:19:12.075881Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.075904Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.075907Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.075908Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.075910Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.075911Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.076141Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.076157Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.076160Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.076161Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.076161Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.076162Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.076210Z DEBUG webrtc_sctp::association: [] recving 28 bytes    
2025-04-14T16:19:12.086958Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.086971Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.086974Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.086975Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.086976Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.086978Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.087087Z DEBUG webrtc_sctp::association: [] recving 240 bytes    
2025-04-14T16:19:12.087115Z DEBUG webrtc_sctp::stream: [0:] reassemblyQueue readable=true    
2025-04-14T16:19:12.087117Z DEBUG webrtc_sctp::stream: [0:] readNotifier.signal()    
2025-04-14T16:19:12.087127Z DEBUG webrtc_sctp::stream: [0:] readNotifier.signal() done    
2025-04-14T16:19:12.087138Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644907    
2025-04-14T16:19:12.087140Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644908    
2025-04-14T16:19:12.087600Z DEBUG Swarm::poll: libp2p_swarm: Connection established peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV endpoint=Listener { local_addr: "/ip4/0.0.0.0/udp/33418/webrtc-direct/certhash/uEiBKNUFynkCnPbCTd6PvVCl1iunrQhPKefEueWRcy4rPNw", send_back_addr: "/ip4/172.17.0.4/udp/46727/webrtc-direct" } total_peers=1
2025-04-14T16:19:12.087636Z DEBUG interop_tests: ConnectionEstablished { peer_id: PeerId("12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV"), connection_id: ConnectionId(1), endpoint: Listener { local_addr: "/ip4/0.0.0.0/udp/33418/webrtc-direct/certhash/uEiBKNUFynkCnPbCTd6PvVCl1iunrQhPKefEueWRcy4rPNw", send_back_addr: "/ip4/172.17.0.4/udp/46727/webrtc-direct" }, num_established: 1, concurrent_dial_errors: None, established_in: 141.575125ms }
2025-04-14T16:19:12.087684Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.087689Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.087691Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.087692Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.087693Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.087694Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.087752Z DEBUG libp2p_webrtc::tokio::connection: Data channel open channel=1
2025-04-14T16:19:12.087816Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.087823Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.087825Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.087826Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.087827Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.087828Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.087842Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: multistream_select::dialer_select: Dialer: Proposed protocol protocol=/ipfs/id/1.0.0
2025-04-14T16:19:12.087884Z DEBUG libp2p_webrtc::tokio::connection: Data channel open channel=3
2025-04-14T16:19:12.087906Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: multistream_select::dialer_select: Dialer: Proposed protocol protocol=/ipfs/ping/1.0.0
2025-04-14T16:19:12.087980Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.087991Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.087992Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.087994Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.087995Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.087996Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.088114Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.088125Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.088127Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.088128Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.088129Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.088130Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.088202Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.088252Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.088256Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.088257Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.088258Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.088259Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.088392Z DEBUG webrtc_sctp::association: [] recving 28 bytes    
2025-04-14T16:19:12.088416Z DEBUG webrtc_sctp::association: [] recving 32 bytes    
2025-04-14T16:19:12.088419Z DEBUG webrtc_sctp::stream: [1:] reassemblyQueue readable=true    
2025-04-14T16:19:12.088420Z DEBUG webrtc_sctp::stream: [1:] readNotifier.signal()    
2025-04-14T16:19:12.088422Z DEBUG webrtc_sctp::stream: [1:] readNotifier.signal() done    
2025-04-14T16:19:12.088422Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644908    
2025-04-14T16:19:12.088424Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644909    
2025-04-14T16:19:12.088436Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: webrtc_data::data_channel: Received DATA_CHANNEL_ACK    
2025-04-14T16:19:12.088449Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: webrtc_sctp::stream: [1:] reliability params: ordered=true type=Reliable value=0    
2025-04-14T16:19:12.088459Z DEBUG webrtc_sctp::association::association_internal: [] sending SACK: SACK cumTsnAck=369644909 arwnd=1048576 dupTsn=[]    
2025-04-14T16:19:12.088552Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.088562Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.088563Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.088564Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.088566Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.088567Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.088643Z DEBUG webrtc_sctp::association: [] recving 28 bytes    
2025-04-14T16:19:12.088680Z DEBUG webrtc_sctp::association: [] recving 32 bytes    
2025-04-14T16:19:12.088683Z DEBUG webrtc_sctp::stream: [3:] reassemblyQueue readable=true    
2025-04-14T16:19:12.088684Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal()    
2025-04-14T16:19:12.088685Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal() done    
2025-04-14T16:19:12.088686Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644909    
2025-04-14T16:19:12.088687Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644910    
2025-04-14T16:19:12.088694Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: webrtc_data::data_channel: Received DATA_CHANNEL_ACK    
2025-04-14T16:19:12.088708Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: webrtc_sctp::stream: [3:] reliability params: ordered=true type=Reliable value=0    
2025-04-14T16:19:12.093118Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.093129Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.093131Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.093132Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.093133Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.093134Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.093243Z DEBUG webrtc_sctp::association: [] recving 40 bytes    
2025-04-14T16:19:12.093261Z DEBUG webrtc_sctp::association::association_internal: [] accepted a new stream (streamIdentifier: 2)    
2025-04-14T16:19:12.093265Z DEBUG webrtc_sctp::stream: [2:] reassemblyQueue readable=true    
2025-04-14T16:19:12.093266Z DEBUG webrtc_sctp::stream: [2:] readNotifier.signal()    
2025-04-14T16:19:12.093266Z DEBUG webrtc_sctp::stream: [2:] readNotifier.signal() done    
2025-04-14T16:19:12.093267Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644910    
2025-04-14T16:19:12.093268Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644911    
2025-04-14T16:19:12.093281Z DEBUG webrtc_sctp::stream: [2:] reliability params: ordered=true type=Reliable value=0    
2025-04-14T16:19:12.093287Z DEBUG libp2p_webrtc::tokio::connection: Incoming data channel channel=0
2025-04-14T16:19:12.093299Z DEBUG libp2p_webrtc::tokio::connection: Data channel open channel=0
2025-04-14T16:19:12.093340Z DEBUG webrtc_sctp::association::association_internal: [] sending SACK: SACK cumTsnAck=369644911 arwnd=1048576 dupTsn=[]    
2025-04-14T16:19:12.093443Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.093491Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.093500Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.093502Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.093502Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.093503Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.093690Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.093699Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.093701Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.093702Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.093703Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.093704Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.093960Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.094010Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.094014Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.094016Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.094017Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.094018Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.094090Z DEBUG webrtc_sctp::association: [] recving 28 bytes    
2025-04-14T16:19:12.094564Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.094576Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.094578Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.094579Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.094580Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.094581Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.094633Z DEBUG webrtc_sctp::association: [] recving 36 bytes    
2025-04-14T16:19:12.094649Z DEBUG webrtc_sctp::association::association_internal: [] resetStream(): senderLastTSN=369644911 <= peer_last_tsn=369644911    
2025-04-14T16:19:12.094657Z DEBUG webrtc_sctp::association::association_internal: [] RESET RESPONSE: Packet:
        source_port: 5000
        destination_port: 5000
        verification_tag: 1971477326
        Chunk: Param A:
 Re-configuration Response Parameter 369644908 1: Success - Performed    
2025-04-14T16:19:12.094743Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.094753Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.094755Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.094756Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.094757Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.094758Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.094890Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.094916Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.094919Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.094920Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.094921Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.094923Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.095028Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.095036Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.095038Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.095039Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.095040Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.095041Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.095074Z DEBUG webrtc_sctp::association: [] recving 28 bytes    
2025-04-14T16:19:12.095944Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.095952Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.095954Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.095955Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.095956Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.095957Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.096024Z DEBUG webrtc_sctp::association: [] recving 40 bytes    
2025-04-14T16:19:12.096047Z DEBUG webrtc_sctp::association::association_internal: [] accepted a new stream (streamIdentifier: 0)    
2025-04-14T16:19:12.096050Z DEBUG webrtc_sctp::stream: [0:] reassemblyQueue readable=true    
2025-04-14T16:19:12.096052Z DEBUG webrtc_sctp::stream: [0:] readNotifier.signal()    
2025-04-14T16:19:12.096053Z DEBUG webrtc_sctp::stream: [0:] readNotifier.signal() done    
2025-04-14T16:19:12.096054Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644911    
2025-04-14T16:19:12.096055Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644912    
2025-04-14T16:19:12.096064Z DEBUG libp2p_webrtc::tokio::connection: Incoming data channel channel=0
2025-04-14T16:19:12.096086Z DEBUG libp2p_webrtc::tokio::connection: Data channel open channel=0
2025-04-14T16:19:12.096149Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: libp2p_swarm::connection: no protocol could be agreed upon for inbound stream
2025-04-14T16:19:12.096215Z  INFO new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: libp2p_webrtc_utils::stream::drop_listener: Stream dropped without graceful close, sending Reset
2025-04-14T16:19:12.096273Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: libp2p_webrtc::tokio::connection: a DropListener failed: Stream closed
2025-04-14T16:19:12.099489Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.099497Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.099498Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.099499Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.099500Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.099501Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.099560Z DEBUG webrtc_sctp::association: [] recving 68 bytes    
2025-04-14T16:19:12.099574Z DEBUG webrtc_sctp::stream: [2:] reassemblyQueue readable=true    
2025-04-14T16:19:12.099575Z DEBUG webrtc_sctp::stream: [2:] readNotifier.signal()    
2025-04-14T16:19:12.099581Z DEBUG webrtc_sctp::stream: [2:] readNotifier.signal() done    
2025-04-14T16:19:12.099582Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644912    
2025-04-14T16:19:12.099583Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644913    
2025-04-14T16:19:12.099603Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.099615Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.099615Z DEBUG webrtc_sctp::association::association_internal: [] sending SACK: SACK cumTsnAck=369644913 arwnd=1048564 dupTsn=[]    
2025-04-14T16:19:12.099617Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.099619Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.099620Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.099596Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: multistream_select::listener_select: Listener: confirming protocol protocol=/ipfs/id/1.0.0
2025-04-14T16:19:12.099621Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.099634Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: multistream_select::listener_select: Listener: sent confirmed protocol protocol=/ipfs/id/1.0.0
2025-04-14T16:19:12.099700Z DEBUG webrtc_sctp::association: [] recving 72 bytes    
2025-04-14T16:19:12.099702Z DEBUG interop_tests: Behaviour(BehaviourEvent: Sent { connection_id: ConnectionId(1), peer_id: PeerId("12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV") })
2025-04-14T16:19:12.099710Z DEBUG webrtc_sctp::stream: [0:] reassemblyQueue readable=true    
2025-04-14T16:19:12.099712Z DEBUG webrtc_sctp::stream: [0:] readNotifier.signal()    
2025-04-14T16:19:12.099712Z DEBUG webrtc_sctp::stream: [0:] readNotifier.signal() done    
2025-04-14T16:19:12.099713Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644913    
2025-04-14T16:19:12.099713Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.099715Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644914    
2025-04-14T16:19:12.099715Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.099716Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.099717Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.099719Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.099720Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.099794Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.099802Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.099804Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.099805Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.099806Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.099806Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.100015Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.100032Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.100033Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.100034Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.100035Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.100036Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.100299Z DEBUG webrtc_sctp::association: [] recving 68 bytes    
2025-04-14T16:19:12.100338Z DEBUG webrtc_sctp::stream: [1:] reassemblyQueue readable=true    
2025-04-14T16:19:12.100352Z DEBUG webrtc_sctp::stream: [1:] readNotifier.signal()    
2025-04-14T16:19:12.100354Z DEBUG webrtc_sctp::stream: [1:] readNotifier.signal() done    
2025-04-14T16:19:12.100355Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644914    
2025-04-14T16:19:12.100356Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644915    
2025-04-14T16:19:12.100361Z DEBUG webrtc_sctp::association::association_internal: [] sending SACK: SACK cumTsnAck=369644915 arwnd=1048500 dupTsn=[]    
2025-04-14T16:19:12.100390Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.100394Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.100395Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.100396Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.100397Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.100398Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.100595Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.100603Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.100604Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.100605Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.100606Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.100607Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.100654Z DEBUG webrtc_sctp::association: [] recving 64 bytes    
2025-04-14T16:19:12.100676Z DEBUG webrtc_sctp::stream: [1:] reassemblyQueue readable=true    
2025-04-14T16:19:12.100677Z DEBUG webrtc_sctp::stream: [1:] readNotifier.signal()    
2025-04-14T16:19:12.100679Z DEBUG webrtc_sctp::stream: [1:] readNotifier.signal() done    
2025-04-14T16:19:12.100680Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644915    
2025-04-14T16:19:12.100681Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644916    
2025-04-14T16:19:12.100694Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: multistream_select::dialer_select: Dialer: Received confirmation for protocol protocol=/ipfs/id/1.0.0
2025-04-14T16:19:12.101717Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.101724Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.101725Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.101726Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.101727Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.101728Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.101781Z DEBUG webrtc_sctp::association: [] recving 352 bytes    
2025-04-14T16:19:12.101794Z DEBUG webrtc_sctp::stream: [1:] reassemblyQueue readable=true    
2025-04-14T16:19:12.101795Z DEBUG webrtc_sctp::stream: [1:] readNotifier.signal()    
2025-04-14T16:19:12.101800Z DEBUG webrtc_sctp::stream: [1:] readNotifier.signal() done    
2025-04-14T16:19:12.101803Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644916    
2025-04-14T16:19:12.101804Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644917    
2025-04-14T16:19:12.101830Z DEBUG webrtc_sctp::association::association_internal: [] sending SACK: SACK cumTsnAck=369644917 arwnd=1048523 dupTsn=[]    
2025-04-14T16:19:12.101836Z  INFO new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: libp2p_webrtc_utils::stream::drop_listener: Stream dropped without graceful close, sending Reset
2025-04-14T16:19:12.101843Z DEBUG interop_tests: Behaviour(BehaviourEvent: Received { connection_id: ConnectionId(1), peer_id: PeerId("12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV"), info: Info { public_key: PublicKey { publickey: Ed25519(PublicKey(compressed): 2535cd371a4d065a62b39ddf36ab82de1ca59e2a0bcea5974ab2be74559944) }, protocol_version: "ipfs/0.1.0", agent_version: "js-libp2p/0.0.0 browser/Mozilla/5.0 (X11; Linux aarch64) AppleWebKit/537.36 (KHTML, like Gecko) HeadlessChrome/133.0.6943.16 Safari/537.36", listen_addrs: [], protocols: ["/ipfs/id/1.0.0", "/ipfs/ping/1.0.0"], observed_addr: "/ip4/172.17.0.3/udp/33418/webrtc-direct/certhash/uEiBKNUFynkCnPbCTd6PvVCl1iunrQhPKefEueWRcy4rPNw/p2p/12D3KooWAv7grb9Z2y3Yahs2M2ojDvhF17ncuhq2e3V4nStm7voy" } })
2025-04-14T16:19:12.101874Z DEBUG interop_tests: NewExternalAddrCandidate { address: "/ip4/172.17.0.3/udp/33418/webrtc-direct/certhash/uEiBKNUFynkCnPbCTd6PvVCl1iunrQhPKefEueWRcy4rPNw/p2p/12D3KooWAv7grb9Z2y3Yahs2M2ojDvhF17ncuhq2e3V4nStm7voy" }
2025-04-14T16:19:12.101885Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.101886Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.101887Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.101888Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.101889Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.101890Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.101984Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.102002Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.102003Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.102004Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.102005Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.102006Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.102033Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.102038Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.102039Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.102040Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.102041Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.102042Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.102058Z DEBUG webrtc_sctp::association: [] recving 32 bytes    
2025-04-14T16:19:12.102068Z DEBUG webrtc_sctp::stream: [1:] reassemblyQueue readable=true    
2025-04-14T16:19:12.102068Z DEBUG webrtc_sctp::stream: [1:] readNotifier.signal()    
2025-04-14T16:19:12.102069Z DEBUG webrtc_sctp::stream: [1:] readNotifier.signal() done    
2025-04-14T16:19:12.102070Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644917    
2025-04-14T16:19:12.102071Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644918    
2025-04-14T16:19:12.102622Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.102641Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.102644Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.102645Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.102646Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.102647Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.102686Z DEBUG webrtc_sctp::association: [] recving 32 bytes    
2025-04-14T16:19:12.102692Z DEBUG webrtc_sctp::stream: [1:] reassemblyQueue readable=true    
2025-04-14T16:19:12.102694Z DEBUG webrtc_sctp::stream: [1:] readNotifier.signal()    
2025-04-14T16:19:12.102694Z DEBUG webrtc_sctp::stream: [1:] readNotifier.signal() done    
2025-04-14T16:19:12.102696Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644918    
2025-04-14T16:19:12.102697Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644919    
2025-04-14T16:19:12.102700Z DEBUG webrtc_sctp::association::association_internal: [] sending SACK: SACK cumTsnAck=369644919 arwnd=1048517 dupTsn=[]    
2025-04-14T16:19:12.102731Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.102734Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.102735Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.102736Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.102736Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.102737Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.102829Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.102841Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.102843Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.102844Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.102845Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.102846Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.102898Z DEBUG webrtc_sctp::association: [] recving 68 bytes    
2025-04-14T16:19:12.102916Z DEBUG webrtc_sctp::stream: [3:] reassemblyQueue readable=true    
2025-04-14T16:19:12.102917Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal()    
2025-04-14T16:19:12.102919Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal() done    
2025-04-14T16:19:12.102920Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644919    
2025-04-14T16:19:12.102921Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644920    
2025-04-14T16:19:12.103382Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.103389Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.103390Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.103391Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.103392Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.103393Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.103448Z DEBUG webrtc_sctp::association: [] recving 52 bytes    
2025-04-14T16:19:12.103457Z DEBUG webrtc_sctp::stream: [3:] reassemblyQueue readable=true    
2025-04-14T16:19:12.103458Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal()    
2025-04-14T16:19:12.103462Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal() done    
2025-04-14T16:19:12.103463Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644920    
2025-04-14T16:19:12.103464Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644921    
2025-04-14T16:19:12.103473Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: multistream_select::dialer_select: Dialer: Received confirmation for protocol protocol=/ipfs/ping/1.0.0
2025-04-14T16:19:12.103486Z DEBUG webrtc_sctp::association::association_internal: [] sending SACK: SACK cumTsnAck=369644921 arwnd=1048517 dupTsn=[]    
2025-04-14T16:19:12.103603Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.103607Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.103609Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.103610Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.103611Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.103612Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.103773Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.103780Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.103782Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.103783Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.103784Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.103784Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.104015Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.104050Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.104053Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.104054Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.104055Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.104056Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.104104Z DEBUG webrtc_sctp::association: [] recving 28 bytes    
2025-04-14T16:19:12.104998Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.105003Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.105004Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.105005Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.105006Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.105007Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.105035Z DEBUG webrtc_sctp::association: [] recving 32 bytes    
2025-04-14T16:19:12.105042Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.105044Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.105045Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.105045Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.105046Z DEBUG webrtc_sctp::stream: [2:] reassemblyQueue readable=true    
2025-04-14T16:19:12.105046Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.105047Z DEBUG webrtc_sctp::stream: [2:] readNotifier.signal()    
2025-04-14T16:19:12.105047Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.105048Z DEBUG webrtc_sctp::stream: [2:] readNotifier.signal() done    
2025-04-14T16:19:12.105049Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644921    
2025-04-14T16:19:12.105050Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644922    
2025-04-14T16:19:12.105143Z DEBUG webrtc_sctp::association: [] recving 32 bytes    
2025-04-14T16:19:12.105156Z DEBUG webrtc_sctp::stream: [2:] reassemblyQueue readable=true    
2025-04-14T16:19:12.105157Z DEBUG webrtc_sctp::stream: [2:] readNotifier.signal()    
2025-04-14T16:19:12.105158Z DEBUG webrtc_sctp::stream: [2:] readNotifier.signal() done    
2025-04-14T16:19:12.105159Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644922    
2025-04-14T16:19:12.105160Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644923    
2025-04-14T16:19:12.105170Z DEBUG webrtc_sctp::association::association_internal: [] sending SACK: SACK cumTsnAck=369644923 arwnd=1048511 dupTsn=[]    
2025-04-14T16:19:12.105237Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.105241Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.105243Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.105244Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.105245Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.105246Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.105380Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.105387Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.105388Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.105389Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.105390Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.105391Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.105497Z DEBUG webrtc_sctp::association: [] recving 32 bytes    
2025-04-14T16:19:12.105503Z DEBUG webrtc_sctp::stream: [2:] reassemblyQueue readable=true    
2025-04-14T16:19:12.105504Z DEBUG webrtc_sctp::stream: [2:] readNotifier.signal()    
2025-04-14T16:19:12.105505Z DEBUG webrtc_sctp::stream: [2:] readNotifier.signal() done    
2025-04-14T16:19:12.105506Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644923    
2025-04-14T16:19:12.105507Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644924    
2025-04-14T16:19:12.105997Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.106005Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.106007Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.106007Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.106008Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.106009Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.106082Z DEBUG webrtc_sctp::association: [] recving 36 bytes    
2025-04-14T16:19:12.106103Z DEBUG webrtc_sctp::association::association_internal: [] resetStream(): senderLastTSN=369644924 <= peer_last_tsn=369644924    
2025-04-14T16:19:12.106106Z DEBUG webrtc_sctp::association::association_internal: [] RESET RESPONSE: Packet:
        source_port: 5000
        destination_port: 5000
        verification_tag: 1971477326
        Chunk: Param A:
 Re-configuration Response Parameter 369644909 1: Success - Performed    
2025-04-14T16:19:12.106160Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.106167Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.106168Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.106169Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.106170Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.106171Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.106578Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.106624Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.106629Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.106631Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.106632Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.106637Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:12.106726Z DEBUG webrtc_sctp::association: [] recving 64 bytes    
2025-04-14T16:19:12.106737Z DEBUG webrtc_sctp::stream: [3:] reassemblyQueue readable=true    
2025-04-14T16:19:12.106738Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal()    
2025-04-14T16:19:12.106739Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal() done    
2025-04-14T16:19:12.106740Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644924    
2025-04-14T16:19:12.106741Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644925    
2025-04-14T16:19:12.106754Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: libp2p_ping::handler: ping succeeded rtt=3.255083ms
2025-04-14T16:19:12.106760Z DEBUG webrtc_sctp::association: [] recving 28 bytes    
2025-04-14T16:19:12.106770Z DEBUG webrtc_sctp::association::association_internal: [] sending SACK: SACK cumTsnAck=369644925 arwnd=1048514 dupTsn=[]    
2025-04-14T16:19:12.106832Z DEBUG interop_tests: Behaviour(BehaviourEvent: Event { peer: PeerId("12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV"), connection: ConnectionId(1), result: Ok(3.255083ms) })
2025-04-14T16:19:12.106842Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:12.106843Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:12.106845Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:12.106846Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:12.106847Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:12.106847Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:13.113106Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:13.113159Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:13.113168Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:13.113172Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:13.113176Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:13.113180Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:13.116236Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:13.116261Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:13.116265Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:13.116268Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:13.116270Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:13.116272Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:13.117456Z DEBUG webrtc_sctp::association: [] recving 80 bytes    
2025-04-14T16:19:13.117536Z DEBUG webrtc_sctp::stream: [3:] reassemblyQueue readable=true    
2025-04-14T16:19:13.117540Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal()    
2025-04-14T16:19:13.117543Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal() done    
2025-04-14T16:19:13.117545Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644925    
2025-04-14T16:19:13.117548Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644926    
2025-04-14T16:19:13.117606Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: libp2p_ping::handler: ping succeeded rtt=4.815542ms
2025-04-14T16:19:13.117839Z DEBUG interop_tests: Behaviour(BehaviourEvent: Event { peer: PeerId("12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV"), connection: ConnectionId(1), result: Ok(4.815542ms) })
2025-04-14T16:19:13.194886Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:13.194928Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:13.194935Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:13.194939Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:13.194943Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:13.194947Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:13.195197Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:13.195231Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:13.195238Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:13.195242Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:13.195246Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:13.195249Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:13.323619Z DEBUG webrtc_sctp::association::association_internal: [] sending SACK: SACK cumTsnAck=369644926 arwnd=1048514 dupTsn=[]    
2025-04-14T16:19:13.323985Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:13.324095Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:13.324112Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:13.324117Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:13.324121Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:13.324125Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:14.121119Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:14.121283Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:14.121296Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:14.121300Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:14.121303Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:14.121306Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:14.125055Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:14.125078Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:14.125082Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:14.125084Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:14.125086Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:14.125088Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:14.125447Z DEBUG webrtc_sctp::association: [] recving 80 bytes    
2025-04-14T16:19:14.125537Z DEBUG webrtc_sctp::stream: [3:] reassemblyQueue readable=true    
2025-04-14T16:19:14.125541Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal()    
2025-04-14T16:19:14.125544Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal() done    
2025-04-14T16:19:14.125546Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644926    
2025-04-14T16:19:14.125550Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644927    
2025-04-14T16:19:14.125586Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: libp2p_ping::handler: ping succeeded rtt=4.848458ms
2025-04-14T16:19:14.126493Z DEBUG interop_tests: Behaviour(BehaviourEvent: Event { peer: PeerId("12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV"), connection: ConnectionId(1), result: Ok(4.848458ms) })
2025-04-14T16:19:14.256651Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:14.256727Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:14.256739Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:14.256744Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:14.256748Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:14.256752Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:14.257158Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:14.257203Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:14.257211Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:14.257215Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:14.257219Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:14.257223Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:14.539139Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:14.539322Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:14.539335Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:14.539339Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:14.539341Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:14.539343Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:14.539679Z DEBUG webrtc_sctp::association: [] recving 64 bytes    
2025-04-14T16:19:14.539739Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644927    
2025-04-14T16:19:14.539817Z DEBUG webrtc_sctp::association::association_internal: [] sending SACK: SACK cumTsnAck=369644927 arwnd=1048514 dupTsn=[]    
2025-04-14T16:19:14.539973Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:14.540008Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:14.540012Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:14.540014Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:14.540016Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:14.540017Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:15.129509Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:15.129609Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:15.129618Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:15.129626Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:15.129631Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:15.129635Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:15.133437Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:15.133460Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:15.133464Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:15.133466Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:15.133468Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:15.133470Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:15.134006Z DEBUG webrtc_sctp::association: [] recving 80 bytes    
2025-04-14T16:19:15.134063Z DEBUG webrtc_sctp::stream: [3:] reassemblyQueue readable=true    
2025-04-14T16:19:15.134066Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal()    
2025-04-14T16:19:15.134069Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal() done    
2025-04-14T16:19:15.134070Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644927    
2025-04-14T16:19:15.134073Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644928    
2025-04-14T16:19:15.134135Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: libp2p_ping::handler: ping succeeded rtt=4.96675ms
2025-04-14T16:19:15.134735Z DEBUG interop_tests: Behaviour(BehaviourEvent: Event { peer: PeerId("12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV"), connection: ConnectionId(1), result: Ok(4.96675ms) })
2025-04-14T16:19:15.318839Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:15.318903Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:15.318913Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:15.318918Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:15.318922Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:15.318926Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:15.319428Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:15.319461Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:15.319468Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:15.319472Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:15.319476Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:15.319480Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:15.335442Z DEBUG webrtc_sctp::association::association_internal: [] sending SACK: SACK cumTsnAck=369644928 arwnd=1048514 dupTsn=[]    
2025-04-14T16:19:15.335726Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:15.335746Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:15.335753Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:15.335755Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:15.335757Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:15.335759Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:16.136247Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:16.136311Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:16.136319Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:16.136322Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:16.136409Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:16.136416Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:16.140059Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:16.140093Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:16.140097Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:16.140099Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:16.140101Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:16.140103Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:16.140359Z DEBUG webrtc_sctp::association: [] recving 80 bytes    
2025-04-14T16:19:16.140446Z DEBUG webrtc_sctp::stream: [3:] reassemblyQueue readable=true    
2025-04-14T16:19:16.140450Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal()    
2025-04-14T16:19:16.140453Z DEBUG webrtc_sctp::stream: [3:] readNotifier.signal() done    
2025-04-14T16:19:16.140455Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644928    
2025-04-14T16:19:16.140458Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644929    
2025-04-14T16:19:16.140535Z DEBUG new_established_connection{remote_addr=/ip4/172.17.0.4/udp/46727/webrtc-direct id=1 peer=12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV}:Connection::poll: libp2p_ping::handler: ping succeeded rtt=4.675917ms
2025-04-14T16:19:16.140698Z DEBUG interop_tests: Behaviour(BehaviourEvent: Event { peer: PeerId("12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV"), connection: ConnectionId(1), result: Ok(4.675917ms) })
2025-04-14T16:19:16.599320Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:16.599363Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:16.599371Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:16.599375Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:16.599379Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:16.599383Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:16.599681Z DEBUG webrtc_sctp::association: [] recving 64 bytes    
2025-04-14T16:19:16.599722Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644929    
2025-04-14T16:19:16.599769Z DEBUG webrtc_sctp::association::association_internal: [] sending SACK: SACK cumTsnAck=369644929 arwnd=1048514 dupTsn=[]    
2025-04-14T16:19:16.599899Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:16.599922Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:16.599928Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:16.599932Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:16.599936Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:16.599939Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:17.105058Z DEBUG Swarm::poll: libp2p_swarm: Connection closed with error KeepAliveTimeout: Connected { endpoint: Listener { local_addr: "/ip4/0.0.0.0/udp/33418/webrtc-direct/certhash/uEiBKNUFynkCnPbCTd6PvVCl1iunrQhPKefEueWRcy4rPNw", send_back_addr: "/ip4/172.17.0.4/udp/46727/webrtc-direct" }, peer_id: PeerId("12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV") } total_peers=0
2025-04-14T16:19:17.105140Z DEBUG interop_tests: ConnectionClosed { peer_id: PeerId("12D3KooWCKcqSjj959qao6LMVXZ7WiQEY1VHV8PgFBeUpJUwhTZV"), connection_id: ConnectionId(1), endpoint: Listener { local_addr: "/ip4/0.0.0.0/udp/33418/webrtc-direct/certhash/uEiBKNUFynkCnPbCTd6PvVCl1iunrQhPKefEueWRcy4rPNw", send_back_addr: "/ip4/172.17.0.4/udp/46727/webrtc-direct" }, num_established: 0, cause: Some(KeepAliveTimeout) }
2025-04-14T16:19:17.377151Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:17.377164Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:17.377166Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:17.377167Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:17.377168Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:17.377169Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:17.377282Z DEBUG webrtc_sctp::association: [] recving 32 bytes    
2025-04-14T16:19:17.377295Z DEBUG webrtc_sctp::stream: [2:] reassemblyQueue readable=true    
2025-04-14T16:19:17.377297Z DEBUG webrtc_sctp::stream: [2:] readNotifier.signal()    
2025-04-14T16:19:17.377297Z DEBUG webrtc_sctp::stream: [2:] readNotifier.signal() done    
2025-04-14T16:19:17.377298Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644929    
2025-04-14T16:19:17.377300Z DEBUG webrtc_sctp::association::association_internal: [] peer_last_tsn = 369644930    
2025-04-14T16:19:17.377304Z DEBUG webrtc_sctp::association: [] recving 36 bytes    
2025-04-14T16:19:17.377307Z DEBUG webrtc_sctp::association::association_internal: [] resetStream(): senderLastTSN=369644930 <= peer_last_tsn=369644930    
2025-04-14T16:19:17.377308Z DEBUG webrtc_sctp::association::association_internal: [] RESET RESPONSE: Packet:
        source_port: 5000
        destination_port: 5000
        verification_tag: 1971477326
        Chunk: Param A:
 Re-configuration Response Parameter 369644910 1: Success - Performed    
2025-04-14T16:19:17.377348Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:17.377354Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:17.377356Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:17.377357Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:17.377358Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:17.377358Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:17.377626Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:17.377633Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:17.377634Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:17.377635Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:17.377636Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:17.377637Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:17.378548Z DEBUG webrtc_sctp::association: [] recving 28 bytes    
2025-04-14T16:19:17.378604Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:17.378622Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:17.378626Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:17.378627Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:17.378628Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:17.378629Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:17.583697Z DEBUG webrtc_sctp::association::association_internal: [] sending SACK: SACK cumTsnAck=369644930 arwnd=1048523 dupTsn=[]    
2025-04-14T16:19:17.583956Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:17.584049Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:17.584058Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:17.584061Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:17.584063Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:17.584065Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:17.975618Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:17.975635Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:17.975638Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:17.975640Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:17.975642Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:17.975643Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:17.975750Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:17.975761Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:17.975763Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:17.975765Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:17.975766Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:17.975767Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:20.636288Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:20.636365Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:20.636377Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:20.636382Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:20.636386Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:20.636389Z DEBUG Swarm::poll: netlink_proto::connection: sending messages    
2025-04-14T16:19:20.636892Z DEBUG Swarm::poll: netlink_proto::connection: reading incoming messages    
2025-04-14T16:19:20.636938Z DEBUG Swarm::poll: netlink_proto::codecs: NetlinkCodec: decoding next message    
2025-04-14T16:19:20.636952Z DEBUG Swarm::poll: netlink_proto::connection: forwarding unsolicited messages to the connection handle    
2025-04-14T16:19:20.636957Z DEBUG Swarm::poll: netlink_proto::connection: forwaring responses to previous requests to the connection handle    
2025-04-14T16:19:20.636961Z DEBUG Swarm::poll: netlink_proto::connection: handling requests    
2025-04-14T16:19:20.636965Z DEBUG Swarm::poll: netlink_proto::connection: sending messages  

@jxs
Copy link
Member

jxs commented Apr 14, 2025

Hi Alex, thanks for opening this.
Cc @DougAnderson444

@DougAnderson444
Copy link
Contributor

Likely related to #5877 ?
Does it work if you try for longer than 10 seconds?

@DougAnderson444
Copy link
Contributor

Given that the final data read from the channel during the noise handshake is done by the client, it would be the one to close the connection.

Yes, and in the current rust-libp2p implementation, both the server and the client try to close - at exactly the same time, causing the issue I saw.

I am curious if your test would pass if you used this patch: master...DougAnderson444:rust-libp2p:core-v0.42-webrtc-utils-0.3.0

@achingbrain
Copy link
Member Author

Given that the final data read from the channel during the noise handshake is done by the client, it would be the one to close the connection.

Actually I'm not sure this would make any difference - if the server does the final write and then closes the connection, the client should still be able to read the data before reading the FIN.

The client doing the close might be "safer" in that it would dodge problems we've seen in the past, but the underlying channel should preserve the order of message/close events.

I am curious if your test would pass if you used this patch

Unfortunately no, this doesn't seem to make any difference.


One thing I've noticed is that since the handshake datachannel (id: 0) is now closed after the connection has been established, 0 is reused for the subsequent outgoing datachannel - might this have something to do with it?

It's supposed to be possible to specify an arbitrary channel id but from what I can see both Firefox and Chrome ignore this option.

@achingbrain
Copy link
Member Author

achingbrain commented Apr 15, 2025

Waiting for 10+s between the dial and opening the ping stream doesn't help either.

What I see on the JS side is that the outgoing datachannel is created, the open event fires, we write the multistream-select message to negotiate the /ipfs/ping/1.0.0 protocol then no data is received:

libp2p:ping pinging /ip4/172.17.0.3/udp/45787/webrtc-direct/certhash/uEiBJn-_tXTvsRhBkMjdAy5hmMagW0ufhuLyHzdds3N5-_A/p2p/12D3KooWRgWpXb6Dr1asK8JSQrWHmSWMYVEy4FoDZHXYd9WnXkFk +5s
libp2p:ping:trace opening ping stream to /ip4/172.17.0.3/udp/45787/webrtc-direct/certhash/uEiBJn-_tXTvsRhBkMjdAy5hmMagW0ufhuLyHzdds3N5-_A/p2p/12D3KooWRgWpXb6Dr1asK8JSQrWHmSWMYVEy4FoDZHXYd9WnXkFk +0ms
libp2p:webrtc:muxer:trace opened outgoing datachannel with channel id 0 +5s
libp2p:webrtc:stream:outbound:0:trace selecting protocol from protocols /ipfs/ping/1.0.0 +0ms
libp2p:webrtc:stream:outbound:0:trace sink reading from source +0ms
libp2p:webrtc:stream:outbound:0:trace select: write ["/multistream/1.0.0", "/ipfs/ping/1.0.0"] +0ms
libp2p:webrtc:stream:outbound:0:trace -> will send 38 bytes +1ms
libp2p:webrtc:stream:outbound:0:trace -> sending message, channel state "connecting" +0ms
libp2p:webrtc:stream:outbound:0 channel state is "connecting" and not "open", waiting for "open" event before sending data +0ms
libp2p:webrtc:stream:outbound:0:trace select: reading multistream-select header +0ms
libp2p:webrtc:stream:outbound:0 channel state is now "open", sending data +2ms
libp2p:webrtc:stream:outbound:0:trace -> sent message open +2ms
libp2p:webrtc:stream:outbound:0:trace -> finished sending data, channel state "open" +0ms
// no further output

@achingbrain
Copy link
Member Author

When running against go-libp2p I notice that the channel ids increment rather than being reused:

libp2p:ping:trace opened ping stream to /ip4/172.17.0.3/udp/49196/webrtc-direct/certhash/uEiAUK3Hpn0oJ_xXpVdNT_yZBqaAku-6BuINmBvAA1KSs8w/p2p/12D3KooWGH4cLF345t71KU1o7Hr9xwWz375W98Ek1sVWUwDFSJbC on stream outbound:4 +6ms
libp2p:webrtc:stream:outbound:4:trace sending 32/32 bytes on channel +0ms
libp2p:webrtc:stream:outbound:4:trace sending message, channel state "open" +0ms
libp2p:webrtc:stream:outbound:4:trace finished sending data, channel state "open" +0ms

Looking more closely at the js logs vs rust-libp2p it seems the datachannel opened for the ping stream ends up with the same channel id as the negotiated handshake datachannel.

Here libp2p:webrtc:stream:handshake:0 is the WebRTC DataChannel used for the handshake (id 0), there's anlibp2p:webrtc:stream:outbound:2 stream being used for identify but then then ping stream gets opened with id 0

libp2p:webrtc-direct:trace client wait for handshake channel to open, starting status connecting +0ms
libp2p:webrtc-direct:trace client handshake channel opened +117ms
libp2p:webrtc-direct:trace client performing noise handshake +0ms
libp2p:webrtc-direct:trace client secure inbound +2ms
libp2p:webrtc:stream:handshake:0:trace sink reading from source +0ms
libp2p:webrtc:stream:handshake:0:trace sending 204/204 bytes on channel +8ms
libp2p:webrtc:stream:handshake:0:trace sending message, channel state "open" +1ms
libp2p:webrtc:stream:handshake:0:trace finished sending data, channel state "open" +0ms
libp2p:webrtc-direct:trace client upgrade outbound +14ms
libp2p:webrtc:maconn:trace starting the outbound connection upgrade +0ms
libp2p:webrtc:maconn successfully upgraded outbound connection +0ms
libp2p:webrtc:muxer:trace opened outgoing datachannel with channel id 2 +0ms
libp2p:webrtc:stream:outbound:2:trace selecting protocol from protocols /ipfs/id/1.0.0 +0ms
libp2p:webrtc:stream:outbound:2:trace sink reading from source +0ms
libp2p:webrtc:stream:outbound:2:trace select: write ["/multistream/1.0.0", "/ipfs/id/1.0.0"] +0ms
libp2p:webrtc:stream:outbound:2:trace sending 36/36 bytes on channel +0ms
libp2p:webrtc:stream:outbound:2 channel state is "connecting" and not "open", waiting for "open" event before sending data +0ms
libp2p:webrtc:stream:outbound:2:trace select: reading multistream-select header +1ms
node 12D3KooWERfq7uUm8VKxcrtTRQYyMkQcKXMHdU6U631Bc46dPazP pings: /ip4/172.17.0.4/udp/42605/webrtc-direct/certhash/uEiCg6ley3FvP3i6J4bH9xUaAnE73qcJs69w_jBgQGkSw3A/p2p/12D3KooWPTmrEbZXsvqkcTN5xkPGj5XCVoPoNup49wnmhDyAzUup
libp2p:ping pinging /ip4/172.17.0.4/udp/42605/webrtc-direct/certhash/uEiCg6ley3FvP3i6J4bH9xUaAnE73qcJs69w_jBgQGkSw3A/p2p/12D3KooWPTmrEbZXsvqkcTN5xkPGj5XCVoPoNup49wnmhDyAzUup +0ms
libp2p:ping:trace opening ping stream to /ip4/172.17.0.4/udp/42605/webrtc-direct/certhash/uEiCg6ley3FvP3i6J4bH9xUaAnE73qcJs69w_jBgQGkSw3A/p2p/12D3KooWPTmrEbZXsvqkcTN5xkPGj5XCVoPoNup49wnmhDyAzUup +0ms
libp2p:webrtc:muxer:trace opened outgoing datachannel with channel id 0 +3ms
libp2p:webrtc:stream:outbound:0:trace selecting protocol from protocols /ipfs/ping/1.0.0 +0ms
libp2p:webrtc:stream:outbound:0:trace sink reading from source +0ms
libp2p:webrtc:stream:outbound:0:trace select: write ["/multistream/1.0.0", "/ipfs/ping/1.0.0"] +0ms
libp2p:webrtc:stream:outbound:0:trace sending 38/38 bytes on channel +0ms
libp2p:webrtc:stream:outbound:0 channel state is "connecting" and not "open", waiting for "open" event before sending data +0ms
libp2p:webrtc:stream:outbound:0:trace select: reading multistream-select header +0ms
libp2p:webrtc:stream:handshake:0:trace incoming flag FIN, write status "writing", read status "ready" +9ms
libp2p:webrtc:stream:handshake:0:trace remote close write +0ms
libp2p:webrtc:stream:handshake:0:trace ending source with 0 bytes to be read by consumer +0ms
libp2p:webrtc:stream:handshake:0:trace source ended +0ms
libp2p:webrtc:stream:handshake:0:trace source ended, waiting for sink to end +0ms
libp2p:webrtc:stream:handshake:0:trace sending FIN_ACK +0ms
libp2p:webrtc:stream:handshake:0:trace not sending flag closing because channel is "FIN_ACK" and not "open" +0ms

achingbrain added a commit to libp2p/js-libp2p that referenced this issue Apr 16, 2025
Removes the closing of the handshake datachannel after the connection
has been opened because it breaks compatibility with rust-libp2p 53.

This can be revisited after libp2p/rust-libp2p#5986
is resolved.
achingbrain added a commit to libp2p/js-libp2p that referenced this issue Apr 16, 2025
Removes the closing of the handshake datachannel after the connection
has been opened because it breaks compatibility with rust-libp2p 53.

This can be revisited after libp2p/rust-libp2p#5986
is resolved.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants