Informationen über Maildrops

[rotalever]

Also ich habe ein Munin-Script, das unter anderem die Maildrops von postfix überwachen soll. Die letzten drei Tage (24.,23. und 22. März) gab es immer einen Ausschlag so kurz nach 9 Uhr morgens, wo ich auch jedesmal eine ganze Reihe Mails verschickt habe.
Die Messung erfolgt durch

...
cd $SPOOLDIR (wobei SPOOLDIR glaube ich /var/spool/postfix ist)
...
maildrop.value `(test -d maildrop && find maildrop -type f ) | wc -l`

Ich weiß nicht, auf welchem Prinzip diese Messung funktioniert, aber ich traue ihr einfach mal...

Um zu sehen, was da nun wirklich passiert ist, dachte ich mir, dass ich einfach mal in den postfix-log reinschaue.


sudo cat /var/log/mail.log | grep drop
...
Mar 22 22:55:19 ## postfix/smtp[9989]: connect to mx3.hotmail.com[xxx.xxx.xxx.xxx]: server dropped connection without sending the initial SMTP greeting (port 25)
Mar 22 22:55:20 ## postfix/smtp[9989]: connect to mx1.hotmail.com[xxx.xxx.xxx.xxx]: server dropped connection without sending the initial SMTP greeting (port 25)
Mar 24 09:13:08 ## postfix/smtp[28622]: connect to mx3.hotmail.com[xxx.xxx.xxx.xxx]: server dropped connection without sending the initial SMTP greeting (port 25)
Mar 24 09:13:08 ## postfix/smtp[28622]: connect to mx4.hotmail.com[xxx.xxx.xxx.xxx]: server dropped connection without sending the initial SMTP greeting (port 25)
Mar 24 09:13:08 ## postfix/smtp[28622]: connect to mx3.hotmail.com[xxx.xxx.xxx.xxx]: server dropped connection without sending the initial SMTP greeting (port 25)
Mar 24 09:13:11 ## postfix/smtp[28640]: connect to mx1.hotmail.com[xxx.xxx.xxx.xxx]: server dropped connection without sending the initial SMTP greeting (port 25)
Mar 24 09:13:12 ## postfix/smtp[28640]: connect to mx1.hotmail.com[xxx.xxx.xxx.xxx]: server dropped connection without sending the initial SMTP greeting (port 25)


Das passt aber nicht mit den gemessenen Werten zusammen, da für Mar 23 kein Eintrag ist und die Einträge für den 22. zu spät sind.

Weiß jemand eine Erklärung für die Maildrops?
Oder, in welchen logfiles könnte ich noch suchen? Oder muss ich nach etwas anderem als "drop" greppen?

[Birdman]

Vermutlich hat Hotmail eine Connections/Zeiteinheit Limite für eine IP Adresse - um halt Spamserver abzuwimmeln. Da diese oftmals kein Mailspooling betreiben ist das eine effektive Methode um Resourcenschonend UBE zu vermindern.

Mehr Infos wirst Du aber in keinem Log finden, da nicht mehr gibt ;)
Wenn der Zielmailserver die Verbindung schon vor dem Greeting String droppt, kann dein Postfix gar nichts loggen.
Du könntest da maximal mit einem TCP Dump rausfinden, wie die Connection geschlossen wurde. Kommt da ein korrektes Fin vom Hotmail Server ist es fast sicher dass dies von Hotmail auch so beabsichtigt ist. (korrekt arbeitende Mailserver stört das auch nicht gross - die schicken das Email einfach paar Minuten später nochmals)

[Lokadamus]

Weiß jemand eine Erklärung für die Maildrops?
Oder, in welchen logfiles könnte ich noch suchen? Oder muss ich nach etwas anderem als "drop" greppen?mmm...

Ist das wirklich die komplette Meldung zum Vorgang eines Aufbaus?
Kannst du Emails überhaupt versenden?
Werden sie zeitweilig von Hotmail angenommen?
Firmenserver oder privat?

[rotalever]

Vermutlich hat Hotmail eine Connections/Zeiteinheit Limite für eine IP Adresse - um halt Spamserver abzuwimmeln. Da diese oftmals kein Mailspooling betreiben ist das eine effektive Methode um Resourcenschonend UBE zu vermindern.

