Pi-hole blocking domain it shouldn't

sawsanders · December 23, 2023, 3:49pm

Pi-hole has started randomly blocking domains that aren't showing up with pihole -q. But only for random network devices.

For example, right now Pi-hole is blocking imap.mail.yahoo.com on my laptop:

Macbook ~ % dig imap.mail.yahoo.com               

; <<>> DiG 9.10.6 <<>> imap.mail.yahoo.com
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 1116
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;imap.mail.yahoo.com.		IN	A

;; ANSWER SECTION:
imap.mail.yahoo.com.	2	IN	A	0.0.0.0

;; Query time: 46 msec
;; SERVER: 192.168.10.25#53(192.168.10.25)
;; WHEN: Sat Dec 23 07:33:46 PST 2023
;; MSG SIZE  rcvd: 64

Querying the lists shows nothing:

pi@pi0-2:~$ pihole -q imap.mail.yahoo.com
Found 0 domains exactly matching 'imap.mail.yahoo.com'.

Found 0 adlists exactly matching 'imap.mail.yahoo.com'.

Dig from Pi-hole:

pi@pi0-2:~$ dig imap.mail.yahoo.com

; <<>> DiG 9.18.18-0ubuntu0.22.04.1-Ubuntu <<>> imap.mail.yahoo.com
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 1029
;; flags: qr rd ra; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;imap.mail.yahoo.com.		IN	A

;; ANSWER SECTION:
imap.mail.yahoo.com.	1027	IN	CNAME	jimap.imap.mail.yahoo.com.
jimap.imap.mail.yahoo.com. 1027	IN	CNAME	jimapinternal.imap.mail.g03.yahoodns.net.
jimapinternal.imap.mail.g03.yahoodns.net. 300 IN A 98.137.27.103
jimapinternal.imap.mail.g03.yahoodns.net. 300 IN A 67.195.228.138

;; Query time: 239 msec
;; SERVER: 192.168.10.25#53(192.168.10.25) (UDP)
;; WHEN: Sat Dec 23 07:32:49 PST 2023
;; MSG SIZE  rcvd: 154

Dig from another computer on the network:

Kitchen ~ % dig imap.mail.yahoo.com

; <<>> DiG 9.10.6 <<>> imap.mail.yahoo.com
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 20347
;; flags: qr rd ra; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
;; QUESTION SECTION:
;imap.mail.yahoo.com.		IN	A

;; ANSWER SECTION:
imap.mail.yahoo.com.	763	IN	CNAME	jimap.imap.mail.yahoo.com.
jimap.imap.mail.yahoo.com. 763	IN	CNAME	jimapinternal.imap.mail.g03.yahoodns.net.
jimapinternal.imap.mail.g03.yahoodns.net. 36 IN	A 67.195.228.138
jimapinternal.imap.mail.g03.yahoodns.net. 36 IN	A 98.137.27.103

;; Query time: 14 msec
;; SERVER: 192.168.10.25#53(192.168.10.25)
;; WHEN: Sat Dec 23 07:37:13 PST 2023
;; MSG SIZE  rcvd: 173

Pi-hole log file showing queries from the laptop being blocked and not on the other computer:

Dec 23 07:45:16 dnsmasq[3045017]: query[A] imap.mail.yahoo.com from 192.168.10.112
Dec 23 07:45:16 dnsmasq[3045017]: gravity blocked imap.mail.yahoo.com is 0.0.0.0
Dec 23 07:45:50 dnsmasq[3045017]: query[A] imap.mail.yahoo.com from 192.168.10.158
Dec 23 07:45:50 dnsmasq[3045017]: forwarded imap.mail.yahoo.com to 127.0.0.1#5335
Dec 23 07:45:50 dnsmasq[3045017]: reply imap.mail.yahoo.com is <CNAME>
Dec 23 07:45:50 dnsmasq[3045017]: reply jimap.imap.mail.yahoo.com is <CNAME>

Restarting the FTL will correct the problem.

Debug log run when issue is present: https://tricorder.pi-hole.net/WNoyclac/

Bucking_Horn · December 23, 2023, 4:10pm

What is Pi-hole's Query Log showing for that unexpectedly blocked request?

sawsanders · December 23, 2023, 4:18pm

Bucking_Horn · December 23, 2023, 4:24pm

So it's not blocking externally or based on CNAME information.

Using Pi-hole's web UI, are there any partial matches in your blocklists?

sawsanders · December 23, 2023, 4:28pm

Nothing:

Found 0 domains *partially* matching '**imap.mail.yahoo.com**'.

