On Mon, 04 Jun 2001, Eric S. Raymond wrote:
Matthias Andree <ma(_at_)dt(_dot_)e-technik(_dot_)uni-dortmund(_dot_)de>:
Pardon me, but it looks to me like postfix is doing something weird and
nonconformant here. After the 550 it should not be anding back a 220!
I don't get your point. fetchmail has two SMTP connections at that time,
so 220 for the second connection is fine.
To me, it looks like fetchmail intersperses the output of two separate SMTP
sessions it keeps:
fetchmail has the initial connection to the local SMTP sink, tries to
deliver the spam, and this spam triggers a regexp filter, fetchmail
reads 550 back. It then tries to bounce back to the sender, opening a
second connection. This is also visible from the Postfix logs:
| Jun 1 10:57:09 emma1 postfix/smtpd[3919]: connect from localhost[127.0.0.1]
... tons of mail successfully received by smtpd, pid 3919
|Jun 1 10:58:25 emma1 postfix/smtpd[3919]: 6B585A20AE:
client=localhost[127.0.0.1]
|Jun 1 10:58:25 emma1 postfix/smtpd[3919]: reject: RCPT from
localhost[127.0.0.1]: 550
</aimcque/jmail.rcv/9/QM253b16f482(_at_)public(_dot_)tpt(_dot_)tj(_dot_)cn>:
Sender address rejected: We're not playing strange Sendmail games here.;
from=</aimcque/jmail.rcv/9/QM253b16f482(_at_)public(_dot_)tpt(_dot_)tj(_dot_)cn>
to=<emma(_at_)localhost>
Jun 1 10:58:25 emma1 postfix/smtpd[4723]: connect from localhost[127.0.0.1]
|Jun 1 10:58:25 emma1 postfix/smtpd[4723]: 87399A2115:
client=localhost[127.0.0.1]
|Jun 1 10:58:25 emma1 postfix/cleanup[4724]: 87399A2115:
message-id=<20010601085825(_dot_)87399A2115(_at_)emma1(_dot_)emma(_dot_)line(_dot_)org>
|Jun 1 10:58:25 emma1 postfix/qmgr[12031]: 87399A2115:
from=<FETCHMAIL-DAEMON(_at_)localhost(_dot_)emma(_dot_)line(_dot_)org>,
size=2574, nrcpt=1 (queue active)
|Jun 1 10:58:25 emma1 postfix/smtpd[4723]: disconnect from localhost[127.0.0.1]
|Jun 1 10:58:25 emma1 postfix/smtpd[3919]: reject: RCPT from
localhost[127.0.0.1]: 550
</aimcque/jmail.rcv/9/QM253b16f482(_at_)public(_dot_)tpt(_dot_)tj(_dot_)cn>:
Sender address rejected: We're not playing strange Sendmail games here.;
from=</aimcque/jmail.rcv/9/QM253b16f482(_at_)public(_dot_)tpt(_dot_)tj(_dot_)cn>
to=<emma(_at_)localhost>
What's going on here?
I did some debugging.
What happens is:
1 fetchmail fetches mail and feeds some mail to the local SMTP sink
successfully
2 postfix dislikes a sender address, but defers the error message until
after the RCPT.
3 fetchmail opens a second connection to bounce the mail back to the
original sender
4 fetchmail sends another RCPT to the local recipient into the first
connection, but as the old MAIL FROM still is invalid, Postfix rejects
this again, fetchmail logs "can't even send to emma".
The whole game can be avoided by configuring Postfix to
"smtpd_delay_reject = no", but that seems to adversely affect
compatibility. I'm not sure how sendmail behaves, but Postfix mimicks
sendmail very closely usually.
Quote from Postfix' RELEASE_NOTES:
: Incompatible changes with postfix-19990601:
: ===========================================
:
: - The SMTP server now delays all UCE restrictions until the RCPT
: TO, VRFY or ETRN command. This makes the restrictions more useful,
: because many SMTP clients do not expect negative responses earlier
: in the protocol. In order to restore the old behavior, specify
: "smtpd_delay_reject = no" in /etc/postfix/main.cf.
Now, there have been a bunch of Postfix releases and I'm wondering why
this bit so late only.
Log files:
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: > localhost[127.0.0.1]: 220
emma1.emma.line.org ESMTP Postfix (Snapshot-20010222)
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: connect from localhost[127.0.0.1]
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: watchdog_pat: 0x80736f0
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: < localhost[127.0.0.1]: EHLO
localhost
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: > localhost[127.0.0.1]:
250-emma1.emma.line.org
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: > localhost[127.0.0.1]:
250-PIPELINING
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: > localhost[127.0.0.1]: 250-SIZE
10240000
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: > localhost[127.0.0.1]: 250-ETRN
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: > localhost[127.0.0.1]: 250 8BITMIME
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: watchdog_pat: 0x80736f0
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: < localhost[127.0.0.1]: MAIL
FROM:</strange/sender(_at_)dt(_dot_)e-technik(_dot_)uni-dortmund(_dot_)de>
SIZE=542
...
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: > localhost[127.0.0.1]: 250 Ok
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: watchdog_pat: 0x80736f0
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: < localhost[127.0.0.1]: RCPT
TO:<emma(_at_)localhost>
...
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: check_access:
/strange/sender(_at_)dt(_dot_)e-technik(_dot_)uni-dortmund(_dot_)de
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: dict_regexp_lookup:
/etc/postfix/regexp_sender:
/strange/sender(_at_)dt(_dot_)e-technik(_dot_)uni-dortmund(_dot_)de
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: mac_parse: 550 We're not playing
strange Sendmail games here.
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: check_table_result:
regexp:/etc/postfix/regexp_sender 550 We're not playing strange Sendmail games
here. /strange/sender(_at_)dt(_dot_)e-technik(_dot_)uni-dortmund(_dot_)de
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: reject: RCPT from
localhost[127.0.0.1]: 550
</strange/sender(_at_)dt(_dot_)e-technik(_dot_)uni-dortmund(_dot_)de>: Sender
address rejected: We're not playing strange Sendmail games here.;
from=</strange/sender(_at_)dt(_dot_)e-technik(_dot_)uni-dortmund(_dot_)de>
to=<emma(_at_)localhost>
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: generic_checks:
name=check_sender_access status=2
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: > localhost[127.0.0.1]: 550
</strange/sender(_at_)dt(_dot_)e-technik(_dot_)uni-dortmund(_dot_)de>: Sender
address rejected: We're not playing strange Sendmail games here.
Jun 4 11:42:54 emma1 postfix/smtpd[22235]: watchdog_pat: 0x80736f0
...
Then, a new, successful session (PID 22238) is logged, receiving mail
from fetchmail-daemon(_at_)localhost to
/strange/sender(_at_)dt(_dot_)e-technik(_dot_)uni-dortmund(_dot_)de(_dot_)
Then, fetchmail resumes
the old connection:
Jun 4 11:42:55 emma1 postfix/smtpd[22235]: < localhost[127.0.0.1]: RCPT
TO:<emma(_at_)localhost>
Jun 4 11:42:55 emma1 postfix/smtpd[22235]: check_access:
/strange/sender(_at_)dt(_dot_)e-technik(_dot_)uni-dortmund(_dot_)de
Jun 4 11:42:55 emma1 postfix/smtpd[22235]: dict_regexp_lookup:
/etc/postfix/regexp_sender:
/strange/sender(_at_)dt(_dot_)e-technik(_dot_)uni-dortmund(_dot_)de
Jun 4 11:42:55 emma1 postfix/smtpd[22235]: mac_parse: 550 We're not playing
strange Sendmail games here.
Jun 4 11:42:55 emma1 postfix/smtpd[22235]: check_table_result:
regexp:/etc/postfix/regexp_sender 550 We're not playing strange Sendmail games
here. /strange/sender(_at_)dt(_dot_)e-technik(_dot_)uni-dortmund(_dot_)de
Jun 4 11:42:55 emma1 postfix/smtpd[22235]: reject: RCPT from
localhost[127.0.0.1]: 550
</strange/sender(_at_)dt(_dot_)e-technik(_dot_)uni-dortmund(_dot_)de>: Sender
address rejected: We're not playing strange Sendmail games here.;
from=</strange/sender(_at_)dt(_dot_)e-technik(_dot_)uni-dortmund(_dot_)de>
to=<emma(_at_)localhost>
Jun 4 11:42:55 emma1 postfix/smtpd[22235]: generic_checks:
name=check_sender_access status=2
Jun 4 11:42:55 emma1 postfix/smtpd[22235]: > localhost[127.0.0.1]: 550
</strange/sender(_at_)dt(_dot_)e-technik(_dot_)uni-dortmund(_dot_)de>: Sender
address rejected: We're not playing strange Sendmail games here.
Jun 4 11:42:55 emma1 postfix/smtpd[22235]: watchdog_pat: 0x80736f0
Jun 4 11:42:55 emma1 postfix/smtpd[22235]: < localhost[127.0.0.1]: RSET
Jun 4 11:42:55 emma1 postfix/smtpd[22235]: > localhost[127.0.0.1]: 250 Ok
Jun 4 11:42:55 emma1 postfix/smtpd[22235]: watchdog_pat: 0x80736f0
Jun 4 11:43:11 emma1 postfix/smtpd[22235]: smtp_get: EOF
Jun 4 11:43:11 emma1 postfix/smtpd[22235]: lost connection after RSET from
localhost[127.0.0.1]
...