search

zfl9 / ipt2socks

将 iptables/nftables 传入的透明代理流量转为 socks5 流量的实用工具
GNU Affero General Public License v3.0
447 stars 103 forks source link

ERR: [udp_socks5_recv_tcpmessage_cb] recv unknown msg from socks5 server, release ctx #52

Closed Ir1Ka closed 7 months ago

Ir1Ka commented 7 months ago

我目前正在 docker 方式部署 ss-tproxy，其中

测试命令 curl http://1.1.1.1 正常，ipt2socks 和 trojan-go 无报错或异常 log，且能得到结果（一个 301 Moved Permanently）。 测试命令 nslookup ip.sb 1.1.1.1 报错，log 如下。 （使用 nsloopup 命令指定 chinadns-ng 监听的端口（127.0.0.1:60053）进行 dns 查询，发现了相同的错误，log 也几乎相同。）

烦请帮忙排查，感谢。

chinadns-ng log：

2024-04-04 17:30:26 I [server.zig:302 QueryLog.query] query(id:4964, tag:none, qtype:1, 'ip.sb') from ::ffff:127.0.0.1#52228
2024-04-04 17:30:26 I [server.zig:349 QueryLog.forward] forward query(qid:7, from:udp, 'ip.sb') to trust group
2024-04-04 17:30:26 I [Upstream.zig:490 Group.send] forward query(qid:7, from:udp) to upstream udpin://8.8.8.8
2024-04-04 17:30:26 I [Upstream.zig:490 Group.send] forward query(qid:7, from:udp) to upstream udpin://1.1.1.1
2024-04-04 17:30:26 I [Upstream.zig:490 Group.send] forward query(qid:7, from:udp) to upstream udpin://2001:4860:4860::8888
2024-04-04 17:30:26 I [Upstream.zig:490 Group.send] forward query(qid:7, from:udp) to upstream udpin://2606:4700:4700::1111
2024-04-04 17:30:31 I [server.zig:302 QueryLog.query] query(id:4964, tag:none, qtype:1, 'ip.sb') from ::ffff:127.0.0.1#40375
2024-04-04 17:30:31 I [server.zig:349 QueryLog.forward] forward query(qid:8, from:udp, 'ip.sb') to trust group
2024-04-04 17:30:31 I [Upstream.zig:490 Group.send] forward query(qid:8, from:udp) to upstream udpin://8.8.8.8
2024-04-04 17:30:31 I [Upstream.zig:490 Group.send] forward query(qid:8, from:udp) to upstream udpin://1.1.1.1
2024-04-04 17:30:31 I [Upstream.zig:490 Group.send] forward query(qid:8, from:udp) to upstream udpin://2001:4860:4860::8888
2024-04-04 17:30:31 I [Upstream.zig:490 Group.send] forward query(qid:8, from:udp) to upstream udpin://2606:4700:4700::1111
2024-04-04 17:30:31 W [server.zig:827 on_timeout] query(qid:7, id:4964, tag:none) from udp://::ffff:127.0.0.1#52228 [timeout]
2024-04-04 17:30:36 W [server.zig:827 on_timeout] query(qid:8, id:4964, tag:none) from udp://::ffff:127.0.0.1#40375 [timeout]
2024-04-04 17:30:36 I [server.zig:302 QueryLog.query] query(id:4964, tag:none, qtype:1, 'ip.sb') from ::ffff:127.0.0.1#45705
2024-04-04 17:30:36 I [server.zig:349 QueryLog.forward] forward query(qid:9, from:udp, 'ip.sb') to trust group
2024-04-04 17:30:36 I [Upstream.zig:490 Group.send] forward query(qid:9, from:udp) to upstream udpin://8.8.8.8
2024-04-04 17:30:36 I [Upstream.zig:490 Group.send] forward query(qid:9, from:udp) to upstream udpin://1.1.1.1
2024-04-04 17:30:36 I [Upstream.zig:490 Group.send] forward query(qid:9, from:udp) to upstream udpin://2001:4860:4860::8888
2024-04-04 17:30:36 I [Upstream.zig:490 Group.send] forward query(qid:9, from:udp) to upstream udpin://2606:4700:4700::1111
2024-04-04 17:30:41 W [server.zig:827 on_timeout] query(qid:9, id:4964, tag:none) from udp://::ffff:127.0.0.1#45705 [timeout]

