Pi-hole won't cache results if answer doesn't fit known reply types and will always display "N/A (0.0ms)" as Reply in Query Log

Hello,

as the title says, Pi-hole won't cache results for unknown query types, i.e. everything that falls into the OTHER category, plus the new query types HTTPS and SVCB.
edit: Issue extends to unknown reply types instead of unknown query types. See my next comment.

When looking at the Query Log it will also always display the Reply as N/A (0.0ms). I don't know if this is specifically a bug of the beta or if this happens on stable as well, but I'm on the beta version so that's the category I chose.

Dig results for both requests. No idea why Windows spawns 3 queries for each.
$ dig TYPE65 https.dns.netmeister.org.

; <<>> DiG 9.16.1-Ubuntu <<>> TYPE65 https.dns.netmeister.org.
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 31647
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;https.dns.netmeister.org.      IN      TYPE65

;; ANSWER SECTION:
https.dns.netmeister.org. 1252  IN      TYPE65  \# 123 2D6E2031202E20616C706E3D2268332C683222206970763668696E74 3D22323030313A3437303A33303A38343A653237363A363366663A66 6537323A333930302220706F72743D22383038302220656368636F6E 6669673D225A57356A636E6C776447566B49474E7361575675644342 6F5A57787362776F3D220A
https.dns.netmeister.org. 1252  IN      TYPE65  \# 25 2D6E2030207777772E6E65746D6569737465722E6F72672E0A

;; Query time: 150 msec
;; SERVER: 172.18.160.1#53(172.18.160.1)
;; WHEN: Thu Aug 26 02:05:06 CEST 2021
;; MSG SIZE  rcvd: 225
$ dig TYPE65 https.dns.netmeister.org.

; <<>> DiG 9.16.1-Ubuntu <<>> TYPE65 https.dns.netmeister.org.
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 52474
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 2, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;https.dns.netmeister.org.      IN      TYPE65

;; ANSWER SECTION:
https.dns.netmeister.org. 1226  IN      TYPE65  \# 25 2D6E2030207777772E6E65746D6569737465722E6F72672E0A
https.dns.netmeister.org. 1226  IN      TYPE65  \# 123 2D6E2031202E20616C706E3D2268332C683222206970763668696E74 3D22323030313A3437303A33303A38343A653237363A363366663A66 6537323A333930302220706F72743D22383038302220656368636F6E 6669673D225A57356A636E6C776447566B49474E7361575675644342 6F5A57787362776F3D220A

;; Query time: 40 msec
;; SERVER: 172.18.160.1#53(172.18.160.1)
;; WHEN: Thu Aug 26 02:05:32 CEST 2021
;; MSG SIZE  rcvd: 225

As you can see from the dig results, each request was answered with appropriate data and there were another 20 minutes left on the time-to-live (TTL). Despite this, Pi-hole forwarded the second query instead of answering from cache. Additionally, the Reply column shows N/A (0.0ms) even though a valid answer was received and the query most certainly was not processed instantaneously.

Here is the same behavior with the GPOS query type. Despite almost 40 minutes left on the TTL the second query was not cached.

Dig results. Again, Windows being over-enthusiastic.
$ dig gpos gpos.dns.netmeister.org.

; <<>> DiG 9.16.1-Ubuntu <<>> gpos gpos.dns.netmeister.org.
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 15593
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;gpos.dns.netmeister.org.       IN      GPOS

;; ANSWER SECTION:
gpos.dns.netmeister.org. 2368   IN      GPOS    "40.731" "-73.9919" "10.0"

;; Query time: 190 msec
;; SERVER: 172.18.160.1#53(172.18.160.1)
;; WHEN: Thu Aug 26 02:15:59 CEST 2021
;; MSG SIZE  rcvd: 85
$ dig gpos gpos.dns.netmeister.org.

; <<>> DiG 9.16.1-Ubuntu <<>> gpos gpos.dns.netmeister.org.
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 17752
;; flags: qr rd ra ad; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;gpos.dns.netmeister.org.       IN      GPOS

;; ANSWER SECTION:
gpos.dns.netmeister.org. 2340   IN      GPOS    "40.731" "-73.9919" "10.0"

;; Query time: 50 msec
;; SERVER: 172.18.160.1#53(172.18.160.1)
;; WHEN: Thu Aug 26 02:16:27 CEST 2021
;; MSG SIZE  rcvd: 85

Granted, you probably won't be seeing these other query types besides HTTPS very often. I chose GPOS here arbitrarily, any query type not known to Pi-hole will show this behavior as well. This site has set up all resource records with definitions of their content for testing:

Maybe a new generic reply type like DATA could be shown for queries of which the format of the answer is not known. (unless its NODATA of course)
And obviously showing the actual response time instead of 0.0 ms would be nice.


$ pihole -v
  Pi-hole version is release/v5.4 v5.3.1-96-g58a21bee (Latest: v5.3.1)
  AdminLTE version is release/v5.6 v5.5.1-65-g224f906 (Latest: v5.5.1)
  FTL version is release/v5.9 vDev-9a53df6 (Latest: v5.8.1)

Not sure if the debug log will be useful but here you go:
[✓] Your debug token is: https://tricorder.pi-hole.net/YisTXm06/

1 Like

Same on the master branch:

I moved the category back to General.

So I've been playing around with this a little and the problem extends to even the known query types. All queries are affected if the answer doesn't fit one of the predefined reply types.

But even the DS and DNSKEY queries don't have DNSSEC as a reply type here for some reason.

There aren't any reply types that would fit any of these queries here, so N/A is better than nothing I guess, but something more descriptive like DATA would be nice just to have any feedback about the result of the query. Also all affected queries were forwarded again instead of being answered from cache. The screenshot doesn't show this but this is the second round of queries (testscript below). The response time is again always 0.0 ms even though the queries were forwarded.

# Test script to quickly test for arbitrary resource records
pihole="192.168.178.15"
for i in a aaaa srv soa ptr txt naptr mx ds rrsig dnskey ns svcb https
do 
    if [ "$i" = ptr ]; then
        ip4="$(dig +short a netmeister.org)"
        ip6="$(dig +short aaaa netmeister.org)"
        echo "$(dig +noall +answer @${pihole} -x ${ip4})"
        echo "$(dig +noall +answer @${pihole} -x ${ip6})"
    fi
    if [ "$i" = svcb ]; then
        j="TYPE64"
    elif [ "$i" = https ]; then
        j="TYPE65"
    else 
        j="$i"
    fi
    echo "$(dig +noall +answer @${pihole} ${j} ${i}.dns.netmeister.org)"
done
# Output of above script
a.dns.netmeister.org.   1158    IN      A       166.84.7.99
aaaa.dns.netmeister.org. 1168   IN      AAAA    2001:470:30:84:e276:63ff:fe72:3900
srv.dns.netmeister.org. 1246    IN      SRV     0 1 80 panix.netmeister.org.
soa.dns.netmeister.org. 1254    IN      SOA     panix.netmeister.org. jschauma.netmeister.org. 2021072312 3600 300 3600000 3600
99.7.84.166.in-addr.arpa. 1255  IN      PTR     panix.netmeister.org.
0.0.9.3.2.7.e.f.f.f.3.6.6.7.2.e.4.8.0.0.0.3.0.0.0.7.4.0.1.0.0.2.ip6.arpa. 1254 IN PTR panix.netmeister.org.
ptr.dns.netmeister.org. 1265    IN      PTR     ptr.dns.netmeister.org.
txt.dns.netmeister.org. 592     IN      TXT     "Format: <text>"
txt.dns.netmeister.org. 592     IN      TXT     "Descriptive text. Completely overloaded for all sorts of things. RFC1035 (1987)"
naptr.dns.netmeister.org. 1284  IN      NAPTR   20 10 "s" "http+N2L+N2C+N2R" "" www.netmeister.org.
naptr.dns.netmeister.org. 1284  IN      NAPTR   10 10 "u" "smtp+E2U" "!.*([^.]+[^.]+)$!mailto:postmaster@$1!i" .
mx.dns.netmeister.org.  1292    IN      MX      50 panix.netmeister.org.
ds.dns.netmeister.org.  1299    IN      DS      56393 13 2 BD36DD608262A026083721FA19E2F7B474F531BB3179CC00A0C38FF0 0CA11657
rrsig.dns.netmeister.org. 1308  IN      RRSIG   TXT 13 4 3600 20210902104320 20210819095136 56039 dns.netmeister.org. 6VhgJLJXR8f8VUPyC0v5EcS17Z/TfDIdVF7f8L9SceRvSfqz5NMzVD3E aMGN7DaEezXdBhqGaf/KFZxKufmIvA==
rrsig.dns.netmeister.org. 1308  IN      RRSIG   NSEC 13 4 3600 20210908211756 20210825205219 56039 dns.netmeister.org. 59eCCJ//Y1O69REgNOry9WB+XKNGMATN6EJ6mqtSqj8H31gKI8Dm2+pj FKHVfj5dJV62LVI9tPQHYSJVb/evdA==
dnskey.dns.netmeister.org. 1317 IN      DNSKEY  257 3 13 XEn4q8CbG2a4Hw47Ih244BDkwY1tOuprXWKEzMyLPtjO9iIRVt4HLLbx 9YaeaYzRcH91mvCstP8I5liQ0Mn1bA==
ns.dns.netmeister.org.  1324    IN      NS      panix.netmeister.org.
svcb.dns.netmeister.org. 1343   IN      TYPE64  \# 85 2D6E20312070616E69782E6E65746D6569737465722E6F72672E2069 70763668696E743D22323030313A3437303A33303A38343A65323736 3A363366663A666537323A333930302220706F72743D223838383822 0A
https.dns.netmeister.org. 1351  IN      TYPE65  \# 25 2D6E2030207777772E6E65746D6569737465722E6F72672E0A
https.dns.netmeister.org. 1351  IN      TYPE65  \# 123 2D6E2031202E20616C706E3D2268332C683222206970763668696E74 3D22323030313A3437303A33303A38343A653237363A363366663A66 6537323A333930302220706F72743D22383038302220656368636F6E 6669673D225A57356A636E6C776447566B49474E7361575675644342 6F5A57787362776F3D220A

I guess dnsmasq is somehow deciding to not record the reply and, hence, FTL did not see it, either.
This would explain both the N/A (because the reply type is not available at this time and the 0.0 msec (because this is what will be shown if the reply has not yet been received).

Can you show relevant logs from /var/log/pihole.log ?

My guess is that the log will contain lines like (guessing from the very first screenshot in this discussion)

query[HTTPS] https.dns.netmeister.org from <whereever>
forwarded https.dns.netmeister.org to <somewhere>
validation result is SECURE

BUT no corresponding lines like

reply https.dns.netmeister.org is <xyz>
cached https.dns.netmeister.org is <xyz>

If this turns out to be true, this will be a dnsmasq bug which we need to solve over there. I'm not hesitant to trace this down and submit a patch upstream.

1 Like

Yes, you are right. Except for the TXT query, all other queries without a proper reply type don't have corresponding reply/cached lines.

Aug 26 18:38:13 dnsmasq[24015]: query[A] a.dns.netmeister.org from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: cached a.dns.netmeister.org is 166.84.7.99
Aug 26 18:38:14 dnsmasq[24015]: query[AAAA] aaaa.dns.netmeister.org from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: cached aaaa.dns.netmeister.org is 2001:470:30:84:e276:63ff:fe72:3900
Aug 26 18:38:14 dnsmasq[24015]: query[SRV] srv.dns.netmeister.org from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: cached srv.dns.netmeister.org is <SRV>
Aug 26 18:38:14 dnsmasq[24015]: query[SOA] soa.dns.netmeister.org from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: forwarded soa.dns.netmeister.org to 127.0.0.1
Aug 26 18:38:14 dnsmasq[24015]: validation result is SECURE
Aug 26 18:38:14 dnsmasq[24015]: query[PTR] 99.7.84.166.in-addr.arpa from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: cached 166.84.7.99 is panix.netmeister.org
Aug 26 18:38:14 dnsmasq[24015]: query[PTR] 0.0.9.3.2.7.e.f.f.f.3.6.6.7.2.e.4.8.0.0.0.3.0.0.0.7.4.0.1.0.0.2.ip6.arpa from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: cached 2001:470:30:84:e276:63ff:fe72:3900 is panix.netmeister.org
Aug 26 18:38:14 dnsmasq[24015]: query[PTR] ptr.dns.netmeister.org from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: forwarded ptr.dns.netmeister.org to 127.0.0.1
Aug 26 18:38:14 dnsmasq[24015]: validation result is SECURE
Aug 26 18:38:14 dnsmasq[24015]: query[TXT] txt.dns.netmeister.org from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: forwarded txt.dns.netmeister.org to 127.0.0.1
Aug 26 18:38:14 dnsmasq[24015]: validation result is SECURE
Aug 26 18:38:14 dnsmasq[24015]: reply txt.dns.netmeister.org is Format: <text>
Aug 26 18:38:14 dnsmasq[24015]: reply txt.dns.netmeister.org is Descriptive text. Completely overloaded for all sorts of things. RFC1035 (1987)
Aug 26 18:38:14 dnsmasq[24015]: query[NAPTR] naptr.dns.netmeister.org from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: forwarded naptr.dns.netmeister.org to 127.0.0.1
Aug 26 18:38:14 dnsmasq[24015]: validation result is SECURE
Aug 26 18:38:14 dnsmasq[24015]: query[MX] mx.dns.netmeister.org from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: forwarded mx.dns.netmeister.org to 127.0.0.1
Aug 26 18:38:14 dnsmasq[24015]: validation result is SECURE
Aug 26 18:38:14 dnsmasq[24015]: query[DS] ds.dns.netmeister.org from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: forwarded ds.dns.netmeister.org to 127.0.0.1
Aug 26 18:38:14 dnsmasq[24015]: validation result is SECURE
Aug 26 18:38:14 dnsmasq[24015]: query[RRSIG] rrsig.dns.netmeister.org from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: forwarded rrsig.dns.netmeister.org to 127.0.0.1
Aug 26 18:38:14 dnsmasq[24015]: validation result is INSECURE
Aug 26 18:38:14 dnsmasq[24015]: query[DNSKEY] dnskey.dns.netmeister.org from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: forwarded dnskey.dns.netmeister.org to 127.0.0.1
Aug 26 18:38:14 dnsmasq[24015]: validation result is SECURE
Aug 26 18:38:14 dnsmasq[24015]: query[NS] ns.dns.netmeister.org from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: forwarded ns.dns.netmeister.org to 127.0.0.1
Aug 26 18:38:14 dnsmasq[24015]: validation result is SECURE
Aug 26 18:38:14 dnsmasq[24015]: query[type=64] svcb.dns.netmeister.org from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: forwarded svcb.dns.netmeister.org to 127.0.0.1
Aug 26 18:38:14 dnsmasq[24015]: validation result is SECURE
Aug 26 18:38:14 dnsmasq[24015]: query[type=65] https.dns.netmeister.org from 192.168.178.20
Aug 26 18:38:14 dnsmasq[24015]: forwarded https.dns.netmeister.org to 127.0.0.1
Aug 26 18:38:14 dnsmasq[24015]: validation result is SECURE
1 Like

I had some time this morning to check the dnsmasq source and now we know what is happening:

dnsmasq can only cache the following types:

  • A
  • AAAA
  • SRV
  • PTR

plus DNSSEC-relevant stuff.
This is not much but surely the majority of things you will see throughout the day.

The interesting bit is now that dnsmasq only logs "reply abc.com is ..." when caching a reply. It does not log any of the the other types (like SOA, or NAPTR). Just because it doesn't cache them. This also explains why you always see a forwarding. This is what actually happens.

Side note: TXT gets a "reply abc.com is ..." line because there is some special code in another region of the code that prints this into the log file. This code is in a somewhat obscure place and seems replacement-worthy.


My plan is to submit a patch that logs all replies even if they don't enter the cache. Furthermore, I will move the special TXT record handling into the same place.

edit Patch submitted upstream. It proposes logging like

Aug 27 10:33:08 dnsmasq[1497026]: query[SOA] soa.dns.netmeister.org from 127.0.0.1
Aug 27 10:33:08 dnsmasq[1497026]: forwarded soa.dns.netmeister.org to 127.0.0.1
Aug 27 10:33:08 dnsmasq[1497026]: reply soa.dns.netmeister.org is non-cached [SOA]

(emphasis on the last line). This is not everything we need here, however, it is an important step. Whether this is accepted will decide on how we continue here.

Thanks again for bringing this to our attention! I totally missed it and, apparently, many others as well.

3 Likes

Thank you for your dedication, even if the issue lies with dnsmasq rather than Pi-hole.

Few questions though.

Would simply logging the reply already solve the N/A (0.0ms) problem? Even if --log-queries is unset in the config? I guess it would still say N/A for an actual reply, but then you can at least distinguish it from NODATA.

How does it handle NODATA answers, actually? Currently there are specific NODATA-IPv4 and NODATA-IPv6 answers printed to log. Or in case of DNSSEC queries it will simply read no DS. PTR queries are then NXDOMAIN instead of NODATA obviously.

Will the reply line contain the actual answer or does it print literally non-cached [SOA] in your example?


True, although I have seen HTTPS as high as 20% at times. That was my main concern on the original post, I just happened to notice that it also happens for other query types as well.

Caching these other types would be nice, but just logging replies and showing the appropriate reply type in the Query Log is a good first step to gauge if caching would even be useful in a significant way. Caching wouldn't be a priority if 99% of these other types are just NODATA anyway, but right now you can't tell that without manually digging for these records.

No. But this is why I said

FTL gets what it needs by hooking into the log routines of dnsmasq. This has the benefit of least code modifications of the original source code to ensure future updates can be merged without having to resolve merge conflicts all the time. As there is a lot more information available internally than what is written to the log, this is often sufficient (but not always).

However, this has the drawback that FTL does not see stuff for which the log routines are not even called so this is why FTL was still at N/A for such queries (it just never saw any reply at all). Now, as these replies are logged, FTL sees them and can report accordingly.

We have a dedicated reply type called NODATA which is used for a negative response for the domain + type. If the response is negative for the domain overall, we get NXDOMAIN. This can also happen to non-PTR queries, e.g. "dig aggggred.com".

The latter. Otherwise, we'd need to implement how to translate the binary data into human-readable for for each of the query types into dnsmasq. Other tools (such as dig) have this code, however, dnsmasq sees itself just as a DNS forwarder and does simply this: forwarding whatever arrives from upstream as long as certain length checks, etc. are fulfilled. It does not need to understand what it is forwarding. This is actually a good thing because it made HTTPS and other types working even with age-old versions of dnsmasq floating around on the web.

Which brings me to my next question: Do you have Apple devices in your network? If so, how many (about)?

The reason I'm asking is that we've been monitoring HTTPS from the very first moment we've seen reports about it. It is worth mentioning that the specification adding HTTPS and SVCB is still only a draft, i.e., it isn't even fully standardized and, hence, possible subject to change. This is why when we (Pi-hole) chose to adopt this kind of query as HTTPS others (like dnsmasq) hasn't yet implemented that TYPE65 is HTTPS.

You'll see this in pihole.log where such queries are logged as query[type=65] instead of something like query[HTTPS]. I assume it is the same hesitance that causes them to not having implemented caching for this type.


Please check out the custom branch tweak/non_cached_replies using

pihole checkout FTL tweak/non_cached_replies
pihole checkout web tweak/non_cached_replies

This branch is based on the latest beta + my patch sent to dnsmasq upstream + the necessary changes to FTL to make this work.

@Daxtorim It would be great if you could

  1. run your test script on it and get BLOB reply type for all of these
  2. check out some HTTPS queries (I do not have any Apple devices) and see if they are either BLOB or NODATA

edit I just pushed another small update (version vDev-1f18a3e) that fixes a cosmetic issue where the first blocked query after a restart could have been incorrectly shown as allowed. The query was still blocked, only the displayed status was incorrect.

The checkout command is case-sensitive, FTL didn't work, it had to be ftl. Just letting you know.

But trying out the branch, it looks very promising. There are some inconsistencies, however. Maybe they are intentional (you didn't list specific changes).

  1. The reply type of the SRV entry in the Query Log changed from IP to BLOB. But given the actual content of the answer, BLOB is more appropriate anyway.

  2. The log entry for the SRV query says <SRV> where as every other entry uses [SRV] format (different brackets; SRV gets cached as opposed to others; I don't care, but consistency).

  3. The PTR query for ptr.dns.netmeister.org doesn't show a reply type. There was a response (the same as my sample output above) but the log entry is still missing a reply line (log attached below). The response time is also missing, but complete absence instead of 0.0 ms is a good thing in my opinion, if there was never a response in the first place.

  4. The queries for DNSKEY and DS records don't get special treatment with the DNSSEC reply type. I assume that is because they weren't part of actual DNSSEC validation and instead just manual lookups, in which case this is fine by me.

This was the second run of the script again, hence the cached status for some queries.

pihole.log
Aug 27 18:02:18 dnsmasq[14628]: query[A] a.dns.netmeister.org from 192.168.178.20
Aug 27 18:02:18 dnsmasq[14628]: cached a.dns.netmeister.org is 166.84.7.99
Aug 27 18:02:18 dnsmasq[14628]: query[AAAA] aaaa.dns.netmeister.org from 192.168.178.20
Aug 27 18:02:18 dnsmasq[14628]: cached aaaa.dns.netmeister.org is 2001:470:30:84:e276:63ff:fe72:3900
Aug 27 18:02:18 dnsmasq[14628]: query[SRV] srv.dns.netmeister.org from 192.168.178.20
Aug 27 18:02:19 dnsmasq[14628]: cached srv.dns.netmeister.org is <SRV>
Aug 27 18:02:19 dnsmasq[14628]: query[SOA] soa.dns.netmeister.org from 192.168.178.20
Aug 27 18:02:19 dnsmasq[14628]: forwarded soa.dns.netmeister.org to 127.0.0.1
Aug 27 18:02:19 dnsmasq[14628]: validation result is SECURE
Aug 27 18:02:19 dnsmasq[14628]: reply soa.dns.netmeister.org is non-cached [SOA]
Aug 27 18:02:19 dnsmasq[14628]: query[PTR] 99.7.84.166.in-addr.arpa from 192.168.178.20
Aug 27 18:02:19 dnsmasq[14628]: cached 166.84.7.99 is panix.netmeister.org
Aug 27 18:02:19 dnsmasq[14628]: query[PTR] 0.0.9.3.2.7.e.f.f.f.3.6.6.7.2.e.4.8.0.0.0.3.0.0.0.7.4.0.1.0.0.2.ip6.arpa from 192.168.178.20
Aug 27 18:02:19 dnsmasq[14628]: cached 2001:470:30:84:e276:63ff:fe72:3900 is panix.netmeister.org
####### ↓↓↓ This one doesn't have a reply line even though a reply was received ↓↓↓
Aug 27 18:02:19 dnsmasq[14628]: query[PTR] ptr.dns.netmeister.org from 192.168.178.20
Aug 27 18:02:19 dnsmasq[14628]: forwarded ptr.dns.netmeister.org to 127.0.0.1
Aug 27 18:02:19 dnsmasq[14628]: validation result is SECURE
#######
Aug 27 18:02:19 dnsmasq[14628]: query[TXT] txt.dns.netmeister.org from 192.168.178.20
Aug 27 18:02:19 dnsmasq[14628]: forwarded txt.dns.netmeister.org to 127.0.0.1
Aug 27 18:02:19 dnsmasq[14628]: validation result is SECURE
Aug 27 18:02:19 dnsmasq[14628]: reply txt.dns.netmeister.org is Format: <text>
Aug 27 18:02:19 dnsmasq[14628]: reply txt.dns.netmeister.org is Descriptive text. Completely overloaded for all sorts of things. RFC1035 (1987)
Aug 27 18:02:19 dnsmasq[14628]: query[NAPTR] naptr.dns.netmeister.org from 192.168.178.20
Aug 27 18:02:19 dnsmasq[14628]: forwarded naptr.dns.netmeister.org to 127.0.0.1
Aug 27 18:02:19 dnsmasq[14628]: validation result is SECURE
Aug 27 18:02:19 dnsmasq[14628]: reply naptr.dns.netmeister.org is non-cached [NAPTR]
Aug 27 18:02:19 dnsmasq[14628]: reply naptr.dns.netmeister.org is non-cached [NAPTR]
Aug 27 18:02:19 dnsmasq[14628]: query[MX] mx.dns.netmeister.org from 192.168.178.20
Aug 27 18:02:19 dnsmasq[14628]: forwarded mx.dns.netmeister.org to 127.0.0.1
Aug 27 18:02:19 dnsmasq[14628]: validation result is SECURE
Aug 27 18:02:19 dnsmasq[14628]: reply mx.dns.netmeister.org is non-cached [MX]
Aug 27 18:02:19 dnsmasq[14628]: query[DS] ds.dns.netmeister.org from 192.168.178.20
Aug 27 18:02:19 dnsmasq[14628]: forwarded ds.dns.netmeister.org to 127.0.0.1
Aug 27 18:02:19 dnsmasq[14628]: validation result is SECURE
Aug 27 18:02:19 dnsmasq[14628]: reply ds.dns.netmeister.org is non-cached [DS]
Aug 27 18:02:19 dnsmasq[14628]: query[RRSIG] rrsig.dns.netmeister.org from 192.168.178.20
Aug 27 18:02:19 dnsmasq[14628]: forwarded rrsig.dns.netmeister.org to 127.0.0.1
Aug 27 18:02:19 dnsmasq[14628]: validation result is INSECURE
Aug 27 18:02:19 dnsmasq[14628]: reply rrsig.dns.netmeister.org is non-cached [RRSIG]
Aug 27 18:02:19 dnsmasq[14628]: reply rrsig.dns.netmeister.org is non-cached [RRSIG]
Aug 27 18:02:19 dnsmasq[14628]: query[DNSKEY] dnskey.dns.netmeister.org from 192.168.178.20
Aug 27 18:02:19 dnsmasq[14628]: forwarded dnskey.dns.netmeister.org to 127.0.0.1
Aug 27 18:02:19 dnsmasq[14628]: validation result is SECURE
Aug 27 18:02:19 dnsmasq[14628]: reply dnskey.dns.netmeister.org is non-cached [DNSKEY]
Aug 27 18:02:19 dnsmasq[14628]: query[NS] ns.dns.netmeister.org from 192.168.178.20
Aug 27 18:02:19 dnsmasq[14628]: forwarded ns.dns.netmeister.org to 127.0.0.1
Aug 27 18:02:19 dnsmasq[14628]: validation result is SECURE
Aug 27 18:02:19 dnsmasq[14628]: reply ns.dns.netmeister.org is non-cached [NS]
Aug 27 18:02:19 dnsmasq[14628]: query[type=64] svcb.dns.netmeister.org from 192.168.178.20
Aug 27 18:02:19 dnsmasq[14628]: forwarded svcb.dns.netmeister.org to 127.0.0.1
Aug 27 18:02:19 dnsmasq[14628]: validation result is SECURE
Aug 27 18:02:19 dnsmasq[14628]: reply svcb.dns.netmeister.org is non-cached [type=64]
Aug 27 18:02:19 dnsmasq[14628]: query[type=65] https.dns.netmeister.org from 192.168.178.20
Aug 27 18:02:19 dnsmasq[14628]: forwarded https.dns.netmeister.org to 127.0.0.1
Aug 27 18:02:19 dnsmasq[14628]: validation result is SECURE
Aug 27 18:02:19 dnsmasq[14628]: reply https.dns.netmeister.org is non-cached [type=65]
Aug 27 18:02:19 dnsmasq[14628]: reply https.dns.netmeister.org is non-cached [type=65]

As for HTTPS queries specifically, NODATA and NXDOMAIN are also working. You saw BLOB in the other screenshot above. I just used dig TYPE65 domain from my PC, but that shouldn't matter (right?). I'll check for genuine queries when the apple devices come home (they are family's).


edit:
Here are queries from actual iPhones. CNAME as a reply type also works and blocking as well. (Blocking wasn't broken in the first place, it just happened to be in the shot)

/edit


Right, there isn't a one-size-fits-all approach to parsing all queries regardless of type. Not something I need anyway, was just curious how that was handled.

Yes, two iPhones and an apple watch. Usually the amount of "natural" HTTPS queries hovers between 5% and 10%, but when the apple devices are alone on the network or guests bring additional ones, the amount can be much higher than that. It's rare, hence my "at times", but it does happen.

Thanks you very much for your thorough tests. Once everything settled, I'm looking forward to add all these DNS requests to our CI test to ensure the now improved functionality will be automatically tested in the future.

Yes. Due to the lack of a "one-fits-all" case, everything that wasn't a specific type went into the IP reply bucket. This comes from a very old part of the code and is now better.

Yes, this is something we'd have to change in dnsmasq, too. However, my feeling is that a patch for this would just be ignored because it doesn't actually change anything. This happened to similar patches from others in the past. Let's call it an inconsistency by design.

This is interesting. PTRs can be cached and are handled in yet another region of the code so I missed them. So far, PTR requests coming from local config (incl. /etc/hosts) are logged (can be seen in your screenshot as well) but replies from upstream are not. This will need another dnsmasq patch.

This is intentional.

Yes. Because they are not interpreted by dnsmasq and, hence, they are just pushed through appearing as arbitrary BLOB data. I guess that's fine.

Yes.

Thanks. This reveals something interesting. Blocking is N/A because we respond with REFUSED. This was recommended in the HTTPS draft as reply when the information isn't available. I just checked the most recent draft and this section was removed without replacement. I'll change this to an empty NODATA reply with appropriate logging.

I'll work on the things when the weather gets worse and report back.

After checking the code, I have to slightly correct myself on this statement. "IP address PTRs" are logged and cached, e.g.,

Aug 28 20:42:55 dnsmasq[1570270]: 433 127.0.0.1/46468 query[PTR] 8.8.8.8.in-addr.arpa from 127.0.0.1
Aug 28 20:42:55 dnsmasq[1570270]: 433 127.0.0.1/46468 forwarded 8.8.8.8.in-addr.arpa to 127.0.0.1
Aug 28 20:42:55 dnsmasq[1570270]: 433 127.0.0.1/46468 reply 8.8.8.8 is dns.google

If PTR lookups are not IP-address related (as in your example), they cannot be cached (and, hence, are not logged). I'll work on this tomorrow.

I added recording the non-cachable PTRs and submitted a patch upstream.

Furthermore, I added your script from above - assuming you'd agree - in a slightly modified form (also adding ANY and CNAME) to our automated CI testing so reply types cannot be off in the future without us noticing this:

edit Yet another patch submitted upstream: when the question type is different than the answer type - this isn't cached, either. It happen with CNAMEs or, even more obvious, with ANY queries.

TBH, logging all this stuff makes the corresponding dnsmasq code even more complex than it was before. I rather hope Simon Kelley has a better idea to implement the same. I just didn't want to touch too many places in the code as the bigger the patch, the less likely the merge...

No objections from me.

Now I guess it's a waiting game to see what Simon thinks about it.

Simon applied the series of patches and improved them by doing exactly what I didn't want to do:

and his reply was:

Right. That was a bit of a rabbit-hole.

I started with your patch, and began to make it more elegant by doing
all the logging in extract_address(). In the process I found a
long-standing bug (CNAME chains ending in a PTR record were not handled
correctly) and a couple of problems introduced by the changes.

The final outcome is quite a big change, and I did wonder if it would be
better to leave it 'till 2.87, but the long-standing CNAME-PTR bug
tipped the balance in favour of doing it now.

I've tagged 2.86rc2. I've systematically tested the affected code, and
we're dog-fooding it now. It would be good to get as much other testing
in as possible before the 2.86.

Cheers,

Simon.

Accordingly, I undid my "dnsmasq patch {1,2,3}" commits in this branch and committed his larger patch instead. Everything compiled just fine and the CI did not complain when doing the dig tests. I will admit that I was a bit surprised that everything worked that smoothly.
The code was pushed yesterday evening to this special branch and is now also part of the regular beta branches - to have as many users as possible contribute to testing.

Thanks for your report and assistance, as always :slight_smile:

3 Likes

The new logging works even on the ftl release/v5.9 branch :+1: , but the web release/v5.6 branch is missing the BLOB reply type.

Thanks for the hint, I've opened a PR awaiting review:

Concerning consistency,

we've got another patch in that makes this use < ... > for types everywhere, even those dnsmasq doesn't know (like Apple's HTTPS):

Sep  2 11:23:52 dnsmasq[1815646]: query[type=65] https.dns.netmeister.org from 127.0.0.1
Sep  2 11:23:52 dnsmasq[1815646]: forwarded https.dns.netmeister.org to 127.0.0.1
Sep  2 11:23:53 dnsmasq[1815646]: validation result is SECURE
Sep  2 11:23:53 dnsmasq[1815646]: reply https.dns.netmeister.org is <type=65>
Sep  2 11:23:53 dnsmasq[1815646]: reply https.dns.netmeister.org is <type=65>

They are now analyzed, too. DNSKEY and DS get DNSSEC type and SECURE status when they have been validated. DS may get NODATA and INSECURE when there is no DS record for the requested domain.

Furthermore, we analyze the DNSSEC status also for cached queries (will be either SECURE or INSECURE as BOGUS queries are not cached).

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.