Logrotate Problem täglich 00:00 Uhr

    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?

    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!

    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.

    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.

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


    Wenn ich mir die Fehlermeldung von lograte ansehe:



    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.

    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

    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.

    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

    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

    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.

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



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

Jetzt mitmachen!

Sie haben noch kein Benutzerkonto auf unserer Seite? Registrieren Sie sich kostenlos und nehmen Sie an unserer Community teil!

Benutzerkonto erstellen Anmelden