Incoming DoH queries take a long time on dnsdist 1.9

[JeffLessem-CU]

Sorry for the length of this, the question is simple, the rest is background information.

I'm having an issue with dnsdist 1.9.x where incoming DoH queries take multiple seconds to return an answer. Incoming queries on DoT or :53 are returned immediately.

Keeping everything else the same, dnsdist works perfectly on 1.8.x, but upgrading to 1.9.x I get the slow down on incoming DoH queries. I'm on aarch64, so I'm building my own dnsdist. I see the problem whether I use builder/build.sh in a git clone or build from the tar file. The system has 4 cores and 24GB or ram, so I don't think it is a resource issue causing the delay. The problems happen whether the incoming query is over ipv4 or ipv6.

My setup is somewhat complex, and definitely circular, but it keeps pihole from being internet facing, and the server is only listening on 443 and 853.

1. dnsdist accepts an incoming query
   1. queries from outside the host go to the "pihole" pool and are passed to a pihole running in a docker
      1. pihole makes a decision to resolve or block the query
         1. if blocked, pihole returns an address of 0.0.0.0 to dnsdist which returns it to the client
         2. if pihole resolves the query, then it forwards it back to dnsdist
   2. queries from the docker go to the "external" pool, which forwards it to one of its upstream servers
   3. if the pihole docker is down, then queries get forwarded to one of the upstream servers

The whole pihole thing does not seem to matter for this issue. If I turn off pihole, so dnsdist passes queries to an upstream server and then replies back to the client, I still get the slowdown. If the query is for a blocked address (answered by pihole) or a non-blocked address (answered by an upstream server) I still get the slowdown.

I'm using Apache as a reverse proxy to accept incoming DoH connections and pass them to dnsdist.

<Location /dns-query>
  ProxyPass h2c://localhost:5054/dns-query
  ProxyPassReverse http://localhost:5054/dns-query
  ProxyPreserveHost On
  RequestHeader set X-Real-IP expr=%{REMOTE_ADDR}
  RequestHeader set X-Forwarded-For expr=%{REMOTE_ADDR}
</Location>

The relevant parts of dnsdist.conf (lines split for readability)

addLocal("0.0.0.0", { maxInFlight="128" })
addLocal("[::]", { maxInFlight="128" })

-- do DoT
addTLSLocal('0.0.0.0:853', '/etc/dnsdist/cert.pem', '/etc/dnsdist/cert.key.pem', 
    { maxInFlight=128, releaseBuffers=true, minTLSVersion='tls1.2', additionalAddresses={'[::]:853'} })

-- do DoH but only http
addDOHLocal("127.0.0.1:5054", nil, nil, "/dns-query",
    { maxInFlight=128, reusePort=true, trustForwardedForHeader=true })

-- pihole in the docker is listening on 9153
newServer({address="127.0.0.1:9153", order=1, name="pihole", pool="pihole", 
    useClientSubnet=true, checkInterval=15, reconnectOnUp=true, 
    mustResolve=true, tcpFastOpen=true, tcpOnly=true })

-- external pool
newServer({address="169.254.169.254", order=2, qps=100, name="Local", 
    pool={ "external", "pihole" }, useClientSubnet=true, checkInterval=2, mustResolve=true })
newServer({address="1.0.0.1:443", order=2, qps=100, 
    pool={ "external", "pihole" }, name="Cloudflare-doh", useClientSubnet=false, checkInterval=2, 
    mustResolve=true, tls="openssl", subjectName="cloudflare-dns.com", 
    validateCertificates=true, dohPath="/dns-query", maxInFlight=128 })
newServer({address="[2606:4700:4700::1001]:443", order=2, qps=100, 
    pool={ "external", "pihole" }, name="Cloudflare-doh", useClientSubnet=false, 
    checkInterval=2, mustResolve=true, tls="openssl", subjectName="cloudflare-dns.com", 
    validateCertificates=true, dohPath="/dns-query", maxInFlight=128 })

setPoolServerPolicy(firstAvailable, "pihole")
setPoolServerPolicy(leastOutstanding, "external")

-- pass queries from docker to external servers
docker_NMG = newNMG()
docker_NMG:addMask("172.16.0.0/12")
docker_NMG:addMask("fe80::c025:b6ff:fe17:7382/64") -- really a routable ipv6 address
addAction(NetmaskGroupRule(docker_NMG), PoolAction("external"))
addAction(NotRule(NetmaskGroupRule(docker_NMG)), PoolAction("pihole"))
addAction(AllRule(), PoolAction("external"))

I didn't create this as an issue, because my setup is weird, but I still see the problem when everything except dnsdist and apache are eliminated. If any additional information will be useful to track down the problem, please let me know.

[mnordhoff]

