[SPAM] Some messages fail delivery in postfix -> maildrop -> crm114 chain
glen martin <[email protected]>
| Newsgroups | gmane.mail.maildrop,gmane.spam.detected |
|---|---|
| Message-ID | <[email protected]> |
Hi all,
I have a problem with misbehaving email delivery. Some inbound
messages, mostly spam but some mailing lists, are not being delivered
through postfix -> maildrop, even though many other messages to same
users are delivered fine. The problem may be with maildrop using xfilter
to call crm114, but different tests are giving conflicting results.
*Summary*:
The inbound email chain generally follows this:
internet -> postfix -> amavisd-new -> ( spamassassin ; clamd ) ->
postfix -> local -> maildrop ( xfilter crm114 ; pattern matches ->
various .maildirs )
What I observe doesn't make much sense to me:
- for many inbound emails, postfix -> maildrop -> .maildir is working fine.
- postfix -> maildrop works, which uses xfilter to call crm114,
crm114 examines and annotates the content, maildrop pattern matches are
performed according to ~/.mailfilter, and mail is being deposited in
desired .maildirs.
- headers in delivered messages confirm that crm114 successfully
examined those messages
- for some inbound messages postfix reports an apparent maildrop error.
Those messages are remaining queued in postfix spool
- if I remove the maildrop xfilter command from ~/.mailfilter, the
message is now successfully delivered
- but if I manually deliver the same content through maildrop at the
command line it works fine, even if the xfilter crm114 command is
performed. Maildrop delivery mode or not doesn't seem to matter
(succeeds both ways).
So something about postfix -> maildrop -> crm114 is failing, only in
combination, for *some* but not all messages, even though the
subcomponents of that chain seem to work fine.
I've been trying to debug (see below), and reading anything I could find
on the web, haven't found any solutions nor other debugging approaches.
Any suggestions on what I could try next, or what the problem might be?
*Detail*:
In the snippets below, I have done text substitutions of hostnames,
usernames and such (to strings like 'host', 'domainname', 'otherdomain',
'uname', 'me', 'alias', etc).
Generally following http://www.postfix.org/MAILDROP_README.html for
indirect delivery using the local agent and maildrop:
In postfix main.cf, I have:
mailbox_command = /usr/bin/maildrop -d ${USER}
In postfix master.cf, I have commented out the maildrop section
since the README didn't say to include it.
I have reloaded postfix to ensure my latest config is being used.
Here is my ~/.mailfilter:
<snip>
MAILDIR="$HOME/.maildir"
DEFAULT="$MAILDIR"
logfile "maildropfilter.log"
log "=========="
xfilter "/usr/bin/crm114 -u $HOME/.crm114/ $HOME/.crm114/mailfilter.crm"
log "----------"
if (/^X-CRM114-Status: SPAM/)
to "$MAILDIR/.0_checkspam._R_spam"
</snip>
The immediate symptom is that the some messages sit spooled forever
(until they expire, I suppose). mailq gives me a whole bunch of items
that look like this:
<snip>
51EE7520BA 1981 Sat Jan 4 11:27:34 MAILER-DAEMON
(temporary failure. Command output: /usr/bin/maildrop: Unable to
filter message.)
[email protected]
[email protected]
</snip>
And if I look in the postfix spool:
# cat /var/spool/postfix/defer/5/51EE7520BA
<[email protected]>: temporary failure. Command output:
/usr/bin/maildrop: Unable to filter message.
[email protected]
[email protected]
offset=586
dsn_orig_rcpt=rfc822;[email protected]
status=4.3.0
action=delayed
diag_type=x-unix
diag_text=/usr/bin/maildrop: Unable to filter message.
reason=temporary failure. Command output: /usr/bin/maildrop: Unable
to filter message.
Here is the portion of the postfix mail log corresponding to the latter
half of processing, after amavisd-new is done:
<snip>
Jan 4 11:27:34 hostname postfix/smtpd[4340]: connect from
localhost[127.0.0.1]
Jan 4 11:27:34 hostname postfix/smtpd[4340]: 51EE7520BA:
client=localhost[127.0.0.1]
Jan 4 11:27:34 hostname postfix/cleanup[4333]: 51EE7520BA:
message-id=<[email protected]>
Jan 4 11:27:34 hostname postfix/smtpd[4340]: disconnect from
localhost[127.0.0.1]
Jan 4 11:27:34 hostname postfix/qmgr[31086]: 51EE7520BA: from=<>,
size=1981, nrcpt=1 (queue active)
Jan 4 11:27:34 hostname amavis[3125]: (03125-07) FWD from <> ->
<[email protected]>,BODY=7BIT 250 2.0.0 from
MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 51EE7520BA
Jan 4 11:27:34 hostname amavis[3125]: (03125-07) Passed SPAM
{RelayedTaggedInbound,Quarantined}, [178.123.228.175]:28346
[47.74.64.174] <> -> <[email protected]>, quarantine:
spam-EUMxcjcGGyTj.gz, Queue-ID: 1A5B2520B4, mail_id: EUMxcjcGGyTj,
Hits: 16.162, size: 507, queued_as: 51EE7520BA, 7561 ms
Jan 4 11:27:34 hostname postfix/smtp[4334]: 1A5B2520B4:
to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024,
delay=10, delays=2.7/0.01/0.01/7.6, dsn=2.0.0, status=sent (250
2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as
51EE7520BA)
Jan 4 11:27:34 hostname postfix/qmgr[31086]: 1A5B2520B4: removed
Jan 4 11:27:34 hostname maildrop[4342]: Unable to filter message.
Jan 4 11:27:34 hostname postfix/local[4341]: 51EE7520BA:
to=<[email protected]>, orig_to=<[email protected]>,
relay=local, delay=0.24, delays=0.04/0.01/0/0.19, dsn=4.3.0,
status=deferred (temporary failure. Command output:
/usr/bin/maildrop: Unable to filter message. )
</snip>
I didn't find the logged command output from maildrop very informative,
so I found _another line in mail.log for a different message_ that was
delivered successfully, here is what it said.
<snip>
postfix/local[4545]: 44D2B520C2: to=<[email protected]>,
relay=local, delay=0.14, delays=0.05/0.01/0/0.08, dsn=2.0.0,
status=sent (delivered to command: /usr/bin/maildrop -d ${USER})
</snip>
Unless I'm missing something, this looks like postfix is configured fine
to deliver through maildrop.
In my .mailfilter you may have noticed a couple of logging statements,
log "========" before the xfilter, and log "----------" after.
Examining that logfile, I find only the "=====" lines for the messages
that are failing delivery, so I expect the xfilter of crm114 is the culprit.
<snip>
$ tail maildropfilter.log
==========
==========
==========
==========
</snip>
So now I tried delivering this message manually to get better debug
output. I put ' to "tmpfile3" ' at top of my ~/.mailfilter, and then
used postqueue to redeliver this message.
<snip>
# postqueue -v -i 51EE7520BA
postqueue: name_mask: ipv4
postqueue: name_mask: subnet
postqueue: inet_addr_local: configured 2 IPv4 addresses
postqueue: been_here: 127.0.0.0/8: 0
postqueue: been_here: 192.168.0.0/24: 0
postqueue: mynetworks: 127.0.0.0/8 192.168.0.0/24
postqueue: flush_send_file: queue_id 51EE7520BA
postqueue: connect to subsystem public/flush
postqueue: send attr request = send_file
postqueue: send attr queue_id = 51EE7520BA
postqueue: public/flush socket: wanted attribute: status
postqueue: input attribute name: status
postqueue: input attribute value: 0
postqueue: public/flush socket: wanted attribute: (list terminator)
postqueue: input attribute name: (end)
postqueue: flush_send_file: queue_id 51EE7520BA status 0
</snip>
Here is the test message itself:
<snip>
uname $ cat tmpfile3
From MAILER-DAEMON Sat Jan 4 11:50:51 2014
Return-Path: <>
X-Original-To: [email protected]
Delivered-To: [email protected]
Received: from localhost (localhost [127.0.0.1])
by hostname.locutory.org (Postfix) with ESMTP id 51EE7520BA
for <[email protected]>; Sat, 4 Jan 2014 11:27:34
-0800 (PST)
X-Quarantine-ID: <EUMxcjcGGyTj>
X-Virus-Scanned: amavisd-new at locutory.org
X-Amavis-Alert: BAD HEADER SECTION, Missing required header field:
"Date"
X-Spam-Flag: YES
X-Spam-Score: 16.162
X-Spam-Level: ****************
X-Spam-Status: Yes, score=16.162 tagged_above=-100 required=6.2
tests=[FSL_HELO_BARE_IP_1=1.426, FSL_HELO_BARE_IP_2=0.001,
MISSING_DATE=1.396, MISSING_MID=0.14,
RCVD_HELO_IP_MISMATCH=1.186,
RCVD_IN_BL_SPAMCOP_NET=1.246, RCVD_IN_BRBL_LASTEXT=1.644,
RCVD_IN_PBL=3.558, RCVD_IN_PSBL=2.7, RCVD_IN_XBL=0.724,
RCVD_NUMERIC_HELO=0.865, RDNS_NONE=1.274, TVD_RCVD_IP=0.001,
TVD_RCVD_IP4=0.001] autolearn=disabled
X-Spam-Tests: FSL_HELO_BARE_IP_1=1.426,FSL_HELO_BARE_IP_2=0.001,
MISSING_DATE=1.396,MISSING_MID=0.14,RCVD_HELO_IP_MISMATCH=1.186,
RCVD_IN_BL_SPAMCOP_NET=1.246,RCVD_IN_BRBL_LASTEXT=1.644,RCVD_IN_PBL=3.558,
RCVD_IN_PSBL=2.7,RCVD_IN_XBL=0.724,RCVD_NUMERIC_HELO=0.865,RDNS_NONE=1.274,
TVD_RCVD_IP=0.001,TVD_RCVD_IP4=0.001
Received: from hostname.locutory.org ([127.0.0.1])
by localhost (hostname.locutory.org [127.0.0.1])
(amavisd-new, port 10024)
with ESMTP id EUMxcjcGGyTj for <[email protected]>;
Sat, 4 Jan 2014 11:27:26 -0800 (PST)
Received: from 178.123.17.19 (unknown [178.123.228.175])
by hostname.locutory.org (Postfix) with SMTP id 1A5B2520B4
for <[email protected]>; Sat, 4 Jan 2014 11:27:24
-0800 (PST)
Received: from unknown (HELO localhost)
([email protected]@47.74.64.174)
by 178.123.228.175 with ESMTPA; Sat, 4 Jan 2014 21:32:19 +0200
From: [email protected]
To: [email protected]
Subject: Make a good present for your wife
Message-Id: <[email protected]>
Date: Sat, 4 Jan 2014 11:27:34 -0800 (PST)
Open your love potential http://detail.tanilm.ru/
</snip>
I tried to manually deliver using maildrop as the recipient user:
uname $ cat tmpfile3 | /usr/bin/maildrop -V 5 .mailfilter
Message start at 44 bytes, envelope sender=MAILER-DAEMON
maildrop: Attempting .mailfilter
.mailfilter(1): MAILDIR="/home/uname/.maildir"
.mailfilter(2): DEFAULT="/home/uname/.maildir"
.mailfilter(4): Opening logfile maildropfilter.log
maildrop: Filtering through xfilter /usr/bin/crm114 -u
/home/uname/.crm114/ /home/uname/.crm114/mailfilter.crm
.mailfilter(11): Evaluating IF condition.
... bunch of condition tests truncated ...
Matching /^X-CRM114-Status: SPAM/ against X-CRM114-Status: SPAM (
pR: -11.8884 )
.mailfilter(11): Search of ^X-CRM114-Status: SPAM = 1
.mailfilter(11): IF evaluated, result=1
maildrop: Delivery complete.
That seemed to work without error, so as root I manually ran it through
maildrop in delivery mode, trying my best to duplicate how postfix would
call maildrop:
# cat ~uname/tmpfile3 | /usr/bin/maildrop -d uname ; echo
${PIPESTATUS[*]}
0 0
And that worked too (I noted '0' return codes).
I did one other test: I commented out the xfilter in my .mailfilter file
and used postqueue to redeliver another one of the failing messages. In
this case, the redelivery succeeded. This suggests the xfilter to
xrm114 failed ... but the previous test showed that call succeeding when
I start maildrop from shell.
So I'm puzzled. The maildrop portion of the inbound email chain seems to
be working fine when called by hand, including calls to crm114 via
xfilter, whether in maildrop delivery mode or not. But when the same
chain is invoked from postfix it fails for some messages, not for others.
This is all running on a gentoo system that is up to date with stable
packages.
# equery list postfix maildrop crm114
* Searching for postfix ...
[IP-] [ ] mail-mta/postfix-2.10.2:0
* Searching for maildrop ...
[IP-] [ ] mail-filter/maildrop-2.6.0:0
* Searching for crm114 ...
[IP-] [ ] app-text/crm114-20100106:0
Maildrop is installed setuid root.
# ls -l /usr/bin/maildrop
-rws--x--x 1 root root 204184 May 25 2013 /usr/bin/maildrop
If you have read this far, thanks for your perseverance. :) Any
suggestions on what additional testing I could use to isolate the
problem would be appreciated.
Thanks
glen
------------------------------------------------------------------------------
Rapidly troubleshoot problems before they affect your business. Most IT
organizations don't have a clear picture of how application performance
affects their revenue. With AppDynamics, you get 100% visibility into your
Java,.NET, & PHP application. Start your 15-day FREE TRIAL of AppDynamics Pro!
http://pubads.g.doubleclick.net/gampad/clk?id=84349831&iu=/4140/ostg.clktrk
_______________________________________________
Courier-maildrop mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/courier-maildrop