# Mailversand mit ssmtp geht manchmal nicht ...

## alexander_ro

Hallo Mädels ... Jungs ...  :Smile: 

Auf einem Raspberry mit Gentoo habe ich ssmtp installiert um Mails an meinen Mailserver senden zu können. Wenn ich die Mail von Hand sende kommt die an auch ein echo von einem cron gestartet kommt an. Nur wenn der Output von einem mit cron gestartetem "emerge --sync" gesendet wird sieht man zwar in den Logfiles das die versendet wurde aber sie kommt nicht an. Der Mailserver sagt "lost connection after DATA" siehe Logzeilen unten.

```

Jan  9 03:31:00 blitz postfix/smtpd[15052]: warning: hostname arc.domain.de.<IP>.in-addr.arpa does not resolve to address <IP>: Name or service not known

Jan  9 03:31:00 blitz postfix/smtpd[15052]: connect from unknown[<IP>]

Jan  9 03:31:00 blitz postfix/smtpd[15052]: Anonymous TLS connection established from unknown[<IP>]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)

Jan  9 03:31:00 blitz postfix/smtpd[15052]: 8E445195807B: client=unknown[<IP>]

Jan  9 03:36:00 blitz postfix/smtpd[15052]: lost connection after DATA (54537 bytes) from unknown[<IP>]

Jan  9 03:36:00 blitz postfix/smtpd[15052]: disconnect from unknown[<IP>] helo=1 ehlo=1 starttls=1 mail=1 rcpt=1 data=0/1 commands=5/6

```

Hier noch die Filterregel die fail2ban anlegt:

```

Chain INPUT (policy ACCEPT)

target     prot opt source               destination

f2b-sshd   tcp  --  anywhere             anywhere             multiport dports ssh

```

Ich habe gelesen das der Fehler an einer Firewall liegt die icmp Pakete

blockiert nur das ich eigentlich keine Firewall habe. Nur fail2ban läuft um

sshd vor übereifrigen Amerikanern, Chinesen, Russen und Australieren zu

schützen.

Ich weiß jetzt nur nicht wie man das Problem lösen soll und ob der fail2ban 

überhaupt das Problem verursacht.

Viele Grüße

Alexander

----------

## mike155

 *Quote:*   

> Wenn ich die Mail von Hand sende kommt die an auch ein echo von einem cron gestartet kommt an. Nur wenn der Output von einem mit cron gestartetem "emerge --sync" gesendet wird 

 

Woran liegt es? An der Länge? Versende doch mal eine Mail von Hand mit 100kB  (z.B. eine Text-Datei).

Wenn Du das Problem von Hand reproduzieren kannst, dann schau Dir die Firewall an mit:

```
iptables -L -v -n
```

In der ersten Spalte jeder Zeile siehst Du, wie viele Pakete von einer Regel gematcht wurden. Dann kannst Du folgendes machen:

```
iptables -L -v -n >a

# Jetzt die E-Mail verschicken

# 2-3 Sekunden warten, nicht die 5 Minuten, bis die Fehlermeldung erscheint

iptables -L -v -n >b

diff a b    # oder ein anderes Diff-Tool, z.B. diffuse

```

Dann siehst Du die Regeln der Firewall, die in der Zwischenzeit Pakete gematcht haben.

----------

## schmidicom

 *alexander_ro wrote:*   

> ...
> 
> Nur wenn der Output von einem mit cron gestartetem "emerge --sync" gesendet wird sieht man zwar in den Logfiles das die versendet wurde aber sie kommt nicht an. Der Mailserver sagt "lost connection after DATA" siehe Logzeilen unten.

 

Wie genau sieht dieser cron-Befehl den aus?

Wird mit ssmtp gleich zu beginn eine Verbindung aufgebaut und erst nach der vollständigen Ausgabe von "emerge --sync" das E-Mail versendet oder kommt ssmtp erst zum Zug wenn "emerge --sync" bereits gelaufen ist? Bei ersterem könnte ich mir denken das es einfach zu lange dauert und die Verbindung deshalb abgebrochen wird, denn im Log sieht es ja so aus als wären schon einige Daten angekommen.

 *Quote:*   