Mehr Infos wirst Du aber in keinem Log finden, da nicht mehr gibt ;)
Wenn der Zielmailserver die Verbindung schon vor dem Greeting String droppt, kann dein Postfix gar nichts loggen.
Du könntest da maximal mit einem TCP Dump rausfinden, wie die Connection geschlossen wurd.[...]
Nee nee, darum ging es mir doch gar nicht :smile: Ich habe ja wie gesagt am 22., 23. und am 24. März einen "maildrop" beobachten können. Da dachte ich mir dass ich mit dem Wort "drop" einfach mal das Logfile greppe. Da ist aber nichts vernünftiges herausgekommen, da 1. dieses Hotmail Zeug nicht am 23. auftrat (wo ich aber trotzdem einen maildrop aufgezeichnet habe) und 2. die Zeiten am 22. nicht mit dem maildrop übereinstimmen.
Ich habe den Log also nur gepostet um zu sagen, dass ich über "grep drop" nichts rausgefunden hatte ;) Hätte ich vielleicht was besser formulieren müssen :smile:

Ist das wirklich die komplette Meldung zum Vorgang eines Aufbaus?

Wie gesagt nur das gegreppte, aber das ist ja vermutlich auch nicht wichtig, siehe oben.

Kannst du Emails überhaupt versenden? Ich habe wie gesagt nur einen einzigen maildrop pro Tag in den letzten drei Tagen beobachtet.

Ja das geht. Sogar einige.

Werden sie zeitweilig von Hotmail angenommen?

Ja eigentlich schon.

Firmenserver oder privat?

Privat, aber das macht doch eigentlich keinen Unterschied oder?


Also nochmal zurück zu meiner Frage ;) es ging mir weniger um die Auswertung der Hotmail-"Probleme", ich denke mal das ist etwas, was postfix doch hoffentlich automatisch regelt..
Es ging mir darum, dass ich maildrops aufgezeichnet habe, sie aber nicht in dem log wiederfinden konnte, zumindest nicht mit dem genannten grep und ich mich deshalb frage, ob es nicht vielleicht noch irgendwelche anderen logs geben könnte, wo was drinsteht oder ob ich einfach nach etwas anderem greppen muss.

[rotalever]

Heute habe ich nur 4 Emails um diese Zeit verschickt. Eine an eine Gmail-Adresse und drei an mich. Die an die Gmail Adresse ist vermutlich auch angekommen, zumindest sieht es im Log so aus und die drei Emails an mich sind auf jeden Fall angekommen (zwei mit Hilfe eines scriptes versendet, eine dritte automatisch durch cron, da ein Script eine Ausgabe produziert hat).
Der mail.log für heute sagt wieder nichts aus.

