UDP tunnel flapping

[wellsgz]

Client side experience constant control channel and data plane flapping while tunnelling UDP traffic. In the meanwhile, TCP tunnel is working without an issue.

Both server and client are deployed with official docker image.

The UDP service being tunnelling is wireguard, MTU has been adjusted to accommodate tunnelling and avoid fragmentation.

Error message on client side:

Jan 07 02:02:52.122  INFO new{service=some_service}:run: rathole::client: Control channel established
Jan 07 02:02:52.817 ERROR new{service=some_service}: rathole::client: Failed to run the control channel

Caused by:
    0: Failed to read control cmd
    1: early eof

Retry in 1s...
Jan 07 02:02:52.818 ERROR new{service=some_service}:run: rathole::client: Failed to run the data channel

Caused by:
    unexpected end of file
Jan 07 02:02:52.819 ERROR new{service=some_service}:run: rathole::client: Failed to run the data channel

Caused by:
    0: Failed to read data cmd
    1: early eof
Jan 07 02:02:54.162  INFO new{service=some_service}:run: rathole::client: Control channel established
Jan 07 02:02:54.879 ERROR new{service=some_service}: rathole::client: Failed to run the control channel

Server side configuration snap:

[server]
bind_addr = "someaddr:8080"
default_token = "sometoken"

[server.transport]
type = "noise"

[server.transport.noise]
local_private_key = "somekey"

[server.services.some_service]
type = "udp"
bind_addr = "0.0.0.0:51820"

Client side configuration snap:

[client]
remote_addr = "someaddr:8080"
default_token = "sometoken"

[client.transport]
type = "noise"

[client.transport.noise]
remote_public_key = "somekey"

[client.services.some_service]
type = "udp"
local_addr = "someip:51820"

[rapiz1]

Can you post the log of the server as well?

[rapiz1]

Can't reproduce :( Can you manage to create a minimal configuration that can reproduce the issue on your machine, instead of just taking out snippets?

[wellsgz]

Server side logs attached, let me know if you need more detail by increasing the log level

You can see the tcp tunnels (doh and xray) are stable, while wireguard channel is established and shutdown repeatedly

Jan 07 03:09:53.262  INFO rathole::server: Listening at 0.0.0.0:8080
Jan 07 03:09:53.262  INFO config_watcher{path="/app/server.toml"}: rathole::config_watcher: Start watching the config
Jan 07 03:10:03.982  INFO handle_connection{addr=someip:49395}: rathole::server: New control channel incomming from someip:49395
Jan 07 03:10:03.985  INFO handle_connection{addr=someip:49396}: rathole::server: New control channel incomming from someip:49396
Jan 07 03:10:03.985  INFO handle_connection{addr=someip:49397}: rathole::server: New control channel incomming from someip:49397
Jan 07 03:10:04.050  INFO handle_connection{addr=someip:49395}: rathole::server: Control channel established service=somenode_doh
Jan 07 03:10:04.050  INFO handle_connection{addr=someip:49395}:new{service=somenode_doh}:run_tcp_connection_pool: rathole::server: Listening at 0.0.0.0:853
Jan 07 03:10:04.052  INFO handle_connection{addr=someip:49397}: rathole::server: Control channel established service=somenode_wireguard
Jan 07 03:10:04.052  INFO handle_connection{addr=someip:49397}:new{service=somenode_wireguard}:run_udp_connection_pool: rathole::server: Listening at 0.0.0.0:51820
Jan 07 03:10:04.052  INFO handle_connection{addr=someip:49396}: rathole::server: Control channel established service=somenode_xray
Jan 07 03:10:04.052  INFO handle_connection{addr=someip:49396}:new{service=somenode_xray}:run_tcp_connection_pool: rathole::server: Listening at 0.0.0.0:443
Jan 07 03:10:13.885  INFO handle_connection{addr=someip:49397}:new{service=somenode_wireguard}:run{service=somenode_wireguard}: rathole::server: Control channel shuting down
Jan 07 03:10:20.015  INFO handle_connection{addr=someip:12469}: rathole::server: New control channel incomming from someip:12469
Jan 07 03:10:20.081  WARN handle_connection{addr=someip:12469}: rathole::server: Dropping previous control channel for digest 48c2c19d725b1be91b4982776eefd7eb0d8e883a09d6c6959dd76cd7590c1b75
Jan 07 03:10:20.082  INFO handle_connection{addr=someip:12469}: rathole::server: Control channel established service=somenode_wireguard
Jan 07 03:10:20.082  INFO handle_connection{addr=someip:12469}:new{service=somenode_wireguard}:run_udp_connection_pool: rathole::server: Listening at 0.0.0.0:51820
Jan 07 03:10:26.148  INFO handle_connection{addr=someip:12469}:new{service=somenode_wireguard}:run{service=somenode_wireguard}: rathole::server: Control channel shuting down
Jan 07 03:10:34.364  INFO handle_connection{addr=someip:32759}: rathole::server: New control channel incomming from someip:32759
Jan 07 03:10:34.432  WARN handle_connection{addr=someip:32759}: rathole::server: Dropping previous control channel for digest 48c2c19d725b1be91b4982776eefd7eb0d8e883a09d6c6959dd76cd7590c1b75
Jan 07 03:10:34.432  INFO handle_connection{addr=someip:32759}: rathole::server: Control channel established service=somenode_wireguard
Jan 07 03:10:34.432  INFO handle_connection{addr=someip:32759}:new{service=somenode_wireguard}:run_udp_connection_pool: rathole::server: Listening at 0.0.0.0:51820
Jan 07 03:10:40.382  INFO handle_connection{addr=someip:32759}:new{service=somenode_wireguard}:run{service=somenode_wireguard}: rathole::server: Control channel shuting down
Jan 07 03:10:41.668  INFO handle_connection{addr=someip:49491}: rathole::server: New control channel incomming from someip:49491
Jan 07 03:10:41.839  WARN handle_connection{addr=someip:49491}: rathole::server: Dropping previous control channel for digest 48c2c19d725b1be91b4982776eefd7eb0d8e883a09d6c6959dd76cd7590c1b75
Jan 07 03:10:41.839  INFO handle_connection{addr=someip:49491}: rathole::server: Control channel established service=somenode_wireguard
Jan 07 03:10:41.839  INFO handle_connection{addr=someip:49491}:new{service=somenode_wireguard}:run_udp_connection_pool: rathole::server: Listening at 0.0.0.0:51820

[wellsgz]

Full configuration below:

Server side:

    [server]
    bind_addr = "0.0.0.0:8080"
    default_token = "sometoken"
    
    [server.transport]
    type = "noise"
    
    [server.transport.noise]
    local_private_key = "somekey"
    
    [server.services.somenode_doh]
    bind_addr = "0.0.0.0:853"
    
    [server.services.somenode_wireguard]
    type = "udp"
    bind_addr = "0.0.0.0:51820"
    
    [server.services.somenode_xray]
    bind_addr = "0.0.0.0:443"
    
    [server.services.yetanother_xray]
    bind_addr = "0.0.0.0:58453"

Client side:

[client]
remote_addr = "someip:8080"
default_token = "sometoken"

[client.transport]
type = "noise"

[client.transport.noise]
remote_public_key = "somekey"

[client.services.somenode_wireguard]
type = "udp"
local_addr = "localip:51820"

[client.services.somenode_doh]
local_addr = "mosdns:853"

[client.services.somenode_xray]
local_addr = "xray:443"

[rapiz1]

Confirmed. This is more likely to happen with large UDP packets. Thanks for reporting!

[wellsgz]

works like a charm with v0.3.3, thanks for the speedy fix!