postfix does not always queue msg to Exchange

[ferociousd]

Hello all,

I have some strange problem, and I can’t figure it out. I’m using Postfix on FreeBSD 7.0 as a mailgateway for about 1 ½ year. The last couple of days, people are complaining that they are missing e-mails that where sent to them.

I turned on logging on Exchange 2003, and started to look into the log files from FreeBSD and Exchange. Mail from sender X outside our organization arrives just normally to somebody inside our organization. But just sometimes, a mail is not being queued to our Exchange server and does not arrive. I have no idea what is going on, several of my colleagues are complaining about it. If I review one mail address, than I can see that mail is being send from the same sender, to the same recipient. But on day one, the mail does arrive, on day 2 it does not arrive and day 3 it does arrive again. If the mail does not arrive, I can not track it in Exchange Tracking center, I can not find it (anymore) in the Postfix queue but the sender does not get a message the mail could not be deliverd.

Here are some of the logs:

Mail does arrive:
pr 19 12:31:20 postfix/lmtp[54265]: 8743D4AE08: to=<insideemailaddress>, relay=127.0.0.1[127.0.0.1]:10024, delay=77, delays=0.14/0/0.01/77, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=52476-12, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4F8354ADEE)
Apr 19 12:31:20 postfix/qmgr[46438]: 4F8354ADEE: removed

Mail does not arrive:
Apr 20 11:12:41 postfix/lmtp[67228]: D678F4AE35: to==<insideemailaddress>, relay=127.0.0.1[127.0.0.1]:10024, conn_use=2, delay=431, delays=4.1/269/0/158, dsn=2.1.0, status=sent (250 2.1.0 Ok, id=66720-05-2, from MTA([127.0.0.1]:10025): 250 2.1.0 Ok)
Apr 20 11:12:41 postfix/qmgr[60642]: D678F4AE35: removed

In the first entry, the mail is being queued and delivered to Exchange. In the second entry, the mail does not arrive, and is not being queued to Exchange. If I search postfix logs on “250 2.1.0 Ok” all messages showed aren’t being queued to Exchange. Does anybody have any idea what is going on? Google didn’t know.

Thanks!

[jledhead]

is postfix doing any other filtering? like, do you have clamav or postgrey or amavis installed that would process before it hits exchange? also instead of searching for "250 2.1.0 Ok", what if you search for the sender address in the postfix log?

Is this reproduce-able or is it just randomly happening?

[ferociousd]

Thanks for answering, still could not find a solution.

I am using Amavis and McAfee. (ClamAV is disabled) We have been using it for about 1 ½ year, and did not have any problems with it.

I added “smtp_connection_cache_on_demand = no” in main.cf, but problem keeps popping up.

If I filter on sender, the first e-mail that has been send arrives just as it should. The second e-mail, fails. (same sender, same recipient ) I will add some logs:

Mail arrives:
Apr 22 08:40:31 postfix/qmgr[926]: E439A4AE23: from=<SENDER>, size=3325, nrcpt=1 (queue active)
Apr 22 08:40:31 amavis[1091]: (01091-09) LMTP::10024 /var/amavis/tmp/amavis-20100421T234225-01091: <SENDER> -> <RECEIVER> SIZE=3325 Received: from frontdoor ([127.0.0.1]) by localhost ([127.0.0.1]) (amavisd-new, port 10024) with LMTP for <RECEIVER>; Thu, 22 Apr 2010 08:40:31 +0200 (CEST)
Apr 22 08:40:31 amavis[1091]: (01091-09) Checking: PpTujJ5Hc6wC INTERNET [] <SENDER> -> <RECIEVER>
Apr 22 08:41:38 amavis[1091]: (01091-09) FWD via SMTP: <SENDER> -> <RECIEVER>,BODY=7BIT 250 2.0.0 Ok, id=01091-09, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as BB7834AE56
Apr 22 08:41:38 amavis[1091]: (01091-09) Passed CLEAN, INTERNET [] [] <SENDER> -> <RECEIVER>, Message-ID: <3A6CA4E1E9768D49971693DC4F58DF39DC737C>, mail_id: PpTujJ5Hc6wC, Hits: 0.567, size: 3325, queued_as: BB7834AE56, 67636 ms


Mail does not arrive: (same sender/ recipient )
Apr 26 11:26:19 postfix/qmgr[77441]: 1848A4AEEA: from=<RECEIVER>, size=6970, nrcpt=1 (queue active)
Apr 26 11:45:15 amavis[82631]: (82631-13-2) LMTP::10024 /var/amavis/tmp/amavis-20100426T114126-82631: <SENDER> -> <RECEIVER> SIZE=6970 Received: from frontdoor ([127.0.0.1]) by localhost ([127.0.0.1]) (amavisd-new, port 10024) with LMTP for <RECEIVER>; Mon, 26 Apr 2010 11:45:15 +0200 (CEST)
Apr 26 11:45:15 amavis[82631]: (82631-13-2) Checking: J-R4uDNNBAc4 INTERNET [] <SENDER> -> <RECEIVER>
Apr 26 11:47:16 amavis[82631]: (82631-13-2) FWD via SMTP: <SENDER> -> <RECEIVER>, 250 2.1.0 Ok, id=82631-13-2, from MTA([127.0.0.1]:10025): 250 2.1.0 Ok
Apr 26 11:47:16 amavis[82631]: (82631-13-2) Passed CLEAN, INTERNET [] [] <SENDER> -> <RECEIVER>, Message-ID: <3A6CA4E1E9768D49971693DC4F58DF39DC7387>, mail_id: J-R4uDNNBAc4, Hits: -0.306, size: 6970, queued_as: 250 2.1.0 Ok, 121823 ms

Unfortunately I can not reproduce the problem.

[jledhead]

I will be honest and say I haven't used amavis. but, do you have amavis writing to its own log file or is everything writing to mail.log? and just out of curiosity, its not sticking it back in the postfix queue is it? the only post even similar to this I could find is this [AMaViS-user] Amavis occasionally losing mail
which is actually very close to your problem. the poster is using different config lines than what you posted

$smtp_connection_cache_enable = 0;
$smtp_connection_cache_on_demand = 0;

even though it didn't fix it. and the reply suggests there is a patch that should fix it. if it doesn't help, maybe you should join the amavis users list for the best help. as a postfix admin I always find it helpful to get on the postfix users list. it is high traffic but you can get excellent help there.

[ferociousd]

I am taking over someone else’s job, I'm not really familiar with Postfix/Amavis but as far as I know, Amavis is logging everything to mail.log.

Amavis returns it to Postfix, but two strange things are happening in my opinion.

1: Amavis does not give the message received from postfix, a queue name.
2: Amavis gives it back to Postfix, but Postfix does not know what to do with it.

I will check the Amavis user group, thanks.