Maybe Apache is trying to pass "localhost" to ::1 but dnsdist is only listening on 127.0.0.1?

[rgacogne]

I just tried to reproduce the issue with:

• Apache/2.4.58
• dnsdist 1.9.3
• sdig to send DoH queries

I'm afraid I cannot reproduce the issue, I get very fast response times. I would suggest getting rid of localhost in favor of 127.0.0.1 as suggested by Matt, although it did not cause any issue for me.

[JeffLessem-CU]

Thanks for the tips, I tried changing localhost in Apache to 127.0.0.1, but it doesn't make any difference.

On 1.9 everything works appropriately with library="h2o" on my addDOHLocal line. The reasons for moving away from h2o are clear, so this is in no way an argument to stay with it.

Running dnsdist -v (with nghttp2) I see a few things in the logs that are suspicious:

Got TCP connection from 127.0.0.1:51262
Packet cache miss for query for utexas.edu|A from 128.XYZ.XYZ.XYZ:0 (DoH, 51 bytes)
Got query for utexas.edu|A from 128.XYZ.XYZ.XYZ:0 (DoH, 53 bytes), relayed to pihole (127.0.0.1:9153)
Got answer from 127.0.0.1:9153, relayed to 128.XYZ.XYZ.XYZ:0 (DoH, 0 bytes), took 2694.16 us

It's relayed the response to me, but I don't get it. The query and relay happens again for AAAA, then I have

Timeout (read) from remote H2 client 127.0.0.1:51262
Timeout while reading from TCP client 127.0.0.1:51262

The sequence of query and timeout will repeat a few times, and eventually it will work. Any ideas about what could be causing TCP connections to break when using 1.9?

I'm using curl/doh to test things, but I can confirm a similar slowdown when using DoH from an Ipad. Running the debug output from doh doesn't give me any clues. It does ALPN, and chooses to talk to Apache over h2, but then just waits for a response while dnsdist is having timeouts. There don't seem to be any meaningful differences comparing the doh debug output from an h2o and nghttp2 session.

Are there any useful debug steps to take in dnsdist, from the console, command line, or conf file?

[rgacogne]

I agree the fact that it works well with h2o but not with nghttp2 points to a problem in DNSdist itself. The log messages in themselves are not particularly suspicious, it could be that DNSdist thinks the response has been sent while the client doesn't, and matches what you describe. I'll re-do my tests with curl/doh. In the meantime, would you be able to get a PCAP capture of the traffic between dnsdist and Apache, and ideally between the client and Apache, while you are sending a query?

[rgacogne]

You could also try strace -f -p <pid of dnsdist> while sending a query.

[rgacogne]

I see doh has a nice verbose mode that can be enabled with -v, perhaps also enable that in your next test so we can see what happens between doh and apache from the point of view of doh. In my own test this yields something like this:

