spamd segfaults a message

[Marcin Owsiany]

Binary package hint: spamassassin

Description: Ubuntu 10.04.1 LTS
Release: 10.04
spamassassin 3.3.1-1

I find the following in syslog after piping the attached message into spamc.

Sep 22 09:40:31 beczulka spamd[25056]: spamd: connection from beczulka [127.0.0.1] at port 59563
Sep 22 09:40:31 beczulka spamd[25056]: spamd: setuid to mowsiany succeeded
Sep 22 09:40:34 beczulka spamd[25056]: spamd: processing message <0c3d01cb5a26$c3b817b0$4b284710$@lv> for mowsiany:82952
Sep 22 09:40:44 beczulka kernel: [539316.340637] spamd[25056]: segfault at 38e8fd3a1 ip 00007f6269838a86 sp 00007fffb3255900 error 4 in libperl.so.5.10.1[7f6269795000+162000]
Sep 22 09:40:44 beczulka spamd[1443]: prefork: child states: BI
Sep 22 09:40:44 beczulka spamd[1443]: spamd: handled cleanup of child pid [25056] due to SIGCHLD: DIED, signal 11 (000b)
Sep 22 09:40:44 beczulka spamd[1443]: spamd: server successfully spawned child process, pid 26046
Sep 22 09:40:44 beczulka spamd[1443]: prefork: child states: II

[Marcin Owsiany (marcin-owsiany-pl)]

And the version of perl-base is 5.10.1-8ubuntu2

[Thierry Carrez (ttx)]

@Marcin: I can't reproduce that:

$ spamc -r < spamd-crash.txt
0/0

Can you reproduce it steadily ?

[Marcin Owsiany (marcin-owsiany-pl)]

On Wed, Sep 22, 2010 at 12:22:54PM -0000, Thierry Carrez wrote:
> @Marcin: I can't reproduce that:
>
> $ spamc -r < spamd-crash.txt
> 0/0
>
> Can you reproduce it steadily ?

Yes. Note, that it's not spamc that segfaults, so it looks the same on
the command line for me:

mowsiany@beczulka:~$ spamc -r < tmp/spamd-crash.txt
0/0
mowsiany@beczulka:~$

But syslog proves there is a crash:

Sep 22 14:38:33 beczulka spamd[4534]: spamd: connection from beczulka [127.0.0.1] at port 43689
Sep 22 14:38:33 beczulka spamd[4534]: spamd: setuid to mowsiany succeeded
Sep 22 14:38:34 beczulka spamd[4534]: spamd: checking message <0c3d01cb5a26$c3b817b0$4b284710$@lv> for mowsiany:82952
Sep 22 14:38:37 beczulka kernel: [557029.199282] spamd[4534]: segfault at 38e8fd3a1 ip 00007f6269838a86 sp 00007fffb3255900 error 4 in libperl.so.5.10.1[7f6269795000+162000]
Sep 22 14:38:37 beczulka spamd[1443]: spamd: handled cleanup of child pid [4534] due to SIGCHLD: DIED, signal 11 (000b)
Sep 22 14:38:37 beczulka spamd[1443]: prefork: child states: I
Sep 22 14:38:37 beczulka spamd[1443]: spamd: server successfully spawned child process, pid 4620
Sep 22 14:38:37 beczulka spamd[1443]: prefork: child states: II

--
Marcin Owsiany <email address hidden> http://marcin.owsiany.pl/
GnuPG: 1024D/60F41216 FE67 DA2D 0ACA FC5E 3F75 D6F6 3A0D 8AA0 60F4 1216

"Every program in development at MIT expands until it can read mail."
                                                              -- Unknown

[Marcin Owsiany (marcin-owsiany-pl)]

I had a look at the history of segfaults in my syslog and found the following things:

There were the following two kernel messages, with slightly different frequencies:
29 times: segfault at 10000000008 ip 00007f6269838a81 sp 00007fffb3255900 error 4 in libperl.so.5.10.1[7f6269795000+162000]
40 times: segfault at 38e8fd3a1 ip 00007f6269838a86 sp 00007fffb3255900 error 4 in libperl.so.5.10.1[7f6269795000+162000]

The segfaults started at Sep 18 21:41:38
At first segfaults were sparse and spamd eventally successfully classified as ham on a retry.
Today they got more frequent up to a point where I had to stop using spamassassin.

