more detail in diagnosing verify "conversation ... timed out while receiving the initial server greeting" error?

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

more detail in diagnosing verify "conversation ... timed out while receiving the initial server greeting" error?

PGNet Dev
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: [hidden email]
        To: [hidden email]
        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: [hidden email]
        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=[hidden email] 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 [hidden email] 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 <[hidden email]>: Recipient address rejected: unverified address: conversation with internal.backend.example.com[10.0.0.21] timed out while receiving the initial server greeting; from=<[hidden email]> to=<[hidden email]> 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?
Reply | Threaded
Open this post in threaded view
|

Re: more detail in diagnosing verify "conversation ... timed out while receiving the initial server greeting" error?

Viktor Dukhovni
On Mon, Jul 20, 2020 at 08:32:48PM -0700, PGNet Dev wrote:

> Jul 20 14:32:30 frontend postfix/verify[20106]: dict_cache_lookup: key=[hidden email] value=1:0:1595290292:conversation with internal.backend.example.com[10.0.0.21] timed out while receiving the initial server greeting

This is plainly logged as a *cache* lookup.  The data in the cache entry
was set to expire at epoch time 1595290292, or 2020-07-20T20:11:32-0400.

> and never hits the backend; at least, I see nothing in its logs

That's what caches are for.

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

Well, the connection timed out, and that fact was cached for the
configured or default time.

> , specifically, to find out _why_ a time-out is occurring.

Because the network did not coƶperate.

> _is_ there additional debug detail available from verify?

No, but verify(8) gets information by actually triggering a delivery,
and some smtp(8) client logged whatever detail it was configured to log
for the connection failure.  But when TCP connections time out, there's
really nothing more to say.

> &/or, is there a standalone approach to 'exercise' just the address probe verify step?
> perhaps in the openssl s_client connection session?

    $ sendmail -bv -f sender -- recipient

--
    Viktor.
Reply | Threaded
Open this post in threaded view
|

Re: more detail in diagnosing verify "conversation ... timed out while receiving the initial server greeting" error?

PGNet Dev
On 7/20/20 10:19 PM, Viktor Dukhovni wrote:
> This is plainly logged as a *cache* lookup.  The data in the cache entry
> was set to expire at epoch time 1595290292, or 2020-07-20T20:11:32-0400.

although that doesn't tell me _why_ the problem exists, it did point to _what_ it (apparently) was.

waiting past the 'expiry' times did nothing; but, manually _deleting_ all /var/lib/postfix/*cache* & restarting did the trick.

no further adjustments to my config req'd.

thx!