broken example: browser-webrtc

[DougAnderson444]

Summary

I fired up the latest https://github.com/libp2p/rust-libp2p/tree/master/examples/browser-webrtc to discover there's an error in the browser console

Expected behavior

The example should ping back and forth between the server and browser, only 1 ping gets across before crashing

Actual behavior

After the first ping, the browser crashes

Relevant log output

Uncaught Error: closure invoked recursively or after being dropped
    at imports.wbg.__wbindgen_throw (browser_webrtc_example.js:668:15)
    at browser_webrtc_example_bg.wasm:0xbed3a
    at browser_webrtc_example_bg.wasm:0xb6add
    at __wbg_adapter_30 (browser_webrtc_example.js:208:10)
    at RTCDataChannel.real (browser_webrtc_example.js:193:20)

Possible Solution

I suspect one of the web_sys closures isn't being handled properly? It likely gets dropped and then called.

Version

libp2p 0.53.1
libp2p_webrtc 0.6.1-alpha

Would you like to work on fixing this bug ?

Maybe

Tasks

Beta Give feedback

1. fix(browser-webrtc-example): use tracing-wasm logger #4952
   send-it +1
2. fix(webrtc example): clarify idle connection timeout #4966
   send-it +1

[DougAnderson444]

Oh, also I see the logging was upgraded to tracing but it doesn't look like it's compatible with wasm-logger as I'm not seeing any browser logs

[DougAnderson444]

The logging is an easy fix, PR above.

[thomaseizinger]

I suspect one of the web_sys closures isn't being handled properly?

Can we somehow identify which one?

[DougAnderson444]

I'm going to insert some tracing logs and try to figure out what is going wrong

[DougAnderson444]

Connection closed with error KeepAliveTimeout

Relevant logs:

DEBUG protocols/ping/src/handler.rs:284 ping succeeded rtt = 2ms;

browser_webrtc_example.js:313 INFO examples/browser-webrtc/src/lib.rs:46 
Ping successful: RTT: 2ms, from 12D3KooWKNSXqyYCpQvvt48a23rTs8sunjyMwH8Qdk7Co7ckoorA

browser_webrtc_example.js:313 TRACE transports/webrtc-websys/src/connection.rs:93 
connection::close_connection

browser_webrtc_example.js:313 DEBUG swarm/src/lib.rs:874 
Connection closed with error KeepAliveTimeout: Connected { endpoint: Dialer { address: "/ip4/10.0.0.140/udp/48471/webrtc-direct/certhash/uEiDxuSN86XFMzcZkqbI0mZE79FoMd5iy5BAIKMGz8KzYTw/p2p/12D3KooWKNSXqyYCpQvvt48a23rTs8sunjyMwH8Qdk7Co7ckoorA", role_override: Dialer }, peer_id: PeerId("12D3KooWKNSXqyYCpQvvt48a23rTs8sunjyMwH8Qdk7Co7ckoorA") } total_peers = 0;

browser_webrtc_example.js:313 INFO examples/browser-webrtc/src/lib.rs:49 
Swarm event: ConnectionClosed { peer_id: PeerId("12D3KooWKNSXqyYCpQvvt48a23rTs8sunjyMwH8Qdk7Co7ckoorA"), connection_id: ConnectionId(1), endpoint: Dialer { address: "/ip4/10.0.0.140/udp/48471/webrtc-direct/certhash/uEiDxuSN86XFMzcZkqbI0mZE79FoMd5iy5BAIKMGz8KzYTw/p2p/12D3KooWKNSXqyYCpQvvt48a23rTs8sunjyMwH8Qdk7Co7ckoorA", role_override: Dialer }, num_established: 0, cause: Some(KeepAliveTimeout) }

browser_webrtc_example.js:691 
Uncaught Error: closure invoked recursively or after being dropped
    at imports.wbg.__wbindgen_throw (browser_webrtc_example.js:691:15)
    at browser_webrtc_example_bg.wasm:0xcc313
    at browser_webrtc_example_bg.wasm:0xc2881
    at __wbg_adapter_30 (browser_webrtc_example.js:208:10)
    at RTCDataChannel.real (browser_webrtc_example.js:193:20)
imports.wbg.__wbindgen_throw @ browser_webrtc_example.js:691
$func1398 @ browser_webrtc_example_bg.wasm:0xcc313
$wasm_bindgen__convert__closures__invoke1_mut__h8a689f96ff52d314 @ browser_webrtc_example_bg.wasm:0xc2881
__wbg_adapter_30 @ browser_webrtc_example.js:208
real @ browser_webrtc_example.js:193

Looks like a KeepAliveTimeout issue? Were there changes made to this recently? I seem to recall seeing something in a changelog

[DougAnderson444]

It appears to be going idle and timing out, even though Pings are being received. Even if I extend the with_idle_connection_timeout it still goes idle and times out, even though it receives a few pings.

So this appears to be a Ping/KeepAlive issue, not a WebRTC issue

[DougAnderson444]

Is Ping designed to not keep the connection alive? Is there a way to override this for the example?

rust-libp2p/swarm/src/handler.rs

Lines 139 to 143 in e889e2e

	/// - Protocols like [ping](https://github.com/libp2p/specs/blob/master/ping/ping.md) **don't** want to keep a connection alive despite an active streams.
	/// In that case, protocol authors can use [`Stream::ignore_for_keep_alive`](crate::Stream::ignore_for_keep_alive) to opt-out a particular stream from the keep-alive algorithm.
	fn connection_keep_alive(&self) -> bool {
	false
	}

I see what is done here though:

rust-libp2p/examples/ping/src/main.rs

Line 42 in e889e2e

.with_swarm_config(|cfg| cfg.with_idle_connection_timeout(Duration::from_secs(u64::MAX)))

which I can put into a PR.

[DougAnderson444]

After running the ping example to verify that it works fine on the command line (which it does), I tried these 3 experiments for our browser webrtc example:

.with_swarm_config(|c| {
            c.with_idle_connection_timeout(Duration::from_secs(
                // u64::MAX, // does not work, errors after 1 ping
                // js_sys::Number::MAX_SAFE_INTEGER as u64, // does not work, errors at ping # 1
                31_556_952u64, // works up to 3 pings, then errors
            ))
        })

The last value errored on ping:

TRACE transports/webrtc-websys/src/stream/poll_data_channel.rs:79 
DataChannel closed

DEBUG protocols/ping/src/handler.rs:262 
Ping failure: Other { error: Custom { kind: TimedOut, error: "ping protocol negotiation timed out" } }

I'm done troubleshooting for tonight 🌛, hopefully there's something obvious going on here that I don't know about.

[thomaseizinger]

Is Ping designed to not keep the connection alive?

Not by itself at least, yes. But as you discovered, one can extend the idle connection timeout.

I tried these 3 experiments for our browser webrtc example:

Did you extend the idle-connection-timeout for both the server and the browser?

[DougAnderson444]

Did you extend the idle-connection-timeout for both the server and the browser?

🤦‍♂️ I did not... but when I did, it works!

Curiously, in wasm we cannot use u64::MAX. The with_idle_connection_timeout breaks in the browser on anything bigger than 32_212_254u64

.with_swarm_config(|c| {
  c.with_idle_connection_timeout(Duration::from_secs(
   32_212_254u64,
   // 32_212_255u64, // breaks, too large for wasm?
  ))
})