Logrotate Problem täglich 00:00 Uhr

weltmeister · 4. November 2020

Täglich um 00:00 Uhr "verabschiedet" sich der Logrotate-Dienst auf einigen Servern unter Debian 10. Leider sind die Logeinträge nicht gerade besonders hilfreich:

Zitat

Nov 4 00:00:07 s5 rsyslogd: [origin software='rsyslogd' swVersion='8.1901.0' x-pid='560' x-info='https://www.rsyslog.com'] rsyslogd was HUPed
Nov 4 00:00:07 s5 systemd[1]: logrotate.service: Main process exited, code=exited, status=1/FAILURE
Nov 4 00:00:07 s5 systemd[1]: logrotate.service: Failed with result 'exit-code'.
Nov 4 00:00:07 s5 systemd[1]: Failed to start Rotate log files.

Hat jemand einen Tipp, wo man zuerst mit der Fehlersuche beginnen könnte?

antondollmaier · 4. November 2020

Logrotate manuell ausführen (logrotate -v -f /etc/logrotate.conf)

weltmeister · 4. November 2020

Zitat von antondollmaier

Logrotate manuell ausführen (logrotate -v -f /etc/logrotate.conf)

...ist perfekt duchgelaufen. Wie aber kann man das Problem lösen, das sich der Dienst von selbst beendet?

TCRserver · 4. November 2020

Wenn ich es noch richtig im Kopf habe, dann war es irgendwas im Zusammenspiel mit dem syslog^bzw. dem postrotate Befehl.
Betroffen waren bei uns nur Systeme die ein Debian 9 auf 10 Upgrade bekommen haben.

So aus dem Kopf raus:
Edit: /etc/logrotate.d/rsyslog

suche nach:

Code

postrotate
                invoke-rc.d rsyslog rotate > /dev/null
        endscript

und ersetze durch:

Code

postrotate
                /usr/lib/rsyslog/rsyslog-rotate
        endscript

Aber wirklich aus dem Kopf raus und ohne Gewähr!

weltmeister · 6. November 2020

Vielen Dank, den Eintrag

Zitat

postrotate
invoke-rc.d rsyslog rotate > /dev/null
endscript

gibt es so in der gen. Datei nicht. Da das Problem leider noch immer besteht: wo könnte man noch nach der Ursache suchen?

antondollmaier · 6. November 2020

Laut erstem Beitrag kam es zu Fehlern im logrotate.service.

Daher: "journalctl -u logrotate.service" aufrufen und prüfen, ob es dort Einträge gibt. Ggf. auch tatsächlich bis 00:00 Uhr warten und im "journalctl -f" mitverfolgen, was so passiert.

Spannend empfinde ich jedoch, dass Logrotate überhaupt um 00:00 Uhr läuft. Standard ist eigentlich 06:25 Uhr für die Dailys.

weltmeister · 6. November 2020

Hier die 3 Einträge von heute:

Code

Nov 06 00:00:05 s20.de systemd[1]: logrotate.service: Main process exited, code=exited, status=1/FAILURE
Nov 06 00:00:05 s20.de systemd[1]: logrotate.service: Failed with result 'exit-code'.
Nov 06 00:00:05 s20.de systemd[1]: Failed to start Rotate log files.

In den Logfiles steht das selbe. Aber klug werde ich daraus nicht.

weltmeister · 12. November 2020

Habe das Problem einmal einem erfahrenen Administrator weitergereicht, hier dessen Antwort:

Wenn ich mir die Fehlermeldung von lograte ansehe:

Code

systemctl status logrotate
● logrotate.service - Rotate log files
  Loaded: loaded (/lib/systemd/system/logrotate.service; static; vendor preset: enabled)
  Active: failed (Result: exit-code) since Thu 2020-11-12 00:00:01 CET; 9h ago
    Docs: man:logrotate(8)
          man:logrotate.conf(5)
 Process: 25679 ExecStart=/usr/sbin/logrotate /etc/logrotate.conf (code=exited, status=1/FAILURE)
Main PID: 25679 (code=exited, status=1/FAILURE)


Nov 12 00:00:01 s26.server.de logrotate[25679]: error: error running shared postrotate script for '/var/www/web4/logs/*.log '
Nov 12 00:00:01 s26.server.de logrotate[25679]: lclogsplit: Kein Prozess gefunden
Nov 12 00:00:01 s26.server.de logrotate[25679]: error: error running shared postrotate script for '/var/www/web5/logs/*.log '
Nov 12 00:00:01 s26.server.de logrotate[25679]: lclogsplit: Kein Prozess gefunden
Nov 12 00:00:01 s26.server.de logrotate[25679]: error: error running shared postrotate script for '/var/www/web6/logs/*.log '
Nov 12 00:00:01 s26.server.de logrotate[25679]: lclogsplit: Kein Prozess gefunden
Nov 12 00:00:01 s26.server.de logrotate[25679]: error: error running shared postrotate script for '/var/www/web3/logs/*.log '
Nov 12 00:00:01 s26.server.de systemd[1]: logrotate.service: Main process exited, code=exited, status=1/FAILURE
Nov 12 00:00:01 s26.server.de systemd[1]: logrotate.service: Failed with result 'exit-code'.Nov 12 00:00:01 s26.server.de systemd[1]: Failed to start Rotate log files.

