Milter hangs, revisited

spamass-milt-list
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
Milter hangs, revisited

From:	Terry Kennedy
Subject:	Milter hangs, revisited
Date:	Tue, 12 Nov 2002 16:06:35 -0500 (EST)
  Some months ago I reported a problem with any attempt to use the milter
resulting in 100% CPU on BSD/OS 4.3. Since then I've received and applied
thread fixes from the OS vendor and I'm trying to get the milter going once
more.

  Now instead of high CPU, I get milter timeouts. It looks like the whole
message gets sent to spamd, but nothing ever comes back. As before, if I
do "spamc < sample_spam_message", I get a near-instantaneous response with
the message marked as spam, or not, as appropriate.

  I also get one additional spamass-milter process per mail message I
attempt to filter):

  After starting, but before any messages:

(0:185) test1:/etc/mail# ps -ax | grep spam
 6623  ??  Is     0:00.49 /usr/bin/perl /usr/bin/spamd -d -u spamd (spamd)
 6640  p0  S      0:00.01 /usr/local/bin/spamass-milter -f -p /var/run/spamass.
 6642  p0  S+     0:00.00 grep spam

  While processing a message:

(0:186) test1:/etc/mail# ps -ax | grep spam
 6623  ??  Is     0:00.49 /usr/bin/perl /usr/bin/spamd -d -u spamd (spamd)
 6640  p0  S      0:00.03 /usr/local/bin/spamass-milter -f -p /var/run/spamass.
 6644  p0  S      0:00.01 (spamass-milter)
 6646  p0  S+     0:00.00 grep spam

  After the timeout is logged:

(0:187) test1:/etc/mail# ps -ax | grep spam
 6623  ??  Is     0:00.49 /usr/bin/perl /usr/bin/spamd -d -u spamd (spamd)
 6640  p0  S      0:00.04 /usr/local/bin/spamass-milter -f -p /var/run/spamass.
 6644  p0  S      0:00.01 (spamass-milter)
 6650  p0  S+     0:00.00 grep spam

  This is with SpamAssassin 2.43 (upgraded from 2.31) and spamass-milter
0.1.2. Does anyone have any ideas about this?

Nov 12 15:19:54 test1 spamass-milter[6585]: smfi_register succeeded
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_envfrom: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_envfrom: exit
Nov 12 15:20:07 test1 sm-mta[6586]: gACKK75S006586: from=<address@hidden>, 
size=2969, class=0, nrcpts=1, msgid=<address@hidden>, proto=ESMTP, daemon=MTA, 
address@hidden [204.141.35.63]
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 153 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 52 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 39 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 44 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 31 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 65 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 33 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 37 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 32 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 22 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 35 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 49 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 41 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 19 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: poll says I can write
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 43 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_header: exit
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_eoh: enter
Nov 12 15:20:07 test1 spamass-milter[6585]: ::output enter
Nov 12 15:20:07 test1 spamass-milter[6585]: polling
Nov 12 15:20:07 test1 spamass-milter[6585]: poll returned 1
Nov 12 15:20:07 test1 spamass-milter[6585]: wrote 2 bytes
Nov 12 15:20:07 test1 spamass-milter[6585]: mlfi_eoh: exit
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)

        Terry Kennedy             http://www.tmk.com
        address@hidden             New York, NY USA
[Prev in Thread]
Current Thread
[Next in Thread]
Milter hangs, revisited, Terry Kennedy <=
- Re: Milter hangs, revisited, Dan Nelson, 2002/11/12
  - Re: Milter hangs, revisited, Terry Kennedy, 2002/11/12
    - Re: Milter hangs, revisited, Dan Nelson, 2002/11/13
    - Re: Milter hangs, revisited, Terry Kennedy, 2002/11/13
Next by Date: Support ???
Next by thread: Re: Milter hangs, revisited
Index(es):
- Date
- Thread