Re: Milter hangs, revisited

[Dan Nelson]

In the last episode (Nov 12), Terry Kennedy said:
> Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_body: enter
> Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
> Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
> Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 2280 bytes
> Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
> Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_eom: enter
> Nov 12 15:20:07 test1 spamass-milter[6585]: ::input enter
> Nov 12 15:20:07 test1 spamass-milter[6585]: ::empty_and_close_pipe enter
> Nov 12 15:20:07 test1 spamass-milter[6585]: ::read_pipe enter
> Nov 12 15:24:07 test1 sm-mta[6586]: gACKK75S006586: Milter (spamassassin): 
> timeout before data read
> Nov 12 15:24:07 test1 sm-mta[6586]: gACKK75S006586: Milter (spamassassin): to 
> error state
> Nov 12 15:24:07 test1 sm-mta[6601]: gACKK75S006586: address@hidden, 
> delay=00:04:00, xdelay=00:00:00, mailer=esmtp, pri=33186, relay=gate.tmk.com. 
> [204.141.35.61], dsn=2.0.0, stat=Sent (gACKO7YY016438 Message accepted for 
> delivery)

According to this, the spamass-milter sent the entire message to spamc,
closed the send pipe, and is waiting for the results.  After 3 minutes
sendmail gives up.  According to your ps output, there isn't even a
spamc running.  All read_pipe does is read from the recv pipe connected
to spamc, so if spamc isn't there the read() should return 0.  Try
changing the debug line on line 922 to read

    debug(1, "::read_pipe(%d) enter", pipe_io[1][0]);

, run it again, make a note of the file number in the log, then run
lsof -p <spamass-milter-pid>, and see what that filedescriptor is
connected to, if anything.

I find it interesting that there are no spamd logs.  In my maillog I
get lines like this (my syslogd is set to log mail.info and higher to
maillog).

Nov 12 15:45:59 <2.6> dan spamd[942]: connection from localhost [127.0.0.1] at 
port 52771
Nov 12 15:45:59 <2.6> dan spamd[7877]: processing message <address@hidden> for 
root:26, expecting 4527 bytes.
Nov 12 15:46:04 <2.6> dan spamd[7877]: clean message (-1.4/5.0) for root:26 in 
5.4 seconds, 4527 bytes.

Maybe spamc is not getting called at all?  If you have process
accounting enabled, run "lastcomm | less" and verify that spamc got
run.

-- 
        Dan Nelson
        address@hidden