Sporadische Probleme mit milter-reject

sTeaLth · 4. Januar 2022

Hallo Community,
ich habe heute nun zum zweiten mal in einer Woche das Problem, dass mein Postfix keine Mail mehr annimmt und folgende Meldung ausgibt:

Code

postfix/cleanup[23307]: 4JSgh638dhzFjRJ: milter-reject: END-OF-MESSAGE from host.domain.tld[A.B.C.D]: 4.7.1 Service unavailable - try again later; from=<abc@sender.tld> to=<xyz@recipient.tld> proto=ESMTP helo=<host.domain.tld>

Beim ersten mal habe ich zuerst das System neu gestartet, hat aber nichts geändert.
Dann habe ich festgestellt, dass der clamav-milter nicht gestartet war (trotz reboot). Also gestartet -> alles wieder ok.

Als das Problem aber heute nochmals aufgetreten ist, lief der clamav-milter. Auch ein Neustart des Servers/Dienstes hat an der Situation nichts geändert.
Da es beim ersten mal am ClamAV lag, habe ich diesen temporär deaktiviert, damit ich meine wichtige Mail erhalten hab und diesen dann wieder aktiviert. Und schwups war das Problem weg.

Die eigentlichen Frage ist aber: Wie kann ich das Problem fassen / debuggen?
So ein willkürliches Problem kann man ja nicht gebrauchen.

Systeminfos:

Code

Ubuntu 18.04
Postfix 3.3.0 (3.3.0-1ubuntu0.4)
ClamAV (0.103.2+dfsg-0ubuntu0.18.04.2)
SpamAssassin (3.4.2-0ubuntu0.18.04.5)
OpenDKIM (2.11.0~alpha-11b)

Danke für alle Ratschläge.

sTeaLth · 4. Januar 2022

Ohje, sehe gerade das hier 2018 schonmal jemand das Problem geschildert hat.

Zitat von fpschm

Hallo,

wir haben nun leider schon seit einigen Wochen das Problem, dass auf unserem Server bei eingeschaltetem ClamAV der Versand von Emails mit der Fehlermeldung "4.7.1 Service unavailable" fehlschlägt.
Im mail.log findet sich dazu dann dieser Eintrag:
[...]hosting postfix/cleanup[14048]: 903C2139611F: milter-reject: END-OF-MESSAGE from xxx: 4.7.1 Service unavailable - try again later[...]

Deaktivieren wir den ClamAV, werden die Emails wieder normal versendet.
Unsere LiveConfig Version ist: 2.5.3 Revision: 4805.
ClamAV Version ist nun ClamAV 0.99.3/24350
Das Problem trat in der vorhergehenden ClamAV Version bereits auf. Nachdem dann die Version 0.99.3 verfügbar wurde haben wir ein Upgrade durchgeführt, jedoch änderte sich das Problem dadurch nicht.

Hat jemand dasselbe Problem? Oder konnte es bereits jemand lösen?

Alles anzeigen

und auch eine Antwort von kk bekommen hat.

Zitat von kk

"Service unavailable" bedeutet in dem Zusammenhang meistens, dass der Prozess "clamd" (bzw. "clamav-daemon") nicht läuft.
Warum der nicht mehr läuft (bzw. seinen Dienst eingestellt hat) lässt sich eventuell über die einschlägigen Log-Dateien herausfinden.

Kürzlich gab es einen kritischen Bug im ClamAV-Daemon, über den man mit einer einzigen (präparierten) E-Mail den ClamAV abstürzen lassen konnte. Inzwischen stehen aktualisierte Debian-/Ubuntu-Pakete dafür bereit, die aber i.d.R. nur über das "updates"-Repository installiert werden (nicht über "security").

Viele Grüße

-Klaus Keppler

Alles anzeigen

https://www.liveconfig.com/de/…-7-1-Service-unavailable)

kk Den "kritischen Bug" aus 2018 der den ClamAV zum Absturz bringt können wir wohl ausschließen, außer es gab aktuell wieder einen.
Evtl. kann mein Post aber dann weg und ich Antworte / Frage unter dem alten Thread nochmal!?!?

suppenuser · 10. Januar 2022

Zitat von sTeaLth

Ohje, sehe gerade das hier 2018 schonmal jemand das Problem geschildert hat.