Found 0 lists *partially* matching '**imap.mail.yahoo.com**'.

Number of results per type:
- **0** exact domain matches
- **0** regex domain matches
- **0** allowlist (antigravity) matches
- **0** blocklist (gravity) matches

yubiuser · December 23, 2023, 4:34pm

Please enable debug.queries and see what it logs when the query is blocked.

sawsanders · December 23, 2023, 4:56pm

Not blocked client:

2023-12-23 08:49:43.822 [3045017M] DEBUG_QUERIES: **** new UDP IPv4 query[A] query "imap.mail.yahoo.com" from usb0/192.168.10.158#60531 (ID 253565, FTL 119581, src/dnsmasq/forward.c:1773)
2023-12-23 08:49:43.826 [3045017M] DEBUG_QUERIES: imap.mail.yahoo.com is known as not to be blocked
2023-12-23 08:49:43.826 [3045017M] DEBUG_QUERIES: **** got cache reply: imap.mail.yahoo.com is (CNAME) (ID 253565, src/dnsmasq/rfc1035.c:1600)
2023-12-23 08:49:43.827 [3045017M] DEBUG_QUERIES: Set reply to CNAME (3) in src/dnsmasq_interface.c:2068
2023-12-23 08:49:43.828 [3045017M] DEBUG_QUERIES: **** got cache reply: jimap.imap.mail.yahoo.com is (CNAME) (ID 253565, src/dnsmasq/rfc1035.c:1600)
2023-12-23 08:49:43.829 [3045017M] DEBUG_QUERIES: **** forwarded imap.mail.yahoo.com to 192.168.10.20#5335 (ID 253565, src/dnsmasq/forward.c:553)
2023-12-23 08:49:43.867 [3045017M] DEBUG_QUERIES: **** DNSSEC imap.mail.yahoo.com is INSECURE (ID 253565, src/dnsmasq/forward.c:1378)
2023-12-23 08:49:43.868 [3045017M] DEBUG_QUERIES: **** got upstream reply from 192.168.10.20#5335: imap.mail.yahoo.com is (CNAME) (ID 253565, src/dnsmasq/rfc1035.c:762)
2023-12-23 08:49:43.869 [3045017M] DEBUG_QUERIES: FTL_CNAME called with: src = imap.mail.yahoo.com, dst = jimap.imap.mail.yahoo.com, id = 253565
2023-12-23 08:49:43.877 [3045017M] DEBUG_QUERIES: jimap.imap.mail.yahoo.com is not known
2023-12-23 08:49:43.879 [3045017M] DEBUG_QUERIES: Checking if "jimap.imap.mail.yahoo.com" is in antigravity (exact): no
2023-12-23 08:49:43.880 [3045017M] DEBUG_QUERIES: Checking if "@@||com^" is in antigravity (ABP): no
2023-12-23 08:49:43.880 [3045017M] DEBUG_QUERIES: Checking if "@@||yahoo.com^" is in antigravity (ABP): no
2023-12-23 08:49:43.881 [3045017M] DEBUG_QUERIES: Checking if "@@||mail.yahoo.com^" is in antigravity (ABP): no
2023-12-23 08:49:43.881 [3045017M] DEBUG_QUERIES: Checking if "@@||imap.mail.yahoo.com^" is in antigravity (ABP): no
2023-12-23 08:49:43.882 [3045017M] DEBUG_QUERIES: Checking if "@@||jimap.imap.mail.yahoo.com^" is in antigravity (ABP): no
2023-12-23 08:49:43.883 [3045017M] DEBUG_QUERIES: Checking if "jimap.imap.mail.yahoo.com" is in gravity (exact): no
2023-12-23 08:49:43.883 [3045017M] DEBUG_QUERIES: Checking if "||com^" is in gravity (ABP): no
2023-12-23 08:49:43.884 [3045017M] DEBUG_QUERIES: Checking if "||yahoo.com^" is in gravity (ABP): no
2023-12-23 08:49:43.884 [3045017M] DEBUG_QUERIES: Checking if "||mail.yahoo.com^" is in gravity (ABP): no
2023-12-23 08:49:43.885 [3045017M] DEBUG_QUERIES: Checking if "||imap.mail.yahoo.com^" is in gravity (ABP): no
2023-12-23 08:49:43.886 [3045017M] DEBUG_QUERIES: Checking if "||jimap.imap.mail.yahoo.com^" is in gravity (ABP): no
2023-12-23 08:49:43.886 [3045017M] DEBUG_QUERIES: DNS cache: 192.168.10.158/jimap.imap.mail.yahoo.com is not blocked (domainlist ID: -1)
2023-12-23 08:49:43.887 [3045017M] DEBUG_QUERIES: Query 253565: CNAME imap.mail.yahoo.com ---> jimap.imap.mail.yahoo.com
2023-12-23 08:49:43.887 [3045017M] DEBUG_QUERIES: **** got upstream reply: jimap.imap.mail.yahoo.com is (CNAME) (ID 253565, src/dnsmasq/rfc1035.c:762)
2023-12-23 08:49:43.888 [3045017M] DEBUG_QUERIES: FTL_CNAME called with: src = jimap.imap.mail.yahoo.com, dst = jimapinternal.imap.mail.g03.yahoodns.net, id = 253565
2023-12-23 08:49:43.890 [3045017M] DEBUG_QUERIES: jimapinternal.imap.mail.g03.yahoodns.net is known as not to be blocked
2023-12-23 08:49:43.891 [3045017M] DEBUG_QUERIES: Query 253565: CNAME jimap.imap.mail.yahoo.com ---> jimapinternal.imap.mail.g03.yahoodns.net
2023-12-23 08:49:43.891 [3045017M] DEBUG_QUERIES: **** got upstream reply: jimapinternal.imap.mail.g03.yahoodns.net is 67.195.228.138 (ID 253565, src/dnsmasq/rfc1035.c:969)
2023-12-23 08:49:43.892 [3045017M] DEBUG_QUERIES: **** got upstream reply: jimapinternal.imap.mail.g03.yahoodns.net is 98.137.27.103 (ID 253565, src/dnsmasq/rfc1035.c:969)

