Postfix Verständnisfrage

[sombrero2007]

Hi @all,

ich hab ein Prob mit meinen Postfix Server. Alle Mails werden rausgeschickt und ausgeliefert. Aber ab und an werden die Mails verzögert raus geschickt (ca. 30 min Verspätung).

In den Logs habe ich mir mal den Versand einer dieser Verspäteten Mails angeschaut und folgendes gefunden:

status=sent (250 Message received and queued)

Bei den Mails die sofort rausgegangen sind, stand dann folgendes

status=sent (delivered to mailbox)

Weiß jemand warum beim einen queued und bei anderen elivered to mailbox steht? Kann das mein Problem sein, wenn ja wie kann ich es lösen?

[dr.disk]

Das ist zuwenig vom Log. Da steht nur, dass der andere Server/das andere Modul die Mail angenommen hat. In Klammer kannst die Statusmeldung welche der Andere abgesetzt hast noch lesen.

Wie schon gesagt, dass ist viel zu wenig Log um irgendwelche Aussagen machen zu können.

[sombrero2007]

Ok, dann poste ich mal etwas mehr

Jul 25 09:04:14 linux-system postfix/pickup[14390]: 00C5AC61B2: uid=30 from=<wwwrun>

Jul 25 09:04:14 linux-system postfix/cleanup[21144]: 00C5AC61B2: message-id=<20070725070413.00C5AC61B2@domain.name.de>

Jul 25 09:04:14 linux-system postfix/qmgr[30874]: 00C5AC61B2: from=<wwwrun@domain.name.de>, size=4225, nrcpt=1 (queue active)

Jul 25 09:04:14 linux-system postfix/smtp[21152]: 7FC65C61ED: to=<0171555885569@sms.debitel.com>, relay=mail11.dmz.domain.name.de[10.206.156.15], delay=2, status=sent (250 Message received and queued)

Jul 25 09:04:14 linux-system postfix/qmgr[30874]: 7FC65C61ED: removed

Jul 25 09:04:14 linux-system postfix/pickup[14390]: 082BCC61B3: uid=30 from=<wwwrun>

Jul 25 09:04:14 linux-system postfix/cleanup[21150]: 082BCC61B3: message-id=<20070725070414.082BCC61B3@domain.name.de>

Jul 25 09:04:14 linux-system postfix/qmgr[30874]: 082BCC61B3: from=<wwwrun@domain.name.de>, size=446, nrcpt=1 (queue active)

Jul 25 09:04:14 linux-system postfix/pickup[14390]: 1469FC61ED: uid=30 from=<wwwrun>

Jul 25 09:04:14 linux-system postfix/cleanup[21144]: 1469FC61ED: message-id=<20070725070414.1469FC61ED@domain.name.de>

Jul 25 09:04:14 linux-system postfix/smtp[21155]: 7899FC61D9: to=<name.nachname@domain.name.de>, relay=mail11.dmz.domain.name.de[10.206.156.15], delay=2, status=sent (250 Message received and queued)

Jul 25 09:04:14 linux-system postfix/smtp[21251]: ABC13C61F2: host mail11.dmz.domain.name.de[10.206.156.15] refused to talk to me: 421 Service not available, closing transmission channel

Jul 25 09:04:14 linux-system postfix/qmgr[30874]: 7899FC61D9: removed

Jul 25 09:04:14 linux-system postfix/qmgr[30874]: 1469FC61ED: from=<wwwrun@domain.name.de>, size=4230, nrcpt=1 (queue active)

Jul 25 09:04:14 linux-system postfix/pickup[14390]: 2019FC6195: uid=30 from=<wwwrun>

Jul 25 09:04:14 linux-system postfix/cleanup[21150]: 2019FC6195: message-id=<20070725070414.2019FC6195@domain.name.de>

Jul 25 09:04:14 linux-system postfix/smtp[21261]: 91131C61EF: to=<01759885569@t-mobile-sms.de>, relay=mail11.dmz.domain.name.de[10.206.156.15], delay=2, status=sent (250 Message received and queued)

Jul 25 09:04:14 linux-system postfix/qmgr[30874]: 91131C61EF: removed

