Huge /var/log/pihole.log

A few days ago I noticed that my pihole.logs are huge. We are two adults and a 12yo with a limited usage of 1 hour / day on his mobile.

The log was about 10MB / day.

The first thing I noted was that we got a huge number of requests from our fire tv stick.
I used to have like 2.500 requests but suddenly this rose to 10.000 requests / day. The same requests over and over again while we are all asleep and the stick should be idling.
About every two minutes especially to firetvcaptiveportal.com and cnd.optimizely.com. The thing is that a single one of those requests easily spans 20 lines, e.g.

Dec 18 00:11:06 dnsmasq[587]: query[AAAA] firetvcaptiveportal.com from 192.168.178.30
Dec 18 00:11:06 dnsmasq[587]: forwarded firetvcaptiveportal.com to 2001:1608:xx:xx::xxxx:xxxx
Dec 18 00:11:06 dnsmasq[587]: forwarded firetvcaptiveportal.com to 84.200.70.40
Dec 18 00:11:06 dnsmasq[587]: forwarded firetvcaptiveportal.com to 2620:119:35::35
Dec 18 00:11:06 dnsmasq[587]: forwarded firetvcaptiveportal.com to 208.67.222.222
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 2600:1f18:1805:8601:713b:508e:a786:40c9
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 2600:1f18:1805:8601:5848:6783:9bd8:44fa
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 2600:1f18:1805:8601:c6d0:b5b9:75f4:46f6
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 2600:1f18:1805:8604:d526:6df6:c2eb:6fe7
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 2600:1f18:1805:8607:6b66:a51c:1259:d4bf
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 2600:1f18:1805:8604:d45f:8661:c361:4e7a
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 2600:1f18:1805:8601:8248:14c:b359:beb3
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 2600:1f18:1805:8604:5ec7:f25a:d2b:8995
Dec 18 00:11:06 dnsmasq[587]: query[A] firetvcaptiveportal.com from 192.168.178.30
Dec 18 00:11:06 dnsmasq[587]: forwarded firetvcaptiveportal.com to 2001:1608:xx:xx::xxxx:xxxx
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 52.86.185.40
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 52.1.167.159
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 174.129.230.26
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 34.192.235.166
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 52.1.182.127
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 52.4.27.132
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 23.20.191.165
Dec 18 00:11:06 dnsmasq[587]: reply firetvcaptiveportal.com is 34.238.204.58

Now imagine 10.000 requests of that kind and you get the picture. Any ideas about the rise of numbers? What numbers should I expect for a fire tv stick?

Anyway I bypassed pihole for the fire tv stick and expected a much smaller log from now on.

To my surprise there are other spammers. Yesterday evening my missus watched the voice of Germany on her android tablet and between 20:22 and 23:58 I have 1849 of those lookups.
3 Times a second then about 20 secs break and then again and again...

Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com from 192.168.178.33
Dec 20 22:27:01 dnsmasq[587]: forwarded e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com to 2001:1608:xx:xx::xxxx:xxxx
Dec 20 22:27:01 dnsmasq[587]: reply e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com is <CNAME>
Dec 20 22:27:01 dnsmasq[587]: reply cws.conviva.com is blocked during CNAME inspection
Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com from fd00::xxxx:xxxx:xxxx:xxxx
Dec 20 22:27:01 dnsmasq[587]: forwarded e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com to 2001:1608:xx:xx::xxxx:xxxx
Dec 20 22:27:01 dnsmasq[587]: reply e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com is <CNAME>
Dec 20 22:27:01 dnsmasq[587]: reply cws.conviva.com is blocked during CNAME inspection
Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com from 192.168.178.33
Dec 20 22:27:01 dnsmasq[587]: forwarded e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com to 2001:1608:xx:xx::xxxx:xxxx
Dec 20 22:27:01 dnsmasq[587]: reply e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com is <CNAME>
Dec 20 22:27:01 dnsmasq[587]: reply cws.conviva.com is blocked during CNAME inspection
Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com from fd00::xxxx:xxxx:xxxx:xxxx
Dec 20 22:27:01 dnsmasq[587]: forwarded e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com to 2001:1608:xx:xx::xxxx:xxxx
Dec 20 22:27:01 dnsmasq[587]: reply e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com is <CNAME>
Dec 20 22:27:01 dnsmasq[587]: reply cws.conviva.com is blocked during CNAME inspection
Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com from 192.168.178.33
Dec 20 22:27:01 dnsmasq[587]: forwarded e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com to 2001:1608:xx:xx::xxxx:xxxx
Dec 20 22:27:01 dnsmasq[587]: reply e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com is <CNAME>
Dec 20 22:27:01 dnsmasq[587]: reply cws.conviva.com is blocked during CNAME inspection
Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box from fd00::xxxx:xxxx:xxxx:xxxx
Dec 20 22:27:01 dnsmasq[587]: forwarded e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box to 192.168.178.1
Dec 20 22:27:01 dnsmasq[587]: reply e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box is NXDOMAIN
Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box from 192.168.178.33
Dec 20 22:27:01 dnsmasq[587]: cached e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box is NXDOMAIN
Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box from fd00::xxxx:xxxx:xxxx:xxxx
Dec 20 22:27:01 dnsmasq[587]: cached e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box is NXDOMAIN
Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box from 192.168.178.33
Dec 20 22:27:01 dnsmasq[587]: cached e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box is NXDOMAIN

