Discussion:
MTA Deferring e-mail
(too old to reply)
Jason T. Slack-Moehrle
2012-10-01 21:35:20 UTC
Permalink
Zimbra 7.1.2 and the MTA seems to be deferring e-mail when it is received.

Oct 1 09:35:42 www postfix/error[16614]: 5FB8C1A803EE: to=<***@xxx.xx>,
relay=none, delay=0.15, delays=0.08/0.01/0/0.06, dsn=4.4.1,
status=deferred (delivery
temporarily suspended: connect to
thedigiologygroup.org[75.149.56.27]:7025: Connection
timed out)

I can telnet to both 25 and 7025.

I do get a

$ telnet thedigiologygroup.org 25
Trying 75.149.56.27...
Connected to thedigiologygroup.org.
Escape character is '^]'.
220 thedigiologygroup.org ESMTP Postfix

500 5.5.2 Error: bad syntax

500 5.5.2 Error: bad syntax`

I dont see email in the inbox obviously and I am not sure how to
troubleshoot what is going on.

Nothing DNS has changed.

This box has been running for a year

Zimbra was removed and re-installed after trying to upgrade to ZCS-8
with no luck.

Here is an example it I tail the log and watch the message come in

Oct 1 14:30:06 www zmmailboxdmgr[9369]: status OK
Oct 1 14:31:34 www postfix/smtpd[9570]: connect from
mail-lb0-f181.google.com[209.85.217.181]
Oct 1 14:31:35 www postfix/smtpd[9570]: setting up TLS connection
from mail-lb0-f181.google.com[209.85.217.181]
Oct 1 14:31:35 www postfix/smtpd[9570]: Anonymous TLS connection
established from mail-lb0-f181.google.com[209.85.217.181]: TLSv1 with
cipher RC4-SHA (128/128 bits)
Oct 1 14:31:36 www postfix/smtpd[9570]: 1DD9A1A80452:
client=mail-lb0-f181.google.com[209.85.217.181]
Oct 1 14:31:36 www postfix/cleanup[9575]: 1DD9A1A80452:
message-id=<CAEyvkJM1Ry0232LhHTyrW7ajHOZW+-62rBv9qX1=***@mail.gmail.com>
Oct 1 14:31:36 www postfix/qmgr[15204]: 1DD9A1A80452:
from=<***@gmail.com>, size=1651, nrcpt=1 (queue active)
Oct 1 14:31:36 www amavis[14927]: (14927-02) ESMTP::10024
/opt/zimbra/data/amavisd/tmp/amavis-20121001T094644-14927:
<***@gmail.com> -> <***@ouremail.us> SIZE=1651 Received: from
thedigiologygroup.org ([127.0.0.1]) by localhost
(thedigiologygroup.org [127.0.0.1]) (amavisd-new, port 10024) with
ESMTP for <***@ouremail.us>; Mon, 1 Oct 2012 14:31:36 -0700 (PDT)
Oct 1 14:31:36 www amavis[14927]: (14927-02) Checking: U0Cg+GK5fRMh
[209.85.217.181] <***@gmail.com> -> <***@ouremail.us>
Oct 1 14:31:36 www clamd[14992]: SelfCheck: Database status OK.
Oct 1 14:31:37 www postfix/smtpd[9579]: connect from
localhost.localdomain[127.0.0.1]
Oct 1 14:31:37 www postfix/smtpd[9579]: 553821A80458:
client=localhost.localdomain[127.0.0.1]
Oct 1 14:31:37 www postfix/cleanup[9575]: 553821A80458:
message-id=<CAEyvkJM1Ry0232LhHTyrW7ajHOZW+-62rBv9qX1=***@mail.gmail.com>
Oct 1 14:31:37 www postfix/qmgr[15204]: 553821A80458:
from=<***@gmail.com>, size=2486, nrcpt=1 (queue active)
Oct 1 14:31:37 www amavis[14927]: (14927-02) FWD via SMTP:
<***@gmail.com> -> <***@ouremail.us>,BODY=7BIT 250 2.0.0 from
MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 553821A80458
Oct 1 14:31:37 www postfix/smtpd[9579]: disconnect from
localhost.localdomain[127.0.0.1]
Oct 1 14:31:37 www postfix/qmgr[15204]: warning: connect to transport
private/lsmtp: No such file or directory
Oct 1 14:31:37 www amavis[14927]: (14927-02) Passed CLEAN,
[209.85.217.181] [209.85.217.181] <***@gmail.com> ->
<***@ouremail.us>, Message-ID:
<CAEyvkJM1Ry0232LhHTyrW7ajHOZW+-62rBv9qX1=***@mail.gmail.com>,
mail_id: U0Cg+GK5fRMh, Hits: -2.7, size: 1651, queued_as:
553821A80458, dkim_id=@gmail.com, 771 ms
Oct 1 14:31:37 www postfix/smtp[9576]: 1DD9A1A80452:
to=<***@ouremail.us>, relay=127.0.0.1[127.0.0.1]:10024, delay=1.5,
delays=0.74/0.01/0/0.77, dsn=2.0.0, status=sent (250 2.0.0 from
MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 553821A80458)
Oct 1 14:31:37 www postfix/qmgr[15204]: 1DD9A1A80452: removed
Oct 1 14:31:37 www amavis[14927]: (14927-02) extra modules loaded:
unicore/lib/gc_sc/Alnum.pl, unicore/lib/gc_sc/Alpha.pl
Oct 1 14:31:37 www postfix/error[9580]: 553821A80458:
to=<***@ouremail.us>, relay=none, delay=0.15,
delays=0.07/0.02/0/0.07, dsn=4.3.0, status=deferred (mail transport
unavailable)

I can send mail out to GMail, however.

Ports seem open:
PORT STATE SERVICE
25/tcp open smtp
80/tcp open http
110/tcp open pop3
111/tcp open rpcbind
143/tcp open imap
443/tcp open https
465/tcp open smtps
587/tcp open submission
631/tcp open ipp
993/tcp open imaps
995/tcp open pop3s
3306/tcp open mysql
5222/tcp open xmpp-client
5269/tcp open xmpp-server
7025/tcp open vmsvc-2
7777/tcp open cbt
10024/tcp open unknown
10025/tcp open unknown

Can anyone help me see what is going wrong? This was working before
attempting a failed upgrade.

-Jason
Wietse Venema
2012-10-01 21:51:15 UTC
Permalink
Post by Jason T. Slack-Moehrle
Oct 1 14:31:37 www postfix/qmgr[15204]: warning: connect to transport
private/lsmtp: No such file or directory
Fix that.

Wietse
Jason T. Slack-Moehrle
2012-10-01 22:10:38 UTC
Permalink
Hi Wietse,
Post by Wietse Venema
Post by Jason T. Slack-Moehrle
Oct 1 14:31:37 www postfix/qmgr[15204]: warning: connect to transport
private/lsmtp: No such file or directory
Fix that.
I am not sure where it expects `private/lsmtp` to be located though.

-Jason
Viktor Dukhovni
2012-10-01 22:24:02 UTC
Permalink
Post by Jason T. Slack-Moehrle
Post by Wietse Venema
Post by Jason T. Slack-Moehrle
Oct 1 14:31:37 www postfix/qmgr[15204]: warning: connect to transport
private/lsmtp: No such file or directory
Fix that.
I am not sure where it expects `private/lsmtp` to be located though.
By fix that, what is meant is to not typo the names of transports
in main.cf and FILTER rules in access tables.

You almost certainly mean "lmtp"...
--
Viktor.
Jason T. Slack-Moehrle
2012-10-01 23:16:21 UTC
Permalink
I noticed that, a typo from earlier.

But now it seems I cannot send, nor receive e-mail:

Oct 1 16:12:05 www zmmailboxdmgr[25272]: status OK
Oct 1 16:12:20 www postfix/smtpd[25394]: connect from mail[192.168.1.27]
Oct 1 16:12:20 www postfix/smtpd[25394]: A6EDD1A8043C:
client=mail[192.168.1.27]
Oct 1 16:12:20 www postfix/cleanup[25398]: A6EDD1A8043C:
message-id=<***@ouremail.us>
Oct 1 16:12:20 www postfix/qmgr[24672]: A6EDD1A8043C:
from=<***@ouremail.us>, size=600, nrcpt=2 (queue active)
Oct 1 16:12:20 www postfix/smtpd[25394]: disconnect from mail[192.168.1.27]
Oct 1 16:12:20 www amavis[20527]: (20527-01) ESMTP::10024
/opt/zimbra/data/amavisd/tmp/amavis-20121001T161220-20527:
<***@ouremail.us> -> <***@gmail.com>,<***@thedigiologygroup.org>
SIZE=600 Received: from thedigiologygroup.org ([127.0.0.1]) by
localhost (thedigiologygroup.org [127.0.0.1]) (amavisd-new, port
10024) with ESMTP; Mon, 1 Oct 2012 16:12:20 -0700 (PDT)
Oct 1 16:12:20 www amavis[20527]: (20527-01) Checking: Fhh+FWfhscEU
MYNETS [192.168.1.27] <***@ouremail.us> ->
<***@gmail.com>,<***@thedigiologygroup.org>
Oct 1 16:12:21 www postfix/smtpd[25403]: connect from
localhost.localdomain[127.0.0.1]
Oct 1 16:12:21 www postfix/smtpd[25403]: 2A6051A80445:
client=localhost.localdomain[127.0.0.1]
Oct 1 16:12:21 www postfix/cleanup[25398]: 2A6051A80445:
message-id=<***@ouremail.us>
Oct 1 16:12:21 www postfix/qmgr[24672]: 2A6051A80445:
from=<***@ouremail.us>, size=1048, nrcpt=1 (queue active)
Oct 1 16:12:21 www amavis[20527]: (20527-01) FWD via SMTP:
<***@ouremail.us> -> <***@gmail.com>,BODY=7BIT 250 2.0.0 from
MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 2A6051A80445
Oct 1 16:12:21 www postfix/smtpd[25403]: 4972C1A80447:
client=localhost.localdomain[127.0.0.1]
Oct 1 16:12:21 www postfix/cleanup[25398]: 4972C1A80447:
message-id=<***@ouremail.us>
Oct 1 16:12:21 www postfix/qmgr[24672]: 4972C1A80447:
from=<***@ouremail.us>, size=1249, nrcpt=1 (queue active)
Oct 1 16:12:21 www amavis[20527]: (20527-01) FWD via SMTP:
<***@ouremail.us> -> <***@thedigiologygroup.org>,BODY=7BIT 250 2.0.0
from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4972C1A80447
Oct 1 16:12:21 www amavis[20527]: (20527-01) Passed CLEAN, MYNETS
LOCAL [192.168.1.27] [192.168.1.27] <***@ouremail.us> ->
<***@gmail.com>,<***@thedigiologygroup.org>, Message-ID:
<***@ouremail.us>, mail_id:
Fhh+FWfhscEU, Hits: -1.106, size: 600, queued_as:
2A6051A80445/4972C1A80447, 571 ms
Oct 1 16:12:21 www postfix/smtp[25400]: A6EDD1A8043C:
to=<***@gmail.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.71,
delays=0.13/0.01/0.01/0.57, dsn=2.0.0, status=sent (250 2.0.0 from
MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 2A6051A80445)
Oct 1 16:12:21 www postfix/smtp[25400]: A6EDD1A8043C:
to=<***@thedigiologygroup.org>, relay=127.0.0.1[127.0.0.1]:10024,
delay=0.71, delays=0.13/0.01/0.01/0.57, dsn=2.0.0, status=sent (250
2.0.0 from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as
2A6051A80445)
Oct 1 16:12:21 www postfix/qmgr[24672]: A6EDD1A8043C: removed
Oct 1 16:12:21 www amavis[20527]: (20527-01) extra modules loaded:
/opt/zimbra/zimbramon/lib/x86_64-linux-thread-multi/auto/Net/SSLeay/autosplit.ix,
/opt/zimbra/zimbramon/lib/x86_64-linux-thread-multi/auto/Net/SSLeay/randomize.al,
/usr/lib64/perl5/vendor_perl/auto/Net/LibIDN/autosplit.ix,
IO/Socket/SSL.pm, Net/LDAP/Extension.pm, Net/LibIDN.pm, Net/SSLeay.pm
Oct 1 16:12:21 www postfix/lmtp[25404]: 4972C1A80447:
to=<***@thedigiologygroup.org>,
relay=thedigiologygroup.org[192.168.1.27]:7025, delay=0.29,
delays=0.07/0.01/0/0.2, dsn=2.1.5, status=sent (250 2.1.5 Delivery OK)
Oct 1 16:12:21 www postfix/qmgr[24672]: 4972C1A80447: removed
Oct 1 16:12:29 www zmmailboxdmgr[25495]: status requested
Oct 1 16:12:29 www zmmailboxdmgr[25495]: status OK
Oct 1 16:12:30 www zmmailboxdmgr[25504]: status requested
Oct 1 16:12:30 www zmmailboxdmgr[25504]: status OK
Oct 1 16:12:51 www postfix/smtp[24675]: connect to
gmail.com[74.125.224.149]:25: Connection timed out
Oct 1 16:13:12 www postfix/smtpd[23012]: timeout after END-OF-MESSAGE
from localhost.localdomain[127.0.0.1]
Oct 1 16:13:12 www postfix/smtpd[23012]: disconnect from
localhost.localdomain[127.0.0.1]
Oct 1 16:13:21 www postfix/smtp[24675]: connect to
gmail.com[74.125.224.150]:25: Connection timed out
Oct 1 16:13:21 www postfix/smtp[24675]: 2A6051A80445:
to=<***@gmail.com>, relay=none, delay=60, delays=0.12/0.01/60/0,
dsn=4.4.1, status=deferred (connect to gmail.com[74.125.224.150]:25:
Connection timed out)
Jason T. Slack-Moehrle
2012-10-01 23:35:32 UTC
Permalink
So it looks like incoming e-mail might be working now, outgoing not so much.

Oct 1 16:33:32 www clamd[20590]: SelfCheck: Database status OK.
Oct 1 16:33:33 www postfix/smtpd[32650]: connect from
localhost.localdomain[127.0.0.1]
Oct 1 16:33:33 www postfix/smtpd[32650]: 64D131A8045E:
client=localhost.localdomain[127.0.0.1]
Oct 1 16:33:33 www postfix/cleanup[3358]: 64D131A8045E:
message-id=<***@ouremail.us>
Oct 1 16:33:33 www postfix/qmgr[24672]: 64D131A8045E:
from=<***@ouremail.us>, size=1399, nrcpt=1 (queue active)
Oct 1 16:33:33 www amavis[20533]: (20533-01) FWD via SMTP:
<***@ouremail.us> -> <***@gmail.com>,BODY=7BIT 250 2.0.0 from
MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 64D131A8045E
Oct 1 16:33:33 www amavis[20533]: (20533-01) Passed CLEAN, MYNETS
LOCAL [192.168.1.27] [192.168.1.27] <***@ouremail.us> ->
<***@gmail.com>, Message-ID:
<***@ouremail.us>, mail_id:
dVByAWcL3Dcp, Hits: -1.106, size: 920, queued_as: 64D131A8045E, 836 ms
Oct 1 16:33:33 www postfix/smtp[3359]: 8F3BF1A80459:
to=<***@gmail.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.97,
delays=0.12/0.01/0.01/0.83, dsn=2.0.0, status=sent (250 2.0.0 from
MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 64D131A8045E)
Oct 1 16:33:33 www postfix/qmgr[24672]: 8F3BF1A80459: removed
Oct 1 16:33:33 www amavis[20533]: (20533-01) extra modules loaded:
/opt/zimbra/zimbramon/lib/x86_64-linux-thread-multi/auto/Net/SSLeay/autosplit.ix,
/opt/zimbra/zimbramon/lib/x86_64-linux-thread-multi/auto/Net/SSLeay/randomize.al,
/usr/lib64/perl5/vendor_perl/auto/Net/LibIDN/autosplit.ix,
IO/Socket/SSL.pm, Net/LDAP/Extension.pm, Net/LibIDN.pm, Net/SSLeay.pm
Oct 1 16:34:03 www postfix/smtp[3362]: connect to
gmail.com[74.125.224.149]:25: Connection timed out
Oct 1 16:34:05 www zmmailboxdmgr[3687]: status requested
Oct 1 16:34:05 www zmmailboxdmgr[3687]: status OK
Oct 1 16:34:18 www zmmailboxdmgr[3896]: status requested
Oct 1 16:34:18 www zmmailboxdmgr[3896]: status OK
Oct 1 16:34:18 www zmmailboxdmgr[3905]: status requested
Oct 1 16:34:18 www zmmailboxdmgr[3905]: status OK
Wietse Venema
2012-10-01 23:47:06 UTC
Permalink
Post by Jason T. Slack-Moehrle
Oct 1 16:34:03 www postfix/smtp[3362]: connect to
gmail.com[74.125.224.149]:25: Connection timed out
You have configured Postfix to connect to gmail.com instead of the
MX HOSTS for gmail.com.

If this is gobbledygook, I suggest that you send output
from "postconf -n".

Wietse
/dev/rob0
2012-10-01 23:57:03 UTC
Permalink
On Mon, Oct 01, 2012 at 04:35:32PM -0700, Jason T. Slack-Moehrle
Post by Jason T. Slack-Moehrle
So it looks like incoming e-mail might be working now, outgoing
not so much.
Oct 1 16:34:03 www postfix/smtp[3362]: connect to
gmail.com[74.125.224.149]:25: Connection timed out
This looks quite like a "disable_dns_lookups=yes" issue. The question
then would be: how was it working before?

$ for Mx in $(dig gmail.com. mx +short | cut -f2 -d\ ) ; do host -tA $Mx ; done
gmail-smtp-in.l.google.com has address 173.194.73.26
alt2.gmail-smtp-in.l.google.com has address 173.194.70.26
alt4.gmail-smtp-in.l.google.com has address 74.125.143.27
alt1.gmail-smtp-in.l.google.com has address 173.194.65.26
alt3.gmail-smtp-in.l.google.com has address 173.194.69.26

None of those are 74.125.224.149 and none are called "gmail.com".
--
http://rob0.nodns4.us/ -- system administration and consulting
Offlist GMX mail is seen only if "/dev/rob0" is in the Subject:
Jason T. Slack-Moehrle
2012-10-02 00:56:06 UTC
Permalink
Post by /dev/rob0
Post by Jason T. Slack-Moehrle
So it looks like incoming e-mail might be working now, outgoing
not so much.
Oct 1 16:34:03 www postfix/smtp[3362]: connect to
gmail.com[74.125.224.149]:25: Connection timed out
This looks quite like a "disable_dns_lookups=yes" issue. The question
then would be: how was it working before?
$ postconf -n
disable_dns_lookups = yes

I now changed it to 'no' and things seem to be working again.

I dont understand why, though, this would be creating the problem.
Could you explain? If it creates this problem, why do people set it?

-Jason
Reindl Harald
2012-10-02 08:02:35 UTC
Permalink
Post by Jason T. Slack-Moehrle
Post by /dev/rob0
Post by Jason T. Slack-Moehrle
So it looks like incoming e-mail might be working now, outgoing
not so much.
Oct 1 16:34:03 www postfix/smtp[3362]: connect to
gmail.com[74.125.224.149]:25: Connection timed out
This looks quite like a "disable_dns_lookups=yes" issue. The question
then would be: how was it working before?
$ postconf -n
disable_dns_lookups = yes
I now changed it to 'no' and things seem to be working again.
I dont understand why, though, this would be creating the problem.
Could you explain?
see docs: http://www.postfix.org/postconf.5.html#disable_dns_lookups

disable_dns_lookups (default: no)
Post by Jason T. Slack-Moehrle
If it creates this problem, why do people set it?
nobody does set it global

it makes sense on internal transports like LMTP in
master.cf but NOT as global setting!

dbmail-lmtp unix - - n - - lmtp -o disable_dns_lookups=yes -o max_use=100
/dev/rob0
2012-10-02 13:42:19 UTC
Permalink
Post by Reindl Harald
Post by Jason T. Slack-Moehrle
Post by /dev/rob0
Post by Jason T. Slack-Moehrle
So it looks like incoming e-mail might be working now, outgoing
not so much.
Oct 1 16:34:03 www postfix/smtp[3362]: connect to
gmail.com[74.125.224.149]:25: Connection timed out
This looks quite like a "disable_dns_lookups=yes" issue. The
question then would be: how was it working before?
$ postconf -n
disable_dns_lookups = yes
I now changed it to 'no' and things seem to be working again.
I dont understand why, though, this would be creating the
problem. Could you explain?
see docs: http://www.postfix.org/postconf.5.html#disable_dns_lookups
disable_dns_lookups (default: no)
The higher-level explanation is that by using the getaddrinfo()
system library routine, you are not able to look up the MX records
which control mail routing.
Post by Reindl Harald
Post by Jason T. Slack-Moehrle
If it creates this problem, why do people set it?
The better question: why did Jason set it? :) Don't change defaults
if you don't understand them.
Post by Reindl Harald
nobody does set it global
it makes sense on internal transports like LMTP in
master.cf but NOT as global setting!
dbmail-lmtp unix - - n - - lmtp -o disable_dns_lookups=yes -o max_use=100
It might also simplify things in a relayhost + transport_maps
configuration, but that is not really important. Bottom line here:
Postfix comes with a lot of knobs and dials you can tweak and turn.
Resist the urge. :)
--
http://rob0.nodns4.us/ -- system administration and consulting
Offlist GMX mail is seen only if "/dev/rob0" is in the Subject:
Continue reading on narkive:
Loading...