Em 06/12/11 18:27, Wietse Venema escreveu:
Leonardo Rodrigues:
i'm facing some weird problems with a particular customer which has
2 MXs published. The first one (lower priority number) is rejecting our
emails lots of times (421 You are disconnected for policy reasons). And,
on the logs, i can see that for some periods of times, postfix only try
to delivers mail to his backup MX (higher priority number), which is
most all the time offline.
If Postfix skips an MX host, then it logs a note saying why, so
that people like you don't have to wonder why it skips the server.
You need to show evidence. grep for the PID of the smtp client and show
all records.
Here are the logs ... as i said, from 2.8.5 postfix. For not taking
the logs TOO long, i have trimmed them to a single destination address.
The original message was to 10 different email addresses on the the same
domain and all of them are behaving just like the one i'll show. I have
also obfuscated our domain and the our customer real address. But the
destination domain, which is a important information, is kept.
Nov 16 15:23:36 correio postfix_notif/smtpd[26616]: C955515D4F2:
client=ip68.interno[192.168.9.68], sasl_method=LOGIN,
sasl_username=notifica...@ourdomain.com.br
Nov 16 15:23:36 correio postfix/cleanup[26447]: C955515D4F2:
message-id=<20111116172336.c955515d...@correio.ourdomain.com.br>
Nov 16 15:23:36 correio postfix/qmgr[6855]: C955515D4F2:
from=<notifica...@ourdomain.com.br>, size=11247, nrcpt=10 (queue active)
Nov 16 15:23:36 correio postfix/error[26594]: C955515D4F2:
to=<ourcusto...@azevedosette.com.br>, relay=none, delay=0.04,
delays=0.02/0.01/0/0.01, dsn=4.4.2, status=deferred (delivery
temporarily suspended: lost connection with
mailsp.azevedosette.com.br[200.162.47.19] while receiving the initial
server greeting)
Nov 16 15:38:29 correio postfix/qmgr[6855]: C955515D4F2:
from=<notifica...@ourdomain.com.br>, size=11247, nrcpt=10 (queue active)
Nov 16 15:38:30 correio postfix/error[29037]: C955515D4F2:
to=<ourcusto...@azevedosette.com.br>, relay=none, delay=894,
delays=893/0.48/0/0.03, dsn=4.4.2, status=deferred (delivery temporarily
suspended: lost connection with
mailsp.azevedosette.com.br[200.162.47.19] while receiving the initial
server greeting)
Nov 16 15:53:29 correio postfix/qmgr[6855]: C955515D4F2:
from=<notifica...@ourdomain.com.br>, size=11247, nrcpt=10 (queue active)
Nov 16 15:53:32 correio postfix/error[31483]: C955515D4F2:
to=<ourcusto...@azevedosette.com.br>, relay=none, delay=1796,
delays=1792/3.8/0/0.03, dsn=4.4.2, status=deferred (delivery temporarily
suspended: lost connection with
mailsp.azevedosette.com.br[200.162.47.19] while receiving the initial
server greeting)
Nov 16 16:23:29 correio postfix/qmgr[6855]: C955515D4F2:
from=<notifica...@ourdomain.com.br>, size=11247, nrcpt=10 (queue active)
Nov 16 16:23:30 correio postfix/error[3582]: C955515D4F2:
to=<ourcusto...@azevedosette.com.br>, relay=none, delay=3593,
delays=3593/0.32/0/0.04, dsn=4.4.2, status=deferred (delivery
temporarily suspended: lost connection with
mailsp.azevedosette.com.br[200.162.47.19] while receiving the initial
server greeting)
Nov 16 17:23:29 correio postfix/qmgr[6855]: C955515D4F2:
from=<notifica...@ourdomain.com.br>, size=11247, nrcpt=10 (queue active)
Nov 16 17:23:30 correio postfix/error[11561]: C955515D4F2:
to=<ourcusto...@azevedosette.com.br>, relay=none, delay=7194,
delays=7192/1.3/0/0.03, dsn=4.4.2, status=deferred (delivery temporarily
suspended: lost connection with
mailsp.azevedosette.com.br[200.162.47.19] while receiving the initial
server greeting)
Nov 16 19:23:29 correio postfix/qmgr[6855]: C955515D4F2:
from=<notifica...@ourdomain.com.br>, size=11247, nrcpt=10 (queue active)
Nov 16 19:23:30 correio postfix/error[28647]: C955515D4F2:
to=<ourcusto...@azevedosette.com.br>, relay=none, delay=14394,
delays=14392/1.3/0/0.05, dsn=4.4.2, status=deferred (delivery
temporarily suspended: lost connection with
mailsp.azevedosette.com.br[200.162.47.19] while receiving the initial
server greeting)
Nov 16 21:23:29 correio postfix/qmgr[6855]: C955515D4F2:
from=<notifica...@ourdomain.com.br>, size=11247, nrcpt=10 (queue active)
Nov 16 21:23:29 correio postfix/error[12474]: C955515D4F2:
to=<ourcusto...@azevedosette.com.br>, relay=none, delay=21593,
delays=21593/0.01/0/0.03, dsn=4.4.2, status=deferred (delivery
temporarily suspended: lost connection with
mailsp.azevedosette.com.br[200.162.47.19] while receiving the initial
server greeting)
Nov 16 23:23:29 correio postfix/qmgr[6855]: C955515D4F2:
from=<notifica...@ourdomain.com.br>, size=11247, nrcpt=10 (queue active)
Nov 16 23:23:29 correio postfix/error[1842]: C955515D4F2:
to=<ourcusto...@azevedosette.com.br>, relay=none, delay=28793,
delays=28792/0.45/0/0.03, dsn=4.4.2, status=deferred (delivery
temporarily suspended: lost connection with
mailsp.azevedosette.com.br[200.162.47.19] while receiving the initial
server greeting)
Nov 17 01:23:29 correio postfix/qmgr[6855]: C955515D4F2:
from=<notifica...@ourdomain.com.br>, size=11247, nrcpt=10 (queue active)
Nov 17 01:23:33 correio postfix/error[15140]: C955515D4F2:
to=<ourcusto...@azevedosette.com.br>, relay=none, delay=35996,
delays=35993/3.3/0/0.02, dsn=4.4.2, status=deferred (delivery
temporarily suspended: lost connection with
mailsp.azevedosette.com.br[200.162.47.19] while receiving the initial
server greeting)
Nov 17 03:28:29 correio postfix/qmgr[6855]: C955515D4F2:
from=<notifica...@ourdomain.com.br>, size=11247, nrcpt=10 (queue active)
Nov 17 03:28:31 correio postfix/error[28703]: C955515D4F2:
to=<ourcusto...@azevedosette.com.br>, relay=none, delay=43494,
delays=43493/1.5/0/0.03, dsn=4.4.2, status=deferred (delivery
temporarily suspended: lost connection with
mailsp.azevedosette.com.br[200.162.47.19] while receiving the initial
server greeting)
Nov 17 05:33:29 correio postfix/qmgr[6855]: C955515D4F2:
from=<notifica...@ourdomain.com.br>, size=11247, nrcpt=10 (queue active)
Nov 17 05:33:31 correio postfix/smtp[9875]: C955515D4F2:
to=<ourcusto...@azevedosette.com.br>,
relay=mail3.azevedosette.com.br[200.198.91.178]:25, delay=50994,
delays=50992/0.92/0.24/0.8, dsn=2.6.0, status=sent (250 2.6.0
<20111116172336.c955515d...@correio.ourdomain.com.br> Queued mail for
delivery)
Nov 17 05:33:31 correio postfix/qmgr[6855]: C955515D4F2: removed
since this specific customer (and only this one) started
complaining receiving our emails with huge delays, i have checked his MX
records, from our email server, which is running a local bind instance
and acting as his own nameserver (no ISPs nameservers are involved) and
the results are always the same. I really believe we're not facing DNS
problems nor the customer changing his MX records:
;; ANSWER SECTION:
azevedosette.com.br. 85088 IN MX 5 mail3.azevedosette.com.br.
azevedosette.com.br. 85088 IN MX 100
mailsp.azevedosette.com.br.
the log for the specific message i posted shows that several
delivery tries were made to the secondary MX
(mailsp.azevedosette.com.br) but no one to the primary MX
(mail3.azevedosette.com.br) but the final one. The interesting, and
that's because i initially asked about some feature that would make
postfix 'skip' bad MXs, is that during the timespan of those tries, i
have logs for other messages for the same destination domain (different
queueids) being delivered to the primary MX and several others
connection being rejected by his primary MX (421 You are disconnected
for policy reasons). Given this information, i can imagine both MXs were
published at that moment. Some logs showing transactions to the primary
MX (some successfully deliveries and some rejections) on the same
timespan of the logs previously posted:
Nov 16 15:53:29 correio postfix/smtp[30078]: F07EA15D4E2: host
mail3.azevedosette.com.br[200.198.91.178] said: 421 You are disconnected
for policy reasons, please try again later (in reply to MAIL FROM command)
Nov 16 15:53:29 correio postfix/smtp[30078]: F07EA15D4E2: lost
connection with mail3.azevedosette.com.br[200.198.91.178] while sending
RCPT TO
Nov 16 15:53:29 correio postfix/smtp[30077]: B3B0D15D4F9: host
mail3.azevedosette.com.br[200.198.91.178] said: 421 You are disconnected
for policy reasons, please try again later (in reply to MAIL FROM command)
Nov 16 15:53:30 correio postfix/smtp[31464]: 0026615D4FB:
to=<addr...@azevedosette.com.br>,
relay=mail3.azevedosette.com.br[200.198.91.178]:25, delay=1783,
delays=1782/0.04/0.2/0.77, dsn=2.6.0, status=sent (250 2.6.0
<20111116172347.0026615d...@correio.ourdomain.com.br> Queued mail for
delivery)
Nov 16 16:18:30 correio postfix/smtp[3000]: 6EDF015D4BB: host
mail3.azevedosette.com.br[200.198.91.178] said: 421 You are disconnected
for policy reasons, please try again later (in reply to RCPT TO command)
Nov 16 16:18:30 correio postfix/smtp[3000]: 6EDF015D4BB: lost connection
with mail3.azevedosette.com.br[200.198.91.178] while sending RCPT TO
Nov 16 16:18:30 correio postfix/smtp[3002]: DB13515D4AD:
to=<addr...@azevedosette.com.br>,
relay=mail3.azevedosette.com.br[200.198.91.178]:25, delay=3373,
delays=3372/0.04/0.25/0.79, dsn=2.6.0, status=sent (250 2.6.0
<20111116172217.db13515d...@correio.ourdomain.com.br> Queued mail for
delivery)
Nov 16 17:18:31 correio postfix/smtp[10887]: 28B3015D4A4:
to=<addr...@azevedosette.com.br>,
relay=mail3.azevedosette.com.br[200.198.91.178]:25, delay=6987,
delays=6984/0.05/0.22/2.4, dsn=2.6.0, status=sent (250 2.6.0
<20111116172205.28b3015d...@correio.ourdomain.com.br> Queued mail for
delivery)
Nov 16 18:15:06 correio postfix/smtp[17592]: 0E00615D5B2:
to=<addr...@azevedosette.com.br>,
relay=mail3.azevedosette.com.br[200.198.91.178]:25, delay=8.8,
delays=0.02/3.6/0.39/4.8, dsn=2.6.0, status=sent (250 2.6.0
<20111116201458.0e00615d...@correio.ourdomain.com.br> Queued mail for
delivery)
Nov 16 18:21:23 correio postfix/smtp[17582]: AEC8B15D750: host
mail3.azevedosette.com.br[200.198.91.178] said: 421 You are disconnected
for policy reasons, please try again later (in reply to MAIL FROM command)
Nov 16 18:21:23 correio postfix/smtp[17582]: AEC8B15D750: lost
connection with mail3.azevedosette.com.br[200.198.91.178] while sending
RCPT TO
Nov 16 21:48:32 correio postfix/smtp[14247]: 9F75015D511:
to=<addr...@azevedosette.com.br>,
relay=mail3.azevedosette.com.br[200.198.91.178]:25, delay=1558,
delays=1555/0.01/0.34/2.6, dsn=2.6.0, status=sent (250 2.6.0
<20111116232233.9f75015d...@correio.ourdomain.com.br> Queued mail for
delivery)
Nov 16 22:58:49 correio postfix/smtp[31315]: EDE2315E7D8:
to=<addr...@azevedosette.com.br>,
relay=mail3.azevedosette.com.br[200.198.91.178]:25, delay=1680,
delays=1659/0.06/0.23/20, dsn=2.6.0, status=sent (250 2.6.0
<4ec455b88202b_68d1..fdbe810d8189@projourdomain.tmail> Queued mail for
delivery)
Nov 16 23:23:30 correio postfix/smtp[1836]: 5EF7A15D4BC:
to=<addr...@azevedosette.com.br>,
relay=mail3.azevedosette.com.br[200.198.91.178]:25, delay=6911,
delays=6910/0.06/0.3/0.86, dsn=2.6.0, status=sent (250 2.6.0
<20111116232819.5ef7a15d...@correio.ourdomain.com.br> Queued mail for
delivery)
Nov 17 01:23:32 correio postfix/smtp[15118]: 612C115D4D7:
to=<addr...@azevedosette.com.br>,
relay=mail3.azevedosette.com.br[200.198.91.178]:25, delay=35992,
delays=35989/1.4/0.21/0.81, dsn=2.6.0, status=sent (250 2.6.0
<20111116172340.612c115d...@correio.ourdomain.com.br> Queued mail for
delivery)
Nov 17 01:23:32 correio postfix/smtp[15130]: ABB9A15D505: host
mail3.azevedosette.com.br[200.198.91.178] said: 421 You are disconnected
for policy reasons, please try again later (in reply to MAIL FROM command)
Nov 17 01:23:32 correio postfix/smtp[15130]: ABB9A15D505: lost
connection with mail3.azevedosette.com.br[200.198.91.178] while sending
RCPT TO
Nov 17 03:23:29 correio postfix/smtp[28130]: B497B15D483:
to=<addr...@azevedosette.com.br>,
relay=mail3.azevedosette.com.br[200.198.91.178]:25, delay=21335,
delays=21334/0.03/0.21/0.65, dsn=2.6.0, status=sent (250 2.6.0
<20111116232754.b497b15d...@correio.ourdomain.com.br> Queued mail for
delivery)
I have tried grepping the PID of the smtp process with errors, as
Wietse requested, and as this message on the mailing list i found on the
archives also suggested
http://marc.info/?l=postfix-users&m=119393677222356&w=2
but i found nothing. In fact my logs only show smtp process logging
on the very last try, which was the successfull one. All the others,
which were basically timeout to the secondary MX, are logged as
postfix/error and not postfix/smtp. Anyway, i tried grepping qmgr and
error PID, on that time, and found absolutely nothing related.
by the way, we're already working with the IT team of this customer
to identify why it's primary MX is rejecting LOTS of our connections. By
now, this wasnt solved yet. I expect this to be solved soon.
Anyway, i'm having hard times trying to figure out why, for some
messages, like the queueid i posted the full log, postfix is apparently
not even trying to delivery to the primary MX for some large periods of
time.
sorry for the huge message, but it was quite a lot information i
have to post to explain the whole scenario.
--
Atenciosamente / Sincerily,
Leonardo Rodrigues
Solutti Tecnologia
http://www.solutti.com.br
Minha armadilha de SPAM, NÃO mandem email
gertru...@solutti.com.br
My SPAMTRAP, do not email it