[Marcin Owsiany (marcin-owsiany-pl)]

another thing: removing ~/.spamassassin does not help

[Marcin Owsiany (marcin-owsiany-pl)]

After installing perl-debug and attaching to a spamd child I managed to obtain the following backtrace:

Program received signal SIGSEGV, Segmentation fault.
0x00007f6269838a86 in S_share_hek_flags (my_perl=0x165e010, str=0x4652010 "OpenVZ", len=6, hash=2293735283, flags=0) at hv.c:2460
2460 hv.c: No such file or directory.
 in hv.c
(gdb) bt full
#0 0x00007f6269838a86 in S_share_hek_flags (my_perl=0x165e010, str=0x4652010 "OpenVZ", len=6, hash=2293735283, flags=0) at hv.c:2460
        entry = 0x1f1fa00
        flags_masked = 0
#1 0x00007f626983a724 in Perl_hv_common (my_perl=0x165e010, hv=0x2f97bc8, keysv=<value optimized out>, key=0x1f1fa00 "\001", klen=6, flags=73736208,
    action=<value optimized out>, val=0x46d5b70, hash=2293735283) at hv.c:795
        xhv = 0x2e55df0
        entry = 0x474a3c8
        oentry = <value optimized out>
        sv = <value optimized out>
        is_utf8 = 0 '\000'
        masked_flags = 0
        return_svp = 0
#2 0x00007f626984339e in Perl_pp_helem (my_perl=0x165e010) at pp_hot.c:1804
        sp = 0x29ecde8
        svp = 0x0
        keysv = 0x46c9468
        sv = <value optimized out>
        hash = 23488208
        preeminent = 0
#3 0x00007f626983e336 in Perl_runops_standard (my_perl=0x165e010) at run.c:40
No locals.
#4 0x00007f62697e61cc in S_run_body (my_perl=<value optimized out>) at perl.c:2426
No locals.
#5 perl_run (my_perl=<value optimized out>) at perl.c:2349
        oldscope = 1
        ret = <value optimized out>
        cur_env = {je_prev = 0x165e278, je_buf = {{__jmpbuf = {0, -8069178308044576023, 4197280, 140736198958288, 0, 0, 8069293152144927465, 7980475193757870825},
              __mask_was_saved = 0, __saved_mask = {__val = {140058883522561, 0, 140060656663128, 140060653156368, 23468904, 0, 0, 4197280, 140736198958288, 140060656751733,
                  0, 23453712, 23453712, 0, 23453712, 23554064}}}}, je_ret = 3, je_mustcatch = 0 '\000'}
#6 0x0000000000400d7c in main (argc=9, argv=0x7fffb3255cd8, env=0x7fffb3255d28) at perlmain.c:117
        exitstatus = -1903176799
(gdb)

[Thierry Carrez (ttx)]

I made spamc (with spamd enabled) loop over the test message: no spamd segfault after 130 iterations... on Maverick and on Lucid. Something else must happen here, maybe some outside memory corruption. Have you tried the same thing on another machine, to rule out RAM issues ?

[Marcin Owsiany (marcin-owsiany-pl)]

On Mon, Sep 27, 2010 at 03:04:42PM -0000, Thierry Carrez wrote:
> I made spamc (with spamd enabled) loop over the test message: no spamd
> segfault after 130 iterations... on Maverick and on Lucid. Something
> else must happen here, maybe some outside memory corruption. Have you
> tried the same thing on another machine, to rule out RAM issues ?

In fact a simple spamd restart has helped (scanning the message 150
times did not return an error). So it might well have been a memory
corruption. All the more that the hash entry data structure which
tripped spamd looked very broken to me:

(gdb) p entry
$1 = (HE *) 0x1f1fa00
(gdb) p *entry
$2 = {hent_next = 0x1, hent_hek = 0x38e8fd3a1, he_valu = {hent_val =
0x100898ce2, hent_refcount = 4303981794}}

I guess this bug should be closed as unreproducible.

--
Marcin Owsiany <email address hidden> http://marcin.owsiany.pl/
GnuPG: 1024D/60F41216 FE67 DA2D 0ACA FC5E 3F75 D6F6 3A0D 8AA0 60F4 1216

"Every program in development at MIT expands until it can read mail."
                                                              -- Unknown

[Scott Kitterman (kitterman)]

Done.