Alles anzeigen

wird klar das es am postrotate Kommando "/usr/bin/killall -HUP lclogsplit" in der Datei: /etc/logrotate.d/liveconfig-vhosts liegt.
Dieses Kommando killt das Programm lclogsplit für jedes Dort angegebene Verzeichnis Abschnitt.
Da schon beim ersten Aufruf der lclogsplit Daemon nicht mehr läuft, werden alle Folgeaufrufe mit Error 1 an das posttrotate zurückgegeben, was dann zu dieser Meldung führt.

Hier müssten Sie einmal an den Anbieter von Liveconfig herantreten ob es diesbezüglich ein Update/Patch gibt. Da das logrotate file aus liveconfig generiert wird, bringt es leider nichts es dort selbst zu beheben, da es immer wieder überschrieben wird.

kk · 16. November 2020

Das Problem liegt wahrscheinlich ganz woanders, das hier beschriebene Verhalten vom logrotate ist lediglich ein Symptom.

Zitat

Code

Nov 12 00:00:01 s26.server.de logrotate[25679]: error: error running shared postrotate script for '/var/www/web4/logs/*.log '
Nov 12 00:00:01 s26.server.de logrotate[25679]: lclogsplit: Kein Prozess gefunden

Das zeigt, dass der lclogsplit-Prozess überhaupt nicht lief, als logrotate ausgeführt wurde. Da lclogsplit aber i.d.R. als Child-Prozess vom Apache gestartet wird, scheint da schon irgendwas nicht zu stimmen.
(Ausnahme: beim Dual-Betrieb von Apache und NGINX läuft lclogsplit als eigenständiger Daemon)
Hier wird übrigens ein HUP-Signal gesendet, der lclogsplit-Prozess wird dadurch also nicht beendet, sondern lediglich darüber informiert dass diese prüfen soll, dass Log-Dateien eventuell rotiert wurden.

Wir können die logrotate-Konfiguration dahingehend ändern, dass der Exit-Code des postrotate-Scripts (also der killall-Aufruf) ignoriert wird. Das dürfte das von Ihnen beschriebene Symptom beseitigen, aber nicht die Ursache beheben.

Viele Grüße

-Klaus Keppler

weltmeister · 16. November 2020

Vielen Dank für die Erläuterungen! Hierzu weitere eingehende Fragen:

Was könnte der Grund dafür sein, dass der lclogsplit-Prozess nicht läuft?
Gibt es eine Möglichkeit, diesen manuell zu starten oder gar neu zu installieren /zu aktivieren?
Hat dieser Dienst Konfigurationsdateien, die man auf Richtigkeit / vorhandensein prüfen kann?

Das Problem tritt auf insgesamt 7 Servern auf, die kürzlich von Debian 9 auf 10 aktualisiert worden sind. Ich wäre sehr daran interessiert, diese aus der Welt zu schaffen.

kk · 17. November 2020

Zitat von weltmeister

Was könnte der Grund dafür sein, dass der lclogsplit-Prozess nicht läuft?
Gibt es eine Möglichkeit, diesen manuell zu starten oder gar neu zu installieren /zu aktivieren?
Hat dieser Dienst Konfigurationsdateien, die man auf Richtigkeit / vorhandensein prüfen kann?

Wie in meinem vorherigen Beitrag schon beschrieben, wird dieser Prozess normalerweise automatisch durch Apache gestartet (aufgrund der Pipe-Anweisung in /etc/apache2/conf-enabled/liveconfig.log: "CustomLog "||/usr/lib/liveconfig/lclogsplit -i -w" LiveConfig")

Wenn lclogsplit also nicht läuft, dann läuft wahrscheinlich der gesamte Apache (zumindest kurzzeitig) nicht.

Ich kenne Ihre Server nicht, aber dieses Verhalten basiert vermutlich auf einer lokalen "Spezialkonfiguration". Der Aufruf von logrotate (via cron.daily) erfolgt normalerweise um 06:25 (siehe /etc/crontab). Wenn bei Ihnen alles um 00:00 statt findet, dann passiert da vielleicht zu viel gleichzeitig. Letztendlich lässt sich das nur anhand der Logs genauer analysieren.

Viele Grüße

-Klaus Keppler

weltmeister · 14. Dezember 2020

Das Problem besteht leider noch immer und ich weiß schon gar nicht mehr, wo ich noch suchen soll. Die Logs sagen leider nicht viel aus, siehe Beitrag 1.

Hat noch jemand einen Tipp, an welcher Stelle nach der Ursache gesucht werden kann?

weltmeister · 29. Dezember 2020

Kann es möglich sein, dass der Dienst streikt, wenn einer Kunden-Accounts "voll" ist?

systemctl status logrotate
Dez 29 00:00:01 s22.de systemd[1]: Starting Rotate log files...
Dez 29 00:00:04 s22.de logrotate[31837]: error: Compressing program wrote following message to stderr when compressing log /var/www/web113/logs/priv/php_errors.log.1:
Dez 29 00:00:04 s22.de logrotate[31837]: gzip: stdout: Disk quota exceeded
Dez 29 00:00:04 s22.de logrotate[31837]: error: failed to compress log /var/www/web113/logs/priv/php_errors.log.1
Dez 29 00:00:08 s22.de systemd[1]: logrotate.service: Main process exited, code=exited, status=1/FAILURE
Dez 29 00:00:08 s22.de systemd[1]: logrotate.service: Failed with result 'exit-code'.
Dez 29 00:00:08 s22.de systemd[1]: Failed to start Rotate log files.

Da auf der Disk noch genügend Speicherplatz frei ist, kann es nur die Quota von der Usergruppe sein und die ist anscheinend voll:

repquota -g / | grep web113
Block Limits Dateilimits
Gruppe belegt weich hart Gnade belegt weich hart Gnade
----------------------------------------------------------------------
web113 -- 5242880 0 5242880 5478 0 0

antondollmaier · 29. Dezember 2020

Zitat von kk

Ich kenne Ihre Server nicht, aber dieses Verhalten basiert vermutlich auf einer lokalen "Spezialkonfiguration". Der Aufruf von logrotate (via cron.daily) erfolgt normalerweise um 06:25 (siehe /etc/crontab). Wenn bei Ihnen alles um 00:00 statt findet, dann passiert da vielleicht zu viel gleichzeitig.

Wie ich kürzlich (aka über Weihnachten) gelernt habe: es gibt in Debian Buster neben dem cron.daily-Cronjob auch einen logrotate.timer:

Code

~# systemctl list-timers
NEXT                         LEFT       LAST                         PASSED       UNIT                         ACTIVATES
Wed 2020-12-30 00:00:00 UTC  11h left   Tue 2020-12-29 00:00:02 UTC  12h ago      logrotate.timer              logrotate.service

Das erklärt damit die 00:00 Uhr Ausführungen.

Fehlersuche sollte jedoch komplett im Journal über "journalctl -u logrotate.service" möglich sein.

weltmeister · 29. Dezember 2020

Zitat von antondollmaier

Das erklärt damit die 00:00 Uhr Ausführungen.

Danke für diesen Hinweis. Man lernt nie aus.

Die Ausgabe von journalctl -u logrotate.service wurde oben (Beitrag um 13:29 Uhr) vermerkt. Daher auch die vermutung, dass es mit einem der vollen Kundenaccounts zu tun haben könnte.

weltmeister · 18. Januar 2021

Heute ist der Dienst auf einem Server ertmalig ausgefallen, auf dem es bisher nie Probleme damit gab:

Zitat

root@s41:~# service logrotate status
● logrotate.service - Rotate log files
Loaded: loaded (/lib/systemd/system/logrotate.service; static; vendor preset: enabled)
Active: failed (Result: exit-code) since Mon 2021-01-18 00:00:07 CET; 7h ago
Docs: man:logrotate(8)
man:logrotate.conf(5)
Process: 14869 ExecStart=/usr/sbin/logrotate /etc/logrotate.conf (code=exited, status=1/FAILURE)
Main PID: 14869 (code=exited, status=1/FAILURE)

Jan 18 00:00:01 s41.de systemd[1]: Starting Rotate log files...
Jan 18 00:00:03 s41.de logrotate[14869]: error: Compressing program wrote following message to stderr when compressing log /var/www/web36/logs/priv/php_errors.log.1:
Jan 18 00:00:03 s41.de logrotate[14869]: gzip: stdout: Disk quota exceeded
Jan 18 00:00:03 s41.de logrotate[14869]: error: failed to compress log /var/www/web36/logs/priv/php_errors.log.1
Jan 18 00:00:07 s41.de systemd[1]: logrotate.service: Main process exited, code=exited, status=1/FAILURE
Jan 18 00:00:07 s41.de systemd[1]: logrotate.service: Failed with result 'exit-code'.
Jan 18 00:00:07 s41.de systemd[1]: Failed to start Rotate log files.
root@s41:~#

Alles anzeigen

Was kann man hier konkret tun um die Ursache dauerhaft zu beheben?

TCRserver · 18. Januar 2021

Also bitte schlagt mich nicht gleich wenn ich falsch liege aber...

Zitat

Jan 18 00:00:03 s41.de logrotate[14869]: gzip: stdout: Disk quota exceeded

... Festplatte voll?!

TCRserver · 18. Januar 2021

Ist der LC Backup Dienst auf dem Server aktiv?

weltmeister · 18. Januar 2021

Zitat von TCRserver

Also bitte schlagt mich nicht gleich wenn ich falsch liege aber...

... Festplatte voll?!

Nein, nur ein einziger Kundenwebspace / Account ist voll. Das sich der Dienst beendet hat sicher damit zu tun.

TCRserver · 18. Januar 2021

Mal so als Idee:
Läuft irgendwas mit Quota zu der Zeit?
Lässt sich der CronJob vom Logrotate um 5 Minuten verschieben?
Nicht dass der Prozess mit irgendwas anderem kollidiert.

Jetzt mitmachen!