Current log file handling can lead to crazy big overlay2

[DutchShadow]

It's 1AM right now and I don't have the energy left to write up a full and clean issue report.
But I believe looking into the Logrotate defaults that are in docker, I think with IoT stack we can solve it by implementing something along the lines of https://hub.docker.com/r/marlic/rpi-logrotate .
The defaults that docker uses are very long and when messing with the home electricity and not having a UPS it can cause havoc to the Overlay2 filesystem.

For example the overlay filesystem gets filled with a 100gigs of pi-hole log if there's multiple power cycles...
The same issue came up with prometheus nodeexporter.

It has been a crazy rabbit hole and currently resetting the stack but let's get this sorted :)

[Paraphraser]

Can I please clarify which logs you are talking about? I assumed you meant the query log (that being the largest PiHole-related "log" I could find on my system) but I'd like to be sure. Here's what I see:

It looks to me like PiHole is retaining the last year's worth of logs. I have never really paid much attention to this (possibly because I live in an area with really shitty power so everything electronic in the house is behind UPS; so power-down of the Pi running PiHole tends to be orderly when we get a grid failure) but these buttons have always made me think PiHole only retains the last 24 hours:

After I took the first screen shot above I tried clicking the flush logs button but it looks to me like nothing happened - the query log kept growing.

I did a bit of futzing around inside the database to see if I could clear the logs by hand but I only succeeded in breaking things so I think a down, erase ./volumes/pihole then up is the way to go.

I don't think this is an IOTstack thing because that would imply that IOTstack has settings or options to control how PiHole logs stuff. It doesn't and, as far as I can tell, PiHole doesn't expose any controls either. You could try opening an issue on PiHole docker. I did a quick search - their issue 659 sounds like it could be relevant.

That issue was talking about files in the container's /var/log but nothing seemed to be out of whack there:

And, for the record, asking docker to show me the log doesn't suggest it gets a huge amount of activity:

The container was last re-created two weeks ago.

[Paraphraser]

I think the query flush process is broken. If I click the button in the GUI, the log shows:

And, yes, "queries" is a view, referencing the "query_storage" table.

[ukkopahis]

Could you post the output of (or show exactly which log file / database you are talking about):

docker-compose exec pihole ls -lh /var/log

@Paraphraser I'm disabling query logging in my devel-branch (see below). I think the project should assume the user is using a smallish SD-card and aim to reduce flash wear. Log rotation will keep disk space usage in check, but won't prevent flash wear. You might not even notice how much there is disk activity.

    pihole: settings to reduce flash wear

diff --git a/.templates/pihole/service.yml b/.templates/pihole/service.yml
index 341f340..33ab644 100644
--- a/.templates/pihole/service.yml
+++ b/.templates/pihole/service.yml
@@ -10,6 +10,8 @@ pihole:
     - TZ=Etc/UTC
     - WEBPASSWORD=%randomAdminPassword%
     - INTERFACE=eth0
+    - QUERY_LOGGING=false    # reduce flash wear
+    - FTLCONF_DBINTERVAL=5.0 # reduce flash wear: write every 5mins
   volumes:
     - ./volumes/pihole/etc-pihole:/etc/pihole
     - ./volumes/pihole/etc-dnsmasq.d:/etc/dnsmasq.d

[DutchShadow]

The main issue I believe is the disk usage comes to a point where "no disk space available" is reported even though the culprit files in var/lib/docker/overlay2/-HashOfVolumeBackupThingOrSomething- have been deleted/truncated.
This because docker keeps them assigned to itself.
df finds full allocation of the available space, du sees the actual new state after deletion and or truncation of offending log files...

[DutchShadow]

part of the rabbithole that looked promising but goes way over my head is in here: moby/moby#32420 (comment)

What I grasp from that comment is that loopback devices eat up disk space allocation without actually using it.
Maybe the menu can have a troubleshooting command where those deleted volumes.img get purged. As described in the comment with something that performs the function of:
for i in `losetup -a | grep deleted | awk '{print $1}' | sed 's/:$//'`; do losetup -d $i; done

[ukkopahis]

