search

erebe / wstunnel

Tunnel all your traffic over Websocket or HTTP2 - Bypass firewalls/DPI - Static binary available
BSD 3-Clause "New" or "Revised" License
4.36k stars 372 forks source link

--connection-min-idle causes frequent WS reconnects and distupts tunnels #358

Closed pvgoran closed 1 month ago

pvgoran commented 2 months ago

Describe the bug

When I use --connection-min-idle, wstunnel client tries to establish N connections each minute, which are rejected by wstunnel server in 10 seconds with Error while upgrading cnx: hyper::Error(HeaderTimeout). Moreover, a SOCKS tunnel I'm trying to use apparently only works if I'm connecting during this 10-seconds window.

Without --connection-min-idle my setup works fine.

To Reproduce

Set up a SOCKS tunnel via WSS connection without reverse proxy, specify --connection-min-idle 1 for wstunnel client.

Monitor server logs.

Run curl --proxy socks5://localhost:xxxx https://ixbt.com/ inside the 10-seconds window between wstunnel::tunnel::server::server: Doing TLS handshake and wstunnel::tunnel::server::server: Error while upgrading cnx: hyper::Error(HeaderTimeout):

<html>
<head><title>301 Moved Permanently</title></head>
<body>
<center><h1>301 Moved Permanently</h1></center>
<hr><center>nginx</center>
</body>
</html>

Run curl --proxy socks5://localhost:xxxx https://ixbt.com/ outside the 10-seconds window:

curl: (35) OpenSSL SSL_connect: SSL_ERROR_SYSCALL in connection to ixbt.com:443

Expected behavior

Connections via tunnel work most of the time, idle WebSocket connections are fully opened and don't reconnect that often.

Your wstunnel setup

Paste your logs of wstunnel, started with --log-lvl=DEBUG, and with the command line used

(Host names and client-server IP addresses were redacted.)

wstunnel  | 2024-09-21T07:34:33.143993Z  INFO wstunnel::protocols::tcp::server: Opening TCP connection to wstunnel.host:443    
wstunnel  | 2024-09-21T07:34:33.144073Z DEBUG hickory_proto::xfer::dns_handle: querying: wstunnel.host A
wstunnel  | 2024-09-21T07:34:33.144146Z DEBUG hickory_resolver::name_server::name_server_pool: sending request: [Query { name: Name("wstunnel.host"), query_type: A, query_class: IN }]
wstunnel  | 2024-09-21T07:34:33.144282Z DEBUG hickory_resolver::name_server::name_server: reconnecting: NameServerConfig { socket_addr: 127.0.0.11:53, protocol: Udp, tls_dns_name: None, trust_negative_responses: false, tls_config: None, bind_addr: None }
wstunnel  | 2024-09-21T07:34:33.44386Z DEBUG hickory_proto::xfer: enqueueing message:QUERY:[Query { name: Name("wstunnel.host"), query_type: A, query_class: IN }]
wstunnel  | 2024-09-21T07:34:33.144652Z DEBUG hickory_proto::xfer::dns_handle: querying: wstunnel.host AAAA
wstunnel  | 2024-09-21T07:34:33.144683Z DEBUG hickory_proto::udp::udp_client_stream: final message: ; header 33287:QUERY:RD:NoError:QUERY:0/0/0
wstunnel  | ; query
wstunnel  | ;; wstunnel.host. IN A
wstunnel  | 
wstunnel  | 
wstunnel  | 2024-09-21T07:34:33.144940Z DEBUG hickory_resolver::name_server::name_server_pool: sending request: [Query { name: Name("wstunnel.host"), query_type: AAAA, query_class: IN }]
wstunnel  | 2024-09-21T07:34:33.144958Z DEBUG hickory_resolver::name_server::name_server: existing connection: NameServerConfig { socket_addr: 127.0.0.11:53, protocol: Udp, tls_dns_name: None, trust_negative_responses: false, tls_config: None, bind_addr: None }
wstunnel  | 2024-09-21T07:34:33.144967Z DEBUG hickory_proto::xfer: enqueueing message:QUERY:[Query { name: Name("wstunnel.host"), query_type: AAAA, query_class: IN }]
wstunnel  | 2024-09-21T07:34:33.145048Z DEBUG hickory_proto::udp::udp_stream: created socket successfully
wstunnel  | 2024-09-21T07:34:33.145125Z DEBUG hickory_proto::udp::udp_client_stream: final message: ; header 6649:QUERY:RD:NoError:QUERY:0/0/0
wstunnel  | ; query
wstunnel  | ;; wstunnel.host. IN AAAA
wstunnel  | 
wstunnel  | 2024-09-21T07:34:33.145244Z DEBUG hickory_proto::udp::udp_stream: created socket successfully
wstunnel  | 
wstunnel  | 2024-09-21T07:34:33.311043Z DEBUG hickory_proto::udp::udp_client_stream: received message id: 33287
wstunnel  | 2024-09-21T07:34:33.311082Z DEBUG hickory_resolver::error: Response:; header 33287:RESPONSE:RD,RA:NoError:QUERY:1/0/0
wstunnel  | ; query
wstunnel  | ;; wstunnel.host. IN A
wstunnel  | ; answers 1
wstunnel  | wstunnel.host. 3600 IN A 4.3.2.1
wstunnel  | ; nameservers 0
wstunnel  | ; additionals 0
wstunnel  | 
wstunnel  | 2024-09-21T07:34:33.311104Z DEBUG hickory_resolver::error: Response:; header 33287:RESPONSE:RD,RA:NoError:QUERY:1/0/0
wstunnel  | ; query
wstunnel  | ;; wstunnel.host. IN A
wstunnel  | ; answers 1
wstunnel  | wstunnel.host. 3600 IN A 4.3.2.1
wstunnel  | ; nameservers 0
wstunnel  | ; additionals 0
wstunnel  | 
wstunnel  | 
wstunnel  | 2024-09-21T07:34:33.334909Z DEBUG hickory_proto::udp::udp_client_stream: received message id: 6649
wstunnel  | 2024-09-21T07:34:33.334953Z DEBUG hickory_resolver::error: Response:; header 6649:RESPONSE:RD,RA:NoError:QUERY:0/1/0
wstunnel  | ; query
wstunnel  | ;; wstunnel.host. IN AAAA
wstunnel  | ; answers 0
wstunnel  | ; nameservers 1
wstunnel  | host. 1800 IN SOA dns1. dns2. 2409200001 86400 7200 2419200 3600
wstunnel  | ; additionals 0
wstunnel  | 
wstunnel  | 2024-09-21T07:34:33.334989Z DEBUG hickory_resolver::lookup_ip: one of ipv4 or ipv6 lookup failed in ipv4_and_ipv6 strategy: no record found for Query { name: Name("wstunnel.host."), query_type: AAAA, query_class: IN }
wstunnel  | 
wstunnel  | 2024-09-21T07:34:33.335083Z DEBUG wstunnel::protocols::tcp::server: Connecting to 4.3.2.1:443
wstunnel  | 2024-09-21T07:34:33.396127Z DEBUG wstunnel::protocols::tcp::server: Connected to tcp endpoint 4.3.2.1:443, aborted all other connection attempts
wstunnel  | 2024-09-21T07:34:33.396145Z  INFO wstunnel::protocols::tls::server: Doing TLS handshake using SNI DnsName("wstunnel.host") with the server wstunnel.host:443
wstunnel  | 2024-09-21T07:34:33.396175Z DEBUG rustls::client::hs: No cached session for DnsName("wstunnel.host")    
wstunnel  | 2024-09-21T07:34:33.396338Z DEBUG rustls::client::hs: Not resuming any session    
wstunnel  | 2024-09-21T07:34:33.460337Z DEBUG rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384    
wstunnel  | 2024-09-21T07:34:33.460364Z DEBUG rustls::client::tls13: Not resuming    
wstunnel  | 2024-09-21T07:34:33.460512Z DEBUG rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([ProtocolName(687474702f312e31)]), ServerNameAck]    
wstunnel  | 2024-09-21T07:34:33.460532Z DEBUG rustls::client::hs: ALPN protocol is Some(b"http/1.1")    
wstunnel  | 2024-09-21T07:34:33.463911Z  INFO wstunnel::protocols::socks5::tcp_server: Starting SOCKS5 server listening cnx on 0.0.0.0:1180 with credentials None
wstunnel  | 2024-09-21T07:34:53.033654Z DEBUG fast_socks5::server: incoming connection from peer 172.28.0.1:52870 @ 172.28.0.2:1180    
wstunnel  | 2024-09-21T07:34:53.033946Z DEBUG fast_socks5::server: Handshake headers: [version: 5, methods len: 1]    
wstunnel  | 2024-09-21T07:34:53.033962Z DEBUG fast_socks5::server: methods supported sent by the client: [0]    
wstunnel  | 2024-09-21T07:34:53.033968Z DEBUG fast_socks5::server: Reply with method AuthenticationMethod::None (0)    
wstunnel  | 2024-09-21T07:34:53.233490Z DEBUG fast_socks5::server: Request: [version: 5, command: 1, rev: 0, address_type: 1]    
wstunnel  | 2024-09-21T07:34:53.233510Z DEBUG fast_socks5::util::target_addr: Address type `IPv4`    
wstunnel  | 2024-09-21T07:34:53.233522Z DEBUG fast_socks5::server: Request target is 91.208.42.67:443    
wstunnel  | 2024-09-21T07:34:53.233532Z DEBUG fast_socks5::server: Domain won't be resolved because `dns_resolve`'s config has been turned off.    
wstunnel  | 2024-09-21T07:34:53.233742Z DEBUG tunnel{id="01921381-4a31-74c2-b4c5-dff259dbf979" remote="91.208.42.67:443"}: wstunnel::tunnel::transport::websocket: with HTTP upgrade request Request { method: GET, uri: /v1/events, version: HTTP/1.1, headers: {"host": "wstunnel.host:443", "upgrade": "websocket", "connection": "upgrade", "sec-websocket-key": "t/xZ4XqUH+1dAgnmet6YRw==", "sec-websocket-version": "13", "sec-websocket-protocol": "v1, authorization.bearer.eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJpZCI6IjAxOTIxMzgxLTRhMzEtNzRjMi1iNGM1LWRmZjI1OWRiZjk3OSIsInAiOnsiVGNwIjp7InByb3h5X3Byb3RvY29sIjpmYWxzZX19LCJyIjoiOTEuMjA4LjQyLjY3IiwicnAiOjQ0M30.vVgsHlhaa5baDeiXOmI-lcFA7apyDtGcbhxuUh4nnc8"}, body: Empty }    
wstunnel  | 2024-09-21T07:34:53.233868Z  INFO wstunnel::protocols::tcp::server: Opening TCP connection to wstunnel.host:443    
wstunnel  | 2024-09-21T07:34:53.233936Z DEBUG hickory_resolver::lookup_ip: one of ipv4 or ipv6 lookup failed in ipv4_and_ipv6 strategy: no record found for Query { name: Name("wstunnel.host."), query_type: AAAA, query_class: IN }
wstunnel  | 2024-09-21T07:34:53.234000Z DEBUG wstunnel::protocols::tcp::server: Connecting to 4.3.2.1:443
wstunnel  | 2024-09-21T07:34:53.234003Z ERROR tunnel{id="01921381-4a31-74c2-b4c5-dff259dbf979" remote="91.208.42.67:443"}: wstunnel::tunnel::client::client: failed to do websocket handshake with the server wss://wstunnel.host:443
wstunnel  | 
wstunnel  | Caused by:
wstunnel  |     0: operation was canceled
wstunnel  |     1: connection error
wstunnel  |     2: peer closed connection without sending TLS close_notify: https://docs.rs/rustls/latest/rustls/manual/_03_howto/index.html#unexpected-eof
wstunnel  | 
wstunnel  | 2024-09-21T07:34:53.291014Z DEBUG wstunnel::protocols::tcp::server: Connected to tcp endpoint 4.3.2.1:443, aborted all other connection attempts
wstunnel  | 2024-09-21T07:34:53.291039Z  INFO wstunnel::protocols::tls::server: Doing TLS handshake using SNI DnsName("wstunnel.host") with the server wstunnel.host:443
wstunnel  | 2024-09-21T07:34:53.291096Z DEBUG rustls::client::hs: Resuming session    
wstunnel  | 2024-09-21T07:34:53.344714Z DEBUG rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384    
wstunnel  | 2024-09-21T07:34:53.344737Z DEBUG rustls::client::tls13: Resuming using PSK    
wstunnel  | 2024-09-21T07:34:53.344851Z DEBUG rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([ProtocolName(687474702f312e31)])]    
wstunnel  | 2024-09-21T07:34:53.344867Z DEBUG rustls::client::hs: ALPN protocol is Some(b"http/1.1")    
wstunnel  | 2024-09-21T07:35:33.145361Z  INFO wstunnel::protocols::tcp::server: Opening TCP connection to wstunnel.host:443    
wstunnel  | 2024-09-21T07:35:33.145402Z DEBUG hickory_resolver::lookup_ip: one of ipv4 or ipv6 lookup failed in ipv4_and_ipv6 strategy: no record found for Query { name: Name("wstunnel.host."), query_type: AAAA, query_class: IN }
wstunnel  | 2024-09-21T07:35:33.145470Z DEBUG wstunnel::protocols::tcp::server: Connecting to 4.3.2.1:443
wstunnel  | 2024-09-21T07:35:33.204260Z DEBUG wstunnel::protocols::tcp::server: Connected to tcp endpoint 4.3.2.1:443, aborted all other connection attempts
wstunnel  | 2024-09-21T07:35:33.204284Z  INFO wstunnel::protocols::tls::server: Doing TLS handshake using SNI DnsName("wstunnel.host") with the server wstunnel.host:443
wstunnel  | 2024-09-21T07:35:33.204335Z DEBUG rustls::client::hs: Resuming session    
wstunnel  | 2024-09-21T07:35:33.265569Z DEBUG rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384    
wstunnel  | 2024-09-21T07:35:33.265591Z DEBUG rustls::client::tls13: Resuming using PSK    
wstunnel  | 2024-09-21T07:35:33.265686Z DEBUG rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([ProtocolName(687474702f312e31)])]    
wstunnel  | 2024-09-21T07:35:33.265697Z DEBUG rustls::client::hs: ALPN protocol is Some(b"http/1.1")    
wstunnel  | 2024-09-21T07:36:33.145431Z  INFO wstunnel::protocols::tcp::server: Opening TCP connection to wstunnel.host:443    
wstunnel  | 2024-09-21T07:36:33.145497Z DEBUG hickory_resolver::lookup_ip: one of ipv4 or ipv6 lookup failed in ipv4_and_ipv6 strategy: no record found for Query { name: Name("wstunnel.host."), query_type: AAAA, query_class: IN }
wstunnel  | 2024-09-21T07:36:33.145577Z DEBUG wstunnel::protocols::tcp::server: Connecting to 4.3.2.1:443
wstunnel  | 2024-09-21T07:36:33.202992Z DEBUG wstunnel::protocols::tcp::server: Connected to tcp endpoint 4.3.2.1:443, aborted all other connection attempts
wstunnel  | 2024-09-21T07:36:33.203018Z  INFO wstunnel::protocols::tls::server: Doing TLS handshake using SNI DnsName("wstunnel.host") with the server wstunnel.host:443
wstunnel  | 2024-09-21T07:36:33.203071Z DEBUG rustls::client::hs: Resuming session    
wstunnel  | 2024-09-21T07:36:33.262736Z DEBUG rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384    
wstunnel  | 2024-09-21T07:36:33.262757Z DEBUG rustls::client::tls13: Resuming using PSK    
wstunnel  | 2024-09-21T07:36:33.262855Z DEBUG rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([ProtocolName(687474702f312e31)])]    
wstunnel  | 2024-09-21T07:36:33.262867Z DEBUG rustls::client::hs: ALPN protocol is Some(b"http/1.1")    
wstunnel  | 2024-09-21T07:36:36.557849Z DEBUG fast_socks5::server: incoming connection from peer 172.28.0.1:58774 @ 172.28.0.2:1180    
wstunnel  | 2024-09-21T07:36:36.557913Z DEBUG fast_socks5::server: Handshake headers: [version: 5, methods len: 1]    
wstunnel  | 2024-09-21T07:36:36.557923Z DEBUG fast_socks5::server: methods supported sent by the client: [0]    
wstunnel  | 2024-09-21T07:36:36.557929Z DEBUG fast_socks5::server: Reply with method AuthenticationMethod::None (0)    
wstunnel  | 2024-09-21T07:36:36.758885Z DEBUG fast_socks5::server: Request: [version: 5, command: 1, rev: 0, address_type: 1]    
wstunnel  | 2024-09-21T07:36:36.758901Z DEBUG fast_socks5::util::target_addr: Address type `IPv4`    
wstunnel  | 2024-09-21T07:36:36.758911Z DEBUG fast_socks5::server: Request target is 91.208.42.67:443    
wstunnel  | 2024-09-21T07:36:36.758917Z DEBUG fast_socks5::server: Domain won't be resolved because `dns_resolve`'s config has been turned off.    
wstunnel  | 2024-09-21T07:36:36.759091Z DEBUG tunnel{id="01921382-de96-71f2-9137-1c22ce43311b" remote="91.208.42.67:443"}: wstunnel::tunnel::transport::websocket: with HTTP upgrade request Request { method: GET, uri: /v1/events, version: HTTP/1.1, headers: {"host": "wstunnel.host:443", "upgrade": "websocket", "connection": "upgrade", "sec-websocket-key": "v5nULGp6/pgTpnVTPQUADA==", "sec-websocket-version": "13", "sec-websocket-protocol": "v1, authorization.bearer.eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJpZCI6IjAxOTIxMzgyLWRlOTYtNzFmMi05MTM3LTFjMjJjZTQzMzExYiIsInAiOnsiVGNwIjp7InByb3h5X3Byb3RvY29sIjpmYWxzZX19LCJyIjoiOTEuMjA4LjQyLjY3IiwicnAiOjQ0M30.bjUQElxys6K9o9vcgodrC09yD9o_2x9MxcyFcwij86E"}, body: Empty }    
wstunnel  | 2024-09-21T07:36:36.759297Z  INFO wstunnel::protocols::tcp::server: Opening TCP connection to wstunnel.host:443    
wstunnel  | 2024-09-21T07:36:36.759343Z DEBUG hickory_resolver::lookup_ip: one of ipv4 or ipv6 lookup failed in ipv4_and_ipv6 strategy: no record found for Query { name: Name("wstunnel.host."), query_type: AAAA, query_class: IN }
wstunnel  | 2024-09-21T07:36:36.759403Z DEBUG wstunnel::protocols::tcp::server: Connecting to 4.3.2.1:443
wstunnel  | 2024-09-21T07:36:36.817409Z DEBUG wstunnel::protocols::tcp::server: Connected to tcp endpoint 4.3.2.1:443, aborted all other connection attempts
wstunnel  | 2024-09-21T07:36:36.817435Z  INFO wstunnel::protocols::tls::server: Doing TLS handshake using SNI DnsName("wstunnel.host") with the server wstunnel.host:443
wstunnel  | 2024-09-21T07:36:36.817498Z DEBUG rustls::client::hs: Resuming session    
wstunnel  | 2024-09-21T07:36:36.836805Z DEBUG tunnel{id="01921382-de96-71f2-9137-1c22ce43311b" remote="91.208.42.67:443"}: wstunnel::tunnel::client::client: Server response: Parts { status: 101, version: HTTP/1.1, headers: {"connection": "upgrade", "upgrade": "websocket", "sec-websocket-accept": "BFTs946ge4VfZy02YMho0kAHRQI=", "sec-websocket-protocol": "v1", "date": "Sat, 21 Sep 2024 07:36:36 GMT"} }    
wstunnel  | 2024-09-21T07:36:36.892905Z DEBUG rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384    
wstunnel  | 2024-09-21T07:36:36.892933Z DEBUG rustls::client::tls13: Resuming using PSK    
wstunnel  | 2024-09-21T07:36:36.893089Z DEBUG rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([ProtocolName(687474702f312e31)])]    
wstunnel  | 2024-09-21T07:36:36.893102Z DEBUG rustls::client::hs: ALPN protocol is Some(b"http/1.1")    
wstunnel  | 2024-09-21T07:36:37.065019Z  INFO tunnel{id="01921382-de96-71f2-9137-1c22ce43311b" remote="91.208.42.67:443"}: wstunnel::tunnel::transport::io: Closing local => remote tunnel
wstunnel  | 2024-09-21T07:36:37.065132Z  INFO tunnel{id="01921382-de96-71f2-9137-1c22ce43311b" remote="91.208.42.67:443"}: wstunnel::tunnel::transport::io: Closing local <= remote tunnel
wstunnel  | 2024-09-21T07:37:33.145785Z  INFO wstunnel::protocols::tcp::server: Opening TCP connection to wstunnel.host:443    
wstunnel  | 2024-09-21T07:37:33.145840Z DEBUG hickory_resolver::lookup_ip: one of ipv4 or ipv6 lookup failed in ipv4_and_ipv6 strategy: no record found for Query { name: Name("wstunnel.host."), query_type: AAAA, query_class: IN }
wstunnel  | 2024-09-21T07:37:33.145913Z DEBUG wstunnel::protocols::tcp::server: Connecting to 4.3.2.1:443
wstunnel  | 2024-09-21T07:37:33.201395Z DEBUG wstunnel::protocols::tcp::server: Connected to tcp endpoint 4.3.2.1:443, aborted all other connection attempts
wstunnel  | 2024-09-21T07:37:33.201415Z  INFO wstunnel::protocols::tls::server: Doing TLS handshake using SNI DnsName("wstunnel.host") with the server wstunnel.host:443
wstunnel  | 2024-09-21T07:37:33.201451Z DEBUG rustls::client::hs: Resuming session    
wstunnel  | 2024-09-21T07:37:33.264615Z DEBUG rustls::client::hs: Using ciphersuite TLS13_AES_256_GCM_SHA384    
wstunnel  | 2024-09-21T07:37:33.264638Z DEBUG rustls::client::tls13: Resuming using PSK    
wstunnel  | 2024-09-21T07:37:33.264736Z DEBUG rustls::client::tls13: TLS1.3 encrypted extensions: [Protocols([ProtocolName(687474702f312e31)])]    
wstunnel  | 2024-09-21T07:37:33.264747Z DEBUG rustls::client::hs: ALPN protocol is Some(b"http/1.1") 
2024-09-21T07:34:11.072472Z  INFO wstunnel::protocols::tls::server: Loading tls certificate from "/var/lib/acme/wstunnel.host/fullchain.pem"
2024-09-21T07:34:11.082791Z  INFO wstunnel::protocols::tls::server: Loading tls private key from "/var/lib/acme/wstunnel.host/key.pem"
2024-09-21T07:34:11.110389Z  INFO wstunnel: Starting wstunnel server v10.1.1 with config WsServerConfig { socket_so_mark: None, bind: 0.0.0.0:443, websocket_ping_frequency: Some(30s), timeout_connect: 10s, websocket_mask_frame: false, restriction_config: None, tls: true, mTLS: false }
2024-09-21T07:34:11.110501Z DEBUG wstunnel: Restriction rules: RestrictionsRules {
    restrictions: [
        RestrictionConfig {
            name: "Allow All",
            match: [
                Any,
            ],
            allow: [
                Tunnel(
                    AllowTunnelConfig {
                        protocol: [],
                        port: [],
                        host: Regex(
                            "^.*$",
                        ),
                        cidr: [
                            0.0.0.0/0,
                            ::/0,
                        ],
                    },
                ),
                ReverseTunnel(
                    AllowReverseTunnelConfig {
                        protocol: [],
                        port: [],
                        port_mapping: {},
                        cidr: [
                            0.0.0.0/0,
                            ::/0,
                        ],
                    },
                ),
            ],
        },
    ],
}
2024-09-21T07:34:11.116706Z  INFO wstunnel::tunnel::server::server: Starting wstunnel server listening on 0.0.0.0:443
2024-09-21T07:34:11.141053Z  INFO wstunnel::tunnel::tls_reloader: Starting to watch tls certificates and private key for changes to reload them
2024-09-21T07:34:12.133599Z  INFO wstunnel::protocols::tls::server: Loading tls certificate from "/var/lib/acme/wstunnel.host/fullchain.pem"
2024-09-21T07:34:12.133760Z  INFO wstunnel::protocols::tls::server: Loading tls private key from "/var/lib/acme/wstunnel.host/key.pem"
2024-09-21T07:34:33.423610Z  INFO wstunnel::tunnel::server::server: Accepting connection
2024-09-21T07:34:33.425086Z  INFO tunnel{peer="1.2.3.4:34496"}: wstunnel::tunnel::server::server: Doing TLS handshake
2024-09-21T07:34:33.426165Z DEBUG tunnel{peer="1.2.3.4:34496"}: rustls::server::hs: decided upon suite TLS13_AES_256_GCM_SHA384
2024-09-21T07:34:33.427106Z DEBUG tunnel{peer="1.2.3.4:34496"}: rustls::server::hs: Chosen ALPN protocol [104, 116, 116, 112, 47, 49, 46, 49]
2024-09-21T07:34:43.495945Z ERROR tunnel{peer="1.2.3.4:34496"}: wstunnel::tunnel::server::server: Error while upgrading cnx: hyper::Error(HeaderTimeout)
2024-09-21T07:34:53.313674Z  INFO wstunnel::tunnel::server::server: Accepting connection
2024-09-21T07:34:53.314528Z  INFO tunnel{peer="1.2.3.4:43924"}: wstunnel::tunnel::server::server: Doing TLS handshake
2024-09-21T07:34:53.314797Z DEBUG tunnel{peer="1.2.3.4:43924"}: rustls::server::hs: decided upon suite TLS13_AES_256_GCM_SHA384
2024-09-21T07:34:53.315184Z DEBUG tunnel{peer="1.2.3.4:43924"}: rustls::server::hs: Chosen ALPN protocol [104, 116, 116, 112, 47, 49, 46, 49]
2024-09-21T07:35:03.370363Z ERROR tunnel{peer="1.2.3.4:43924"}: wstunnel::tunnel::server::server: Error while upgrading cnx: hyper::Error(HeaderTimeout)
2024-09-21T07:35:33.231094Z  INFO wstunnel::tunnel::server::server: Accepting connection
2024-09-21T07:35:33.231912Z  INFO tunnel{peer="1.2.3.4:45790"}: wstunnel::tunnel::server::server: Doing TLS handshake
2024-09-21T07:35:33.232099Z DEBUG tunnel{peer="1.2.3.4:45790"}: rustls::server::hs: decided upon suite TLS13_AES_256_GCM_SHA384
2024-09-21T07:35:33.232758Z DEBUG tunnel{peer="1.2.3.4:45790"}: rustls::server::hs: Chosen ALPN protocol [104, 116, 116, 112, 47, 49, 46, 49]
2024-09-21T07:35:43.293282Z ERROR tunnel{peer="1.2.3.4:45790"}: wstunnel::tunnel::server::server: Error while upgrading cnx: hyper::Error(HeaderTimeout)
2024-09-21T07:36:33.230366Z  INFO wstunnel::tunnel::server::server: Accepting connection
2024-09-21T07:36:33.230941Z  INFO tunnel{peer="1.2.3.4:49260"}: wstunnel::tunnel::server::server: Doing TLS handshake
2024-09-21T07:36:33.231868Z DEBUG tunnel{peer="1.2.3.4:49260"}: rustls::server::hs: decided upon suite TLS13_AES_256_GCM_SHA384
2024-09-21T07:36:33.232513Z DEBUG tunnel{peer="1.2.3.4:49260"}: rustls::server::hs: Chosen ALPN protocol [104, 116, 116, 112, 47, 49, 46, 49]
2024-09-21T07:36:36.789482Z  INFO tunnel{peer="1.2.3.4:49260" id="01921382-de96-71f2-9137-1c22ce43311b" remote="91.208.42.67:443"}: wstunnel::tunnel::server::server: Tunnel accepted due to matched restriction: Allow All
2024-09-21T07:36:36.789550Z  INFO tunnel{peer="1.2.3.4:49260" id="01921382-de96-71f2-9137-1c22ce43311b" remote="91.208.42.67:443"}: wstunnel::protocols::tcp::server: Opening TCP connection to 91.208.42.67:443
2024-09-21T07:36:36.789648Z DEBUG wstunnel::protocols::tcp::server: Connecting to 91.208.42.67:443
2024-09-21T07:36:36.803695Z DEBUG tunnel{peer="1.2.3.4:49260" id="01921382-de96-71f2-9137-1c22ce43311b" remote="91.208.42.67:443"}: wstunnel::protocols::tcp::server: Connected to tcp endpoint 91.208.42.67:443, aborted all other connection attempts
2024-09-21T07:36:36.803790Z  INFO tunnel{peer="1.2.3.4:49260" id="01921382-de96-71f2-9137-1c22ce43311b" remote="91.208.42.67:443"}: wstunnel::tunnel::server::server: connected to Tcp { proxy_protocol: false } 91.208.42.67:443
2024-09-21T07:36:36.859921Z  INFO wstunnel::tunnel::server::server: Accepting connection
2024-09-21T07:36:36.860248Z  INFO tunnel{peer="1.2.3.4:56120"}: wstunnel::tunnel::server::server: Doing TLS handshake
2024-09-21T07:36:36.860348Z DEBUG tunnel{peer="1.2.3.4:56120"}: rustls::server::hs: decided upon suite TLS13_AES_256_GCM_SHA384
2024-09-21T07:36:36.860793Z DEBUG tunnel{peer="1.2.3.4:56120"}: rustls::server::hs: Chosen ALPN protocol [104, 116, 116, 112, 47, 49, 46, 49]
2024-09-21T07:36:37.095112Z ERROR tunnel{peer="1.2.3.4:49260" id="01921382-de96-71f2-9137-1c22ce43311b" remote="91.208.42.67:443"}: wstunnel::tunnel::transport::io: error while reading from tunnel rx websocket close
2024-09-21T07:36:37.095217Z  INFO tunnel{peer="1.2.3.4:49260" id="01921382-de96-71f2-9137-1c22ce43311b" remote="91.208.42.67:443"}: wstunnel::tunnel::transport::io: Closing local <= remote tunnel
2024-09-21T07:36:37.095462Z  INFO tunnel{peer="1.2.3.4:49260" id="01921382-de96-71f2-9137-1c22ce43311b" remote="91.208.42.67:443"}: wstunnel::tunnel::transport::io: Closing local => remote tunnel
2024-09-21T07:36:46.922353Z ERROR tunnel{peer="1.2.3.4:56120"}: wstunnel::tunnel::server::server: Error while upgrading cnx: hyper::Error(HeaderTimeout)
2024-09-21T07:37:33.227114Z  INFO wstunnel::tunnel::server::server: Accepting connection
2024-09-21T07:37:33.229285Z  INFO tunnel{peer="1.2.3.4:48898"}: wstunnel::tunnel::server::server: Doing TLS handshake
2024-09-21T07:37:33.229880Z DEBUG tunnel{peer="1.2.3.4:48898"}: rustls::server::hs: decided upon suite TLS13_AES_256_GCM_SHA384
2024-09-21T07:37:33.230512Z DEBUG tunnel{peer="1.2.3.4:48898"}: rustls::server::hs: Chosen ALPN protocol [104, 116, 116, 112, 47, 49, 46, 49]
2024-09-21T07:37:43.291193Z ERROR tunnel{peer="1.2.3.4:48898"}: wstunnel::tunnel::server::server: Error while upgrading cnx: hyper::Error(HeaderTimeout)

