Fehler in der Logdatei mail! Ursachenforschung

G

gammla

Member
Hallo!
Ich bin gerade dabei jeden Fehler in meiner Logdatei zu verfolgen und wenn möglich zu beheben.
Leider bin ich an einen Punkt angekommen, der mir dies nicht mehr ermöglicht:


Hier mal ein Übersicht was zu diesem Zeitpunkt "auf" dem System passiert.
Ich habe xinetd neu gestartet! Steht aber vielleicht nur zufällig in diesem Zusammenhang!

Inhalt von System-Log (/var/log/messages)
Code: 
Apr 23 09:17:17 h1385133 xinetd[8529]: Reading included configuration file: /etc/xinetd.d/daytime-udp [file=/etc/xinetd.d/daytime-udp] [line=14]
Apr 23 09:17:17 h1385133 xinetd[8529]: Reading included configuration file: /etc/xinetd.d/daytime [file=/etc/xinetd.d/daytime] [line=16]
Apr 23 09:17:17 h1385133 xinetd[8529]: Reading included configuration file: /etc/xinetd.d/cvs [file=/etc/xinetd.d/cvs] [line=11]
Apr 23 09:17:17 h1385133 xinetd[8529]: Reading included configuration file: /etc/xinetd.d/cups-lpd [file=/etc/xinetd.d/cups-lpd] [line=15]
Apr 23 09:17:17 h1385133 xinetd[8529]: Reading included configuration file: /etc/xinetd.d/chargen-udp [file=/etc/xinetd.d/chargen-udp] [line=14]
Apr 23 09:17:17 h1385133 xinetd[8529]: Reading included configuration file: /etc/xinetd.d/chargen [file=/etc/xinetd.conf] [line=26]
Apr 23 09:17:12 h1385133 vsftpd: Wed Apr 23 09:17:12 2008 [pid 8511] CONNECT: Client "127.0.0.1"
Apr 23 09:17:08 h1385133 vsftpd: Wed Apr 23 09:17:08 2008 [pid 8057] CONNECT: Client "127.0.0.1"
Apr 23 09:17:03 h1385133 vsftpd: Wed Apr 23 09:17:03 2008 [pid 8045] CONNECT: Client "127.0.0.1"
Apr 23 09:16:53 h1385133 vsftpd: Wed Apr 23 09:16:53 2008 [pid 5620] CONNECT: Client "127.0.0.1"
Apr 23 09:16:40 h1385133 syslog-ng[2971]: STATS: dropped 0
Apr 23 09:16:39 h1385133 xinetd[3311]: Exiting...

Kurz vor den gleich angesprochenen Fehlern startet EXIM (Mein MTA) einen queue run, bei dem er nach der logfile nur frozen messages
feststellt. Nach meiner Information wird an dieser Stelle ja nichts "aufgetaut". Muss also auch nicht mit dem Problem zusammenhängen.

Inhalt von Exim Logfile (/var/log/exim/main.log)
Code: 
2008-04-23 09:16:45 End queue run: pid=5607
2008-04-23 09:16:45 1JoM2M-00075N-1f Message is frozen
2008-04-23 09:16:45 1JnzYS-0003ez-Dl Message is frozen
2008-04-23 09:16:45 1JoTLX-0007eV-8z Message is frozen
2008-04-23 09:16:45 Start queue run: pid=5607

Hier werden die Fehler protokolliert, die ich beheben möchte:
Inhalt von Mail Logfile (/var/log/mail)
Code: 
Apr 23 09:17:12 h1385133 spamd[3404]: prefork: child states: II
Apr 23 09:17:12 h1385133 spamd[3413]: spamd: bad protocol: header error: (closed before headers) at /usr/sbin/spamd line 1985.
Apr 23 09:17:12 h1385133 spamd[3413]: spamd: connection from localhost [127.0.0.1] at port 33014
Apr 23 09:17:12 h1385133 imapd-ssl: Unexpected SSL connection shutdown.
Apr 23 09:17:12 h1385133 imapd: Disconnected, ip=[::ffff:127.0.0.1], time=0
Apr 23 09:17:12 h1385133 imapd: Connection, ip=[::ffff:127.0.0.1]
Apr 23 09:17:12 h1385133 pop3d: Unexpected SSL connection shutdown.
Apr 23 09:17:12 h1385133 pop3d: Disconnected, ip=[::ffff:127.0.0.1]
Apr 23 09:17:12 h1385133 pop3d: Connection, ip=[::ffff:127.0.0.1]


Fehler 1:
Code: 
Apr 23 09:17:12 h1385133 pop3d: Unexpected SSL connection shutdown.

Fehler 2:
Code: 
Apr 23 09:17:12 h1385133 spamd[3413]: spamd: bad protocol: header error: (closed before headers) at /usr/sbin/spamd line 1985.

