Stream EOF immediately after connection established

yuan-thomas commented 3 months ago

Describe the bug

I have a wstunnel in Docker behind a reverse proxy, that has a public endpoint.

Server side is straight default: wstunnel server ws://0.0.0.0:8080

Client side is wstunnel client -L tcp://9090:www.google.com:80 wss://wstunnel.myserver.com

To Reproduce

Then just connect to localhost:9090 at client and GET request

Expected behavior

There should be normal http response but nothing happens. Checking the log, it seems as if the connection is immediately cut after established. But the trace doesn't tell too much.

Your wstunnel setup

client log

2024-08-13T10:54:35.967083Z  INFO wstunnel::tls: Doing TLS handshake using SNI DnsName("wstunnel.myserver.com") with the server wstunnel.myserver.com:443
2024-08-13T10:54:35.967192Z DEBUG rustls::client::hs: No cached session for DnsName("wstunnel.myserver.com")
2024-08-13T10:54:35.967369Z DEBUG rustls::client::hs: Not resuming any session
2024-08-13T10:54:36.014793Z DEBUG rustls::client::hs: ALPN protocol is None
2024-08-13T10:54:36.015157Z DEBUG rustls::client::hs: Using ciphersuite TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
2024-08-13T10:54:36.015378Z DEBUG rustls::client::tls12: ECDHE curve is EcParameters { curve_type: NamedCurve, named_group: secp256r1 }
2024-08-13T10:54:36.015555Z DEBUG rustls::client::tls12: Server DNS name is DnsName("wstunnel.myserver.com")
2024-08-13T10:54:36.037783Z DEBUG tunnel{id="01914b60-1d8d-75c0-9fce-e194b44c931e" remote="www.google.com:80"}: wstunnel::tunnel::transport::websocket: with HTTP upgrade request Request { method: GET, uri: /v1/events, version: HTTP/1.1, headers: {"host": "wstunnel.myserver.com", "upgrade": "websocket", "connection": "upgrade", "sec-websocket-key": "h8d+JIqKcqwJsRAzpc/HPA==", "sec-websocket-version": "13", "sec-websocket-protocol": "v1, authorization.bearer.eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJpZCI6IjAxOTE0YjYwLTFkOGQtNzVjMC05ZmNlLWUxOTRiNDRjOTMxZSIsInAiOnsiVGNwIjp7InByb3h5X3Byb3RvY29sIjpmYWxzZX19LCJyIjoid3d3Lmdvb2dsZS5jb20iLCJycCI6ODB9.C-cXFxKnPaJLKUxvsU1J5uXap4PMxL9FgZnjqwM3QvY"}, body: Empty }
2024-08-13T10:54:36.328816Z DEBUG tunnel{id="01914b60-1d8d-75c0-9fce-e194b44c931e" remote="www.google.com:80"}: wstunnel::tunnel::client: Server response: Parts { status: 101, version: HTTP/1.1, headers: {"connection": "upgrade", "upgrade": "websocket", "sec-websocket-accept": "h4MGxQW8K85SqHrlRt7Hsi0+PT4=", "sec-websocket-protocol": "v1", "date": "Tue, 13 Aug 2024 10:54:29 GMT"} }
**2024-08-13T10:54:36.569826Z ERROR tunnel{id="01914b60-1d8d-75c0-9fce-e194b44c931e" remote="www.google.com:80"}: wstunnel::tunnel::transport::io: error while reading from tunnel rx websocket close**
2024-08-13T10:54:36.570126Z  INFO tunnel{id="01914b60-1d8d-75c0-9fce-e194b44c931e" remote="www.google.com:80"}: wstunnel::tunnel::transport::io: Closing local <= remote tunnel
2024-08-13T10:54:36.570390Z  INFO tunnel{id="01914b60-1d8d-75c0-9fce-e194b44c931e" remote="www.google.com:80"}: wstunnel::tunnel::transport::io: Closing local => remote tunnel

server


2024-08-13T10:54:29.227341Z DEBUG tunnel{peer="172.17.0.1:19400" forwarded_for="49.120.2.34" id="01914b60-1d8d-75c0-9fce-e194b44c931e" remote="www.google.com:80"}: hickory_proto::udp::udp_client_stream: received message id: 58256
2024-08-13T10:54:29.227437Z DEBUG tunnel{peer="172.17.0.1:19400" forwarded_for="49.120.2.34" id="01914b60-1d8d-75c0-9fce-e194b44c931e" remote="www.google.com:80"}: hickory_resolver::error: Response:; header 58256:RESPONSE:RD,RA:NoError:QUERY:1/0/0
; query
;; www.google.com. IN A
; answers 1
www.google.com. 300 IN A 172.217.24.36
; nameservers 0
; additionals 0

