Daniel Hopkirk - RandomInsanity:
> Thanks Wietse,
>
> I'm still a little confused here. Based on the logs (and what I expect) the
> server 202.137.240.16 which is the destination server for this mail has
> rejected the recipient with a permanent error.
The "user unknown" is logged AFTER the SMTP server has already
greylisted the remote SMTP client. Postfix may be smart, bit it
cannot predict the future. I am still working on that part.
This is the order in which events are logged to the maillog file:
First, the address verify daemon injects an address verification
probe message into the mail queue.
Feb 17 14:54:24 scanner-nz-01 postfix/cleanup[58630]: 13761BC51:
message-id=<20150217015424.13761b...@scanner-nz-01.nownz.co.nz>
Feb 17 14:54:24 scanner-nz-01 postfix/qmgr[55254]: 13761BC51: from=<
double-bou...@scanner-nz-01.nownz.co.nz>, size=264, nrcpt=1
(queue active)
The Postfix SMTP server is supposed to wait up to 9 seconds for the
address verification probe to complete. In the absence of a result
(more on that later), the Postfix SMTP server continues with other
restrictions and greylists the recipient.
Feb 17 14:54:24 scanner-nz-01 postfix/smtpd[58620]: NOQUEUE: reject:
RCPT from unknown[65.55.34.24]: 450 4.7.1
<nosuchem...@randominsanity.net.nz>: Recipient address rejected:
Greylisted for 5 minutes; from=<hopper...@hotmail.com>
to=<nosuchem...@randominsanity.net.nz> proto=ESMTP
helo=<COL004-OMC1S14.hotmail.com>
Then, the Postfix SMTP CLIENT reports that the downstream server
rejects the recipient. But this news comes too late. The SMTP
server has already greylisted the remote SMTP client.
Feb 17 14:54:24 scanner-nz-01 postfix/smtp[58631]: 13761BC51:
to=<nosuchem...@randominsanity.net.nz>,
relay=202.137.240.16[202.137.240.16]:25, delay=0.06,
delays=0/0/0.01/0.05, dsn=5.1.1, status=undeliverable (host
202.137.240.16[202.137.240.16] said: 550 5.1.1
<nosuchem...@randominsanity.net.nz>: Recipient address rejected:
User unknown in local recipient table (in reply to RCPT TO
command))
Now, all this happens within the same second, and that suggests
that there is a problem. This a piece of code from the SMTP server
that collects the address verify result:
for (count = 0; /* see below */ ; /* see below */ ) {
verify_status = verify_clnt_query(addr, &rcpt_status, why);
if (verify_status != VRFY_STAT_OK || rcpt_status != DEL_RCPT_STAT_TODO)
break;
if (++count >= var_verify_poll_count)
break;
sleep(var_verify_poll_delay);
}
I see no address_verify_poll_count or address_verify_poll_delay
settings in your "postconf -n" output. Any chance you have
these settings in master.cf?
The verify_clnt_query() function does not return until it has a
received a reply from the verify daemon. This would mean that the
verify daemon immediately replied with VRFY_STAT_BAD, but then both
the smtpd(8) and verify(8) daemons should have logged a warning.
The only way that I can explain the above logging is that something
is causing the sleep() call to return immediately. As if the wakeup
time is translated into absolute time, and the hardware clock is
several seconds ahead of the OS's idea of time.
Does this Postfix instance run inside a VM? They do weird things
with clocks.
Wietse
