Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Retry failures on staled DoH3 clients #340

Closed
lifenjoiner opened this issue Jul 14, 2023 · 0 comments
Closed

Retry failures on staled DoH3 clients #340

lifenjoiner opened this issue Jul 14, 2023 · 0 comments

Comments

@lifenjoiner
Copy link

When exploring quic-go/quic-go#3943, I got the following failure for Query2.

logs
D:\DNS\dnsproxy>set QUIC_GO_LOG_LEVEL=info

D:\DNS\dnsproxy>dnsproxy.exe -l 127.0.0.1 -p 58053 -u h3://cloudflare-dns.com/dns-query -v
2023/07/14 18:52:56 8524#1 [info] Starting dnsproxy v0.51.0
2023/07/14 18:52:56 8524#1 [debug] Upstream 0: https://cloudflare-dns.com:443/dns-query
2023/07/14 18:52:56 8524#1 [info] dnsproxy: starting dns proxy server
2023/07/14 18:52:56 8524#1 [info] dnsproxy: cache: disabled
2023/07/14 18:52:56 8524#1 [info] dnsproxy: creating udp server socket 127.0.0.1:58053
2023/07/14 18:52:56 8524#1 [info] dnsproxy: listening to udp://127.0.0.1:58053
2023/07/14 18:52:56 8524#1 [info] dnsproxy: creating tcp server socket 127.0.0.1:58053
2023/07/14 18:52:56 8524#1 [info] dnsproxy: listening to tcp://127.0.0.1:58053
2023/07/14 18:52:56 8524#7 [info] dnsproxy: entering tcp listener loop on 127.0.0.1:58053
2023/07/14 18:52:56 8524#6 [info] dnsproxy: entering udp listener loop on 127.0.0.1:58053

Query1.~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

2023/07/14 18:53:00 8524#18 [debug] dnsproxy: handling new udp packet from 127.0.0.1:56292
2023/07/14 18:53:00 8524#18 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 37439
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;github.com.    IN       A

2023/07/14 18:53:00 8524#18 [debug] dnsproxy: cache: disabled; not caching
2023/07/14 18:53:00 8524#18 [debug] creating a new http client
2023/07/14 18:53:00 8524#18 [debug] parallel lookup: lookup for cloudflare-dns.com succeeded in 213.602ms: [::ffff:104.16.249.249 ::ffff:104.16.248.249]
2023/07/14 18:53:00 8524#18 [debug] bootstrap: dialing [::ffff:104.16.248.249]:443 (1/2)
2023/07/14 18:53:00 8524#18 [debug] bootstrap: connection to [::ffff:104.16.248.249]:443 succeeded in 973.8μs
2023/07/14 18:53:00 8524#18 [debug] using HTTP/3 for this upstream: QUIC was faster
2023/07/14 18:53:00 8524#18 [debug] https://cloudflare-dns.com:443/dns-query: sending request over udp: A github.com.
2023/07/14 18:53:00 client Starting new connection to cloudflare-dns.com ([::]:52648 -> 104.16.248.249:443), source connection ID (empty), destination connection ID 12aac591e4226a68bc8ae897b0, version v1
2023/07/14 18:53:01 client Queueing packet (1053 bytes) for later decryption
2023/07/14 18:53:01 8524#18 [debug] https://cloudflare-dns.com:443/dns-query: response received over udp: ok
2023/07/14 18:53:01 8524#18 [debug] time.Duration.Milliseconds(): upstream https://cloudflare-dns.com:443/dns-query successfully finished exchange of ;github.com.      IN       A. Elapsed 372.7348ms.
2023/07/14 18:53:01 8524#18 [debug] proxy: replying from upstream: rtt is 373.8497ms
2023/07/14 18:53:01 8524#18 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 37439
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;github.com.    IN       A

;; ANSWER SECTION:
github.com.     14      IN      A       20.205.243.166

2023/07/14 18:56:01 client Peer closed connection with error: Application error 0x100 (remote)
2023/07/14 18:56:01 client Connection 12aac591e4226a68bc8ae897b0 closed.

Query2.~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

2023/07/14 18:58:37 8524#55 [debug] dnsproxy: handling new udp packet from 127.0.0.1:51618
2023/07/14 18:58:37 8524#55 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 13852
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;github.com.    IN       A

