bug(Gossipsub over WebRTC) Unpredictable Dial upgrade Timeout error

[DougAnderson444]

Summary

I've been experimenting with the WebRTC transport and successfully got Ping to work between:

• rust-libp2p server
• js-libp2p browser client

Next step was to escalate to gossipsub to build a simple chat demo between the same two systems. After much hacking, sometimes the two connect, but most times they do not.

Experiment Repo: https://github.com/DougAnderson444/rdy2serve

Expected behaviour

Launch a rust-server, launch a js-browser instance, have the two connect over WebRTC and exchange chat messages via gossipsub. I was expecting consistent behaviour of rust-libp2p gossipsub.

Actual behaviour

Rust-libp2p gossipsub over WebRTC is unpredictable. Most of the time it doesn't work.... but then all of the sudden it will connect and chat just fine. I found that sometimes after launching 5 or 6 browsers, the connection upgrades, which made me think if there's a minimum mesh peer issue, but other times the single browser window connects just fine.

From what I can tell, when it fails, gossipsub is not upgrading the connection consistently.

Some consistent observations:

• The browser dials the server just fine. But the lack of Gossipsub upgrade times out the connection. This is why Ping works, but Gossipsub usually fails.
• The server successfully registers the Gossipsub subscriber as the browser. But again, this goes to waste if the upgrade fails.
• The key and final error is; [libp2p_gossipsub::handler] Dial upgrade error Timeout then a [libp2p_swarm] NegotiationTimeout

Typical failure (Server side rust)

[2023-03-22T21:42:41Z DEBUG rdy2serve] > Spawning task for server!
[2023-03-22T21:42:41Z DEBUG rdy2serve] > Send message!
[2023-03-22T21:42:41Z DEBUG libp2p_gossipsub::behaviour] Subscribing to topic: chat
[2023-03-22T21:42:41Z DEBUG libp2p_gossipsub::behaviour] Running JOIN for topic: TopicHash { hash: "chat" }
[2023-03-22T21:42:41Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T21:42:41Z DEBUG libp2p_gossipsub::behaviour] JOIN: Inserting 0 random peers into the mesh
[2023-03-22T21:42:41Z DEBUG libp2p_gossipsub::behaviour] Completed JOIN for topic: TopicHash { hash: "chat" }
[2023-03-22T21:42:41Z DEBUG libp2p_gossipsub::behaviour] Subscribed to topic: chat
[2023-03-22T21:42:41Z DEBUG libp2p_swarm] Listener ListenerId(17932517352972169224); New address: "/ip6/2607:fea8:fec0:7337::d93a/udp/59241/webrtc/certhash/uEiBHA3fZ6lJn-J64Szi7Qf9VOGrvAOUPHEAuYblDlxk4ow"
[2023-03-22T21:42:41Z INFO  rtc_server] Listening on /ip6/2607:fea8:fec0:7337::d93a/udp/59241/webrtc/certhash/uEiBHA3fZ6lJn-J64Szi7Qf9VOGrvAOUPHEAuYblDlxk4ow
[2023-03-22T21:42:41Z DEBUG libp2p_swarm] Listener ListenerId(17932517352972169224); New address: "/ip6/2607:fea8:fec0:7337:6b21:9df6:d46e:29d3/udp/59241/webrtc/certhash/uEiBHA3fZ6lJn-J64Szi7Qf9VOGrvAOUPHEAuYblDlxk4ow"
[2023-03-22T21:42:41Z DEBUG rtc_server] >>>> Setting ADDRESS
[2023-03-22T21:42:41Z DEBUG libp2p_swarm] Listener ListenerId(17932517352972169224); New address: "/ip6/2607:fea8:fec0:7337:1c60:851b:bb34:fac1/udp/59241/webrtc/certhash/uEiBHA3fZ6lJn-J64Szi7Qf9VOGrvAOUPHEAuYblDlxk4ow"
[2023-03-22T21:42:41Z DEBUG libp2p_swarm] Listener ListenerId(17932517352972169224); New address: "/ip6/::1/udp/59241/webrtc/certhash/uEiBHA3fZ6lJn-J64Szi7Qf9VOGrvAOUPHEAuYblDlxk4ow"
[2023-03-22T21:42:41Z INFO  rtc_server] Listening on /ip6/::1/udp/59241/webrtc/certhash/uEiBHA3fZ6lJn-J64Szi7Qf9VOGrvAOUPHEAuYblDlxk4ow
[2023-03-22T21:42:41Z DEBUG rtc_server] >>>> Reply listener spawned.
Connect with:
/ip6/2607:fea8:fec0:7337:6b21:9df6:d46e:29d3/udp/59241/webrtc/certhash/uEiBHA3fZ6lJn-J64Szi7Qf9VOGrvAOUPHEAuYblDlxk4ow/p2p/12D3KooWQc4gfhDkuT5gYzho3TvxxVboe7M9Aoh24GKbFfEAy6vE

*** To Shutdown, use Ctrl + C ***