> ...lost connection after DATA (54537 bytes)...

 

----------

## alexander_ro

Wann der cron die Verbindung zum Mailserver aufbaut weiß ich nicht. Es ist der vixie-cron.

Ich habe den emerge einfach als auszuführendes Kommando angegeben. Sieht dann so aus:

```

SHELL=/bin/bash

PATH=/sbin:/bin:/usr/sbin:/usr/bin

MAILTO=<mail-adresse>

HOME=/

# Dienste ausführen

# Min  Stunde  Tag   Monat  Wochentag Programm starten

  30   3       *     *      *         /usr/bin/emerge --sync

```

<Edit>

Manuell kann ich eine Mail mit 100 KB versenden. Aber das mit den Paketzählern ist schwierig weil die sich schon verändern wenn ich den Befehl nur mit der Befehlswiederholung hintereinander Aufrufe.

```

Chain INPUT (policy ACCEPT 2750 packets, 536K bytes)

 pkts bytes target     prot opt in     out     source               destination         

59488 5799K f2b-sshd   tcp  --  *      *       0.0.0.0/0            0.0.0.0/0            multiport dports 22

```

Der zeigt ja auch eine Liste an mit den IP-Adressen die REJECT sind. Da ist die IP-Adresse des Versenders nicht dabei.

</Edit>

----------

## mike155

Da ich auch  vixie-cron und ssmtp verwende, habe ich versucht, das Problem zu reproduzieren. Ich habe folgendes nach /etc/crontab geschrieben:

```
15 2 * * *  root  /usr/bin/emerge --sync

```

emerge läuft 10 Minuten (langsam, da /usr/portage ein NFS share ist). Danach versendet cron die Ausgabe von emerge als E-Mail über ssmtp und postfix. Die E-Mail kommt einwandfrei an.

---

Zuerst funktionierte es übrigens nicht. Auf dem Mail-Server (postfix) stand im syslog:

```
postfix/smtpd[15537]: fatal: in parameter smtpd_relay_restrictions or smtpd_recipient_restrictions, specify at least one working instance of: 

                             reject_unauth_destination, defer_unauth_destination, reject, defer, defer_if_permit or check_relay_domains

postfix/master[15525]: warning: process /usr/libexec/postfix/smtpd pid 15537 exit status 1

postfix/master[15525]: warning: /usr/libexec/postfix/smtpd: bad command startup -- throttling

```

Es stellte sich heraus, dass es am Upgrade auf Postfix 3.3.1-r1 lag. Sobald ich auf Postfix 3.2.4 zurückging, ging es wieder. Für Postfix 3.3.1 hat mir dieser Post weitergeholfen: nachdem ich in main.cf den Parameter "compatibility_level = 2" gesetzt hatte, funktionierte auch Postfix 3.3.1.Last edited by mike155 on Thu Jan 10, 2019 2:52 am; edited 1 time in total

----------

## mike155

Wie sind Dein Raspberry und der Mail-Server miteinander verbunden? Stehen sie direkt nebeneinander? Hängen sie im gleichen LAN? Oder geht die Verbindung übers Internet? Stehen vielleicht noch weitere Firewalls zwischen den beiden Rechnern?

Ich würde an dieser Stelle tcpdump auf dem Raspberry und dem Mail-Server starten und den cronjob laufen lassen. Dann würde ich mir die Mitschnitte mit Wireshark ansehen und Paket für Paket überprüfen, ob jedes gesendete Paket auch ankommt. Neben fehlenden ICMP-Paketen könnte es sich auch um eine fehlerhafte MTU handeln (falls Du übers Internet gehst).

----------

## alexander_ro

Außer den oben genannten Meldungen sagt mein Postfix nichts zu dem Thema.

Der Postfix hängt am gleichen Switch wie der Raspberry und dem Postfix habe ich erlaubt alle Mails aus meinem Netz einfach anzunehmen.

```

smtpd_recipient_restrictions =

  permit_mynetworks

```

