XTLS
短时间内连续查询内置DNS时返回空结果
版本：最新代码编译
配置
{
"log": {
"loglevel": "info"
},
"inbounds": [
{
"tag": "dns",
"protocol": "dokodemo-door",
"port": 5300,
"listen": "127.0.0.1",
"settings": {
"address": "1.1.1.1",
"port": 53,
"network": "tcp,udp"
}
}
],
"outbounds": [
{
"tag": "direct",
"protocol": "freedom",
"settings": {
"domainStrategy": "UseIP"
}
},
{
"tag": "dns",
"protocol": "dns"
},
{
"tag": "reject",
"protocol": "blackhole"
}
],
"dns": {
// 禁用缓存是方便复现，不禁用当然也可以复现。事实上就是在不禁用缓存的情况下发现此问题。
"disableCache": true,
"servers": ["1.1.1.1"]
},
"routing": {
"rules": [
{
"type": "field",
"outboundTag": "dns",
"port": "53"
}
]
}
}
复现步骤：
# 大约10秒内复现
# 间隔1秒似乎无法复现
while true; do dig mail.google.com @127.0.0.1 -p 5300; sleep 0.5; done
日志：
补充：
如果上游使用 https://1.1.1.1/dns-query ，则无法复现。但是日志中除了第一次请求之外都有报一个错。
图2的报错也是从1.5.0开始出现的
[Error] app/dns: failed to retrieve response for mail.google.com. > Post "https://1.1.1.1/dns-query": context canceled
估计就是这个commit https://github.com/XTLS/Xray-core/commit/cd4631ce9982d8be15f5a0d10df8c79bcf40c82f
~~补充：在测试环境中，上游1.1.1.1的延迟很低，大约1~2ms，10秒内重现。如果使用延迟较高的上游，大约30ms，则无法重现。~~
测试发现1.1.1.1会空解析，8.8.8.8正常
1.1.1.1
8.8.8.8
@RPRX @nekohasekai @yuhan6665 大佬们看看这个问题，挺严重的。DNS并发稍微高一点就会空解析，如果开着缓存的话还会长时间空解析，具体表现为某网址始终打不开。 如果不能重现，请直接关闭issue。
1
context canceledis not for an error 2 need more when metempty response
I believe its easy to reproduce. I can't provide any more information.
我也是这样 使用passwall2 日志里面非常多这样的报错 返回empty结果 app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport request > read tcp 20.205.115.81:80->192.168.99.9:44384: read: connection reset by peer
app/dns: failed to lookup ip for domain assets.msn.cn at server UDP:127.0.0.1:15354 > empty response 如果开启缓存用一段时间国外会无法连接了
现在关闭缓存使用 查询empty之后 会再次查询返回一个ip
查询一个域名就一定会有empty 和failed
2023/06/29 18:01:16 [Warning] core: Xray 1.8.3 started 2023/06/29 18:01:16 [Debug] [3471772999] proxy/dokodemo: processing connection from: 192.168.99.9:47606 2023/06/29 18:01:16 [Info] [3471772999] proxy/dokodemo: received request for 192.168.99.9:47606 2023/06/29 18:01:16 [Debug] [2090306756] proxy/dokodemo: processing connection from: 192.168.99.9:54998 2023/06/29 18:01:16 [Info] [2090306756] proxy/dokodemo: received request for 192.168.99.9:54998 2023/06/29 18:01:16 [Debug] [3128813088] proxy/dokodemo: processing connection from: 192.168.99.9:53948 2023/06/29 18:01:16 [Info] [3128813088] proxy/dokodemo: received request for 192.168.99.9:53948 2023/06/29 18:01:16 [Debug] [2494312218] proxy/dokodemo: processing connection from: 192.168.99.9:58188 2023/06/29 18:01:16 [Info] [2494312218] proxy/dokodemo: received request for 192.168.99.9:58188 2023/06/29 18:01:16 [Debug] [2986996014] proxy/dokodemo: processing connection from: 192.168.99.9:56814 2023/06/29 18:01:16 [Info] [2986996014] proxy/dokodemo: received request for 192.168.99.9:56814 2023/06/29 18:01:16 [Debug] [3328705362] proxy/dokodemo: processing connection from: 192.168.99.9:37296 2023/06/29 18:01:16 [Info] [3328705362] proxy/dokodemo: received request for 192.168.99.9:37296 2023/06/29 18:01:16 [Debug] [866230384] proxy/dokodemo: processing connection from: 192.168.99.9:55418 2023/06/29 18:01:16 [Info] [866230384] proxy/dokodemo: received request for 192.168.99.9:55418 2023/06/29 18:01:16 [Debug] [3672985192] proxy/dokodemo: processing connection from: 192.168.99.9:60318 2023/06/29 18:01:16 [Info] [3672985192] proxy/dokodemo: received request for 192.168.99.9:60318 2023/06/29 18:01:16 [Info] [2090306756] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport request > read tcp 221.238.41.89:80->192.168.99.9:54998: read: connection reset by peer 2023/06/29 18:01:16 [Debug] [1455964331] proxy/dokodemo: processing connection from: 192.168.99.9:49830 2023/06/29 18:01:16 [Info] [1455964331] proxy/dokodemo: received request for 192.168.99.9:49830 2023/06/29 18:01:16 [Info] [3471772999] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport request > read tcp 49.7.253.58:80->192.168.99.9:47606: read: connection reset by peer 2023/06/29 18:01:16 [Info] [3128813088] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport request > read tcp 49.7.253.177:80->192.168.99.9:53948: read: connection reset by peer 2023/06/29 18:01:16 192.168.99.9:54998 accepted tcp:221.238.41.89:80 [tcp_redir -> direct] 2023/06/29 18:01:16 192.168.99.9:53948 accepted tcp:49.7.253.177:80 [tcp_redir -> direct] 2023/06/29 18:01:16 192.168.99.9:55418 accepted tcp:42.81.193.250:80 [tcp_redir -> direct] 2023/06/29 18:01:16 192.168.99.9:58188 accepted tcp:42.81.179.212:80 [tcp_redir -> direct] 2023/06/29 18:01:16 [Info] [2090306756] app/dispatcher: taking detour [direct] for [tcp:221.238.41.89:80] 2023/06/29 18:01:16 [Info] [2090306756] transport/internet/tcp: dialing TCP to tcp:221.238.41.89:80 2023/06/29 18:01:16 [Info] [866230384] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport request > read tcp 42.81.193.250:80->192.168.99.9:55418: read: connection reset by peer 2023/06/29 18:01:16 [Info] [3128813088] app/dispatcher: taking detour [direct] for [tcp:49.7.253.177:80] 2023/06/29 18:01:16 [Info] [3128813088] transport/internet/tcp: dialing TCP to tcp:49.7.253.177:80 2023/06/29 18:01:16 [Info] [2494312218] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport request > read tcp 42.81.179.212:80->192.168.99.9:58188: read: connection reset by peer 2023/06/29 18:01:16 192.168.99.9:37296 accepted tcp:49.7.253.65:80 [tcp_redir -> direct] 2023/06/29 18:01:16 192.168.99.9:56814 accepted tcp:49.7.253.214:80 [tcp_redir -> direct] 2023/06/29 18:01:16 192.168.99.9:60318 accepted tcp:42.81.184.206:80 [tcp_redir -> direct] 2023/06/29 18:01:16 192.168.99.9:49830 accepted tcp:42.81.184.82:80 [tcp_redir -> direct] 2023/06/29 18:01:16 [Debug] transport/internet: dialing to tcp:221.238.41.89:80 2023/06/29 18:01:16 192.168.99.9:47606 accepted tcp:49.7.253.58:80 [tcp_redir -> direct] 2023/06/29 18:01:16 [Info] [866230384] app/dispatcher: taking detour [direct] for [tcp:42.81.193.250:80] 2023/06/29 18:01:16 [Debug] transport/internet: dialing to tcp:49.7.253.177:80 2023/06/29 18:01:16 [Info] [2090306756] transport/internet/tcp: dialing TCP to tcp:221.238.41.89:80 2023/06/29 18:01:16 [Debug] transport/internet: dialing to tcp:221.238.41.89:80 2023/06/29 18:01:16 [Info] [2494312218] app/dispatcher: taking detour [direct] for [tcp:42.81.179.212:80] 2023/06/29 18:01:16 [Info] [3128813088] transport/internet/tcp: dialing TCP to tcp:49.7.253.177:80 2023/06/29 18:01:16 [Info] [2494312218] transport/internet/tcp: dialing TCP to tcp:42.81.179.212:80 2023/06/29 18:01:16 [Debug] transport/internet: dialing to tcp:49.7.253.177:80 2023/06/29 18:01:16 [Info] [2986996014] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport request > read tcp 49.7.253.214:80->192.168.99.9:56814: read: connection reset by peer 2023/06/29 18:01:16 [Info] [3328705362] app/proxyman/inbound: connection ends > proxy/dokodemo: connection ends > proxy/dokodemo: failed to transport request > read tcp 49.7.253.65:80->192.168.99.9:37296: read: connection reset by peer
2023/06/29 18:01:17 [Debug] transport/internet: dialing to tcp:183.57.48.48:7512 2023/06/29 18:01:17 192.168.99.110:48092 accepted tcp:183.57.48.48:7512 [tcp_redir -> direct] 2023/06/29 18:01:17 [Debug] transport/internet/udp: UDP original destination: udp:180.163.28.117:8001 2023/06/29 18:01:17 [Debug] [2168241480] proxy/dokodemo: processing connection from: 192.168.99.110:1863 2023/06/29 18:01:17 [Info] [2168241480] proxy/dokodemo: received request for 192.168.99.110:1863 2023/06/29 18:01:17 [Info] [2168241480] app/dispatcher: taking detour [direct] for [udp:180.163.28.117:8001] 2023/06/29 18:01:17 [Debug] transport/internet: dialing to udp:180.163.28.117:8001 2023/06/29 18:01:17 192.168.99.110:1863 accepted udp:180.163.28.117:8001 [udp_redir -> direct] 2023/06/29 18:01:17 [Info] [2168241480] proxy/freedom: connection opened to udp:180.163.28.117:8001, local endpoint [::]:54150, remote endpoint 180.163.28.117:8001 2023/06/29 18:01:17 [Info] [2986996014] app/proxyman/outbound: failed to process outbound traffic > proxy/freedom: failed to open connection to tcp:49.7.253.214:80 > common/retry: [dial tcp 49.7.253.214:80: operation was canceled] > common/retry: all retry attempts failed 2023/06/29 18:01:17 [Info] [866230384] app/proxyman/outbound: failed to process outbound traffic > proxy/freedom: failed to open connection to tcp:42.81.193.250:80 > common/retry: [dial tcp 42.81.193.250:80: operation was canceled] > common/retry: all retry attempts failed 2023/06/29 18:01:17 [Info] [2494312218] app/proxyman/outbound: failed to process outbound traffic > proxy/freedom: failed to open connection to tcp:42.81.179.212:80 > common/retry: [dial tcp 42.81.179.212:80: operation was canceled] > common/retry: all retry attempts failed 2023/06/29 18:01:17 [Info] [2090306756] app/proxyman/outbound: failed to process outbound traffic > proxy/freedom: failed to open connection to tcp:221.238.41.89:80 > common/retry: [dial tcp 221.238.41.89:80: operation was canceled] > common/retry: all retry attempts failed 2023/06/29 18:01:17 [Info] [1455964331] app/proxyman/outbound: failed to process outbound traffic > proxy/freedom: failed to open connection to tcp:42.81.184.82:80 > common/retry: [dial tcp 42.81.184.82:80: operation was canceled] > common/retry: all retry attempts failed 2023/06/29 18:01:17 [Info] [3128813088] app/proxyman/outbound: failed to process outbound traffic > proxy/freedom: failed to open connection to tcp:49.7.253.177:80 > common/retry: [dial tcp 49.7.253.177:80: operation was canceled] > common/retry: all retry attempts failed 2023/06/29 18:01:17 [Info] [3672985192] app/proxyman/outbound: failed to process outbound traffic > proxy/freedom: failed to open connection to tcp:42.81.184.206:80 > common/retry: [dial tcp 42.81.184.206:80: operation was canceled] > common/retry: all retry attempts failed 2023/06/29 18:01:17 [Info] [3471772999] app/proxyman/outbound: failed to process outbound traffic > proxy/freedom: failed to open connection to tcp:49.7.253.58:80 > common/retry: [dial tcp 49.7.253.58:80: operation was canceled] > common/retry: all retry attempts failed 2023/06/29 18:01:17 [Info] [3328705362] app/proxyman/outbound: failed to process outbound traffic > proxy/freedom: failed to open connection to tcp:49.7.253.65:80 > common/retry: [dial tcp 49.7.253.65:80: operation was canceled] > common/retry: all retry attempts failed 2023/06/29 18:01:18 [Debug] [3869254660] proxy/dokodemo: processing connection from: 192.168.99.110:53397 2023/06/29 18:01:18 [Info] [3869254660] proxy/dokodemo: received request for 192.168.99.110:53397 2023/06/29 18:01:18 [Info] [3869254660] app/dispatcher: sniffed domain: logdc.happyelements.cn 2023/06/29 18:01:18 [Info] [3869254660] app/dispatcher: taking detour [direct] for [tcp:logdc.happyelements.cn:443] 2023/06/29 18:01:18 [Debug] app/dns: domain logdc.happyelements.cn matches following rules: [geosite:cn(DNS idx:2)] 2023/06/29 18:01:18 [Debug] app/dns: domain logdc.happyelements.cn will use DNS in order: [UDP:127.0.0.1:15354] 2023/06/29 18:01:18 [Debug] app/dns: DNS cache is disabled. Querying IP for logdc.happyelements.cn at UDP:127.0.0.1:15354 2023/06/29 18:01:18 [Debug] app/dns: UDP:127.0.0.1:15354 querying DNS for: logdc.happyelements.cn. 2023/06/29 18:01:18 [Debug] transport/internet/udp: dispatch request to: udp:127.0.0.1:15354 2023/06/29 18:01:18 [Debug] transport/internet/udp: dispatch request to: udp:127.0.0.1:15354 2023/06/29 18:01:18 192.168.99.110:53397 accepted tcp:120.78.90.85:443 [tcp_redir -> direct] 2023/06/29 18:01:18 [Info] app/dns: UDP:127.0.0.1:15354 got answer: logdc.happyelements.cn. TypeA -> [112.74.166.213 120.79.199.175 120.78.90.85 120.79.6.51 120.78.141.229] 1.074371ms
2023/06/29 18:01:20 [Debug] app/dns: domain www.youtube.com will use the first DNS: [UDP:127.0.0.1:15355] 2023/06/29 18:01:20 [Info] [3663590643] app/dispatcher: taking detour [dns-out] for [udp:127.0.0.1:5335] 2023/06/29 18:01:20 [Debug] app/dns: DNS cache is disabled. Querying IP for www.youtube.com at UDP:127.0.0.1:15355 2023/06/29 18:01:20 [Info] [3663590643] proxy/dns: handling DNS traffic to udp:127.0.0.1:15355 2023/06/29 18:01:20 127.0.0.1:40637 accepted udp:127.0.0.1:5335 [dns-in -> dns-out] 2023/06/29 18:01:20 DNS accepted udp:127.0.0.1:15355 [dns-in1 -> direct] 2023/06/29 18:01:20 127.0.0.1:53986 accepted udp:127.0.0.1:5335 [dns-in -> dns-out] 2023/06/29 18:01:20 [Debug] app/dns: UDP:127.0.0.1:15355 querying DNS for: www.youtube.com. 2023/06/29 18:01:20 [Debug] [1493697461] proxy/dokodemo: processing connection from: 127.0.0.1:53986 2023/06/29 18:01:20 [Debug] transport/internet/udp: dispatch request to: udp:127.0.0.1:15355 2023/06/29 18:01:20 [Info] transport/internet/udp: establishing new connection for udp:127.0.0.1:15355 2023/06/29 18:01:20 [Info] [1493697461] proxy/dokodemo: received request for 127.0.0.1:53986 2023/06/29 18:01:20 [Info] app/dispatcher: taking detour [direct] for [udp:127.0.0.1:15355] 2023/06/29 18:01:20 [Info] [1493697461] app/dispatcher: taking detour [dns-out] for [udp:127.0.0.1:5335] 2023/06/29 18:01:20 [Info] [1493697461] proxy/dns: handling DNS traffic to udp:127.0.0.1:15355 2023/06/29 18:01:20 [Debug] app/dns: domain www.youtube.com will use the first DNS: [UDP:127.0.0.1:15355] 2023/06/29 18:01:20 [Debug] transport/internet: dialing to udp:127.0.0.1:15355 2023/06/29 18:01:20 [Debug] app/dns: DNS cache is disabled. Querying IP for www.youtube.com at UDP:127.0.0.1:15355 2023/06/29 18:01:20 [Debug] app/dns: UDP:127.0.0.1:15355 querying DNS for: www.youtube.com. 2023/06/29 18:01:20 [Debug] transport/internet/udp: dispatch request to: udp:127.0.0.1:15355 2023/06/29 18:01:20 [Info] proxy/freedom: connection opened to udp:127.0.0.1:15355, local endpoint [::]:41387, remote endpoint 127.0.0.1:15355 2023/06/29 18:01:20 [Info] app/dns: UDP:127.0.0.1:15355 got answer: www.youtube.com. TypeAAAA -> [] 1.074231ms 2023/06/29 18:01:20 [Debug] app/dns: UDP:127.0.0.1:15355 updating IP records for domain:www.youtube.com.
2023/06/29 18:01:20 [Info] app/dns: failed to lookup ip for domain www.youtube.com at server UDP:127.0.0.1:15355 > empty response
2023/06/29 18:01:20 [Info] [2341758022] proxy/socks: client UDP connection from udp:127.0.0.1:35823 2023/06/29 18:01:20 [Debug] [2341758022] proxy/socks: send packet to udp:127.0.0.1:5335 with 33 bytes 2023/06/29 18:01:20 [Debug] [2341758022] transport/internet/udp: dispatch request to: udp:127.0.0.1:5335 2023/06/29 18:01:20 [Info] transport/internet/udp: establishing new connection for udp:127.0.0.1:5335 2023/06/29 18:01:20 [Info] [2341758022] app/dispatcher: taking detour [direct] for [udp:127.0.0.1:5335] 2023/06/29 18:01:20 udp:127.0.0.1:35823 accepted udp:127.0.0.1:5335 [direct] 2023/06/29 18:01:20 [Debug] transport/internet: dialing to udp:127.0.0.1:5335 2023/06/29 18:01:20 [Info] [2341758022] proxy/freedom: connection opened to udp:127.0.0.1:5335, local endpoint [::]:56170, remote endpoint 127.0.0.1:5335 2023/06/29 18:01:20 [Debug] [2341758022] proxy/socks: writing back UDP response with 508 bytes 2023/06/29 18:01:20 [Info] app/dns: UDP:127.0.0.1:15355 got answer: www.youtube.com. TypeA -> [199.16.156.75] 3.319285ms 2023/06/29 18:01:20 [Debug] app/dns: UDP:127.0.0.1:15355 updating IP records for domain:www.youtube.com. 2023/06/29 18:01:20 [Debug] transport/internet/udp: UDP original destination: udp:119.28.28.28:53 2023/06/29 18:01:20 [Debug] transport/internet/udp: UDP original destination: udp:1.2.4.8:53 2023/06/29 18:01:20 [Debug] transport/internet/udp: UDP original destination: udp:180.76.76.76:53 2023/06/29 18:01:20 [Debug] transport/internet/udp: UDP original destination: udp:182.254.116.116:53 2023/06/29 18:01:20 [Debug] transport/internet/udp: UDP original destination: udp:114.114.115.115:53 2023/06/29 18:01:20 [Debug] [1562286742] proxy/dokodemo: processing connection from: 192.168.99.131:52647 2023/06/29 18:01:20 [Info] [1562286742] proxy/dokodemo: received request for 192.168.99.131:52647 2023/06/29 18:01:20 [Info] [1562286742] app/dispatcher: sniffed domain: www.youtube.com 2023/06/29 18:01:20 [Info] [1562286742] app/dispatcher: taking detour [default] for [tcp:www.youtube.com:443]
- 据我所见，只在CF的DNS重现（包括v6）
- 只在UDP时重现
- 重现时如图所示，输出empty response，紧接着有1条查询结果，但是dig命令收到的是空解析。不重启xray，永远都不会恢复。
- 绝大部分环境都能重现，也有不能重现的环境，所以根本原因还是不明。
- 重现时查询间隔为0.5s，间隔1s时不能重现。
测试环境：甲骨文首尔；RN圣何塞 1.1.1.1 延迟1ms 重现 1.0.0.1 延迟1ms 重现 9.9.9.9 延迟1ms 不能重现 //这个比1.1.1.1延迟还低 8.8.8.8 延迟33ms 不能重现 208.67.222.222 延迟33ms 不能重现 2606:4700:4700::1111 延迟1ms 重现 //CF的v6 2001:4860:4860::8888 延迟33ms 不能重现 //谷歌的v6 2620:fe::9 延迟1ms 不能重现 //Quad9的v6
failed to lookup ip for domain是这里输出的 https://github.com/XTLS/Xray-core/blob/6991c119e7551b3b19935fc3169da2dfb7be439b/app/dns/dns.go#L213
另外复现时是连查同一个域名吗，*ray 的 DNS 有缓存，这是把缓存给关了？
复现时是连查同一个域名，不重启xray该域名永远空解析，即使已经关了缓存。 关缓存是为了方便复现，不然要等正常结果的缓存过期。
使用的域名没有什么特殊的，随便一个都能复现。
想确定一下最初是否是 CF 的问题导致空解析，你可以写个简单程序向 CF 连查同一个域名试试吗？
就是Shell命令，持续运行绝对不会空解析
while true; do dig www.google.com @1.1.1.1; sleep 0.5; done