My questions:

  • Does anyone have reliable info about the DNS TTL on android devices? Why does the android tablet not keep the dns entries in its dns cache?
  • Why do I see 3 requests within one second? Each time from the IPv4, the IPv6 and the link local address, so overall 9 requests / sec?
  • Can dnsmasq be adjusted so that it does not log the cached queries and results? How?
  • At the moment I have pihole as the local DNS-Server. If I set it as the upstream DNS server on the internet connection and use the internal Fritzbox DNS-Server as my local DNS-Server:
    All that excessive logging should be gone, right? As the Fritzbox-DNS-Server would answer out of its cache and would not have to talk to the pihole dnsmasq. Correct?
  • What will I loose if I disable logging to my /var/log/pihole.log and will there anything be missing in my pihole-FTL.db? How to disable logging to only the /var/log/pihole.log and not to pihole-FTL.db?

Thx in advance

A few thoughts:

(1) a 10MB log file is not huge. That's fairly typical. The log rotates daily and older logs (retained for 6 days total) are compressed. Here is the directory of my current logs for a Pi-hole serving 6 clients with 16K queries in the past 24 hours:

ls -lha /var/log/pihole.log*

-rw-r--r-- 1 pihole pihole 1.5M Dec 21 08:11 /var/log/pihole.log
-rw-r--r-- 1 pihole pihole 4.8M Dec 21 00:00 /var/log/pihole.log.1
-rw-r--r-- 1 pihole pihole 275K Dec 20 00:00 /var/log/pihole.log.2.gz
-rw-r--r-- 1 pihole pihole 281K Dec 19 00:00 /var/log/pihole.log.3.gz
-rw-r--r-- 1 pihole pihole 248K Dec 18 00:00 /var/log/pihole.log.4.gz
-rw-r--r-- 1 pihole pihole 264K Dec 17 00:00 /var/log/pihole.log.5.gz

(2) In your particular case, a single query results in quite a few line entries in the log for several reasons. There are both A and AAAA queries, and you have several upstream DNS servers in use, so the forward to each of them is shown.

I don't have specifics on Android clients, but TTLs are typically quite short. In your examples,

firetvcaptiveportal.com TTL is 50 seconds

cws.conviva.com is 247 seconds, but the CNAMEs below it are 45 and 24 seconds respectively. Fairly short.

The client is making the request and it is shown as coming from each of the IP's for that client.

There is a setting in Pi-hole to disable logging, which will turn off this particular dnsmasq log file. But, given the relatively small size and temporary nature of this log, I would leave it enabled. As you have seen, it provides some pretty good insight into client DNS activity.

Disable query logging on Web GUI > Settings:

The dnsmasq log is completely separate and independent from your long term database. If you disable the dnsmasq log, the primary impact is that you won't have a log to live tail, and some details of the queries will be lost (they aren't stored in the long term database). Your dashboard will be unchanged, as that is populated from the long term database.

Thank you for your thoughts.

I have a limited understanding of DNS and my assumptions and the reality don't quite seem to match.
Maybe you can help me understand.

My assumptions:

  1. Every DNS-record has a TTL. The DNS-server in charge (authoritative server?) determines the TTL. Lets assume it sets the TTL of the entry foo.bar to 3600 secs.
  2. I am not directly queriyng the DNS-server in charge but some other DNS-server, e.g. 1.1.1.1. Now there is a chance that 1.1.1.1 itself has just queried foo.bar and can offer me a long remaining TTL of say 3500 secs. However it is also possible that 1.1.1.1 needs to refresh the entry of foo.bar itself and can only offer me a remaining TTL of say 100 seconds.
  3. The queried entry will go into my client's dns cache and the client should not make any more queries for foo.bar until the TTL expires.