在 ipt2socks 容器中报如下错误：

ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_tproxy_recvmsg_cb] recv from xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx#34304, nrecv:23
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_tproxy_recvmsg_cb] try to connect to 127.0.0.1#1080 ...
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_tproxy_recvmsg_cb] recv from xx.xx.x.xxx#59313, nrecv:23
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_tproxy_recvmsg_cb] try to connect to 127.0.0.1#1080 ...
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_connect_cb] connect to 127.0.0.1#1080 succeeded
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_send_authreq_cb] send to 127.0.0.1#1080, nsend:3
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_connect_cb] connect to 127.0.0.1#1080 succeeded
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_send_authreq_cb] send to 127.0.0.1#1080, nsend:3
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_tproxy_recvmsg_cb] recv from xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx#43805, nrecv:23
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_tproxy_recvmsg_cb] try to connect to 127.0.0.1#1080 ...
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_tproxy_recvmsg_cb] recv from xx.xx.x.xxx#34522, nrecv:23
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_tproxy_recvmsg_cb] try to connect to 127.0.0.1#1080 ...
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_connect_cb] connect to 127.0.0.1#1080 succeeded
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_send_authreq_cb] send to 127.0.0.1#1080, nsend:3
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_connect_cb] connect to 127.0.0.1#1080 succeeded
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_send_authreq_cb] send to 127.0.0.1#1080, nsend:3
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_authresp_cb] recv from 127.0.0.1#1080, nrecv:2
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_authresp_cb] send to 127.0.0.1#1080, nsend:10
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_authresp_cb] recv from 127.0.0.1#1080, nrecv:2
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_authresp_cb] send to 127.0.0.1#1080, nsend:22
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_authresp_cb] recv from 127.0.0.1#1080, nrecv:2
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_authresp_cb] send to 127.0.0.1#1080, nsend:10
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_authresp_cb] recv from 127.0.0.1#1080, nrecv:2
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_authresp_cb] send to 127.0.0.1#1080, nsend:22
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_proxyresp_cb] recv from 127.0.0.1#1080, nrecv:10
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_proxyresp_cb] send to 2001:4860:4860::8888#53, nsend:45
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_proxyresp_cb] recv from 127.0.0.1#1080, nrecv:10
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_proxyresp_cb] send to 1.1.1.1#53, nsend:33
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_proxyresp_cb] recv from 127.0.0.1#1080, nrecv:10
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_proxyresp_cb] send to 2606:4700:4700::1111#53, nsend:45
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_proxyresp_cb] recv from 127.0.0.1#1080, nrecv:10
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_recv_proxyresp_cb] send to 8.8.8.8#53, nsend:33
ipt2socks-1  | 2024-04-04 17:30:26 ERR: [udp_socks5_recv_tcpmessage_cb] recv unknown msg from socks5 server, release ctx
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_context_timeout_cb] context will be released, reason: manual
ipt2socks-1  | 2024-04-04 17:30:26 ERR: [udp_socks5_recv_tcpmessage_cb] recv unknown msg from socks5 server, release ctx
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_context_timeout_cb] context will be released, reason: manual
ipt2socks-1  | 2024-04-04 17:30:26 ERR: [udp_socks5_recv_tcpmessage_cb] recv unknown msg from socks5 server, release ctx
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_context_timeout_cb] context will be released, reason: manual
ipt2socks-1  | 2024-04-04 17:30:26 ERR: [udp_socks5_recv_tcpmessage_cb] recv unknown msg from socks5 server, release ctx
ipt2socks-1  | 2024-04-04 17:30:26 INF: [udp_socks5_context_timeout_cb] context will be released, reason: manual
ipt2socks-1  | 2024-04-04 17:30:31 INF: [udp_tproxy_recvmsg_cb] recv from xx.xx.x.xxx#59313, nrecv:23
ipt2socks-1  | 2024-04-04 17:30:31 INF: [udp_tproxy_recvmsg_cb] try to connect to 127.0.0.1#1080 ...
ipt2socks-1  | 2024-04-04 17:30:31 INF: [udp_socks5_connect_cb] connect to 127.0.0.1#1080 succeeded
ipt2socks-1  | 2024-04-04 17:30:31 INF: [udp_socks5_send_authreq_cb] send to 127.0.0.1#1080, nsend:3
ipt2socks-1  | 2024-04-04 17:30:31 INF: [udp_tproxy_recvmsg_cb] recv from xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx#34304, nrecv:23

且在 trojan-go 容器中打印如下日志：