kk Den "kritischen Bug" aus 2018 der den ClamAV zum Absturz bringt können wir wohl ausschließen, außer es gab aktuell wieder einen.
Evtl. kann mein Post aber dann weg und ich Antworte / Frage unter dem alten Thread nochmal!?!?

Schau mal im Log nach sowas wie "ERROR: Timed out while reading clamd reply"

Wenn die Datenbanken von ClamAV nicht sauber geladen wurden (z.B. ein File korrupt) dann knallt der milter an die Wand.
Ist im Regelfall (sofern man auch den Milter restartet) beim nächsten Update der Daten dann auch erledigt.

Gruß Ralf

antondollmaier · 10. Januar 2022

Code

# /etc/systemd/system/clamav-daemon.service.d/clamav_restart.conf
[Service]
Restart=always

Danach ein "systemctl daemon-reload; systemctl restart clamav-daemon" und clamav wird automatisch neu gestartet.

it-worker · 11. April 2023

Bei mir tritt seit Februar exakt dasselbe Problem auf (Debian 11). Das Problem scheint immer kurz nach dem Update der Virendatenbank aufzutreten.
Ich habe lediglich clamav installiert und in LiveConfig den Haken rein gemacht.

Es kommt dann immer die "milter-reject: END-OF-MESSAGE from" Meldung in mail.log und Postfix versendet keine E-mails und empfängt auch keine. In den clamav-Logfiles kommt:

1) clamav.log:
Tue Apr 11 08:34:25 2023 -> SelfCheck: Database status OK.
Tue Apr 11 09:34:39 2023 -> SelfCheck: Database status OK.
Tue Apr 11 10:02:05 2023 -> Reading databases from /var/lib/clamav
Tue Apr 11 10:02:58 2023 -> Database correctly reloaded (8661648 signatures)
Tue Apr 11 10:02:58 2023 -> Activating the newly loaded database...
Tue Apr 11 10:34:31 2023 -> Client disconnected (FD 9)
Tue Apr 11 10:34:31 2023 -> Client disconnected (FD 10)
Tue Apr 11 10:34:31 2023 -> Client disconnected (FD 11)
Tue Apr 11 10:34:31 2023 -> Client disconnected (FD 12)

2) clamav-milter.log:
Tue Apr 11 10:05:06 2023 -> ERROR: Timed out while reading clamd reply
Tue Apr 11 10:05:06 2023 -> ERROR: No reply from clamd
Tue Apr 11 10:05:16 2023 -> ERROR: Timed out while reading clamd reply
Tue Apr 11 10:05:16 2023 -> ERROR: No reply from clamd
Tue Apr 11 10:05:36 2023 -> ERROR: Timed out while reading clamd reply
Tue Apr 11 10:05:36 2023 -> ERROR: No reply from clamd

ein wenig später folgt:
Tue Apr 11 10:15:53 2023 -> ERROR: Failed to initiate streaming/fdpassing
Tue Apr 11 10:15:53 2023 -> WARNING: No clamd server appears to be available
Tue Apr 11 10:15:58 2023 -> ERROR: Failed to initiate streaming/fdpassing
Tue Apr 11 10:15:58 2023 -> WARNING: No clamd server appears to be available
Tue Apr 11 10:15:59 2023 -> ERROR: Failed to initiate streaming/fdpassing