Jul 25 09:04:14 linux-system postfix/smtp[21244]: A2031C6178: to=<017599999999@t-mobile-sms.de>, relay=mail11.dmz.domain.name.de[10.206.156.15], delay=2, status=sent (250 Message received and queued)

Jul 25 09:04:14 linux-system postfix/qmgr[30874]: A2031C6178: removed

Jul 25 09:04:14 linux-system postfix/qmgr[30874]: 2019FC6195: from=<wwwrun@domain.name.de>, size=4232, nrcpt=1 (queue active)

Jul 25 09:04:14 linux-system postfix/pickup[14390]: 29E33C61D9: uid=30 from=<wwwrun>

Jul 25 09:04:14 linux-system postfix/cleanup[21144]: 29E33C61D9: message-id=<20070725070414.29E33C61D9@domain.name.de>

Jul 25 09:04:14 linux-system postfix/qmgr[30874]: 29E33C61D9: from=<wwwrun@domain.name.de>, size=446, nrcpt=1 (queue active)

Jul 25 09:04:14 linux-system postfix/smtp[21248]: 9AACBC61F0: to=<name.nachname@domain.name.de>, relay=mail11.dmz.domain.name.de[10.206.156.15], delay=2, status=sent (250 Message received and queued)

Jul 25 09:04:14 linux-system postfix/qmgr[30874]: 9AACBC61F0: removed

Jul 25 09:04:14 linux-system postfix/smtp[21264]: B312AC61F1: to=<0175999999999@sms.debitel.com>, relay=mail11.dmz.domain.name.de[10.206.156.15], delay=2, status=sent (250 Message received and queued)

Jul 25 09:04:14 linux-system postfix/qmgr[30874]: B312AC61F1: removed

Jul 25 09:04:14 linux-system postfix/smtp[21254]: C4389C61F9: to=<01855555555@t-mobile-sms.de>, relay=mail11.dmz.domain.name.de[10.206.156.15], delay=2, status=sent (250 Message received and queued)

[dr.disk]

Ist immer noch zuwenig Log. Du kannst ja expemplarisch eine Mail raussuchen und alles dazu posten was im Log steht. Die Einträge die zusammengehören erkennst Du an der ID die Postfix benutzt. Die steht hinter dem Modulnamen und hat etwa folgende Form: B312AC61F1 (diese ID ist von Deinem Log vorletzter Eintrag).

Alternativ dazu gebe ich Dir auch per PN meine Mail-Adresse, dann kannst das ganze Log senden.

[sombrero2007]

Das Problem mit den Mails kann ich leider nicht wieder stellen, die mails die ich schicke, nach ein paar Sekunden an, so wie es sein sollte

Ich gehe mal stark davon aus, dass es an einem Exchange-Server liegt, der nicht in unserem zuständigkeitsbereich ist, aber ich will mir erst 100% darauf verlassen, dass es wirklich nicht an meinen Postfix Liegt, bevor ich da aussagen treffe. Wenn ich da jetzt ein Mail raus schicke, und diese gleich ankommt, dann kannst ja nichts mit der Log anfangen oder?

Ich hab mir mal im Outlook, dass Header einer Verspäteten Mail angeschaut. Komisch finde ich, dass die Mail erst ca. 30 min später von linux-system.de an mail11.domain.de verschickt wurde, oder habe ich das jetzt falsch verstanden?

Microsoft Mail Internet Headers Version 2.0

Received:

from S4DE8PSAANQ.mitte.host.de ([10.152.11.196])

by S4DE8PSAAHF.mitte.host.de with Microsoft SMTPSVC(6.0.3790.3959);

Wed, 25 Jul 2007 09:34:30 +0200

Received:

from mail11.domain.de ([10.206.200.110])

by S4DE8PSAANQ.mitte.host.de with Microsoft SMTPSVC(6.0.3790.3959);

Wed, 25 Jul 2007 09:34:30 +0200

Return-Path: <wwwrun@linux-system.de>

Received:

from linux-system.de ([10.206.157.168] [10.206.157.168])

by mail11.domain.de with ESMTP for empfänger@domain.de;

Wed, 25 Jul 2007 09:34:43 +0200

Received:

by linux-system.de (Postfix, from userid 30)

id 1469FC61ED;