trojan-1  | [INFO]  2024/04/04 17:30:26 socks connection from 127.0.0.1:39880 metadata [::]:0
trojan-1  | [INFO]  2024/04/04 17:30:26 socks connection from 127.0.0.1:39888 metadata 0.0.0.0:0
trojan-1  | [INFO]  2024/04/04 17:30:26 socks connection from 127.0.0.1:39896 metadata [::]:0
trojan-1  | [INFO]  2024/04/04 17:30:26 socks connection from 127.0.0.1:39902 metadata 0.0.0.0:0
trojan-1  | [INFO]  2024/04/04 17:30:31 socks connection from 127.0.0.1:57196 metadata 0.0.0.0:0
trojan-1  | [INFO]  2024/04/04 17:30:31 socks connection from 127.0.0.1:57202 metadata [::]:0
trojan-1  | [INFO]  2024/04/04 17:30:31 socks connection from 127.0.0.1:57186 metadata 0.0.0.0:0
trojan-1  | [INFO]  2024/04/04 17:30:31 socks connection from 127.0.0.1:57194 metadata [::]:0
trojan-1  | [INFO]  2024/04/04 17:30:36 socks connection from 127.0.0.1:57230 metadata 0.0.0.0:0
trojan-1  | [INFO]  2024/04/04 17:30:36 socks connection from 127.0.0.1:57222 metadata [::]:0
trojan-1  | [INFO]  2024/04/04 17:30:36 socks connection from 127.0.0.1:57240 metadata [::]:0
trojan-1  | [INFO]  2024/04/04 17:30:36 socks connection from 127.0.0.1:57210 metadata 0.0.0.0:0
Ir1Ka commented 7 months ago

当我把 udp 关掉时（tcponly=true），可以正常工作。我可能需要确认我的服务器是否支持 udp。

Ir1Ka commented 7 months ago

我通过工具 https://github.com/ezbik/scripts/tree/master/udpchk 测试，我的代理服务器支持 udp。

zfl9 commented 7 months ago

trojan-go 的 socks5 的 udp 实现有问题吧，我看 log 好像意外的关闭了 tcp/1080 上的连接。

另外我记得 trojan-go 支持透明代理传入的呀？

zfl9 commented 7 months ago

因为这个之前测试过 trojan 原版 C++ 写的客户端（开了 udp），是没问题的。

之前有个 issue 和你说的很像，看起来都是 socks5 服务器的 udp 实现有问题。

51

zfl9 commented 7 months ago

https://datatracker.ietf.org/doc/html/rfc1928

这是 socks5 的 RFC，其中有提到 UDP ASSOCIATE （也就是 udp 代理），有这样一段话： 意思是说，req 中的 dst.addr 和 dst.port 可以是全 0 的，这个本身和代理流程没关系。

The UDP ASSOCIATE request is used to establish an association within the UDP relay process to handle UDP datagrams. The DST.ADDR and DST.PORT fields contain the address and port that the client expects to use to send UDP datagrams on for the association. The server MAY use this information to limit access to the association. If the client is not in possesion of the information at the time of the UDP ASSOCIATE, the client MUST use a port number and address of all zeros.

然后是这段话：socks5 服务器这边，如果关闭与 UDP ASSOCIATE 请求关联的那个 tcp 连接，则视为“udp代理”的终止信号。这就是 ipt2socks 的 recv unknown msg from socks5 server 的报错来源，因为这表示服务器要终止 udp 代理（但显然不应该，因为 udp 代理才刚开始呢。。）

A UDP association terminates when the TCP connection that the UDP ASSOCIATE request arrived on terminates.

zfl9 commented 7 months ago

所以这是 trojan-go 的 udp (socks5) 实现不符合 RFC 规范，建议去 trojan-go 报告 issue。

Ir1Ka commented 7 months ago

我用原版 trojan-gfw 做，似乎也有相同的问题。 我尝试用 trojan-go 的透明代理模式，但似乎也不工作。😣

zfl9 commented 7 months ago

不应该吧，我自己正在使用 trojan-gfw + ipt2socks，udp 正常。

zfl9 commented 7 months ago

你这三个 docker 容器在同一个宿主机上吗？

有没有试过先把 docker 移除，在宿主机上看看？

Ir1Ka commented 7 months ago

是的，三个容器均位于同一个宿主机上，并且均使用 host 网络。 ss-tproxy 使用 tcponly 是可以正常工作的。

接下来我将尝试均直接工作在宿主机上。

Ir1Ka commented 7 months ago

trojan-gfw 报了和 trojan-go 上类似的信息（但并不是报错）：

