On 5/18/2011 6:27 PM, Wietse Venema wrote:
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.
I commented out the extra delay options in master.cf. I don't think
that's affecting it anyway, as those only listen on localhost, and on
ports other than 25. The only things I anonymized were my hostnames and
the *public* IPs on mynetworks, everything else was left alone. The
10.2.1.39 address in the previous log was the actual address, and should
match 10.0.0.0/8 from mynetworks.
Below is a peer debug log at level 9 with those delay options commented.
The only thing I anonymized was the the hostnames, IP addresses are
actual. It did the same thing when I added 10.2.1.39 to mynetworks. To
create this, I telnetted from the monitor server to postfix on port 25,
typed in mail, then disconnected the telnet. If I send a properly
formatted mail command instead of the single word, it still sends the
503. In this log, I left the postfix hostname alone, but I changed the
hostname of the monitor server.
May 18 18:49:19 nexus2 postfix/smtpd[24852]: connect from
monitor.example.com[10.2.1.39]
May 18 18:49:19 nexus2 postfix/smtpd[24852]: match_hostname:
monitor.example.com ~? 127.0.0.0/8
May 18 18:49:19 nexus2 postfix/smtpd[24852]: match_hostaddr: 10.2.1.39
~? 127.0.0.0/8
May 18 18:49:19 nexus2 postfix/smtpd[24852]: match_hostname:
monitor.example.com ~? 10.0.0.0/8
May 18 18:49:19 nexus2 postfix/smtpd[24852]: match_hostaddr: 10.2.1.39
~? 10.0.0.0/8
May 18 18:49:19 nexus2 postfix/smtpd[24852]: >
monitor.example.com[10.2.1.39]: 220 nexus2.example.com ESMTP Postfix
(Debian/GNU)
May 18 18:49:19 nexus2 postfix/smtpd[24852]: watchdog_pat: 0x7fe596441400
May 18 18:49:19 nexus2 postfix/smtpd[24852]: vstream_fflush_some: fd 24
flush 58
May 18 18:49:21 nexus2 postfix/smtpd[24852]: vstream_buf_get_ready: fd
24 got 6
May 18 18:49:21 nexus2 postfix/smtpd[24852]: <
monitor.example.com[10.2.1.39]: mail
May 18 18:49:21 nexus2 postfix/smtpd[24852]: >
monitor.example.com[10.2.1.39]: 503 5.5.1 Error: send HELO/EHLO first
May 18 18:49:21 nexus2 postfix/smtpd[24852]: watchdog_pat: 0x7fe596441400
May 18 18:49:21 nexus2 postfix/smtpd[24852]: vstream_fflush_some: fd 24
flush 39
May 18 18:49:23 nexus2 postfix/smtpd[24852]: smtp_get: EOF
May 18 18:49:23 nexus2 postfix/smtpd[24852]: match_hostname:
monitor.example.com ~? 127.0.0.0/8
May 18 18:49:23 nexus2 postfix/smtpd[24852]: match_hostaddr: 10.2.1.39
~? 127.0.0.0/8
May 18 18:49:23 nexus2 postfix/smtpd[24852]: match_hostname:
monitor.example.com ~? 10.0.0.0/8
May 18 18:49:23 nexus2 postfix/smtpd[24852]: match_hostaddr: 10.2.1.39
~? 10.0.0.0/8
May 18 18:49:23 nexus2 postfix/smtpd[24852]: lost connection after MAIL
from monitor.example.com[10.2.1.39]
May 18 18:49:23 nexus2 postfix/smtpd[24852]: disconnect from
monitor.example.com[10.2.1.39]
I'm glad to hear that you aren't having this problem, which gives me
some hope that it's isolated to my specific config, the debian package,
or 2.7.1.
Thanks,
Shawn
