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=<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/example-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/example-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
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
