Froschs Blog

Computer und was das Leben sonst noch so zu bieten hat

Zur Website | Impressum

Rotierende Logfiles

15. Mai 2017 um 17:13 Uhr von Atari-Frosch

Bereits vor längerer Zeit fiel mir auf, daß bei der Rotation einiger Logfiles zumindest gelegentlich seltsame Dinge passieren. Nun habe ich mir das dieser Tage mal genauer angesehen.

dovecot

dovecot benutzt gelegentlich – nicht immer – die rotierten Logfiles weiter. Es schreibt also nach der Rotation seine Einträge nach

/var/log/dovecot-errors.log.1

statt sie, wie vorgesehen, in die nach der Rotation neu erzeugte Datei

/var/log/dovecot-errors.log

zu schreiben.

Wird dann in der Folgewoche wiederum rotiert, greift die Anweisung notifempty in der jeweiligen Konfigurationsdatei von logrotate, und das Log wächst immer weiter, statt korrekt rotiert zu werden, weil die .log-Datei ja leer bleibt – bis ich dovecot manuell neu starte.

Manpages lesen kann manchmal echt hilfreich sein – und die von logrotate ist sogar recht übersichtlich. Dabei entdeckte ich nämlich den Parameter copytruncate als Alternative für create. Der Unterschied besteht darin, daß bei zweiterem die bisherige Logdatei umbenannt und dann mit touch eine neue angelegt wird, während bei ersterem die Datei erst kopiert und dann das Original geleert wird.

Also:

create macht, nachdem die älteren Logfiles entsprechend umbenannt wurden, aus der .log eine .log.1 und erzeugt dann eine neue, leere .log. Danach muß das Programm, welches dieses Log schreibt, „angestupst“ werden, damit es mitbekommt, daß jetzt mit einer anderen Datei gleichen Namens weitergearbeitet werden soll. Vorteile: Eine Umbenennung geht schneller als eine Kopie. Gleichzeitig kann dabei nichts verloren gehen. Nachteil: Dem entsprechenden Programm muß die Änderung signalisiert werden, und es muß das Signal auch sauber verarbeiten, sonst schreibt es weiter in die .log.1, denn anscheinend achten nicht alle Programme darauf, ob der Dateiname noch stimmt, sondern orientieren sich an anderen Metadaten wie zum Beispiel der Inode-Nummer – die ändert sich bei einer Umbenennung nicht.

copytruncate kopiert die bisherige .log in eine neue .log.1 und leert die bisherige .log aus. Vorteile: Das schreibende Programm muß davon gar nichts mitbekommen, es braucht also auch kein Signal. Nachteile: Das Kopieren dauert länger als eine Umbenennung. Außerdem werden dabei die Zeilen des Logs, die währenddessen geschrieben werden, höchstwahrscheinlich verloren gehen. Das wiederum dürfte aber nur eine Rolle spielen, wenn die Logdateien sehr groß werden und daher der Kopiervorgang doch etwas länger dauert. Und dann kann man immer noch auf kürzere Rotationsabstände umstellen und dafür mehr rotierte Logs beibehalten.

Durch die Umstellung von create auf copytruncate bei den Logs von dovecot erhoffte ich mir also einen sauberen Übergang von der bisherigen, rotierten in die „neue“ Logdatei.

Leider trat diese gewünschte Wirkung aber nicht ein.

Ich hatte die Anweisungen für die Rotation dieser Logs aus /etc/logrotate.d/rsyslog rausgezogen, wo ich sie, so vermute ich, vor ewigen Zeiten mal selbst reingeklebt hatte. Mir scheint, daß das Debian-Paket für dovecot gar keine eigene Logrotate-Anweisungsdatei schreibt, wie es für andere Server-Programme üblich ist.

/etc/logrotate.d/dovecot sah nach dem Herausziehen und ein paar Anpassungen von mir erstmal so aus:

/var/log/dovecot-errors.log {
        weekly
        missingok
        rotate 5
        compress
        delaycompress
        notifempty
        copytruncate
        dateext
        mail root@…
        mailfirst
}

dateext hatte ich beim Studium der Manpage zusätzlich entdeckt und gleich mal eingebaut, weil mir das sinnvoller erscheint als die übliche Durchnumerierung; dabei wird statt einem .1 das Tagesdatum an die Logdatei geklebt.

Die Dateirechte stimmten mit denen der anderen Dateien in diesem Verzeichnis überein, aber offenbar wurden die Anweisungen nicht ausgeführt. Ich bekam keine Mail, und es wurde weiterhin in die .log.1 geschrieben. Laut

$ cat /var/lib/logrotate/status

jedoch war die Datei genauso wie alle anderen ausgeführt worden – man merkt nur nix davon.

Im Dovecot-Wiki fand ich das hier und paßte es leicht an (Mailanweisungen rein, sharedscripts raus, weil hier sinnfrei):

/var/log/dovecot*.log {
        weekly
        rotate 5
        missingok
        notifempty
        compress
        delaycompress
        mail root@…
        mailfirst
        postrotate
                doveadm log reopen
        endscript
}