Blocked client:

2023-12-23 08:49:48.583 [3045017M] DEBUG_QUERIES: **** new UDP IPv4 query[A] query "imap.mail.yahoo.com" from usb0/192.168.10.112#50733 (ID 253573, FTL 119589, src/dnsmasq/forward.c:1773)
2023-12-23 08:49:48.586 [3045017M] DEBUG_QUERIES: imap.mail.yahoo.com is known as gravity blocked
2023-12-23 08:49:48.587 [3045017M] DEBUG_QUERIES: Preparing reply for "imap.mail.yahoo.com", EDE: N/A
2023-12-23 08:49:48.587 [3045017M] DEBUG_QUERIES:   Adding RR: "imap.mail.yahoo.com A 0.0.0.0"
2023-12-23 08:49:48.588 [3045017M] DEBUG_QUERIES: **** got cache reply: imap.mail.yahoo.com is 0.0.0.0 (ID 253573, src/dnsmasq_interface.c:406)
2023-12-23 08:49:48.588 [3045017M] DEBUG_QUERIES: Skipping detection of external blocking IP for ID 253573 as origin is HOSTS
2023-12-23 08:49:48.589 [3045017M] DEBUG_QUERIES: Set reply to IP (4) in src/dnsmasq_interface.c:2068

deHakkelaar · December 23, 2023, 7:42pm

I experienced exactly the same with a local newspaper domain ... twice.
First time it got resolved by running pihole -up.
Second time restarting pihole-FTL fixed it.
Will post log output once it happens again.

DL6ER · December 24, 2023, 9:04am

This means the decision why this is to be blocked for this client has been done before.

I'd recommend the following to ease debugging:

sudo service pihole-FTL stop
sudo rm /var/log/pihole/FTL.log*
sudo service pihole-FTL start

to clear the logs initially.

Then, when you notice it again, run

zgrep -A15 "\"imap.mail.yahoo.com\" from usb0/192.168.10.112" /var/log/pihole/FTL.log*

which will list all queries for this domain from this client. The first one should already be the one telling us why it was blocked. -A15 gives us fifteen lines of context after the matching string. If this is insufficient (there is no other new ... query line here), you could try larger numbers.

Update includes a restart when the binary got updated.

sawsanders · December 24, 2023, 2:30pm

Ok, done. Hopefully it happens soon and we can figure out what's happening.

In the mean time, I hope you all have a Merry Christmas!

DL6ER · December 24, 2023, 3:27pm

We might have an idea where it comes from (missing recycling of cache entries causing incorrect left overs). I've already written a proposed fix earlier today but haven't found the time to actually test it. And no promises when I will come to it but hopefully soon (ish).

PS: and when I'm right, it will not happen within 24h after a restart or a DNS cache flushing

DL6ER · December 24, 2023, 8:46pm

github.com/pi-hole/FTL

Implement DNS cache recycling

pi-hole:development-v6 ← pi-hole:fix/cache_recycling

opened 08:45PM - 24 Dec 23 UTC

