"failed to do websocket handshake" after server restart, client doesn't auto-reconnect

[jemand771]

Describe the bug After a tunnel server restart, client(s) don't reconnect automatically.

To Reproduce Steps to reproduce the behavior:

1. start wstunnel server wstunnel server --restrict-to 0.0.0.0:52100 wss://0.0.0.0:8022 -r my-token
2. start wstunnel client wstunnel client -R tcp://0.0.0.0:52100:localhost:22 -P my-token --log-lvl DEBUG wss://tunnel.example.org:8022
3. restart server (sigterm process, restart manually)
4. observe client log

Expected behavior Given that the client realized something is wrong, I'd expect an automatic reconnect after some time. Also, the error message looks weird/ungaught.

Screenshots Client log (debug) Note that I've replaced the server hostname and ip address with dummy values. I'm going to be experimenting with (briefly) unprotected ssh tunnels and don't want any bot scooping up the ip 👀

[dumb-init] Unable to detach from controlling tty (errno=25 Inappropriate ioctl for device).
[dumb-init] Child spawned with PID 7.
[dumb-init] Unable to attach to controlling tty (errno=25 Inappropriate ioctl for device).
[dumb-init] setsid complete.
2024-02-21T16:48:31.780986Z  INFO tunnel{id="018dcc91-9e24-7d13-a908-6ee87c7aba92" remote="0.0.0.0:52100"}: wstunnel::tcp: Opening TCP connection to tunnel.example.org:8022
2024-02-21T16:48:31.781177Z DEBUG tunnel{id="018dcc91-9e24-7d13-a908-6ee87c7aba92" remote="0.0.0.0:52100"}: hickory_proto::xfer::dns_handle: querying: tunnel.example.org A
2024-02-21T16:48:31.781246Z DEBUG tunnel{id="018dcc91-9e24-7d13-a908-6ee87c7aba92" remote="0.0.0.0:52100"}: hickory_resolver::name_server::name_server_pool: sending request: [Query { name: Name("tunnel.example.org"), query_type: A, query_class: IN }]
2024-02-21T16:48:31.781298Z DEBUG tunnel{id="018dcc91-9e24-7d13-a908-6ee87c7aba92" remote="0.0.0.0:52100"}: hickory_resolver::name_server::name_server: reconnecting: NameServerConfig { socket_addr: 192.168.0.210:53, protocol: Udp, tls_dns_name: None, trust_negative_responses: false, tls_config: None, bind_addr: None }
2024-02-21T16:48:31.781352Z DEBUG tunnel{id="018dcc91-9e24-7d13-a908-6ee87c7aba92" remote="0.0.0.0:52100"}: hickory_proto::xfer: enqueueing message:QUERY:[Query { name: Name("tunnel.example.org"), query_type: A, query_class: IN }]
2024-02-21T16:48:31.781418Z DEBUG tunnel{id="018dcc91-9e24-7d13-a908-6ee87c7aba92" remote="0.0.0.0:52100"}: hickory_proto::udp::udp_client_stream: final message: ; header 26110:QUERY:RD:NoError:QUERY:0/0/0
; query
;; tunnel.example.org. IN A

2024-02-21T16:48:31.781523Z DEBUG tunnel{id="018dcc91-9e24-7d13-a908-6ee87c7aba92" remote="0.0.0.0:52100"}: hickory_proto::udp::udp_stream: created socket successfully
2024-02-21T16:48:31.782425Z DEBUG hickory_proto::udp::udp_client_stream: received message id: 26110
2024-02-21T16:48:31.782466Z DEBUG hickory_resolver::error: Response:; header 26110:RESPONSE:RD,RA:NoError:QUERY:1/0/0
; query
;; tunnel.example.org. IN A
; answers 1
tunnel.example.org. 1864 IN A 1.2.3.4
; nameservers 0
; additionals 0

2024-02-21T16:48:31.782487Z DEBUG hickory_resolver::error: Response:; header 26110:RESPONSE:RD,RA:NoError:QUERY:1/0/0
; query
;; tunnel.example.org. IN A
; answers 1
tunnel.example.org. 1864 IN A 1.2.3.4
; nameservers 0
; additionals 0

2024-02-21T16:48:31.782515Z DEBUG wstunnel::tcp: Connecting to 1.2.3.4:8022
2024-02-21T16:48:31.835020Z  INFO wstunnel::tls: Doing TLS handshake using sni DnsName("tunnel.example.org") with the server tunnel.example.org:8022
2024-02-21T16:48:31.835168Z DEBUG rustls::client::hs: No cached session for DnsName("tunnel.example.org")
2024-02-21T16:48:31.835567Z DEBUG rustls::client::hs: Not resuming any session
2024-02-21T16:48:31.885897Z DEBUG rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384
2024-02-21T16:48:31.886015Z DEBUG rustls::client::tls13: Not resuming
2024-02-21T16:48:31.886544Z DEBUG rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([ProtocolName(687474702f312e31)]), ServerNameAck]
2024-02-21T16:48:31.886612Z DEBUG rustls::client::hs: ALPN protocol is Some(b"http/1.1")
2024-02-21T16:48:31.887482Z DEBUG tunnel{id="018dcc91-9e24-7d13-a908-6ee87c7aba92" remote="0.0.0.0:52100"}: wstunnel::tunnel::transport::websocket: with HTTP upgrade request Request { method: GET, uri: /my-token/events, version: HTTP/1.1, headers: {"host": "tunnel.example.org:8022", "upgrade": "websocket", "connection": "upgrade", "sec-websocket-key": "Ho0T5fXSSHKVzZemoDWeXg==", "sec-websocket-version": "13", "sec-websocket-protocol": "v1, authorization.bearer.eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJpZCI6IjAxOGRjYzkxLTllMjQtN2QxMy1hOTA4LTZlZTg3YzdhYmE5MiIsInAiOiJSZXZlcnNlVGNwIiwiciI6IjAuMC4wLjAiLCJycCI6NTIxMDB9.Zvo73EQygtsZdFtdJo7DAVuyXZA10dwtgS_x-5TxU5s"}, body: Empty }
2024-02-21T16:48:37.806771Z DEBUG rustls::common_state: Sending warning alert CloseNotify
2024-02-21T16:48:37.807253Z ERROR wstunnel: failed to do websocket handshake with the server wss://tunnel.example.org:8022

Caused by:
    0: connection error
    1: unexpected end of file
2024-02-21T16:48:37.807335Z DEBUG hickory_proto::xfer::dns_exchange: io_stream is done, shutting down

note: I've removed the desktop information block. my machine is not relevant to this issue.

Additional context I'm using the docker images, tag v9.2.2. server is amd64, client is arm64. just to make sure: the connection works perfectly fine as long as I start the server first. the network connection between the two devices is not restricted in any way (company firewall, government proxy, whatever)

related issues (but with different errors):

• https://github.com/erebe/wstunnel/issues/163 but the error is different
• https://github.com/erebe/wstunnel/issues/205

[erebe]

Hello,

I will look at it next week or the week after, when i will have a bit more free time on hand.

[erebe]

Should be fixed in pre-release 9.2.3, would you mind letting me know if that's ok ? https://github.com/erebe/wstunnel/releases/tag/v9.2.3

[jemand771]

I haven't tried any more elaborate scenarios (e.g. reconnect after long downtime), but just from a quick test it looks like that works: restart the server, try to use the reverse tunnel -> comes back after a couple of seconds. thanks! :D