Ein logrotate --force dovecot bewirkte jedoch weiterhin – nichts. Erst nachdem ich dovecot händisch stoppte und neu startete, schreibt er jetzt endlich wieder in die richtige Logdatei.

Und jetzt weiß ich auch nicht …

nginx

Bei den Logfiles von nginx konnte ich das eigentliche Problem ebenfalls nicht lösen, fand aber eine Alternative, und die ist dann auch noch viel besser als das, was ich bisher gemacht hatte.

Die Rotation funktionierte hier prinzipiell. Die damit erzeugten Logdateien ließ ich mir bisher jeden Sonntag um 11:00 Uhr als Mail schicken – per Cronjob. Leider scheint das nicht immer wie vorgesehen zu funktionieren, denn immer mal wieder bekam ich Logfiles von der Vorwoche zugeschickt, die ich bereits hatte, während mir das aktuelle dann gar nicht geschickt wurde. Und in der darauffolgenden Woche bekomme ich dann wieder das aktuelle.

Eigentlich laufen diese Cronjobs zu einer einigermaßen festen Zeit, nämlich morgens um 06:25 Uhr. Einigermaßen, weil die Zeitstempel der rotierten Dateien bei mir zwischen 06:20 und 06:25 Uhr liegen. Damit sollte ein Versand der rotierten Dateien um 11:00 Uhr locker ausreichen. Also, eigentlich.

Auch wieder aus der manpage von logrotate lernte ich den Parameter mail kennen (den habe ich ja oben bei dovecot auch gleich angewandt). Damit und einer folgenden Mailadresse kann man angeben, wohin rotierte Logdateien geschickt werden sollen. Allerdings wird damit regulär das älteste rotierte Logfile verschickt; will man, wie ich, das jeweils neueste haben, muß man zusätzlich den Parameter mailfirst mit angeben.

Zusätzlich habe ich auch hier mal testweise für alle Logs auf copytruncate umgestellt. Daß mir dabei regulär was verloren geht, glaube ich mal nicht. Dafür muß nginx dann auch nicht mehr „angestupst“ werden, weil sich ja das Logfile nicht ändert. Es wird auch durchaus dazu geraten, für nginx diese Einstellung zu wählen, weil er wohl gelegentlich dazu tendiert, nicht auf das entsprechende Signal zu reagieren.

Ergebnis: nginx ist mit diesem Setting absolut einverstanden. Und die Mails wurden allesamt um 06:25 Uhr erzeugt. Was bei dem Weg über den Cronjob falsch lief, weiß ich also weiterhin nicht. Generell ist die Lösung über die Logrotate-Konfiguration aber natürlich sauberer als die mit dem Cronjob.

… und, totally unrelated, postfix

So nebenbei fiel mir dann noch auf: Wenn ich mir mit Hilfe von Scripts Status-Mails vom System schicken lasse, gingen die bisher an root@localhost. Der postfix ist so konfiguriert, daß Mails an diese Adresse in mein virtuelles Postfach eingeworfen werden, sodaß ich sie in meinen Thunderbird geliefert bekomme. Und meistens hat das auch funktioniert. Aber nur meistens: Vereinzelt (und für eine Art von Meldungen generell) wurden die Mails trotzdem lokal ausgeliefert, landeten also in der Mailbox von root auf dem Server – wo ich eher selten reinschaue. Warum auch, da sollten ja eigentlich gar keine Mails landen.

Warum das passiert, konnte ich nicht herausfinden. DAher habe ich in allen Scripts, die Systemmails erzeugen, den Empfänger auf root@$domain geändert. Damit kann das nicht mehr passieren. Das war also nur ein Workaround, keine Problemlösung. Was soll's, works for me.

Ein Kommentar zu “Rotierende Logfiles”

  1. SackOhneSenf quakte:

    Da du schon am Manpage lesen bist, empfehle ich dir einen Blick in die Manpage von Dovecot zu werfen, bevorzugt den Abschnitt über Signals:

    Du mußt einfach dem Master Prozess von Dovecot ein SIGUSR1 schicken, damit der seine Logfiles neu öffnet, dann also in die rotierten Log-Dateien schreibt … die alten Dateien bis zum eintreffen des Signals weiter zu verwenden ist Absicht und hilft Beschädigungen am Dateisystem zu vermeiden.

    Meines Wissens hat Logrotate irgend eine Möglichkeit nach dem rotieren der Files einem Prozess ein Signal zu senden (oder ein Kommando auszuführen -> pkill -SIGUSRR1 dovecot) … und falls nicht, einfach kurze Zeit nach dem rotieren per Cron-Job das Signal an Dovecot senden. Im Zweifel kann man aber auch alle paar Stunden das Signal auf Verdacht senden, falls er die gleichen Dateien wieder öffnet hast du eben nur etwas Prozessorzeit verbraten.

    … es gibt also diverse Lösungsmöglichkeiten für dein Problem.


Kommentieren

Bitte beachte die Kommentarregeln!

XHTML: Du kannst diese Tags verwenden: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>