Shawn Heisey:
> On 5/18/2011 5:09 PM, Wietse Venema wrote:
> > This applies restrictions before RCPT TO, so you reported
> > the wrong Postfix configuration, or you have parameter
> > settings in master.cf that you should also report about.
...
> I actually do hope that this is a mistake on my part, so I can get it
> corrected quickly and not trouble you any further. Here's the master.cf
> file:
>
> http://pastebin.com/UZPVfzB5
In master.cf you have "smtpd_delay_reject = no". With this, Postfix
will apply smtpd_sender_restrictions when it receives the MAIL FROM
command, instead of waiting until the RCPT TO command.
In your log, Postfix rejects the MAIL FROM command. This means you
have some pipelining check in some smtpd_sender_restrictions setting,
perhaps via some access table lookup.
Finally, with all the anonymization you haven't proven that the client
IP address actually matches mynetworks. For that, you'd have to turn
on verbose logging (debug_peer_list = 127.0.0.1, or whatever the IP).
That will show all the restrictions that Postfix evaluates.
With my own system, permit_mynetworks does override
reject_unauth_pipelining, so I guess you either aren't matching
mynetworks, or you have given incorrect confguration info, or the
Debian maintainer introduced an error.
Below are examples for Postfix versions 2.9 (the latest) and 2.5
(the oldest supported release).
Wietse
% postconf mail_version
mail_version = 2.9-20110501
% postconf smtpd_delay_reject smtpd_sender_restrictions
smtpd_delay_reject = no
smtpd_sender_restrictions = permit_mynetworks reject_unauth_pipelining
% od -cb /tmp/pipelined
0000000 h e l o l o c a l h o s t \r \n
150 145 154 157 040 154 157 143 141 154 150 157 163 164 015 012
0000020 m a i l f r o m : < w i e t s
155 141 151 154 040 146 162 157 155 072 074 167 151 145 164 163
0000040 e @ l o c a l h o s t > \r \n r c
145 100 154 157 143 141 154 150 157 163 164 076 015 012 162 143
0000060 p t t o : < w i e t s e @ l o
160 164 040 164 157 072 074 167 151 145 164 163 145 100 154 157
0000100 c a l h o s t > \r \n d a t a \r \n
143 141 154 150 157 163 164 076 015 012 144 141 164 141 015 012
0000120 b l a h \r \n . \r \n q u i t \r \n
142 154 141 150 015 012 056 015 012 161 165 151 164 015 012
0000137
% nc -w 5 127.0.0.1 25 < /tmp/pipelined
220 tail.porcupine.org ESMTP Postfix
250 tail.porcupine.org
250 2.1.0 Ok
250 2.1.5 Ok
354 End data with <CR><LF>.<CR><LF>
250 2.0.0 Ok: queued as 3QZXv46m0vznjlT
221 2.0.0 Bye
% tail /var/log/maillog
May 18 20:14:08 tail postfix/smtpd[7496]: connect from localhost[127.0.0.1]
May 18 20:14:08 tail postfix/smtpd[7496]: improper command pipelining after
HELO from localhost[127.0.0.1]: mail from:<wietse@localhost>\r\nrcpt
to:<wietse@localhost>\r\ndata\r\nblah\r\n.\r\nquit\r\n
May 18 20:14:08 tail postfix/smtpd[7496]: 3QZXv46m0vznjlT:
client=localhost[127.0.0.1]
May 18 20:14:08 tail postfix/cleanup[7499]: 3QZXv46m0vznjlT:
message-id=<3qzxv46m0vzn...@tail.porcupine.org>
May 18 20:14:08 tail postfix/smtpd[7496]: disconnect from localhost[127.0.0.1]
May 18 20:14:08 tail postfix/qmgr[1819]: 3QZXv46m0vznjlT:
from=<wie...@localhost.porcupine.org>, size=318, nrcpt=1 (queue active)
May 18 20:14:09 tail postfix/local[7500]: 3QZXv46m0vznjlT:
to=<wie...@localhost.porcupine.org>, orig_to=<wietse@localhost>, relay=local,
delay=0.1, delays=0.02/0.04/0/0.03, dsn=2.0.0, status=sent (delivered to
mailbox)
May 18 20:14:09 tail postfix/qmgr[1819]: 3QZXv46m0vznjlT: removed
% postconf mail_version
mail_version = 2.5.13
% postconf smtpd_delay_reject smtpd_sender_restrictions
smtpd_delay_reject = no
smtpd_sender_restrictions = permit_mynetworks reject_unauth_pipelining
% od -cb /tmp/pipelined
0000000 h e l o l o c a l h o s t \r \n
150 145 154 157 040 154 157 143 141 154 150 157 163 164 015 012
0000020 m a i l f r o m : < w i e t s
155 141 151 154 040 146 162 157 155 072 074 167 151 145 164 163
0000040 e @ l o c a l h o s t > \r \n r c
145 100 154 157 143 141 154 150 157 163 164 076 015 012 162 143
0000060 p t t o : < w i e t s e @ l o
160 164 040 164 157 072 074 167 151 145 164 163 145 100 154 157
0000100 c a l h o s t > \r \n d a t a \r \n
143 141 154 150 157 163 164 076 015 012 144 141 164 141 015 012
0000120 b l a h \r \n . \r \n q u i t \r \n
142 154 141 150 015 012 056 015 012 161 165 151 164 015 012
0000137
% nc -w 5 127.0.0.1 25 < /tmp/pipelined
220 tail.porcupine.org ESMTP Postfix
250 tail.porcupine.org
250 2.1.0 Ok
250 2.1.5 Ok
354 End data with <CR><LF>.<CR><LF>
250 2.0.0 Ok: queued as 96147547CAE
221 2.0.0 Bye
% tail /var/log/maillog
May 18 20:18:48 tail postfix/smtpd[12863]: connect from localhost[127.0.0.1]
May 18 20:18:48 tail postfix/smtpd[12863]: 96147547CAE:
client=localhost[127.0.0.1]
May 18 20:18:48 tail postfix/cleanup[12867]: 96147547CAE:
message-id=<20110519001848.96147547...@tail.porcupine.org>
May 18 20:18:48 tail postfix/smtpd[12863]: disconnect from localhost[127.0.0.1]
May 18 20:18:48 tail postfix/qmgr[12860]: 96147547CAE:
from=<wie...@localhost.porcupine.org>, size=355, nrcpt=1 (queue active)
May 18 20:18:48 tail postfix/local[12868]: 96147547CAE:
to=<wie...@localhost.porcupine.org>, orig_to=<wietse@localhost>, relay=local,
delay=0.02, delays=0.01/0.01/0/0, dsn=2.0.0, status=sent (delivered to mailbox)
May 18 20:18:48 tail postfix/qmgr[12860]: 96147547CAE: removed