2023/07/14 18:58:37 8524#55 [debug] dnsproxy: cache: disabled; not caching
2023/07/14 18:58:37 8524#55 [debug] https://cloudflare-dns.com:443/dns-query: sending request over udp: A github.com.
2023/07/14 18:58:37 8524#55 [debug] https://cloudflare-dns.com:443/dns-query: response received over udp: requesting https://cloudflare-dns.com:443/dns-query: Get "https://cloudflare-dns.com:443/dns-query?dns=AAABAAABAAAAAAAABmdpdGh1YgNjb20AAAEAAQ": Application error 0x100 (remote)
2023/07/14 18:58:37 8524#55 [debug] re-creating the http client due to requesting https://cloudflare-dns.com:443/dns-query: Get "https://cloudflare-dns.com:443/dns-query?dns=AAABAAABAAAAAAAABmdpdGh1YgNjb20AAAEAAQ": Application error 0x100 (remote)
2023/07/14 18:58:37 8524#55 [debug] bootstrap: dialing [::ffff:104.16.248.249]:443 (1/2)
2023/07/14 18:58:37 8524#55 [debug] bootstrap: connection to [::ffff:104.16.248.249]:443 succeeded in 0s
2023/07/14 18:58:37 8524#55 [debug] using HTTP/3 for this upstream: QUIC was faster
2023/07/14 18:58:37 8524#55 [debug] github.com/AdguardTeam/dnsproxy/proxy.exchangeWithUpstream(): upstream https://cloudflare-dns.com:443/dns-query failed to exchange ;github.com.     IN       A in 2.4137ms. Cause: requesting https://cloudflare-dns.com:443/dns-query: Get "https://cloudflare-dns.com:443/dns-query?dns=AAABAAABAAAAAAAABmdpdGh1YgNjb20AAAEAAQ": Application error 0x100 (remote)
2023/07/14 18:58:37 8524#55 [debug] proxy: replying from upstream: rtt is 2.9802ms
2023/07/14 18:58:37 8524#55 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: SERVFAIL, id: 13852
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;github.com.    IN       A

2023/07/14 18:58:37 8524#55 [debug] dnsproxy: handling dns (proto udp) request: talking to dns upstream: requesting https://cloudflare-dns.com:443/dns-query: Get "https://cloudflare-dns.com:443/dns-query?dns=AAABAAABAAAAAAAABmdpdGh1YgNjb20AAAEAAQ": Application error 0x100 (remote)

Query3.~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

2023/07/14 19:00:21 8524#56 [debug] dnsproxy: handling new udp packet from 127.0.0.1:52637
2023/07/14 19:00:21 8524#56 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): IN: ;; opcode: QUERY, status: NOERROR, id: 13473
;; flags: rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;github.com.    IN       A

2023/07/14 19:00:21 8524#56 [debug] dnsproxy: cache: disabled; not caching
2023/07/14 19:00:21 8524#56 [debug] https://cloudflare-dns.com:443/dns-query: sending request over udp: A github.com.
2023/07/14 19:00:21 client Starting new connection to cloudflare-dns.com ([::]:52638 -> 104.16.248.249:443), source connection ID (empty), destination connection ID 67679a0adc74b181fe214057ff, version v1
2023/07/14 19:00:21 8524#56 [debug] https://cloudflare-dns.com:443/dns-query: response received over udp: ok
2023/07/14 19:00:21 8524#56 [debug] time.Duration.Milliseconds(): upstream https://cloudflare-dns.com:443/dns-query successfully finished exchange of ;github.com.      IN       A. Elapsed 44.9088ms.
2023/07/14 19:00:21 8524#56 [debug] proxy: replying from upstream: rtt is 46.0905ms
2023/07/14 19:00:21 8524#56 [debug] github.com/AdguardTeam/dnsproxy/proxy.(*Proxy).logDNSMessage(): OUT: ;; opcode: QUERY, status: NOERROR, id: 13473
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;github.com.    IN       A

;; ANSWER SECTION:
github.com.     35      IN      A       20.205.243.166

To reproduce on Windows:

  1. set QUIC_GO_LOG_LEVEL=info
  2. dnsproxy.exe -l 127.0.0.1 -p 58053 -u h3://cloudflare-dns.com/dns-query -v
  3. Query "github.com". Query1.
  4. Wait until client Connection * closed. shows up.
  5. Redo query "github.com". It fails! <<<--------------------------- Query2.
  6. Query "github.com" the 3rd time. It succeeds. Query3.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant