FTL regularly using 100% CPU during which no DNS

Please follow the below template, it will help us to help you!

Expected Behaviour:

PiHole to respond to DNS requests all the time

Actual Behaviour:

Once or twice an hour, PiHole stops responding to DNS requests. When I ssh in, htop shows CPU at 100% with pihole-FTL accounting for at least 95%. This lasts about 5 minutes, after which DNS starts working again.

In the FTL logs at around the time of the issue I see:

[2020-03-16 16:57:15.702 475] Resizing "/FTL-strings" from 98304 to 102400
tail: /var/log/pihole-FTL.log: file truncated
[2020-03-16 17:33:16.806 10216] Using log file /var/log/pihole-FTL.log
[2020-03-16 17:33:16.808 10216] ########## FTL started! ##########

Pihole log shows this at the same time:
Mar 16 17:33:09 dnsmasq[475]: exiting on receipt of SIGTERM

I am running PiHole on Raspberry Pi B 2nd Generation. No other services or software running. OS is DietPi. Using DietPi ramlog. See my thread at https://www.reddit.com/r/pihole/comments/fgugv8/high_pihole_load/ for more logs.

Debug Token:

Error uploading debug log from command line and doesn't upload from web interface. I can send debug log to an alternative address.

What versions are you running? (pihole -v) And how did you install Pi-hole on DietPi, curl or DietPi Software?

root@PiHole:~# pihole -v
  Pi-hole version is v4.4 (Latest: v4.4)
  AdminLTE version is v4.3.3 (Latest: v4.3.3)
  FTL version is v4.3.1 (Latest: v4.3.1)

Installed via DietPi software.

@MichaIng Do you want to take a look at this one? My first advice is going to be to install via curl.

1 Like

If you suspect the DietPi install is broken, I'd rather look into how it might be broken, so DietPi can be advised to fix it, rather than just start from scratch just for me.

1 Like

Micha is the maintainer of DietPi, so that's where we'll start.

1 Like

Awesome! Thanks.

My dietpi-update output showing version

[ INFO ] DietPi-Update | Current version : v6.28.0
[ INFO ] DietPi-Update | Latest version  : v6.28.0

I'm using DietPi-Ramlog #2 option.

Can you please paste the service log, after such case? Since your log shows a SIGTERM this should come from the systemd service.

journalctl -u pihole-FTL
1 Like

@DanSchaper
What does this mean? From the logs it looks like this was the last task before is crashed, starting new afterwards after 5 minutes.

1 Like

That's just a regular log message. Should see that as the SHM file reallocates to a bigger contiguous memory space.

Is it possible that /var/log ran out of space?

The RAMlog is cleared every hour, so this should not be possible. That the file is truncated is the result from hourly clearing. If I remember right, this shows up on FTL start, hence is not related to the prior failure/SIGTERM.

@dunxd
Additionally to journalctl output, could you paste as well kernel messages, just to role or any kernel/SDcard I/O or memory issues.

dmesg
1 Like

@DL6ER Would the log file being deleted without FTL being signaled cause any issues?

How is it cleared?

I don't think so, how is the file deleted?

edit Ah, I see you're looking into the same direction.

The file is not deleted, the following is done with every log file once an hour:

> /var/log/pihole-FTL.log

We had an exemption and special handling for pihole.log in place, clearing it only if grown over 50% of tmpfs space and stopping/starting the service before/after. I had some discussion on GitHub some year ago, if this is (still) required, especially since we never handled the new pihole-FTL.log special and the result was that especially pihole-FTL.log should be very stable against log file manipulation while pihole.log logging can and should be disabled, since it does not contain much more than the web interface query log. So we do pihole -l off now on install.
I can search for the GitHub topic, would be of course important to know if this changed. But really, not a single (other) program of all what Debian offers ever had any issue with a truncated log file, so I doubt that this can crash or overload pihole-FTL.
EDIT: Else logrotate would cause the same issue :thinking:

1 Like

I concur. This seems to be the wrong track.

We do not even know where FTL is entering the high CPU load.
Neither do we know if

