RE: Explanation of error messages.

[Ron Snyder]

Hrm. I am getting core dumps, but I wonder if I'm looking at two unrelated
things.  I have seen several cases where I'll get a write(Q) (or similar),
but not have a coredump.  Here's a snippet of my maillog that does seem to
correspond to a coredump:
Sep 19 12:28:02 mailgate spamass-milter[4996]: polling
Sep 19 12:28:02 mailgate spamass-milter[4996]: poll returned 1
Sep 19 12:28:02 mailgate spamass-milter[4996]: poll says I can write
Sep 19 12:28:02 mailgate spamass-milter[4996]: wrote 1511 bytes
Sep 19 12:28:02 mailgate spamass-milter[4996]: ::output exit
Sep 19 12:28:02 mailgate spamass-milter[4996]: mlfi_body: exit
Sep 19 12:28:02 mailgate spamass-milter[4996]: mlfi_eom: enter
Sep 19 12:28:02 mailgate spamass-milter[4996]: ::input enter
Sep 19 12:28:02 mailgate spamass-milter[4996]: ::empty_and_close_pipe enter
Sep 19 12:28:02 mailgate spamass-milter[4996]: ::read_pipe enter
Sep 19 12:28:03 mailgate spamass-milter[4996]: read 1024 bytes
Sep 19 12:28:03 mailgate spamass-milter[4996]: ::read_pipe exit
Sep 19 12:28:03 mailgate spamass-milter[4996]: ::read_pipe enter
Sep 19 12:28:03 mailgate spamass-milter[4996]: read 1024 bytes
Sep 19 12:28:03 mailgate spamass-milter[4996]: ::read_pipe exit
Sep 19 12:28:03 mailgate spamass-milter[4996]: ::read_pipe enter
Sep 19 12:28:03 mailgate spamass-milter[4996]: read 1024 bytes
Sep 19 12:28:03 mailgate spamass-milter[4996]: ::read_pipe exit
Sep 19 12:28:03 mailgate spamass-milter[4996]: ::read_pipe enter
Sep 19 12:28:03 mailgate spamass-milter[4996]: ::read_pipe exit
Sep 19 12:28:03 mailgate spamass-milter[4996]: ::empty_and_close_pipe exit
Sep 19 12:28:03 mailgate spamass-milter[4996]: ::input exit
Sep 19 12:28:03 mailgate sendmail[31015]: g8JJS1mY031015: Milter add:
header: X-Spam-Status: No, hits=-4.1
required=5.0\n\ttests=IN_REP_TO,X_AUTH_WARNING\n\tversion=2.31
Sep 19 12:28:03 mailgate spamass-milter[4996]: mlfi_eom: exit
Sep 19 12:28:03 mailgate sendmail[31015]: g8JJS1mY031015:
to=<address@hidden>, delay=00:00:01, mailer=smtp, pri=139891,
stat=queued
Sep 19 12:28:03 mailgate spamass-milter[4996]: mlfi_close
Sep 19 12:28:03 mailgate spamass-milter[4996]: read 1024 bytes
Sep 19 12:28:03 mailgate spamass-milter[4996]: ::read_pipe exit
Sep 19 12:28:03 mailgate sendmail[22782]: g8JJS1mY022782:
milter_read(spamassassin): cmd read returned 0, expecting 5
Sep 19 12:28:03 mailgate sendmail[22782]: g8JJS1mY022782: Milter
(spamassassin): to error state
Sep 19 12:28:03 mailgate sendmail[22782]: g8JJS1mY022782: Milter: data,
reject=451 4.7.1 Please try again later
Sep 19 12:28:03 mailgate sendmail[22782]: g8JJS1mY022782:
to=<address@hidden>, delay=00:00:01, pri=30894, stat=Please try
again later
Sep 19 12:28:04 mailgate root: starting spamassassin-milter

Adding the MALLOC_OPTIONS doesn't seem to have had any effect on the
behavior or frequency of the core dumps. The backtrace seems to be the same,
and at the same assembly instruction.
argh.

-ron