trojan-1  | Welcome to trojan 1.16.0
trojan-1  | [2024-04-05 03:52:25] [WARN] trojan service (client) started at 127.0.0.1:1080
trojan-1  | [2024-04-05 03:53:16] [INFO] 127.0.0.1:45494 requested UDP associate to 0.0.0.0:0, open UDP socket 127.0.0.1:50742 for relay
trojan-1  | [2024-04-05 03:53:16] [INFO] 127.0.0.1:45504 requested UDP associate to 0.0.0.0:0, open UDP socket 127.0.0.1:48627 for relay
trojan-1  | [2024-04-05 03:53:16] [INFO] 127.0.0.1:45496 requested UDP associate to 0000:0000:0000:0000:0000:0000:0000:0000:0, open UDP socket 127.0.0.1:60833 for relay
trojan-1  | [2024-04-05 03:53:16] [INFO] 127.0.0.1:45512 requested UDP associate to 0000:0000:0000:0000:0000:0000:0000:0000:0, open UDP socket 127.0.0.1:58958 for relay
trojan-1  | [2024-04-05 03:54:26] [INFO] 127.0.0.1:45496 disconnected, 213 bytes received, 69 bytes sent, lasted for 70 seconds
trojan-1  | [2024-04-05 03:54:26] [INFO] 127.0.0.1:45504 disconnected, 213 bytes received, 69 bytes sent, lasted for 70 seconds
trojan-1  | [2024-04-05 03:54:26] [INFO] 127.0.0.1:45494 disconnected, 213 bytes received, 69 bytes sent, lasted for 70 seconds
trojan-1  | [2024-04-05 03:54:26] [INFO] 127.0.0.1:45512 disconnected, 213 bytes received, 69 bytes sent, lasted for 70 seconds
zfl9 commented 7 months ago

trojan-gfw 报了和 trojan-go 上类似的信息（但并不是报错）：

trojan-1  | Welcome to trojan 1.16.0
trojan-1  | [2024-04-05 03:52:25] [WARN] trojan service (client) started at 127.0.0.1:1080
trojan-1  | [2024-04-05 03:53:16] [INFO] 127.0.0.1:45494 requested UDP associate to 0.0.0.0:0, open UDP socket 127.0.0.1:50742 for relay
trojan-1  | [2024-04-05 03:53:16] [INFO] 127.0.0.1:45504 requested UDP associate to 0.0.0.0:0, open UDP socket 127.0.0.1:48627 for relay
trojan-1  | [2024-04-05 03:53:16] [INFO] 127.0.0.1:45496 requested UDP associate to 0000:0000:0000:0000:0000:0000:0000:0000:0, open UDP socket 127.0.0.1:60833 for relay
trojan-1  | [2024-04-05 03:53:16] [INFO] 127.0.0.1:45512 requested UDP associate to 0000:0000:0000:0000:0000:0000:0000:0000:0, open UDP socket 127.0.0.1:58958 for relay
trojan-1  | [2024-04-05 03:54:26] [INFO] 127.0.0.1:45496 disconnected, 213 bytes received, 69 bytes sent, lasted for 70 seconds
trojan-1  | [2024-04-05 03:54:26] [INFO] 127.0.0.1:45504 disconnected, 213 bytes received, 69 bytes sent, lasted for 70 seconds
trojan-1  | [2024-04-05 03:54:26] [INFO] 127.0.0.1:45494 disconnected, 213 bytes received, 69 bytes sent, lasted for 70 seconds
trojan-1  | [2024-04-05 03:54:26] [INFO] 127.0.0.1:45512 disconnected, 213 bytes received, 69 bytes sent, lasted for 70 seconds

这个是正常的，从日志上看，udp 代理正常运行中。

Ir1Ka commented 7 months ago

看起来是 ipt2socks 在容器中工作会有异常，或者我的容器或其他配置有问题。

zfl9 commented 7 months ago

权限问题？操作 tproxy 套接字需要 CAP_NET_ADMIN；

但是看log，应该不是。

而且容器用的 net 都是宿主机的，并没有单独的 namespace，应该也不是这里的问题。

有没有可能是 gid 不对呢？因为 docker 容器默认情况下（如果我没记错）有自己单独的 uid/gid namespace。

Ir1Ka commented 7 months ago

我知道是什么原因了，是我的配置有误，我把 ip2socks 容器的 NET_BIND_SERVICE cap 给移除了。

Ir1Ka commented 7 months ago

有没有可能是 gid 不对呢？因为 docker 容器默认情况下（如果我没记错）有自己单独的 uid/gid namespace。

docker 默认情况下没有用独立的 uid/gid namespace。

我在调试过程中注意到 ipt2socks 日志中有如下 log：

ERR: [udp_socks5_recv_udpmessage_cb] bind tproxy reply address: Permission denied

我再注意到我的 docker 配置中，我对 ipt2socks 容器移除了 NET_BIND_SERVICE cap，我尝试加回此权限，然后工作正常了。