is connected to the crash at all.

  • How many devices do you have connected to your network?
  • How many queries are they doing roughly?

I already saw your setup is an RPi 2 running DietPi and nothing besides Pi-hole on it. Maybe the large workload is storing something in the database (not too likely) or the tries to re-resolve host names (happening once an hour, not twice).

  • Have you checked the query log after such a period of intense work? Maybe it is real and your Pi-hole has to reply to thousands of queries per second from some client going mad?
1 Like
root@PiHole:~# journalctl -u pihole-FTL
-- Logs begin at Sun 2020-03-15 16:06:21 GMT, end at Wed 2020-03-18 10:1Mar 15 16:06:39 PiHole systemd[1]: Starting LSB: pihole-FTL daemon...
Mar 15 16:06:40 PiHole pihole-FTL[339]: Not running
Mar 15 16:06:43 PiHole su[437]: (to pihole) root on none
Mar 15 16:06:43 PiHole su[437]: pam_unix(su:session): session opened forMar 15 16:06:55 PiHole pihole-FTL[339]: FTL started!
Mar 15 16:06:55 PiHole su[437]: pam_unix(su:session): session closed forMar 15 16:06:56 PiHole systemd[1]: Started LSB: pihole-FTL daemon.
Mar 16 17:33:05 PiHole systemd[1]: Stopping LSB: pihole-FTL daemon...
Mar 16 17:33:09 PiHole dnsmasq[475]: log failed: Bad file descriptor
Mar 16 17:33:09 PiHole dnsmasq[475]: DHCPACK(eth0) 192.168.1.100 38:f9:dMar 16 17:33:09 PiHole dnsmasq[475]: failed to write /etc/pihole/dhcp.leMar 16 17:33:13 PiHole pihole-FTL[10106]: .....
Mar 16 17:33:14 PiHole pihole-FTL[10106]: Not stopped; may still be shutMar 16 17:33:14 PiHole systemd[1]: pihole-FTL.service: Control process eMar 16 17:33:14 PiHole systemd[1]: pihole-FTL.service: Failed with resulMar 16 17:33:14 PiHole systemd[1]: Stopped LSB: pihole-FTL daemon.
Mar 16 17:33:14 PiHole systemd[1]: Starting LSB: pihole-FTL daemon...
Mar 16 17:33:14 PiHole pihole-FTL[10158]: /etc/init.d/pihole-FTL: line 6Mar 16 17:33:15 PiHole pihole-FTL[10158]: Stopped
Mar 16 17:33:16 PiHole su[10210]: (to pihole) root on none
Mar 16 17:33:16 PiHole su[10210]: pam_unix(su:session): session opened fMar 16 17:33:26 PiHole pihole-FTL[10158]: FTL started!
Mar 16 17:33:26 PiHole su[10210]: pam_unix(su:session): session closed fMar 16 17:33:27 PiHole systemd[1]: Started LSB: pihole-FTL daemon.
Mar 16 18:03:54 PiHole systemd[1]: Stopping LSB: pihole-FTL daemon...
Mar 16 18:03:57 PiHole pihole-FTL[10429]: .
Mar 16 18:03:57 PiHole pihole-FTL[10429]: Stopped
Mar 16 18:03:57 PiHole systemd[1]: pihole-FTL.service: Succeeded.
Mar 16 18:03:57 PiHole systemd[1]: Stopped LSB: pihole-FTL daemon.
Mar 16 18:03:57 PiHole systemd[1]: Starting LSB: pihole-FTL daemon...
Mar 16 18:03:57 PiHole pihole-FTL[10465]: Not running
Mar 16 18:03:58 PiHole su[10510]: (to pihole) root on none
Mar 16 18:03:59 PiHole su[10510]: pam_unix(su:session): session opened fMar 16 18:04:09 PiHole pihole-FTL[10465]: FTL started!
Mar 16 18:04:09 PiHole su[10510]: pam_unix(su:session): session closed fMar 16 18:04:09 PiHole systemd[1]: Started LSB: pihole-FTL daemon.
lines 1-37/37 (END)