Das hier hatte ich gefunden: https://www.heinlein-support.de/blog/mailserver/postfix-timeout-after-data-lost-connection/

Den Vorschlag mit dem kleiner stellen der MTU habe ich ausprobiert. Hat aber nicht geholfen.

Jetzt bin ich noch über das gestolpert weiß aber nicht so genau was der Kernelparameter da eigentlich tut und ob man das probieren kann ohne andere Probleme einzubauen. Muss man das beim Mailserver oder bei Client ausschalten?

https://www.d7031.de/content/postfix-and-lost-connection-after-data/

Ich habe den verdacht das das ausschalten der Performance des Netzwerks nicht wirklich gut tut.

----------

## toralf

 *alexander_ro wrote:*   

> 
> 
> Ich weiß jetzt nur nicht wie man das Problem lösen soll und ob der fail2ban 
> 
> überhaupt das Problem verursacht.
> ...

 Na dann schalte doch fail2ban aus udn teste es.  :Wink: 

Mit einem cronjob Eintrag der Art

```
* * * * * date
```

kannst Du minütlich herausfinden, ob Mails vom cron versendet werden (können). Wenn es dann einfach an der Dauer der Ausführung des cron jobs liegt (das vermute ich), dann könntest Du für cron jobs mit einer langen Ausführungszeit einfach ein "emerge ... &>/tmp/log; cat /tmp/log | mail ..." machen.

----------

## mike155

 *toralf wrote:*   

> Wenn es dann einfach an der Dauer der Ausführung des cron jobs liegt (das vermute ich), dann könntest Du für cron jobs mit einer langen Ausführungszeit einfach ein "emerge ... &>/tmp/log; cat /tmp/log | mail ..." machen.
> 
> 

 

Bisher bin ich davon ausgegangen, dass cron selbst die Ausgabe sammelt und am Ende verschickt. Aber das stimmt nicht, zumindest stimmt es bei größeren Datenmengen nicht. 

Ich habe in den Source Code geschaut: vixie cron liest die Daten über eine Pipe - ohne eigene Zwischenspeicherung.

Wenn ein cronjob nur wenige Daten schreibt, werden die Daten in der Pipe zwischengespeichert. Vixie-cron erhält die Daten dann erst am Ende des cronjobs und überträgt die Daten auch erst dann an den Mail-Server.

Wenn ein cronjob mehr Daten schreibt als die Länge des Pipe-Buffers, erhält vixie-cron die ersten Daten bereits während der cronjob noch läuft. Vixie-cron öffnet zu diesem Zeitpunkt eine Verbindung zum Mail-Server und überträgt die bereits erhaltenen Daten. Danach hält vixie-cron die Verbindung zum Mail-Server offen, bis der cronjob endet. Wenn der cronjob länger läuft und vor dem Ende des cronjobs ein Timeout auf dem Mail-Server zuschlägt, gibt es einen Fehler.

Also, es liegt nicht allein an der Ausführungszeit des cronjobs und auch nicht allein an der Länge der Ausgabe, sondern an beidem zusammen.

@alexander_ro: Der Lösungsvorschlag von toralf ist richtig. Vermutlich geht sogar folgendes:

```
emerge ... &>/tmp/log; cat /tmp/log; rm /tmp/log

```

Alternativ könntest Du auch das Timeout im Mail-Server hochsetzen - aber das ist maximal ein Workaround.

----------

## alexander_ro

toralfs Lösung will mir nicht so recht gefallen. Das Problem ist das ich dann jedes mal an jeder stelle diese Krücke einbauen muss und wenn es vergessen wird geht die Sucherei von vorne Los. Ich brauch da eine Lösung die einfach funktioniert. Aus meiner Sicht ist dieser ssmtp damit schon ein bisschen kaputt. Das es am Timout des Mailservers liegt glaube ich nicht weil der schlicht damit leben muss das Daten langsam kommen es gibt immer noch Langsame oder überlastete Datenverbindungen. Die Mails von solchen Übertragungen kommen ja auch an ohne Timeout. Auch bei dem emerge ist es ja nicht so das der Minuten lang keinen Output produzieren würde. Über die Pipe laufen da zwar Langsam aber permanent die Daten damit muss der ssmtp leben können wenn nicht macht er was falsch. Ich habe den jetzt entfernt und durch einen Postfix ersetzt der kann das ja auch und macht keine Zicken. Hat sofort funktioniert.

