I invoke the address verification at the postscreen handoff smtpd.
>From the log you can see
connect from outside
Apr 20 15:28:35 mail01 postfix/postscreen[10625]: CONNECT from
[66.111.4.25]:42434 to [192.0.2.16]:25
dnsbl checks & pass
Apr 20 15:28:35 mail01 postfix/dnsblog[10627]: addr 66.111.4.25 listed
by domain list.dnswl.org as 127.0.5.1
Apr 20 15:28:35 mail01 postfix/postscreen[10625]: PASS OLD
[66.111.4.25]:42434
handoff to postscreen smtpd
Apr 20 15:28:35 mail01 postfix/psint/smtpd[10630]: connect from
out1-smtp.messagingengine.com[66.111.4.25]
immediately starts the verify, fails DURING the verify, and appears to involve
no other service I've defined.
All that's involved here is postscreen, its handoff smtp, and the address
verification step against the backend. How am I supposed to get this simpler
without removing postscreen or the address verification step or the backend?
Apr 20 15:28:37 mail01 postfix/verify[10636]: name_mask: ipv4
Apr 20 15:28:37 mail01 postfix/verify[10636]: inet_addr_local:
configured 10 IPv4 addresses
Apr 20 15:28:37 mail01 postfix/verify[10636]: process generation: 73
(73)
Apr 20 15:28:37 mail01 postfix/verify[10636]: set_eugid: euid 5001 egid
5001
Apr 20 15:28:37 mail01 postfix/verify[10636]: database
lmdb:/var/lib/postfix/verify_cache: using size limit 16777216 during open
Apr 20 15:28:37 mail01 postfix/verify[10636]: dict_open:
lmdb:/var/lib/postfix/verify_cache
Apr 20 15:28:37 mail01 postfix/verify[10636]: set_eugid: euid 0 egid 0
Apr 20 15:28:37 mail01 postfix/verify[10636]:
lmdb:/var/lib/postfix/verify_cache cache cleanup will start after 41130s
Apr 20 15:28:37 mail01 postfix/verify[10636]: connection established fd
128
Apr 20 15:28:37 mail01 postfix/verify[10636]: master_notify: status 0
Apr 20 15:28:37 mail01 postfix/verify[10636]: verify socket: wanted
attribute: request
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
request
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute value:
query
Apr 20 15:28:37 mail01 postfix/verify[10636]: verify socket: wanted
attribute: address
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
address
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute value:
exampl...@example.com
Apr 20 15:28:37 mail01 postfix/verify[10636]: verify socket: wanted
attribute: (list terminator)
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
(end)
Apr 20 15:28:37 mail01 postfix/verify[10636]: dict_cache_lookup:
key=exampl...@example.com value=(not found)
Apr 20 15:28:37 mail01 postfix/verify[10636]: GOT exampl...@example.com
status=3 probed=0 updated=0 text=Address verification in progress
Apr 20 15:28:37 mail01 postfix/verify[10636]: send attr status = 0
Apr 20 15:28:37 mail01 postfix/verify[10636]: send attr
recipient_status = 3
Apr 20 15:28:37 mail01 postfix/verify[10636]: send attr reason =
Address verification in progress
Apr 20 15:28:37 mail01 postfix/verify[10636]: PROBE
exampl...@example.com status=3 probed=1461191317 updated=0
Apr 20 15:28:37 mail01 postfix/verify[10636]: connect to subsystem
private/rewrite
Apr 20 15:28:37 mail01 postfix/verify[10636]: send attr request =
rewrite
Apr 20 15:28:37 mail01 postfix/verify[10636]: send attr rule = local
Apr 20 15:28:37 mail01 postfix/verify[10636]: send attr address =
pr...@verify.mail01.example.com
Apr 20 15:28:37 mail01 postfix/verify[10636]: private/rewrite socket:
wanted attribute: flags
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
flags
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute value: 0
Apr 20 15:28:37 mail01 postfix/verify[10636]: private/rewrite socket:
wanted attribute: address
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
address
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute value:
pr...@verify.mail01.example.com
Apr 20 15:28:37 mail01 postfix/verify[10636]: private/rewrite socket:
wanted attribute: (list terminator)
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
(end)
Apr 20 15:28:37 mail01 postfix/verify[10636]: rewrite_clnt: local:
pr...@verify.mail01.example.com -> pr...@verify.mail01.example.com
Apr 20 15:28:37 mail01 postfix/verify[10636]: connect to subsystem
public/cleanup
Apr 20 15:28:37 mail01 postfix/verify[10636]: PUT exampl...@example.com
status=3 probed=1461191317 updated=0 text=Address verification in progress
Apr 20 15:28:37 mail01 postfix/verify[10636]: dict_cache_update:
key=exampl...@example.com value=3:1461191317:0:Address verification in progress
Apr 20 15:28:37 mail01 postfix/verify[10636]: master_notify: status 1
Apr 20 15:28:37 mail01 postfix/verify[10636]: post_mail_open_event:
read event
Apr 20 15:28:37 mail01 postfix/verify[10636]: name_mask: sendmail
Apr 20 15:28:37 mail01 postfix/verify[10636]: name_mask: verify
Apr 20 15:28:37 mail01 postfix/verify[10636]: fd=14: stream buffer size
old=0 new=8192
Apr 20 15:28:37 mail01 postfix/verify[10636]: public/cleanup socket:
wanted attribute: queue_id
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
queue_id
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute value:
3qqxP16Cm9z2x7f
Apr 20 15:28:37 mail01 postfix/verify[10636]: public/cleanup socket:
wanted attribute: (list terminator)
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
(end)
Apr 20 15:28:37 mail01 postfix/verify[10636]: send attr flags = 544
Apr 20 15:28:37 mail01 postfix/cleanup[10637]: 3qqxP16Cm9z2x7f:
message-id=<3qqxp16cm9z2...@mail01.example.com>
Apr 20 15:28:37 mail01 postfix/verify[10636]: public/cleanup socket:
wanted attribute: status
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
status
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute value: 0
Apr 20 15:28:37 mail01 postfix/verify[10636]: public/cleanup socket:
wanted attribute: (list terminator)
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
reason
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute value:
(end)
Apr 20 15:28:37 mail01 postfix/verify[10636]: public/cleanup socket:
wanted attribute: (list terminator)
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
(end)
Apr 20 15:28:37 mail01 postfix/qmgr[10621]: 3qqxP16Cm9z2x7f:
from=<pr...@verify.mail01.example.com>, size=247, nrcpt=1 (queue active)
Apr 20 15:28:37 mail01 postfix/verify[10636]: connection established fd
129
Apr 20 15:28:37 mail01 postfix/verify[10636]: master_notify: status 0
Apr 20 15:28:37 mail01 postfix/verify[10636]: verify socket: wanted
attribute: request
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
request
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute value:
update
Apr 20 15:28:37 mail01 postfix/verify[10636]: verify socket: wanted
attribute: address
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
address
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute value:
exampl...@example.com
Apr 20 15:28:37 mail01 postfix/verify[10636]: verify socket: wanted
attribute: recipient_status
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
recipient_status
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute value: 2
Apr 20 15:28:37 mail01 postfix/verify[10636]: verify socket: wanted
attribute: reason
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
reason
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute value:
mail for example.com loops back to myself
Apr 20 15:28:37 mail01 postfix/verify[10636]: verify socket: wanted
attribute: (list terminator)
Apr 20 15:28:37 mail01 postfix/verify[10636]: input attribute name:
(end)
Apr 20 15:28:37 mail01 postfix/verify[10636]: dict_cache_lookup:
key=exampl...@example.com value=3:1461191317:0:Address verification in progress
Apr 20 15:28:37 mail01 postfix/verify[10636]: PUT exampl...@example.com
status=2 probed=0 updated=1461191317 text=mail for example.com loops back to
myself
Apr 20 15:28:37 mail01 postfix/verify[10636]: dict_cache_update:
key=exampl...@example.com value=2:0:1461191317:mail for example.com loops back
to myself
Apr 20 15:28:37 mail01 postfix/verify[10636]: send attr status = 0
Apr 20 15:28:37 mail01 postfix/verify[10636]: master_notify: status 1
Apr 20 15:28:37 mail01 postfix/smtp[10638]: 3qqxP16Cm9z2x7f:
to=<exampl...@example.com>, relay=none, delay=0.01, delays=0/0.01/0/0,
dsn=5.4.6, status=undeliverable (mail for example.com loops back to myself)
Apr 20 15:28:37 mail01 postfix/qmgr[10621]: 3qqxP16Cm9z2x7f: removed
Apr 20 15:28:40 mail01 postfix/verify[10636]: master_notify: status 0
Apr 20 15:28:40 mail01 postfix/verify[10636]: verify socket: wanted
attribute: request
Apr 20 15:28:40 mail01 postfix/verify[10636]: input attribute name:
request
Apr 20 15:28:40 mail01 postfix/verify[10636]: input attribute value:
query
Apr 20 15:28:40 mail01 postfix/verify[10636]: verify socket: wanted
attribute: address
Apr 20 15:28:40 mail01 postfix/verify[10636]: input attribute name:
address
Apr 20 15:28:40 mail01 postfix/verify[10636]: input attribute value:
exampl...@example.com
Apr 20 15:28:40 mail01 postfix/verify[10636]: verify socket: wanted
attribute: (list terminator)
Apr 20 15:28:40 mail01 postfix/verify[10636]: input attribute name:
(end)
Apr 20 15:28:40 mail01 postfix/verify[10636]: dict_cache_lookup:
key=exampl...@example.com value=2:0:1461191317:mail for example.com loops back
to myself
Apr 20 15:28:40 mail01 postfix/verify[10636]: GOT exampl...@example.com
status=2 probed=0 updated=1461191317 text=mail for example.com loops back to
myself
Apr 20 15:28:40 mail01 postfix/verify[10636]: send attr status = 0
Apr 20 15:28:40 mail01 postfix/verify[10636]: send attr
recipient_status = 2
Apr 20 15:28:40 mail01 postfix/verify[10636]: send attr reason = mail
for example.com loops back to myself
Apr 20 15:28:40 mail01 postfix/verify[10636]: master_notify: status 1
Apr 20 15:28:40 mail01 postfix/psint/smtpd[10630]: NOQUEUE:
reject_warning: RCPT from out1-smtp.messagingengine.com[66.111.4.25]: 550 5.1.1
<exampl...@example.com>: Recipient address rejected: undeliverable address:
mail for example.com loops back to myself; from=<ja...@2.example.com>
to=<exampl...@example.com> proto=ESMTP helo=<out1-smtp.messagingengine.com>
Without the address verify turned on, there's no "send attr reason = mail for
example.com loops back to myself" error. At. All.
Testing deliverability using
sendmail -bv exampl...@example.com
returns this at the console, with no error,
Mail Delivery Status Report will be mailed to <root>.
this in the logs, with no error,
Apr 20 15:55:26 mail01 postfix/pickup[10620]: 3qqxzy6K7Gz2ylB: uid=0
from=<root>
Apr 20 15:55:26 mail01 postfix/cleanup[11915]: 3qqxzy6K7Gz2ylB:
message-id=<3qqxzy6k7gz2...@mail01.example.com>
Apr 20 15:55:26 mail01 postfix/qmgr[10621]: 3qqxzy6K7Gz2ylB:
from=<r...@mail01.example.com>, size=304, nrcpt=1 (queue active)
Apr 20 15:55:27 mail01 postfix/vpn/smtp[11933]: 3qqxzy6K7Gz2ylB:
to=<exampl...@example.com>, relay=back.mail01.example.com[10.1.1.16]:50003,
delay=0.31, delays=0/0/0.23/0.07, dsn=2.1.5, status=deliverable (250 2.1.5 Ok)
Apr 20 15:55:27 mail01 postfix/cleanup[11915]: 3qqxzz1ZMNz30YW:
message-id=<3qqxzz1zmnz3...@mail01.example.com>
Apr 20 15:55:27 mail01 postfix/bounce[11945]: 3qqxzy6K7Gz2ylB: sender
delivery status notification: 3qqxzz1ZMNz30YW
Apr 20 15:55:27 mail01 postfix/qmgr[10621]: 3qqxzz1ZMNz30YW: from=<>,
size=2058, nrcpt=1 (queue active)
Apr 20 15:55:27 mail01 postfix/qmgr[10621]: 3qqxzy6K7Gz2ylB: removed
Apr 20 15:55:27 mail01 postfix/cleanup[11915]: 3qqxzz1cX6z2x7f:
message-id=<3qqxzz1zmnz3...@mail01.example.com>
Apr 20 15:55:27 mail01 postfix/local[11946]: 3qqxzz1ZMNz30YW:
to=<r...@mail01.example.com>, relay=local, delay=0.01, delays=0/0/0/0,
dsn=2.0.0, status=sent (forwarded as 3qqxzz1cX6z2x7f)
Apr 20 15:55:27 mail01 postfix/qmgr[10621]: 3qqxzz1cX6z2x7f: from=<>,
size=2208, nrcpt=1 (queue active)
Apr 20 15:55:27 mail01 postfix/qmgr[10621]: 3qqxzz1ZMNz30YW: removed
Apr 20 15:55:27 mail01 postfix/vpn/smtp[11933]: 3qqxzz1cX6z2x7f:
to=<exampl...@example.com>, orig_to=<r...@mail01.example.com>,
relay=back.mail01.example.com[10.1.1.16]:50003, delay=0.36,
delays=0/0/0.23/0.12, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as
384D91016C1)
Apr 20 15:55:27 mail01 postfix/qmgr[10621]: 3qqxzz1cX6z2x7f: removed
and this is the report, with no error,
This is the mail system at host mail01.example.com.
Enclosed is the mail delivery report that you requested.
The mail system
<exampl...@example.com>: delivery via
back.mail01.example.com[10.1.1.16]:50003: 250 2.1.5 Ok
Reporting-MTA: dns; mail01.example.com
X-Postfix-Queue-ID: 3qqxpW2wK4z2ylB
X-Postfix-Sender: rfc822; r...@mail01.example.com
Arrival-Date: Wed, 20 Apr 2016 15:47:15 -0700 (PDT)
Final-Recipient: rfc822; exampl...@example.com
Original-Recipient: rfc822;exampl...@example.com
Action: deliverable
Status: 2.1.5
Remote-MTA: dns; back.mail01.example.com
Diagnostic-Code: smtp; 250 2.1.5 Ok
Return-Path: <r...@mail01.example.com>
Received: by mail01.example.com (Postfix, from userid 0)
id 3qqxpW2wK4z2ylB; Wed, 20 Apr 2016 15:47:15 -0700 (PDT)
From: r...@mail01.example.com
Subject: probe
To: exampl...@example.com
Message-Id: <3qqxpw2wk4z2...@mail01.example.com>
Date: Wed, 20 Apr 2016 15:47:15 -0700 (PDT)
Something is clearly wrong, here^,
Apr 20 15:28:40 mail01 postfix/verify[10636]: dict_cache_lookup:
key=exampl...@example.com value=2:0:1461191317:mail for example.com loops back
to myself
Apr 20 15:28:40 mail01 postfix/verify[10636]: GOT exampl...@example.com
status=2 probed=0 updated=1461191317 text=mail for example.com loops back to
myself
Apr 20 15:28:40 mail01 postfix/verify[10636]: send attr status = 0
Apr 20 15:28:40 mail01 postfix/verify[10636]: send attr
recipient_status = 2
Apr 20 15:28:40 mail01 postfix/verify[10636]: send attr reason = mail
for example.com loops back to myself
It's good to keep saying 'simplify' and telling me to straighten out the helo
names.
How do I make this any simpler, and still have it at all relevant? And what
helo name, and where, needs to be corrected?
Jason
