ping check doesn't receive pong

[chase-qi]

Describe the bug

When downloading a large file on slow/unstable network, the tunnel is closed after about 2 minutes. From the client log, ping check didn't get pong, and the client closed the tunnel after several times ping checks.

To Reproduce

1. server: sudo wstunnel server --log-lvl DEBUG wss://[::]:443
2. client: wstunnel client --connection-min-idle 3 --log-lvl DEBUG -L socks5://127.0.0.1:1080 wss://192.168.18.66:443
3. app: curl --limit-rate 200K -x socks5://127.0.0.1:1080 https://gemmei.ftp.acc.umu.se/debian-cd/current/amd64/iso-cd/debian-12.9.0-amd64-netinst.iso --output debian.iso

Expected behavior

Downloading with slow network shouldn't be closed.

Your wstunnel setup

• client

$ /usr/local/bin/wstunnel client --log-lvl DEBUG -L socks5://127.0.0.1:1080 wss://192.168.18.66:443
2025-01-23T08:13:47.107302Z  INFO wstunnel: Starting wstunnel client v10.1.8
2025-01-23T08:13:47.107385Z  INFO wstunnel::protocols::socks5::tcp_server: Starting SOCKS5 server listening cnx on 127.0.0.1:1080 with credentials None
2025-01-23T08:13:51.101037Z DEBUG fast_socks5::server: incoming connection from peer 127.0.0.1:47148 @ 127.0.0.1:1080
2025-01-23T08:13:51.101120Z DEBUG fast_socks5::server: Handshake headers: [version: 5, methods len: 2]
2025-01-23T08:13:51.101145Z DEBUG fast_socks5::server: methods supported sent by the client: [0, 1]
2025-01-23T08:13:51.101182Z DEBUG fast_socks5::server: Reply with method AuthenticationMethod::None (0)
2025-01-23T08:13:51.105865Z DEBUG fast_socks5::server: Request: [version: 5, command: 1, rev: 0, address_type: 1]
2025-01-23T08:13:51.105936Z DEBUG fast_socks5::util::target_addr: Address type `IPv4`
2025-01-23T08:13:51.105973Z DEBUG fast_socks5::server: Request target is 194.71.11.137:443
2025-01-23T08:13:51.105992Z DEBUG fast_socks5::server: Domain won't be resolved because `dns_resolve`'s config has been turned off.
2025-01-23T08:13:51.106578Z  INFO wstunnel::protocols::tcp::server: Opening TCP connection to 192.168.18.66:443
2025-01-23T08:13:51.106904Z DEBUG wstunnel::protocols::tcp::server: Connecting to 192.168.18.66:443
2025-01-23T08:13:51.107507Z DEBUG wstunnel::protocols::tcp::server: Connected to tcp endpoint 192.168.18.66:443, aborted all other connection attempts
2025-01-23T08:13:51.107556Z  INFO wstunnel::protocols::tls::server: Doing TLS handshake using SNI IpAddress(V4(Ipv4Addr([192, 168, 18, 66]))) with the server 192.168.18.66:443
2025-01-23T08:13:51.107619Z DEBUG rustls::client::hs: No cached session for IpAddress(V4(Ipv4Addr([192, 168, 18, 66])))
2025-01-23T08:13:51.107937Z DEBUG rustls::client::hs: Not resuming any session
2025-01-23T08:13:51.109132Z DEBUG rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384
2025-01-23T08:13:51.109184Z DEBUG rustls::client::tls13: Not resuming
2025-01-23T08:13:51.109494Z DEBUG rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([ProtocolName(687474702f312e31)])]
2025-01-23T08:13:51.109540Z DEBUG rustls::client::hs: ALPN protocol is Some(b"http/1.1")
2025-01-23T08:13:51.109950Z DEBUG tunnel{id="01949239-8682-7a22-a92e-f2e7fc200ae1" remote="194.71.11.137:443"}: wstunnel::tunnel::transport::websocket: with HTTP upgrade request Request { method: GET, uri: /v1/events, version: HTTP/1.1, headers: {"host": "192.168.18.66", "upgrade": "websocket", "connection": "upgrade", "sec-websocket-key": "ZCNSQSID+VlRrzlWf7RG8w==", "sec-websocket-version": "13", "sec-websocket-protocol": "v1, authorization.bearer.eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJpZCI6IjAxOTQ5MjM5LTg2ODItN2EyMi1hOTJlLWYyZTdmYzIwMGFlMSIsInAiOnsiVGNwIjp7InByb3h5X3Byb3RvY29sIjpmYWxzZX19LCJyIjoiMTk0LjcxLjExLjEzNyIsInJwIjo0NDN9.okN2IxZ9Vwt0sGnUzqQCZdxjV_CdXWHoTvLMku5Sxd0"}, body: Empty }
2025-01-23T08:13:51.459947Z DEBUG tunnel{id="01949239-8682-7a22-a92e-f2e7fc200ae1" remote="194.71.11.137:443"}: wstunnel::tunnel::client::client: Server response: Parts { status: 101, version: HTTP/1.1, headers: {"connection": "upgrade", "upgrade": "websocket", "sec-websocket-accept": "NYzpk1taM1+ZSMS6Mdf5ZpR4dmg=", "sec-websocket-protocol": "v1", "date": "Thu, 23 Jan 2025 08:13:51 GMT"} }
2025-01-23T08:14:21.461228Z DEBUG tunnel{id="01949239-8682-7a22-a92e-f2e7fc200ae1" remote="194.71.11.137:443"}: wstunnel::tunnel::transport::io: sending ping to keep connection alive
2025-01-23T08:14:51.461350Z DEBUG tunnel{id="01949239-8682-7a22-a92e-f2e7fc200ae1" remote="194.71.11.137:443"}: wstunnel::tunnel::transport::io: sending ping to keep connection alive
2025-01-23T08:15:21.461581Z DEBUG tunnel{id="01949239-8682-7a22-a92e-f2e7fc200ae1" remote="194.71.11.137:443"}: wstunnel::tunnel::transport::io: sending ping to keep connection alive
2025-01-23T08:15:51.460974Z DEBUG tunnel{id="01949239-8682-7a22-a92e-f2e7fc200ae1" remote="194.71.11.137:443"}: wstunnel::tunnel::transport::io: sending ping to keep connection alive
2025-01-23T08:15:51.461080Z  INFO tunnel{id="01949239-8682-7a22-a92e-f2e7fc200ae1" remote="194.71.11.137:443"}: wstunnel::tunnel::transport::io: Closing local => remote tunnel
2025-01-23T08:15:51.461377Z  INFO tunnel{id="01949239-8682-7a22-a92e-f2e7fc200ae1" remote="194.71.11.137:443"}: wstunnel::tunnel::transport::io: Closing local <= remote tunnel