Zu Fehler 1:
Ist das überhaupt ein Fehler?
Sobald etwas "unerwartet" ist, ist es ja zumindest etwas, was nicht ganz normal ist!
Wenn ich mir die zwei Logeinträge zuvor anschaue,
Code: 
Apr 23 09:17:12 h1385133 pop3d: Disconnected, ip=[::ffff:127.0.0.1]
Apr 23 09:17:12 h1385133 pop3d: Connection, ip=[::ffff:127.0.0.1]
machte es den Eindruck, dass der Server (127.0.0.1) versucht eine Verbindung aufzubauen. Schafft es aber nicht, da es eine "Unexpected SSL connection" ist.

Falls dies "Unexpected SSL connection" nicht mit dem vorherigen Verbindungsversuch zusammenhängt, bin ich ahnungslos!
Auffällig ist aber, dass es sich hierbei um eine IPv6 ([::ffff:127.0.0.1]) handelt. Vielleicht ist dem pop3d und dem imapd diese "Art" nicht bekannt.

In welche Richtung, kann ich hier weiterforschen?


Zu Fehler 2:
Spamassassin funktionert soweit fehlerfrei. Die Emails werden ohne Probleme durchgereicht und als Spam oder nicht Spam markiert!
Zumindest schränkt dieser "Fehler" nicht die Funktion ein. Mich würde trotzdem interessieren, was da abläuft.

Zu diesem Problem kann ich über Google folgendes finden:

Überwachung ist gut, wenn man sie denn kontrolliert
Munin ist eine gute Möglichkeit Trends von verschiedenen Werten abzugeben. Was aber, wenn es mal schnell gehen muss? Für die einfache Überwachung von Prozessen, Dateien, Verzeichnissen oder Devices bietet sich monit an. So überwache ich auf meinem Server z.B. u.a. meinen Apache, Exim, ClamAV und auch SpamAssassin.

Allerdings hat sich herausgestellt, dass das Monitoring von meinem SpamAssassin ein wenig für Ärger sorgen kann. Sollte man monit einsetzen und folgende Zeilen in seinem /var/log/spamd.log sehen, dann ist u.U. monit bzw. dessen Fehlkonfiguration schuld.

Tue Jan 1 20:24:12 2008 [6906] info: spamd: connection from localhost [127.0.0.1] at port 4366
Tue Jan 1 20:24:12 2008 [6906] warn: spamd: bad protocol: header error: (closed before headers) at /usr/sbin/spamd line 1985.
Tue Jan 1 20:24:12 2008 [6897] info: prefork: child states: II

Passiert ist mir dies beim Versuch SpamAssassin über den Port 783 zu monitoren. Das sorgt dann brav dafür, dass sich das Logfile rasch mit nervigen und unnötigen Meldungen aufbläht.
Click to expand...
Quelle:
http://blog.sinnwidrig.org/2008/01/03/uberwachung-ist-gut-wenn-man-sie-denn-kontrolliert/

Hier wird gesagt, dass "monit" und dessen Fehlkonfiguration daran schuld sei!
monit ist laut Yast bei mir nicht installiert.
Auch eine Suche nach monit bringt keinen Erfolg. (-> ist ja auch nicht installiert)

Es könnte doch auch gut möglich sein, dass ein anderes Monitoring-Programm den "gleichen" Fehler wie monit erzeugt.
Vielleicht muss man auch in einer ganz anderen Richtung suchen!
Vielleicht steht es auch in direktem Zusammenhang mit dem eventuellen IPv6 Problem?

Es wird ja angegeben, dass der Fehler in Zeil 1985 auftrat.
Hier ein Auszug:

Code: 
sub protocol_error {
  my ($err) = @_;
  my $resp = "EX_PROTOCOL";
  syswrite($client, "SPAMD/1.0 $resphash{$resp} Bad header line: $err\r\n");
  warn("spamd: bad protocol: header error: $err");
}

Das scheint die Funktion zur Fehlerausgabe zu sin. Wenn man jetzt nur noch wüsste, wer sie aufruft....?


Vielleicht könnt ihr ein wenig Licht in Dunkle bringen!

Gruß,

Gammla
 
Last edited by a moderator:
gammla said:
Inhalt von Exim Logfile (/var/log/exim/main.log)
Code: 
2008-04-23 09:16:45 End queue run: pid=5607
2008-04-23 09:16:45 1JoM2M-00075N-1f Message is frozen
2008-04-23 09:16:45 1JnzYS-0003ez-Dl Message is frozen
2008-04-23 09:16:45 1JoTLX-0007eV-8z Message is frozen
2008-04-23 09:16:45 Start queue run: pid=5607
Click to expand...
Suche in dem Log nach den Message-IDs. Dann findest du auch den Grund, warum die Mails noch in der Queue hängen.

gammla said:
Zu Fehler 1:
Ist das überhaupt ein Fehler?
Click to expand...
Nein.

gammla said:
Wenn ich mir die zwei Logeinträge zuvor anschaue,
Code: 
Apr 23 09:17:12 h1385133 pop3d: Disconnected, ip=[::ffff:127.0.0.1]
Apr 23 09:17:12 h1385133 pop3d: Connection, ip=[::ffff:127.0.0.1]
machte es den Eindruck, dass der Server (127.0.0.1) versucht eine Verbindung aufzubauen. Schafft es aber nicht, da es eine "Unexpected SSL connection" ist.
Click to expand...
Bitte lies die Fehlermeldung komplett. Da steht nicht "Unexpected SSL connection", sondern "Unexpected SSL connection shutdown". Der Client hat einfach die Verbindung beendet, ohne auf Wiedersehen zu sagen.

