[Postfixbuch-users] Postfix/Postgrey: einige Mails gehen an Postgrey vorbei (?)

[Stephan Budach]

>> > Um den Weg den die Mail nimmt zu beobachten in der Main.cf mal -v hinter den smtp prozess
>> > schreiben. Damit werden die Logfiles ausführlicher.
> 
> smtpd, nicht smtp

So, ich habe jetzt den smtpd mal mit -v laufen lassen und habe eben folgende Mail gefunden, die es einfach offenbar um alle Restrictions geschafft hat:

Apr 29 16:20:59 mosx postfix/smtpd[900]: connect from gqx150.internetdsl.tpnet.pl[83.3.179.150]
Apr 29 16:20:59 mosx postfix/smtpd[900]: match_list_match: gqx150.internetdsl.tpnet.pl: no match
Apr 29 16:20:59 mosx postfix/smtpd[900]: match_list_match: 83.3.179.150: no match
Apr 29 16:20:59 mosx postfix/smtpd[900]: match_list_match: gqx150.internetdsl.tpnet.pl: no match
Apr 29 16:20:59 mosx postfix/smtpd[900]: match_list_match: 83.3.179.150: no match
Apr 29 16:20:59 mosx postfix/smtpd[900]: > gqx150.internetdsl.tpnet.pl[83.3.179.150]: 220 mosx.stephanbudach.de ESMTP Postfix
Apr 29 16:20:59 mosx postfix/smtpd[900]: watchdog_pat: 0x30a578
Apr 29 16:21:00 mosx postfix/smtpd[900]: < gqx150.internetdsl.tpnet.pl[83.3.179.150]: HELO tpnet.pl
Apr 29 16:21:00 mosx postfix/smtpd[900]: > gqx150.internetdsl.tpnet.pl[83.3.179.150]: 250 mosx.stephanbudach.de
Apr 29 16:21:00 mosx postfix/smtpd[900]: watchdog_pat: 0x30a578
Apr 29 16:21:01 mosx postfix/smtpd[900]: < gqx150.internetdsl.tpnet.pl[83.3.179.150]: MAIL FROM: <devan at tpnet.pl>
Apr 29 16:21:01 mosx postfix/smtpd[900]: extract_addr: input: <devan at tpnet.pl>
Apr 29 16:21:01 mosx postfix/smtpd[900]: smtpd_check_addr: addr=devan at tpnet.pl
Apr 29 16:21:01 mosx postfix/smtpd[900]: send attr request = rewrite
Apr 29 16:21:01 mosx postfix/smtpd[900]: send attr rule = canonicalize
Apr 29 16:21:01 mosx postfix/smtpd[900]: send attr address = devan at tpnet.pl
Apr 29 16:21:01 mosx postfix/smtpd[900]: private/rewrite socket: wanted attribute: address
Apr 29 16:21:01 mosx postfix/smtpd[900]: input attribute name: address
Apr 29 16:21:01 mosx postfix/smtpd[900]: input attribute value: devan at tpnet.pl
Apr 29 16:21:01 mosx postfix/smtpd[900]: private/rewrite socket: wanted attribute: (list terminator)
Apr 29 16:21:01 mosx postfix/smtpd[900]: input attribute name: (end)
Apr 29 16:21:01 mosx postfix/smtpd[900]: rewrite_clnt: canonicalize: devan at tpnet.pl -> devan at tpnet.pl
Apr 29 16:21:01 mosx postfix/smtpd[900]: send attr request = resolve
Apr 29 16:21:01 mosx postfix/smtpd[900]: send attr address = devan at tpnet.pl
Apr 29 16:21:01 mosx postfix/smtpd[900]: private/rewrite socket: wanted attribute: transport
Apr 29 16:21:01 mosx postfix/smtpd[900]: input attribute name: transport
Apr 29 16:21:01 mosx postfix/smtpd[900]: input attribute value: smtp
Apr 29 16:21:01 mosx postfix/smtpd[900]: private/rewrite socket: wanted attribute: nexthop
Apr 29 16:21:01 mosx postfix/smtpd[900]: input attribute name: nexthop
Apr 29 16:21:01 mosx postfix/smtpd[900]: input attribute value: webmail.hansenet.de
Apr 29 16:21:01 mosx postfix/smtpd[900]: private/rewrite socket: wanted attribute: recipient
Apr 29 16:21:01 mosx postfix/smtpd[900]: input attribute name: recipient
Apr 29 16:21:01 mosx postfix/smtpd[900]: input attribute value: devan at tpnet.pl
Apr 29 16:21:01 mosx postfix/smtpd[900]: private/rewrite socket: wanted attribute: flags
Apr 29 16:21:01 mosx postfix/smtpd[900]: input attribute name: flags
Apr 29 16:21:01 mosx postfix/smtpd[900]: input attribute value: 4096
Apr 29 16:21:01 mosx postfix/smtpd[900]: private/rewrite socket: wanted attribute: (list terminator)
Apr 29 16:21:01 mosx postfix/smtpd[900]: input attribute name: (end)
Apr 29 16:21:01 mosx postfix/smtpd[900]: resolve_clnt: `devan at tpnet.pl' -> transp=`smtp' host=`webmail.hansenet.de' rcpt=`devan at tpnet.pl' flags= class=default
Apr 29 16:21:01 mosx postfix/smtpd[900]: ctable_locate: install entry key devan at tpnet.pl
Apr 29 16:21:01 mosx postfix/smtpd[900]: extract_addr: result: devan at tpnet.pl
Apr 29 16:21:01 mosx postfix/smtpd[900]: fsspace: .: block size 4096, blocks free 12582648
Apr 29 16:21:01 mosx postfix/smtpd[900]: smtpd_check_size: blocks 4096 avail 12582648 min_free 0 msg_size_limit 26214400
Apr 29 16:21:01 mosx postfix/smtpd[900]: > gqx150.internetdsl.tpnet.pl[83.3.179.150]: 250 Ok
Apr 29 16:21:01 mosx postfix/smtpd[900]: watchdog_pat: 0x30a578
Apr 29 16:21:02 mosx postfix/smtpd[900]: < gqx150.internetdsl.tpnet.pl[83.3.179.150]: RCPT TO: <budy at stephanbudach.de>
Apr 29 16:21:02 mosx postfix/smtpd[900]: extract_addr: input: <budy at stephanbudach.de>
Apr 29 16:21:02 mosx postfix/smtpd[900]: smtpd_check_addr: addr=budy at stephanbudach.de
Apr 29 16:21:02 mosx postfix/smtpd[900]: ctable_locate: move existing entry key budy at stephanbudach.de
Apr 29 16:21:02 mosx postfix/smtpd[900]: extract_addr: result: budy at stephanbudach.de
Apr 29 16:21:02 mosx postfix/smtpd[900]: connect to subsystem public/cleanup
Apr 29 16:21:02 mosx postfix/smtpd[900]: public/cleanup socket: wanted attribute: queue_id
Apr 29 16:21:02 mosx postfix/smtpd[900]: input attribute name: queue_id
Apr 29 16:21:02 mosx postfix/smtpd[900]: input attribute value: 5AC3E83661
Apr 29 16:21:02 mosx postfix/smtpd[900]: public/cleanup socket: wanted attribute: (list terminator)
Apr 29 16:21:02 mosx postfix/smtpd[900]: input attribute name: (end)
Apr 29 16:21:02 mosx postfix/smtpd[900]: send attr flags = 50
Apr 29 16:21:02 mosx postfix/smtpd[900]: 5AC3E83661: client=gqx150.internetdsl.tpnet.pl[83.3.179.150]
Apr 29 16:21:02 mosx postfix/smtpd[900]: > gqx150.internetdsl.tpnet.pl[83.3.179.150]: 250 Ok
Apr 29 16:21:02 mosx postfix/smtpd[900]: watchdog_pat: 0x30a578
Apr 29 16:21:03 mosx postfix/smtpd[900]: < gqx150.internetdsl.tpnet.pl[83.3.179.150]: DATA
Apr 29 16:21:03 mosx postfix/smtpd[900]: >>> START Data command RESTRICTIONS <<<
Apr 29 16:21:03 mosx postfix/smtpd[900]: generic_checks: name=reject_multi_recipient_bounce
Apr 29 16:21:03 mosx postfix/smtpd[900]: generic_checks: name=reject_multi_recipient_bounce status=0
Apr 29 16:21:03 mosx postfix/smtpd[900]: >>> END Data command RESTRICTIONS <<<
Apr 29 16:21:03 mosx postfix/smtpd[900]: > gqx150.internetdsl.tpnet.pl[83.3.179.150]: 354 End data with <CR><LF>.<CR><LF>
Apr 29 16:21:05 mosx postfix/smtpd[900]: public/cleanup socket: wanted attribute: status
Apr 29 16:21:05 mosx postfix/cleanup[902]: 5AC3E83661: message-id=<C3B2A3DA.A1BC980B at tpnet.pl>
Apr 29 16:21:05 mosx postfix/smtpd[900]: input attribute name: status
Apr 29 16:21:05 mosx postfix/smtpd[900]: input attribute value: 0
Apr 29 16:21:05 mosx postfix/qmgr[555]: 5AC3E83661: from=<devan at tpnet.pl>, size=2574, nrcpt=1 (queue active)
Apr 29 16:21:05 mosx postfix/smtpd[900]: public/cleanup socket: wanted attribute: reason
Apr 29 16:21:05 mosx postfix/smtpd[900]: input attribute name: reason
Apr 29 16:21:05 mosx postfix/smtpd[900]: input attribute value: (end)
Apr 29 16:21:05 mosx postfix/smtpd[900]: public/cleanup socket: wanted attribute: (list terminator)
Apr 29 16:21:05 mosx postfix/smtpd[900]: input attribute name: (end)
Apr 29 16:21:05 mosx postfix/smtpd[900]: > gqx150.internetdsl.tpnet.pl[83.3.179.150]: 250 Ok: queued as 5AC3E83661
Apr 29 16:21:05 mosx postfix/smtpd[900]: watchdog_pat: 0x30a578
Apr 29 16:21:06 mosx postfix/smtpd[900]: smtp_get: EOF
Apr 29 16:21:06 mosx postfix/smtpd[900]: disconnect from gqx150.internetdsl.tpnet.pl[83.3.179.150]
Apr 29 16:21:06 mosx postfix/smtpd[900]: master_notify: status 1
Apr 29 16:21:06 mosx postfix/smtpd[900]: connection closed
Apr 29 16:21:06 mosx postfix/smtpd[900]: watchdog_stop: 0x30a578
Apr 29 16:21:09 mosx postfix/smtpd[922]: connect from localhost[127.0.0.1]
Apr 29 16:21:09 mosx postfix/smtpd[922]: 4D6FC8367F: client=localhost[127.0.0.1]
Apr 29 16:21:09 mosx postfix/cleanup[902]: 4D6FC8367F: message-id=<C3B2A3DA.A1BC980B at tpnet.pl>
Apr 29 16:21:09 mosx postfix/qmgr[555]: 4D6FC8367F: from=<devan at tpnet.pl>, size=3193, nrcpt=1 (queue active)
Apr 29 16:21:09 mosx postfix/smtpd[922]: disconnect from localhost[127.0.0.1]
Apr 29 16:21:09 mosx postfix/smtp[903]: 5AC3E83661: to=<budy at stephanbudach.de>, relay=127.0.0.1[127.0.0.1], delay=8, status=sent (250 2.6.0 Ok, id=29903-04, from MTA([127.0.0.1]:10025): 250 Ok: queued as 4D6FC8367F)
Apr 29 16:21:09 mosx postfix/qmgr[555]: 5AC3E83661: removed
Apr 29 16:21:09 mosx postfix/lmtp[923]: 4D6FC8367F: to=<budy at stephanbudach.de>, relay=/var/imap/socket/lmtp[/var/imap/socket/lmtp], delay=0, status=sent (250 2.1.5 Ok)
Apr 29 16:21:09 mosx postfix/qmgr[555]: 4D6FC8367F: removed
Apr 29 16:21:23 mosx postfix/smtpd[898]: proxymap stream disconnect
Apr 29 16:21:23 mosx postfix/smtpd[898]: watchdog_stop: 0x30a578
Apr 29 16:21:23 mosx postfix/smtpd[898]: watchdog_start: 0x30a578
Apr 29 16:22:37 mosx postfix/smtpd[898]: rewrite stream disconnect
Apr 29 16:22:37 mosx postfix/smtpd[898]: idle timeout -- exiting
Apr 29 16:22:37 mosx postfix/smtpd[900]: watchdog_start: 0x30a578
Apr 29 16:22:37 mosx postfix/smtpd[900]: proxymap stream disconnect
Apr 29 16:22:37 mosx postfix/smtpd[900]: watchdog_stop: 0x30a578
Apr 29 16:22:37 mosx postfix/smtpd[900]: watchdog_start: 0x30a578
Apr 29 16:22:41 mosx postfix/smtpd[900]: rewrite stream disconnect
Apr 29 16:22:41 mosx postfix/smtpd[900]: watchdog_stop: 0x30a578
Apr 29 16:22:41 mosx postfix/smtpd[900]: watchdog_start: 0x30a578
Apr 29 16:22:46 mosx postfix/smtpd[900]: idle timeout -- exiting

Mir ist nicht klar warum das hier pasiert, auch wen RCPT TO erst später im Log auftaucht.

Apr 29 16:21:01 mosx postfix/smtpd[900]: < gqx150.internetdsl.tpnet.pl[83.3.179.150]: MAIL FROM: <devan at tpnet.pl>
Apr 29 16:21:01 mosx postfix/smtpd[900]: extract_addr: input: <devan at tpnet.pl>
Apr 29 16:21:01 mosx postfix/smtpd[900]: smtpd_check_addr: addr=devan at tpnet.pl
Apr 29 16:21:01 mosx postfix/smtpd[900]: send attr request = rewrite
Apr 29 16:21:01 mosx postfix/smtpd[900]: send attr rule = canonicalize
Apr 29 16:21:01 mosx postfix/smtpd[900]: send attr address = devan at tpnet.pl
Apr 29 16:21:01 mosx postfix/smtpd[900]: private/rewrite socket: wanted attribute: address
Apr 29 16:21:01 mosx postfix/smtpd[900]: input attribute name: address
Apr 29 16:21:01 mosx postfix/smtpd[900]: input attribute value: devan at tpnet.pl

Da müsste doch eigentlich so etwas herauskommen (andere Mail):

Apr 29 16:20:57 mosx postfix/smtpd[898]: < dslb-088-064-131-151.pools.arcor-ip.net[88.64.131.151]: RCPT TO:<helmdo at stephanbudach.de>
Apr 29 16:20:57 mosx postfix/smtpd[898]: extract_addr: input: <helmdo at stephanbudach.de>
Apr 29 16:20:57 mosx postfix/smtpd[898]: smtpd_check_addr: addr=helmdo at stephanbudach.de
Apr 29 16:20:57 mosx postfix/smtpd[898]: send attr request = rewrite
Apr 29 16:20:57 mosx postfix/smtpd[898]: send attr rule = canonicalize
Apr 29 16:20:57 mosx postfix/smtpd[898]: send attr address = helmdo at stephanbudach.de
Apr 29 16:20:57 mosx postfix/smtpd[898]: private/rewrite socket: wanted attribute: address
Apr 29 16:20:57 mosx postfix/smtpd[898]: input attribute name: address
Apr 29 16:20:57 mosx postfix/smtpd[898]: input attribute value: helmdo at stephanbudach.de

Cheers,
Stephan



-- 
Stephan Budach
Jung von Matt/it-services GmbH
Glashuettenstrasse 79
20357 Hamburg

Tel: +49 40-4321-1353
Fax: +49 40-4321-1114
Internet: http://www.jvm.de

Geschäftsführer: Frank Wilhelm, Ulrich Pallas
AG HH HRB 98380, Ust-ID-Nr: DE 189569691