DL6ER

+53 -45

# What does this implement/fix? This PR completes what was started in #1694 -… memory recycling. The issue at hand was caused by adding the facility to recycle DNS cache records but then never actually doing it. The missing bits are added in this PR. This fixes an issue described on Discourse (see link below): After a certain time has passed, clients and domains may be recycled, however the cache records saying that "clientID=123,domainID=234 -> blocked" remained. This was harmless *until* a new (possibly but not necessarily the old) client/domain combination in exactly this configuration appeared which then lead to a cached reply which was actually intended for something entirely different. This is fixed by recycling cache records as soon as they are not referenced by any query. This is similar to how we recycle clients and domains, too - we remove them when the last query referencing them disappeared due to aging (> 24h). --- **Related issue or feature (if applicable):** N/A **Pull request in [docs](https://github.com/pi-hole/docs) with documentation (if applicable):** N/A --- **By submitting this pull request, I confirm the following:** 1. I have read and understood the [contributors guide](https://docs.pi-hole.net/guides/github/contributing/), as well as this entire template. I understand which branch to base my commits and Pull Requests against. 2. I have commented my proposed changes within the code. 3. I am willing to help maintain this change if there are issues with it later. 4. It is compatible with the [EUPL 1.2 license](https://opensource.org/licenses/EUPL-1.1) 5. I have squashed any insignificant commits. ([`git rebase`](http://gitready.com/advanced/2009/02/10/squashing-commits-with-rebase.html)) ## Checklist: - [x] The code change is tested and works locally. - [x] I based my code and PRs against the repositories `developmental` branch. - [x] I [signed off](https://docs.pi-hole.net/guides/github/how-to-signoff/) all commits. Pi-hole enforces the [DCO](https://docs.pi-hole.net/guides/github/dco/) for all contributions - [x] I [signed](https://docs.github.com/en/authentication/managing-commit-signature-verification/signing-commits) all my commits. Pi-hole requires signatures to verify authorship - [x] I have read the above and my PR is ready for review.

It'd be awesome, if you could verify this does not happen any longer after running

sudo pihole checkout ftl fix/cache_recycling

(the binaries will be available in +/- 20 minutes from now)

Merry Christmas!

sawsanders · December 24, 2023, 11:04pm

Thanks, I will switch branches and test this out ASAP.

I tried switching branches and it wasn't available (2+ hrs after your post). I looked at GitHub and it appears the build has failed?? I'll check back on it later.

Anyway, thank you and Merry Christmas again!

DL6ER · December 25, 2023, 3:58am

Yeah, sorry for that. I unintentionally broke deep CNAME inspection because I did a simplification to the cache lookup I shouldn't have done. This is now fixed thanks to our merciless extensive automated testing suite. Should already be available now.

gpb · December 25, 2023, 2:57pm

I've had this happening multiple times over the past week or so, always reloading gravity fixed it. I applied the patch and will report back if it recurs.

DL6ER · December 25, 2023, 8:43pm

Please also report back if it does not reoccur

deHakkelaar · December 26, 2023, 2:09pm

The problem with the grep is that whenever I startup a browser, it already queries my troubled www.nu.nl domain (without visiting the site) followed by a bunch of other queries + replies which generates allot of log lines.

When still working ... I think:

2023-12-26 05:18:35.643 [523464M] DEBUG_QUERIES: **** new UDP IPv4 query[A] query "www.nu.nl" from eth0/10.0.0.11#58355 (ID 25936, FTL 3881, src/dnsmasq/forward.c:1773)
2023-12-26 05:18:35.644 [523464M] DEBUG_QUERIES: www.nu.nl is known as not to be blocked
2023-12-26 05:18:35.644 [523464M] DEBUG_QUERIES: **** got stale cache reply: www.nu.nl is (CNAME) (ID 25936, src/dnsmasq/rfc1035.c:1600)
2023-12-26 05:18:35.644 [523464M] DEBUG_QUERIES: Set reply to CNAME (3) in src/dnsmasq_interface.c:2068
2023-12-26 05:18:35.645 [523464M] DEBUG_QUERIES: **** got stale cache reply: edge-www-nu-nl-production.892094674759.eu-west-1.ext.cloud.onenet.nl is (CNAME) (ID 25936, src/dnsmasq/rfc1035.c:1600)
2023-12-26 05:18:35.645 [523464M] DEBUG_QUERIES: **** got cache reply: www.nu.nl.edgekey.net is (CNAME) (ID 25936, src/dnsmasq/rfc1035.c:1600)
2023-12-26 05:18:35.646 [523464M] DEBUG_QUERIES: **** got stale cache reply: e67691.b.akamaiedge.net is 2.19.195.227 (ID 25936, src/dnsmasq/rfc1035.c:1963)
2023-12-26 05:18:35.646 [523464M] DEBUG_QUERIES: FTL_CNAME called with: src = e67691.b.akamaiedge.net, dst = e67691.b.akamaiedge.net, id = 25936
2023-12-26 05:18:35.647 [523464M] DEBUG_QUERIES: e67691.b.akamaiedge.net is known as not to be blocked
2023-12-26 05:18:35.647 [523464M] DEBUG_QUERIES: Query 25936: CNAME e67691.b.akamaiedge.net ---> e67691.b.akamaiedge.net
2023-12-26 05:18:35.647 [523464M] DEBUG_QUERIES: **** got stale cache reply: e67691.b.akamaiedge.net is 104.110.240.42 (ID 25936, src/dnsmasq/rfc1035.c:1963)
2023-12-26 05:18:35.648 [523464M] DEBUG_QUERIES: FTL_CNAME called with: src = e67691.b.akamaiedge.net, dst = e67691.b.akamaiedge.net, id = 25936
2023-12-26 05:18:35.648 [523464M] DEBUG_QUERIES: e67691.b.akamaiedge.net is known as not to be blocked
2023-12-26 05:18:35.648 [523464M] DEBUG_QUERIES: Query 25936: CNAME e67691.b.akamaiedge.net ---> e67691.b.akamaiedge.net
2023-12-26 05:18:35.649 [523464M] DEBUG_QUERIES: **** forwarded www.nu.nl to 127.0.0.1#5335 (ID 25936, src/dnsmasq/forward.c:553)

[non related queries]

2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: **** new UDP IPv4 query[A] query "e67691.b.akamaiedge.net" from eth0/10.0.0.11#50925 (ID 25939, FTL 3884, src/dnsmasq/forward.c:1773)
2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: e67691.b.akamaiedge.net is known as not to be blocked
2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: **** got stale cache reply: e67691.b.akamaiedge.net is 104.110.240.42 (ID 25939, src/dnsmasq/rfc1035.c:1963)
2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: Set reply to IP (4) in src/dnsmasq_interface.c:2068
2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: FTL_CNAME called with: src = e67691.b.akamaiedge.net, dst = e67691.b.akamaiedge.net, id = 25939
2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: e67691.b.akamaiedge.net is known as not to be blocked
2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: Query 25939: CNAME e67691.b.akamaiedge.net ---> e67691.b.akamaiedge.net
2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: **** got stale cache reply: e67691.b.akamaiedge.net is 2.19.195.227 (ID 25939, src/dnsmasq/rfc1035.c:1963)
2023-12-26 05:18:35.663 [523464M] DEBUG_QUERIES: FTL_CNAME called with: src = e67691.b.akamaiedge.net, dst = e67691.b.akamaiedge.net, id = 25939
2023-12-26 05:18:35.663 [523464M] DEBUG_QUERIES: e67691.b.akamaiedge.net is known as not to be blocked
2023-12-26 05:18:35.663 [523464M] DEBUG_QUERIES: Query 25939: CNAME e67691.b.akamaiedge.net ---> e67691.b.akamaiedge.net
2023-12-26 05:18:35.663 [523464M] DEBUG_QUERIES: **** forwarded e67691.b.akamaiedge.net to 127.0.0.1#5335 (ID 25939, src/dnsmasq/forward.c:553)

[non related queries]

2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: **** new UDP IPv4 query[A] query "e67691.b.akamaiedge.net" from eth0/10.0.0.11#50925 (ID 25939, FTL 3884, src/dnsmasq/forward.c:1773)
2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: e67691.b.akamaiedge.net is known as not to be blocked
2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: **** got stale cache reply: e67691.b.akamaiedge.net is 104.110.240.42 (ID 25939, src/dnsmasq/rfc1035.c:1963)
2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: Set reply to IP (4) in src/dnsmasq_interface.c:2068
2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: FTL_CNAME called with: src = e67691.b.akamaiedge.net, dst = e67691.b.akamaiedge.net, id = 25939
2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: e67691.b.akamaiedge.net is known as not to be blocked
2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: Query 25939: CNAME e67691.b.akamaiedge.net ---> e67691.b.akamaiedge.net
2023-12-26 05:18:35.662 [523464M] DEBUG_QUERIES: **** got stale cache reply: e67691.b.akamaiedge.net is 2.19.195.227 (ID 25939, src/dnsmasq/rfc1035.c:1963)
2023-12-26 05:18:35.663 [523464M] DEBUG_QUERIES: FTL_CNAME called with: src = e67691.b.akamaiedge.net, dst = e67691.b.akamaiedge.net, id = 25939
2023-12-26 05:18:35.663 [523464M] DEBUG_QUERIES: e67691.b.akamaiedge.net is known as not to be blocked
2023-12-26 05:18:35.663 [523464M] DEBUG_QUERIES: Query 25939: CNAME e67691.b.akamaiedge.net ---> e67691.b.akamaiedge.net
2023-12-26 05:18:35.663 [523464M] DEBUG_QUERIES: **** forwarded e67691.b.akamaiedge.net to 127.0.0.1#5335 (ID 25939, src/dnsmasq/forward.c:553)

