Ahh that makes sense; I'd just written the logging order off to multiple
processes and flushing.
Neither address_verify_poll_count nor address_verify_poll_delay are in the
master.cf. It does use smtpd_proxy_filter (amavis) but I don't know if that
can impact at this stage?
This is indeed on VMWare hosted box.
However out of curiosity as much as clutching at straws I cleared the
verify cache and restarted postfix. After a couple of test emails it now
appears to be refusing the email instantly as expected. My best guess
would be that the invalid test address I was using has been accepted at
some point in my configuration tweaks, and based on the docs referencing
its optimistic caching it may have been operating on that previous accept?
Does this sound like a valid interpretation?
Cheers,
Daniel
On Wed, Feb 18, 2015 at 11:28 AM, Wietse Venema <wie...@porcupine.org>
wrote:
> 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
>