Wed, 25 Jul 2007 09:04:14 +0200 (CEST)

To: "empfänger@domain.de

[dr.disk]

Das könnte mehrere Gründe haben warum der die Mail erst nach 30 Minuten an nimmt. Könnte z.B. an einem Greylisting liegen.

Aber kuck Dir mal den Received-Block eins unterhalb dem von Dir rot markiertem Eintrag an. Da steht als Postfix-ID die "1469FC61ED". Such mal alles was Du dazu findest im Maillog. Dann solltest Du auch den Grund finden warum die Mail da 30 Minuten braucht.

[sombrero2007]

Hab mir alles angeschaut was mit der ID zu tun hatte, aber werde nicht wirklich schlau daraus Ich poste es hier mal vielleicht siehst du was (siehe Datei im Anhang).

mail_log.txt

[dr.disk]

Zusammengeschnitten auf diese eine ID von oben ergibt das folgendes:

Jul 25 09:04:14 linux-system postfix/pickup[14390]: 1469FC61ED: uid=30 from=<wwwrun>

Jul 25 09:04:14 linux-system postfix/cleanup[21144]: 1469FC61ED: message-id=<20070725070414.1469FC61ED@linux-system.de>

Jul 25 09:04:14 linux-system postfix/qmgr[30874]: 1469FC61ED: from=<wwwrun@linux-system.de>, size=4230, nrcpt=1 (queue active)

Jul 25 09:04:15 linux-system postfix/smtp[21155]: 1469FC61ED: host mail11.dmz.domain.com[10.206.200.156] refused to talk to me: 421 Service not available, closing transmission channel

Jul 25 09:04:15 linux-system postfix/smtp[21155]: 1469FC61ED: to=<mail@domain.de>, relay=u9jwn.mgb01.firma.de[173.20.63.178], delay=1, status=deferred (host u9jwn.mgb01.firma.de[173.20.63.178] refused to talk to me: 421 Service not available, closing transmission channel)

Jul 25 09:34:33 linux-system postfix/qmgr[30874]: 1469FC61ED: from=<wwwrun@linux-system.de>, size=4230, nrcpt=1 (queue active)

Jul 25 09:34:34 linux-system postfix/smtp[27173]: 1469FC61ED: to=<mail@domain.de>, relay=mail11.dmz.domain.com[10.206.200.156], delay=1820, status=sent (250 Message received and queued)

Jul 25 09:34:34 linux-system postfix/qmgr[30874]: 1469FC61ED: removed

Um 9:04:15 hat der Mailserver u9jwn.mgb01.firma.de die Email abgelehnt, jedoch um 9:34:34 angenommen. Das sieht nach einem typsichen Greylisting aus oder der Server u9jwn.mgb01.firma.de hat irgendein Config-Problem. Am Postfix von Dir liegt's auf jeden Fall nicht.

[sombrero2007]

Supi, das bringt mich schon weiter muss nur jemand finden, der sich dafür zuständig fühlt

[sombrero2007]

Also man sagte mir gerade, dass es doch an meinen Sever liegt? Der Server hat sie ja refused mit der Meldung "421 Service not available" das heißt, mein Server Qued ja die Mail und dann versucht er nach einem bestimmten Zeitraum die Mail wieder zu verschicken. Kann man das im Postfix einstellen? Was ist da die Defaulttime?

[dr.disk]

status=deferred (host u9jwn.mgb01.firma.de[173.20.63.178] refused to talk to me: 421 Service not available, closing transmission channel)

Da steht aber eindeutig die Gegenseite hat die Verbindung beendet. Darauf kannst Du keinen Einfluss nehmen, das liegt an der Gegenseite. Die Zeit bis Postfix es wieder versucht die Mail zuzustellen kann geändert werden. Diese Werte sollte man aber auf dem Standard lassen und nicht verändern.

[sombrero2007]

Der Vom Support hat gemeint, dass Sie unter den relayhost, den ich bei mir in der Config eingetragen habe, 3 Server dahinter verbergen! Wenn der eine die Mail abweißt wie man in dem Log sehen kann, dann wird die Mail bei mir in einer queue gelegt und dann wartet postfix 30 min und versucht dann die mail wieder zu verschicken, aber dies mal benutzt er dann einen anderen Server.

