Gestern Abend habe ich, vor lauter Wut im Bauch, auf Google+ etwas über die "guten" alten Dienste atd, crond und logrotate geschrieben. Der Beitrag war mit insgesamt 114 Zeichen natürlich nicht sonderlich ausführlich, hat aber trotz dieser kürze einige Menschen zum Kommentieren motiviert. Mein Post auf Google+ entstand durch den Umstand, dass ich mal wieder mit diesen sehr alten Unix Tools einen Fehler suchen durfte, den es so mit modernen Lösungen (z.B. journald, Timer Units) nicht geben würde.

Welches Problem hatte ich eigentlich? Nun, meine Icinga Instanz hat mir ein zunehmend volles /var/log gemeldet. Da ich keine Modifikationen an der Konfiguration von Logrotate oder crond durchgeführt habe, sollte logrotate die Logfiles in diesem Ordner wöchentlich rotieren, alte Komprimieren und alles, was älter als 4 Wochen ist, über den Jordan jagen. Das Volume für dieses Verzeichnis hat eine Größe von immerhin 10 GiB, was für die Logfiles für einen Zeitraum von 4 Wochen bei 2 aktiven Diensten (Apache, Postfix) wirklich ausreichend sein sollte. Beim Überprüfen ist mir Folgendes am Anfang der mail.log aufgefallen:

Jul 11 08:17:36 h2022461 cyrus/master[1276]: about to exec /usr/lib/cyrus/bin/imapd
Jul 11 08:17:36 h2022461 cyrus/imaps[1276]: executed
Jul 11 08:17:36 h2022461 cyrus/imaps[1276]: accepted connection
Jul 11 08:17:36 h2022461 cyrus/imaps[1276]: mystore: starting txn 2147483710
Jul 11 08:17:36 h2022461 cyrus/imaps[1276]: mystore: committing txn 2147483710
Jul 11 08:17:36 h2022461 cyrus/imaps[1276]: starttls: TLSv1 with cipher AES256-SHA
(256/256 bits new) no authentication
Jul 11 08:18:00 h2022461 postfix/anvil[901]: statistics: max connection rate 2/60s
for (smtp:X.Y.Z.Z) at Jul 11 08:11:32
Jul 11 08:18:00 h2022461 postfix/anvil[901]: statistics: max connection count 1
for (smtp:X.Y.Z.Z) at Jul 11 08:08:55
Jul 11 08:18:00 h2022461 postfix/anvil[901]: statistics: max cache size 2 at Jul
11 08:14:39
Jul 11 08:18:36 h2022461 cyrus/master[622]: process 1276 exited, status 0

Die Datei hat eine Größe von über 500 MiB und nachweislich Einträge, welche noch vom letzten Jahr sind. Viele andere Logfiles haben ähnliche Größen, die /var/log/xconsole.log war sogar über 1 GiB groß. Insgesamt wurden so mehr als 8 GiB kostbarer Festplattenplatz für unsinnige Logfiles verschwendet. Eine Ursache, warum so viel Platz verschwendet wird und die Rotation der Logfiles nicht richtig gelaufen ist findet man nirgendwo.

Als Admin macht man sich dann erst mal auf die Fehlersuche, der erste Anlauf wäre hier natürlich die /etc/logrotate.conf. Doch von dort gibt es nur einen Hinweis auf 2 unwichtigere Logfiles und natürlich ein Include vom Verzeichnis /etc/logrotate.d. Und genau für den Postfix gibt es dort natürlich keine Konfigurationsdatei, welche sich für die mail.log auch nur im Ansatz verantwortlich fühlt. Die Rotation der Logfiles vom Postfix erfolgt nämlich nicht über logrotate wie man annehmen würde, sondern selbstverständlich über das Script /etc/cron.daily/sysklogd.

Welche Probleme haben wir bisher gesehen? Fassen wir das doch Mal zusammen:

  1. Informationen werden in verschiedenen Logfiles gleichzeitig vorgehalten, die /var/log/xconsole.log enthält viele Informationen die man auch schon in der /var/log/messages, /var/log/daemon.log oder der /var/log/syslog finden kann.
  2. Die Rotation der Logfiles ist nicht an genau einer Stelle, nämlich der Konfiguration vom spezialisierten Tool logrotate, gespeichert, sondern zusätzlich arbeitet auch noch ein Cronjob und übernimmt die gleiche Tätigkeit, aber eben für andere Dateien. Wo ist "One Job, One Tool" wenn man es mal braucht?
Immerhin wissen wir jetzt schon mal, wo unsere Logfiles, zumindest in der Theorie rotiert werden. Ein beherztes grep cron.daily /var/log/syslog bestätigt auch das unsere Cronjobs hierfür täglich ihre Arbeit machen sollten. Jetzt haben wir das nächste Problem: Wo sehe ich ob ein Cronjob wirklich gelaufen ist? Wo sehe ich welche Ausgaben ein Cronjob erzeugt hat?