gammla said:
Zu Fehler 2:
Spamassassin funktionert soweit fehlerfrei. Die Emails werden ohne Probleme durchgereicht und als Spam oder nicht Spam markiert!
Zumindest schränkt dieser "Fehler" nicht die Funktion ein. Mich würde trotzdem interessieren, was da abläuft.
Click to expand...
Steht doch klipp und klar in der Logmeldung: Es gab einen Verbindungsaufbau (in deinem Fall wohl durch monit). Die Verbindung wurde danach gleich wieder beendet, ohne entsprechende Header zu senden.

gammla said:
monit ist laut Yast bei mir nicht installiert.
Click to expand...
Irgendein Prozess greift jedenfalls von localhost aus auf deinen SpamAssassin zu.

gammla said:
Es könnte doch auch gut möglich sein, dass ein anderes Monitoring-Programm den "gleichen" Fehler wie monit erzeugt.
Click to expand...
Ja.

gammla said:
Vielleicht steht es auch in direktem Zusammenhang mit dem eventuellen IPv6 Problem?
Click to expand...
Nein.
 
Wenn einige Prozesse "unerwartet" sterben wenn gerade Last erzeugt wird (--> exim queue-run) würde ich mal als erstes mal nachschauen, ob ein Ressourcen-Problem vorhanden ist.
 
Hallo!
Habe mal einen q-run manuell gestartet:
Code: 
exim -q -v
LOG: queue_run MAIN
  Start queue run: pid=14403
delivering 1JoTLX-0007eV-8z (queue run pid 14403)
LOG: skip_delivery MAIN
  Message is frozen
delivering 1JoM2M-00075N-1f (queue run pid 14403)
LOG: skip_delivery MAIN
  Message is frozen
delivering 1JnzYS-0003ez-Dl (queue run pid 14403)
LOG: skip_delivery MAIN
  Message is frozen
delivering 1JodwE-0003iW-Df (queue run pid 14403)
LOG: skip_delivery MAIN
  Message is frozen
LOG: queue_run MAIN
  End queue run: pid=14403

bzw.:
Code: 
2008-04-23 14:25:32 End queue run: pid=14403
2008-04-23 14:25:32 1JodwE-0003iW-Df Message is frozen
2008-04-23 14:25:32 1JnzYS-0003ez-Dl Message is frozen
2008-04-23 14:25:32 1JoM2M-00075N-1f Message is frozen
2008-04-23 14:25:32 1JoTLX-0007eV-8z Message is frozen
2008-04-23 14:25:32 Start queue run: pid=14403

Hierbei handelt es sich um Mails, die an root nicht zugestellt werden können. Das ist aber eine andere Baustelle.
Betrachten wir nochmals, ob Prozesse "unerwartet" sterben.
Zu der Zeit 14.25.32 taucht in keiner Logdatei eine ungewöhnlichkeit auf.

Ich hoffe, dass ich keine Ressoucen-Problem habe. Das wäre ärgerlich.
Hier die Ausgabe von free:

Code: 
             total       used       free     shared    buffers     cached
Mem:        515072     424576      90496          0      52444     146284
-/+ buffers/cache:     225848     289224
Swap:      2104496      14180    2090316

Das sieht so aus, als wäre noch reichlich frei (289224)!

So, fassen wir nochmal alles kurz zusammen:

Ein Ressourcen-Problem scheint es nicht zu sein.


Zu dem Clienten, der die Verbindung nicht richtig beendet:
Das Microsoft Outlook solche Sachen oft bzw. teilweise nicht richtig macht, ist wohl bekannt. Diese Information habe ich bei Google gefunden.

Da es sich hier aber um einen "internen" Client (127.0.0.1) handelt macht mir das schon ein wenig Sorgen. Wer greift denn da auf Spamassassin zu?

Wie kann ich das herausfinden?

Nun sehe ich noch ein Problem. xinetd scheint wohl irgendwie ein Problem zu haben:
Code: 
Apr 23 14:23:35 h1385133 xinetd[14383]: warning: can't get client address: Transport endpoint is not connected
Apr 23 14:20:01 h1385133 /usr/sbin/cron[14297]: (root) CMD (/usr/local/sa24/sa24d3/sa24d3 --server-stats >>/dev/null 2>&1)
Apr 23 14:16:42 h1385133 xinetd[14283]: warning: can't get client address: Transport endpoint is not connected
Apr 23 14:16:42 h1385133 syslog-ng[2971]: STATS: dropped 0
Apr 23 14:15:01 h1385133 /usr/sbin/cron[14227]: (root) CMD (/usr/local/sa24/sa24d3/sa24d3 --server-stats >>/dev/null 2>&1)

Was könnte dafür die Ursache sein?

Gruß,

Gammla
 
You must log in or register to reply here.
Back
Top