Postfix, Amavis und ClamAV extrem langsam

Seit kurzer Zeit dauerte es länger und länger, bis Postfix eingehende Mails an Dovecot ausliefert. Am Ende stellte sich das als einfaches Rechteproblem heraus: ClamAV konnte nicht die von Amavis erzeugten Dateien lesen, und rannte offensichtlich für jeden einzelnen Zustellungsversuch in einen Timeout.

Tatsächlich trugen mehrere - zugegebenermaßen dämliche - Fehler mehr oder weniger zum Gesamtproblem bei.

ClamAV war nicht in der Amavis-Gruppe

Das größte Problem war, dass clamd die von Amavis erzeugten Dateien nicht lesen konnte. In den Logfiles tauchten deshalb solche Meldungen auf:

Dec  2 17:36:30 mail amavis[10284]: (10284-01) (!)run_av (ClamAV-clamd) FAILED - unexpected , output="/var/amavis/tmp/amavis-20191202T173630-10284-9LpO_9G2/parts: lstat() failed: Permission denied. ERROR\n"
Dec  2 17:36:30 mail amavis[10284]: (10284-01) (!)ClamAV-clamd av-scanner FAILED: CODE(0x55c9fd7d88c0) unexpected , output="/var/amavis/tmp/amavis-20191202T173630-10284-9LpO_9G2/parts: lstat() failed: Permission denied. ERROR\n" at (eval 85) line 950.

Auf unserem Server läuft amavisd-new als Benutzer amavis in der Gruppe amavis, während clamd als Benutzer clamav in der Gruppe clamav läuft. Nachdem der User clamav der Gruppe amavis zugefügt war, war das Problem vollständig behoben. Statt zwei Minuten pro Mail, lief der Virus-Scan] jetzt wieder in Bruchteilen einer Sekunde durch.

"All Primary Virus Scanners Failed"

Eine weitere Meldung, die ich eigentlich schon öfters gesehen, aus Faulheit aber immer ignoriert hatte, war folgende:

Dec  2 17:36:30 mail amavis[10284]: (10284-01) (!)WARN: all primary virus scanners failed, considering backups

Es stellte sich heraus, dass ich bei irgendeinem Upgrade eine lokale Modifikation an der Konfigurationsdatei /etc/amavid.conf versäumt hatte. Die Datei definiert ein Array @av_scanners mit Kandidaten für alle möglichen kommerziellen(?) Virus-Scanner. Das frei verfügbare ClamAV war indes auskommentiert.

Die Fehlermeldung bedeutet, dass amavisd-new alle Kandidaten erfolglos durchprobiert hat, was nicht überrascht, weil kein einziger davon installiert war. Die Meldung verschwand, nachdem der Eintrag für ClamAV wieder aktiviert war:

@av_scanners = (
...
['ClamAV-clamd',
\&ask_daemon, ["CONTSCAN {}\n", "/var/run/clamav/clamd.sock"],
qr/\bOK$/m, qr/\bFOUND$/m,
qr/^.*?: (?!Infected Archive)(.*) FOUND$/m ],
...
);

Der Pfad zur ClamAV-Socketdatei (/var/run/clamav/clamd.sock) muss natürlich korrekt sein. Im Zweifelsfall überprüft man die Variable LocalSocket in /etc/clamd.conf:

...
LocalSocket /var/run/clamav/clamd.sock
...

Zugegebenermaßen weiß ich nicht, wie problematisch die Meldung "all primary virus scanners failed" tatsächlich ist. Sie tritt jedenfalls nicht mehr auf.

Zu viele nicht zustellbare Mails

Die oben geschilderten Probleme waren vermutlich schon älter, fielen aber nicht weiter auf, weil wir eine relativ kleine Organisation, in der Zustellzeiten von zwei Minuten per Mail nicht direkt auffallen. Das änderte sich erst, als ein Cronjob plötzlich nicht mehr funktioniert.

Unglücklicherweise war der Benutzer, unter dem der Cronjob lief, nicht dafür konfiguriert, Mails zu empfangen. Postfix steckte sie deshalb alle für die Voreinstellung von fünf Tagen in die Warteschlange, und versuchte regelmäßig eine erneute Zustellung. Die normalen Mails gingen nun in den Unmengen von Cron-Fehler-Mails unter, und die Zustellung dauerte plötzlich mehr als einen Tag.

Es ist deshalb wichtig sicherzustellen, dass alle User, die Cronjobs konfigurieren dürfen, auch Mails empfangen können, entweder mit einem Alias oder einem Eintrag im Virtual Table von Postfix.

Tatsächlich gibt es viele Gruünde, weshalb Mails tagelang in der Warteschlange von Postfix hängen können, bis sie endlich bouncen, und darum ist es eine gute Idee, regelmäßig mailq auszuführen, um zu sehen, ob die Mailqueue ungewöhnlich voll ist.