we use recipient address verification amongst some of our own domains. on occasion, i see the following log entries:
Jul 6 08:26:22 msa-aux postfix/smsp/smtpd[2545]: connect from client.example.com[10.48.40.102] Jul 6 08:26:22 msa-aux postfix/smsp/smtpd[2545]: Anonymous TLS connection established from client.example.com[10.48.40.102]: TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits) Jul 6 08:26:23 msa-aux postfix/cleanup[2552]: 3h5pzz1NVpzyQm: message-id=<3h5pzz1nvpz...@msa-aux.systems.example.com> Jul 6 08:26:23 msa-aux postfix/qmgr[5256]: 3h5pzz1NVpzyQm: from=<double-bou...@systems.example.com>, size=238, nrcpt=1 (queue active) Jul 6 08:26:29 msa-aux postfix/smsp/smtpd[2545]: NOQUEUE: reject: RCPT from client.example.com[10.48.40.102]: 450 4.1.1 <j...@example.com>: Recipient address rejected: unverified address: Address verification in progress; from=<rsm...@mail.example.com> to=<j...@example.com> proto=ESMTP helo=<client.example.com> Jul 6 08:26:29 msa-aux postfix/smsp/smtpd[2545]: disconnect from client.example.com[10.48.40.102] Jul 6 08:26:29 msa-aux postfix/kvcc-internal/smtp[2553]: 3h5pzz1NVpzyQm: to=<j...@example.com>, relay=mta.example.com[10.3.70.5]:25, delay=6.4, delays=0.01/0.02/6.2/0.21, dsn=2.1.5, status=deliverable (250 2.1.5 Ok) Jul 6 08:26:29 msa-aux postfix/qmgr[5256]: 3h5pzz1NVpzyQm: removed Jul 6 08:28:14 msa-aux postfix/verify[2551]: close database /var/lib/postfix/verify_cache.db: No such file or directory (possible Berkeley DB bug) postfix appears to begin the verification process, but seems to reject the message just before the recipient is determined to be deliverable. here's the related log snippit from 10.3.70.5: Jul 6 08:26:23 mta1 postfix/postscreen[16943]: CONNECT from [10.36.40.26]:45643 to [10.3.70.5]:25 Jul 6 08:26:29 mta1 postfix/postscreen[16943]: PASS OLD [10.36.40.26]:45643 Jul 6 08:26:29 mta1 postfix/smtpd[16952]: connect from msa-aux.systems.example.com[10.36.40.26] Jul 6 08:26:29 mta1 postfix/smtpd[16952]: Anonymous TLS connection established from msa-aux.systems.example.com[10.36.40.26]: TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits) Jul 6 08:26:29 mta1 postfix/smtpd[16952]: 3h5q054KcRzJmm1: client=msa-aux.systems.example.com[10.36.40.26] Jul 6 08:26:29 mta1 postfix/smtpd[16952]: disconnect from msa-aux.systems.example.com[10.36.40.26] a bit later, a message from the same client, to that now verified recipient, is processed successfully: Jul 6 08:43:50 msa-aux postfix/smsp/smtpd[2642]: Anonymous TLS connection established from client.example.com[10.48.40.102]: TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits) Jul 6 08:43:50 msa-aux postfix/smsp/smtpd[2642]: 3h5qN66fp6zyQm: client=client.example.com[10.48.40.102], sasl_method=PLAIN, sasl_username=client_postfix Jul 6 08:43:50 msa-aux postfix/cleanup[2648]: 3h5qN66fp6zyQm: message-id=<d09f36dab46b8e9ad95da0e90d1aa...@www.example.com> Jul 6 08:43:50 msa-aux postfix/qmgr[5256]: 3h5qN66fp6zyQm: from=<rsm...@mail.example.com>, size=2123, nrcpt=1 (queue active) Jul 6 08:43:50 msa-aux postfix/smsp/smtpd[2642]: disconnect from client.example.com[10.48.40.102] Jul 6 08:43:51 msa-aux postfix/kvcc-internal/smtp[2649]: 3h5qN66fp6zyQm: to=<j...@example.com>, relay=mta.example.com[10.3.70.5]:25, delay=0.24, delays=0.04/0.02/0.01/0.18, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 3h5qN710RqzJmm1) Jul 6 08:43:51 msa-aux postfix/qmgr[5256]: 3h5qN66fp6zyQm: removed this isn't consistent - most mail is verified and then relayed successfully. it seems to happen once every few hundred messages or so. how can i further troubleshoot why this is occurring? on a semi-related note, how can the verified recipient be included in the log entry on the server against which verification is being performed?: Jul 6 08:26:29 mta1 postfix/smtpd[16952]: 3h5q054KcRzJmm1: client=msa-aux.systems.example.com[10.36.40.26] this would be helpful in troubleshooting. thanks -ben
