search

vi / websocat

Command-line client for WebSockets, like netcat (or curl) for ws:// with advanced socat-like functions
MIT License
7.18k stars 278 forks source link

Websocat in servermode eating a CPU core after closing TCP socket #35

Open therealprof opened 5 years ago

therealprof commented 5 years ago

I noticed that with my misbehaving client if I just close the TCP socket on the client side, the loop in block_on will run at maximum speed just spinning:

    frame #36: 0x0000000100028241 websocat`tokio::runtime::current_thread::runtime::Runtime::block_on::h5787e30364afd47d(self=0x00007fff5fbfd788, f=<unavailable>) + 81 at runtime.rs:189
    frame #37: 0x0000000100006f69 websocat`websocat::run::he5b002ccc4cdf93a + 11529 at main.rs:672
    frame #38: 0x0000000100009130 websocat`websocat::main::h64c0053338159ebd + 16 at main.rs:678

Not sure where exactly the bug is but I would expect websocat to handle such a situation.

vi commented 5 years ago

What is the websocat command line? Is there -E option? Maybe autoreconnect: is in effect?

therealprof commented 5 years ago

I'm using websocat -vvv -s 8090:

Listening on ws://127.0.0.1:8090/
[INFO  websocat::lints] Auto-inserting the line mode
[DEBUG websocat] Done third phase of interpreting options.
[DEBUG websocat] Done fourth phase of interpreting options.
[DEBUG websocat] Preparation done. Now actually starting.
[INFO  websocat::sessionserve] Serving Message2Line(WsServer(TcpListen(V4(127.0.0.1:8090)))) to BroadcastReuser(Line2Message(Stdio)) with Options { websocket_text_mode: true, websocket_protocol: None, udp_oneshot_mode: false, unidirectional: false, unidirectional_reverse: false, exit_on_eof: true, oneshot: false, unlink_unix_socket: false, exec_args: [], ws_c_uri: "ws://0.0.0.0/", linemode_strip_newlines: false, linemode_strict: false, origin: None, custom_headers: [], websocket_version: None, websocket_dont_close: false, one_message: false, no_auto_linemode: false, buffer_size: 65536, broadcast_queue_len: 16, read_debt_handling: Warn, linemode_zero_terminated: false, restrict_uri: None, serve_static_files: [], exec_set_env: false, reuser_send_zero_msg_on_disconnect: false, process_zero_sighup: false, process_exit_sighup: false, socks_destination: None, auto_socks5: None, socks5_bind_script: None, tls_domain: None, tls_insecure: false, max_parallel_conns: None }
therealprof commented 5 years ago

These are the last lines of output:

[INFO  websocat::ws_server_peer] Upgraded
[INFO  websocat::broadcast_reuse_peer] Reusing
[TRACE websocat::my_copy] poll
[TRACE websocat::my_copy] poll
[TRACE websocat::my_copy] poll
[DEBUG websocat::ws_peer] drop WsWriteWrapper
websocat: WebSocketError: WebSocket data frame error
vi commented 5 years ago

Is it reproducible when using websocat ws://127.0.0.1:8090 as a client and interrupting it with Ctrl+C? What platform is it on? Linux,Windows,Mac,Other?

Debugging output for myself when I start server, connect with another websocat, then terminate it:

$ websocat -vvv -s 8090
Listening on ws://127.0.0.1:8090/
[INFO  websocat::lints] Auto-inserting the line mode
[DEBUG websocat] Done third phase of interpreting options.
[DEBUG websocat] Done fourth phase of interpreting options.
[DEBUG websocat] Preparation done. Now actually starting.
[INFO  websocat::sessionserve] Serving Message2Line(WsServer(TcpListen(V4(127.0.0.1:8090)))) to BroadcastReuser(Line2Message(Stdio)) with Options { websocket_text_mode: true, websocket_protocol: None, udp_oneshot_mode: false, unidirectional: false, unidirectional_reverse: false, exit_on_eof: true, oneshot: false, unlink_unix_socket: false, exec_args: [], ws_c_uri: "ws://0.0.0.0/", linemode_strip_newlines: false, linemode_strict: false, origin: None, custom_headers: [], websocket_version: None, websocket_dont_close: false, one_message: false, no_auto_linemode: false, buffer_size: 65536, broadcast_queue_len: 16, read_debt_handling: Warn, linemode_zero_terminated: false, restrict_uri: None, serve_static_files: [], exec_set_env: false, reuser_send_zero_msg_on_disconnect: false, process_zero_sighup: false, process_exit_sighup: false, socks_destination: None, auto_socks5: None, socks5_bind_script: None, tls_domain: None, tls_insecure: false, max_parallel_conns: None }
[INFO  websocat::net_peer] Incoming TCP connection from Some(V4(127.0.0.1:47864))
[DEBUG websocat::sessionserve] Underlying connection established
[INFO  websocat::sessionserve] Serving 1 ongoing connections
[INFO  websocat::ws_server_peer] Incoming connection to websocket: /
[DEBUG websocat::ws_server_peer] Incoming { version: Http11, subject: (Get, AbsolutePath("/")), headers: Headers { Host: 127.0.0.1:8090
, Connection: Upgrade
, Upgrade: websocket
, Sec-WebSocket-Version: 13
, Sec-WebSocket-Key: smVW/7cfNRxR3xDJ6S6a+Q==
, } }
[DEBUG websocat::ws_server_peer] Headers { }
[DEBUG websocat::ws_server_peer] Headers { Sec-WebSocket-Accept: y+RH4hFg6GFtCQKH//rfTJpuqZ8=
, Connection: Upgrade
, Upgrade: websocket
, }
[INFO  websocat::ws_server_peer] Upgraded
[INFO  websocat::broadcast_reuse_peer] Initializing
[INFO  websocat::stdio_peer] get_stdio_peer (async)
[INFO  websocat::stdio_peer] Setting stdin to nonblocking mode
[INFO  websocat::stdio_peer] Installing signal handler
[DEBUG websocat::ws_peer] incoming text
asdf
[DEBUG websocat::ws_peer] incoming text
safddsf
[DEBUG websocat::ws_peer] incoming None
[DEBUG websocat::my_copy] BrokenPipe: read_done
[DEBUG websocat::my_copy] done
[INFO  websocat::sessionserve] Forward finished
[INFO  websocat::sessionserve] Forward shutdown finished
[INFO  websocat::sessionserve] One of directions finished
[DEBUG websocat::ws_peer] drop WsWriteWrapper
therealprof commented 5 years ago

Is it reproducible when using websocat ws://127.0.0.1:8090 as a client and interrupting it with Ctrl+C?

Yes.

What platform is it on? Linux,Windows,Mac,Other?

Mac

vi commented 5 years ago

Seems to be not reproducible on Linux; I'll try on Mac later.

Which version of Websocat do you use? 1.3.0? Is it also reproducible with 1.2.0 or 1.1.0?

therealprof commented 5 years ago

I haven't tried older versions, only 1.3.0. I also tried bumping all dependencies (except hyper which is API incompatible) but no change.

vi commented 5 years ago

Tried on Mac myself for 1.3.0 and 1.2.0 and can't easily reproduce it.

Are you building websocat yourself or using Github release?

therealprof commented 5 years ago

cargo installed it.

therealprof commented 5 years ago

Same behaviour with websocat_mac downloaded from GitHub, though.

vi commented 5 years ago

Is it the same for https://github.com/vi/websocat/releases/download/v1.3.0/websocat_mac?

Looks like yes...

vi commented 5 years ago

Does it accept new connections while busy looping after bug?

vi commented 5 years ago

Is it the same for older websocat like https://github.com/vi/websocat/releases/download/v1.1.0/websocat_mac

vi commented 5 years ago

Can you try to dtruss it? Which syscalls are invoked before and when it is busy looping?

therealprof commented 5 years ago

Same thing for v1.1.0. But I'm afraid I don't really have time to deeply analyse it right now.

vi commented 5 years ago

What version of OS X?

We can analyse it later; I'm not sure how to address it by myself (I'm not a Mac user in general).

One of experiments: running websocat -t -E tcp-l:127.0.0.1:8090 - (i.e. just a TCP server, not WebSocket server) and checking if the bug can be still triggered.

therealprof commented 5 years ago

macOS 10.12.6

therealprof commented 5 years ago

websocat -t -E tcp-l:127.0.0.1:8090 - -> same problem

vi commented 5 years ago

So the problem seems to be independent of WebSockets.

Can you try running this TCP echo server: https://github.com/tokio-rs/tokio/blob/master/examples/echo.rs and checking if has the problem (not necessary now, when you have time for this). If needed I can make a pre-built version.