The reality:

Let's look at the below part from my logs.
I have 3 exact same IP4 queries:
query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com from [Android_Tablet_IP4] in lines 1, 11 and 21
and two slightly modified ones with .fritz.box
query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box from [Android_Tablet_IP4] in lines 30 and 36

Similar thing for IP6: 2 exact same queries:
query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com from [Android_Tablet_IP6_ULA] in lines 6 and 16
and two slightly modified ones with .fritz.box
query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box from [Android_Tablet_IP6_ULA] in lines 26 and 33.

All within 1 second!

 1 Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com from [Android_Tablet_IP4]
 2 Dec 20 22:27:01 dnsmasq[587]: forwarded e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com to [IP6_of_DNSWATCH]
 3 Dec 20 22:27:01 dnsmasq[587]: reply e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com is <CNAME>
 4 Dec 20 22:27:01 dnsmasq[587]: reply cws.conviva.com is blocked during CNAME inspection
 5 
 6 Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com from [Android_Tablet_IP6_ULA]
 7 Dec 20 22:27:01 dnsmasq[587]: forwarded e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com to [IP6_of_DNSWATCH]
 8 Dec 20 22:27:01 dnsmasq[587]: reply e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com is <CNAME>
 9 Dec 20 22:27:01 dnsmasq[587]: reply cws.conviva.com is blocked during CNAME inspection
10 
11 Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com from [Android_Tablet_IP4]
12 Dec 20 22:27:01 dnsmasq[587]: forwarded e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com to [IP6_of_DNSWATCH]
13 Dec 20 22:27:01 dnsmasq[587]: reply e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com is <CNAME>
14 Dec 20 22:27:01 dnsmasq[587]: reply cws.conviva.com is blocked during CNAME inspection
15 
16 Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com from [Android_Tablet_IP6_ULA]
17 Dec 20 22:27:01 dnsmasq[587]: forwarded e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com to [IP6_of_DNSWATCH]
18 Dec 20 22:27:01 dnsmasq[587]: reply e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com is <CNAME>
19 Dec 20 22:27:01 dnsmasq[587]: reply cws.conviva.com is blocked during CNAME inspection
20 
21 Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com from [Android_Tablet_IP4]
22 Dec 20 22:27:01 dnsmasq[587]: forwarded e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com to [IP6_of_DNSWATCH]
23 Dec 20 22:27:01 dnsmasq[587]: reply e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com is <CNAME>
24 Dec 20 22:27:01 dnsmasq[587]: reply cws.conviva.com is blocked during CNAME inspection
25 
26 Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box from [Android_Tablet_IP6_ULA]
27 Dec 20 22:27:01 dnsmasq[587]: forwarded e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box to 192.168.178.1
28 Dec 20 22:27:01 dnsmasq[587]: reply e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box is NXDOMAIN
29 
30 Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box from [Android_Tablet_IP4]
31 Dec 20 22:27:01 dnsmasq[587]: cached e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box is NXDOMAIN
32 
33 Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box from [Android_Tablet_IP6_ULA]
34 Dec 20 22:27:01 dnsmasq[587]: cached e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box is NXDOMAIN
35 
36 Dec 20 22:27:01 dnsmasq[587]: query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box from [Android_Tablet_IP4]
37 Dec 20 22:27:01 dnsmasq[587]: cached e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box is NXDOMAIN

Now when I run
dig e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com @84.200.70.40

I get

(...)
;; ANSWER SECTION:
e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com. 300 IN CNAME cws.conviva.com.
cws.conviva.com.        209     IN      CNAME   cws-eu.conviva.com.
cws-eu.conviva.com.     141     IN      CNAME   cws-iad1.conviva.com.
cws-iad1.conviva.com.   141     IN      A       199.127.194.93
(...)

My interpretation of the result is that e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com is the IP 199.127.194.93 and the entry has a remaining TTL of 141 seconds.

So I would expect at least 140 seconds of peace and quiet in my logfile but instead the whole shebang starts over 20 seconds later. Leading to a total of:

1849 times query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com from [Android_Tablet_IP4]
1144 times query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box from [Android_Tablet_IP4]
1190 times query[A] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com from [Android_Tablet_IP6_ULA]
 978 times query[AAAA] e1cd4958785f7e0dcfaee56d57a7db4096b34051.cws.conviva.com.fritz.box from [Android_Tablet_IP6_ULA]