Leider kann ich das in meinen Logs nicht nachvoziehen, ändert sich die ID der mail wenn Sie in einer queue gelegt wird?

Wenn ich die Standardwerte so belasse und eine Mail nicht zugestellt werden kann, dann wird Sie ja wieder 30 min bei mir gehalten und erst dann über einen anderen Server verschickt.

[dr.disk]

Das ist doch Postfix egal ob hinter dem Namen einer oder mehrere Mailserver stehen. Wenn da per DNS/Lastverteiler drei drin sind, dann sollten auch alle drei funktionieren. Falls von denen ein Mailserver nicht richtig funktioniert ist das doch nicht Dein Problem. Woher sollte Postfix wissen, dass das mehrere sind? Kann er ja gar nicht wissen. Es gab einen Fehler der temporär ist, also versucht Dein Mailserver es einfach später nochmals. Dieses Verhalten ist doch absolut richtig - was sollte Dein Mailserver sonst tun?

Postfix legt aufgrund seines modularen Aufbaus die Mails während seiner Verarbeitung permanent in irgendwelche verschiedenen Queues. Im Log wäre da ja gar nichts mehr nachzuvollziehen falls sich diese ID ändern würde. Die bleibt also immer gleich.

Beim nächsten Zustellungsversuch startet Postfix wieder das smtp-Modul. Dieses Modul sucht per DNS einen zuständigen Mailserver und versucht diesen zu erreichen. Da kommt's jetzt auf das DNS-Ergebnis an ob da ein anderer Server ausgewählt wird oder nicht.

Also nochmals zusammengefaßt - meine Meinung zu dem Thema: Wenn Postfix versucht eine Mail zuzustellen holt er per DNS die Info welcher Server zuständig ist. Ob es da nur einen gibt oder mehrere ist doch egal. Wichtig dabei ist doch nur, dass alle Server die dafür zuständig sind auch tatsächlich sauber funktionieren. Und wenn Sie das täten hättest Du das Problem nicht. Ich sehe das Problem immer noch nicht bei Dir sondern bei dem Gegenüber.

[sombrero2007]

Gut, dass habe ich verstanden.

Aber, wenn die jetzt gerade ein Problem haben, dann braucht mein postfix erst mal 30 min um die mail noch mal rauszuschicken und wenn mich jetzt jemand frägst, warum ist die Mail 30 min zuspät gekommen, dann muss ich sagen, mein Postfix braucht so lange. Dann wird natürlich die Frage kommen, kann man diese Zeit nicht verringern. Warum wäre so eine Einstellung nicht gut?

[lupo49]

Gut, dass habe ich verstanden.

Aber, wenn die jetzt gerade ein Problem haben, dann braucht mein postfix erst mal 30 min um die mail noch mal rauszuschicken und wenn mich jetzt jemand frägst, warum ist die Mail 30 min zuspät gekommen, dann muss ich sagen, mein Postfix braucht so lange. Dann wird natürlich die Frage kommen, kann man diese Zeit nicht verringern. Warum wäre so eine Einstellung nicht gut?

Ich koennte mir vorstellen, dass ein niedriger Zustellungs-Intervall eine

hoehere Load auf dem Mailserver verursacht (bei einem stark frequentiertem

Server). Desweiteren koennte dein Mailserver komplett geblockt werden,

wenn du versuchst die Mail zu oft hintereinander zuzustellen.

Andererseits sollte, wenn der Absender immer wieder Mails an den gleichen

Empfaenger schickt, das Problem nur einmal auftreten. Da sich der Mailserver

beim ersten Zustellungsversuch die IP-Adresse vom sendenden Mailserver, die

Absenderadresse und Empfaengeradresse merkt und beim 2. Zustellungs-

versuch die Mail sofort annimmt, wenn die drei Daten uebereinstimmen.

Ich wuerde jetzt temporaer mal das Intervall runterschrauben und ueberpruefen,

ob sich das negativ auf andere Funktionen auswirkt.

[sombrero2007]

Und wo muss ich das Ändern?

Kann es sein, dass es ich um das queue_run_delay handelt? Bei mir steht hier ein Wert von 1000s drin, der ist recht hoch.