• server

$ sudo wstunnel server --log-lvl DEBUG wss://[::]:443
2025-01-23T08:13:38.246080Z  INFO wstunnel::embedded_certificate: Generating self-signed tls certificate
....
....
2025-01-23T08:15:51.473696Z  WARN cnx{peer="[::ffff:192.168.18.6]:53876"}:tunnel{id="01949239-8682-7a22-a92e-f2e7fc200ae1" remote="194.71.11.137:443"}: wstunnel::tunnel::transport::io: error while writing to tx tunnel Connection reset by peer (os error 104)
2025-01-23T08:15:51.473793Z ERROR cnx{peer="[::ffff:192.168.18.6]:53876"}:tunnel{id="01949239-8682-7a22-a92e-f2e7fc200ae1" remote="194.71.11.137:443"}: wstunnel::tunnel::transport::io: error while reading from tunnel rx peer closed connection without sending TLS close_notify: https://docs.rs/rustls/latest/rustls/manual/_03_howto/index.html#unexpected-eof
2025-01-23T08:15:51.473917Z  INFO cnx{peer="[::ffff:192.168.18.6]:53876"}:tunnel{id="01949239-8682-7a22-a92e-f2e7fc200ae1" remote="194.71.11.137:443"}: wstunnel::tunnel::transport::io: Closing local => remote tunnel
2025-01-23T08:15:51.475023Z  INFO cnx{peer="[::ffff:192.168.18.6]:53876"}:tunnel{id="01949239-8682-7a22-a92e-f2e7fc200ae1" remote="194.71.11.137:443"}: wstunnel::tunnel::transport::io: Closing local <= remote tunnel

Desktop (please complete the following information):

• OS: debian
• Version: v10.1.8

Additional context
Disabling the ping check using --websocket-ping-frequency-sec 0 solved my issue. I am opening the issue for the ping check failure.

[erebe]

Thanks for the reproduction case, I will try to take a look at it in the in-coming week

[erebe]

Hello,

I got the chance to look at it, and sadly I can't do anything about it.
In the websocket protocol, there is no QoS/out of band notification for the control messages.
So the client must first dequeue all the messages before getting the ping, and flush all the messages to the network for the pong to be sent to the server. Which on a slow connection take a lot of time.

The only way I see, beside disabling ping as you have done, it to reduce the buffer of the tcp stack at OS level to reduce the latency. it will force to have a small buffer queue.

net.ipv4.tcp_wmem = 4096 16384 4194304 
net.ipv4.tcp_rmem = 4096 87380 6291456     

I don't see any alternative beside that

[chase-qi]

@erebe Thank you so much for looking into it. It sounds like a limitation in this case. Yeah, I guess let's live with it. So far, disabling ping worked great for me.