I have found that in some rare cases spamd does not send the checked
mail back through sendmail. If is removed from postfix queue and never sent.

The example of failed delivery:

Dec 16 18:27:48 centurion postfix/smtpd[9706]: connect from
localhost[127.0.0.1]
Dec 16 18:27:50 centurion postfix/smtpd[9706]: NOQUEUE: filter: RCPT
from localhost[127.0.0.1]: <localhost[127.0.0.1]>: Client host triggers
FILTER spamassassin:dummy; from=<dmitry.katsubo@nbic.nl>
to=<b.vanbreukelen@uu.nl> proto=ESMTP helo=<[127.0.0.1]>
Dec 16 18:27:50 centurion postfix/smtpd[9706]: E3FDA600B8FA:
client=localhost[127.0.0.1], sasl_method=PLAIN,
sasl_username=dmitry@centurion
Dec 16 18:27:51 centurion postfix/smtpd[9706]: E3FDA600B8FA: filter:
RCPT from localhost[127.0.0.1]: <localhost[127.0.0.1]>: Client host
triggers FILTER spamassassin:dummy; from=<dmitry.katsubo@nbic.nl>
to=<H.W.P.vandenToorn@uu.nl> proto=ESMTP helo=<[127.0.0.1]>
Dec 16 18:27:51 centurion postfix/cleanup[9709]: E3FDA600B8FA:
message-id=<4B291878.2020304@nbic.nl>
Dec 16 18:27:51 centurion postfix/qmgr[4731]: E3FDA600B8FA:
from=<dmitry.katsubo@nbic.nl>, size=1969, nrcpt=2 (queue active)
Dec 16 18:27:51 centurion spamd[2012]: spamd: connection from localhost
[127.0.0.1] at port 38955
Dec 16 18:27:51 centurion spamd[2012]: spamd: handle_user unable to find
user: 'H.W.P.vandenToorn'
Dec 16 18:27:51 centurion spamd[2012]: spamd: still running as root:
user not specified with -u, not found, or set to root, falling back to
nobody
Dec 16 18:27:51 centurion spamd[2012]: spamd: processing message
<4B291878.2020304@nbic.nl> for H.W.P.vandenToorn:65534
Dec 16 18:27:52 centurion postfix/smtpd[9706]: disconnect from
localhost[127.0.0.1]
Dec 16 18:28:10 centurion spamd[2012]: auto-whitelist: open of
auto-whitelist file failed: locker: safe_lock: cannot create tmp
lockfile
/nonexistent/.spamassassin/auto-whitelist.lock.centurion.dynalias.com.2012
for /nonexistent/.spamassassin/auto-whitelist.lock: No such file or
directory
Dec 16 18:28:10 centurion spamd[2012]: spamd: clean message (-101.4/5.0)
for H.W.P.vandenToorn:65534 in 18.2 seconds, 1961 bytes.
Dec 16 18:28:10 centurion spamd[2012]: spamd: result: . -101 -
ALL_TRUSTED,USER_IN_WHITELIST
scantime=18.2,size=1961,user=H.W.P.vandenToorn,uid=65534,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=38955,mid=<4B291878.2020304@nbic.nl>,autolearn=failed

Dec 16 18:28:10 centurion postfix/pipe[9710]: E3FDA600B8FA:
to=<H.W.P.vandenToorn@uu.nl>, relay=spamassassin, delay=20,
delays=1.3/0.02/0/18, dsn=2.0.0, status=sent (delivered via spamassassin
service)
Dec 16 18:28:10 centurion postfix/pipe[9710]: E3FDA600B8FA:
to=<b.vanbreukelen@uu.nl>, relay=spamassassin, delay=20,
delays=1.3/0.02/0/18, dsn=2.0.0, status=sent (delivered via spamassassin
service)
Dec 16 18:28:10 centurion postfix/qmgr[4731]: E3FDA600B8FA: removed
Dec 16 18:28:10 centurion spamd[1597]: prefork: child states: II

postfix/pipe reports that the message was delivered to spamassassin, but
it is never being piped to sendmail. strace of postfix is attached.

The example of successful delivery via spamassassin filter (with save
configuration settings):

