Over 40 million entries in log file in under 6 hours

HeeeroYuy · January 18, 2023, 6:54am

Soo. Strange behaviour here.
My Pi-Hole is running on Proxmox (mini PC with intel CPU). Normal queries during 24 hours likely 25.000.
There was a log delete yesterday so there were only the approx. 25.000 entries.
This morning my Proxmox server warned me, that the disk is full and Pi-Hole said over 2GB in log files.
Pi-Hole couldn't load the web GUI properly but i saw 40 million queries.
WTF?! Thats 55k per minute for approx. 6 hours, twice as much as a whole day

I couldn't see any entries because nothing was working until i deleted the log file.

Question: What can lead to this amount in such a short time?
Running:
Pi-hole [v5.15]
FTL [v5.20.1]
Web Interface [v5.18.1]

PromoFaux · January 18, 2023, 7:00am

Debug token to help us diagnose please (pihole -d)

Though from the sounds of things you have port 53 open to the outside world. If so, close it immediately - it is dangerous to run an open resolver

HeeeroYuy · January 18, 2023, 7:11am

pihole_debug.zip (9.8 KB)
Here you go. And no, 53 is not accesible. Only 80,443,5613 and passive FTP ports. And all these are forwarded to my NAS and not the Proxmox-Server (Pi-Hole especially)

But please correct me if I'm wrong.

PromoFaux · January 18, 2023, 9:29am

OK, glad it is not public - but had to make sure first!

I see you have conditional forwarding set up.

What is the DNS server of your router? Is it set to use the Pi-hole device? If that is the case, then you have a bit of a feedback loop in play...

Try disabling conditional forwarding to see if that stops it - and then we can go from there.

I also see that you have disabled FTL's rate limiting (which would have at least caught this earlier)

HeeeroYuy · January 18, 2023, 10:47am

Hm... my router is 192.168.1.1 and its DNS is both (1st and 2nd) 192.168.1.29 (Pi-Hole)
So my clients are routed to my router and from there to Pi-Hole.
The router is my DHCP server with several static IPs and the rest dynamic.

I've activated conditional forwarding due to this statement:
"If not configured as your DHCP server, Pi-hole typically won't be able to determine the names of devices on your local network. As a result, tables such as Top Clients will only show IP addresses."

But I'm not seeing an overall loop, every querie shows up exactly once or - if more often - with a more elapsed time (15 seconds). For a loop, the time stamps would be more like the same seconds but different ms, or am I wrong?
FYI: all the dns.msftncsi.com are single requests from the ASUS router. I will deactivate this later. It's not a loop.

Right now after 5 hours of operation, Pi-Hole has recorded 13.602 queries. After 24 hours it should be somewhere around 65.000. But not 40 Million over night.

sorry for the german UI:

Question: Can i activate and auto flush for the log file? Let's say after x thousand entries, flush it?

Bucking_Horn · January 18, 2023, 1:11pm

No, your clients are talking to directly to PI-hole for DNS, as your router's DHCP server is telling them to:

*** [ DIAGNOSING ]:e[0m Discovering active DHCP servers (takes 10 seconds)
   Scanning all your interfaces for DHCP servers
   
   * Received 315 bytes from eth0:192.168.1.1
     Offered IP address: 192.168.1.29
     DHCP options:
      Message type: DHCPOFFER (2)
      dns-server: 192.168.1.29
      dns-server: 192.168.1.29
      router: 192.168.1.1
      --- end of options ---

PromoFaux asked about the DNS server that your router itself is using as upstream DNS. Commonly, that is a WAN/Internet setting in your router.

Conditional Forwarding may cause a partial loop if your router would be using Pi-hole as its upstream.
If that would be the case, you should be able to trigger it by requesting resolution of a non-existent local hostname, e.g. nslookup bogus-hostname. If that request would be looping, it would become rate-limited by Pi-hole (if you'd reverted your Pi-hole's rate-limit setting), and it should show up in Pi-hole's diagnosis pane as well.

HeeeroYuy · January 18, 2023, 1:21pm

Let me try the nslookup when I'm back home.
The router is using Pi-Hole as DNS but the upstream (Gateway) comes from my ISP.
Let's say my current WAN IP is 1.2.3.100, then the gateway is 1.2.3.254. That's something I can't edit.

Bucking_Horn · January 18, 2023, 1:41pm

That could well be the case, but you may want verify that via your router.

The screenshot you've shared above quite likely shows your router's DHCP server DNS configuration, as the information (double .129) nicely aligns with your DHCP server's response I've quoted above from your debug log.

I'd expect the DNS servers that your router itself would be using to be shown on a different screen, commonly a WAN/Internet setting.

jfb · January 18, 2023, 1:59pm

Another thing that would help us is the output of the following commands from the terminal that underlies Pi-hole:

echo ">stats >quit" | nc localhost 4711

echo ">top-clients >quit" | nc localhost 4711

echo ">top-domains >quit" | nc localhost 4711

echo ">top-ads >quit" | nc localhost 4711

HeeeroYuy · January 18, 2023, 2:18pm

I can only see the ISP's gateway in LAN/WAN settings and the DHCP DNS.
LAN gateway is my router: 192.168.1.1 (changeable)
DNS is 192.168.1.29 (Pi-Hole, changeable)
Upstream Link is 31.xx.xx.254 (gateway from ISP and not changeable by me)
WAN IP is 31.xx.xx.146 (provided by ISP, non static and not changeable)

Right now im a little bit confused. The requests go to Pi-Hole and Pi-Hole itself uses Cloudflare.
Even the router is using Pi-Hole (seen in the log files) and therefore everything goes via Cloudflare.

HeeeroYuy · January 18, 2023, 2:26pm

echo ">stats >quit" | nc localhost 4711
domains_being_blocked 5774775
dns_queries_today 21469
ads_blocked_today 5795
ads_percentage_today 26.992407
unique_domains 2683
queries_forwarded 9490
queries_cached 6021
clients_ever_seen 13
unique_clients 13
dns_queries_all_types 21469
reply_UNKNOWN 3227
reply_NODATA 447
reply_NXDOMAIN 3234
reply_CNAME 3702
reply_IP 10301
reply_DOMAIN 425
reply_RRNAME 2
reply_SERVFAIL 10
reply_REFUSED 0
reply_NOTIMP 117
reply_OTHER 0
reply_DNSSEC 0
reply_NONE 0
reply_BLOB 4
dns_queries_all_replies 21469
privacy_level 0
status enabled

echo ">top-clients >quit" | nc localhost 4711
0 6847 192.168.1.3 HELHEIM.RT-AC87u
1 4844 192.168.1.42 SP_J2.RT-AC87u
2 4028 192.168.1.1 router.asus.com
3 2969 192.168.1.41 SP_J1.RT-AC87u
4 1068 192.168.1.11 IS_TS-853a1.RT-AC87u
5 669 192.168.1.55 Tb_F.RT-AC87u
6 576 192.168.1.111 MM_LG.RT-AC87u
7 271 192.168.1.112 MM_SC.RT-AC87u
8 118 192.168.1.101 IoT_RV.RT-AC87u
9 116 127.0.0.1 localhost

echo ">top-domains >quit" | nc localhost 4711
0 2041 dns.msftncsi.com
1 644 edge.api.myqnapcloud.com
2 599 www.google.com
3 394 ns1.asuscomm.com
4 339 aae-sgweb001-1.asuscomm.com
5 284 update.qnap.com
6 252 rgom10-en.url.trendmicro.com
7 235 nanotekdynamic.asuscomm.com
8 177 profile.accounts.firefox.com
9 173 _ldap._tcp.dc._msdcs.group.jenoptik.corp

echo ">top-ads >quit" | nc localhost 4711
0 1433 wd.adcolony.com
1 1368 adc3-launch.adcolony.com
2 589 events3alt.adcolony.com
3 583 mob.adzmobi.com
4 515 graph.instagram.com
5 91 region1.app-measurement.com
6 88 dit.whatsapp.net
7 82 edge-mqtt.facebook.com
8 64 device-messaging-na.amazon.com
9 60 infoevent.startappservice.com

jfb · January 18, 2023, 3:53pm

These show apparently normal traffic volume - nothing close to 40 million entries. This information is taken from the query database at /etc/pihole/pihole-FTL.db.

What log file did you delete? The query database? The dnsmasq log at /var/log/pihole/pihole.log?

HeeeroYuy · January 18, 2023, 4:48pm

C:\Windows\system32>nslookup 192.168.1.222
Server:  pi.hole
Address:  192.168.1.29

*** 192.168.1.222 wurde von pi.hole nicht gefunden: Non-existent domain.

C:\Windows\system32>nslookup https://www.gagle.de/
Server:  pi.hole
Address:  192.168.1.29

*** https://www.gagle.de/ wurde von pi.hole nicht gefunden: Non-existent domain.

C:\Windows\system32>

and

C:\Windows\system32>tracert -d www.firebog.net

Routenverfolgung zu www.firebog.net [104.21.76.113]
über maximal 30 Hops:

  1     2 ms     2 ms     2 ms  192.168.1.1
  2    20 ms    47 ms    17 ms  31.16.10.252
  3    19 ms    17 ms    18 ms  83.169.174.130
  4    19 ms    18 ms    17 ms  145.254.3.128
  5    26 ms    27 ms    26 ms  145.254.2.195
  6     *       27 ms     *     80.81.194.180
  7    30 ms    29 ms    26 ms  162.158.84.53
  8    29 ms    27 ms    27 ms  104.21.76.113

Ablaufverfolgung beendet.

whereas 31.16.10.254 is my gateway. So Hop 1 is my router, Pi-Hole shows the request

and Hop 2 is my ISP.

Everything seems right, no loops.

I have NO idea, why there has been 40M entries.

HeeeroYuy · January 18, 2023, 4:50pm

The pihole-FTL.db was over 2GB. And my VM was full so nothing worked anymore.
I will observe this topic. Maybe there was a problem with Proxmox or my ISP had some issues.

jfb · January 18, 2023, 4:58pm

Your dnsmasq log at /var/log/pihole/pihole.log will have all the queries, forwards and replies.

This will likely show if you had a DNS loop or other condition that caused the high query volume.

sudo grep query /var/log/pihole/pihole.log

Or, if you just want a quick count of queries:

sudo grep query /var/log/pihole/pihole.log | wc -l

Bucking_Horn · January 18, 2023, 5:34pm

Does that mean that your router is using yor Pi-hole as upstream DNS server?
Your following statement would suggest that:

When Conditional Forwarding is enabled, this would close aforementioned partial DNS loop.

None of your commands matches the one that I've suggested.
To trigger the loop, the query has to take its path to your router (via CF), and your router has to lack information about the requested domain, so that it would forward that query to its upstream (i.e. back to your Pi-hole, if your router is using Pi-hole as upstream).

A query for an unknown plain hostname, or an unknown qualified hostname matching your CF's local domain name may trigger it.

According to your debug log, that would suggest something like:

nslookup unknown.nanotekdynamic

Please share the respective log lines from /var/log/pihole/pihole.log, or from monitoring Tools|Tail pihole.log during that nslookup.

HeeeroYuy · January 18, 2023, 7:21pm

aaand here it is:

Jan 18 18:31:49 dnsmasq[267]: query[PTR] lb._dns-sd._udp.104.89.70.100.in-addr.arpa from 192.168.1.95
Jan 18 18:31:49 dnsmasq[267]: forwarded lb._dns-sd._udp.104.89.70.100.in-addr.arpa to 1.1.1.1
Jan 18 18:31:49 dnsmasq[267]: query[PTR] lb._dns-sd._udp.0.1.168.192.in-addr.arpa from 192.168.1.95
Jan 18 18:31:49 dnsmasq[267]: forwarded lb._dns-sd._udp.0.1.168.192.in-addr.arpa to 192.168.1.1
Jan 18 18:31:49 dnsmasq[267]: query[PTR] lb._dns-sd._udp.RT-AC87u from 192.168.1.95
Jan 18 18:31:49 dnsmasq[267]: forwarded lb._dns-sd._udp.RT-AC87u to 1.1.1.1
Jan 18 18:31:49 dnsmasq[267]: reply lb._dns-sd._udp.104.89.70.100.in-addr.arpa is NXDOMAIN
Jan 18 18:31:49 dnsmasq[267]: reply lb._dns-sd._udp.RT-AC87u is NXDOMAIN
[...]
Jan 18 19:09:15 dnsmasq[267]: forwarded lb._dns-sd._udp.0.1.168.192.in-addr.arpa to 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: query[PTR] lb._dns-sd._udp.0.1.168.192.in-addr.arpa from 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: forwarded lb._dns-sd._udp.0.1.168.192.in-addr.arpa to 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: query[PTR] lb._dns-sd._udp.0.1.168.192.in-addr.arpa from 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: forwarded lb._dns-sd._udp.0.1.168.192.in-addr.arpa to 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: query[PTR] lb._dns-sd._udp.0.1.168.192.in-addr.arpa from 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: forwarded lb._dns-sd._udp.0.1.168.192.in-addr.arpa to 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: query[PTR] lb._dns-sd._udp.0.1.168.192.in-addr.arpa from 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: forwarded lb._dns-sd._udp.0.1.168.192.in-addr.arpa to 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: query[PTR] lb._dns-sd._udp.0.1.168.192.in-addr.arpa from 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: forwarded lb._dns-sd._udp.0.1.168.192.in-addr.arpa to 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: query[PTR] lb._dns-sd._udp.0.1.168.192.in-addr.arpa from 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: forwarded lb._dns-sd._udp.0.1.168.192.in-addr.arpa to 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: query[PTR] lb._dns-sd._udp.0.1.168.192.in-addr.arpa from 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: forwarded lb._dns-sd._udp.0.1.168.192.in-addr.arpa to 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: query[PTR] lb._dns-sd._udp.0.1.168.192.in-addr.arpa from 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: forwarded lb._dns-sd._udp.0.1.168.192.in-addr.arpa to 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: query[PTR] lb._dns-sd._udp.0.1.168.192.in-addr.arpa from 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: forwarded lb._dns-sd._udp.0.1.168.192.in-addr.arpa to 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: query[PTR] lb._dns-sd._udp.0.1.168.192.in-addr.arpa from 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: forwarded lb._dns-sd._udp.0.1.168.192.in-addr.arpa to 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: query[PTR] lb._dns-sd._udp.0.1.168.192.in-addr.arpa from 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: forwarded lb._dns-sd._udp.0.1.168.192.in-addr.arpa to 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: query[PTR] lb._dns-sd._udp.0.1.168.192.in-addr.arpa from 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: forwarded lb._dns-sd._udp.0.1.168.192.in-addr.arpa to 192.168.1.1
Jan 18 19:09:15 dnsmasq[267]: exiting on receipt of SIGTERM

My file is over 2GB again and Pi-Hole says:
There was a problem applying your settings.
Debugging information:
PHP error (2): fsockopen(): Unable to connect to 127.0.0.1:4711 (Connection refused) in /var/www/html/admin/scripts/pi-hole/php/FTL.php:47

and the GUI:

But its interesting. That was a random hit. I haven't done anything. I was eating and returned to my PC.

And now I'm unable to restart the DNS service... lol. new error

HeeeroYuy · January 18, 2023, 7:36pm

Found this solution. I'm not familiar with Pi-Hole. What I'm changing here right now?

I change line 47 of FTP.php from 1.0 to 30. So far so good in testing.
return @fsockopen($address, $port, $errno, $errstr, 30);

Bucking_Horn · January 18, 2023, 7:54pm

There's your loop, initiated by 192.168.1.95, and then forwarded from Pi-hole to your router to Pi-hole to your router...:

Jan 18 18:31:49 dnsmasq[267]: query[PTR] lb._dns-sd._udp.RT-AC87u from 192.168.1.95
Jan 18 19:09:15 dnsmasq[267]: forwarded lb._dns-sd._udp.0.1.168.192.in-addr.arpa to 192.168.1.1
                                                                                 --------------

Jan 18 19:09:15 dnsmasq[267]: query[PTR] lb._dns-sd._udp.0.1.168.192.in-addr.arpa from 192.168.1.1
                                                                                  ----------------

If you'd put the rate-limit back in, those queries would have been cut at a few hundreds.

To address this, you should consider to remove Pi-hole from your router's upstream DNS server configuration.

HeeeroYuy · January 18, 2023, 8:12pm

So I found the settings.
WAN-DNS is now 1.1.1.1 / 1.0.0.1
DHCP DNS is 192.168.1.29 / 192.168.1.29

That should work, shouldn't it?

and DHCP:

And the device is my fucking business iPhone (controlled by my company).