[Postfixbuch-users] Lost connection after DATA

Di Sep 9 23:16:20 CEST 2008

On Wed, 3 Sep 2008 08:32:29 +0200 (CEST)
"Christian Garling" <christian at cg-networks.de> wrote:

> Hallo zusammen,
> 
> dank logwatch ist mir aufgefallen, dass sich im mail.log etliche
> Meldungen dieser Art tummeln:
> 
> lost connection after DATA (0 bytes)
> 
> Ist das "normal" oder bedenklich? Kann man dagegen was unternehmen?
> 

Die selbe Frage wollte ich auch gerade stellen.
Ich habe meine smtpd_recipient_restrictions rauf, runter und wieder
rauf gedacht und komme absolut nicht zu der Erkenntnis, warum dem
einliefernden Host ein DATA erlaubt wird, zumal die alle via 550
abgewiesen wurden. Demnach ist es auch nicht logisch, dass Postfix eine
Verbindung zum smptd_proxy_filter aufbaut, die dann aufgrund dessen
REJECT zu dieser Log-meldung führen könnte. Das ist auch dadurch
begründet, dass eben besagte Meldung vom selben smtpd-Prozess ins Log
geschrieben wird, auf dem auch das connect des einliefernden Hosts
kommt. Wäre der smtpd_proxy_filter involviert, müsste das ein smtpd mit
anderer PID sein...

Ich kann mir vorstellen, dass das was mit nem syntaktisch falsch
formulierten Return-Code des policyd-weight zu tun hat, denn soweit ich
das gesehen habe geht all' diesen Log-Einträgen (lost connection after
DATA (0 bytes)) ein REJECT des policyd-weight voraus.

Hier mal die (hoffentlich komplette) Abschrift einer solchen Sitzung:

Sep  9 21:31:38 localhost postfix/smtpd[9038]: connect from unknown
[78.183.45.62] 

Sep  9 21:31:48 localhost postfix/policyd-weight[9040]:
decided action=550 Your MTA is listed in too many DNSBLs; check
http://rbls.org/?q=78.183.45.62 

Sep  9 21:31:48 localhost postfix/smtpd [9038]: NOQUEUE: reject: RCPT
from unknown[78.183.45.62]: 550 5.7.1 < [78.183.45.62]>: Helo command
rejected: Your MTA is listed in too many DNSBLs; check
http://rbls.org/?q=78.183.45.62; from=<quaffeddd7 at msdestinations.com>
to=<ellegehausen at ccwf.de> proto=ESMTP helo=<[78.183.45.62]> 

Sep  9 21:31:48 localhost postfix/smtpd[9038]: lost connection after
DATA (0 bytes) from unknown [78.183.45.62] 

Sep  9 21:31:48 localhost postfix/smtpd[9038]: disconnect from unknown
[78.183.45.62]

Man kann ziemlich deutlich das REJECT des policyd-weight erkennen. Im
Rahmen der smtpd_recipient_restrictions wird der wie folgt definiert
und aufgerufen:

smtpd_restriction_classes =
  greylisting
  policydweight
greylisting = check_policy_service inet:127.0.0.1:60000
policydweight = check_policy_service inet:127.0.0.1:12525

smtpd_recipient_restrictions =
[einige check_*_access-restrictions, definitiv OHNE policyd-weight]
  reject_non_fqdn_sender
  reject_non_fqdn_recipient
  permit_mynetworks
  permit_sasl_authenticated
  [... einige andere Dinge auch ohne policyd-weight ]
  reject_unauth_destination
# nun die restlichen Dinge ueber den Client in Erfahrung bringen
  reject_invalid_hostname
  reject_unknown_sender_domain
  reject_unknown_recipient_domain
  check_sender_mx_access cidr:/etc/postfix/mapfiles/bogus_mx
# im naechsten Schritt muss der Client-Host den policyd-weight
# ueberleben: in der access-map koennen einzelne hosts mittels DUNNO
# vom policyd-weight ausgeschlossen werden, bevor der catch-all-Eintrag
# den policyd-weight auf ihn loslaesst...
  check_helo_access pcre:/etc/postfix/mapfiles/policyd-weight_helo
# nun pruefen wir ob greylisting in Frage kommt
  check_client_access pcre:/etc/postfix/mapfiles/greylist_client_pcre

Den policyd-weight rufe ich einzig und allein in der
mapfiles/policyd-weight_helo auf, die wie folgt aussieht:

--- schnipp 8< --- policyd-weight_helo
#Einige Hosts wollen wir mal vom policyd-weight ausnehmen...
/^isis\.olly-eva\.lan$/           DUNNO

#alle Hosts sollen dem policyd-weight unterzogen werden...
/^.*$/                          policydweight
--- >8 schnapp ---

Der Postgrey (welcher erst nach policyd-weight zum Einsatz kommt) kommt
-- wie man im Log sehen kann schon gar nicht mehr zum Einsatz, weil ja
policyd-weight vorher schon einen 550 ausgelöst hat.

Nun ist es mir absolut unverständlich wieso der Host noch ein DATA
senden durfte und dann die Verbindung abbricht... Kein Problem, wenn
das nur hin und wieder mal der Fall ist, aber es ist am laufenden Band
so... ca. 6000x in der Zeit von 06:00 - 23:00 Uhr.

Hier noch die Definition des entsprechenden smtpd's:
mailout:smtp  inet  n       -       -       -       -       smtpd
 -o content_filter=
 -o smtpd_proxy_filter=127.0.0.1:10024
 -o receive_override_options=no_address_mappings
 -o smtp_send_xforward_command=yes

Postfix-Version ist 2.5.4

Vielleicht fällt jemandem eine logische Erklärung dazu ein?!

PS: Es gibt lediglich einen Paket-Filter zwischen Postfix und dem
weiten Internet. Keinen Proxy! -- Ehrlich! ;)

-- 
Mit freundlichen Grüßen / Best regards,
Oliver Meißner-Knippschild <lists.o at la-familia-grande.de>

registered Linux user #462769 (http://counter.li.org)
PGP-Fingerprint: FA5D 891C 298B 08DF 1ED7 9AFB 57B1 B3D7 3109 925A
Download key at: http://www.la-familia-grande.de/keys/3109925A.txt

-- 
Büroschimpfwort des Tages: Vorkoster - Mitarbeiter, der pünktlich zur
Kantinenöffnung Mittagspause macht. (Henrik Karcher)
-------------- nächster Teil --------------
Ein Dateianhang mit Binärdaten wurde abgetrennt...
Dateiname   : nicht verfügbar
Dateityp    : application/pgp-signature
Dateigröße  : 189 bytes
Beschreibung: nicht verfügbar
URL         : <https://listi.jpberlin.de/pipermail/postfixbuch-users/attachments/20080909/96dde17d/attachment.sig>