3) freshclam.log:
Tue Apr 11 10:01:36 2023 -> daily database available for update (local version: 26871, remote version: 26872)
Tue Apr 11 10:01:50 2023 -> Testing database: '/var/lib/clamav/tmp.e5d96d1992/clamav-b8b9027196e7c225d606da08a47c5692.tmp-daily.cld' ...
Tue Apr 11 10:02:04 2023 -> Database test passed.
Tue Apr 11 10:02:04 2023 -> daily.cld updated (version: 26872, sigs: 2029730, f-level: 90, builder: raynman)
Tue Apr 11 10:02:04 2023 -> main.cvd database is up-to-date (version: 62, sigs: 6647427, f-level: 90, builder: sigmgr)
Tue Apr 11 10:02:04 2023 -> bytecode.cld database is up-to-date (version: 334, sigs: 91, f-level: 90, builder: anvilleg)
Tue Apr 11 10:02:05 2023 -> Clamd successfully notified about the update.
Tue Apr 11 10:02:05 2023 -> --------------------------------------
Tue Apr 11 11:02:05 2023 -> Received signal: wake up
Tue Apr 11 11:02:05 2023 -> ClamAV update process started at Tue Apr 11 11:02:05 2023
Tue Apr 11 11:02:05 2023 -> daily.cld database is up-to-date (version: 26872, sigs: 2029730, f-level: 90, builder: raynman)
Tue Apr 11 11:02:05 2023 -> main.cvd database is up-to-date (version: 62, sigs: 6647427, f-level: 90, builder: sigmgr)
Tue Apr 11 11:02:05 2023 -> bytecode.cld database is up-to-date (version: 334, sigs: 91, f-level: 90, builder: anvilleg)
Tue Apr 11 11:02:05 2023 -> --------------------------------------
Tue Apr 11 12:02:05 2023 -> Received signal: wake up
Tue Apr 11 12:02:05 2023 -> ClamAV update process started at Tue Apr 11 12:02:05 2023

Das sind meine Konfigurationen:

1) clamd.conf:
LocalSocket /var/run/clamav/clamd.ctl
FixStaleSocket true
LocalSocketGroup clamav
LocalSocketMode 666
# TemporaryDirectory is not set to its default /tmp here to make overriding
# the default with environment variables TMPDIR/TMP/TEMP possible
User clamav
ScanMail true
ScanArchive true
ArchiveBlockEncrypted false
MaxDirectoryRecursion 15
FollowDirectorySymlinks false
FollowFileSymlinks false
ReadTimeout 180
MaxThreads 12
MaxConnectionQueueLength 15
LogSyslog false
LogRotate true
LogFacility LOG_LOCAL6
LogClean false
LogVerbose true
PreludeEnable no
PreludeAnalyzerName ClamAV
DatabaseDirectory /var/lib/clamav
OfficialDatabaseOnly false
SelfCheck 3600
Foreground false
Debug false
ScanPE true
MaxEmbeddedPE 10M
ScanOLE2 true
ScanPDF true
ScanHTML true
MaxHTMLNormalize 10M
MaxHTMLNoTags 2M
MaxScriptNormalize 5M
MaxZipTypeRcg 1M
ScanSWF true
ExitOnOOM false
LeaveTemporaryFiles false
AlgorithmicDetection true
ScanELF true
IdleTimeout 30
CrossFilesystems true
PhishingSignatures true
PhishingScanURLs true
PhishingAlwaysBlockSSLMismatch false
PhishingAlwaysBlockCloak false
PartitionIntersection false
DetectPUA false
ScanPartialMessages false
HeuristicScanPrecedence false
StructuredDataDetection false
CommandReadTimeout 30
SendBufTimeout 200
MaxQueue 100
ExtendedDetectionInfo true
OLE2BlockMacros false
AllowAllMatchScan true
ForceToDisk false
DisableCertCheck false
DisableCache false
MaxScanTime 120000
MaxScanSize 100M
MaxFileSize 25M
MaxRecursion 16
MaxFiles 10000
MaxPartitions 50
MaxIconsPE 100
PCREMatchLimit 10000
PCRERecMatchLimit 5000
PCREMaxFileSize 25M
ScanXMLDOCS true
ScanHWP3 true
MaxRecHWP3 16
StreamMaxLength 25M
LogFile /var/log/clamav/clamav.log
LogTime true
LogFileUnlock false
LogFileMaxSize 0
Bytecode true
BytecodeSecurity TrustSigned
BytecodeTimeout 60000
OnAccessMaxFileSize 5M
ConcurrentDatabaseReload yes

2) clamav-milter.conf:
MilterSocket /var/run/clamav/clamav-milter.ctl
FixStaleSocket true
User clamav
ReadTimeout 120
Foreground false
PidFile /var/run/clamav/clamav-milter.pid
ClamdSocket unix:/var/run/clamav/clamd.ctl
OnClean Accept
OnInfected Reject
OnFail Defer
AddHeader Replace
LogSyslog false
LogFacility LOG_LOCAL6
LogVerbose false
LogInfected Off
LogClean Off
LogRotate true
MaxFileSize 25M
SupportMultipleRecipients false
TemporaryDirectory /tmp
LogFile /var/log/clamav/clamav-milter.log
LogTime true
LogFileUnlock false
LogFileMaxSize 1M
MilterSocketGroup clamav
MilterSocketMode 666
RejectMsg Rejecting harmful email: %v found.