Dec  8 13:15:24 centurion postfix/smtpd[12361]: connect from
localhost[127.0.0.1]
Dec  8 13:15:27 centurion postfix/smtpd[12361]: NOQUEUE: filter: RCPT
from localhost[127.0.0.1]: <localhost[127.0.0.1]>: Client host triggers
FILTER spamassassin:dummy; from=<dma_k@mail.ru> to=<pamitu@yahoo.com>
proto=ESMTP helo=<[127.0.0.1]>
Dec  8 13:15:27 centurion postfix/smtpd[12361]: AE891600CF01:
client=localhost[127.0.0.1], sasl_method=PLAIN,
sasl_username=dmitry@centurion
Dec  8 13:15:29 centurion postfix/cleanup[12365]: AE891600CF01:
message-id=<4B1E426E.2020506@mail.ru>
Dec  8 13:15:29 centurion postfix/qmgr[25264]: AE891600CF01:
from=<dma_k@mail.ru>, size=1750, nrcpt=1 (queue active)
Dec  8 13:15:29 centurion spamd[321]: spamd: connection from localhost
[127.0.0.1] at port 52403
Dec  8 13:15:29 centurion spamd[321]: spamd: handle_user unable to find
user: 'pamitu'
Dec  8 13:15:29 centurion spamd[321]: spamd: still running as root: user
not specified with -u, not found, or set to root, falling back to nobody
Dec  8 13:15:29 centurion spamd[321]: spamd: processing message
<4B1E426E.2020506@mail.ru> for pamitu:65534
Dec  8 13:15:29 centurion postfix/smtpd[12361]: disconnect from
localhost[127.0.0.1]
Dec  8 13:15:53 centurion spamd[321]: auto-whitelist: open of
auto-whitelist file failed: locker: safe_lock: cannot create tmp
lockfile
/nonexistent/.spamassassin/auto-whitelist.lock.centurion.dynalias.com.321 for
/nonexistent/.spamassassin/auto-whitelist.lock: No such file or directory
Dec  8 13:15:53 centurion spamd[321]: spamd: clean message (-1.4/5.0)
for pamitu:65534 in 24.1 seconds, 1742 bytes.
Dec  8 13:15:53 centurion spamd[321]: spamd: result: . -1 - ALL_TRUSTED
scantime=24.1,size=1742,user=pamitu,uid=65534,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=52403,mid=<4B1E426E.2020506@mail.ru>,autolearn=failed
Dec  8 13:15:53 centurion spamd[2684]: prefork: child states: II
Dec  8 13:15:53 centurion postfix/pickup[11237]: 946D6600EFFD: uid=65534
from=<dma_k@mail.ru>
Dec  8 13:15:53 centurion postfix/cleanup[12365]: 946D6600EFFD:
message-id=<4B1E426E.2020506@mail.ru>
Dec  8 13:15:53 centurion postfix/pipe[12366]: AE891600CF01:
to=<pamitu@yahoo.com>, relay=spamassassin, delay=26,
delays=2.1/0.06/0/24,dsn=2.0.0, status=sent (delivered via spamassassin
service)
Dec  8 13:15:53 centurion postfix/qmgr[25264]: AE891600CF01: removed
Dec  8 13:15:53 centurion postfix/qmgr[25264]: 946D6600EFFD:
from=<dma_k@mail.ru>, size=2056, nrcpt=1 (queue active)
Dec  8 13:15:55 centurion postfix/smtp[12380]: 946D6600EFFD:
to=<pamitu@yahoo.com>, relay=194.134.41.21[194.134.41.21]:25, delay=2.1,
delays=0.1/0.02/1.1/0.89, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued
as AD1B66618F)
Dec  8 13:15:55 centurion postfix/qmgr[25264]: 946D6600EFFD: removed

Additional information:

# dpkg -l | egrep '(spam|postfix)'
ii  postfix             2.6.5-3
ii  postfix-pcre        2.6.5-3
ii  spamassassin        3.2.5-6
ii  spamc               3.2.5-6

process the -e command line argument.  In the strace output you sent,
spamc is pid 9711:

[pid  9710] clone(Process 9711 attached child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb730d938) = 9711
...
[pid  9711] execve("/usr/bin/spamc", ["/usr/bin/spamc", "-u", "H.W.P.vandenToorn", "b.vanbreukelen", "-e", "/usr/sbin/sendmail", "-oi", "-f", "dmitry.katsubo@nbic.nl", "H.W.P.vandenToorn@uu.nl", "b.vanbreukelen@uu.nl"], [/* 3 vars */]) = 0

You can see where spamc connects to spamd and passes it the message:
[pid  9711] socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
[pid  9711] rt_sigaction(SIGALRM, {0x804e140, [], 0}, {SIG_DFL, [], 0}, 8) = 0
[pid  9711] alarm(600)                  = 0
[pid  9711] connect(3, {sa_family=AF_INET, sin_port=htons(783), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
[pid  9711] alarm(0)                    = 600
[pid  9711] rt_sigaction(SIGALRM, {SIG_DFL, [], 0}, {0x804e140, [], 0}, 8) = 0
[pid  9711] send(3, "PROCESS SPAMC/1.4\r\nUser: H.W.P.vandenToorn\r\nContent-length: 1961\r\n\r\n", 68, 0) = 68
[pid  9711] send(3, "Return-Path: <dmitry.katsubo@nbic.nl>\nReceived: from [127.0.0.1] (localhost [127.0.0.1])\n\t(using TLSv1 with cipher DHE-RSA-AES25"..., 1961, 0) = 1961

Then later where it reads the processed message back from spamd with a
long repeating sequence of:
[pid  9711] rt_sigaction(SIGALRM, {SIG_DFL, [], 0}, {0x804e140, [], 0}, 8) = 0
[pid  9711] rt_sigaction(SIGALRM, {0x804e140, [], 0}, {SIG_DFL, [], 0}, 8) = 0
[pid  9711] alarm(600)                  = 0
[pid  9711] recv(3, "P", 1, 0)          = 1

It then writes the processed message back out file descriptor 1, which
is the pipe it has set up with pid 9710 (pipe(8)).  This is how it would
normally operate, if -e wasn't given.

Does spamc not log anything?  If you add the '-l' flag, which tells it
to log to stderr, does postfix do anything useful with those logs?

Also, I wonder if passing spamc the '-x' flag would be useful here.
Normally, if spamc encounters an error, it just returns the unaltered
message.  However, the docs aren't clear about how this interacts with
'-e'.  Maybe having spamc exit with a meaningful error code would be
useful, or at least helpful for our debugging, in this case.

noah

Hi Noah!

Thanks for the descriptive information. Indeed, smapd does not launch
sendmail process. I looked through the sources of spamc.c from
SpamAssassin 3.2.5 and I noticed that function get_output_fd(int *fd) is
called from several places, but it should function OK with respect to
process cloning and execution of sendmail.

The problem gets more difficult as not all messages are not delivered,
but once you find that message, which failed to be delivered and try to
send it again (from Thunderbird) it is not delivered again. So I think,
it is not a random factor (like memory overrun or overlap) that
influences the problem, but the message itself. However I was not able
to find any evidences in spamc source, because in any case (in
message_filter() or message_write() fails) the message should be
delivered to sendmail. I have strace'd a successful delivery and
attached it to the letter. As to the trace is seems that spamc "forgets"
that exec_argv is defined. This sound like memory allocation problems,
probably in message_filter().

I have added "-x" flag to spamc argument list. Alas many
spamassassin+postfix guides lack mentioning this flag. Thank you for the
important hint! I hoped it will at least not let failed messages to
disappear, put keep them in mail queue. But smapc gets crazy and does
not follow this option as well. It seems like it has forgotten

I've also noticed that maybe the delivery failed, when number of
recipients is more then one (I've seen the failed delivery for 3 and 6
recipients). In log files I also notice this entry:

spamd[1440]: prefork: child states: II

which seems to be always appear in case of failed delivery, but also
appears from time to time in log. This message does not tell anything
wrong, it just says, that two children are idle. However I have
"--max-children 10" setting for smapd. Weird!

Maybe someone from SpamAssassin team can help? Vince, Dirk, do you have
any ideas about the problem? Or maybe you can forward this message to
somebody, who can hack more deeply into spamc code?

Noah Meyerhans wrote on 21/01/2010 05:34: