rust server & libev client: UDP does not work

[piangere]

Case 1:
Server: rust 1.15.0-alpha.4
Client: libev 3.3.5
udp does not work

Case 2
Server: rust 1.15.0-alpha.4
Client: rust 1.14.3
udp works

Case 3:
Server: libev 3.3.5
Client: libev 3.3.5
udp works

Case 4:
Server: libev 3.3.5
Client: rust 1.14.3
udp works

[zonyitoo]

At least tell everybody how to reproduce.

[piangere]

Case 1:
Server: rust 1.15.0-alpha.4

/usr/local/bin/ssserver -c /etc/shadowsocks-libev/config.json

cat /etc/shadowsocks-libev/config.json
{
    "server":"0.0.0.0",
    "server_port":83,
    "password":"*",
    "timeout":60,
    "method":"aes-256-gcm",
    "mode":"tcp_and_udp",
    "fast_open":true
}

Client: libev 3.3.5

ss-redir -c /koolshare/ss/ss.json -u --reuse-port -f /var/run/ss_1.pid

cat /koolshare/ss/ss.json
{
    "server":"*",
    "server_port":83,
    "local_address":"0.0.0.0",
    "local_port":3333,
    "password":"*",
    "timeout":600,
    "method":"aes-256-gcm"
}

My router is with full cone NAT.

with this setup:

• tcp works
• udp does not work

Note: it can't be network issue since case2 work fine with UDP.

I test with dota2 server. Case 1 cannot ping any server while case 2, case 3, case 4 can.

I also test whether UDP works with nslookup and as you can see, case 1 does not work.

$ nslookup twitter.com 8.8.8.8
;; connection timed out; no servers could be reached

When UDP works (case2):

$ nslookup twitter.com 8.8.8.8
Server:         8.8.8.8
Address:        8.8.8.8#53

Non-authoritative answer:
Name:   twitter.com
Address: 104.244.42.65
Name:   twitter.com
Address: 104.244.42.129

[zonyitoo]

What did you see when using Case1 in ssserver's log? Could you see any logs about UDP?

[piangere]

What did you see when using Case1 in ssserver's log? Could you see any logs about UDP?

case 1:

Server: rust 1.15.0-alpha.4
Client: libev 3.3.5. ss-redir in router

a computer beneath router:

~$ nslookup twitter.com 8.8.8.8
;; connection timed out; no servers could be reached

Server

2022-06-02T06:12:22.510825898-04:00 DEBUG [793:140644057778688] [shadowsocks_service::server::udprelay] created udp association for xx.xx.xx.xx:58470

xx.xx.xx.xx is the WAN ip of my router.

case 2:

Server: rust 1.15.0-alpha.4
Client: rust 1.14.3. sslocal redir mode in router

a computer beneath router:

~$ nslookup twitter.com 8.8.8.8
Server:         8.8.8.8
Address:        8.8.8.8#53

Non-authoritative answer:
Name:   twitter.com
Address: 104.244.42.129
Name:   twitter.com
Address: 104.244.42.193

Server

2022-06-02T06:13:28.566963125-04:00 DEBUG [793:140644057778688] [shadowsocks_service::server::udprelay] created udp association for xx.xx.xx.xx:33067
2022-06-02T06:13:28.703817474-04:00 DEBUG [793:140644057778688] [shadowsocks_service::server::udprelay] created udp association for xx.xx.xx.xx:34590

xx.xx.xx.xx is the WAN ip of my router.

case 3 & case 4

I can confirm nslookup works. Since the server is libev not rust, it's not the focus of the issue.

Difference

in case 1, ssserver logs 1 record
in case 2, ssserver logs 2 record2

It looks like in case 1:

• libev redir ---> ssserver ---> 8.8.8.8: working
• 8.8.8.8 ---> ssserver --X-> libev redir: not working
  or, is it (I am not sure how UDP works with shadowsocks)
• 8.8.8.8 --X-> libev redir?

It's some interoperability issue.

[zonyitoo]

You should try to enable higher log level, for example -vvv.

The line created udp association ... indicated that ssserver receives an UDP association packet from a new client, so it was going to create a new association for it.

So if you can see 2 lines of logs, then there must be 2 individual clients (or sockets) were created and send 2 UDP packets to ssserver.

And yes,

CLIENT -> libev-sslocal -> ssserver -> 8.8.8.8
CLIENT <- libev-sslocal <- ssserver <- 8.8.8.8

You should add -vvv on ssserver and see if it receives responses from 8.8.8.8.

[piangere]

Here you are:

case 1:

CLIENT -> libev ss-redir -> rust ssserver -> 8.8.8.8

2022-06-02T10:14:25.346354261-04:00 TRACE [1565:139851401037568] [shadowsocks::relay::udprelay::aead] UDP packet got AEAD salt b"\xed\xf9\x11|\xf5\xaf&6x]\xac\xb9\xb1\x1c\xec\xdf\x90\xbf\xb0\xdf\xd1\xfc\xdb\x983u\xfd\x1d\x99\x95\xffS"
2022-06-02T10:14:25.346608037-04:00 TRACE [1565:139851401037568] [shadowsocks::relay::udprelay::proxy_socket] UDP server client receive from xx.xx.xx.xx:52772, addr 8.8.8.8:53, control: None, packet length 84 bytes, payload length 29 bytes
2022-06-02T10:14:25.346993232-04:00 DEBUG [1565:139851401042432] [shadowsocks_service::server::udprelay] created udp association for xx.xx.xx.xx:52772
2022-06-02T10:14:25.347254650-04:00 TRACE [1565:139851398936320] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:52772 -> 8.8.8.8:53 with 29 bytes, control: None
2022-06-02T10:14:25.348478684-04:00 TRACE [1565:139851398936320] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:52772 <- [::ffff:8.8.8.8]:53 received 61 bytes
2022-06-02T10:14:25.348927140-04:00 TRACE [1565:139851398936320] [shadowsocks::relay::udprelay::aead] UDP packet generated aead salt b"^\xdc\x9dQ\x9c\xf7\xb7\\\xf8^\xc2\xa4$\xdb\x9f*mS\xf1cl\x99\x89\xa5\xf7\xd9\xc5\xd8J\'/\x0f"
2022-06-02T10:14:25.350032864-04:00 TRACE [1565:139851398936320] [shadowsocks::relay::udprelay::proxy_socket] UDP server client send to, addr [::ffff:8.8.8.8]:53, control: UdpSocketControlData { client_session_id: 0, server_session_id: 0, packet_id: 0 }, payload length 61 bytes, packet length 128 bytes
2022-06-02T10:14:25.350505598-04:00 TRACE [1565:139851398936320] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:52772 <- [::ffff:8.8.8.8]:53 with 61 bytes
2022-06-02T10:14:30.350542210-04:00 TRACE [1565:139851398936320] [shadowsocks::relay::udprelay::aead] UDP packet got AEAD salt b"\xb1*\xa72h\xd1\xf5B\x1d\xba\xec\xe1R\xe72\x02\x08Fb\x8fU\x0fm\xa8\x1a\xda-uZ4\xf0\x16"
2022-06-02T10:14:30.351088534-04:00 TRACE [1565:139851398936320] [shadowsocks::relay::udprelay::proxy_socket] UDP server client receive from xx.xx.xx.xx:52772, addr 8.8.8.8:53, control: None, packet length 84 bytes, payload length 29 bytes
2022-06-02T10:14:30.351358848-04:00 TRACE [1565:139851398936320] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:52772 -> 8.8.8.8:53 with 29 bytes, control: None
2022-06-02T10:14:30.352053293-04:00 TRACE [1565:139851401037568] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:52772 <- [::ffff:8.8.8.8]:53 received 61 bytes
2022-06-02T10:14:30.352214921-04:00 TRACE [1565:139851401037568] [shadowsocks::relay::udprelay::aead] UDP packet generated aead salt b"\xd0g\xc3\xc0\x8do\xf8\x9eYx\x97\x81\xa1\xd24\x03-h\x1fw\xfc\xdf\xa9\xbe d\xf6\x81\x04t1R"
2022-06-02T10:14:30.352570751-04:00 TRACE [1565:139851401037568] [shadowsocks::relay::udprelay::proxy_socket] UDP server client send to, addr [::ffff:8.8.8.8]:53, control: UdpSocketControlData { client_session_id: 0, server_session_id: 0, packet_id: 0 }, payload length 61 bytes, packet length 128 bytes
2022-06-02T10:14:30.352769184-04:00 TRACE [1565:139851401037568] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:52772 <- [::ffff:8.8.8.8]:53 with 61 bytes
2022-06-02T10:14:35.353380145-04:00 TRACE [1565:139851401037568] [shadowsocks::relay::udprelay::aead] UDP packet got AEAD salt b"fW\xba\x8cn\xef\x81\xdf\xcc\xedj\x12\x1eF\xfb/\x08=\x19\xa6\x81*\xf3\xd3N\xab\x80x\x9b\xacd\\"
2022-06-02T10:14:35.353683854-04:00 TRACE [1565:139851401037568] [shadowsocks::relay::udprelay::proxy_socket] UDP server client receive from xx.xx.xx.xx:52772, addr 8.8.8.8:53, control: None, packet length 84 bytes, payload length 29 bytes
2022-06-02T10:14:35.353907136-04:00 TRACE [1565:139851401037568] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:52772 -> 8.8.8.8:53 with 29 bytes, control: None
2022-06-02T10:14:35.354505286-04:00 TRACE [1565:139851398936320] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:52772 <- [::ffff:8.8.8.8]:53 received 61 bytes
2022-06-02T10:14:35.354677916-04:00 TRACE [1565:139851398936320] [shadowsocks::relay::udprelay::aead] UDP packet generated aead salt b")\xc3\x8e7\xfb\'1\xbbY\x1a%b\x0f\x93\x83\xd8,\xbd\x11\xeek\xd1\xb6\xf9f>\xb9\x03\x01#\xd0\\"
2022-06-02T10:14:35.355085907-04:00 TRACE [1565:139851398936320] [shadowsocks::relay::udprelay::proxy_socket] UDP server client send to, addr [::ffff:8.8.8.8]:53, control: UdpSocketControlData { client_session_id: 0, server_session_id: 0, packet_id: 0 }, payload length 61 bytes, packet length 128 bytes
2022-06-02T10:14:35.355286573-04:00 TRACE [1565:139851398936320] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:52772 <- [::ffff:8.8.8.8]:53 with 61 bytes
2022-06-02T10:14:35.874949843-04:00 TRACE [1565:139851401042432] [shadowsocks::relay::tcprelay::crypto_io] generated AEAD cipher salt b"\xa3\xf0\xcd\x1b<cj\x96\xa2\xc5\xcf\x03;\xd1\xb2i\xf8\xee\x05-U^\xcd\xcb\xd1\xd1\xc3\xe7&\x98\xce\xb0"
2022-06-02T10:14:35.876398443-04:00 TRACE [1565:139851398936320] [shadowsocks::relay::tcprelay::aead] got AEAD salt b"|\x06T\x03&\x1a\xe4\xdd\xe9n\x8b\xea\x06A\x12\xaaT\x7f\x06\xb3\x7f\x05qi\x0e\xac\xe2a\x89|dx"
2022-06-02T10:14:35.876643955-04:00 TRACE [1565:139851398936320] [shadowsocks_service::server::tcprelay] accepted tcp client connection xx.xx.xx.xx:43717, establishing tunnel to 8.8.8.8:53
2022-06-02T10:14:35.877062772-04:00 DEBUG [1565:139851401037568] [shadowsocks_service::server::tcprelay] established tcp tunnel xx.xx.xx.xx:43717 <-> 8.8.8.8:53 with ConnectOpts { fwmark: None, bind_local_addr: None, bind_interface: None, tcp: TcpSocketOpts { send_buffer_size: None, recv_buffer_size: None, nodelay: false, fastopen: true, keepalive: Some(15s) } }
2022-06-02T10:14:36.024542301-04:00 TRACE [1565:139851401037568] [shadowsocks_service::server::tcprelay] tcp tunnel xx.xx.xx.xx:43717 <-> 8.8.8.8:53 closed, L2R 0 bytes, R2L 112 bytes

case 2:

CLIENT -> rust sslocal redir mode -> rust ssserver -> 8.8.8.8

rust sslocal redir mode setting:

sslocal --protocol redir -b 0.0.0.0:3333 -s *.*.*.*:83 -m aes-256-gcm -k ***** --tcp-redir redirect --udp-redir tproxy -U -d

2022-06-02T10:15:47.148040647-04:00 TRACE [1565:139851401037568] [shadowsocks::relay::udprelay::aead] UDP packet got AEAD salt b"\xb6\t^\xae\xb8Ux9c\x9az\x01\xe90,\xa9V\xd6\x05\xdd\xb8\xd3\x8d\xa9\x85\x8dN7!\x17\x90J"
2022-06-02T10:15:47.149099636-04:00 TRACE [1565:139851401037568] [shadowsocks::relay::udprelay::proxy_socket] UDP server client receive from xx.xx.xx.xx:49383, addr 8.8.8.8:53, control: None, packet length 84 bytes, payload length 29 bytes
2022-06-02T10:15:47.149402036-04:00 DEBUG [1565:139851401042432] [shadowsocks_service::server::udprelay] created udp association for xx.xx.xx.xx:49383
2022-06-02T10:15:47.151182103-04:00 TRACE [1565:139851401037568] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:49383 -> 8.8.8.8:53 with 29 bytes, control: None
2022-06-02T10:15:47.152355329-04:00 TRACE [1565:139851398936320] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:49383 <- [::ffff:8.8.8.8]:53 received 61 bytes
2022-06-02T10:15:47.152749419-04:00 TRACE [1565:139851398936320] [shadowsocks::relay::udprelay::aead] UDP packet generated aead salt b"\xba\xe2\xfd\x8d\xf0\t\xa55\xff\xdaUI\xf8\xcc\x11\xf7v\x914\x85\x04Q\x05\xa4\xe4\xc7a\x8e\x1f>\xd2\xd2"
2022-06-02T10:15:47.154064389-04:00 TRACE [1565:139851398936320] [shadowsocks::relay::udprelay::proxy_socket] UDP server client send to, addr [::ffff:8.8.8.8]:53, control: UdpSocketControlData { client_session_id: 0, server_session_id: 0, packet_id: 0 }, payload length 61 bytes, packet length 128 bytes
2022-06-02T10:15:47.154670500-04:00 TRACE [1565:139851398936320] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:49383 <- [::ffff:8.8.8.8]:53 with 61 bytes
2022-06-02T10:15:47.297508557-04:00 TRACE [1565:139851398936320] [shadowsocks::relay::udprelay::aead] UDP packet got AEAD salt b"\x94Qpx\xbe\x9a\xc2\x12\xfc\x89\xa7\xd82\xef$\xa0+\xed,#,\x8d\xd9{\x1b\xd1\xc0V2TM\xf9"
2022-06-02T10:15:47.298490216-04:00 TRACE [1565:139851398936320] [shadowsocks::relay::udprelay::proxy_socket] UDP server client receive from xx.xx.xx.xx:46720, addr 8.8.8.8:53, control: None, packet length 84 bytes, payload length 29 bytes
2022-06-02T10:15:47.299088671-04:00 DEBUG [1565:139851401042432] [shadowsocks_service::server::udprelay] created udp association for xx.xx.xx.xx:46720
2022-06-02T10:15:47.299352243-04:00 TRACE [1565:139851401037568] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:46720 -> 8.8.8.8:53 with 29 bytes, control: None
2022-06-02T10:15:47.300653124-04:00 TRACE [1565:139851398936320] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:46720 <- [::ffff:8.8.8.8]:53 received 101 bytes
2022-06-02T10:15:47.300920713-04:00 TRACE [1565:139851398936320] [shadowsocks::relay::udprelay::aead] UDP packet generated aead salt b"FKC$1G(&y\xad\xe4\n\x93h\xcdd\x02\xd5!\xea\xa0CWu\xeb\xb6\x11m\xa6\x07H\xb4"
2022-06-02T10:15:47.301271805-04:00 TRACE [1565:139851398936320] [shadowsocks::relay::udprelay::proxy_socket] UDP server client send to, addr [::ffff:8.8.8.8]:53, control: UdpSocketControlData { client_session_id: 0, server_session_id: 0, packet_id: 0 }, payload length 101 bytes, packet length 168 bytes
2022-06-02T10:15:47.301452422-04:00 TRACE [1565:139851398936320] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:46720 <- [::ffff:8.8.8.8]:53 with 101 bytes