[non related queries]

2023-12-26 05:18:35.671 [523464M] DEBUG_QUERIES: **** new UDP IPv4 query[AAAA] query "e67691.b.akamaiedge.net" from eth0/10.0.0.11#62077 (ID 25942, FTL 3887, src/dnsmasq/forward.c:1773)
2023-12-26 05:18:35.671 [523464M] DEBUG_QUERIES: e67691.b.akamaiedge.net is known as not to be blocked
2023-12-26 05:18:35.671 [523464M] DEBUG_QUERIES: **** got stale cache reply: e67691.b.akamaiedge.net is (NODATA) (ID 25942, src/dnsmasq/rfc1035.c:1951)
2023-12-26 05:18:35.671 [523464M] DEBUG_QUERIES: Set reply to NODATA (1) in src/dnsmasq_interface.c:2068
2023-12-26 05:18:35.671 [523464M] DEBUG_QUERIES: **** forwarded e67691.b.akamaiedge.net to 127.0.0.1#5335 (ID 25942, src/dnsmasq/forward.c:553)

[non related queries]

2023-12-26 05:18:35.676 [523464M] DEBUG_QUERIES: **** got upstream reply from 127.0.0.1#5335: e67691.b.akamaiedge.net is 104.110.240.42 (ID 25939, src/dnsmasq/rfc1035.c:969)
2023-12-26 05:18:35.676 [523464M] DEBUG_QUERIES: **** got upstream reply: e67691.b.akamaiedge.net is 2.19.195.227 (ID 25939, src/dnsmasq/rfc1035.c:969)

[non related queries]

2023-12-26 05:18:35.820 [523464M] DEBUG_QUERIES: **** got upstream reply from 127.0.0.1#5335: www.nu.nl is (CNAME) (ID 25936, src/dnsmasq/rfc1035.c:762)
2023-12-26 05:18:35.821 [523464M] DEBUG_QUERIES: FTL_CNAME called with: src = www.nu.nl, dst = edge-www-nu-nl-production.892094674759.eu-west-1.ext.cloud.onenet.nl, id = 25936
2023-12-26 05:18:35.821 [523464M] DEBUG_QUERIES: edge-www-nu-nl-production.892094674759.eu-west-1.ext.cloud.onenet.nl is known as not to be blocked
2023-12-26 05:18:35.822 [523464M] DEBUG_QUERIES: Query 25936: CNAME www.nu.nl ---> edge-www-nu-nl-production.892094674759.eu-west-1.ext.cloud.onenet.nl
2023-12-26 05:18:35.822 [523464M] DEBUG_QUERIES: **** got upstream reply: edge-www-nu-nl-production.892094674759.eu-west-1.ext.cloud.onenet.nl is (CNAME) (ID 25936, src/dnsmasq/rfc1035.c:762)
2023-12-26 05:18:35.822 [523464M] DEBUG_QUERIES: FTL_CNAME called with: src = edge-www-nu-nl-production.892094674759.eu-west-1.ext.cloud.onenet.nl, dst = www.nu.nl.edgekey.net, id = 25936
2023-12-26 05:18:35.823 [523464M] DEBUG_QUERIES: www.nu.nl.edgekey.net is known as not to be blocked
2023-12-26 05:18:35.823 [523464M] DEBUG_QUERIES: Query 25936: CNAME edge-www-nu-nl-production.892094674759.eu-west-1.ext.cloud.onenet.nl ---> www.nu.nl.edgekey.net
2023-12-26 05:18:35.823 [523464M] DEBUG_QUERIES: **** got upstream reply: www.nu.nl.edgekey.net is (CNAME) (ID 25936, src/dnsmasq/rfc1035.c:762)
2023-12-26 05:18:35.824 [523464M] DEBUG_QUERIES: FTL_CNAME called with: src = www.nu.nl.edgekey.net, dst = e67691.b.akamaiedge.net, id = 25936
2023-12-26 05:18:35.824 [523464M] DEBUG_QUERIES: e67691.b.akamaiedge.net is known as not to be blocked
2023-12-26 05:18:35.824 [523464M] DEBUG_QUERIES: Query 25936: CNAME www.nu.nl.edgekey.net ---> e67691.b.akamaiedge.net
2023-12-26 05:18:35.825 [523464M] DEBUG_QUERIES: **** got upstream reply: e67691.b.akamaiedge.net is 104.110.240.42 (ID 25936, src/dnsmasq/rfc1035.c:969)
2023-12-26 05:18:35.825 [523464M] DEBUG_QUERIES: **** got upstream reply: e67691.b.akamaiedge.net is 2.19.195.227 (ID 25936, src/dnsmasq/rfc1035.c:969)

