KISS 🇺🇦

Stop the war!

Stop the war in Ukraine! Fuck putin!

More information is at: https://war.ukraine.ua/.

There is a fund to support the Ukrainian Army: https://savelife.in.ua/en/donate/, and there is a special bank account that accepts funds in multiple currencies: https://bank.gov.ua/en/about/support-the-armed-forces. I donated to them. Please donate if you can!

Killer putin

Killer putin. Source: politico.eu.

Arrested putin

"It hasn't happened yet, but it will happen sooner or later. Beautiful photo, isn't it?" Source: twitter.

logrotate fails constantly on ArchLinux?!

| comments

I noticed the same thing on my two Arch Linux computers: systemctl --failed repeatedly showed logrotate.service as failed. I’d restart it, it would be successful then, but later it would fail on its own again.

Both servers had pi-hole (from AUR), which turned out to be the key here.

The logs showed:

1
2
3
4
5
6
7

$ journalctl -b -u logrotate.service
Feb 22 00:00:12 alarmpi systemd[1]: Starting Rotate log files...
Feb 22 00:00:12 alarmpi logrotate[14961]: error: state file /var/lib/logrotate.status is already locked
Feb 22 00:00:12 alarmpi logrotate[14961]: logrotate does not support parallel execution on the same set of logfiles.
Feb 22 00:00:12 alarmpi systemd[1]: logrotate.service: Main process exited, code=exited, status=3/NOTIMPLEMENTED
Feb 22 00:00:12 alarmpi systemd[1]: logrotate.service: Failed with result 'exit-code'.
Feb 22 00:00:12 alarmpi systemd[1]: Failed to start Rotate log files.

I couldn’t find anything related to NOTIMPLEMENTED in logrotate online, especially since restarting it manually always fixed this. This error always appeared when the service was run by a timer.

1
2
3
4
5
6

$ systemctl list-timers
NEXT                         LEFT          LAST                         PASSED       UNIT                         ACTIVATES
Wed 2022-04-20 00:00:00 EEST 16h left      Tue 2022-04-19 00:00:00 EEST 7h ago       logrotate.timer              logrotate.service
Wed 2022-04-20 00:00:00 EEST 16h left      Tue 2022-04-19 00:00:00 EEST 7h ago       pi-hole-logtruncate.timer    pi-hole-logtruncate.service
Wed 2022-04-20 00:00:00 EEST 16h left      Tue 2022-04-19 00:00:00 EEST 7h ago       shadow.timer                 shadow.service
…

I suspected that something weird was going on with the pi-hole-logtruncate.service, which never failed on either computer.

Solution

systemd coalesces timers with nearby trigger times so that the system has to schedule fewer events (see the AccuracySec section in man systemd.timer). In this case, it scheduled both logrotate services to run at the same time, which apparently caused the conflict — this was my hypothesis. I needed a persistent way to move them away from one another.

My solution is to add a randomized delay to one of the timers with systemd’s override files. I ran sudo systemctl edit pi-hole-logtruncate.timer and added this to the override file:

1
2

[Timer]
RandomizedDelaySec=1h

Now the timers list shows a different start time:

1
2
3
4
5
6

$ systemctl list-timers
NEXT                         LEFT        LAST                         PASSED       UNIT                         ACTIVATES
Sat 2022-04-23 00:00:00 EEST 15h left    Fri 2022-04-22 00:00:00 EEST 8h ago       logrotate.timer              logrotate.service
Sat 2022-04-23 00:00:00 EEST 15h left    Fri 2022-04-22 00:00:00 EEST 8h ago       shadow.timer                 shadow.service
Sat 2022-04-23 00:03:22 EEST 15h left    Fri 2022-04-22 00:00:00 EEST 8h ago       pi-hole-logtruncate.timer    pi-hole-logtruncate.service
…

This has been working fine for me for two weeks. In principle, it’s still possible that systemd runs both of them at the same time in some cases, but that’s not worth the trouble of looking for another fix.

ps. I later found a couple of comments about this issue on the package’s AUR page with different solutions, for example: https://aur.archlinux.org/packages/pi-hole-server#comment-760494.

Comments