[2023-03-22T21:42:42Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-03-22T21:42:42Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: chat Contains: 0 needs: 2
[2023-03-22T21:42:42Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T21:42:42Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-03-22T21:42:42Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-03-22T21:42:47Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-03-22T21:42:47Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: chat Contains: 0 needs: 2
[2023-03-22T21:42:47Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T21:42:47Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-03-22T21:42:47Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
➡️  Incoming Connection on "/ip6/2607:fea8:fec0:7337:1c60:851b:bb34:fac1/udp/54688/webrtc"
[2023-03-22T21:42:50Z DEBUG libp2p_webrtc::tokio::upgrade] new inbound connection from [2607:fea8:fec0:7337:1c60:851b:bb34:fac1]:54688 (ufrag: libp2p+webrtc+v1/v2phFsV9PsqAetv8DIyuzDVPxLuWkMCz)
[2023-03-22T21:42:50Z DEBUG libp2p_webrtc::tokio::upgrade] calculated SDP offer for inbound connection: RTCSessionDescription { sdp_type: Offer, 
sdp: "v=0\no=- 0 0 IN IP6 2607:fea8:fec0:7337:1c60:851b:bb34:fac1\ns=-\nc=IN IP6 2607:fea8:fec0:7337:1c60:851b:bb34:fac1\nt=0 0\n\nm=application 
54688 UDP/DTLS/SCTP webrtc-datachannel\na=mid:0\na=ice-options:ice2\na=ice-ufrag:libp2p+webrtc+v1/v2phFsV9PsqAetv8DIyuzDVPxLuWkMCz\na=ice-pwd:libp2p+webrtc+v1/v2phFsV9PsqAetv8DIyuzDVPxLuWkMCz\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: "IP6", unicast_address: "2607:fea8:fec0:7337:1c60:851b:bb34:fac1" }, session_name: "-", session_information: None, uri: None, email_address: None, phone_number: None, connection_information: Some(ConnectionInformation { network_type: "IN", address_type: "IP6", address: Some(Address { address: "2607:fea8:fec0:7337:1c60:851b:bb34:fac1", 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: 54688, 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/v2phFsV9PsqAetv8DIyuzDVPxLuWkMCz") }, Attribute { key: "ice-pwd", value: Some("libp2p+webrtc+v1/v2phFsV9PsqAetv8DIyuzDVPxLuWkMCz") }, 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") }] }] }) }
[2023-03-22T21:42:50Z DEBUG libp2p_webrtc::tokio::upgrade] created SDP answer for inbound connection: RTCSessionDescription { sdp_type: Answer, sdp: "v=0\r\no=- 7452631523901864230 814960400 IN IP4 0.0.0.0\r\ns=-\r\nt=0 0\r\na=fingerprint:sha-256 47:03:77:D9:EA:52:67:F8:9E:B8:4B:38:BB:41:FF:55:38:6A:EF:00:E5:0F:1C:40:2E:61:B9:43:97:19:38:A3\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/v2phFsV9PsqAetv8DIyuzDVPxLuWkMCz\r\na=ice-pwd:libp2p+webrtc+v1/v2phFsV9PsqAetv8DIyuzDVPxLuWkMCz\r\n", parsed: Some(SessionDescription { version: 0, origin: Origin { username: "-", session_id: 7452631523901864230, session_version: 814960400, 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 47:03:77:D9:EA:52:67:F8:9E:B8:4B:38:BB:41:FF:55:38:6A:EF:00:E5:0F:1C:40:2E:61:B9:43:97:19:38:A3") }, 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/v2phFsV9PsqAetv8DIyuzDVPxLuWkMCz") }, Attribute { key: "ice-pwd", value: Some("libp2p+webrtc+v1/v2phFsV9PsqAetv8DIyuzDVPxLuWkMCz") }] }] }) }
[2023-03-22T21:42:51Z DEBUG libp2p_webrtc::tokio::connection] Data channel 0 open
[2023-03-22T21:42:51Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7") Listener { local_addr: "/ip6/::/udp/59241/webrtc/certhash/uEiBHA3fZ6lJn-J64Szi7Qf9VOGrvAOUPHEAuYblDlxk4ow", send_back_addr: "/ip6/2607:fea8:fec0:7337:1c60:851b:bb34:fac1/udp/54688/webrtc" }; Total (peer): 1.
[2023-03-22T21:42:51Z DEBUG libp2p_gossipsub::behaviour] New peer connected: 12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7
✔️  Connection Established to 12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7 in 313.8259ms on /ip6/2607:fea8:fec0:7337:1c60:851b:bb34:fac1/
udp/54688/webrtc
[2023-03-22T21:42:51Z TRACE libp2p_webrtc::tokio::connection] Opening data channel 1
[2023-03-22T21:42:51Z DEBUG libp2p_webrtc::tokio::connection] Data channel 1 open
[2023-03-22T21:42:51Z TRACE libp2p_webrtc::tokio::connection] Outbound substream 1
[2023-03-22T21:42:51Z DEBUG libp2p_webrtc::tokio::connection] Incoming data channel 0
[2023-03-22T21:42:51Z DEBUG libp2p_webrtc::tokio::connection] Data channel 0 open
[2023-03-22T21:42:51Z DEBUG libp2p_webrtc::tokio::connection] Incoming data channel 0
[2023-03-22T21:42:51Z DEBUG libp2p_webrtc::tokio::connection] Data channel 0 open
[2023-03-22T21:42:51Z TRACE libp2p_webrtc::tokio::connection] Incoming substream 2
[2023-03-22T21:42:51Z TRACE libp2p_webrtc::tokio::connection] Incoming substream 4
[2023-03-22T21:42:51Z DEBUG libp2p_gossipsub::protocol] Upgrading inbound gossipsub
[2023-03-22T21:42:51Z TRACE libp2p_core::upgrade::apply] Upgraded inbound stream to /meshsub/1.1.0
[2023-03-22T21:42:51Z DEBUG libp2p_swarm::connection] negotiating_in.poll_next_unpin
[2023-03-22T21:42:51Z DEBUG libp2p_gossipsub::handler] Fully Negotiated inbound substream request
[2023-03-22T21:42:51Z TRACE libp2p_gossipsub::handler] New inbound substream request (Total: 1)
[2023-03-22T21:42:51Z DEBUG libp2p_gossipsub::behaviour] New peer type found: Gossipsub v1.1 for peer: 12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7
[2023-03-22T21:42:51Z DEBUG libp2p_swarm::connection] negotiating_in.poll_next_unpin error
[2023-03-22T21:42:51Z INFO  libp2p_webrtc::tokio::substream::drop_listener] Substream 4 dropped without graceful close, sending Reset
[2023-03-22T21:42:51Z DEBUG libp2p_webrtc::tokio::connection] a DropListener failed: Stream closed
[2023-03-22T21:42:51Z DEBUG libp2p_webrtc::tokio::connection] Incoming data channel 0
[2023-03-22T21:42:51Z DEBUG libp2p_webrtc::tokio::connection] Data channel 0 open
[2023-03-22T21:42:51Z TRACE libp2p_webrtc::tokio::connection] Incoming substream 6
[2023-03-22T21:42:51Z DEBUG libp2p_gossipsub::protocol] Upgrading inbound gossipsub
[2023-03-22T21:42:51Z TRACE libp2p_core::upgrade::apply] Upgraded inbound stream to /meshsub/1.1.0
[2023-03-22T21:42:51Z DEBUG libp2p_swarm::connection] negotiating_in.poll_next_unpin
[2023-03-22T21:42:51Z DEBUG libp2p_gossipsub::handler] Fully Negotiated inbound substream request
[2023-03-22T21:42:51Z TRACE libp2p_gossipsub::handler] New inbound substream request (Total: 2)
[2023-03-22T21:42:51Z INFO  libp2p_webrtc::tokio::substream::drop_listener] Substream 2 dropped without graceful close, sending Reset
[2023-03-22T21:42:51Z DEBUG libp2p_gossipsub::behaviour] Handling subscriptions: [Subscription { action: Subscribe, topic_hash: TopicHash { hash: "chat" } }], from source: 12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7
[2023-03-22T21:42:51Z DEBUG libp2p_gossipsub::behaviour] SUBSCRIPTION: Adding gossip peer: 12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7 to topic: TopicHash { hash: "chat" }
[2023-03-22T21:42:51Z DEBUG libp2p_gossipsub::behaviour] SUBSCRIPTION: Adding peer 12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7 to the mesh for topic TopicHash { hash: "chat" }
[2023-03-22T21:42:51Z DEBUG libp2p_gossipsub::behaviour] Sending GRAFT to peer 12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7 for topic TopicHash { hash: "chat" }
[2023-03-22T21:42:51Z TRACE libp2p_gossipsub::behaviour] Completed handling subscriptions from source: PeerId("12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7")
💨💨💨  TopicHash { hash: "chat" } Subscriber: 12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7
[2023-03-22T21:42:51Z DEBUG rtc_server] ### Number peers: 1 ###
Peer: PeerId("12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7")
[2023-03-22T21:42:51Z DEBUG libp2p_gossipsub::behaviour] Adding explicit peer 12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7
[2023-03-22T21:42:51Z TRACE libp2p_gossipsub::behaviour] Publishing message: MessageId(3137353136383036373533393236393838323138)
[2023-03-22T21:42:51Z TRACE libp2p_gossipsub::mcache] Put message MessageId(3137353136383036373533393236393838323138) in mcache
[2023-03-22T21:42:51Z TRACE libp2p_gossipsub::behaviour] Sending message to peer: PeerId("12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7") 
[2023-03-22T21:42:51Z DEBUG libp2p_gossipsub::behaviour] Published message: MessageId(3137353136383036373533393236393838323138)
[2023-03-22T21:42:52Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-03-22T21:42:52Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: chat Contains: 1 needs: 2
[2023-03-22T21:42:52Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T21:42:52Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-03-22T21:42:52Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T21:42:52Z DEBUG libp2p_gossipsub::behaviour] Gossiping IHAVE to 0 peers.
[2023-03-22T21:42:52Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-03-22T21:42:57Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-03-22T21:42:57Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: chat Contains: 1 needs: 2
[2023-03-22T21:42:57Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T21:42:57Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-03-22T21:42:57Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T21:42:57Z DEBUG libp2p_gossipsub::behaviour] Gossiping IHAVE to 0 peers.
[2023-03-22T21:42:57Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-03-22T21:43:01Z DEBUG libp2p_swarm::connection] negotiating_out.poll_next_unpin error
[2023-03-22T21:43:01Z WARN  libp2p_gossipsub::handler] Dial upgrade error Timeout, more info: RPC { subscriptions: [SubOpts { subscribe: Some(true), topic_id: Some("chat") }], publish: [], control: None }
[2023-03-22T21:43:01Z DEBUG libp2p_swarm] Connection closed with error Handler(NegotiationTimeout): Connected { endpoint: Listener { local_addr: 
"/ip6/::/udp/59241/webrtc/certhash/uEiBHA3fZ6lJn-J64Szi7Qf9VOGrvAOUPHEAuYblDlxk4ow", send_back_addr: "/ip6/2607:fea8:fec0:7337:1c60:851b:bb34:fac1/udp/54688/webrtc" }, peer_id: PeerId("12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7") }; Total (peer): 0.
[2023-03-22T21:43:01Z DEBUG libp2p_gossipsub::behaviour] Peer disconnected: 12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7
[2023-03-22T21:43:01Z DEBUG libp2p_gossipsub::behaviour] Removing explicit peer 12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7
❌⛓️ Connection Closed to: 12D3KooWJMaKfrdWjtr4ccmoVGgt5nDD94LW9CLdbgb1QmgFVcW7 caused by Some(Handler(NegotiationTimeout))
[2023-03-22T21:43:02Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-03-22T21:43:02Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: chat Contains: 0 needs: 2
[2023-03-22T21:43:02Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T21:43:02Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-03-22T21:43:02Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T21:43:02Z DEBUG libp2p_gossipsub::behaviour] Gossiping IHAVE to 0 peers.
[2023-03-22T21:43:02Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat

Typical Success (Server side rust)

[2023-03-22T17:39:53Z DEBUG rdy2serve] > Spawning task for server!
[2023-03-22T17:39:53Z DEBUG rdy2serve] > Send message!
[2023-03-22T17:39:53Z DEBUG libp2p_gossipsub::behaviour] Subscribing to topic: chat
[2023-03-22T17:39:53Z DEBUG libp2p_gossipsub::behaviour] Running JOIN for topic: TopicHash { hash: "chat" }
[2023-03-22T17:39:53Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:39:53Z DEBUG libp2p_gossipsub::behaviour] JOIN: Inserting 0 random peers into the mesh
[2023-03-22T17:39:53Z DEBUG libp2p_gossipsub::behaviour] Completed JOIN for topic: TopicHash { hash: "chat" }
[2023-03-22T17:39:53Z DEBUG libp2p_gossipsub::behaviour] Subscribed to topic: chat
[2023-03-22T17:39:53Z DEBUG libp2p_swarm] Listener ListenerId(4436090551883230123); New address: "/ip6/2607:fea8:fec0:7337::d93a/udp/57511/webrtc/certhash/uEiDG_PH_2c_bJniPRvkmhT8limgRsCo5HX9aooz8JFYUMA"
[2023-03-22T17:39:53Z INFO  rtc_server] Listening on /ip6/2607:fea8:fec0:7337::d93a/udp/57511/webrtc/certhash/uEiDG_PH_2c_bJniPRvkmhT8limgRsCo5HX9aooz8JFYUMA
[2023-03-22T17:39:53Z DEBUG libp2p_swarm] Listener ListenerId(4436090551883230123); New address: "/ip6/2607:fea8:fec0:7337:6b21:9df6:d46e:29d3/udp/57511/webrtc/certhash/uEiDG_PH_2c_bJniPRvkmhT8limgRsCo5HX9aooz8JFYUMA"
[2023-03-22T17:39:53Z DEBUG rtc_server] >>>> Setting ADDRESS
[2023-03-22T17:39:53Z DEBUG libp2p_swarm] Listener ListenerId(4436090551883230123); New address: "/ip6/2607:fea8:fec0:7337:1c60:851b:bb34:fac1/udp/57511/webrtc/certhash/uEiDG_PH_2c_bJniPRvkmhT8limgRsCo5HX9aooz8JFYUMA"
[2023-03-22T17:39:53Z DEBUG libp2p_swarm] Listener ListenerId(4436090551883230123); New address: "/ip6/::1/udp/57511/webrtc/certhash/uEiDG_PH_2c_bJniPRvkmhT8limgRsCo5HX9aooz8JFYUMA"
[2023-03-22T17:39:53Z INFO  rtc_server] Listening on /ip6/::1/udp/57511/webrtc/certhash/uEiDG_PH_2c_bJniPRvkmhT8limgRsCo5HX9aooz8JFYUMA
[2023-03-22T17:39:53Z DEBUG rtc_server] >>>> Reply listener spawned.
Connect with:
/ip6/2607:fea8:fec0:7337:6b21:9df6:d46e:29d3/udp/57511/webrtc/certhash/uEiDG_PH_2c_bJniPRvkmhT8limgRsCo5HX9aooz8JFYUMA/p2p/12D3KooWJj44RRYcKXAYugBr586LQ3a9XjWRzeS29w36zFqELDkW

*** To Shutdown, use Ctrl + C ***

[2023-03-22T17:39:54Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-03-22T17:39:54Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: chat Contains: 0 needs: 2
[2023-03-22T17:39:54Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:39:54Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-03-22T17:39:54Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
➡️  Incoming Connection on "/ip6/2607:fea8:fec0:7337:1c60:851b:bb34:fac1/udp/55180/webrtc"
[2023-03-22T17:39:58Z DEBUG libp2p_webrtc::tokio::upgrade] new inbound connection from [2607:fea8:fec0:7337:1c60:851b:bb34:fac1]:55180 (ufrag: libp2p+webrtc+v1/79a5/RCWapAAJeK4XanN6ja2aN5ld1/2)
[2023-03-22T17:39:58Z DEBUG libp2p_webrtc::tokio::upgrade] calculated SDP offer for inbound connection: RTCSessionDescription { sdp_type: Offer, sdp: "v=0\no=- 0 0 IN IP6 2607:fea8:fec0:7337:1c60:851b:bb34:fac1\ns=-\nc=IN IP6 2607:fea8:fec0:7337:1c60:851b:bb34:fac1\nt=0 0\n\nm=application 55180 UDP/DTLS/SCTP webrtc-datachannel\na=mid:0\na=ice-options:ice2\na=ice-ufrag:libp2p+webrtc+v1/79a5/RCWapAAJeK4XanN6ja2aN5ld1/2\na=ice-pwd:libp2p+webrtc+v1/79a5/RCWapAAJeK4XanN6ja2aN5ld1/2\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: "IP6", unicast_address: "2607:fea8:fec0:7337:1c60:851b:bb34:fac1" }, session_name: "-", session_information: None, uri: None, email_address: None, phone_number: None, connection_information: Some(ConnectionInformation { network_type: "IN", address_type: "IP6", address: Some(Address { address: "2607:fea8:fec0:7337:1c60:851b:bb34:fac1", 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: 55180, 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/79a5/RCWapAAJeK4XanN6ja2aN5ld1/2") }, Attribute { key: "ice-pwd", value: Some("libp2p+webrtc+v1/79a5/RCWapAAJeK4XanN6ja2aN5ld1/2") }, 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") }] }] }) }
[2023-03-22T17:39:58Z DEBUG libp2p_webrtc::tokio::upgrade] created SDP answer for inbound connection: RTCSessionDescription { sdp_type: Answer, sdp: "v=0\r\no=- 5677243940037295767 522211500 IN IP4 0.0.0.0\r\ns=-\r\nt=0 0\r\na=fingerprint:sha-256 C6:FC:F1:FF:D9:CF:DB:26:78:8F:46:F9:26:85:3F:25:8A:68:11:B0:2A:39:1D:7F:5A:A2:8C:FC:24:56:14:30\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/79a5/RCWapAAJeK4XanN6ja2aN5ld1/2\r\na=ice-pwd:libp2p+webrtc+v1/79a5/RCWapAAJeK4XanN6ja2aN5ld1/2\r\n", parsed: Some(SessionDescription { version: 0, origin: Origin { username: "-", session_id: 5677243940037295767, session_version: 522211500, 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 C6:FC:F1:FF:D9:CF:DB:26:78:8F:46:F9:26:85:3F:25:8A:68:11:B0:2A:39:1D:7F:5A:A2:8C:FC:24:56:14:30") }, 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/79a5/RCWapAAJeK4XanN6ja2aN5ld1/2") }, Attribute { key: "ice-pwd", value: Some("libp2p+webrtc+v1/79a5/RCWapAAJeK4XanN6ja2aN5ld1/2") }] }] }) }
[2023-03-22T17:39:58Z DEBUG libp2p_webrtc::tokio::connection] Data channel 0 open
[2023-03-22T17:39:58Z DEBUG libp2p_swarm] Connection established: PeerId("12D3KooWGXUH3UfQJyNk6EMCrzP8xfzmgpeTKHkZh62f4936kuzt") Listener { local_addr: "/ip6/::/udp/57511/webrtc/certhash/uEiDG_PH_2c_bJniPRvkmhT8limgRsCo5HX9aooz8JFYUMA", send_back_addr: "/ip6/2607:fea8:fec0:7337:1c60:851b:bb34:fac1/udp/55180/webrtc" }; Total (peer): 1.
[2023-03-22T17:39:58Z DEBUG libp2p_gossipsub::behaviour] New peer connected: 12D3KooWGXUH3UfQJyNk6EMCrzP8xfzmgpeTKHkZh62f4936kuzt
✔️  Connection Established to 12D3KooWGXUH3UfQJyNk6EMCrzP8xfzmgpeTKHkZh62f4936kuzt in 200.5684ms on /ip6/2607:fea8:fec0:7337:1c60:8
51b:bb34:fac1/udp/55180/webrtc
📞  Dialing /ip6/2607:fea8:fec0:7337:1c60:851b:bb34:fac1/udp/55180/webrtc
[2023-03-22T17:39:58Z DEBUG libp2p_webrtc::tokio::connection] Data channel 1 open
[2023-03-22T17:39:58Z DEBUG libp2p_swarm] Connection attempt to unknown peer failed with Transport([("/ip6/2607:fea8:fec0:7337:1c60:851b:bb34:fac1/udp/55180/webrtc", MultiaddrNotSupported("/ip6/2607:fea8:fec0:7337:1c60:851b:bb34:fac1/udp/55180/webrtc"))])
🌟 Event: OutgoingConnectionError { peer_id: None, error: Transport([("/ip6/2607:fea8:fec0:7337:1c60:851b:bb34:fac1/udp/55180/webrtc", MultiaddrNotSupported("/ip6/2607:fea8:fec0:7337:1c60:851b:bb34:fac1/udp/55180/webrtc"))]) }

[2023-03-22T17:39:58Z DEBUG libp2p_webrtc::tokio::connection] Incoming data channel 0
[2023-03-22T17:39:58Z DEBUG libp2p_webrtc::tokio::connection] Data channel 0 open
[2023-03-22T17:39:58Z DEBUG libp2p_webrtc::tokio::connection] Incoming data channel 0
[2023-03-22T17:39:58Z DEBUG libp2p_webrtc::tokio::connection] Data channel 0 open
[2023-03-22T17:39:58Z DEBUG libp2p_gossipsub::behaviour] New peer type found: Gossipsub v1.1 for peer: 12D3KooWGXUH3UfQJyNk6EMCrzP8xfzmgpeTKHkZh62f4936kuzt
[2023-03-22T17:39:58Z DEBUG libp2p_webrtc::tokio::connection] Incoming data channel 0
[2023-03-22T17:39:58Z DEBUG libp2p_webrtc::tokio::connection] Data channel 0 open
[2023-03-22T17:39:58Z INFO  libp2p_webrtc::tokio::substream::drop_listener] Substream 2 dropped without graceful close, sending Reset
[2023-03-22T17:39:58Z INFO  libp2p_webrtc::tokio::substream::drop_listener] Substream 4 dropped without graceful close, sending Reset
[2023-03-22T17:39:58Z DEBUG libp2p_webrtc::tokio::connection] a DropListener failed: Stream closed
[2023-03-22T17:39:58Z DEBUG libp2p_gossipsub::behaviour] Handling subscriptions: [Subscription { action: Subscribe, topic_hash: TopicHash { hash: "chat" } }], from source: 12D3KooWGXUH3UfQJyNk6EMCrzP8xfzmgpeTKHkZh62f4936kuzt
[2023-03-22T17:39:58Z DEBUG libp2p_gossipsub::behaviour] SUBSCRIPTION: Adding gossip peer: 12D3KooWGXUH3UfQJyNk6EMCrzP8xfzmgpeTKHkZh62f4936kuzt to topic: TopicHash { hash: "chat" }
[2023-03-22T17:39:58Z DEBUG libp2p_gossipsub::behaviour] SUBSCRIPTION: Adding peer 12D3KooWGXUH3UfQJyNk6EMCrzP8xfzmgpeTKHkZh62f4936kuzt to the mesh for topic TopicHash { hash: "chat" }
[2023-03-22T17:39:58Z DEBUG libp2p_gossipsub::behaviour] Sending GRAFT to peer 12D3KooWGXUH3UfQJyNk6EMCrzP8xfzmgpeTKHkZh62f4936kuzt for topic TopicHash { hash: "chat" }
💨💨💨  TopicHash { hash: "chat" } Subscriber: 12D3KooWGXUH3UfQJyNk6EMCrzP8xfzmgpeTKHkZh62f4936kuzt
[2023-03-22T17:39:58Z DEBUG rtc_server] ### Number peers: 1 ###
Peer: PeerId("12D3KooWGXUH3UfQJyNk6EMCrzP8xfzmgpeTKHkZh62f4936kuzt")
[2023-03-22T17:39:58Z DEBUG libp2p_gossipsub::behaviour] Adding explicit peer 12D3KooWGXUH3UfQJyNk6EMCrzP8xfzmgpeTKHkZh62f4936kuzt
[2023-03-22T17:39:58Z DEBUG libp2p_gossipsub::behaviour] Published message: MessageId(31353736343138343733313631303438323533)
[2023-03-22T17:39:59Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-03-22T17:39:59Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: chat Contains: 1 needs: 2
[2023-03-22T17:39:59Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:39:59Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-03-22T17:39:59Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:39:59Z DEBUG libp2p_gossipsub::behaviour] Gossiping IHAVE to 0 peers.
[2023-03-22T17:39:59Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-03-22T17:40:04Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-03-22T17:40:04Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: chat Contains: 1 needs: 2
[2023-03-22T17:40:04Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:40:04Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-03-22T17:40:04Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:40:04Z DEBUG libp2p_gossipsub::behaviour] Gossiping IHAVE to 0 peers.
[2023-03-22T17:40:04Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-03-22T17:40:08Z DEBUG libp2p_gossipsub::behaviour] Handling message: MessageId(34393731303230333633333535313133353030) from peer: 12D3KooWGXUH3UfQJyNk6EMCrzP8xfzmgpeTKHkZh62f4936kuzt
[2023-03-22T17:40:08Z DEBUG libp2p_gossipsub::behaviour] Put message MessageId(34393731303230333633333535313133353030) in duplicate_cache and resolve promises
[2023-03-22T17:40:08Z DEBUG libp2p_gossipsub::behaviour] Sending received message to user
[2023-03-22T17:40:08Z DEBUG libp2p_gossipsub::behaviour] Forwarding message: MessageId(34393731303230333633333535313133353030)
[2023-03-22T17:40:08Z DEBUG libp2p_gossipsub::behaviour] Completed message handling for message: MessageId(34393731303230333633333535313133353030)
📨 Got message: 'hello1' with id: 34393731303230333633333535313133353030 from peer: 12D3KooWGXUH3UfQJyNk6EMCrzP8xfzmgpeTKHkZh62f4936kuzt
[2023-03-22T17:40:08Z DEBUG libp2p_gossipsub::behaviour] Published message: MessageId(3131303437343530333230313133323738353830)
[2023-03-22T17:40:09Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-03-22T17:40:09Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: chat Contains: 1 needs: 2
[2023-03-22T17:40:09Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:40:09Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-03-22T17:40:09Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:40:09Z DEBUG libp2p_gossipsub::behaviour] Gossiping IHAVE to 0 peers.
[2023-03-22T17:40:09Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-03-22T17:40:14Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-03-22T17:40:14Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: chat Contains: 1 needs: 2
[2023-03-22T17:40:14Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:40:14Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-03-22T17:40:14Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:40:14Z DEBUG libp2p_gossipsub::behaviour] Gossiping IHAVE to 0 peers.
[2023-03-22T17:40:14Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-03-22T17:40:19Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-03-22T17:40:19Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: chat Contains: 1 needs: 2
[2023-03-22T17:40:19Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:40:19Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-03-22T17:40:19Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:40:19Z DEBUG libp2p_gossipsub::behaviour] Gossiping IHAVE to 0 peers.
[2023-03-22T17:40:19Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-03-22T17:40:24Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-03-22T17:40:24Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: chat Contains: 1 needs: 2
[2023-03-22T17:40:24Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:40:24Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-03-22T17:40:24Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-03-22T17:40:24Z DEBUG libp2p_gossipsub::behaviour] Handling message: MessageId(3137343139333433313636313038363236383436) from peer: 12D3KooWGXUH3UfQJyNk6EMCrzP8xfzmgpeTKHkZh62f4936kuzt
[2023-03-22T17:40:24Z DEBUG libp2p_gossipsub::behaviour] Put message MessageId(3137343139333433313636313038363236383436) in duplicate_cache and resolve promises
[2023-03-22T17:40:24Z DEBUG libp2p_gossipsub::behaviour] Sending received message to user
[2023-03-22T17:40:24Z DEBUG libp2p_gossipsub::behaviour] Forwarding message: MessageId(3137343139333433313636313038363236383436)
[2023-03-22T17:40:24Z DEBUG libp2p_gossipsub::behaviour] Completed message handling for message: MessageId(3137343139333433313636313038363236383436)
📨 Got message: 'bird is the word' with id: 3137343139333433313636313038363236383436 from peer: 12D3KooWGXUH3UfQJyNk6EMCrzP8xfzmgpeTKHkZh62f4936kuzt
[2023-03-22T17:40:24Z DEBUG libp2p_gossipsub::behaviour] Published message: MessageId(31313734333139313233363732323731343030)
[2023-03-22T17:40:29Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-03-22T17:40:29Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: chat Contains: 1 needs: 2
[2023-03-22T17:40:29Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:40:29Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-03-22T17:40:29Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:40:29Z DEBUG libp2p_gossipsub::behaviour] Gossiping IHAVE to 0 peers.
[2023-03-22T17:40:29Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat
[2023-03-22T17:40:34Z DEBUG libp2p_gossipsub::behaviour] Starting heartbeat
[2023-03-22T17:40:34Z DEBUG libp2p_gossipsub::behaviour] HEARTBEAT: Mesh low. Topic: chat Contains: 1 needs: 2
[2023-03-22T17:40:34Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:40:34Z DEBUG libp2p_gossipsub::behaviour] Updating mesh, new mesh: {}
[2023-03-22T17:40:34Z DEBUG libp2p_gossipsub::behaviour] RANDOM PEERS: Got 0 peers
[2023-03-22T17:40:34Z DEBUG libp2p_gossipsub::behaviour] Gossiping IHAVE to 0 peers.
[2023-03-22T17:40:34Z DEBUG libp2p_gossipsub::behaviour] Completed Heartbeat

Typical Client side failure (browser JS)

libp2p:dialer storing multiaddrs 12D3KooWQc4gfhDkuT5gYzho3TvxxVboe7M9Aoh24GKbFfEAy6vE +0ms DefaultMultiaddr {bytes: Uint8Array(101), Symbol(@multiformats/js-multiaddr/multiaddr): true}
common.js:113 libp2p:dialer creating dial target for 12D3KooWQc4gfhDkuT5gYzho3TvxxVboe7M9Aoh24GKbFfEAy6vE +12ms
common.js:113 libp2p:dialer 1 tokens request, returning 1, 99 remaining +5ms
DevTools failed to load source map: Could not load content for chrome-extension://bfnaelmomeimhlpmgjnjophhpkkoljpa/content-script/contentScript.js.map: System error: net::ERR_BLOCKED_BY_CLIENT
DevTools failed to load source map: Could not load content for chrome-extension://bfnaelmomeimhlpmgjnjophhpkkoljpa/content-script/inpageSol.js.map: System error: net::ERR_BLOCKED_BY_CLIENT
common.js:113 libp2p:dialer creating dial target for 12D3KooWQc4gfhDkuT5gYzho3TvxxVboe7M9Aoh24GKbFfEAy6vE +195ms
common.js:113 libp2p:webrtc:transport dialing address - /ip6/2607:fea8:fec0:7337:6b21:9df6:d46e:29d3/udp/59241/webrtc/certhash/uEiBHA3fZ6lJn-J64Szi7Qf9VOGrvAOUPHEAuYblDlxk4ow/p2p/12D3KooWQc4gfhDkuT5gYzho3TvxxVboe7M9Aoh24GKbFfEAy6vE +0ms
common.js:113 libp2p:dialer token 0 released +251ms
common.js:113 libp2p:dialer dial succeeded to 12D3KooWQc4gfhDkuT5gYzho3TvxxVboe7M9Aoh24GKbFfEAy6vE +2ms
common.js:113 libp2p:dialer dial succeeded to 12D3KooWQc4gfhDkuT5gYzho3TvxxVboe7M9Aoh24GKbFfEAy6vE +1ms
Chat.svelte:94 peer connected {connection: CustomEvent}
Chat.svelte:85 Sending msg: Bird bird bird, bird is the word!
Chat.svelte:142 {stream: WebRTCStream}

Possible Solution

Troubleshoot the upgrade process, specific for WebRTC process.

Version

• libp2p version: 0.51.1

Would you like to work on fixing this bug?

Maybe. I've troubleshot as far as I can, willing to help more but I'm at a loss as to what to try next,

[DougAnderson444]

To add to the troubleshooting, whenever I have the server dial the browser (which totally shouldn't work, it always fails as the browser is not listening) the chances of a successful handshake increases significantly. It's strange behaviour. Makes me wonder if there's a part of the WebRTC handshake from the server to the browser that doesn't always get called.

eprintln!("✔️  Connection Established to {peer_id} in {established_in:?} on {send_back_addr}");

// This dial shouldn't work, but strangely increases the odds of connecting...
let mut res = send_back_addr;
strip_peer_id(&mut res);

eprintln!("📞  Server dialing the browser {res}");

let dial_opts = DialOpts::unknown_peer_id()
    .address(res.clone())
    .build();
if let Err(e) = swarm.dial(dial_opts) {
    println!("❌  (Expected) Dialing error: {e:?}");
}

[DougAnderson444]

Linking here libp2p/universal-connectivity#3

[DougAnderson444]

Addressing gossipsub upgrade issues here: #3625

[DougAnderson444]

@thomaseizinger It's definitely a rust-libp2p issue.

I've narrowed it down: it is happening on the rust server side, somewhere between:

[libp2p_gossipsub::behaviour] 
SUBSCRIPTION: Adding gossip peer: 12D3KooWF6qfHkJE9NDfLd6BJeWFNNSbGBpPcYYM6HxH8Eng3m7m to topic

and

[WARN  libp2p_gossipsub::handler] Dial upgrade error Timeout

Somehow gossipsub adds the peer, adds a subscriber, but then fails on the upgrade (but only most of the time...)

[DougAnderson444]

[WARN libp2p_gossipsub::handler] Dial upgrade error Timeout

coming from libp2p_swarm::connection:

rust-libp2p/swarm/src/connection.rs

Lines 249 to 264 in fd09835

	// In case the [`ConnectionHandler`] can not make any more progress, poll the negotiating outbound streams.
	match negotiating_out.poll_next_unpin(cx) {
	Poll::Pending | Poll::Ready(None) => {}
	Poll::Ready(Some((info, Ok(protocol)))) => {
	handler.on_connection_event(ConnectionEvent::FullyNegotiatedOutbound(
	FullyNegotiatedOutbound { protocol, info },
	));
	continue;
	}
	Poll::Ready(Some((info, Err(error)))) => {
	handler.on_connection_event(ConnectionEvent::DialUpgradeError(
	DialUpgradeError { info, error },
	));
	continue;
	}
	}

[thomaseizinger]

and

[WARN  libp2p_gossipsub::handler] Dial upgrade error Timeout

We don't actually perform any upgrade on our side other than negotiating the protocol. Can you run with RUST_LOG=multistream_select=debug?

This might be an issue on the JS end. If the stream upgrade there is not completed within 10s (I think is our default timeout) then this error happens. Is the JS event-loop blocked perhaps? Can you turn up logging for the JS side?

[DougAnderson444]

I think @mxinden has figured it out here libp2p/universal-connectivity#3 (comment) , tracking here #3690

I am so glad, this was really driving me crazy!

[DougAnderson444]

This can probably be closed now, I've not been seeing the issue like it was before.