Garbage response times for many (almost half at times) CNAME answers

Expected Behaviour:

Pi-hole measures the response time of any query accurately in units of 1/10 ms and displays it in the Query Log.

Actual Behaviour:

The response times for queries that end in CNAME records are really unreliable. Many of the response times are displayed as 0.0 ms, presumably because response times greater than 30 min are filtered out. But every now and again the reported response times are less than 30 minutes and really highlight the issue.

Of these 39 A and AAAA queries in a 10 minute interval whose responses were recorded as CNAMEs 19 (almost half) show a ridiculous response time of over 25 minutes despite a second query for the same domain showing a reasonable response time of mostly less than 200 milliseconds.

Here is a second equivalent case 2 intervals later where 8/18 recorded responses are shown as 0.0 ms.

The issue seems to come and go without any discernible pattern. Most of the time it's just a few queries here and there with a wrong response time but other times it's almost half of all queries.

Some of these domains point at lengthy CNAME chains with every link having a shorter TTL, other's CNAME records point directly at A or AAAA resources with identical TTLs without additional CNAMEs in between.


I experimented with removing the filter that I linked to above and found that in all cases I could find the response time is very close to the timestamp of the query, resulting in response times of half a century.

But when I do catch these low but still ridiculous times they seem to get gradually worse over time:
40 ms followed by 15 seconds.


2 minutes later: 200 ms followed by 147 seconds

Another 3.5 minutes later: response times of almost 6 minutes

Again 2.5 minutes later: 3.9 ms (probs cached by unbound) followed by 8.5 minutes

7 minutes later: 15 minute response time

10 minutes later: 25 minute response time

4.5 minutes later: the largest response time displayed is 29.8 minutes

Everything else after that shows 0.0 ms in the Query Log because of the filter. Maybe the timestamp of when the query is send upstream isn't updated and just freezes. I have no idea why it would only affect one query of the A/AAAA pairs and not the other. And as stated above, it doesn't happen to all pairs of queries either.

In my case around 11% of all queries are affected by this.

$ echo ">getallqueries >quit" | nc 127.0.0.1 4711 | awk '{if($8 == "0"){count+=1}}; {total+=1} END {print total,count}'
21948 2499

Edit: Just thought about maybe checking against all queries isn't really useful. So here are the numbers for just forwarded queries that resulted in a CNAME reply with 0 response time:

$ echo ">getallqueries >quit" | nc 127.0.0.1 4711 | awk '{if($5 == "2" && $7 == "3"){if($8 == "0"){count+=1}; {total+=1}}} END {print total,count}'
5612 1081

That's worse actually, just under 20%.

Debug Token:

[✓] Your debug token is: https://tricorder.pi-hole.net/skHFU0ED/

Thanks for your report. It can have happened that we calculated the response time more than once when a query was partially answered from cache but still needs to get forwarded because of some shorter lived children. Just as you've found. This was broken in the last dnsmasq update, i.e., FTL v5.10.1 when the internal handling of how cached CNAMEs are handled changed.

Please try whether

pihole checkout ftl fix/reponse_times

fixes this for you.


edit When testing, please ensure pihole-FTL -v has the commit ID 610c32ec

Nope, still see a lot of 0.0 ms for CNAME replies.

Pi-hole version is v5.5 (Latest: v5.5)
AdminLTE version is in detached HEAD state at v5.7 (Latest: v5.7)
FTL version is fix/reponse_times vDev-610c32e (Latest: v5.10.2)

Can you show us the correlated /var/log/pihole.log lines? Just thinking that if the replies are not properly logged, we may not know when the reply arrived.

0.0 has now the meaning of "no reply so far". That changed as I removed the artificial upper boundary for the reply time.

Oct 11 19:33:57 dnsmasq[16117]: query[A] www.youtube.com from 192.168.178.20
Oct 11 19:33:57 dnsmasq[16117]: cached www.youtube.com is <CNAME>
Oct 11 19:33:57 dnsmasq[16117]: forwarded www.youtube.com to 1.1.1.1
Oct 11 19:33:57 dnsmasq[16117]: query[AAAA] www.youtube.com from 192.168.178.20
Oct 11 19:33:57 dnsmasq[16117]: forwarded www.youtube.com to 1.1.1.1
Oct 11 19:33:57 dnsmasq[16117]: reply www.youtube.com is <CNAME>
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 142.250.74.206
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 142.250.184.238
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 142.250.186.174
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 142.250.186.110
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 172.217.18.110
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 142.250.184.206
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 216.58.212.174
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 142.250.186.46
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 172.217.23.110
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 216.58.212.142
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 172.217.16.142
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 142.250.186.142
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 142.250.185.238
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 142.250.185.78
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 142.250.186.78
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 142.250.181.238
Oct 11 19:33:57 dnsmasq[16117]: reply www.youtube.com is <CNAME>
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 2a00:1450:4001:80e::200e
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 2a00:1450:4001:80f::200e
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 2a00:1450:4001:810::200e
Oct 11 19:33:57 dnsmasq[16117]: reply youtube-ui.l.google.com is 2a00:1450:4001:811::200e

It looks like it was logged properly.

Yeah, indeed. Thanks for the testing domain, I should be able to reproduce this locally in 5 minutes...

www.youtube.com.	57388	IN	CNAME	youtube-ui.l.google.com.
youtube-ui.l.google.com. 299	IN	A	142.250.186.78
youtube-ui.l.google.com. 299	IN	A	142.250.186.46
youtube-ui.l.google.com. 299	IN	A	142.250.74.206
youtube-ui.l.google.com. 299	IN	A	172.217.16.142
youtube-ui.l.google.com. 299	IN	A	142.250.181.238
youtube-ui.l.google.com. 299	IN	A	142.250.184.238
youtube-ui.l.google.com. 299	IN	A	142.250.185.238
youtube-ui.l.google.com. 299	IN	A	142.250.185.206
youtube-ui.l.google.com. 299	IN	A	142.250.185.174
youtube-ui.l.google.com. 299	IN	A	142.250.185.142
youtube-ui.l.google.com. 299	IN	A	142.250.185.110
youtube-ui.l.google.com. 299	IN	A	142.250.185.78
youtube-ui.l.google.com. 299	IN	A	216.58.212.142
youtube-ui.l.google.com. 299	IN	A	172.217.23.110
youtube-ui.l.google.com. 299	IN	A	142.250.184.206
youtube-ui.l.google.com. 299	IN	A	172.217.18.110

I was not able to reproduce it this easily. The result looks as expected (I'm using the same FTL version you're using here):

Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 query[A] www.youtube.com from 192.168.2.206
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 forwarded www.youtube.com to 127.0.0.1
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 validation result is INSECURE
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply www.youtube.com is <CNAME>
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 172.217.18.110
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 142.250.184.206
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 172.217.23.110
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 216.58.212.142
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 142.250.185.78
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 142.250.185.110
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 142.250.185.142
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 142.250.185.174
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 142.250.185.206
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 142.250.185.238
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 142.250.184.238
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 142.250.181.238
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 172.217.16.142
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 142.250.74.206
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 142.250.186.46
Oct 11 21:29:42 dnsmasq[502755]: 17581 192.168.2.206/54555 reply youtube-ui.l.google.com is 142.250.186.78

I'd like you to add

DEBUG_QUERIES=true
DEBUG_FLAGS=true

to /etc/pihole/pihole-FTL.conf

as well as changing

log-queries

to

log-queries=extra

in /etc/dnsmasq.d/01-pihole.conf and restart FTL to enable the config changes.

Next time you see it, please include all the relevant lines from beoth pihole.log and pihole-FTL.log. It should help with identifying what the difference between your and my test were and where to look at.


edit I just realized your log output misses a validation message. Are you using DNSSEC in Pi-hole?
It's already too late for me today to test various configurations. I always have DNSSEC enabled on all of my devices and that may already be the difference because it changes how some queries are cached or forwarded (everything always have to be verifiable). A noteworthy difference is

and

(no cached CNAME is logged)

In my OP I did, yes. But I have disabled it afterwards and changed upstream servers to Cloudflare (1st and 3rd checkbox) to avoid any weirdness that comes from unbound doing it's own caching and prefetching. But as you can see in my replies, the issue persists in either case.

You can even see that difference in my log above. The CNAME reply for the A query was cached and had a response time of 0 but the one for the AAAA query was not cached and had a response time of 42.2 ms.
The issue also doesn't happen consistently, that's why every screenshot is of a different domain. :sweat_smile:


Nvm, managed to trigger www.youtube.com again (just opened a private window of Firefox and went to that domain, took a couple tries though).

pihole.log

Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 query[A] www.youtube.com from 192.168.178.20
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 cached www.youtube.com is <CNAME>
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 forwarded www.youtube.com to 1.1.1.1
Oct 11 22:32:25 dnsmasq[18362]: 1261 192.168.178.20/58875 query[AAAA] www.youtube.com from 192.168.178.20
Oct 11 22:32:25 dnsmasq[18362]: 1261 192.168.178.20/58875 forwarded www.youtube.com to 1.1.1.1
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply www.youtube.com is <CNAME>
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 142.250.185.78
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 142.250.185.206
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 142.250.184.206
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 142.250.186.142
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 142.250.185.110
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 142.250.186.174
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 142.250.185.238
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 172.217.16.142
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 142.250.181.238
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 172.217.18.110
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 172.217.23.110
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 142.250.184.238
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 142.250.185.174
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 142.250.185.142
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 216.58.212.142
Oct 11 22:32:25 dnsmasq[18362]: 1260 192.168.178.20/59780 reply youtube-ui.l.google.com is 142.250.186.110
Oct 11 22:32:25 dnsmasq[18362]: 1261 192.168.178.20/58875 reply www.youtube.com is <CNAME>
Oct 11 22:32:25 dnsmasq[18362]: 1261 192.168.178.20/58875 reply youtube-ui.l.google.com is 2a00:1450:4001:831::200e
Oct 11 22:32:25 dnsmasq[18362]: 1261 192.168.178.20/58875 reply youtube-ui.l.google.com is 2a00:1450:4001:813::200e
Oct 11 22:32:25 dnsmasq[18362]: 1261 192.168.178.20/58875 reply youtube-ui.l.google.com is 2a00:1450:4001:812::200e
Oct 11 22:32:25 dnsmasq[18362]: 1261 192.168.178.20/58875 reply youtube-ui.l.google.com is 2a00:1450:4001:811::200e

pihole-FTL.log

[2021-10-11 22:32:25.148 18362M] Processing FTL hook from src/dnsmasq/forward.c:1575...
[2021-10-11 22:32:25.148 18362M]      Flags: F_FORWARD F_IPV4 F_QUERY
[2021-10-11 22:32:25.149 18362M] **** new UDP IPv4 query[A] query "www.youtube.com" from wlan0:192.168.178.20#59780 (ID 1260, FTL 36380, src/dnsmasq/forward.c:1577)
[2021-10-11 22:32:25.149 18362M] www.youtube.com is known as not to be blocked
[2021-10-11 22:32:25.150 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:1502...
[2021-10-11 22:32:25.150 18362M]      Flags: F_FORWARD F_CNAME
[2021-10-11 22:32:25.150 18362M] **** got cache reply: www.youtube.com is (CNAME) (ID 1260, src/dnsmasq/rfc1035.c:1502)
[2021-10-11 22:32:25.150 18362M] Set reply to CNAME (3) in src/dnsmasq_interface.c:2015
[2021-10-11 22:32:25.152 18362M] Processing FTL hook from src/dnsmasq/forward.c:522...
[2021-10-11 22:32:25.152 18362M]      Flags: F_FORWARD F_IPV4 F_SERVER
[2021-10-11 22:32:25.152 18362M] **** forwarded www.youtube.com to 1.1.1.1#53 (ID 1260, src/dnsmasq/forward.c:522)
[2021-10-11 22:32:25.153 18362M] Processing FTL hook from src/dnsmasq/forward.c:1575...
[2021-10-11 22:32:25.153 18362M]      Flags: F_FORWARD F_IPV4 F_QUERY
[2021-10-11 22:32:25.154 18362M] **** new UDP IPv4 query[AAAA] query "www.youtube.com" from wlan0:192.168.178.20#58875 (ID 1261, FTL 36381, src/dnsmasq/forward.c:1577)
[2021-10-11 22:32:25.154 18362M] www.youtube.com is known as not to be blocked
[2021-10-11 22:32:25.155 18362M] Processing FTL hook from src/dnsmasq/forward.c:522...
[2021-10-11 22:32:25.156 18362M]      Flags: F_FORWARD F_IPV4 F_SERVER
[2021-10-11 22:32:25.156 18362M] **** forwarded www.youtube.com to 1.1.1.1#53 (ID 1261, src/dnsmasq/forward.c:522)
[2021-10-11 22:32:25.186 18362M] FTL_CNAME called with: src = (null), dst = www.youtube.com, id = 1260
[2021-10-11 22:32:25.187 18362M] www.youtube.com is known as not to be blocked
[2021-10-11 22:32:25.187 18362M] Query 1260: CNAME www.youtube.com
[2021-10-11 22:32:25.188 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:782...
[2021-10-11 22:32:25.189 18362M]      Flags: F_FORWARD F_CNAME F_UPSTREAM
[2021-10-11 22:32:25.189 18362M] **** got upstream reply from 1.1.1.1#53: www.youtube.com is (CNAME) (ID 1260, src/dnsmasq/rfc1035.c:782)
[2021-10-11 22:32:25.190 18362M] FTL_CNAME called with: src = www.youtube.com, dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.190 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.190 18362M] Query 1260: CNAME www.youtube.com ---> youtube-ui.l.google.com
[2021-10-11 22:32:25.191 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.191 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.191 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 142.250.185.78 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.192 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.192 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.192 18362M] Query 1260: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.193 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.193 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.193 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 142.250.185.206 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.194 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.194 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.195 18362M] Query 1260: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.195 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.195 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.195 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 142.250.184.206 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.196 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.196 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.197 18362M] Query 1260: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.197 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.198 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.198 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 142.250.186.142 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.198 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.199 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.199 18362M] Query 1260: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.199 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.200 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.200 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 142.250.185.110 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.201 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.201 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.201 18362M] Query 1260: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.202 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.202 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.202 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 142.250.186.174 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.203 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.203 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.203 18362M] Query 1260: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.204 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.204 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.204 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 142.250.185.238 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.205 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.205 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.205 18362M] Query 1260: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.206 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.206 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.206 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 172.217.16.142 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.207 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.207 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.208 18362M] Query 1260: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.208 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.210 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.210 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 142.250.181.238 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.211 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.211 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.212 18362M] Query 1260: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.212 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.212 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.213 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 172.217.18.110 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.213 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.213 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.214 18362M] Query 1260: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.214 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.214 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.215 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 172.217.23.110 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.215 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.215 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.216 18362M] Query 1260: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.216 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.216 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.217 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 142.250.184.238 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.217 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.218 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.218 18362M] Query 1260: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.218 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.219 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.219 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 142.250.185.174 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.220 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.220 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.220 18362M] Query 1260: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.221 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.221 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.221 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 142.250.185.142 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.222 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.222 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.222 18362M] Query 1260: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.223 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.223 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.223 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 216.58.212.142 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.224 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1260
[2021-10-11 22:32:25.224 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.224 18362M] Query 1260: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.225 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.225 18362M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-11 22:32:25.225 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 142.250.186.110 (ID 1260, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.227 18362M] FTL_CNAME called with: src = (null), dst = www.youtube.com, id = 1261
[2021-10-11 22:32:25.228 18362M] www.youtube.com is known as not to be blocked
[2021-10-11 22:32:25.228 18362M] Query 1261: CNAME www.youtube.com
[2021-10-11 22:32:25.229 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:782...
[2021-10-11 22:32:25.229 18362M]      Flags: F_FORWARD F_CNAME F_UPSTREAM
[2021-10-11 22:32:25.229 18362M] **** got upstream reply from 1.1.1.1#53: www.youtube.com is (CNAME) (ID 1261, src/dnsmasq/rfc1035.c:782)
[2021-10-11 22:32:25.230 18362M] Set reply to CNAME (3) in src/dnsmasq_interface.c:2088
[2021-10-11 22:32:25.230 18362M] FTL_CNAME called with: src = www.youtube.com, dst = youtube-ui.l.google.com, id = 1261
[2021-10-11 22:32:25.230 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.231 18362M] Query 1261: CNAME www.youtube.com ---> youtube-ui.l.google.com
[2021-10-11 22:32:25.231 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.231 18362M]      Flags: F_FORWARD F_IPV6 F_UPSTREAM
[2021-10-11 22:32:25.231 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 2a00:1450:4001:831::200e (ID 1261, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.232 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1261
[2021-10-11 22:32:25.232 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.232 18362M] Query 1261: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.232 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.233 18362M]      Flags: F_FORWARD F_IPV6 F_UPSTREAM
[2021-10-11 22:32:25.233 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 2a00:1450:4001:813::200e (ID 1261, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.233 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1261
[2021-10-11 22:32:25.234 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.234 18362M] Query 1261: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.234 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.234 18362M]      Flags: F_FORWARD F_IPV6 F_UPSTREAM
[2021-10-11 22:32:25.234 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 2a00:1450:4001:812::200e (ID 1261, src/dnsmasq/rfc1035.c:893)
[2021-10-11 22:32:25.235 18362M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1261
[2021-10-11 22:32:25.235 18362M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-11 22:32:25.235 18362M] Query 1261: CNAME youtube-ui.l.google.com
[2021-10-11 22:32:25.235 18362M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-11 22:32:25.236 18362M]      Flags: F_FORWARD F_IPV6 F_UPSTREAM
[2021-10-11 22:32:25.236 18362M] **** got upstream reply from 1.1.1.1#53: youtube-ui.l.google.com is 2a00:1450:4001:811::200e (ID 1261, src/dnsmasq/rfc1035.c:893)

I woke up in the night and knew what the logic twist is here. We measure the reply time only until the first reply is received (users may have all-servers). However, a cache reply is a reply as well so the second reply is actually the first reply from upstream but the response time is not updated. Hence, we need to memorize that the query is incomplete as cache was only partially valid and use the next reply packet to compute the response time.

I pushed an update to the branch.

The last commit on the branch is still 610c32e from 2 days ago.

Please try again, the workflows on the repository were updated and didn't pick up already existing branches. After rebasing the branch on development, it should work now.

I went back to my standard configuration of unbound and DNSSEC since it didn't seem to have made a difference.

Patch didn't make a difference either unfortunately.

Pi-hole version is v5.5 (Latest: v5.5)
AdminLTE version is v5.7 (Latest: v5.7)
FTL version is fix/reponse_times vDev-ada24e5 (Latest: v5.10.2)

pihole.log

Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 query[A] www.youtube.com from fddc:704f:99b9:178:95fb:ad2e:c155:96f8
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 cached www.youtube.com is <CNAME>
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 forwarded www.youtube.com to 127.0.0.1
Oct 12 21:57:55 dnsmasq[5148]: 1734 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/54229 query[AAAA] www.youtube.com from fddc:704f:99b9:178:95fb:ad2e:c155:96f8
Oct 12 21:57:55 dnsmasq[5148]: 1734 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/54229 forwarded www.youtube.com to 127.0.0.1
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 validation result is INSECURE
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply www.youtube.com is <CNAME>
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 142.250.186.46
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 142.250.186.78
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 142.250.186.110
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 142.250.186.142
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 142.250.186.174
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 172.217.18.110
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 142.250.184.206
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 172.217.23.110
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 216.58.212.142
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 142.250.185.78
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 142.250.185.110
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 142.250.185.142
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 142.250.185.174
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 142.250.185.206
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 142.250.185.238
Oct 12 21:57:55 dnsmasq[5148]: 1733 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/63470 reply youtube-ui.l.google.com is 142.250.74.206
Oct 12 21:57:55 dnsmasq[5148]: 1734 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/54229 validation result is INSECURE
Oct 12 21:57:55 dnsmasq[5148]: 1734 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/54229 reply www.youtube.com is <CNAME>
Oct 12 21:57:55 dnsmasq[5148]: 1734 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/54229 reply youtube-ui.l.google.com is 2a00:1450:4001:82f::200e
Oct 12 21:57:55 dnsmasq[5148]: 1734 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/54229 reply youtube-ui.l.google.com is 2a00:1450:4001:808::200e
Oct 12 21:57:55 dnsmasq[5148]: 1734 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/54229 reply youtube-ui.l.google.com is 2a00:1450:4001:802::200e
Oct 12 21:57:55 dnsmasq[5148]: 1734 fddc:704f:99b9:178:95fb:ad2e:c155:96f8/54229 reply youtube-ui.l.google.com is 2a00:1450:4001:803::200e

pihole-FTL.log

[2021-10-12 21:57:55.506 5148M] Processing FTL hook from src/dnsmasq/forward.c:1575...
[2021-10-12 21:57:55.506 5148M]      Flags: F_FORWARD F_IPV6 F_QUERY
[2021-10-12 21:57:55.507 5148M] **** new UDP IPv6 query[A] query "www.youtube.com" from wlan0:fddc:704f:99b9:178:95fb:ad2e:c155:96f8#63470 (ID 1733, FTL 37206, src/dnsmasq/forward.c:1577)
[2021-10-12 21:57:55.507 5148M] www.youtube.com is known as not to be blocked
[2021-10-12 21:57:55.507 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:1502...
[2021-10-12 21:57:55.508 5148M]      Flags: F_FORWARD F_CNAME
[2021-10-12 21:57:55.508 5148M] **** got cache reply: www.youtube.com is (CNAME) (ID 1733, src/dnsmasq/rfc1035.c:1502)
[2021-10-12 21:57:55.508 5148M] Set reply to CNAME (3) in src/dnsmasq_interface.c:2019
[2021-10-12 21:57:55.510 5148M] Processing FTL hook from src/dnsmasq/forward.c:522...
[2021-10-12 21:57:55.510 5148M]      Flags: F_FORWARD F_IPV4 F_SERVER
[2021-10-12 21:57:55.511 5148M] **** forwarded www.youtube.com to 127.0.0.1#5335 (ID 1733, src/dnsmasq/forward.c:522)
[2021-10-12 21:57:55.511 5148M] Processing FTL hook from src/dnsmasq/forward.c:1575...
[2021-10-12 21:57:55.512 5148M]      Flags: F_FORWARD F_IPV6 F_QUERY
[2021-10-12 21:57:55.512 5148M] **** new UDP IPv6 query[AAAA] query "www.youtube.com" from wlan0:fddc:704f:99b9:178:95fb:ad2e:c155:96f8#54229 (ID 1734, FTL 37207, src/dnsmasq/forward.c:1577)
[2021-10-12 21:57:55.512 5148M] www.youtube.com is known as not to be blocked
[2021-10-12 21:57:55.514 5148M] Processing FTL hook from src/dnsmasq/forward.c:522...
[2021-10-12 21:57:55.515 5148M]      Flags: F_FORWARD F_IPV4 F_SERVER
[2021-10-12 21:57:55.515 5148M] **** forwarded www.youtube.com to 127.0.0.1#5335 (ID 1734, src/dnsmasq/forward.c:522)
[2021-10-12 21:57:55.580 5148M] Processing FTL hook from src/dnsmasq/forward.c:1184...
[2021-10-12 21:57:55.580 5148M]      Flags: F_SECSTAT
[2021-10-12 21:57:55.580 5148M] **** DNSSEC www.youtube.com is INSECURE (ID 1733, src/dnsmasq/forward.c:1184)
[2021-10-12 21:57:55.581 5148M] FTL_CNAME called with: src = (null), dst = www.youtube.com, id = 1733
[2021-10-12 21:57:55.581 5148M] www.youtube.com is known as not to be blocked
[2021-10-12 21:57:55.581 5148M] Query 1733: CNAME www.youtube.com
[2021-10-12 21:57:55.581 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:782...
[2021-10-12 21:57:55.581 5148M]      Flags: F_FORWARD F_CNAME F_UPSTREAM
[2021-10-12 21:57:55.582 5148M] **** got upstream reply from 127.0.0.1#5335: www.youtube.com is (CNAME) (ID 1733, src/dnsmasq/rfc1035.c:782)
[2021-10-12 21:57:55.582 5148M] FTL_CNAME called with: src = www.youtube.com, dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.582 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.582 5148M] Query 1733: CNAME www.youtube.com ---> youtube-ui.l.google.com
[2021-10-12 21:57:55.583 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.583 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.584 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 142.250.186.46 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.584 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.585 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.585 5148M] Query 1733: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.585 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.585 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.585 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 142.250.186.78 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.586 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.586 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.586 5148M] Query 1733: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.586 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.587 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.587 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 142.250.186.110 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.587 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.588 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.588 5148M] Query 1733: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.588 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.588 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.589 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 142.250.186.142 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.589 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.589 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.589 5148M] Query 1733: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.590 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.590 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.590 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 142.250.186.174 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.590 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.591 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.591 5148M] Query 1733: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.591 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.591 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.591 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 172.217.18.110 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.592 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.592 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.592 5148M] Query 1733: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.592 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.593 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.593 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 142.250.184.206 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.593 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.593 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.594 5148M] Query 1733: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.594 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.594 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.594 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 172.217.23.110 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.595 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.595 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.595 5148M] Query 1733: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.595 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.595 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.596 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 216.58.212.142 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.596 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.596 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.596 5148M] Query 1733: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.597 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.597 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.597 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 142.250.185.78 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.598 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.598 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.598 5148M] Query 1733: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.598 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.599 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.599 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 142.250.185.110 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.599 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.599 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.600 5148M] Query 1733: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.600 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.600 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.600 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 142.250.185.142 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.601 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.601 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.601 5148M] Query 1733: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.601 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.601 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.602 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 142.250.185.174 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.602 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.602 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.602 5148M] Query 1733: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.603 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.603 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.603 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 142.250.185.206 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.603 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.604 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.604 5148M] Query 1733: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.604 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.604 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.604 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 142.250.185.238 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.605 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1733
[2021-10-12 21:57:55.605 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.605 5148M] Query 1733: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.605 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.606 5148M]      Flags: F_FORWARD F_IPV4 F_UPSTREAM
[2021-10-12 21:57:55.606 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 142.250.74.206 (ID 1733, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.644 5148M] Processing FTL hook from src/dnsmasq/forward.c:1184...
[2021-10-12 21:57:55.645 5148M]      Flags: F_SECSTAT
[2021-10-12 21:57:55.645 5148M] **** DNSSEC www.youtube.com is INSECURE (ID 1734, src/dnsmasq/forward.c:1184)
[2021-10-12 21:57:55.645 5148M] FTL_CNAME called with: src = (null), dst = www.youtube.com, id = 1734
[2021-10-12 21:57:55.646 5148M] www.youtube.com is known as not to be blocked
[2021-10-12 21:57:55.646 5148M] Query 1734: CNAME www.youtube.com
[2021-10-12 21:57:55.646 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:782...
[2021-10-12 21:57:55.646 5148M]      Flags: F_FORWARD F_CNAME F_UPSTREAM
[2021-10-12 21:57:55.646 5148M] **** got upstream reply from 127.0.0.1#5335: www.youtube.com is (CNAME) (ID 1734, src/dnsmasq/rfc1035.c:782)
[2021-10-12 21:57:55.647 5148M] Set reply to CNAME (3) in src/dnsmasq_interface.c:2092
[2021-10-12 21:57:55.647 5148M] FTL_CNAME called with: src = www.youtube.com, dst = youtube-ui.l.google.com, id = 1734
[2021-10-12 21:57:55.647 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.648 5148M] Query 1734: CNAME www.youtube.com ---> youtube-ui.l.google.com
[2021-10-12 21:57:55.648 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.648 5148M]      Flags: F_FORWARD F_IPV6 F_UPSTREAM
[2021-10-12 21:57:55.648 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 2a00:1450:4001:82f::200e (ID 1734, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.649 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1734
[2021-10-12 21:57:55.649 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.649 5148M] Query 1734: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.649 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.649 5148M]      Flags: F_FORWARD F_IPV6 F_UPSTREAM
[2021-10-12 21:57:55.650 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 2a00:1450:4001:808::200e (ID 1734, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.650 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1734
[2021-10-12 21:57:55.650 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.651 5148M] Query 1734: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.651 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.651 5148M]      Flags: F_FORWARD F_IPV6 F_UPSTREAM
[2021-10-12 21:57:55.651 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 2a00:1450:4001:802::200e (ID 1734, src/dnsmasq/rfc1035.c:893)
[2021-10-12 21:57:55.651 5148M] FTL_CNAME called with: src = (null), dst = youtube-ui.l.google.com, id = 1734
[2021-10-12 21:57:55.652 5148M] youtube-ui.l.google.com is known as not to be blocked
[2021-10-12 21:57:55.652 5148M] Query 1734: CNAME youtube-ui.l.google.com
[2021-10-12 21:57:55.652 5148M] Processing FTL hook from src/dnsmasq/rfc1035.c:893...
[2021-10-12 21:57:55.652 5148M]      Flags: F_FORWARD F_IPV6 F_UPSTREAM
[2021-10-12 21:57:55.653 5148M] **** got upstream reply from 127.0.0.1#5335: youtube-ui.l.google.com is 2a00:1450:4001:803::200e (ID 1734, src/dnsmasq/rfc1035.c:893)

Please try again. (all good things go by three)

There was a short-circuiting in place that prevented further analysis of "additional" replies for efficiency reasons. As the first reply was from cache, the first upstream reply already fell into the category of an additional reply and analysis was short-circuited before the response time was computed. I moved the computation immediately before the short-circuiting and it should work now as I planned it already for the previous commit.

edit The expected version is vDev-d04ea9f

Third time's the charm, or so they say :grinning_face_with_smiling_eyes:
Out of over 6600 forwarded queries that have the CNAME reply type only 8 show a response time of 0.0 ms. The vast majority of problematic cases are solved, there are just some edge case left.

Pi-hole version is v5.5 (Latest: v5.5)
AdminLTE version is v5.7 (Latest: v5.7)
FTL version is fix/reponse_times vDev-d04ea9f (Latest: v5.10.2)

This one failed DNSSEC validation but was marked INSECURE anyway. Another AAAA query a minute before this one had the exact same issue.

$ grep "fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649" /var/log/pihole.log
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 query[A] aws.duplex.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 cached aws.duplex.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 2606:4700:4700::1111
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 validation aws.duplex.snapchat.com is BOGUS
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 reply error is SERVFAIL

These three queries plus one more later on just never received any answer.

$ grep "192.168.178.51/36255\|192.168.178.51/60199\|192.168.178.51/61774" /var/log/pihole.log
Oct 14 12:25:21 dnsmasq[29757]: 13531 192.168.178.51/60199 query[A] graph.facebook.com from 192.168.178.51
Oct 14 12:25:21 dnsmasq[29757]: 13531 192.168.178.51/60199 cached graph.facebook.com is <CNAME>
Oct 14 12:25:21 dnsmasq[29757]: 13531 192.168.178.51/60199 cached api.facebook.com is <CNAME>
Oct 14 12:25:21 dnsmasq[29757]: 13531 192.168.178.51/60199 forwarded graph.facebook.com to 1.1.1.1
Oct 14 12:25:21 dnsmasq[29757]: 13532 192.168.178.51/36255 query[AAAA] graph.facebook.com from 192.168.178.51
Oct 14 12:25:21 dnsmasq[29757]: 13532 192.168.178.51/36255 cached graph.facebook.com is <CNAME>
Oct 14 12:25:21 dnsmasq[29757]: 13532 192.168.178.51/36255 forwarded graph.facebook.com to 1.1.1.1
Oct 14 12:25:21 dnsmasq[29757]: 13549 192.168.178.51/61774 query[A] config.edge.skype.com from 192.168.178.51
Oct 14 12:25:21 dnsmasq[29757]: 13549 192.168.178.51/61774 cached config.edge.skype.com is <CNAME>
Oct 14 12:25:21 dnsmasq[29757]: 13549 192.168.178.51/61774 forwarded config.edge.skype.com to 1.1.1.1

The only connecting property of these two, AFAIK, is that they were forwarded to multiple upstream DNS servers, but I also have several counter examples where this case worked just fine, so i don't know what happened to these here ones.

$ grep "fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191" /var/log/pihole.log
Oct 14 07:03:41 dnsmasq[29757]: 11885 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 query[A] aws.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11885 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 cached aws.api.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11885 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 forwarded aws.api.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11885 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 forwarded aws.api.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11885 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 forwarded aws.api.snapchat.com to 2606:4700:4700::1111
Oct 14 07:03:41 dnsmasq[29757]: 11890 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 validation result is INSECURE
Oct 14 07:03:41 dnsmasq[29757]: 11890 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 reply aws.api.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11890 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 reply aws.api.sc-gw.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11890 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 reply eu-west1-aws.api.sc-gw.com is 34.249.185.75

$ grep "fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670" /var/log/pihole.log
Oct 14 04:08:53 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 query[A] api.dropboxapi.com from fddc:704f:99b9:178:74cb:252e:8291:c4cb
Oct 14 04:08:53 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 cached api.dropboxapi.com is <CNAME>
Oct 14 04:08:53 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 cached api.dropbox.com is <CNAME>
Oct 14 04:08:53 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 forwarded api.dropboxapi.com to 2606:4700:4700::1111
Oct 14 04:09:03 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 forwarded api.dropboxapi.com to 1.1.1.1
Oct 14 04:09:03 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 forwarded api.dropboxapi.com to 2606:4700:4700::1111
Oct 14 04:09:03 dnsmasq[29757]: 8748 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 validation result is INSECURE
Oct 14 04:09:03 dnsmasq[29757]: 8748 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 reply api.dropboxapi.com is <CNAME>
Oct 14 04:09:03 dnsmasq[29757]: 8748 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 reply api.dropbox.com is <CNAME>
Oct 14 04:09:03 dnsmasq[29757]: 8748 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 reply api-env.dropbox-dns.com is 162.125.66.19 (DNSSEC signed)

^^^ What does the extra (DNSSEC signed) on the reply line mean here, considering the validation result is INSECURE?



Something else I noticed now as well, which I guess is tangentially related to this issue:
Queries that are already forwarded or Retried get the CNAME reply type and response time of the initial cache lookup but aren't updated after that. The two AAAA queries were immediately forwarded, the second one being marked as duplicate and not further tracked. The A queries, however, were preceded by a cache lookup before being forwarded. The duplicate one was left with the initial CNAME reply type and the delay of the cache lookup. Retried queries behave the same way.

$ grep "fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/36756\|fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/39968\|fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444\|fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/39228" /var/log/pihole.log
Oct 14 17:54:23 dnsmasq[29757]: 25613 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/36756 query[AAAA] android.clients.google.com from fddc:704f:99b9:178:cc89:6582:c2d3:3b2b
Oct 14 17:54:23 dnsmasq[29757]: 25613 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/36756 forwarded android.clients.google.com to 1.1.1.1
Oct 14 17:54:23 dnsmasq[29757]: 25615 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/39968 query[AAAA] android.clients.google.com from fddc:704f:99b9:178:cc89:6582:c2d3:3b2b
Oct 14 17:54:23 dnsmasq[29757]: 25613 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/36756 validation result is INSECURE
Oct 14 17:54:23 dnsmasq[29757]: 25613 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/36756 reply android.clients.google.com is <CNAME>
Oct 14 17:54:23 dnsmasq[29757]: 25613 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/36756 reply android.l.google.com is NODATA-IPv6
Oct 14 17:54:23 dnsmasq[29757]: 25615 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/39968 reply query is duplicate
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 query[A] android.clients.google.com from fddc:704f:99b9:178:cc89:6582:c2d3:3b2b
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 cached android.clients.google.com is <CNAME>
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 forwarded android.clients.google.com to 1.1.1.1
Oct 14 17:54:23 dnsmasq[29757]: 25617 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/39228 query[A] android.clients.google.com from fddc:704f:99b9:178:cc89:6582:c2d3:3b2b
Oct 14 17:54:23 dnsmasq[29757]: 25617 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/39228 cached android.clients.google.com is <CNAME>
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 validation result is INSECURE
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.clients.google.com is <CNAME>
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 172.217.23.110
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 142.250.184.206
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 216.58.212.142
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 142.250.185.78
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 142.250.185.110
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 142.250.186.110
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 142.250.186.78
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 142.250.74.206
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 142.250.181.238
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 142.250.185.174
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 142.250.185.142
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 216.58.212.174
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 172.217.16.142
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 142.250.186.46
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 142.250.185.238
Oct 14 17:54:23 dnsmasq[29757]: 25616 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/44444 reply android.l.google.com is 142.250.185.206
Oct 14 17:54:23 dnsmasq[29757]: 25617 fddc:704f:99b9:178:cc89:6582:c2d3:3b2b/39228 reply query is duplicate

Thanks for your additional testing, let's get started to get the rest fixed.

Well, this is an issue if this is really true. The way you greped lost some information on the way. Please provide

grep -E ": (1187[7-9]|1188[0-2])" /var/log/pihole.log

Well, this is a special case, indeed. We should remove the reply type if a reply from upstream was never received even if, technically, FTL is correct saying it is a CNAME. However, we have no facility to say that we have a valid reply type but no reply time. I didn't consider this a valid use case so far. Commit addressing this pushed to the current branch.

The first one: A query was made with ID 11885. The reply lines you showed were, however, for query ID 11890. So we'd need at least the full story of these. Even better would be

grep -E ": (1188[5-9]|11890)" /var/log/pihole.log

This applies for the second one, too (forwarded query with ID 8722 vs. reply with ID 8748).

This is difficult to say without seeing the corresponding DNSEC queries. With the bit of information we have here, hypothesis: api-env.dropbox-dns.com is part of the CNAME and correctly signed. However, if at least one element of the CNAME is not signed the entire query should not be considered SECURE and, hence, gets marked as INSECURE.
Why they have their DNS only partially signed is something I cannot answer.

dnsmasq silently drops retries from clients. We just mark them such and loose track of them the same way because they will never actually receive a reply. The situation can be improved by always saying N/A for the reply of these domains here.


edit My hypothesis about the dropbox domain above was correct, see here:

  • dropbox.com is NOT signed (-> INSECURE)
  • dropboxapi.com is NOT signed (-> INSECURE)
  • dropbox-dns.com is signed (-> SECURE)

The overall query is INSECURE as not all elements could be validated:

Screenshot from 2021-10-14 21-12-12

Whoops, I didn't really pay attention to that ID in the front and thought the IP-address/Port(?) would be good enough. But that ID alone can't be enough either (the case about the (DNSSEC signed)):

Otherwise, when greping for just the IDs of each problematic query from the previous reply they all turn into cases of "no reply received".

If the first ID is the only connection between log lines, then that also throws up a few more questions about the DNSSEC validation. It marked the query for us-east4-gcp.api.sc-gw.com BOGUS on the grounds of validation aws.duplex.snapchat.com is BOGUS. How are these two completely different subdomains related (DNSViz: duplex vs api)? Why did it validate only the AAAA query but not the A query? Both answers were served from cache. Why is the validation message printed twice?

$ grep -E ": (1187[7-9]|1188[0-2])" /var/log/pihole.log
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 query[A] aws.duplex.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 cached aws.duplex.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11878 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 query[AAAA] aws.duplex.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11878 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 forwarded aws.duplex.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11879 fddc:704f:99b9:178:a8:d461:21cd:4bb9/51601 query[A] us-central1-gcp.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11879 fddc:704f:99b9:178:a8:d461:21cd:4bb9/51601 cached us-central1-gcp.api.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11879 fddc:704f:99b9:178:a8:d461:21cd:4bb9/51601 cached us-central1-gcp.api.sc-gw.com is 35.190.43.134
Oct 14 07:03:41 dnsmasq[29757]: 11880 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64642 query[AAAA] us-central1-gcp.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11880 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64642 cached us-central1-gcp.api.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11880 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64642 cached us-central1-gcp.api.sc-gw.com is NODATA-IPv6
Oct 14 07:03:41 dnsmasq[29757]: 11881 fddc:704f:99b9:178:a8:d461:21cd:4bb9/54146 query[A] us-east4-gcp.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11881 fddc:704f:99b9:178:a8:d461:21cd:4bb9/54146 cached us-east4-gcp.api.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11881 fddc:704f:99b9:178:a8:d461:21cd:4bb9/54146 cached us-east4-gcp.api.sc-gw.com is 35.190.43.134
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/58989 query[AAAA] us-east4-gcp.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/58989 cached us-east4-gcp.api.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/58989 cached us-east4-gcp.api.sc-gw.com is NODATA-IPv6
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 2606:4700:4700::1111
Oct 14 07:03:41 dnsmasq[29757]: 11878 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 forwarded aws.duplex.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11878 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 forwarded aws.duplex.snapchat.com to 2606:4700:4700::1111
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 validation aws.duplex.snapchat.com is BOGUS
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 reply error is SERVFAIL
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 validation aws.duplex.snapchat.com is BOGUS
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 reply error is SERVFAIL

The two cases of "I don't know what's wrong" (also "no reply received"):

grep for IDs 11885-11890
$ grep -E ": (1188[5-9]|11890)" /var/log/pihole.log
Oct 14 07:03:41 dnsmasq[29757]: 11885 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 query[A] aws.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11885 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 cached aws.api.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11885 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 forwarded aws.api.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11886 fddc:704f:99b9:178:a8:d461:21cd:4bb9/54316 query[AAAA] aws.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11886 fddc:704f:99b9:178:a8:d461:21cd:4bb9/54316 forwarded aws.api.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11887 fddc:704f:99b9:178:a8:d461:21cd:4bb9/63569 query[A] us-east1-aws.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11887 fddc:704f:99b9:178:a8:d461:21cd:4bb9/63569 cached us-east1-aws.api.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11887 fddc:704f:99b9:178:a8:d461:21cd:4bb9/63569 forwarded us-east1-aws.api.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11888 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56745 query[AAAA] us-east1-aws.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11888 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56745 forwarded us-east1-aws.api.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11889 fddc:704f:99b9:178:a8:d461:21cd:4bb9/50558 query[A] gcp.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11889 fddc:704f:99b9:178:a8:d461:21cd:4bb9/50558 cached gcp.api.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11889 fddc:704f:99b9:178:a8:d461:21cd:4bb9/50558 cached gcp.api.sc-gw.com is 35.190.43.134
Oct 14 07:03:41 dnsmasq[29757]: 11890 fddc:704f:99b9:178:a8:d461:21cd:4bb9/63236 query[AAAA] gcp.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11890 fddc:704f:99b9:178:a8:d461:21cd:4bb9/63236 cached gcp.api.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11890 fddc:704f:99b9:178:a8:d461:21cd:4bb9/63236 cached gcp.api.sc-gw.com is NODATA-IPv6
Oct 14 07:03:41 dnsmasq[29757]: 11885 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 forwarded aws.api.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11885 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 forwarded aws.api.snapchat.com to 2606:4700:4700::1111
Oct 14 07:03:41 dnsmasq[29757]: 11886 fddc:704f:99b9:178:a8:d461:21cd:4bb9/54316 forwarded aws.api.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11886 fddc:704f:99b9:178:a8:d461:21cd:4bb9/54316 forwarded aws.api.snapchat.com to 2606:4700:4700::1111
Oct 14 07:03:41 dnsmasq[29757]: 11890 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 validation result is INSECURE
Oct 14 07:03:41 dnsmasq[29757]: 11890 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 reply aws.api.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11890 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 reply aws.api.sc-gw.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11890 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56191 reply eu-west1-aws.api.sc-gw.com is 34.249.185.75
Oct 14 07:03:41 dnsmasq[29757]: 11887 fddc:704f:99b9:178:a8:d461:21cd:4bb9/63569 validation result is INSECURE
Oct 14 07:03:41 dnsmasq[29757]: 11887 fddc:704f:99b9:178:a8:d461:21cd:4bb9/63569 reply us-east1-aws.api.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11887 fddc:704f:99b9:178:a8:d461:21cd:4bb9/63569 reply us-east1-aws.api.sc-gw.com is 100.26.12.76
Oct 14 07:03:41 dnsmasq[29757]: 11890 fddc:704f:99b9:178:a8:d461:21cd:4bb9/54316 validation aws.api.snapchat.com is BOGUS
Oct 14 07:03:41 dnsmasq[29757]: 11890 fddc:704f:99b9:178:a8:d461:21cd:4bb9/54316 reply error is SERVFAIL
Oct 14 07:03:49 dnsmasq[29757]: 11888 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56745 forwarded us-east1-aws.api.snapchat.com to 1.1.1.1
Oct 14 07:03:49 dnsmasq[29757]: 11888 fddc:704f:99b9:178:a8:d461:21cd:4bb9/56745 forwarded us-east1-aws.api.snapchat.com to 2606:4700:4700::1111
grep for ID 8722
$ grep -E ": 8722" /var/log/pihole.log
Oct 14 04:08:53 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 query[A] api.dropboxapi.com from fddc:704f:99b9:178:74cb:252e:8291:c4cb
Oct 14 04:08:53 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 cached api.dropboxapi.com is <CNAME>
Oct 14 04:08:53 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 cached api.dropbox.com is <CNAME>
Oct 14 04:08:53 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 forwarded api.dropboxapi.com to 2606:4700:4700::1111
Oct 14 04:09:03 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 forwarded api.dropboxapi.com to 1.1.1.1
Oct 14 04:09:03 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 forwarded api.dropboxapi.com to 2606:4700:4700::1111

No, it isn't. Because we might be doing additional DNSSEC-related queries when we have to walk the DNS path from the root servers down to the actual domain. They are independent and, hence, get their own IDs. They are likely the next IDs after this one. This is expected and correct.

What does not look okay is that an ID seems to be re-used here. Two times the same ID for different queries is fishy but seen in your screenshot. Could you send me the entirety of the log file via PM (or here if you don't mind) starting from the first line in your screenshot to the last line so I can examine what might be broken here?

Maybe something is broken, see above.

Is this expected? That you do not receive a reply from upstream? I haven't seen any no reply case in the logs I still have on my own Pi-hole.

I don't think they are related (-> ID issue).

It did this, it is the reason for the duplicated DNSSEC validation printing (see below), see two quotes below. We'd need a grep with a larger upper boundary than 11882 to see possibly existing additional queries. Better would be a full log excerpt spanning from

Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 query[A] aws.duplex.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9

to

Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 reply error is SERVFAIL

grep -n ... will be helpful as it prints line numbers making it easier to see from where to where you should copy the lines.

The long-lived CNAME was served from cache. Children needed to be forwarded. It will be the validation of those forwarded children that failed. Only trusted (INSECURE or SECURE) elements enter the cache. It is possible that the CNAME got cached because it is INSECURE but the children don't ever get cached because they fail.

It was sent to two clients/ports if you pay close attention:

Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 validation aws.duplex.snapchat.com is BOGUS
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 reply error is SERVFAIL
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 validation aws.duplex.snapchat.com is BOGUS
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 reply error is SERVFAIL

The first corresponds to ID 11877, the second corresponds to ID 11878. The printed ID 1882 is a mistake.


I also checked your other logs but if the ID cannot really be trusted, then analysis may be moot anyway. I'll check this when I have your full log snippet and maybe report this upstream for fixing if I don't see it immediately.

TL;DR: There is a dnsmasq bug with IDs in logs (log-queries=extra):

  1. In one case, we've seen that seemingly two completely unrelated queries got logged with the same ID
  2. In another case, we've seen DNSSEC replies with ID uncorrelated to the actual queries. I assume it was forgotten to set the log_id and, hence, the logging routine just used the last ID that was logged - even if it came from an entirely uncorrelated query

I should be able to support or dismiss this with the new log snippet (see two times bold highlighted text above).

This is it, just these lines. I copied the line numbers from vim as well.

 19898 Oct 14 04:09:01 dnsmasq[29757]: 8748 192.168.178.50/39340 query[A] mobile.pipe.aria.microsoft.com from 192.168.178.50
 19899 Oct 14 04:09:01 dnsmasq[29757]: 8748 192.168.178.50/39340 gravity blocked mobile.pipe.aria.microsoft.com is 0.0.0.0
 19900 Oct 14 04:09:03 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 forwarded api.dropboxapi.com to 1.1.1.1
 19901 Oct 14 04:09:03 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 forwarded api.dropboxapi.com to 2606:4700:4700::1111
 19902 Oct 14 04:09:03 dnsmasq[29757]: 8748 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 validation result is INSECURE
 19903 Oct 14 04:09:03 dnsmasq[29757]: 8748 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 reply api.dropboxapi.com is <CNAME>
 19904 Oct 14 04:09:03 dnsmasq[29757]: 8748 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 reply api.dropbox.com is <CNAME>
 19905 Oct 14 04:09:03 dnsmasq[29757]: 8748 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 reply api-env.dropbox-dns.com is 162.125.66.19 (DNSSEC signed)

 31049 Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 query[A] aws.duplex.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
 31050 Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 cached aws.duplex.snapchat.com is <CNAME>
 31051 Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 1.1.1.1
 31052 Oct 14 07:03:41 dnsmasq[29757]: 11878 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 query[AAAA] aws.duplex.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
 31053 Oct 14 07:03:41 dnsmasq[29757]: 11878 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 forwarded aws.duplex.snapchat.com to 1.1.1.1
 31054 Oct 14 07:03:41 dnsmasq[29757]: 11879 fddc:704f:99b9:178:a8:d461:21cd:4bb9/51601 query[A] us-central1-gcp.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
 31055 Oct 14 07:03:41 dnsmasq[29757]: 11879 fddc:704f:99b9:178:a8:d461:21cd:4bb9/51601 cached us-central1-gcp.api.snapchat.com is <CNAME>
 31056 Oct 14 07:03:41 dnsmasq[29757]: 11879 fddc:704f:99b9:178:a8:d461:21cd:4bb9/51601 cached us-central1-gcp.api.sc-gw.com is 35.190.43.134
 31057 Oct 14 07:03:41 dnsmasq[29757]: 11880 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64642 query[AAAA] us-central1-gcp.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9       
 31058 Oct 14 07:03:41 dnsmasq[29757]: 11880 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64642 cached us-central1-gcp.api.snapchat.com is <CNAME>
 31059 Oct 14 07:03:41 dnsmasq[29757]: 11880 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64642 cached us-central1-gcp.api.sc-gw.com is NODATA-IPv6
 31060 Oct 14 07:03:41 dnsmasq[29757]: 11881 fddc:704f:99b9:178:a8:d461:21cd:4bb9/54146 query[A] us-east4-gcp.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
 31061 Oct 14 07:03:41 dnsmasq[29757]: 11881 fddc:704f:99b9:178:a8:d461:21cd:4bb9/54146 cached us-east4-gcp.api.snapchat.com is <CNAME>
 31062 Oct 14 07:03:41 dnsmasq[29757]: 11881 fddc:704f:99b9:178:a8:d461:21cd:4bb9/54146 cached us-east4-gcp.api.sc-gw.com is 35.190.43.134
 31063 Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/58989 query[AAAA] us-east4-gcp.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
 31064 Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/58989 cached us-east4-gcp.api.snapchat.com is <CNAME>
 31065 Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/58989 cached us-east4-gcp.api.sc-gw.com is NODATA-IPv6
 31066 Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 1.1.1.1
 31067 Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 2606:4700:4700::1111
 31068 Oct 14 07:03:41 dnsmasq[29757]: 11878 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 forwarded aws.duplex.snapchat.com to 1.1.1.1
 31069 Oct 14 07:03:41 dnsmasq[29757]: 11878 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 forwarded aws.duplex.snapchat.com to 2606:4700:4700::1111
 31070 Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 validation aws.duplex.snapchat.com is BOGUS
 31071 Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 reply error is SERVFAIL
 31072 Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 validation aws.duplex.snapchat.com is BOGUS
 31073 Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 reply error is SERVFAIL

The entire log file should be here https://tricorder.pi-hole.net/xI5e7P7C/. (Did this work? It's a gzip compressed file.)

No, I don't think so. Why would Cloudflare just drop the query? On other occasions queries for the same domains got replies. But keep in mind that these are also just 8 queries out of several thousand, it might just be packet loss.


For what it's worth, I don't find any more problematic cases of CNAME replies without response times with my crude script since updating last night.

$ echo ">getallqueries >quit" | nc 127.0.0.1 4711 | awk 'BEGIN {count=0;total=0}; {if($5 == "2" && $7 == "3"){if($8 == "0"){count+=1; print $0}; {total+=1}}} END {print total,count}'
4668 0
Pi-hole version is v5.5 (Latest: v5.5)
AdminLTE version is v5.7 (Latest: v5.7)
FTL version is fix/reponse_times vDev-5617eed (Latest: v5.10.2)

And Retried and already forwarded queries also don't show the "misleading" CNAME reply either anymore. :+1:

Okay, thanks for this. I build a fix based on your log lines alone (without being able to reproduce this myself easily). Could you try updating the branch once more?

To see if the fix works (and is sufficient), we are looking for the validation result ID error we have observed here (well, we are looking for the absence of the error which is somewhat more tricky):

1. Incorrect ID when a lot of stuff happened in between
Oct 14 04:08:53 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 query[A] api.dropboxapi.com from fddc:704f:99b9:178:74cb:252e:8291:c4cb
Oct 14 04:08:53 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 cached api.dropboxapi.com is <CNAME>
Oct 14 04:08:53 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 cached api.dropbox.com is <CNAME>
Oct 14 04:08:53 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 forwarded api.dropboxapi.com to 2606:4700:4700::1111
[ ... a lot of uncorrelated stuff not shown here ... ]
Oct 14 04:09:01 dnsmasq[29757]: 8748 192.168.178.50/39340 query[A] mobile.pipe.aria.microsoft.com from 192.168.178.50
Oct 14 04:09:01 dnsmasq[29757]: 8748 192.168.178.50/39340 /etc/hosts mobile.pipe.aria.microsoft.com is 0.0.0.0
Oct 14 04:09:03 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 forwarded api.dropboxapi.com to 1.1.1.1
Oct 14 04:09:03 dnsmasq[29757]: 8722 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 forwarded api.dropboxapi.com to 2606:4700:4700::1111
[ the following lines are incorrect, ID should be 8722 ]
Oct 14 04:09:03 dnsmasq[29757]: 8748 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 validation result is INSECURE
Oct 14 04:09:03 dnsmasq[29757]: 8748 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 reply api.dropboxapi.com is <CNAME>
Oct 14 04:09:03 dnsmasq[29757]: 8748 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 reply api.dropbox.com is <CNAME>
Oct 14 04:09:03 dnsmasq[29757]: 8748 fddc:704f:99b9:178:74cb:252e:8291:c4cb/35670 reply api-env.dropbox-dns.com is 162.125.66.19 (DNSSEC signed)

2. Also visible with identical (incorrect) IDs when we got validation results for A/AAAA queries of the same domain
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 query[A] aws.duplex.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 cached aws.duplex.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11878 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 query[AAAA] aws.duplex.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11878 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 forwarded aws.duplex.snapchat.com to 1.1.1.1
[ ... other unrelated stuff is going on, query ID is increasing ... ]
[ queries are being retried because no reply was received from upstream ]
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 2606:4700:4700::1111
Oct 14 07:03:41 dnsmasq[29757]: 11878 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 forwarded aws.duplex.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11878 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 forwarded aws.duplex.snapchat.com to 2606:4700:4700::1111
[ this time, the reply came immediately, however, IDs should be 11877 and 11878 instead of 11882, see also client/port ]
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 validation aws.duplex.snapchat.com is BOGUS
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 reply error is SERVFAIL
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 validation aws.duplex.snapchat.com is BOGUS
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 reply error is SERVFAIL

I tried to fix this by moving an unconditional setting of the ID variable to the latest ID further up into the condition to do this only when we are really seeing a retry from a client. I'm not exactly sure it will work right away but my tired brain seems to think this is the right solution.


edit My fix may be insufficient. It may fix the issue we discussed here, however, it is actually intended to update/replace the ID if queries are retried. I'll work on this later.

Indeed. The way I tried to find these cases is by looking for reply or validation lines and check if there is an earlier query[] line with identical ID and client. If yes, all good. If no, i.e. either the ID or the client doesn't match, all bad.

The script below prints out all log lines with the client for which IDs seem to change, and also prints out all lines containing the offending IDs. There are 197 of such cases among >32'000 queries in my original log file that i uploaded to tricorder (should have expired by now).

There are no cases (no output other than the counter) in today's log file among >15'000 queries. I lost yesterday's to the update, forgot that it overwrites the dnsmasq file again and it didn't have the log-queries=extra anymore. :sweat_smile:

As far as I can tell, the issue is fixed. Or at least the symptoms I could identify.

Thank you, as always, for tracking down the issue and creating a fix so quickly. :heart: :+1:

Script
#!/bin/bash
shopt -s nocasematch

log_file="/home/dax/pihole.old.log"

IP_Port_combos=$(awk '{if(($6 ~ /^[0-9a-f:./]+$/)){print $6}}' ${log_file} | sort -u)
num_combos=$(echo "${IP_Port_combos}" | wc -l)

counter=1
for client in ${IP_Port_combos};
do
        echo -en "\r${counter}/${num_combos}"

        log_lines=$(grep "${client}" "${log_file}")

        # If the current line indicates an incoming query, create an array entry at the index of the ID
        # and the value of the client (IP/Port).
        # If the current line indicates a reply, check the array at index ID for the client value.
        # 1. If the current client is the same as the array value: good
        # 2. If the current client differs from the array value: bad
        result=$(echo "${log_lines}" | awk '
                BEGIN {error=0;array["init"]=0;errIDs=""};
                {
                        queryIDs = queryIDs "\n" $5

                        if($7 ~ /query.*/){
                                array[$5] = $6;
                        }
                        if($7 ~ /reply|validation/ && array[$5] != $6){
                                error = 1;
                                array[$5] = $6;
                        }
                };
                END {
                        if(error == 1){
                                print queryIDs
                        }else{
                                print "ok"
                        }
                }
        ')
        if [ "${result}" != "ok" ]; then
                echo ""
                echo "#####"
                echo "Problematic Client: ${client}"
                echo "${log_lines}"
                for id in $(echo "${result}" | sort -u);
                do
                        echo "Relevant ID: ${id}"
                        grep ": ${id} " "${log_file}"
                done
        fi

        counter=$((counter+1))
done
Sample output for my first log that I linked above
#####
Problematic Client: fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 query[A] aws.duplex.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 cached aws.duplex.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 2606:4700:4700::1111
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 validation aws.duplex.snapchat.com is BOGUS
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 reply error is SERVFAIL
Relevant ID: 11877
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 query[A] aws.duplex.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 cached aws.duplex.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 1.1.1.1
Oct 14 07:03:41 dnsmasq[29757]: 11877 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 forwarded aws.duplex.snapchat.com to 2606:4700:4700::1111
Relevant ID: 11882
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/58989 query[AAAA] us-east4-gcp.api.snapchat.com from fddc:704f:99b9:178:a8:d461:21cd:4bb9
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/58989 cached us-east4-gcp.api.snapchat.com is <CNAME>
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/58989 cached us-east4-gcp.api.sc-gw.com is NODATA-IPv6
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 validation aws.duplex.snapchat.com is BOGUS
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64649 reply error is SERVFAIL
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 validation aws.duplex.snapchat.com is BOGUS
Oct 14 07:03:41 dnsmasq[29757]: 11882 fddc:704f:99b9:178:a8:d461:21cd:4bb9/64522 reply error is SERVFAIL