== Info:   Trying 127.0.0.1:80...
== Info: Found bundle for host: 0x57fe27f8e180 [serially]
== Info: Server doesn't support multiplex (yet)
== Info: Hostname 127.0.0.1 was found in DNS cache
== Info:   Trying 127.0.0.1:80...
== Info: Connected to 127.0.0.1 (127.0.0.1) port 80
=> Send header, 0000000256 bytes (0x00000100)
0000: 50 4f 53 54 20 2f 64 6e 73 2d 71 75 65 72 79 20 POST /dns-query
0010: 48 54 54 50 2f 31 2e 31 0d 0a 48 6f 73 74 3a 20 HTTP/1.1..Host:
0020: 31 32 37 2e 30 2e 30 2e 31 0d 0a 55 73 65 72 2d 127.0.0.1..User-
0030: 41 67 65 6e 74 3a 20 63 75 72 6c 2d 64 6f 68 2f Agent: curl-doh/
0040: 31 2e 30 0d 0a 43 6f 6e 6e 65 63 74 69 6f 6e 3a 1.0..Connection:
0050: 20 55 70 67 72 61 64 65 2c 20 48 54 54 50 32 2d  Upgrade, HTTP2-
0060: 53 65 74 74 69 6e 67 73 0d 0a 55 70 67 72 61 64 Settings..Upgrad
0070: 65 3a 20 68 32 63 0d 0a 48 54 54 50 32 2d 53 65 e: h2c..HTTP2-Se
0080: 74 74 69 6e 67 73 3a 20 41 41 4d 41 41 41 42 6b ttings: AAMAAABk
0090: 41 41 51 41 6f 41 41 41 41 41 49 41 41 41 41 41 AAQAoAAAAAIAAAAA
00a0: 0d 0a 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 ..Content-Type:
00b0: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 64 6e 73 2d application/dns-
00c0: 6d 65 73 73 61 67 65 0d 0a 41 63 63 65 70 74 3a message..Accept:
00d0: 20 61 70 70 6c 69 63 61 74 69 6f 6e 2f 64 6e 73  application/dns
00e0: 2d 6d 65 73 73 61 67 65 0d 0a 43 6f 6e 74 65 6e -message..Conten
00f0: 74 2d 4c 65 6e 67 74 68 3a 20 33 30 0d 0a 0d 0a t-Length: 30....
=> Send data, 0000000030 bytes (0x0000001e)
0000: 00 00 01 00 00 01 00 00 00 00 00 00 08 70 6f 77 .............pow
0010: 65 72 64 6e 73 03 63 6f 6d 00 00 01 00 01       erdns.com.....
== Info: upload completely sent off: 30 bytes
== Info: Connected to 127.0.0.1 (127.0.0.1) port 80
=> Send header, 0000000256 bytes (0x00000100)
0000: 50 4f 53 54 20 2f 64 6e 73 2d 71 75 65 72 79 20 POST /dns-query
0010: 48 54 54 50 2f 31 2e 31 0d 0a 48 6f 73 74 3a 20 HTTP/1.1..Host:
0020: 31 32 37 2e 30 2e 30 2e 31 0d 0a 55 73 65 72 2d 127.0.0.1..User-
0030: 41 67 65 6e 74 3a 20 63 75 72 6c 2d 64 6f 68 2f Agent: curl-doh/
0040: 31 2e 30 0d 0a 43 6f 6e 6e 65 63 74 69 6f 6e 3a 1.0..Connection:
0050: 20 55 70 67 72 61 64 65 2c 20 48 54 54 50 32 2d  Upgrade, HTTP2-
0060: 53 65 74 74 69 6e 67 73 0d 0a 55 70 67 72 61 64 Settings..Upgrad
0070: 65 3a 20 68 32 63 0d 0a 48 54 54 50 32 2d 53 65 e: h2c..HTTP2-Se
0080: 74 74 69 6e 67 73 3a 20 41 41 4d 41 41 41 42 6b ttings: AAMAAABk
0090: 41 41 51 41 6f 41 41 41 41 41 49 41 41 41 41 41 AAQAoAAAAAIAAAAA
00a0: 0d 0a 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 ..Content-Type:
00b0: 61 70 70 6c 69 63 61 74 69 6f 6e 2f 64 6e 73 2d application/dns-
00c0: 6d 65 73 73 61 67 65 0d 0a 41 63 63 65 70 74 3a message..Accept:
00d0: 20 61 70 70 6c 69 63 61 74 69 6f 6e 2f 64 6e 73  application/dns
00e0: 2d 6d 65 73 73 61 67 65 0d 0a 43 6f 6e 74 65 6e -message..Conten
00f0: 74 2d 4c 65 6e 67 74 68 3a 20 33 30 0d 0a 0d 0a t-Length: 30....
=> Send data, 0000000030 bytes (0x0000001e)
0000: 00 00 01 00 00 01 00 00 00 00 00 00 08 70 6f 77 .............pow
0010: 65 72 64 6e 73 03 63 6f 6d 00 00 1c 00 01       erdns.com.....
== Info: upload completely sent off: 30 bytes
<= Recv header, 0000000017 bytes (0x00000011)
0000: 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d HTTP/1.1 200 OK.
0010: 0a                                              .
<= Recv header, 0000000037 bytes (0x00000025)
0000: 44 61 74 65 3a 20 46 72 69 2c 20 32 36 20 41 70 Date: Fri, 26 Ap
0010: 72 20 32 30 32 34 20 30 37 3a 35 30 3a 30 31 20 r 2024 07:50:01
0020: 47 4d 54 0d 0a                                  GMT..
<= Recv header, 0000000016 bytes (0x00000010)
0000: 53 65 72 76 65 72 3a 20 41 70 61 63 68 65 0d 0a Server: Apache..
<= Recv header, 0000000039 bytes (0x00000027)
0000: 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70 Content-Type: ap
0010: 70 6c 69 63 61 74 69 6f 6e 2f 64 6e 73 2d 6d 65 plication/dns-me
0020: 73 73 61 67 65 0d 0a                            ssage..
<= Recv header, 0000000029 bytes (0x0000001d)
0000: 43 61 63 68 65 2d 43 6f 6e 74 72 6f 6c 3a 20 6d Cache-Control: m
0010: 61 78 2d 61 67 65 3d 33 36 30 30 0d 0a          ax-age=3600..
<= Recv header, 0000000020 bytes (0x00000014)
0000: 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20 Content-Length:
0010: 39 37 0d 0a                                     97..
<= Recv header, 0000000002 bytes (0x00000002)
0000: 0d 0a                                           ..
<= Recv data, 0000000097 bytes (0x00000061)
0000: 00 00 81 80 00 01 00 00 00 01 00 00 08 70 6f 77 .............pow
0010: 65 72 64 6e 73 03 63 6f 6d 00 00 1c 00 01 c0 0c erdns.com.......
0020: 00 06 00 01 00 00 0e 10 00 37 0f 70 64 6e 73 2d .........7.pdns-
0030: 70 75 62 6c 69 63 2d 6e 73 31 c0 0c 0e 70 65 74 public-ns1...pet
0040: 65 72 2e 76 61 6e 2e 64 69 6a 6b c0 0c 78 a4 70 er.van.dijk..x.p
0050: 05 00 00 2a 30 00 00 0e 10 00 09 3a 80 00 00 0e ...*0......:....
0060: 10                                              .
== Info: Connection #1 to host 127.0.0.1 left intact
<= Recv header, 0000000017 bytes (0x00000011)
0000: 48 54 54 50 2f 31 2e 31 20 32 30 30 20 4f 4b 0d HTTP/1.1 200 OK.
0010: 0a                                              .
<= Recv header, 0000000037 bytes (0x00000025)
0000: 44 61 74 65 3a 20 46 72 69 2c 20 32 36 20 41 70 Date: Fri, 26 Ap
0010: 72 20 32 30 32 34 20 30 37 3a 35 30 3a 30 31 20 r 2024 07:50:01
0020: 47 4d 54 0d 0a                                  GMT..
<= Recv header, 0000000016 bytes (0x00000010)
0000: 53 65 72 76 65 72 3a 20 41 70 61 63 68 65 0d 0a Server: Apache..
<= Recv header, 0000000039 bytes (0x00000027)
0000: 43 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70 Content-Type: ap
0010: 70 6c 69 63 61 74 69 6f 6e 2f 64 6e 73 2d 6d 65 plication/dns-me
0020: 73 73 61 67 65 0d 0a                            ssage..
<= Recv header, 0000000028 bytes (0x0000001c)
0000: 43 61 63 68 65 2d 43 6f 6e 74 72 6f 6c 3a 20 6d Cache-Control: m
0010: 61 78 2d 61 67 65 3d 33 30 30 0d 0a             ax-age=300..
<= Recv header, 0000000020 bytes (0x00000014)
0000: 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20 Content-Length:
0010: 36 32 0d 0a                                     62..
<= Recv header, 0000000002 bytes (0x00000002)
0000: 0d 0a                                           ..
<= Recv data, 0000000062 bytes (0x0000003e)
0000: 00 00 81 80 00 01 00 02 00 00 00 00 08 70 6f 77 .............pow
0010: 65 72 64 6e 73 03 63 6f 6d 00 00 01 00 01 c0 0c erdns.com.......
0020: 00 01 00 01 00 00 01 2c 00 04 c7 3c 67 3d c0 0c .......,...<g=..
0030: 00 01 00 01 00 00 01 2c 00 04 c7 3c 67 a1       .......,...<g.
== Info: Connection #0 to host 127.0.0.1 left intact
[powerdns.com]
TTL: 300 seconds
A: 199.60.103.61
A: 199.60.103.161