Followed by below when it gets blocked:

2023-12-26 05:24:10.174 [523464M] DEBUG_QUERIES: **** new UDP IPv4 query[A] query "www.nu.nl" from eth0/10.0.0.11#57410 (ID 26109, FTL 4053, src/dnsmasq/forward.c:1773)
2023-12-26 05:24:10.175 [523464M] DEBUG_QUERIES: www.nu.nl is known as not to be blocked
2023-12-26 05:24:10.175 [523464M] DEBUG_QUERIES: **** got stale cache reply: www.nu.nl is (CNAME) (ID 26109, src/dnsmasq/rfc1035.c:1600)
2023-12-26 05:24:10.175 [523464M] DEBUG_QUERIES: Set reply to CNAME (3) in src/dnsmasq_interface.c:2068
2023-12-26 05:24:10.175 [523464M] DEBUG_QUERIES: **** got stale cache reply: edge-www-nu-nl-production.892094674759.eu-west-1.ext.cloud.onenet.nl is (CNAME) (ID 26109, src/dnsmasq/rfc1035.c:1600)
2023-12-26 05:24:10.175 [523464M] DEBUG_QUERIES: **** got cache reply: www.nu.nl.edgekey.net is (CNAME) (ID 26109, src/dnsmasq/rfc1035.c:1600)
2023-12-26 05:24:10.175 [523464M] DEBUG_QUERIES: **** got stale cache reply: e67691.b.akamaiedge.net is 104.110.240.42 (ID 26109, src/dnsmasq/rfc1035.c:1963)
2023-12-26 05:24:10.175 [523464M] DEBUG_QUERIES: FTL_CNAME called with: src = e67691.b.akamaiedge.net, dst = e67691.b.akamaiedge.net, id = 26109
2023-12-26 05:24:10.176 [523464M] DEBUG_QUERIES: e67691.b.akamaiedge.net is known as not to be blocked
2023-12-26 05:24:10.176 [523464M] DEBUG_QUERIES: Query 26109: CNAME e67691.b.akamaiedge.net ---> e67691.b.akamaiedge.net
2023-12-26 05:24:10.176 [523464M] DEBUG_QUERIES: **** got stale cache reply: e67691.b.akamaiedge.net is 2.19.195.227 (ID 26109, src/dnsmasq/rfc1035.c:1963)
2023-12-26 05:24:10.176 [523464M] DEBUG_QUERIES: FTL_CNAME called with: src = e67691.b.akamaiedge.net, dst = e67691.b.akamaiedge.net, id = 26109
2023-12-26 05:24:10.176 [523464M] DEBUG_QUERIES: e67691.b.akamaiedge.net is known as not to be blocked
2023-12-26 05:24:10.176 [523464M] DEBUG_QUERIES: Query 26109: CNAME e67691.b.akamaiedge.net ---> e67691.b.akamaiedge.net
2023-12-26 05:24:10.176 [523464M] DEBUG_QUERIES: **** forwarded www.nu.nl to 127.0.0.1#5335 (ID 26109, src/dnsmasq/forward.c:553)

[non related queries]

