Compute loop + no processing with spamass-milter

[Terry Kennedy]

  [This is an expanded version of a message I sent to dnelson a week ago, 
but as I didn't get an answer I'm kicking it out to this {hopefully} wider
audience].

  I'm trying to install the milter on BSD/OS 4.3. I started with the 0.1.1
kit, but I get "timeout before data read" from sendmail.

  I checked the CVS tree and fetched the newer files which include enhanced
debugging, but I still can't make sense of what is happening. I'm attaching a
logfile in case this is something obvious that someone can spot.

  Also, is there going to be a tarball-format release with the updated parts
any time soon?

  You might want to add a pointer to the poll emulator library for people who
are trying to install the milter on systems without poll. It can be found at:
http://www.clapper.org/software/poll/

  Here's the log. At the point where the logging stops, the milter is chewing
all available CPU.

(0:1509) test2:/usr/local/src/spamass-milter-0.1.1# spamass-milter -p 
/var/run/spamass.sock -d 2
Aug 10 07:05:21 test2 spamass-milter[11970]: smfi_register succeeded
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_envfrom: enter
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_envfrom: exit
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: enter
Aug 10 07:05:37 test2 spamass-milter[11970]: ::output enter
Aug 10 07:05:37 test2 spamass-milter[11970]: polling
Aug 10 07:05:37 test2 spamass-milter[11970]: poll returned 1
Aug 10 07:05:37 test2 spamass-milter[11970]: poll says I can write
Aug 10 07:05:37 test2 spamass-milter[11970]: wrote 153 bytes
Aug 10 07:05:37 test2 spamass-milter[11970]: ::output exit
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: exit
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: enter
Aug 10 07:05:37 test2 spamass-milter[11970]: ::output enter
Aug 10 07:05:37 test2 spamass-milter[11970]: polling
Aug 10 07:05:37 test2 spamass-milter[11970]: poll returned 1
Aug 10 07:05:37 test2 spamass-milter[11970]: poll says I can write
Aug 10 07:05:37 test2 spamass-milter[11970]: wrote 52 bytes
Aug 10 07:05:37 test2 spamass-milter[11970]: ::output exit
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: exit
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: enter
Aug 10 07:05:37 test2 spamass-milter[11970]: ::output enter
Aug 10 07:05:37 test2 spamass-milter[11970]: polling
Aug 10 07:05:37 test2 spamass-milter[11970]: poll returned 1
Aug 10 07:05:37 test2 spamass-milter[11970]: poll says I can write
Aug 10 07:05:37 test2 spamass-milter[11970]: wrote 45 bytes
Aug 10 07:05:37 test2 spamass-milter[11970]: ::output exit
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: exit
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: enter
Aug 10 07:05:37 test2 spamass-milter[11970]: ::output enter
Aug 10 07:05:37 test2 spamass-milter[11970]: polling
Aug 10 07:05:37 test2 spamass-milter[11970]: poll returned 1
Aug 10 07:05:37 test2 spamass-milter[11970]: poll says I can write
Aug 10 07:05:37 test2 spamass-milter[11970]: wrote 44 bytes
Aug 10 07:05:37 test2 spamass-milter[11970]: ::output exit
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: exit
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: enter
Aug 10 07:05:37 test2 spamass-milter[11970]: ::output enter
Aug 10 07:05:37 test2 spamass-milter[11970]: polling
Aug 10 07:05:37 test2 spamass-milter[11970]: poll returned 1
Aug 10 07:05:37 test2 spamass-milter[11970]: poll says I can write
Aug 10 07:05:37 test2 spamass-milter[11970]: wrote 26 bytes
Aug 10 07:05:37 test2 spamass-milter[11970]: ::output exit
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: exit
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: enter
Aug 10 07:05:37 test2 spamass-milter[11970]: ::output enter
Aug 10 07:05:37 test2 spamass-milter[11970]: polling
Aug 10 07:05:37 test2 spamass-milter[11970]: poll returned 1
Aug 10 07:05:37 test2 spamass-milter[11970]: poll says I can write
Aug 10 07:05:37 test2 spamass-milter[11970]: wrote 50 bytes
Aug 10 07:05:37 test2 spamass-milter[11970]: ::output exit
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: exit
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: enter
Aug 10 07:05:37 test2 spamass-milter[11970]: ::output enter
Aug 10 07:05:37 test2 spamass-milter[11970]: polling
Aug 10 07:05:37 test2 spamass-milter[11970]: poll returned 1
Aug 10 07:05:37 test2 spamass-milter[11970]: poll says I can write
Aug 10 07:05:37 test2 spamass-milter[11970]: wrote 32 bytes
Aug 10 07:05:37 test2 spamass-milter[11970]: ::output exit
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: exit
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: enter
Aug 10 07:05:37 test2 spamass-milter[11970]: ::output enter
Aug 10 07:05:37 test2 spamass-milter[11970]: polling
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_header: enter
Aug 10 07:05:37 test2 last message repeated 1 times
Aug 10 07:05:37 test2 spamass-milter[11970]: mlfi_eoh: enter
Aug 10 07:09:37 test2 sm-msp-queue[11971]: g7AB5bdX011971: Milter 
(spamassassin): timeout before data read

  At this point the milter is still chewing all available CPU:
11970  p0  S      0:00.08 spamass-milter -p /var/run/spamass.sock -d 2
11972  p0  R      5:00.34 (spamass-milter)
  later...
11970  p0  S      0:00.16 spamass-milter -p /var/run/spamass.sock -d 2
11972  p0  R     13:07.12 (spamass-milter)

  and it will continue doing that until it is killed. I don't think this is
related to the poll() emulation as this is the same behavior I was seeing 
with the 0.1.1 version, which used select().

  I've seen it wedge after logging "mlfi_body: enter" and "mlfi_eom: enter"
as well.

  If I take a test mail message and do "spamc < test > output", I get the
expected output, so I'm pretty sure it is in the milter and not spamc/spamd.
And I tried this with the exact same message that the milter wedged on, so
that shouldn't be the problem either.

        Terry Kennedy             http://www.tmk.com
        address@hidden             New York, NY USA