We have a case where we are occasionally losing mail sent through amavis. We are using amavisd-new-2.6.1-2. Here's what's happening:
Mail comes into postfix (port 25), postfix routes through amavis (10024), which then routes to backend postfix (10025). I think this is a common, if not standard, configuration people use. Postfix (25) is accepting the mail. It then tries to deliver it to amavis, and it 'thinks' it is successful, so postfix removes it from the queue. Amavis actually had a problem, but instead of returning an error code to postfix, it inadvertantly returned a success code. Here are the applicable log entries: Feb 18 19:44:17 gwsinam01 postfix/smtpd[25360]: 0F3DF1F817E: client=unknown[165.212.54.192] Feb 18 19:44:17 gwsinam01 postfix/cleanup[31503]: 0F3DF1F817E: message-id=<997nbrtsd9056...@per1-denvercolo-gwsin01> Feb 18 19:44:17 gwsinam01 postfix/qmgr[28031]: 0F3DF1F817E: from=<mdri...@emdvg192.eservices.usa.net>, size=1512, nrcpt=1 (queue active) Feb 18 19:44:17 gwsinam01 postfix/lmtp[31510]: 0F3DF1F817E: to=<interte...@emdvg192.eservices.usa.net>, relay=127.0.0.1[127.0.0.1], delay=0, status=sent (250 2.1.0 Ok, id=18065-02-5, from MTA([127.0.0.1]:10025): 250 Ok) Feb 18 19:44:17 gwsinam01 postfix/qmgr[28031]: 0F3DF1F817E: removed Feb 18 19:44:17 gwsinam01 amavis[18065]: (18065-02-5) Negative SMTP resp. to DATA: 250 Ok Feb 18 19:44:17 gwsinam01 amavis[18065]: (18065-02-5) Passed CLEAN, [165.212.54.192] [165.212.54.192] <mdri...@emdvg192.eservices.usa.net> -> <interte...@emdvg192.eservices.usa.net>, Message-ID: <997nbrtsd9056...@per1-denvercolo-gwsin01>, mail_id: WWoHsFeMNE+K, Hits: -, size: 1511, pt: 18, queued_as: 250 Ok, 77 ms Feb 18 19:44:17 gwsinam01 postfix/lmtp[31510]: 0F3DF1F817E: to=<interte...@emdvg192.eservices.usa.net>, relay=127.0.0.1[127.0.0.1], delay=0, status=sent (250 2.1.0 Ok, id=18065-02-5, from MTA([127.0.0.1]:10025): 250 Ok) This problem is not easy to duplicate, but when it starts to happen on a box, it seems that it will continue to happen periodically until amavis is restarted. The "Negative SMTP resp. to DATA" line seems to indicate that the amavis SMTP transaction with the backend postfix has somehow gotten out of sync. We thought that maybe this was due to smtp connection caching, so we added the following lines to the config file about a month ago: $smtp_connection_cache_enable = 0; $smtp_connection_cache_on_demand = 0; However, the problem occurred again yesterday even with this setting. In addition to the log entries above that show we are losing mail, we see other items in the log that are similar in nature but don't cause a loss of mail. Here is another group of log entries: -- amavis logs -- Feb 18 03:20:16 gwsinam01 amavis[22317]: (22317-02) (!)rw_loop: leaving rw loop, no progress Feb 18 03:20:16 gwsinam01 amavis[22317]: (22317-02) (!)FWD via SMTP: <mdri...@emdvg192.eservices.usa.net> -> <ctgwsinv...@emdvg192.eservices.usa.net>, 451 4.5.0 From MTA([127.0.0.1]:10025) during fwd-connect (Negative greeting: at (eval 87) line 555.): id=22317-02 Feb 18 03:20:16 gwsinam01 amavis[22317]: (22317-02) Blocked MTA-BLOCKED, [165.212.54.192] [165.212.54.192] <mdri...@emdvg192.eservices.usa.net> -> <ctgwsinv...@emdvg192.eservices.usa.net>, Message-ID: <723nbrdtc7056...@per1-denvercolo-gwsin01>, mail_id: 8jTOPl+MEkHm, Hits: -, size: 1516, pt: 18, 30080 ms -- postfix logs -- Feb 18 03:19:31 gwsinam01 postfix/smtpd[31890]: 5AAE61F818F: client=unknown[165.212.54.192] Feb 18 03:19:31 gwsinam01 postfix/cleanup[1362]: 5AAE61F818F: message-id=<723nbrdtc7056...@per1-denvercolo-gwsin01> Feb 18 03:19:31 gwsinam01 postfix/qmgr[28031]: 5AAE61F818F: from=<mdri...@emdvg192.eservices.usa.net>, size=1517, nrcpt=1 (queue active) Feb 18 03:20:32 gwsinam01 postfix/lmtp[1368]: 5AAE61F818F: to=<ctgwsinv...@emdvg192.eservices.usa.net>, relay=127.0.0.1[127.0.0.1], delay=76, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.5.0 From MTA([127.0.0.1]:10025) during fwd-connect (Negative greeting: at (eval 87) line 555.): id=22317-02 (in reply to end of DATA command)) Feb 18 03:44:29 gwsinam01 postfix/qmgr[28031]: 5AAE61F818F: from=<mdri...@emdvg192.eservices.usa.net>, size=1517, nrcpt=1 (queue active) Feb 18 03:44:29 gwsinam01 postfix/lmtp[3806]: 5AAE61F818F: to=<ctgwsinv...@emdvg192.eservices.usa.net>, relay=127.0.0.1[127.0.0.1], delay=1513, status=sent (250 2.6.0 Ok, id=25703-02-6, from MTA([127.0.0.1]:10025): 250 Ok: queued as CF7401F8191) Feb 18 03:44:29 gwsinam01 postfix/qmgr[28031]: 5AAE61F818F: removed This message was rejected by amavis, but was properly deferred and then retried successfully by postfix. Any help figuring out how to fix this would be appreciated. Chris USA.NET You Run Your Business. We'll Run Your Email. This message is for the sole use of the intended recipient(s) and may contain confidential and/or privileged information of USA.NET, Inc. Any unauthorized review, use, copying, disclosure, or distribution is prohibited. If you are not the intended recipient, please immediately contact the sender by reply email and delete all copies of the original message. ------------------------------------------------------------------------------ Open Source Business Conference (OSBC), March 24-25, 2009, San Francisco, CA -OSBC tackles the biggest issue in open source: Open Sourcing the Enterprise -Strategies to boost innovation and cut costs with open source participation -Receive a $600 discount off the registration fee with the source code: SFAD http://p.sf.net/sfu/XcvMzF8H _______________________________________________ AMaViS-user mailing list AMaViS-user@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/amavis-user AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3 AMaViS-HowTos:http://www.amavis.org/howto/
