Amavisd Fehler / Mail Warteschlange blockiert

[Ebi]

Guten morgen gen Tübingen!

Als ich heute morgen nach dem System Check sehen wollte war dieses nicht im entsprechenden Postfach. Ein Blick auf den Intranator zeigte dann, dass sich dort in der Mail-Warteschlange über 700 E-Mails angesammelt hatten, welche wegen Timeout bei der Verbindungsinitialisierung nicht gesendet werden konnten.

Ein Neustart vom Intranator hat das Problem dann behoben und auch das verschollene System Check kam dann irgendwann. Dort wurde dann ein Fehler zwischen den internen Mail-Diensten des Intranators ersichtlich. Hier das Log:

Jun 19 03:57:32 zhadum named[1744]: dispatch 0xa47a180: shutting down due to TCP receive error: 208.96.6.134#53: connection reset
Jun 19 03:57:32 zhadum named[1744]: dispatch 0xa5a12d8: shutting down due to TCP receive error: 208.96.6.134#53: connection reset
Jun 19 03:57:33 zhadum named[1744]: dispatch 0xa676a80: shutting down due to TCP receive error: 208.96.6.134#53: connection reset
Jun 19 04:00:15 zhadum amavis[20274]: Net::Server: 2008/06/19-04:00:15 Can't connect to TCP port 10024 on 127.0.0.1 [Address already in use]\n at line 86 in file /usr/lib/perl5/vendor_perl/5.8.8/Net/Server/Proto/TCP.pm
Jun 19 04:00:48 zhadum mon[2352]: failure for intranator amavisd 1213840848 (NO SUMMARY)
Jun 19 04:02:49 zhadum mon[2352]: calling alert restart_amavisd.alert for intranator/amavisd (/usr/lib/mon/alert.d/restart_amavisd.alert,) (NO SUMMARY)
Jun 19 04:02:49 zhadum mon[2352]: failure for intranator amavisd 1213840969 (NO SUMMARY)
Jun 19 04:02:51 zhadum amavisd: failed
Jun 19 04:02:54 zhadum amavisd: failed
Jun 19 04:02:58 zhadum amavis[20368]: Net::Server: 2008/06/19-04:02:57 Can't connect to TCP port 10024 on 127.0.0.1 [Address already in use]\n at line 86 in file /usr/lib/perl5/vendor_perl/5.8.8/Net/Server/Proto/TCP.pm
Jun 19 04:04:40 zhadum mon[2352]: calling alert restart_amavisd.alert for intranator/amavisd (/usr/lib/mon/alert.d/restart_amavisd.alert,) (NO SUMMARY)
Jun 19 04:04:40 zhadum mon[2352]: failure for intranator amavisd 1213841080 (NO SUMMARY)
Jun 19 04:04:43 zhadum amavisd: failed
Jun 19 04:04:45 zhadum amavisd: failed
Jun 19 04:04:49 zhadum amavis[20435]: Net::Server: 2008/06/19-04:04:49 Can't connect to TCP port 10024 on 127.0.0.1 [Address already in use]\n at line 86 in file /usr/lib/perl5/vendor_perl/5.8.8/Net/Server/Proto/TCP.pm
Jun 19 04:06:39 zhadum mon[2352]: calling alert restart_amavisd.alert for intranator/amavisd (/usr/lib/mon/alert.d/restart_amavisd.alert,) (NO SUMMARY)
Jun 19 04:06:39 zhadum mon[2352]: failure for intranator amavisd 1213841199 (NO SUMMARY)
Jun 19 04:06:42 zhadum amavisd: failed
Jun 19 04:06:44 zhadum amavisd: failed

So ging das dann bis zum Restart weiter. Was ist hier passiert? Ist das ein potentiell größeres Problem oder einmalige Ausnahme?

Liebe Grüße,
Jens Eberhardt

PS: Vielleicht war ja eine blockierte Warteschlange auch die Ursache für http://forum.intra2net.com/1333-system-check.html??

[Gerd von Egidy]

Hallo,

in dem Log-Ausschnitt erkennt das interne Überwachungssystem, daß der Email-Virenscanner nicht mehr reagiert und versucht ihn neu zu starten (das ist das "calling alert restart_amavisd"). Allerdings geht das schief, da die interne Adresse noch verwendet wird.

Vermutlich hat sich einer der Amavis-Prozesse so aufgehängt, daß er zwar noch die Adresse belegt hat, aber auf keinerlei Anfragen oder Beenden-Befehle mehr reagierte.

So etwas kann in sehr seltenen Fällen vorkommen. Dann hilft entweder ein Neustart des Intranators so wie Sie es gemacht haben oder ein manuelles Aufräumen und Neustarten der Amavis-Prozesse durch unseren Support.

Ihr System sollte nach dem Neustart wieder voll funktionsfähig sein, es sind keine weiteren Eingriffe nötig.

Herzliche Grüße,

v. Egidy

[Ebi]

Guten Morgen,

der Fehler ist bisher nicht wieder aufgetaucht - soweit, so gut. Allerdings taucht der "Security Violations"-Teil der besagten amavisd-Fehlermeldungen nun bei jedem Neustart des Intranators wieder im System Check auf (mit korrektem Datum 19. Juni). So gestern nun im Zuge des Neustarts beim Update gesehen und auch damals nach dem Neustart wg. des Problems beobachtet.

Auszug:

Jun 19 04:00:48 intranator mon[2352]: failure for intranator amavisd 1213840848 (NO SUMMARY)
Jun 19 04:02:49 intranator mon[2352]: failure for intranator amavisd 1213840969 (NO SUMMARY)
Jun 19 04:02:51 intranator amavisd: failed
Jun 19 04:02:54 intranator amavisd: failed

Was könnte hier schief laufen?

Liebe Grüße,
Jens Eberhardt

[Gerd von Egidy]

Hallo,

verstehe ich das richtig, daß jetzt jeden Morgen in dem Email-Report die Meldungen vom 19. Juni auftauchen, obwohl die dort eigentlich nur 1x, nämlich am 20. Juni, hätten auftauchen sollen?

Herzliche Grüße,

v. Egidy

[Ebi]

Das ist richtig. Allerdings auch nicht jeden Tag. Ich dachte erst, dass diese immer dann auftauchen, wenn ein Neustart des Systems durchgeführt wurde (wss bei den ersten beiden Malen auch korrekt war), allerdings habe ich diese im System Check vom 1. Juli auch wieder gefunden und hier wurde das System nicht neu gestartet.

Gerade noch aufgefallen - es tauchen ausserdem noch andere, vereinzelte Meldungen vom 23. und 24. Juni auf.

Liebe Grüße,
Jens Eberhardt

[Thomas Jarosch]

Hallo,

Zitat von Ebi

Das ist richtig. Allerdings auch nicht jeden Tag. Ich dachte erst, dass diese immer dann auftauchen, wenn ein Neustart des Systems durchgeführt wurde (wss bei den ersten beiden Malen auch korrekt war), allerdings habe ich diese im System Check vom 1. Juli auch wieder gefunden und hier wurde das System nicht neu gestartet.

Gerade noch aufgefallen - es tauchen ausserdem noch andere, vereinzelte Meldungen vom 23. und 24. Juni auf.

Des Rätsels Lösung finden Sie hier:
http://forum.intra2net.com/1372-fehl...ate-5-0-a.html

Herzliche Grüsse,
Thomas Jarosch