Postfix Fails Delivery of Redirected Messages

Question

Level 1

15 points

Postfix Fails Delivery of Redirected Messages

I'm running Server 10.4, and I've setup junkmail and notjunkmail users for spam training.

However, I'm getting an intermittant, but highly consistent/frequent, failure when I redirect a message to either of those accounts. The accounts will receive normally sent messages, just not bounced ones.

Suggestions?

Here are some logs:

SYSTEM.LOG (SquirrelMail Redirect Failed)
postfix/smtpd[11938]: auxpropfunc error no mechanism available

MAIL.LOG (SquirrelMail Redirect Failed)
postfix/smtpd[11886]: connect from localhost[127.0.0.1]
postfix/smtpd[11886]: 561765B255: client=localhost[127.0.0.1]
postfix/cleanup[11935]: 561765B255: message-id=<20051003051749.8539C589E5@mail.nicksay.com>
postfix/qmgr[9895]: 561765B255: from=<alex@nicksay.com>, size=3499, nrcpt=1 (queue active)
postfix/smtpd[11886]: disconnect from localhost[127.0.0.1]
postfix/smtpd[11938]: connect from localhost[127.0.0.1]
postfix/smtpd[11938]: A9A895B26D: client=localhost[127.0.0.1]
postfix/cleanup[11935]: A9A895B26D: message-id=<20051003051749.8539C589E5@mail.nicksay.com>
postfix/qmgr[9895]: A9A895B26D: from=<alex@nicksay.com>, size=4078, nrcpt=1 (queue active)
postfix/smtpd[11938]: disconnect from localhost[127.0.0.1]
postfix/smtp[11936]: 561765B255: to=<junkmail@mail.nicksay.com>, relay=127.0.0.1[127.0.0.1], delay=2, status=sent (250 2.6.0 Ok, id=11377-05, from MTA: 250 Ok: queued as A9A895B26D)
postfix/qmgr[9895]: 561765B255: removed
postfix/pipe[11940]: A9A895B26D: to=<junkmail@mail.nicksay.com>, relay=cyrus, delay=1, status=sent (mail.nicksay.com)
postfix/qmgr[9895]: A9A895B26D: removed

SYSTEM.LOG (Mail.app Redirect Failed)
postfix/smtpd[11892]: auxpropfunc error no mechanism available

MAIL.LOG (Mail.app Redirect Failed)
postfix/smtpd[11886]: connect from adsl-66-218-51-134.dslextreme.com[66.218.51.134]
postfix/smtpd[11886]: 25AFE5B21F: client=adsl-66-218-51-134.dslextreme.com[66.218.51.134], sasl_method=PLAIN, sasl_username=alex
postfix/cleanup[11889]: 25AFE5B21F: resent-message-id=<BAY10-F236A1BA174DC2A4148D6D0B1600@bitsmart.com>
postfix/cleanup[11889]: 25AFE5B21F: message-id=<B65B66B3-D0E0-4754-9CF4-BBF615B5A479@bitsmart.com>
postfix/qmgr[9895]: 25AFE5B21F: from=<alex@nicksay.com>, size=1189, nrcpt=1 (queue active)
postfix/smtpd[11892]: connect from localhost[127.0.0.1]
postfix/smtpd[11892]: DBCE85B22E: client=localhost[127.0.0.1]
postfix/cleanup[11889]: DBCE85B22E: resent-message-id=<BAY10-F236A1BA174DC2A4148D6D0B1600@bitsmart.com>
postfix/cleanup[11889]: DBCE85B22E: message-id=<B65B66B3-D0E0-4754-9CF4-BBF615B5A479@bitsmart.com>
postfix/qmgr[9895]: DBCE85B22E: from=<alex@nicksay.com>, size=1666, nrcpt=1 (queue active)
postfix/smtpd[11892]: disconnect from localhost[127.0.0.1]
postfix/smtp[11890]: 25AFE5B21F: to=<junkmail@mail.nicksay.com>, relay=127.0.0.1[127.0.0.1], delay=1, status=sent (250 2.6.0 Ok, id=11043-07, from MTA: 250 Ok: queued as DBCE85B22E)
postfix/qmgr[9895]: 25AFE5B21F: removed
postfix/pipe[11894]: DBCE85B22E: to=<junkmail@mail.nicksay.com>, relay=cyrus, delay=1, status=sent (mail.nicksay.com)
postfix/qmgr[9895]: DBCE85B22E: removed