Diese beiden Fragen sind nicht einfach zu beantworten, denn jetzt können wir uns jeden Cronjob im Detail anschauen:

  • Wurde im Job pauschal stdout/stderr nach /dev/null umgeleitet?
  • Wird im Job vielleicht das Syslog bei Fehlern manuell benachrichtigt?
  • Ist die Mailadresse für diesen Job korrekt und konnte dorthin eine Mail zugestellt werden?
  • Ist ein MTA installiert und konfiguriert welcher sich um die Zustellung von Mails im Fehlerfall kümmern könnte?
Einige dieser Punkte sind global zu prüfen, andere sind für jedes Script einzeln zu prüfen. Um es kurz zu machen: Ohne einiges an Recherche wissen wir nicht was mit der Ausgabe und den Fehler von einem Cronjob etwas passiert, oder ob dies nicht einfach fälschlicherweise in /dev/null verschwindet.

In den Kommentaren stellte Christian die These auf das mein System falsch konfiguriert sei wenn /var/log voll laufen kann, dem ist und war nicht so. Ein manueller Lauf der Cronjobs und anschließendes Neustarten von crond hat dazu geführt, dass die Logfiles wieder rotiert wurden. Was wir aber weiter oben lesen durften, bestätigt auch die Erfahrungen von Michael (aus den Kommentaren) und mir: Cronjobs machen gerne mal schmerzen, sind schlecht zu kontrollieren und der gute alte Syslog ist dort keine große Hilfe. Die manuelle Suche nach dem Fehler ist mühsam und zeitaufwendig, außer man startet einfach aus Faulheit die Kiste oder irgendwelche Dienste ziellos neu, was ich aber nicht für zielführend halte.

Bei systemd sehe ich in Kombination von Timer Units und dem systemd Journal alle relevanten Informationen an einer Stelle. Genauso gibt es auch nur eine Stelle, welche sich um den Speicherplatzbedarf vom Journal kümmert. Und es werden auch keine Informationen über verschiedene Dateien verteilt oder sogar doppelt gespeichert. Und in der Praxis sieht das so aus:

[root@server ~]# systemctl list-timers
NEXT    LEFT          LAST    PASSED  UNIT                  ACTIVATES
… CEST  5h 41min left … CEST  18h ago man-db.timer          man-db.service
… CEST  5h 41min left … CEST  18h ago shadow.timer          shadow.service
… CEST  5h 41min left … CEST  18h ago updatedb.timer        updatedb.service
… CEST  7h left       … CEST  16h ago my-rdiff-backup.timer my-rdiff-backup.service

5 timers listed.
Pass --all to see loaded but inactive timers, too.
[root@server ~]# systemctl status my-rdiff-backup.timer
● my-rdiff-backup.timer - my-rdiff-backup Service Timer for Hanny/Nanny
   Loaded: loaded (/etc/systemd/system/my-rdiff-backup.timer; disabled)
   Active: active (waiting) since Thu 2014-05-01 10:02:17 CEST; 1 weeks 5 days ago

May 01 10:02:17 server systemd[1]: Starting my-rdiff-backup Service Timer for Hanny/Nanny.
May 01 10:02:17 server systemd[1]: Started my-rdiff-backup Service Timer for Hanny/Nanny.
[root@server ~]# systemctl status my-rdiff-backup.service
● my-rdiff-backup.service - My rdiff-backup for Hanny/Nanny
   Loaded: loaded (/etc/systemd/system/my-rdiff-backup.service; static)
   Active: inactive (dead) since Tue 2014-05-13 02:02:00 CEST; 16h ago
  Process: 8304 ExecStart=/usr/bin/rdiff-backup --meine-parameter (code=exited,
  status=0/SUCCESS)
 Main PID: 8304 (code=exited, status=0/SUCCESS)

May 13 02:00:00 server systemd[1]: Started My rdiff-backup for Hanny/Nanny.

Die Ausgaben habe ich etwas zensiert, um mein Layout nicht zu sprengen, aber es sind noch alle relevanten Informationen vorhanden: Wann lief der Job? Wann läuft er als Nächstes? Wann wurde der Job mit welchem Exit Status beendet?

Der einzige Nachteil, dass binäre Logfiles verwendet werden, kommt mir mittlerweile fast schon lächerlich vor. Das journal unterstützt mich nach anfänglicher Kritik bei der Arbeit, dass gleiche gilt für die Timer Units. Ich vermisse die Tools grep, tail und head in meinem /var/log nicht mehr.