Mar 25 09:13:04 example postfix/smtpd[7734]: connect from example.com[127.0.0.1]
Mar 25 09:13:05 example postfix/smtpd[7734]: AAAAAAAAAAA: client=example.com[127.0.0.1]
Mar 25 09:13:05 example postfix/cleanup[7743]: AAAAAAAAAAA: message-id=<###@example.com>
Mar 25 09:13:05 example postfix/qmgr[29881]: AAAAAAAAAAA: from=<####@example.com>, size=###, nrcpt=1 (queue active)
Mar 25 09:13:05 example postfix/smtpd[7734]: disconnect from example.com[127.0.0.1]
Mar 25 09:13:05 example postfix/smtpd[7734]: connect from example.com[127.0.0.1]
Mar 25 09:13:05 example postfix/smtpd[7734]: BBBBBBBBBBB: client=example.com[127.0.0.1]
Mar 25 09:13:05 example postfix/cleanup[7743]: BBBBBBBBBBB: message-id=<###@example.com>
Mar 25 09:13:05 example postfix/qmgr[29881]: BBBBBBBBBBB: from=<####@example.com>, size=###, nrcpt=1 (queue active)
Mar 25 09:13:05 example postfix/smtpd[7734]: disconnect from example.com[127.0.0.1]
Mar 25 09:13:05 example postfix/smtp[7748]: BBBBBBBBBBB: to=<my.email@another.example.com>, relay=###[####], delay=0, status=sent (250 2.6.0 Message accepted ...
Mar 25 09:13:05 example postfix/qmgr[29881]: BBBBBBBBBBB: removed
Mar 25 09:13:05 example postfix/smtp[7744]: AAAAAAAAAAA: to=<######@gmail.com>, relay=gmail-smtp-in.#.google.com[####], delay=0, status=sent (250 2.0.0 OK ...
Mar 25 09:13:05 example postfix/qmgr[29881]: AAAAAAAAAAA: removed
Mar 25 09:42:18 example postfix/smtpd[17843]: connect from example.com[127.0.0.1]
Mar 25 09:42:18 example postfix/smtpd[17843]: CCCCCCCCCCC: client=example.com[127.0.0.1]
Mar 25 09:42:18 example postfix/cleanup[17846]: CCCCCCCCCCC: message-id=<###@example.com>
Mar 25 09:42:18 example postfix/qmgr[29881]: CCCCCCCCCCC: from=<####@example.com>, size=###, nrcpt=1 (queue active)
Mar 25 09:42:18 example postfix/smtpd[17843]: disconnect from example.com[127.0.0.1]
Mar 25 09:42:18 example postfix/pickup[17734]: DDDDDDDDDD: uid=0 from=<root>
Mar 25 09:42:18 example postfix/cleanup[17846]: DDDDDDDDDD: message-id=<###@example.com>
Mar 25 09:42:18 example postfix/qmgr[29881]: DDDDDDDDDD: from=<root@example.com>, size=###, nrcpt=1 (queue active)
Mar 25 09:42:19 example postfix/smtp[17848]: DDDDDDDDDD: to=<my.email@another.example.com>, relay=###[####], delay=1, status=sent (250 2.6.0 Message accepted ...
Mar 25 09:42:19 example postfix/qmgr[29881]: DDDDDDDDDD: removed
Mar 25 09:42:19 example postfix/smtp[17847]: CCCCCCCCCCC: to=<my.email@another.example.com>, relay=###[####], delay=1, status=sent (250 2.6.0 Message accepted ...
Mar 25 09:42:19 example postfix/qmgr[29881]: CCCCCCCCCCC: removed


Trotzdem habe ich einen "maildrop"-peak von kurz nach 9 Uhr bis vielleicht viertel vor 10 (so genau kann man das in der Log-Grafik nicht erkennen).
Könnte es vielleicht an dieser Mail liegen, die der cron-Daemon verschickt? Es muss doch irgendein logfile geben, was mir sagt, was da immer passiert...:(

[Lokadamus]

Privat, aber das macht doch eigentlich keinen Unterschied oder?

Also nochmal zurück zu meiner Frage ;) es ging mir weniger um die Auswertung der Hotmail-"Probleme", ich denke mal das ist etwas, was postfix doch hoffentlich automatisch regelt..mmm...

Kommt drauf an, welche Maßnahmen welcher Provider unternommen hat, um Spam zu verhindern.

Must du in die MailQueue gucken, um zu sehen, ob da noch welche drinne sind. Die sollten aber auch im Log irgendwie auftauchen (deferred wäre der Status).

Du kannst in den anderen Logfiles (messages zum Beispiel) mal schauen, ob du da was zum genannten Zeitpunkt findest.

Edit: Google (http://www.google.de/search?q=server+dropped+connection+without+sending+the+initial+SMTP+greeting) wirft auch nicht viel raus, eher allgemeines wie falsche Konfig.

[rotalever]

Kommt drauf an, welche Maßnahmen welcher Provider unternommen hat, um Spam zu verhindern.
Hotmail hat zumindest meinen SPF-Eintrag in so einer White-Liste drin. Die einzigen richtigen Probleme hatte ich mit Yahoo, das habe ich aber mitlerweile mit denen geregelt. Aber wie gesagt, zeigt mail.log für heute ja keine derartigen Probleme. Trotzdem bleibt dieser maildrop..
Das mit den gedroppten Connections ist ja wie gesagt denke ich nicht das Problem.

Must du in die MailQueue gucken, um zu sehen, ob da noch welche drinne sind. Die sollten aber auch im Log irgendwie auftauchen (deferred wäre der Status).

mailq und postqueue -p sagen, dass die Queue leer ist.

Du kannst in den anderen Logfiles (messages zum Beispiel) mal schauen, ob du da was zum genannten Zeitpunkt findest.
In. syslog, messages, user.log, auth.log Nichts gefunden. mail.log habe ich ja im letzten Beitrag geposted.