Okay, thank you for the explanation.
Your answer got me looking into why the message appears all the time when it should not appear if the result is already present in pihole-ftl's cache.
I think pihole-ftl is not storing anything in its cache and forwarding all requests to dnscrypt-proxy. The logs seem to confirm this as well, two consecutive requests to are both forwarded to dnscrypt-proxy. Query times are similar for both requests.
Oct 9 18:02:38 dnsmasq[554]: 60859 127.0.0.1/45827 query[A] google.com from 127.0.0.1
Oct 9 18:02:38 dnsmasq[554]: 60859 127.0.0.1/45827 forwarded google.com to 127.0.0.1
Oct 9 18:02:38 dnsmasq[554]: * 127.0.0.1/45827 dnssec-query[DS] com to 127.0.0.1
Oct 9 18:02:38 dnsmasq[554]: * 127.0.0.1/45827 dnssec-query[DNSKEY] . to 127.0.0.1
Oct 9 18:02:38 dnsmasq[554]: 60859 127.0.0.1/45827 reply google.com is 172.217.194.102
Oct 9 18:02:38 dnsmasq[554]: 60859 127.0.0.1/45827 reply google.com is 172.217.194.113
Oct 9 18:02:38 dnsmasq[554]: 60859 127.0.0.1/45827 reply google.com is 172.217.194.101
Oct 9 18:02:38 dnsmasq[554]: 60859 127.0.0.1/45827 reply google.com is 172.217.194.139
Oct 9 18:02:38 dnsmasq[554]: 60859 127.0.0.1/45827 reply google.com is 172.217.194.138
Oct 9 18:02:38 dnsmasq[554]: 60859 127.0.0.1/45827 reply google.com is 172.217.194.100
Oct 9 18:02:38 dnsmasq[22103]: 60860 127.0.0.1/44171 query[A] google.com from 127.0.0.1
Oct 9 18:02:38 dnsmasq[22103]: 60860 127.0.0.1/44171 forwarded google.com to 127.0.0.1
Oct 9 18:02:38 dnsmasq[22103]: * 127.0.0.1/44171 dnssec-query[DS] com to 127.0.0.1
Oct 9 18:02:39 dnsmasq[22103]: * 127.0.0.1/44171 dnssec-query[DNSKEY] . to 127.0.0.1
Oct 9 18:02:39 dnsmasq[22103]: * 127.0.0.1/44171 reply . is DNSKEY keytag 2134, algo 8
Oct 9 18:02:39 dnsmasq[22103]: * 127.0.0.1/44171 reply . is DNSKEY keytag 41656, algo 8
Oct 9 18:02:39 dnsmasq[22103]: * 127.0.0.1/44171 reply . is DNSKEY keytag 19036, algo 8
Oct 9 18:02:39 dnsmasq[22103]: * 127.0.0.1/44171 reply . is DNSKEY keytag 20326, algo 8
Oct 9 18:02:39 dnsmasq[22103]: * 127.0.0.1/44171 reply com is DS keytag 30909, algo 8, digest 2
Oct 9 18:02:39 dnsmasq[22103]: * 127.0.0.1/44171 dnssec-query[DS] google.com to 127.0.0.1
Oct 9 18:02:39 dnsmasq[22103]: * 127.0.0.1/44171 dnssec-query[DNSKEY] com to 127.0.0.1
Oct 9 18:02:39 dnsmasq[22103]: * 127.0.0.1/44171 reply com is DNSKEY keytag 46475, algo 8
Oct 9 18:02:39 dnsmasq[22103]: * 127.0.0.1/44171 reply com is DNSKEY keytag 30909, algo 8
Oct 9 18:02:39 dnsmasq[22103]: * 127.0.0.1/44171 reply google.com is no DS
Oct 9 18:02:39 dnsmasq[22103]: 60860 127.0.0.1/44171 validation result is INSECURE
Oct 9 18:02:39 dnsmasq[22103]: 60860 127.0.0.1/44171 reply google.com is 172.217.194.102
Oct 9 18:02:39 dnsmasq[22103]: 60860 127.0.0.1/44171 reply google.com is 172.217.194.113
Oct 9 18:02:39 dnsmasq[22103]: 60860 127.0.0.1/44171 reply google.com is 172.217.194.101
Oct 9 18:02:39 dnsmasq[22103]: 60860 127.0.0.1/44171 reply google.com is 172.217.194.139
Oct 9 18:02:39 dnsmasq[22103]: 60860 127.0.0.1/44171 reply google.com is 172.217.194.138
Oct 9 18:02:39 dnsmasq[22103]: 60860 127.0.0.1/44171 reply google.com is 172.217.194.100
Oct 9 18:02:45 dnsmasq[554]: 60960 127.0.0.1/41794 query[A] google.com from 127.0.0.1
Oct 9 18:02:45 dnsmasq[554]: 60960 127.0.0.1/41794 forwarded google.com to 127.0.0.1
Oct 9 18:02:45 dnsmasq[554]: * 127.0.0.1/41794 dnssec-query[DS] com to 127.0.0.1
Oct 9 18:02:45 dnsmasq[554]: * 127.0.0.1/41794 dnssec-query[DNSKEY] . to 127.0.0.1
Oct 9 18:02:45 dnsmasq[554]: 60960 127.0.0.1/41794 reply google.com is 172.217.194.102
Oct 9 18:02:45 dnsmasq[554]: 60960 127.0.0.1/41794 reply google.com is 172.217.194.113
Oct 9 18:02:45 dnsmasq[554]: 60960 127.0.0.1/41794 reply google.com is 172.217.194.101
Oct 9 18:02:45 dnsmasq[554]: 60960 127.0.0.1/41794 reply google.com is 172.217.194.139
Oct 9 18:02:45 dnsmasq[554]: 60960 127.0.0.1/41794 reply google.com is 172.217.194.138
Oct 9 18:02:45 dnsmasq[554]: 60960 127.0.0.1/41794 reply google.com is 172.217.194.100
Oct 9 18:02:45 dnsmasq[22172]: 60961 127.0.0.1/56487 query[A] google.com from 127.0.0.1
Oct 9 18:02:45 dnsmasq[22172]: 60961 127.0.0.1/56487 forwarded google.com to 127.0.0.1
Oct 9 18:02:45 dnsmasq[22172]: * 127.0.0.1/56487 dnssec-query[DS] com to 127.0.0.1
Oct 9 18:02:45 dnsmasq[22172]: * 127.0.0.1/56487 dnssec-query[DNSKEY] . to 127.0.0.1
Oct 9 18:02:45 dnsmasq[22172]: * 127.0.0.1/56487 reply . is DNSKEY keytag 2134, algo 8
Oct 9 18:02:45 dnsmasq[22172]: * 127.0.0.1/56487 reply . is DNSKEY keytag 41656, algo 8
Oct 9 18:02:45 dnsmasq[22172]: * 127.0.0.1/56487 reply . is DNSKEY keytag 19036, algo 8
Oct 9 18:02:45 dnsmasq[22172]: * 127.0.0.1/56487 reply . is DNSKEY keytag 20326, algo 8
Oct 9 18:02:45 dnsmasq[22172]: * 127.0.0.1/56487 reply com is DS keytag 30909, algo 8, digest 2
Oct 9 18:02:45 dnsmasq[22172]: * 127.0.0.1/56487 dnssec-query[DS] google.com to 127.0.0.1
Oct 9 18:02:45 dnsmasq[22172]: * 127.0.0.1/56487 dnssec-query[DNSKEY] com to 127.0.0.1
Oct 9 18:02:45 dnsmasq[22172]: * 127.0.0.1/56487 reply com is DNSKEY keytag 46475, algo 8
Oct 9 18:02:45 dnsmasq[22172]: * 127.0.0.1/56487 reply com is DNSKEY keytag 30909, algo 8
Oct 9 18:02:45 dnsmasq[22172]: * 127.0.0.1/56487 reply google.com is no DS
Oct 9 18:02:45 dnsmasq[22172]: 60961 127.0.0.1/56487 validation result is INSECURE
Oct 9 18:02:45 dnsmasq[22172]: 60961 127.0.0.1/56487 reply google.com is 172.217.194.102
Oct 9 18:02:45 dnsmasq[22172]: 60961 127.0.0.1/56487 reply google.com is 172.217.194.113
Oct 9 18:02:45 dnsmasq[22172]: 60961 127.0.0.1/56487 reply google.com is 172.217.194.101
Oct 9 18:02:45 dnsmasq[22172]: 60961 127.0.0.1/56487 reply google.com is 172.217.194.139
Oct 9 18:02:45 dnsmasq[22172]: 60961 127.0.0.1/56487 reply google.com is 172.217.194.138
Oct 9 18:02:45 dnsmasq[22172]: 60961 127.0.0.1/56487 reply google.com is 172.217.194.100
I compared this behavior with the logs from dnsmasq-2.79 and the logs for this do show that the second response was served from the cache.
dnsmasq: started, version 2.79 cachesize 10000
dnsmasq: compile time options: IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP DHCPv6 no-Lua TFTP no-conntrack ipset auth DNSSEC loop-detect inotify
dnsmasq: DNSSEC validation enabled
dnsmasq: asynchronous logging enabled, queue limit is 5 messages
dnsmasq: using nameserver 127.0.0.1#54
dnsmasq: read /etc/hosts - 5 addresses
dnsmasq: 1 127.0.0.1/33543 query[A] google.com from 127.0.0.1
dnsmasq: 1 127.0.0.1/33543 forwarded google.com to 127.0.0.1
dnsmasq: * 127.0.0.1/33543 dnssec-query[DS] com to 127.0.0.1
dnsmasq: * 127.0.0.1/33543 dnssec-query[DNSKEY] . to 127.0.0.1
dnsmasq: 1 127.0.0.1/33543 reply google.com is 172.217.194.102
dnsmasq: 1 127.0.0.1/33543 reply google.com is 172.217.194.113
dnsmasq: 1 127.0.0.1/33543 reply google.com is 172.217.194.101
dnsmasq: 1 127.0.0.1/33543 reply google.com is 172.217.194.139
dnsmasq: 1 127.0.0.1/33543 reply google.com is 172.217.194.138
dnsmasq: 1 127.0.0.1/33543 reply google.com is 172.217.194.100
dnsmasq: 2 127.0.0.1/43569 query[A] google.com from 127.0.0.1
dnsmasq: 2 127.0.0.1/43569 forwarded google.com to 127.0.0.1
dnsmasq: * 127.0.0.1/43569 dnssec-query[DS] com to 127.0.0.1
dnsmasq: * 127.0.0.1/43569 dnssec-query[DNSKEY] . to 127.0.0.1
dnsmasq: * 127.0.0.1/43569 reply . is DNSKEY keytag 2134, algo 8
dnsmasq: * 127.0.0.1/43569 reply . is DNSKEY keytag 41656, algo 8
dnsmasq: * 127.0.0.1/43569 reply . is DNSKEY keytag 19036, algo 8
dnsmasq: * 127.0.0.1/43569 reply . is DNSKEY keytag 20326, algo 8
dnsmasq: * 127.0.0.1/43569 reply com is DS keytag 30909, algo 8, digest 2
dnsmasq: * 127.0.0.1/43569 dnssec-query[DS] google.com to 127.0.0.1
dnsmasq: * 127.0.0.1/43569 dnssec-query[DNSKEY] com to 127.0.0.1
dnsmasq: * 127.0.0.1/43569 reply com is DNSKEY keytag 46475, algo 8
dnsmasq: * 127.0.0.1/43569 reply com is DNSKEY keytag 30909, algo 8
dnsmasq: * 127.0.0.1/43569 reply google.com is no DS
dnsmasq: 2 127.0.0.1/43569 validation result is INSECURE
dnsmasq: 2 127.0.0.1/43569 reply google.com is 172.217.194.102
dnsmasq: 2 127.0.0.1/43569 reply google.com is 172.217.194.113
dnsmasq: 2 127.0.0.1/43569 reply google.com is 172.217.194.101
dnsmasq: 2 127.0.0.1/43569 reply google.com is 172.217.194.139
dnsmasq: 2 127.0.0.1/43569 reply google.com is 172.217.194.138
dnsmasq: 2 127.0.0.1/43569 reply google.com is 172.217.194.100
dnsmasq: 3 127.0.0.1/36602 query[A] google.com from 127.0.0.1
dnsmasq: 3 127.0.0.1/36602 cached google.com is 172.217.194.100
dnsmasq: 3 127.0.0.1/36602 cached google.com is 172.217.194.138
dnsmasq: 3 127.0.0.1/36602 cached google.com is 172.217.194.139
dnsmasq: 3 127.0.0.1/36602 cached google.com is 172.217.194.101
dnsmasq: 3 127.0.0.1/36602 cached google.com is 172.217.194.113
dnsmasq: 3 127.0.0.1/36602 cached google.com is 172.217.194.102
Note that upstream is dnscrypt-proxy for both pihole-ftl and dnsmasq2.79.
The response time for the second request is substantially lower (77ms for the 1st, 6ms for the 2nd). The truncated message also does not appear for the cached response.
I think I may be having the same problem mentioned in this thread: Pi-hole not caching when using dnscrypt-proxy
Should I move the conversation over there?
EDIT: This may also help
pi@pi-hole:~ $ echo ">cacheinfo" | nc 127.0.0.1 4711
cache-size: 10000
cache-live-freed: 0
cache-inserted: 0
---EOM---