Re: Milter (spamassassin): to error state : spamassassin milter seems to randomly fail

[Joost van Baal]

Hi,

On Mon, Aug 18, 2003 at 09:54:15AM -0500, Dan Nelson wrote:
> In the last episode (Aug 18), Joost van Baal said:
> > OK, have build with these flags.  I am working with $Id:
> > spamass-milter.cpp,v 1.52 2003/06/26 15:10:44 dnelson Exp $ (in
> > spamass-milter-0.2.0, with some Debian patches).

The Debian patch contains:

  * Patch by Valentin Chopov to fix segfaults on
    empty message bodies. [The "bob" patch]

.

> > In the spamass-milter.cpp CVS log I see:
> > 
> >  revision 1.61
> >  date: 2003/08/06 04:45:46;  author: dnelson;  state: Exp;  lines: +11 -4
> >  Fix two cases where we caught an error but didn't clean up the assassin
> >  object.
> > 
> > The revision 1.60 date: 2003/08/06 04:29:48; log looks interesting too.
> > Would it be useful if I started using 1.61 or later?
> 
> Possibly.  If your milter process is dying with signal 6, then r1.61
> wil most likely fix it (the code ends up throwing an uncaught exception
> and abort()ing).  Beware that CVS versions 1.62 and above sometimes
> leak processes due to my use of popen() to call "sendmail -bv" (I don't
> think popen and pthreads play nice together); I'm trying to figure out
> where the bug is.

Hm, ok.  I'll keep an eye on my spamass-milter behaviour, and might
upgrade to this snapshot.

> > Anyway, my /usr/sbin/spamass-milter is an "ELF 32-bit LSB executable,
> > Intel 80386, version 1 (SYSV), dynamically linked (uses shared libs),
> > not stripped".
> > 
> > I have
> > 
> >  address@hidden:~# ps axfww | grep '[s]pamass'
> >  32217 ?        S      0:00 /usr/sbin/spamass-milter -p 
> > /var/run/sendmail/spamass.sock
> >  32218 ?        S      0:00  \_ /usr/sbin/spamass-milter -p 
> > /var/run/sendmail/spamass.sock
> >  32219 ?        S      0:00      \_ /usr/sbin/spamass-milter -p 
> > /var/run/sendmail/spamass.sock
> 
> This looks fine; LinuxThreads uses one process for each thread and
> creates two helper processes, so an idle milter will look like this.

OK.  Anyway, spamassassin filtering failed last night:

Aug 18 22:31:46 babbage sm-mta[2465]: h7IKRjZZ002465: Milter (spamassassin): 
timeout before data read
Aug 18 22:31:46 babbage sm-mta[2465]: h7IKRjZZ002465: Milter (spamassassin): to 
error state
Aug 18 22:31:46 babbage sm-mta[2465]: h7IKRjZZ002465: Milter: to=<snip>, 
reject=451 4.7.1 Please try again later
Aug 18 22:31:46 babbage sm-mta[2465]: h7IKRjZZ002465: Milter (milter-amavis): 
abort filter
Aug 18 22:31:46 babbage sm-mta[2465]: h7IKRjZZ002465: from=<snip>, size=3530, 
class=0, nrcpts=0, proto=ESMTP, daemon=MTA, relay=[snip]
Aug 18 22:31:50 babbage sm-mta[2495]: h7IKRoZZ002495: Milter (spamassassin): 
timeout before data read
Aug 18 22:31:50 babbage sm-mta[2495]: h7IKRoZZ002495: Milter (spamassassin): to 
error state
Aug 18 22:31:50 babbage sm-mta[2495]: h7IKRoZZ002495: Milter (spamassassin): 
init failed to open
Aug 18 22:31:50 babbage sm-mta[2495]: h7IKRoZZ002495: Milter (spamassassin): to 
error state
Aug 18 22:31:50 babbage sm-mta[2495]: h7IKRoZZ002495: Milter (spamassassin): 
init success to open
Aug 18 22:31:50 babbage sm-mta[2495]: h7IKRoZZ002495: Milter (milter-amavis): 
init success to negotiate
Aug 18 22:31:50 babbage sm-mta[2495]: h7IKRoZZ002495: Milter: initialization 
failed, temp failing commands
....
Aug 18 22:38:57 babbage sm-mta[2718]: h7IKYvZZ002718: Milter (spamassassin): to 
error state
Aug 18 22:38:57 babbage sm-mta[2718]: h7IKYvZZ002718: Milter (spamassassin): 
init success to open
Aug 18 22:38:57 babbage sm-mta[2718]: h7IKYvZZ002718: Milter (milter-amavis): 
init success to negotiate
Aug 18 22:38:57 babbage sm-mta[2718]: h7IKYvZZ002718: Milter: initialization 
failed, temp failing commands
Aug 18 22:39:03 babbage sm-mta[9207]: accepting connections again for daemon MTA
Aug 18 22:39:03 babbage sm-mta[9207]: rejecting connections on daemon MTA: 100 
children, max 100
...
Aug 18 22:50:00 babbage sm-mta[2720]: h7IKZ0ZZ002720: Milter (spamassassin): 
error connecting to filter: Connection timed out with 
/var/run/sendmail/spamass.sock
Aug 18 22:50:00 babbage sm-mta[2720]: h7IKZ0ZZ002720: Milter (spamassassin): to 
error state
Aug 18 22:50:00 babbage sm-mta[2720]: h7IKZ0ZZ002720: Milter: initialization 
failed, temp failing commands
Aug 18 22:50:00 babbage sm-mta[2720]: h7IKZ0ZZ002720: [snip] did not issue 
MAIL/EXPN/VRFY/ETRN during connection to MTA
....
Aug 19 08:55:52 babbage sm-mta[10890]: h7J6k4qn010890: Milter (spamassassin): 
error connecting to filter: No such file or directory
Aug 19 08:55:52 babbage sm-mta[10890]: h7J6k4qn010890: Milter (spamassassin): 
to error state
Aug 19 08:55:52 babbage sm-mta[10890]: h7J6k4qn010890: Milter: initialization 
failed, temp failing commands

At that time, processes

 spamd    11134  0.0  0.6 17896 13848 ?       S    Aug14   1:17 /usr/sbin/spamd 
-m 10 --nouser-config -u spamd -d --pidfile=/var/run/spamd.pid
 root      7495  0.0  0.0 269200 1096 ?       S    Aug18   0:00 
/usr/sbin/spamass-milter -p /var/run/sendmail/spamass.sock

where running.  (Just _one_ spamass-milter.)  There were no resource problems:

 address@hidden:~% free
              total       used       free     shared    buffers     cached
 Mem:       2069344    2036560      32784          0     289480    1071116
 -/+ buffers/cache:     675964    1393380
 Swap:      1999192       4488    1994704
 address@hidden:~% uptime
  08:53:13 up 48 days, 19:02, 12 users,  load average: 0.00, 0.00, 0.00

gdb on this last spamass-milter process gave:

 (gdb) attach 7495
 Attaching to process 7495
 Reading symbols from /usr/sbin/spamass-milter...(no debugging symbols found)...
 done.
 Reading symbols from /usr/lib/libstdc++-libc6.2-2.so.3...
 (no debugging symbols found)...done.
 Loaded symbols for /usr/lib/libstdc++-libc6.2-2.so.3
 Reading symbols from /lib/libm.so.6...(no debugging symbols found)...done.
 Loaded symbols for /lib/libm.so.6
 Reading symbols from /lib/libpthread.so.0...(no debugging symbols found)...
 done.
 [New Thread 1024 (LWP 7492)]
 Error while reading shared library symbols:
 Can't attach LWP 7492: No such process
 Reading symbols from /lib/libc.so.6...(no debugging symbols found)...done.
 Loaded symbols for /lib/libc.so.6
 Reading symbols from /lib/ld-linux.so.2...(no debugging symbols found)...done.
 Loaded symbols for /lib/ld-linux.so.2
 0x400bf87e in sigsuspend () from /lib/libc.so.6

 (gdb) info threads
 [New Thread 2049 (LWP 7494)]
 Can't attach LWP 7494: No such process

