search

AdguardTeam / dnsproxy

Simple DNS proxy with DoH, DoT, DoQ and DNSCrypt support
Apache License 2.0
2.37k stars 246 forks source link

a good amount of chance failing to resolve when using http3/h3 #283

Closed cattyhouse closed 1 year ago

cattyhouse commented 1 year ago

There is a good amount of chance failing to resolve when using http3/h3, but not always, it happens randomly.

command and args

/usr/local/bin/dnsproxy -l 127.0.0.1 -p 53888 -u h3://8.8.8.8/dns-query -v

tested versions

v045.0 - v0.46.0

test method

dig @127.0.0.1 -p 53888 mirrors.ocf.berkeley.edu

some keywords from log

Connection max age expired
failed to exchange
error handling DNS (udp)
0-RTT rejected

logs when failed to resolve

# log one

Oct 19 07:22:45 n2 dnsproxy[6528]: 2022/10/19 07:22:45 6528#118 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).udpHandlePacket(): Start handling new UDP packet from 127.0.0.1:42875
Oct 19 07:22:45 n2 dnsproxy[6528]: 2022/10/19 07:22:45 6528#118 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 27199
Oct 19 07:22:45 n2 dnsproxy[6528]: ;; flags: rd ad; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
Oct 19 07:22:45 n2 dnsproxy[6528]: ;; OPT PSEUDOSECTION:
Oct 19 07:22:45 n2 dnsproxy[6528]: ; EDNS: version 0; flags: ; udp: 1232
Oct 19 07:22:45 n2 dnsproxy[6528]: ; COOKIE: 053f847c1f1956f5
Oct 19 07:22:45 n2 dnsproxy[6528]: ;; QUESTION SECTION:
Oct 19 07:22:45 n2 dnsproxy[6528]: ;mirrors.ocf.berkeley.edu.   IN       A
Oct 19 07:22:45 n2 dnsproxy[6528]: 2022/10/19 07:22:45 6528#118 [debug] https://8.8.8.8:443/dns-query: sending request A mirrors.ocf.berkeley.edu.
Oct 19 07:22:45 n2 dnsproxy[6528]: 2022/10/19 07:22:45 6528#118 [debug] https://8.8.8.8:443/dns-query: response: requesting https://8.8.8.8:443/dns-query: Get_0rtt "https://8.8.8.8:443/dns-query?dns=AAABIAABAAAAAAABB21pcnJvcnMDb2NmCGJlcmtlbGV5A2VkdQAAAQABAAApBNAAAAAAAAwACgAIBT-EfB8ZVvU": NO_ERROR: 168:Connection max age expired
Oct 19 07:22:45 n2 dnsproxy[6528]: 2022/10/19 07:22:45 6528#118 [debug] github.com/AdguardTeam/dnsproxy/proxy.exchangeWithUpstream(): upstream https://8.8.8.8:443/dns-query failed to exchange ;mirrors.ocf.berkeley.edu.    IN       A in 823.431µs. Cause: requesting https://8.8.8.8:443/dns-query: Get_0rtt "https://8.8.8.8:443/dns-query?dns=AAABIAABAAAAAAABB21pcnJvcnMDb2NmCGJlcmtlbGV5A2VkdQAAAQABAAApBNAAAAAAAAwACgAIBT-EfB8ZVvU": NO_ERROR: 168:Connection max age expired
Oct 19 07:22:45 n2 dnsproxy[6528]: 2022/10/19 07:22:45 6528#118 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).replyFromUpstream(): RTT: 1.163646ms
Oct 19 07:22:45 n2 dnsproxy[6528]: 2022/10/19 07:22:45 6528#118 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: SERVFAIL, id: 27199
Oct 19 07:22:45 n2 dnsproxy[6528]: ;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0
Oct 19 07:22:45 n2 dnsproxy[6528]: ;; QUESTION SECTION:
Oct 19 07:22:45 n2 dnsproxy[6528]: ;mirrors.ocf.berkeley.edu.   IN       A
Oct 19 07:22:45 n2 dnsproxy[6528]: 2022/10/19 07:22:45 6528#118 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).udpHandlePacket(): error handling DNS (udp) request: talking to dns upstream: requesting https://8.8.8.8:443/dns-query: Get_0rtt "https://8.8.8.8:443/dns-query?dns=AAABIAABAAAAAAABB21pcnJvcnMDb2NmCGJlcmtlbGV5A2VkdQAAAQABAAApBNAAAAAAAAwACgAIBT-EfB8ZVvU": NO_ERROR: 168:Connection max age expired

# log two

Oct 19 07:24:45 n2 dnsproxy[6528]: 2022/10/19 07:24:45 6528#90 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).udpHandlePacket(): Start handling new UDP packet from 127.0.0.1:11732
Oct 19 07:24:45 n2 dnsproxy[6528]: 2022/10/19 07:24:45 6528#90 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 48980
Oct 19 07:24:45 n2 dnsproxy[6528]: ;; flags: rd ad; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
Oct 19 07:24:45 n2 dnsproxy[6528]: ;; OPT PSEUDOSECTION:
Oct 19 07:24:45 n2 dnsproxy[6528]: ; EDNS: version 0; flags: ; udp: 1232
Oct 19 07:24:45 n2 dnsproxy[6528]: ; COOKIE: ea53ed148d3a84f3
Oct 19 07:24:45 n2 dnsproxy[6528]: ;; QUESTION SECTION:
Oct 19 07:24:45 n2 dnsproxy[6528]: ;mirrors.ocf.berkeley.edu.   IN       A
Oct 19 07:24:45 n2 dnsproxy[6528]: 2022/10/19 07:24:45 6528#90 [debug] github.com/AdguardTeam/dnsproxy/upstream.(*bootstrapper).createDialContext.func1(): Dialing to 8.8.8.8:443
Oct 19 07:24:45 n2 dnsproxy[6528]: 2022/10/19 07:24:45 6528#90 [debug] github.com/AdguardTeam/dnsproxy/upstream.(*bootstrapper).createDialContext.func1(): dialer has successfully initialized connection to 8.8.8.8:443 in 230.212µs
Oct 19 07:24:45 n2 dnsproxy[6528]: 2022/10/19 07:24:45 6528#90 [debug] using HTTP/3 for this upstream: QUIC was faster
Oct 19 07:24:45 n2 dnsproxy[6528]: 2022/10/19 07:24:45 6528#90 [debug] https://8.8.8.8:443/dns-query: sending request A mirrors.ocf.berkeley.edu.
Oct 19 07:24:46 n2 dnsproxy[6528]: 2022/10/19 07:24:46 6528#90 [debug] https://8.8.8.8:443/dns-query: response: requesting https://8.8.8.8:443/dns-query: Get_0rtt "https://8.8.8.8:443/dns-query?dns=AAABIAABAAAAAAABB21pcnJvcnMDb2NmCGJlcmtlbGV5A2VkdQAAAQABAAApBNAAAAAAAAwACgAI6lPtFI06hPM": 0-RTT rejected
Oct 19 07:24:46 n2 dnsproxy[6528]: 2022/10/19 07:24:46 6528#90 [debug] github.com/AdguardTeam/dnsproxy/proxy.exchangeWithUpstream(): upstream https://8.8.8.8:443/dns-query failed to exchange ;mirrors.ocf.berkeley.edu.     IN       A in 218.087374ms. Cause: requesting https://8.8.8.8:443/dns-query: Get_0rtt "https://8.8.8.8:443/dns-query?dns=AAABIAABAAAAAAABB21pcnJvcnMDb2NmCGJlcmtlbGV5A2VkdQAAAQABAAApBNAAAAAAAAwACgAI6lPtFI06hPM": 0-RTT rejected
Oct 19 07:24:46 n2 dnsproxy[6528]: 2022/10/19 07:24:46 6528#90 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).replyFromUpstream(): RTT: 220.799868ms
Oct 19 07:24:46 n2 dnsproxy[6528]: 2022/10/19 07:24:46 6528#90 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: SERVFAIL, id: 48980
Oct 19 07:24:46 n2 dnsproxy[6528]: ;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0
Oct 19 07:24:46 n2 dnsproxy[6528]: ;; QUESTION SECTION:
Oct 19 07:24:46 n2 dnsproxy[6528]: ;mirrors.ocf.berkeley.edu.   IN       A
Oct 19 07:24:46 n2 dnsproxy[6528]: 2022/10/19 07:24:46 6528#90 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).udpHandlePacket(): error handling DNS (udp) request: talking to dns upstream: requesting https://8.8.8.8:443/dns-query: Get_0rtt "https://8.8.8.8:443/dns-query?dns=AAABIAABAAAAAAABB21pcnJvcnMDb2NmCGJlcmtlbGV5A2VkdQAAAQABAAApBNAAAAAAAAwACgAI6lPtFI06hPM": 0-RTT rejected
ameshkov commented 1 year ago

Hmm, 0-RTT rejected is kind of expected, dnsproxy should retry when it encounters it.

Connection max age expired is something new, we'll check it out.

cattyhouse commented 1 year ago

also noted that in this case only h3 is used. but log shows QUIC was faster, seems like it also did a http2 probe, which is no need.

ameshkov commented 1 year ago

No worries, no probe was made actually, it's just how it's logged.

cattyhouse commented 1 year ago

thanks for the fix! tested dozens, 100% success.

ameshkov commented 1 year ago

Thanks for the report:)