MAIL.LOG (SquirrelMail Redirect Succeeded)
postfix/smtpd[11779]: connect from localhost[127.0.0.1]
postfix/smtpd[11779]: A861E5B0E0: client=localhost[127.0.0.1]
postfix/cleanup[11782]: A861E5B0E0: message-id=<CDBCDDIGPPCFGIDPDLHGOGDMCBAA.plyoung_js@moen.com>
postfix/qmgr[9895]: A861E5B0E0: from=<alex@nicksay.com>, size=4538, nrcpt=1 (queue active)
postfix/smtpd[11779]: disconnect from localhost[127.0.0.1]
postfix/smtpd[11787]: connect from localhost[127.0.0.1]
postfix/smtpd[11787]: 0EBEA5B0F2: client=localhost[127.0.0.1]
postfix/cleanup[11782]: 0EBEA5B0F2: message-id=<CDBCDDIGPPCFGIDPDLHGOGDMCBAA.plyoung_js@moen.com>
postfix/qmgr[9895]: 0EBEA5B0F2: from=<alex@nicksay.com>, size=5104, nrcpt=1 (queue active)
postfix/smtpd[11787]: disconnect from localhost[127.0.0.1]
postfix/pipe[11789]: 0EBEA5B0F2: to=<junkmail@mail.nicksay.com>, relay=cyrus, delay=0, st

Posted on Oct 3, 2005 3:17 PM

Reply

Answer 1

Alex Nicksay Author

Level 1

15 points

Oct 3, 2005 3:19 PM in response to Alex Nicksay

postfix/pipe[11789]: 0EBEA5B0F2: to=<junkmail@mail.nicksay.com>, relay=cyrus, delay=0, status=sent (mail.nicksay.com)
postfix/qmgr[9895]: 0EBEA5B0F2: removed
postfix/smtp[11783]: A861E5B0E0: to=<junkmail@mail.nicksay.com>, relay=127.0.0.1[127.0.0.1], delay=2, status=sent (250 2.6.0 Ok, id=11377-02, from MTA: 250 Ok: queued as 0EBEA5B0F2)
postfix/qmgr[9895]: A861E5B0E0: removed

MAIL.LOG (SquirrelMail Send Succeeded)
postfix/smtpd[12091]: connect from localhost[127.0.0.1]
postfix/smtpd[12091]: 4C3005B3E6: client=localhost[127.0.0.1]
postfix/cleanup[12094]: 4C3005B3E6: message-id=<55510.66.218.51.100.1128373489.squirrel@mail.nicksay.com>
postfix/qmgr[9895]: 4C3005B3E6: from=<alex@nicksay.com>, size=752, nrcpt=1 (queue active)
postfix/smtpd[12091]: disconnect from localhost[127.0.0.1]
postfix/smtpd[12097]: connect from localhost[127.0.0.1]
postfix/smtpd[12097]: 0DB205B3F7: client=localhost[127.0.0.1]
postfix/cleanup[12094]: 0DB205B3F7: message-id=<55510.66.218.51.100.1128373489.squirrel@mail.nicksay.com>
postfix/qmgr[9895]: 0DB205B3F7: from=<alex@nicksay.com>, size=1246, nrcpt=1 (queue active)
postfix/smtpd[12097]: disconnect from localhost[127.0.0.1]
postfix/smtp[12095]: 4C3005B3E6: to=<junkmail@mail.nicksay.com>, relay=127.0.0.1[127.0.0.1], delay=1, status=sent (250 2.6.0 Ok, id=11377-07, from MTA: 250 Ok: queued as 0DB205B3F7)
postfix/qmgr[9895]: 4C3005B3E6: removed
postfix/pipe[12099]: 0DB205B3F7: to=<junkmail@mail.nicksay.com>, relay=cyrus, delay=0, status=sent (mail.nicksay.com)
postfix/qmgr[9895]: 0DB205B3F7: removed