Luckily, I have a 262M spamass-milter core file, from Aug 18 22:27, named 
/core.2487 .  At 22:00, we had:

root      7492  0.0  0.0 11208 1012 ?        S    15:49   0:00 
/usr/sbin/spamass-milter -p /var/run/sendmail/spamass.sock
root      7494  0.0  0.0 11208 1012 ?        S    15:49   0:00  \_ 
/usr/sbin/spamass-milter -p /var/run/sendmail/spamass.sock
root      7495  0.0  0.0 11208 1012 ?        S    15:49   0:00      \_ 
/usr/sbin/spamass-milter -p /var/run/sendmail/spamass.sock
root     22436  0.0  0.0 11208 1012 ?        S    20:47   0:00      \_ 
/usr/sbin/spamass-milter -p /var/run/sendmail/spamass.sock
root     31314  0.0  0.0 11208 1012 ?        S    21:58   0:00      \_ 
/usr/sbin/spamass-milter -p /var/run/sendmail/spamass.sock
root     31347  0.0  0.0 11208 1012 ?        S    21:59   0:00      \_ 
/usr/sbin/spamass-milter -p /var/run/sendmail/spamass.sock

Running gdb on this core file gives:

address@hidden:~% gdb /usr/sbin/spamass-milter /core.2487
GNU gdb 2002-04-01-cvs
Copyright 2002 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "i386-linux"...(no debugging symbols found)...
Core was generated by `/usr/sbin/spamass-milter -p 
/var/run/sendmail/spamass.sock'.
Program terminated with signal 11, Segmentation fault.
Reading symbols from /usr/lib/libstdc++-libc6.2-2.so.3...(no debugging symbols 
found)...done.
Loaded symbols for /usr/lib/libstdc++-libc6.2-2.so.3
Reading symbols from /lib/libm.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib/libm.so.6
Reading symbols from /lib/libpthread.so.0...(no debugging symbols found)...done.
Loaded symbols for /lib/libpthread.so.0
Reading symbols from /lib/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib/libc.so.6
Reading symbols from /lib/ld-linux.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib/ld-linux.so.2
#0  0x4010b1b7 in memcpy () from /lib/libc.so.6

(gdb) info threads
* 1 process 2487  0x4010b1b7 in memcpy () from /lib/libc.so.6

(gdb) bt
#0  0x4010b1b7 in memcpy () from /lib/libc.so.6
#1  0x40032130 in string_char_traits<char>::copy () from 
/usr/lib/libstdc++-libc6.2-2.so.3
#2  0x08052987 in basic_string<char, string_char_traits<char>, 
__default_alloc_template<true, 0> >::Rep::copy ()
#3  0x08052e2c in basic_string<char, string_char_traits<char>, 
__default_alloc_template<true, 0> >::replace ()
#4  0x0805367c in basic_string<char, string_char_traits<char>, 
__default_alloc_template<true, 0> >::append ()
#5  0x08050330 in SpamAssassin::output ()
#6  0x08050765 in SpamAssassin::output ()
#7  0x0804d970 in mlfi_envrcpt ()
#8  0x080567c7 in st_rcpt ()
#9  0x08056072 in mi_engine ()
#10 0x08054e79 in mi_handle_session ()
#11 0x0805468d in mi_thread_handle_wrapper ()
#12 0x400880ba in pthread_start_thread () from /lib/libpthread.so.0

What more information do you need, and how can I get that from my core
file?

BTW: one more thing which might be relevant I've forgotten to mention:
the box is a dual CPU one, I'm doing SMP.

Bye,

Joost

-- 
                          Joost van Baal
address@hidden                                              S&N ITS
(013-466-)3519                                http://banach.uvt.nl/
kamer C 230A                                   aanwezig: ma, di, vr

pgpBYPRvWjRwX.pgp
Description: PGP signature