Would have been interesting to know and solve the root cause.

[ukkopahis]

The main issue I believe is the disk usage comes to a point where "no disk space available" is reported even though the culprit files in var/lib/docker/overlay2/-HashOfVolumeBackupThingOrSomething- have been deleted/truncated.

This is how linux works. If there's a process keeping an open file handle to the file, the disk space won't be released. If all else fails, just do a reboot.

You shouldn't manually touch anything in /var/lib/docker/ - those are files managed by dockerd,

[DutchShadow]

The main issue I believe is the disk usage comes to a point where "no disk space available" is reported even though the culprit files in var/lib/docker/overlay2/-HashOfVolumeBackupThingOrSomething- have been deleted/truncated.

This is how linux works. If there's a process keeping an open file handle to the file, the disk space won't be released. If all else fails, just do a reboot.

You shouldn't manually touch anything in /var/lib/docker/ - those are files managed by dockerd,

The issue is a reboot does not fix it, it would definitely be expected behaviour but it doesn't happen. However it is a docker issue, not a IoTStack issue. What I am proposing is to implement preventative measures in the form of configurations and in the form of things like daily log rotate tools... The mount in a mount in a mount can also be a unintended side effect of the stack setup. Which doesn't crop up during normal operations but happens with spotty power (like disconnecting the main breaker to pull a new ground wire in the house)

[ukkopahis]

Docker log rotation can be done by docker itself by setting max-size and max-file

https://docs.docker.com/config/containers/logging/json-file/#options
https://blog.boatswain.io/post/docker-container-log-rotation/

Rotation could be done by adding to the IOTstack generated docker-compose.yml into each service:

logging:
  driver: "json-file"
  # add log rotation
  options:
    max-size: "10M"
    max-file: "3"

(and update to existing containers: docker-compose up -d)

But is this a good default? If a "log flooding" problem were to occur for a user with a SD-card, it would be worn out pretty fast and fail. I think we should avoid default configurations that may be detrimental/destructive to hardware.

[DutchShadow]

I wonder if we can somehow reproduce the failures from lotsa power cycling... Idk what's best... Maybe some selective options for disabling logging for nodeexporter cadvisor and pihole (whomst I've seen making big log files).
In the normal scenario weekly rotation would mitigate any issue as it's set to standard anyhow...

[Paraphraser]

A fix for the non-flushing query log is in the works.

[DutchShadow]

Found an interesting way (only viable on SSD) to rotate logs nicely.
Just through the (on my system at least) log driver' settings.
I've changed journald to 500m max and 6day longest and for now it runs smoothly.

[ukkopahis]

@DutchShadow Could you post your working logging configuration as a future reference for others?

[DutchShadow]

----Recommended for SSD ONLY - Log rotation causes increased SD card wear... ---

We want to know our logdriver is journald find out by checking in /etc/docker/daemon.json
here we should find:
sudo nano /etc/docker/daemon.json

{ "log-driver": "journald", "storage-driver": "overlay2" }
Nothing to change here (allthough might be a nice config rabbit hole for a later date :)
Then use the steps as described in linux uprising to configure your journald to your liking.
https://www.linuxuprising.com/2019/10/how-to-clean-up-systemd-journal-logs.html

This can be done by editing the journald configuration file (/etc/systemd/journald.conf), and uncommenting,
sudo nano /etc/systemd/journald.conf
then adding a value to SystemMaxUse= (e.g.: SystemMaxUse=100M to remove archived journal files until the disk space they use falls below 100M) // I chose 500M
and/or MaxFileSec= (.e.g. MaxFileSec=5day to make all journal files contain no data older than 5 days).

[DutchShadow]

Before having intermittent power in your setup without a UPS i.e. messing with your breaker box (which got me into this mess).
Consider doing the following:
journalctl --disk-usage
If above 1/10th of available space on storage media do the following:
sudo journalctl --rotate --vacuum-size=500M
Rotate initiates an archival off all inactive logs.
Vacuum size sets the amount of space you want the logs to be using.

This should give you a couple of ungraceful shutdowns whilst the power is intermittent.