----------

## toralf

With this cron job

```
23 15 * * * echo "start"; sleep 600; echo "end"

```

I'm testing in moment whether the sSMTP (I'm using) can handle longer timeouts or not:

```
Every 2.0s: /usr/bin/pstree -Ulnspu -a 1949                                     mr-fox: Fri Jan 11 15:25:06 2019

init,1

  └─crond,1949

      ├─crond,1980

      │   └─(sh,2002)

      └─crond,32715

          ├─sh,32724,tinderbox -c echo "start"; sleep 600; echo "end"

          │   └─sleep,32726 600

          └─sendmail,32727,tinderbox -FCronDaemon -i -odi -oem -oi -t -f tinderbox

```

----------

## mike155

 *alexander_ro wrote:*   

> Hat sofort funktioniert.

 

Das Problem ist also vorerst gelöst. 

Spannend ist, warum es gelöst ist!  Warum funktioniert es, wenn cron die Daten an einen lokalen Postfix überträgt? Und warum funktioniert es nicht, wenn cron die Daten über ssmtp an den entfernten Postfix überträgt?

Eine Erklärung für dieses Rätsel schreibe ich weiter unten.

Hier stand etwas Polemik, die sich aber als falsch herausgestellt hat. Ich erlaube mir deshalb, sie zu löschen. Hoffentlich war niemand beleidigt...Last edited by mike155 on Sat Jan 12, 2019 1:36 am; edited 2 times in total

----------

## toralf

 *mike155 wrote:*   

> 
> 
> Die Antwort ist vermutlich im ersten Post versteckt. Dort steht, dass der Timeout genau nach 5 Minuten zugeschlagen hat, und dass Du SSL Verschlüsselung verwendet hast.
> 
> Ich schreibe gleich mehr, muss aber noch ein paar Tests machen. Ich vermute, dass es mit der TLS-Verbindung zu tun hat und letztendlich der SSL-Timer zuschlägt. Das passiert beim lokalen Postfix, der wohl nicht über SSL angesprochen wird, vermutlich nicht.

 Yep, meine Tests hier mit sSMTP haben auch bei 20 min und mehr keine Probleme aufgezeigt, da würde ich den vixie-cron auch von der Verdächtigenliste streichen.

----------

## mike155

 *toralf wrote:*   

> Yep, meine Tests hier mit sSMTP haben auch bei 20 min und mehr keine Probleme aufgezeigt, da würde ich den vixie-cron auch von der Verdächtigenliste streichen.

 

Ja, die Tests sind mühselig, weil man immer so lange warten muss. Aber statt 

```
23 15 * * *  echo "start"; sleep 600; echo "end

```

sollte man besser nehmen:

```
23 15 * * *  cat /etc/services; sleep 600; cat /etc/services

```

Wenn man nur "echo start" nimmt, kann man es nicht testen, weil die Ausgabe zu kurz ist. Sie wird in der Pipe gepuffert. Die Übertragung findet dann erst am Ende statt, nach dem sleep.

--- 

Ich kann die Timeouts jetzt reproduzieren - mit folgendem Eintrag in /etc/crontab: 

```
10 22 * * *  root  cat /etc/services; sleep 400; cat /etc/services

```

oder auch mit folgender Anweisung:

```
( cat /etc/services; sleep 400; cat /etc/services ) | /usr/lib/sendmail <e-mail-addr>

```

Auf dem Postfix Mail-Server sehe ich genau 5 Minuten später:

```
Jan 11 22:15:01 xxxx postfix/smtpd[1106]: lost connection after DATA (38191 bytes) from yyyy [10.0.0.1] 

Jan 11 22:15:01 xxxx postfix/smtpd[1106]: disconnect from yyyy [10.0.0.1] helo=1 mail=1 rcpt=1 data=0/1 commands=3/4

```