[JeffLessem-CU]

Finally had the opportunity to do some packet capturing. Here are the various logs.

I ran doh -4 -v cnn.com https://example.com/dns-query and it returned immediately. Then I ran doh -4 -v utexas.edu https://example.com/dns-query and got the problematic delay. It seems that often the first query will return quickly, and perhaps cached queries also return quickly.

IPs should be:

• 192.168.0.1 the client running a DoH query
• 80.0.0.1 the server with dnsdist
• 172.30.0.2 The docker running a PiHole

pcap file from the client client193_ANONYMIZED.pcapng.gz
pcap file between Apache and dnsdist dnsdist193.pcap.gz
dnsdist193.log
doh.log

[rgacogne]

Thanks a lot! In at least two streams I see a PING HTTP/2 request sent by Apache HTTPd to DNSdist just before trying to reuse a connection and no response from DNSdist, which sounds like a bug indeed. nghttp2 is supposed to automatically reply to these queries so I'm guessing it doesn't get the packet, probably because DNSdist is somehow no longer reading from the socket. I have not been able to reproduce this yet but I have an idea, so I'll look into it in the next coming days.

[rgacogne]

The specific PING issue is solved by #14128 in my tests (it took a while to configure Apache HTTPd in such a way that to reproduce the issue but I finally managed). I'm unfortunately not sure it will solve your issue at all since in my tests Apache HTTPd re-established a new connection quite quickly when the response to the PING frame did not arrive, but I do not see that happening in your traces so perhaps something is different there.

[JeffLessem-CU]

Thanks, that change seems to correct the issue, at least in my testing. I was using the entire tree in your fork with all of the other changes, not just the few lines in 14128.

[rgacogne]

Thanks a lot for testing and reporting back!