i'm setting up 2 postfix instances on 2 separate boxes, 'frontend' & 'backend',
to use address verification probes from front- to back-end
testing @ 'frontend', I can see the VRFY offered by the backend
openssl s_client \
-4 \
-bind 10.0.0.11 \
-connect internal.backend.example.com:25 \
-cert /sec/client.EC.crt \
-key /sec/client.EC.key \
-CAfile /sec/ca_chain.crt
ehlo localhost
250-backend.example.com
250-PIPELINING
250-SIZE 104857600
250-VRFY
250-XFORWARD NAME ADDR PROTO HELO SOURCE PORT IDENT
250-ENHANCEDSTATUSCODES
250-8BITMIME
250-DSN
250 SMTPUTF8
a test send from shell @ 'frontend'
sendmail -i -f root -t <<EOF
From: ad...@frontend.example.com
To: testus...@example.net
Subject: test 1234
testing 1234
EOF
_is_ received/delivered at 'backend', with no errors/issues.
but a test send from an external site, e.g. fastmail, appears to fail @ address
probe verify (with 'verify -v' set)
Jul 20 14:32:28 frontend postfix/postscreen[20096]: CONNECT from
[66.111.4.26]:53083 to [XX.XX.XX.XX]:25
Jul 20 14:32:28 frontend postfix/postscreen[20096]: PASS OLD
[66.111.4.26]:53083
Jul 20 14:32:28 frontend postfix/tlsmgr[20102]: open smtp TLS cache
lmdb:/var/lib/postfix/smtp_cache
Jul 20 14:32:28 frontend postfix/tlsmgr[20102]: tlsmgr_cache_run_event:
start TLS smtp session cache cleanup
Jul 20 14:32:28 frontend postfix/postscreen-internal/smtpd[20101]:
connect from out2-smtp.messagingengine.com[66.111.4.26]
Jul 20 14:32:28 frontend postfix/postscreen-internal/smtpd[20101]:
Anonymous TLS connection established from
out2-smtp.messagingengine.com[66.111.4.26]: TLSv1.2 with cipher
AECDH-AES256-SHA (256/256 bits)
Jul 20 14:32:30 frontend postfix/verify[20106]: name_mask: ipv4
Jul 20 14:32:30 frontend postfix/verify[20106]: inet_addr_local:
configured 9 IPv4 addresses
Jul 20 14:32:30 frontend postfix/verify[20106]: process generation: 323
(323)
Jul 20 14:32:30 frontend postfix/verify[20106]: set_eugid: euid 5001
egid 5001
Jul 20 14:32:30 frontend postfix/verify[20106]: database
lmdb:/var/lib/postfix/verify_cache: using size limit 16777216 during open
Jul 20 14:32:30 frontend postfix/verify[20106]: dict_open:
lmdb:/var/lib/postfix/verify_cache
Jul 20 14:32:30 frontend postfix/verify[20106]: set_eugid: euid 0 egid 0
Jul 20 14:32:30 frontend postfix/verify[20106]:
lmdb:/var/lib/postfix/verify_cache cache cleanup will start after 33177s
Jul 20 14:32:30 frontend postfix/verify[20106]: connection established
fd 128
Jul 20 14:32:30 frontend postfix/verify[20106]: master_notify: status 0
Jul 20 14:32:30 frontend postfix/verify[20106]: verify socket: wanted
attribute: request
Jul 20 14:32:30 frontend postfix/verify[20106]: input attribute name:
request
Jul 20 14:32:30 frontend postfix/verify[20106]: input attribute value:
query
Jul 20 14:32:30 frontend postfix/verify[20106]: verify socket: wanted
attribute: address
Jul 20 14:32:30 frontend postfix/verify[20106]: input attribute name:
address
Jul 20 14:32:30 frontend postfix/verify[20106]: input attribute value:
testus...@example.net
Jul 20 14:32:30 frontend postfix/verify[20106]: verify socket: wanted
attribute: (list terminator)
Jul 20 14:32:30 frontend postfix/verify[20106]: input attribute name:
(end)
Jul 20 14:32:30 frontend postfix/verify[20106]: dict_cache_lookup:
key=testus...@example.net value=1:0:1595290292:conversation with
internal.backend.example.com[10.0.0.21] timed out while receiving the initial
server greeting
Jul 20 14:32:30 frontend postfix/verify[20106]: GOT
testus...@example.net status=1 probed=0 updated=1595290292 text=conversation
with internal.backend.example.com[10.0.0.21] timed out while receiving the
initial server greeting
Jul 20 14:32:30 frontend postfix/verify[20106]: send attr status = 0
Jul 20 14:32:30 frontend postfix/verify[20106]: send attr
recipient_status = 1
Jul 20 14:32:30 frontend postfix/verify[20106]: send attr reason =
conversation with internal.backend.example.com[10.0.0.21] timed out while
receiving the initial server greeting
Jul 20 14:32:30 frontend postfix/verify[20106]: master_notify: status 1
Jul 20 14:32:30 frontend postfix/postscreen-internal/smtpd[20101]:
NOQUEUE: reject: RCPT from out2-smtp.messagingengine.com[66.111.4.26]: 450
4.1.1 <testus...@example.net>: Recipient address rejected: unverified address:
conversation with internal.backend.example.com[10.0.0.21] timed out while
receiving the initial server greeting; from=<myu...@fastmail.com>
to=<testus...@example.net> proto=ESMTP helo=<out2-smtp.messagingengine.com>
Jul 20 14:32:30 frontend postfix/postscreen-internal/smtpd[20101]:
disconnect from out2-smtp.messagingengine.com[66.111.4.26] ehlo=2 starttls=1
mail=1 rcpt=0/1 data=0/1 rset=1 quit=1 commands=6/8
Jul 20 14:32:35 frontend postfix/verify[20106]: connection closed fd 128
and never hits the backend; at least, I see nothing in its logs
to troubleshoot, I'd like to get more detail out of 'verify' than
"conversation with internal.backend.example.com[10.0.0.21] timed out
while receiving the initial server greeting"
, specifically, to find out _why_ a time-out is occurring.
_is_ there additional debug detail available from verify?
&/or, is there a standalone approach to 'exercise' just the address probe
verify step?
perhaps in the openssl s_client connection session?