Thanks for any help.

Reply

Answer 2

Alex Nicksay Author

Level 1

15 points

Oct 3, 2005 3:22 PM in response to Alex Nicksay

A quick clarification....

Squirrelmail or Mail.app will successfully send the redirected message.

Mail.log seems to indicate that Postfix is delivering it. (I think?)
System.log says 'auxpropfunc error no mechanism available'.

The message doesn't show up in the junkmail user's inbox.

Thanks.

Reply

Answer 3

pterobyte

Level 6

11,104 points

Oct 4, 2005 1:17 AM in response to Alex Nicksay

You can ignore "postfix/smtpd[11938]: auxpropfunc error no mechanism available". It's a known issue and has nothing to do with your problem.

Do you have any other delivery problems? Is the junk you are redirecting maybe above the "kill_level"?

Reply

Answer 4

Alex Nicksay Author

Level 1

15 points

Oct 4, 2005 1:55 AM in response to pterobyte

I don't think that there are other problems, but this is quite a new setup and it's currently getting light usage (i.e. just me until it's ready to be a production server).

The odd thing about this problem is that the first junk message I redirect will get through, but subsequent ones won't. If I wait several hours and try again, the same scenario happens: the first is delivered, the rest are not.

I'm guessing that the "kill_level" is measured against the "hits" value in the X-Spam-Status header?

From my AMAVISD.CONF:
$sa tag_leveldeflt = -999; # add spam info headers if at, or above that level
$sa tag2_leveldeflt = 5.0; # add 'spam detected' headers at that level
$sa kill_leveldeflt = 22.0;
#$sa kill_leveldeflt = $sa tag2_leveldeflt; # triggers spam evasive actions

From a (first) successfully delivery:

X-Spam-Status: No, hits=1.533 tagged_above=-999 required=5
tests=DATE IN_PAST_0306, DOMAIN_4U2
X-Spam-Level: *

From multiple (subsequent) failed deliveries:

X-Spam-Status: No, hits=1.714 tagged_above=-999 required=5 tests=BANG_MORE,
DRUGS_ERECTILE, FROM ENDS_INNUMS, FROM HAS_ULINENUMS
X-Spam-Level: *

X-Spam-Status: No, hits=3.435 tagged_above=-999 required=5
tests=RCVD HELO_IPMISMATCH, RCVD NUMERICHELO
X-Spam-Level: *

X-Spam-Status: No, hits=1.827 tagged_above=-999 required=5
tests=DATE IN_PAST_0306, MIME BASE64_NONAME, MIME BASE64TEXT
X-Spam-Level: *

Reply

Answer 5

Alex Nicksay Author

Level 1

15 points

Oct 4, 2005 2:08 AM in response to Alex Nicksay

I was just looking at MAILACCESS.LOG and noticed several lines like

lmtpunix[15114]: dupelim: eliminated duplicate message to user.junkmail id <BAY10-F236A1BA174DC2A4148D6D0B1600@bitsmart.com> (delivery)

or

lmtpunix[15307]: dupelim: eliminated duplicate message to user.junkmail id <4551347352766298013115484@dotnet.com> (delivery)

Would this explain the situation?
Postfix does deliver them successfully, but "lmtpunix" thinks they're duplicates and deletes them?

Why would it think they're duplicates?
(Some, but definitely not all, of the messages I had sent before, as I was testing spam redirection integrated into SquirrelMail.)
Is there a record of previously delivered messages I might need to delete/clear out/reset?

Thanks.

Reply

Answer 6

pterobyte

Level 6

11,104 points

Oct 4, 2005 4:38 AM in response to Alex Nicksay

I can't see a reason why it should consider them duplicates (unless they really are duplicates of course). Could it be that you have amavisd configured to send them on as well?

Reply

Answer 7

Alex Nicksay Author

Level 1

15 points

Oct 4, 2005 10:23 AM in response to pterobyte

In Server Admin, I've set Junk to be "Delivered". The *_destiny settings in AMAVISD.CONF are:

$final virusdestiny = D_DISCARD; # (defaults to D_BOUNCE)
$final banneddestiny = D_BOUNCE; # (defaults to D_BOUNCE)
$final spamdestiny = D_PASS; # (defaults to D_REJECT)
$final bad_headerdestiny = D_PASS; # (defaults to D_PASS), D_BOUNCE suggested

I did a test this morning. I received 4 false neg junk messages. I redirected them one at a time to the junkmail account. Each one was delivered.

Yesterday I had redirected one that was delivered. Last night, I purged the junkmail mailbox contents (via the command from your excellent spamtrainer script).
So, I redirected it today. This one was not delivered and a "dupelim" log message showed up.

So, why won't it let me redirect the message twice?

At this Cyrus IMAP HOW-TO:
http://www.faqs.org/docs/Linux-HOWTO/Cyrus-IMAP.html#ss8.4
I read the following:

If you don't periodically prune the database of deliveries,
you can fill up your file system. Adding a cron job which
will run once a day is one way to do this. That involves
going to /etc/cron.daily and creating a file named
cyrus-imapd. Inside that file, put the following two lines
of code:
#!/bin/bash
su cyrus -s /bin/bash -c '/usr/cyrus/bin/deliver -E 3'
Make this script executable by running: chmod 755 cyrus-imad
You should also create the deliverdb directory to store database
files in:
mkdir /var/imap/deliverdb

Does that relate at all?

Thanks again; I appreciate the continued help.

Reply

Answer 8

Alex Nicksay Author

Level 1

15 points

Oct 4, 2005 10:57 AM in response to Alex Nicksay

The HOW-TO I read isn't actually correct for the setup that comes with OS X Server. Instead, one would use

sudo -u cyrusimap /usr/bin/cyrus/bin/cyr_expire -E 3

To delete delivery database entries older than 3 days.

I gave this a run, and afterwards I was able to redirect messages that were previously being eliminated as duplicates, I think. I'll need to wait a day or so before I can really be sure.

If this is the case, I'm going to add it to my periodic-daily. While duplicate suppression is a good thing (for mailing lists, etc), I think being able to send the same message to the same mailbox again is a good thing if you have to wait a couple days. So I'll probably use "-E 3".

I'll see how this goes tomorrow and post an update here afterward.

Reply

Answer 9

pterobyte

Level 6

11,104 points

Oct 4, 2005 11:13 AM in response to Alex Nicksay

To be honest, this is the first time I encounter this kind of behaviour on Tiger Server (and my server processes lots of messages).

Did you tweak your imapd.conf by any chance? I remember a parameter along the lines of "duplicatesuppression: 0 or duplicatesuppression: 1" that can trigger this behaviour?

Reply

Answer 10

Alex Nicksay Author

Level 1

15 points

Oct 4, 2005 12:05 PM in response to pterobyte

My system is basically a stock install. I've tweaked a bunch of SquirrelMaill plugins, etc, but that's it. The only config file I've edited is amavisd.conf, where I changed the value of local domainsmaps, but I've checked that the behavior is the same whether it is set to

@local domainsmaps = ( 1 );

or

@local domainsmaps = ( [".$mydomain"], read hash("/etc/postfix/virtualdomains") );

Mine is set to the latter for now, though I think I'll change it to the former once I let server out of "beta" (i.e. my users start working with it).

Otherwise, I really think it's all set to defaults or configured by Server Admin's settings.

Reply

Answer 11

Alex Nicksay Author

Level 1

15 points

Nov 7, 2005 6:07 AM in response to Alex Nicksay

Just a quick follow-up.

I haven't had any problems for the last several weeks, so I think the situation is resolved.

Thanks for the help.

Reply