...within ~ 3 hours!

My resolv.conf looks something like this:

# Generated by resolvconf
nameserver 84.200.70.40 <- DNS Watch
nameserver 208.67.222.222
nameserver fd00::216e:xxxx:xxxx:xxxx <- ULA of my pi

I don't quite understand what is going wrong and why those massive amounts of dns-queries occur at all.

Thanks again.

I don't think caching and TTLs are involved here:
Pi-hole is blocking that domain.

Your client device is just desparate to access that specific domain:
As it doesn't get an IP for an answer, it'll keep misbehaving and will request DNS resolution over and over, regardless of TTL.

You may deal with this as you already have in one instance, exempting that client from all filtering.
Or you could whitelist the domain in question, or combine that into a group that has that domain whitelisted, instead of doing no filtering at all, or just ban that device from your network.

Banning my missus' tablet from the network - yeah - that'll do me good :joy:

Can you explain the difference between

is blocked during CNAME inspection

and

gravity blocked xxx is 0.0.0.0

I am itching to up the local-ttl to ~900 but my understanding is that this would only apply for the 0.0.0.0 responses. I don't understand the "is blocked during CNAME inspection" responses yet.

Thx.

Let me repeat:
Since I suspect your client to react on the answer being blocked, I doubt that fiddling with TTLs will stop your client from repeating its requests. Your current observation with several requests per second would already suggest its not caring about TTL at all.
Addressing that client's behaviour by the means I've already listed above would seem preferable.

Also, note that increasing the local TTL would in turn mean that any changes to domain related filtering (e.g. whitelisting, blacklisting) may take that long before they kick-in, and those changes may be overwritten by Pi-hole upon UI interactions and on upgrades.

The requested domain itself is blocked immediately.

The requested domain itself was allowed, but pointed to a CNAME, and that CNAME is blocked.

In both cases, Pi-hole will block the answer, i.e. by replying 0.0.0.0 in a standard configuration.
It could be that changing that behaviour by selecting a different blocking mode resulting in a different answer (e.g. NXDOMAIN or NODATA) would be more appealing for your client, but that also could trigger that repetitive request behaviour for other clients and domains.

I did a couple of experiments in the last days. I kept some of the changes and undid some of them again. In case someone stumbles across this question in the future I'd like to share my findings. I started with about 10 MB of /var/log/pihole.log a day.

  1. The first thing I did was to install Log2RAM. With Log2RAM I don't care any more whether I have 15 MB or 5 MB of logdata per day and I have no more worries about wearing out my SD-card.
  2. The second thing was to bypass pihole for my Fire-TV-Stick. This took off about 1 MB from my logdata. In the end I added FireTV-Stick again to Pihole because without Pihole I had to endure ad-clips in the streaming-app "JOYN". No go.
  3. I upped the TTL from 2 seconds to 900 seconds. I know the admins here don't like to hear this, but I know what I did. I never fumbled with any whitelists or blacklists and I might even up it some more to 2700 or more. This took off about 1.5 MB of logdata. However I also noticed that some apps / clients don't seem to respect the TTL and still queried more often that the assumed 15 minutes.
  4. I made pihole my upstream DNS-Server instead of the local DNS-Server. In total this reduced my logsize the most so that I ended up with a total of about 5 MB / day. Any cached queries will no longer be visible in my logs as they are directly answered by my Fritzbox. However: I also ended up undoing this modification because I no longer can identify the causing endhosts. There is only one endhost left in the logs and that is fritzbox itself. That greatly reduces the fun of pihole for me so I changed it back.

In sum I learned:

  • If writeload on the SD card because of big logfiles is an issue for you: Use Log2RAM
  • If you know what you do: Up the TTL to 900 or 2700 or even more.
  • Not all clients seem to respect the TTL however
  • Sometimes you have rogue apps or websites that can add thousands of lines to your logs. I guess you have to live with that

As I noted in my previous reply, your log files are not abnormally large at 10 MB. That is a trivial amount of space on a card, and the logs are retained for only five days (and the first four days are compressed).

This amount of writing to the SD card is not going to wear out the card.

Increasing your local TTL (I assume this is what you changed) to 900 seconds or 2700 seconds for the purpose of saving a few MB on an already small log is not an approach I would recommend to any readers of this thread.

2 Likes

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