Desktop (please complete the following information):

erebe commented 2 months ago

Hello, Thanks for reporting the issue. I am going to increase the timeout in order to play nice with the min-idle flag in the next release.

Regarding this breaking existing tunnel, it should not happen if the tunnel is already established. Only if the connection/tunnel is in pending state waiting for something to forward.

Nonetheless I understand it can flood the logs. Going to fix it when i am back from vacation (~2weeks)

pvgoran commented 2 months ago

Regarding this breaking existing tunnel, it should not happen if the tunnel is already established. Only if the connection/tunnel is in pending state waiting for something to forward.

If an application connection is already established via the tunnel, this particular connection is maintained.

However, even if there is an established and working connection within the tunnel, another connection attempt via this tunnel (at least, in case of a SOCKS tunnel) still fails under the same conditions (when made outside of the 10-seconds window). So a SOCKS tunnel remains unusable, except for "lucky" connections which make it at the right time.

(With other kinds of tunnels the situation may be different; I didn't try them yet.)

Nonetheless I understand it can flood the logs. Going to fix it when i am back from vacation (~2weeks)

Looking forward to it!

erebe commented 1 month ago

Should be fixed in next release. You can give it a try in this pre-release https://github.com/erebe/wstunnel/releases/tag/v10.1.2-rc1

erebe commented 1 month ago

Made a proper release https://github.com/erebe/wstunnel/releases/tag/v10.1.2

Let me know if it is ok.

erebe commented 1 month ago

confirmed by another user, that it is fixed

pvgoran commented 1 month ago

I also confirm that running version 10.1.2 on the server side fixes this bug.

Idle connections are still re-created every minute (thus polluting the logs), but it's a different story.