narkive

unknown

1970-01-01 00:00:00 UTC

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

--------------050802040603040900020405
Content-Type: text/html; charset=ISO-8859-1
Content-Transfer-Encoding: 7bit

<html>
<head>
<meta http-equiv="content-type" content="text/html;
charset=ISO-8859-1">
</head>
<body bgcolor="#FFFFFF" text="#000000">
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 <a class="moz-txt-link-freetext"
href="http://www.postfix.org/MAILDROP_README.html">http://www.postfix.org/MAILDROP_README.html</a>
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: <blockquote><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> 
</blockquote>
 
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: <blockquote><snip> 
51EE7520BA     1981 Sat Jan  4 11:27:34  MAILER-DAEMON 
(temporary failure. Command output: /usr/bin/maildrop: Unable to
filter message.) 
                                         <a
class="moz-txt-link-abbreviated"
href="mailto:***@hostname.locutory.org">***@hostname.locutory.org</a> 
                                         <a
class="moz-txt-link-abbreviated"
href="mailto:***@otherdomain.com">***@otherdomain.com</a> 
</snip> 
</blockquote>
 
And if I look in the postfix spool: 
<blockquote> # cat /var/spool/postfix/defer/5/51EE7520BA 
 
<a class="moz-txt-link-rfc2396E"
href="mailto:***@hostname.locutory.org"><***@hostname.locutory.org></a>:
temporary failure. Command output: /usr/bin/maildrop: Unable to
filter message. 
<a class="moz-txt-link-abbreviated"
href="mailto:recipient=***@hostname.locutory.org">recipient=***@hostname.locutory.org</a> 
<a class="moz-txt-link-abbreviated"
href="mailto:original_recipient=***@otherdomain.com">original_recipient=***@otherdomain.com</a> 
offset=586 
<a class="moz-txt-link-abbreviated"
href="mailto:dsn_orig_rcpt=rfc822;***@otherdomain.com">dsn_orig_rcpt=rfc822;***@otherdomain.com</a> 
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. 
 
</blockquote>
Here is the portion of the postfix mail log corresponding to the
latter half of processing, after amavisd-new is done: <blockquote><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=<a class="moz-txt-link-rfc2396E"
href="mailto:***@hostname.locutory.org"><***@hostname.locutory.org></a> 
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
<> -> <a class="moz-txt-link-rfc2396E"
href="mailto:***@otherdomain.com"><***@otherdomain.com></a>,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] <> -> <a class="moz-txt-link-rfc2396E"
href="mailto:***@otherdomain.com"><***@otherdomain.com></a>,
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=<a
class="moz-txt-link-rfc2396E"
href="mailto:***@otherdomain.com"><***@otherdomain.com></a>,
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=<a
class="moz-txt-link-rfc2396E"
href="mailto:***@hostname.locutory.org"><***@hostname.locutory.org></a>,
orig_to=<a class="moz-txt-link-rfc2396E"
href="mailto:***@otherdomain.com"><***@otherdomain.com></a>,
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> 
</blockquote>
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. <blockquote><snip> 
postfix/local[4545]: 44D2B520C2: to=<a
class="moz-txt-link-rfc2396E" href="mailto:***@locutory.org"><***@locutory.org></a>,
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> 
</blockquote>
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. <blockquote><snip> 
$ tail maildropfilter.log 
========== 
========== 
========== 
========== 
</snip> 
</blockquote>
 
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. <blockquote><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> 
</blockquote>
Here is the test message itself: <blockquote><snip> 
uname $ cat tmpfile3