> -----Original Message-----
> From: Dan Nelson [mailto:address@hidden 
> Sent: Thursday, September 19, 2002 9:30 AM
> To: Ron Snyder
> Cc: Christopher Crowley; address@hidden
> Subject: Re: Explanation of error messages.
> 
> 
> In the last episode (Sep 19), Ron Snyder said:
> > 
> > > Return should never segfault :)  Try the "disassemble" 
> gdb command and
> > > see what the code at 0xb94d is doing (i.e. see if it's 
> really a ret
> > > instruction).  Maybe gdb is lying.  Actually, since a C++ 
> string was
> > > allocated in read_pipe, it might be segfaulting in the destructor.
> > 
> > I've included some context around 0xb94d to help...
> > 
> > 0xb920 <read_pipe__12SpamAssassin+2828>:        addl   $0x18,%esp
> > 0xb923 <read_pipe__12SpamAssassin+2831>:        pushl  $0xadf4
> > 0xb928 <read_pipe__12SpamAssassin+2836>:        pushl  $0x2
> > 0xb92a <read_pipe__12SpamAssassin+2838>:        call   
> 0xba68 <debug__FiPCce>
> ^^^ debug(2, "read %d bytes");
> > 0xb92f <read_pipe__12SpamAssassin+2843>:        addl   $0x10,%esp
> > 0xb932 <read_pipe__12SpamAssassin+2846>:        addl   
> $0xfffffff8,%esp
> > 0xb935 <read_pipe__12SpamAssassin+2849>:        pushl  $0xae02
> > 0xb93a <read_pipe__12SpamAssassin+2854>:        pushl  $0x1
> > 0xb93c <read_pipe__12SpamAssassin+2856>:        call   
> 0xba68 <debug__FiPCce>
> ^^^ debug(1, "::read_pipe exit");
> > 0xb941 <read_pipe__12SpamAssassin+2861>:        movl   
> 0xfffffb18(%ebp),%eax
> > 0xb947 <read_pipe__12SpamAssassin+2867>:        movl   
> 0x4(%eax),%edx
> > 0xb94a <read_pipe__12SpamAssassin+2870>:        movl   
> 0x4(%edx),%eax
> > 0xb94d <read_pipe__12SpamAssassin+2873>:        movl   (%eax),%eax
> > 0xb94f <read_pipe__12SpamAssassin+2875>:        movl   
> %eax,0x4(%edx)
> > 0xb952 <read_pipe__12SpamAssassin+2878>:        movl   
> 0xfffffbfc(%ebp),%ecx
> > 0xb958 <read_pipe__12SpamAssassin+2884>:        leal   
> 0xfffffff0(%ecx),%edi
> > 0xb95b <read_pipe__12SpamAssassin+2887>:        movl   
> 0xfffffff8(%ecx),%eax
> > 0xb95e <read_pipe__12SpamAssassin+2890>:        leal   
> 0xffffffff(%eax),%edx
> > 0xb961 <read_pipe__12SpamAssassin+2893>:        movl   
> %edx,0xfffffff8(%ecx)
> > 0xb964 <read_pipe__12SpamAssassin+2896>:        cmpl   $0x1,%eax
> > 0xb967 <read_pipe__12SpamAssassin+2899>:        jne    
> 0xb9a0 <read_pipe__12SpamAssassin+2956>
> > 0xb969 <read_pipe__12SpamAssassin+2901>:        movl   
> 0xfffffff4(%ecx),%edx
> > 0xb96c <read_pipe__12SpamAssassin+2904>:        leal   
> 0x10(%edx),%eax
> > 0xb96f <read_pipe__12SpamAssassin+2907>:        cmpl   $0x80,%eax
> > 0xb974 <read_pipe__12SpamAssassin+2912>:        jbe    
> 0xb984 <read_pipe__12SpamAssassin+2928>
> ^^^ Everything here must be the destructor for "reason", 
> since there is
> no code between the last debug and "return size;".
> 
> This could be caused by memory corruption that happened earlier.  Try
> setting the enviroment variable MALLOC_OPTIONS="AJ" before starting
> spamass-milter, and see if instead of a segfault, you get a
> malloc-initiated abort().
> 
> -- 
>       Dan Nelson
>       address@hidden
>