3) freshclam.conf:
DatabaseOwner clamav
UpdateLogFile /var/log/clamav/freshclam.log
LogVerbose false
LogSyslog false
LogFacility LOG_LOCAL6
LogFileMaxSize 0
LogRotate true
LogTime true
Foreground false
Debug false
MaxAttempts 5
DatabaseDirectory /var/lib/clamav
DNSDatabaseInfo current.cvd.clamav.net
ConnectTimeout 30
ReceiveTimeout 0
TestDatabases yes
ScriptedUpdates yes
CompressLocalDatabase no
Bytecode true
NotifyClamd /etc/clamav/clamd.conf
# Check for new database 24 times a day
Checks 24
DatabaseMirror db.local.clamav.net
DatabaseMirror database.clamav.net

Hat irgendwer eine Idee wie man das Problem in den Griff bekommt? So ist das nicht benutzbar. Mal ist der Mailserver für 0,5h weg, mal für 5-6h. Mit dem Monitoring bemerkt man das nicht, weil der Dienst ja verfügbar ist.

Vielen Dank schon mal!

Sven_67 · 11. April 2023

Das Problem hatte ich auch schon, lag bei mir am Greylisting.

Greylisting deaktiviert, lief wieder alles normal.

it-worker · 12. April 2023

Hallo Sven,
Ja, die milter_reject Meldung im mail.log erscheint natürlich bei Aussetzern sämtlicher Milter. Bei mir ist es klar der Clamav, und das nur kurz nach dem Downloaden neuer Virendaten. Mal eine halbe Stunde, mal Stunden. Greylisting funktioniert bei mir. Wenn ich hingegen Clamav deaktiviere in LiveConfig, läuft ebenso alles. Also bei mir ist es exakt so wie im Eingangsposting beschrieben.
Wenn irgendwer eine Lösung hätte, wäre ich sehr verbunden. Aktuelle Updates sind natürlich eingespielt...

Sven_67 · 15. April 2023

IT-Worker, läuft bei dir der Spamassassin?

it-worker · 16. April 2023

Zitat von Sven_67

IT-Worker, läuft bei dir der Spamassassin?

Ja, der läuft gut. Es kommen auch die Fehler nur in den clamav-logs (und natürlich im mail.log - Ausschnitte aus den Logs siehe oben). Aber leider nicht mit dem Hinweis woran es liegt dass Clamav nicht verfügbar ist Wenn ich Clamav ausschalte in LiveConfig läuft auch alles einwandfrei. Auch wenn Spamassassin, Blacklists, Greylisting und DKIM eingeschaltet sind in LiveConfig.
In der /var/run ist clamav übrigens vorhanden. Es scheitert nur bei den Updates bzw. kurz danach. Aber ich finde nicht heraus was genau schief läuft.

Ich habe es schon mit "ConcurrentDatabaseReload yes" und "no" versucht, ob das einen Unterschied macht, aber das ändert leider gar nichts. Damit bin ich leider völlig ratlos und habe jetzt kurzerhand Clamav mal deaktiviert, um weitere Ausfälle zu vermeiden. Aber Dauerzustand kann das natürlich auch nicht sein.

kk · 17. April 2023

Wie viel RAM hat denn der betroffene Server?

it-worker · 17. April 2023

Zitat von kk

Wie viel RAM hat denn der betroffene Server?

8GB Ram, 4GB Swap.
In der kern.log finde ich um den Updatezeitpunkt (also wenn das Problem auftaucht) keinerlei Hinweise darauf dass der Maschine das Ram ausgehen würde.

Und sonst läuft Clamav ja auch. Nur nach den Updates treten zeitweise diese Probleme auf.

Meine Erfahrungen mit zu wenig Ram bei Clamav ist, dass dann auch die ctl-Datei in der /var/run/clamav/ nicht geschrieben wird. Die gibt es aber. Aber ich könnte jetzt nicht sagen, ob bei zu wenig Ram auch entsprechende log-Einträge in den clamav-Logs und in der kern.log erscheinen. Aber davon wäre eigentlich auszugehen, oder?

Jetzt mitmachen!