---

Jetzt ist nur die Frage, wer die Timeouts wirft. In der ssmtp Quelldatei "ssmtp.h" habe ich folgendes gefunden:

```
#define MEDWAIT (5 * 60)

```

und in ssmtp.c:

```
int timeout = 0;

...

if (++timeout >= MEDWAIT) {

    log_event(LOG_ERR, "killed: timeout on stdin while reading body -- message saved to dead.letter.");

    die("Timeout on stdin while reading body");

}
```

Um herauszufinden, ob es wirklich der ssmtp ist, setze ich im Quellcode: 

```
#define MEDWAIT ( 125 )

```

und installiere ssmtp erneut. Ich starte einen cronjob über /etc/crontab:

```
47 22 * * *  root  cat /etc/services; sleep 400; cat /etc/services

```

Und genau 125 Sekunden später erhalte ich auf dem Postfix Mail-Server:

```
Jan 11 22:49:06 xxxx postfix/smtpd[1232]: lost connection after DATA (38191 bytes) from yyyy [10.0.0.1] 

Jan 11 22:49:06 xxxx postfix/smtpd[1232]: disconnect from yyyy [10.0.0.1] helo=1 mail=1 rcpt=1 data=0/1 commands=3/4

```

Ergebnis: es ist der ssmtp, der den Timeout wirft.

----------

## mike155

Das war ein nettes kleines Rätsel. Mittlerweile kann ich nachvollziehen, was passiert ist.

Vixie cron startet einen cronjob und liest dessen Ausgabedaten über eine Pipe. Sobald Vixie cron die ersten Bytes aus der Pipe erhalten hat, startet es "/usr/bin/sendmail" und übergibt alle eintreffenden Ausgabedaten über eine zweite Pipe an das gestartete sendmail. Vixie cron führt keine Zwischenspeicherung der Ausgabedaten durch und nimmt damit in Kauf, dass /usr/bin/sendmail bis zum Ende des cronjobs laufen muss.

Das Programm "/usr/sbin/sendmail" wird bei alexander_ro von sstmp bereitgestellt. Sobald es gestartet wird und die ersten Daten erhält, baut es eine Verbindung zum Postfix Mail-Server auf. Danach überträgt es alle eingehenden Daten an Postfix, bis es ein EOF empfängt. Es enthält allerdings eine Zusatzregel: wenn es 5 Minuten lang keine Eingangsdaten erhält, beendet es sich mit einem Timeout.

alexander_ro hat das Programm "emerge --sync" über cron gestartet. Auf einem schnellen Rechner ist das Programm nach wenigen Sekunden fertig. Auf meinem NFS Client hingegen braucht es 10 Minuten. Auf einem Raspberry Pi wird es wohl auch einige Minuten laufen. 

"emerge --sync" gibt nun am Anfang einige Zeilen aus. Offenbar genug, um den Puffer der Pipe zu cron zu füllen, so dass cron sendmail startet und die ersten Daten an sendmail übergibt. Danach muss "emerge --sync" mindestens 5 Minuten lang keine Daten ausgegeben haben - oder nur so wenige, dass der Puffer der Pipe nicht gefüllt wurde. Dadurch erhielt sendmail 5 Minuten lang keine Daten - und hat sich mit einem Timeout beendet. 

Ist das realistisch? Ja! Wie ich in diesem Post beschrieben habe, startet emerge einen rsync-Prozess, der Hard Links in ".tmp-unverified-download-quarantine" anlegt. Dieser Prozess braucht auf meinem NFS Client 344 Sekunden - also länger als 5 Minuten - und gibt dabei nichts auf der Konsole aus. Gut möglich, dass das auf dem Raspberry Pi auch so lange dauert.

Postfix auf dem Mail Server bemerkt 5 Minuten nach dem Start der Verbindung von ssmtp, dass die Verbindung abgebrochen ist. Es verwirft dann die eingegangene E-Mail und schreibt eine Fehlermeldung nach syslog.