xx.xx.xx.xx is my WAN IP.

[zonyitoo]

2022-06-02T10:14:25.348478684-04:00 TRACE [1565:139851398936320] [shadowsocks_service::server::udprelay] udp relay xx.xx.xx.xx:52772 <- [::ffff:8.8.8.8]:53 received 61 bytes

Ok, I know why.

shadowsocks-rust uses IPv6 sockets for outbound, so the received address is always an IPv6 address. As you can see in the logs, 8.8.8.8 becomes an IPv4-mapped-IPv6 address ::ffff:8.8.8.8.

shadowsocks-libev would then create a IPv6 socket and bind to ::ffff:8.8.8.8 and then send back to your client.

https://github.com/shadowsocks/shadowsocks-libev/blob/c2fc967c1a3e4d864d866cc92dd29a04cdb11f98/src/udprelay.c#L904-L916

The (struct sockaddr *)&remote_ctx->src_addr is an IPv4 address, based on your configuration in shadowsocks-libev. So you should see errors like: [udp] remote_recv_sendto.

There are 2 possible solutions for this:

1. ssserver of shadowsocks-rust converts IPv4-mapped-IPv6 target address back to IPv4 before sending back
2. shadowsocks-libev converts IPv4-mapped-IPv6 address to IPv4 if the sa_family of src_addr is AF_INET

[piangere]

Glad you found the root cause.

Yes, I've not enabled IPv6 on my local network but my proxy server has it enabled. So there's a mismatch.

We should probably support IPv4 and IPv6 mixed scenarios.

[zonyitoo]

Did you actually see [udp] remote_recv_sendto in libev's log?

[piangere]

Sorry, I've not enabled log for libev.
I think it's fairly easy to reproduce the issue. Maybe you and madeye can work it out?

[zonyitoo]

These commits should fix this issue.

[piangere]

any test build so I can help verify?

[zonyitoo]

https://github.com/shadowsocks/shadowsocks-rust/actions