Google Groups no longer supports new Usenet posts or subscriptions. Historical content remains viewable.
Dismiss

address verification: "Address verification in progress"

783 views
Skip to first unread message

btb

unread,
Jul 7, 2014, 12:25:53 PM7/7/14
to
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=<3h5pzz1...@msa-aux.systems.example.com>
Jul 6 08:26:23 msa-aux postfix/qmgr[5256]: 3h5pzz1NVpzyQm: from=<double...@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 <jd...@example.com>: Recipient address rejected: unverified address: Address verification in progress; from=<rsm...@mail.example.com> to=<jd...@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=<jd...@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=<d09f36dab46b8e9a...@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=<jd...@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

btb

unread,
Jul 7, 2014, 12:29:48 PM7/7/14
to
On 2014.07.07 12.25, btb wrote:
> 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=<3h5pzz1...@msa-aux.systems.example.com>
> Jul 6 08:26:23 msa-aux postfix/qmgr[5256]: 3h5pzz1NVpzyQm: from=<double...@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 <jd...@example.com>: Recipient address rejected: unverified address: Address verification in progress; from=<rsm...@mail.example.com> to=<jd...@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/example-internal/smtp[2553]: 3h5pzz1NVpzyQm: to=<jd...@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=<d09f36dab46b8e9a...@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/example-internal/smtp[2649]: 3h5qN66fp6zyQm: to=<jd...@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

i neglected to include my config. please see below.

>postconf -nf
address_verify_negative_expire_time = 30s
address_verify_negative_refresh_time = 30s
address_verify_positive_expire_time = 12h
address_verify_positive_refresh_time = 6h
alias_database =
alias_maps =
allow_local_senders = check_sender_access
hash:${table_directory}/allowed_sender_domains
append_dot_mydomain = no
base_recipient_restrictions = reject_non_fqdn_sender
reject_unknown_sender_domain reject_non_fqdn_recipient
reject_unknown_recipient_domain check_recipient_access
hash:${table_directory}/bogus_domains check_recipient_access
hash:${table_directory}/recipient_verification_domains
reject_unauth_pipelining
biff = no
config_directory = /etc/postfix
delay_warning_time = 4h
disable_vrfy_command = yes
enable_long_queue_ids = yes
local_recipient_maps =
local_transport = error:local mail delivery is disabled
message_size_limit = 10485760
mydestination =
mydomain = systems.example.com
myhostname = ${smtpd_myhostname}
mynetworks =
myorigin = ${mydomain}
parent_domain_matches_subdomains =
pki_directory = ${config_directory}/pki
proxy_read_maps = ${virtual_alias_maps} ${virtual_mailbox_domains}
${virtual_mailbox_maps}
proxy:ldap:${table_directory}/non_auth_submitters.cf
recipient_canonical_maps = hash:${table_directory}/canonical_recipients
smspd_banner = ${smspd_myhostname} ESMTP mail_submission_service
smspd_myhostname = msa.${mydomain}
smspd_recipient_restrictions = base_recipient_restrictions
permit_sasl_authenticated check_client_access
ldap:${table_directory}/non_auth_submitters.cf reject
smspd_tls_cert_file = ${pki_directory}/${smspd_myhostname}-cert.pem
smspd_tls_key_file = ${pki_directory}/${smspd_myhostname}-key.pem
smtp_address_preference = ipv4
smtp_helo_name = ${smtpd_myhostname}
smtp_tls_CAfile = ${smtpd_tls_CAfile}
smtp_tls_note_starttls_offer = yes
smtp_use_tls = yes
smtpd_banner = ${smtpd_myhostname} ESMTP mail_transfer_service
smtpd_data_restrictions = reject_unauth_pipelining
smtpd_etrn_restrictions = reject
smtpd_helo_required = yes
smtpd_myhostname = mta.${mydomain}
smtpd_recipient_restrictions = base_recipient_restrictions
check_client_access
ldap:${table_directory}/non_auth_submitters.cf
reject_unauth_destination
permit
smtpd_relay_restrictions =
smtpd_restriction_classes = base_recipient_restrictions
smspd_recipient_restrictions allow_local_senders
smtpd_sasl_auth_enable = no
smtpd_sasl_path = inet:[::1]:sasl
smtpd_sasl_security_options = noanonymous
smtpd_sasl_type = dovecot
smtpd_sender_restrictions = check_recipient_access
hash:${table_directory}/local_recipient_domains check_sender_access
hash:${table_directory}/bogus_domains
smtpd_tls_CAfile = /etc/pki/trusted_root_authorities/ca-certificates.crt
smtpd_tls_auth_only = yes
smtpd_tls_cert_file = ${pki_directory}/${smtpd_myhostname}-cert.pem
smtpd_tls_dh1024_param_file = ${pki_directory}/dh_1024.pem
smtpd_tls_dh512_param_file = ${pki_directory}/dh_512.pem
smtpd_tls_key_file = ${pki_directory}/${smtpd_myhostname}-key.pem
smtpd_tls_loglevel = 1
smtpd_tls_received_header = yes
smtpd_use_tls = yes
strict_rfc821_envelopes = yes
table_directory = ${config_directory}/tables
transport_maps = hash:${table_directory}/transports
unknown_address_reject_code = 554
unknown_client_reject_code = 554
unknown_hostname_reject_code = 554
unknown_local_recipient_reject_code = 554
unknown_relay_recipient_reject_code = 554
unverified_recipient_reject_code = 550
unverified_sender_reject_code = 550
virtual_alias_domains =
virtual_alias_maps =
proxy:ldap:${table_directory}/virtual_alias_maps-address_literals.cf
proxy:ldap:${table_directory}/virtual_alias_maps-domains.cf
virtual_gid_maps = ${virtual_uid_maps}
virtual_mailbox_base = /var/mail/virtual
virtual_mailbox_domains =
proxy:ldap:${table_directory}/virtual_mailbox_domains.cf
virtual_mailbox_maps = proxy:ldap:${table_directory}/virtual_mailbox_maps.cf
virtual_minimum_uid = 999
virtual_uid_maps = static:999

>cat tables/recipient_verification_domains
# domains we own, for which recipient verification should be done
example.com reject_unverified_recipient
mail.example.com reject_unverified_recipient
systems.example.com reject_unverified_recipient

>postconf -Mf
smtp inet n - n - - smtpd
smsp inet n - n - - smtpd
-o syslog_name=postfix/smsp -o myhostname=${smspd_myhostname}
-o smtpd_banner=${smspd_banner} -o
smtpd_tls_key_file=${smspd_tls_key_file}
-o smtpd_tls_cert_file=${smspd_tls_cert_file} -o
smtpd_sasl_auth_enable=yes
-o smtpd_recipient_restrictions=smspd_recipient_restrictions
pickup fifo n - - 60 1 pickup
cleanup unix n - n - 0 cleanup
qmgr fifo n - n 300 1 qmgr
tlsmgr unix - - - 1000? 1 tlsmgr
rewrite unix - - n - - trivial-rewrite
bounce unix - - - - 0 bounce
defer unix - - - - 0 bounce
trace unix - - - - 0 bounce
verify unix - - - - 1 verify
flush unix n - - 1000? 0 flush
proxymap unix - - n - - proxymap
proxywrite unix - - n - 1 proxymap
smtp unix - - - - - smtp
-o smtp_helo_name=msa-aux.example.com
-o smtp_generic_maps=regexp:${table_directory}/generic.regexp
relay unix - - - - - smtp
-o smtp_fallback_relay=
showq unix n - - - - showq
error unix - - - - - error
retry unix - - - - - error
discard unix - - - - - discard
virtual unix - n n - - virtual
lmtp unix - - - - - lmtp
anvil unix - - - - 1 anvil
scache unix - - - - 1 scache
example-internal unix - - - - - smtp
-o syslog_name=postfix/example-internal

Wietse Venema

unread,
Jul 7, 2014, 12:39:52 PM7/7/14
to
btb:
> Jul 6 08:26:29 msa-aux postfix/example-internal/smtp[2553]:
> 3h5pzz1NVpzyQm: to=<jd...@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)

It took 6.4 seconds to verify this recipient, of which 6.2 seconds
were spent connecting over TCP and completing the SMTP handshake
with the remote SMTP server.

> 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?

Find out why it takes 6.2 seconds to connect over TCP and to
complete the SMTP handshake with the remote SMTP server.

Wietse

Robert Schetterer

unread,
Jul 7, 2014, 1:09:41 PM7/7/14
to
additional you may check this

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)


Best Regards
MfG Robert Schetterer

--
[*] sys4 AG

http://sys4.de, +49 (89) 30 90 46 64
Franziskanerstra�e 15, 81669 M�nchen

Sitz der Gesellschaft: M�nchen, Amtsgericht M�nchen: HRB 199263
Vorstand: Patrick Ben Koetter, Marc Schiffbauer
Aufsichtsratsvorsitzender: Florian Kirstein

btb

unread,
Jul 7, 2014, 1:36:55 PM7/7/14
to
On 2014.07.07 12.39, Wietse Venema wrote:
> Find out why it takes 6.2 seconds to connect over TCP and to
> complete the SMTP handshake with the remote SMTP server.

given postscreen_greet_wait, it's a coincidence that the remote server's
postscreen logs show that same delay ~6 second delay, but list it as
PASS OLD:

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

the timing seems to suggest postscreen, but obviously PASS OLD says
otherwise. other PASS OLD log entries show no such delay. i'll
investigate further.

in the mean time, how can i configure postfix to wait longer for
verification?

-ben

Noel Jones

unread,
Jul 7, 2014, 1:58:46 PM7/7/14
to
The controls are:
http://www.postfix.org/postconf.5.html#address_verify_poll_count
(default 3)
http://www.postfix.org/postconf.5.html#address_verify_poll_delay
(default 3s)

Use great care when adjusting these.

If postfix waits too long for address verification replies, it can
cause a denial of service by keeping all the smtpd workers busy
doing nothing.

The better solution is to identify and fix your network delay.


-- Noel Jones

Wietse Venema

unread,
Jul 7, 2014, 2:06:00 PM7/7/14
to
btb:
> On 2014.07.07 12.39, Wietse Venema wrote:
> > Find out why it takes 6.2 seconds to connect over TCP and to
> > complete the SMTP handshake with the remote SMTP server.
>
> given postscreen_greet_wait, it's a coincidence that the remote server's
> postscreen logs show that same delay ~6 second delay, but list it as
> PASS OLD:

There is no conincidence. "PASS OLD" means that the SMTP client
already had a record in the postscreen cache.

To avoid ruining your address verification performance with postscreen
delays, use the postscreen_access_list feature.

http://www.postfix.org/postconf.5.html#postscreen_access_list

Wietse

Benny Pedersen

unread,
Jul 7, 2014, 4:54:34 PM7/7/14
to
On 7. jul. 2014 19.58.46 CEST, Noel Jones <njo...@megan.vbhcs.org> wrote:
>> Jul 6 08:26:29 mta1 postfix/postscreen[16943]: PASS OLD
>> [10.36.40.26]:45643
>The better solution is to identify and fix your network delay.

And whitelist rfc 1918 in postscreen

0 new messages