Kommen wir zur Gretchenfrage: welches Programm ist nun das Schuldige? 

Vermutlich keines der Programme. Vixie cron und ssmtp passen nur einfach nicht gut zusammen. Vixie cron verlässt sich darauf, sendmail über einen langen Zeitraum mit Daten füttern zu können. 

sendmail von ssmtp ist NICHT dafür geeignet. Es hat ein enges Timeout, weil es Daten über eine TCP/IP-Verbindung an einen Mail-Server überträgt. 

sendmail von Postfix ist dafür geeignet. Es schreibt die Daten in eine Datei und hat deshalb kein enges Timeout.

 *alexander_ro wrote:*   

> Ich habe den [ssmtp] jetzt entfernt und durch einen Postfix ersetzt der kann das ja auch und macht keine Zicken. Hat sofort funktioniert.

 

Am Anfang dachte ich, dass der Wechsel von ssmtp auf postfix nur ein Workaround sei, der lediglich aus Zufall funktioniert. Mittlerweile habe ich meine Meinung geändert. Es ist ein vernünftiger Schritt, der das von alexander_ro beschriebene Problem erst einmal löst.

----------

## alexander_ro

Die Definition eines Timout ist es wenn keine Übertragung stattfindet abzubrechen. Das ist aber wohl bei einem "emerge --sync" nie der Fall. Zumindest habe ich das noch nie erlebt. Es hätte hier über Tage lang so sein müssen das der emerge > 5 Minuten hängt. Wir sind uns einige das auch die schnellsten Tipper lahme Datenraten schaffen? So würde Dir eine ssh Verbindung wählend dem Tippen abkacken. Datenverbindungen dürfen von einem Timeout niemals abgebrochen werden auch wenn alle 4 Minuten nur wenige Byte kommen.

<Edit>

Ich habe nun mal nachgemessen. Er braucht auf der Konsole aufgerufen nahe an die 5 Minuten ohne Daten zu senden.

Hier:

```

* Verifying /usr/portage/.tmp-unverified-download-quarantine ...        [ ok ]

```

Das ist mir nie so wirklich aufgefallen wenn ich den von der Konsole aus aufgerufen habe. Vermutlich weil man dann auch andere Sachen nebenbei macht kommt es einem nicht so lange vor. Der für meinen Test jetzt war aber ein Raspi der sonst nichts zu tun hatte. Der mit dem ssmtp macht auch anderes nebenbei deshalb wird es vermutlich länger als die 5 Minuten dauern. Dann ist die Erklärung von euch scheinbar doch richtig mir kam das vorher sehr unwahrscheinlich vor.

Trotzdem bin ich der Meinung das der ssmtp kaputt ist. Vielleicht jetzt kein Programmierfehler aber ein "Error by Design". Wenn Output von einem Script nur nicht mehr ankommt weil es warum auch immer mal irgendwo ein bisschen länger dauert ist das vielleicht für ein Hobby Projekt zu verschmerzen um aber Nachrichten von Produktivsystemen zu erhalten untauglich. Ich habe eigentlich schon immer einen postfix auch für die reine Mailzustellung an einen anderen Mailserver benutzt und bin nur durch einen Artikel in einer Fachzeitschrift auf den ssmtp gekommen. Der Autor meinte man braucht für sowas keinen MTA und könne viel Speicherplatz und Rechenleistung mit Einsatz des ssmtp sparen. Wie sich jetzt aber herausstellte hatte der Autor nicht wirklich eine Ahnung von dem was er da schrieb. Wenigsten hatte ich Glück das mein erster Versuch gleich die Schwächen offenbart hat. Ich bleib bei meiner bisherigen Methode und benutze für Mailtransport weiter immer den postfix.

Wenn ich mich richtig erinnere wurde das nur verworfen aber in keinem dead.letter gespeichert:

```

killed: timeout on stdin while reading body -- message saved to dead.letter

```

Was nicht verwundert wenn er nur durchleitet woher sollte er die Message haben um die in eine Datei zu schreiben.

</Edit>

----------