2023-12-26 05:24:10.245 [523464M] DEBUG_QUERIES: **** got upstream reply from 127.0.0.1#5335: www.nu.nl is (CNAME) (ID 26109, src/dnsmasq/rfc1035.c:762)
2023-12-26 05:24:10.245 [523464M] DEBUG_QUERIES: FTL_CNAME called with: src = www.nu.nl, dst = edge-www-nu-nl-production.892094674759.eu-west-1.ext.cloud.onenet.nl, id = 26109
2023-12-26 05:24:10.245 [523464M] DEBUG_QUERIES: edge-www-nu-nl-production.892094674759.eu-west-1.ext.cloud.onenet.nl is known as not to be blocked
2023-12-26 05:24:10.245 [523464M] DEBUG_QUERIES: Query 26109: CNAME www.nu.nl ---> edge-www-nu-nl-production.892094674759.eu-west-1.ext.cloud.onenet.nl
2023-12-26 05:24:10.245 [523464M] DEBUG_QUERIES: **** got upstream reply: edge-www-nu-nl-production.892094674759.eu-west-1.ext.cloud.onenet.nl is (CNAME) (ID 26109, src/dnsmasq/rfc1035.c:762)
2023-12-26 05:24:10.246 [523464M] DEBUG_QUERIES: FTL_CNAME called with: src = edge-www-nu-nl-production.892094674759.eu-west-1.ext.cloud.onenet.nl, dst = www.nu.nl.edgekey.net, id = 26109
2023-12-26 05:24:10.246 [523464M] DEBUG_QUERIES: www.nu.nl.edgekey.net is known as gravity blocked
2023-12-26 05:24:10.246 [523464M] DEBUG_QUERIES: Set reply to CNAME (3) in src/dnsmasq_interface.c:1578
2023-12-26 05:24:10.246 [523464M] DEBUG_QUERIES: Query 26109: CNAME edge-www-nu-nl-production.892094674759.eu-west-1.ext.cloud.onenet.nl ---> www.nu.nl.edgekey.net
2023-12-26 05:24:10.246 [523464M] DEBUG_QUERIES: **** got upstream reply: www.nu.nl.edgekey.net is blocked during CNAME inspection (ID 26109, src/dnsmasq/rfc1035.c:794)
2023-12-26 05:24:10.246 [523464M] DEBUG_QUERIES: Preparing reply for "www.nu.nl", EDE: N/A
2023-12-26 05:24:10.246 [523464M] DEBUG_QUERIES:   Adding RR: "www.nu.nl A 0.0.0.0"
2023-12-26 05:24:10.246 [523464M] DEBUG_QUERIES: **** got cache reply: www.nu.nl is 0.0.0.0 (ID 26109, src/dnsmasq_interface.c:406)
2023-12-26 05:24:10.380 [523464M] DEBUG_QUERIES: **** got upstream reply from 127.0.0.1#5335: e67691.b.akamaiedge.net is 104.110.240.42 (ID 26112, src/dnsmasq/rfc1035.c:969)
2023-12-26 05:24:10.380 [523464M] DEBUG_QUERIES: **** got upstream reply: e67691.b.akamaiedge.net is 2.19.195.227 (ID 26112, src/dnsmasq/rfc1035.c:969)

I wont restart pihole-FLT or update yet.
~~Or at least not until tonight when I get back from a trip.~~
If have any questions or instructions?

dehakkelaar@ph6b:~$ pihole -v
Core
    Version is v5.17.1-255-g6e8029f6 (Latest: v5.17.2)
    Branch is development-v6
    Hash is 6e8029f6 (Latest: 6e8029f6)
Web
    Version is v5.19-605-g8495f2fc (Latest: v5.21)
    Branch is development-v6
    Hash is 8495f2fc (Latest: c5c2c5b7)
FTL
    Version is vDev-7b59c65 (Latest: v5.23)
    Branch is development-v6
    Hash is 7b59c651 (Latest: 07c403a3)

sawsanders · December 27, 2023, 4:54am

Almost two days on this branch and I haven't noticed anything odd yet. I am continuing to keep an eye on things.

DL6ER · December 27, 2023, 9:55am

Yeah, so when this domain is on neither of your blocking lists, you are very likely affected by the same issue as @sawsanders - both restarting pihole-FTL or running the bugfix branch in this discussion should resolve it (the restart for at least 24 hours, the bugfix branch permanently)

deHakkelaar · December 27, 2023, 3:54pm

Indeed none of the involved domains in the logs are on the blocking lists when querying with pihole -q.

dehakkelaar@ph6b:~$ sudo pihole checkout ftl fix/cache_recycling
  Please note that changing branches severely alters your Pi-hole subsystems
  Features that work on the master branch, may not on a development branch
  This feature is NOT supported unless a Pi-hole developer explicitly asks!
  Have you read and understood this? [y/N] y

  [â] Branch fix/cache_recycling exists
  [i] Switching to branch: "fix/cache_recycling" from "development-v6"
  [â] Downloading and Installing FTL
  [â] Restarting pihole-FTL service...
  [â] Enabling pihole-FTL service to start on reboot...