2024-08-13T10:54:29.227505Z DEBUG tunnel{peer="172.17.0.1:19400" forwarded_for="49.120.2.34" id="01914b60-1d8d-75c0-9fce-e194b44c931e" remote="www.google.com:80"}: hickory_resolver::error: Response:; header 58256:RESPONSE:RD,RA:NoError:QUERY:1/0/0 ; query ;; www.google.com. IN A ; answers 1 www.google.com. 300 IN A 172.217.24.36 ; nameservers 0 ; additionals 0

2024-08-13T10:54:29.227819Z DEBUG wstunnel::protocols::tcp::server: Connecting to [2404:6800:4006:804::2004]:80 2024-08-13T10:54:29.227878Z DEBUG tunnel{peer="172.17.0.1:19400" forwarded_for="49.120.2.34" id="01914b60-1d8d-75c0-9fce-e194b44c931e" remote="www.google.com:80"}: wstunnel::protocols::tcp::server: Cannot connect to tcp endpoint [2404:6800:4006:804::2004]:80 reason Cannot assign requested address (os error 99) 2024-08-13T10:54:29.479297Z DEBUG wstunnel::protocols::tcp::server: Connecting to 172.217.24.36:80 2024-08-13T10:54:29.479989Z DEBUG tunnel{peer="172.17.0.1:19400" forwarded_for="49.120.2.34" id="01914b60-1d8d-75c0-9fce-e194b44c931e" remote="www.google.com:80"}: wstunnel::protocols::tcp::server: Connected to tcp endpoint 172.217.24.36:80, aborted all other connection attempts 2024-08-13T10:54:29.480036Z INFO tunnel{peer="172.17.0.1:19400" forwarded_for="49.120.2.34" id="01914b60-1d8d-75c0-9fce-e194b44c931e" remote="www.google.com:80"}: wstunnel::tunnel::server: connected to Tcp { proxy_protocol: false } www.google.com:80 2024-08-13T10:54:29.716534Z ERROR tunnel{peer="172.17.0.1:19400" forwarded_for="49.120.2.34" id="01914b60-1d8d-75c0-9fce-e194b44c931e" remote="www.google.com:80"}: wstunnel::tunnel::transport::io: error while reading from tunnel rx Unexpected EOF 2024-08-13T10:54:29.716840Z INFO tunnel{peer="172.17.0.1:19400" forwarded_for="49.120.2.34" id="01914b60-1d8d-75c0-9fce-e194b44c931e" remote="www.google.com:80"}: wstunnel::tunnel::transport::io: Closing local <= remote tunnel 2024-08-13T10:54:29.716964Z INFO tunnel{peer="172.17.0.1:19400" forwarded_for="49.120.2.34" id="01914b60-1d8d-75c0-9fce-e194b44c931e" remote="www.google.com:80"}: wstunnel::tunnel::transport::io: Closing local => remote tunnel



## Desktop (please complete the following information):
 - OS: Windows client and Ubuntu docker
 - Version 9.8.0 RC and 9.7.4

**Additional context**

erebe commented 3 months ago

You can try with --log-lvl=TRACE to get more info, and/or with http2 instead of websocket.

But it seems something is cutting the connection in the middle. Do you try to bypass someting specifically ?

yuan-thomas commented 3 months ago

TRACE seemed to be similar. But I will collect it anyway.

I start suspecting it is the reverse proxy in between. As I own the reverse proxy, there is not known restriction, but might be a technical issue. According to your document, I don't think I can use http/http2 when behind reverse proxy? Is there a good way to capture the traffic between client and server?

erebe commented 3 months ago

You may need to configure your reverse proxy for websocket. Some need spécial handling to not consider the response of the upgrade request as the final message.

yuan-thomas commented 3 months ago

Ok, I have more details about this now.

The handshake and upgrade were processed successfully. The connection can be active for up to 30 seconds until, the client or the server sends out the very first byte in Websocket, or a ping is sent in the channel. Then immediately I get this error: 2024-08-24T00:18:31.556303Z ERROR tunnel{id="019181bf-685c-77a1-a9f7-3022650ec6b2" remote="www.targetserver.com:80"}: wstunnel::tunnel::transport::io: error while reading from tunnel rx websocket close

I suspect that happens is something to with traffic encoding of this particular reverse proxy server that I use. It probably tries to 'do something' or interprete the payload but couldn't understand.

That's my speculation but if it rings any bell...

yuan-thomas commented 1 month ago

Tested with another reverse proxy. Really seems to be a compatibility issue. Closing.

erebe / wstunnel