bitlbee dies with SIGABRT when trying to "account off"

[aron@…]

This is consistent for me. I'm running bitlbee-3.2-1.fc18.x86_64 on Fedora 18. It happens at when I do "account off" for any jabber account. The trace below is for "account off hipchat"

Program received signal SIGABRT, Aborted.
0x00007f336659eba5 in __GI_raise (sig=sig@entry=6)
    at ../nptl/sysdeps/unix/sysv/linux/raise.c:63
63        return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);
(gdb) thread apply all bt full

Thread 1 (Thread 0x7f3368a95740 (LWP 5129)):
#0  0x00007f336659eba5 in __GI_raise (sig=sig@entry=6)
    at ../nptl/sysdeps/unix/sysv/linux/raise.c:63
        resultvar = 0
        pid = 5129
        selftid = 5129
#1  0x00007f33665a0358 in __GI_abort () at abort.c:90
        save_stage = 2
        act = {__sigaction_handler = {sa_handler = 0x7f33666e0ba1, 
            sa_sigaction = 0x7f33666e0ba1}, sa_mask = {__val = {3, 
    140734403060427, 5, 139858738543988, 1, 139858738550686, 3, 
    140734403060404, 12, 139858738550690, 2, 139858738550690, 2, 
    140734403061216, 18, 140734403062976}}, sa_flags = 98, sa_restorer = 0x7}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x00007f33665de59b in __libc_message (do_abort=do_abort@entry=2, 
    fmt=fmt@entry=0x7f33666e2b88 "*** glibc detected *** %s: %s: 0x%s ***\n")
    at ../sysdeps/unix/sysv/linux/libc_fatal.c:197
        ap = {{gp_offset = 40, fp_offset = 48, overflow_arg_area = 
    0x7fff481a2cd0, reg_save_area = 0x7fff481a2be0}}
        ap_copy = {{gp_offset = 16, fp_offset = 48, overflow_arg_area = 
    0x7fff481a2cd0, reg_save_area = 0x7fff481a2be0}}
        fd = 2
        on_2 = <optimized out>
        list = <optimized out>
        nlist = <optimized out>
        cp = <optimized out>
        written = <optimized out>
#3  0x00007f33665e4776 in malloc_printerr (action=3, str=
    0x7f33666e2cc0 "munmap_chunk(): invalid pointer", ptr=<optimized out>)
    at malloc.c:4969
        buf = "00007f336918276c"
        cp = <optimized out>
#4  0x00007f33681d279f in g_free (mem=0x7f336918276c) at gmem.c:252
No locals.
#5  0x00007f3368b058fb in ssl_disconnect (conn_=0x7f33691a9140)
    at ssl_nss.c:298
        conn = 0x7f33691a9140
#6  0x00007f3368b15f58 in jabber_logout (ic=0x7f3369182600) at jabber.c:305
        jd = 0x7f3369182660
#7  0x00007f3368b09ba0 in imc_logout (ic=0x7f3369182600, 
    allow_reconnect=allow_reconnect@entry=0) at nogaim.c:376
        bee = 0x7f3369168620
        a = 0x7f336917cad0
        l = <optimized out>
        delay = <optimized out>
#8  0x00007f3368b07c1f in account_off (bee=<optimized out>, a=0x7f336917cad0)
    at account.c:358
No locals.
#9  0x00007f3368af55e4 in root_privmsg (iu=0x7f336916a100, msg=
    0x7f33692627b2 "account hipchat off") at irc_user.c:225
        cmd = 0x7fff481a2d90 "account"
#10 0x00007f3368af1b1b in control_channel_privmsg (ic=0x7f336917b140, msg=
    0x7f33692627b2 "account hipchat off") at irc_channel.c:599
        irc = <optimized out>
        iu = 0x7f336916a100
        s = <optimized out>
#11 0x00007f3368aedd5c in irc_process (irc=irc@entry=0x7f3369168270)
    at irc.c:393
        conv = 0x7f33692627a0 "PRIVMSG"
        temp = <optimized out>
        cmd = 0x7f33692205a0
        i = 0
#12 0x00007f3368ae9ecc in bitlbee_io_current_client_read (data=0x7f3369168270, 
    fd=6, cond=cond@entry=B_EV_IO_READ) at bitlbee.c:226
        line = 
    "PRIVMSG &bitlbee :account hipchat off\r\n\000\071s@public.talk.google.com/TalkGadget1CDF7E77\" to=\"agriffis@gmail.com\"><priority>24</priority><caps:c node=\"http://talkgadget.google.com/client/caps\" ver=\"1.0\" e"...
        st = <optimized out>
#13 0x00007f3368afda75 in gaim_io_invoke (data=0x7f33691679e0, 
    condition=<optimized out>, source=<optimized out>) at events_glib.c:88
        gaim_cond = B_EV_IO_READ
        st = <optimized out>
#14 gaim_io_invoke (source=<optimized out>, condition=<optimized out>, data=
    0x7f33691679e0) at events_glib.c:72
        closure = <optimized out>
        st = 0
#15 0x00007f33681cca55 in g_main_dispatch (context=0x7f336914b200)
    at gmain.c:2715
        dispatch = 0x7f336820a7e0 <g_io_unix_dispatch>
        was_in_call = 0
        user_data = 0x7f33691679e0
        callback = 0x7f3368afda30 <gaim_io_invoke>
        cb_funcs = 0x7f33684a59a0 <g_source_callback_funcs>
        cb_data = 0x7f3369166b80
        current_source_link = {data = 0x7f33691683b0, next = 0x0}
        need_destroy = <optimized out>
        source = 0x7f33691683b0
        current = 0x7f336914af60
        i = 0
#16 g_main_context_dispatch (context=context@entry=0x7f336914b200)
    at gmain.c:3219
No locals.
#17 0x00007f33681ccd88 in g_main_context_iterate (context=0x7f336914b200, 
    block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at gmain.c:3290
        max_priority = 2147483647
        timeout = 13072
        some_ready = 1
        nfds = <optimized out>
        allocated_nfds = <optimized out>
        fds = 0x7f336927bbc0
#18 0x00007f33681cd182 in g_main_loop_run (loop=0x7f336914b0e0) at gmain.c:3484
        __PRETTY_FUNCTION__ = "g_main_loop_run"
#19 0x00007f3368afdaec in b_main_run () at events_glib.c:64
No locals.
#20 0x00007f3368ae912f in main (argc=<optimized out>, argv=0x7fff481a34c8)
    at unix.c:183
        i = <optimized out>
        old_cwd = 0x0
        sig = {__sigaction_handler = {sa_handler = 
    0x7f3368afc070 <sighandler>, sa_sigaction = 0x7f3368afc070 <sighandler>}, 
          sa_mask = {__val = {0 <repeats 16 times>}}, sa_flags = -2147483648, 
          sa_restorer = 0x0}
        old = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, 
          sa_mask = {__val = {0, 1, 0, 139858747417264, 139858778919904, 
    139858778919904, 140734403064320, 140734403065032, 139858774096357, 0, 0, 
    140734403064480, 140734403064320, 17, 139858749616864, 0}}, sa_flags = 0, 
          sa_restorer = 0x7f54299b4c20}

[wilmer]

Yet another nss-specific issue. :-( I'll poke the Fedora dev..

[wilmer]

Matej, let me CC you this way. Might be a known issue already?

[Aron Griffis <aron@…>]

FYI if I comment out the offending g_free() then I get a different error. Oddly enough it appears to be *earlier* in the sequence.

(gdb) thread apply all bt full

Thread 1 (Thread 0x7ffff7fbc740 (LWP 14284)):
#0  0x00007ffff5ac7ba5 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:63
        resultvar = 0
        pid = 14284
        selftid = 14284
#1  0x00007ffff5ac9358 in __GI_abort () at abort.c:90
        save_stage = 2
        act = {__sigaction_handler = {sa_handler = 0x7ffff5c09ba1, sa_sigaction = 0x7ffff5c09ba1}, sa_mask = {__val = {3, 140737488344843, 5, 
    140737316425076, 1, 140737316431774, 3, 140737488344820, 12, 140737316431778, 2, 140737316431778, 2, 140737488345632, 24, 140737488347392}}, 
          sa_flags = 151, sa_restorer = 0x7}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x00007ffff5b0759b in __libc_message (do_abort=do_abort@entry=2, fmt=fmt@entry=0x7ffff5c0bb88 "*** glibc detected *** %s: %s: 0x%s ***\n")
    at ../sysdeps/unix/sysv/linux/libc_fatal.c:197
        ap = {{gp_offset = 40, fp_offset = 48, overflow_arg_area = 0x7fffffffe110, reg_save_area = 0x7fffffffe020}}
        ap_copy = {{gp_offset = 16, fp_offset = 48, overflow_arg_area = 0x7fffffffe110, reg_save_area = 0x7fffffffe020}}
        fd = 13
        on_2 = <optimized out>
        list = <optimized out>
        nlist = <optimized out>
        cp = <optimized out>
        written = <optimized out>
#3  0x00007ffff5b0ea8e in malloc_printerr (ptr=0x5555558d64f0, str=0x7ffff5c0bbe0 "double free or corruption (fasttop)", action=3) at malloc.c:4969
        buf = "00005555558d64f0"
        cp = <optimized out>
#4  _int_free (av=0x7ffff5e43740 <main_arena>, p=0x5555558d64e0, have_lock=0) at malloc.c:3826
        size = <optimized out>
        fb = <optimized out>
        nextchunk = <optimized out>
        nextsize = <optimized out>
        nextinuse = <optimized out>
        prevsize = <optimized out>
        bck = <optimized out>
        fwd = <optimized out>
        errstr = 0x7ffff5c0bbe0 "double free or corruption (fasttop)"
        locked = <optimized out>
#5  0x00007ffff76fb79f in g_free (mem=0x5555558d64f0) at gmem.c:252
No locals.
#6  0x000055555559f451 in jabber_chat_free (c=0x5555558c6aa0) at conference.c:153
        jc = 0x5555558c6870
#7  0x00005555555a50e7 in jabber_logout (ic=0x55555583c620) at jabber.c:297
        jd = 0x55555583c680
#8  0x000055555559430f in imc_logout (ic=0x55555583c620, allow_reconnect=0) at nogaim.c:376
        bee = 0x555555822620
        a = 0x555555836ad0
        l = 0x0
        delay = 32767
#9  0x00005555555919c9 in account_off (bee=0x555555822620, a=0x555555836ad0) at account.c:358
No locals.
#10 0x000055555557b560 in cmd_account (irc=0x555555822270, cmd=0x555555801b80 <cmd.13649>) at root_commands.c:586
        a = 0x555555836ad0
        len = 3
#11 0x0000555555579e1e in root_command (irc=0x555555822270, cmd=0x555555801b80 <cmd.13649>) at root_commands.c:67
        i = 0
        len = 7
#12 0x0000555555579cae in root_command_string (irc=0x555555822270, command=0x7fffffffe340 "account") at root_commands.c:34
No locals.
#13 0x00005555555781fa in root_privmsg (iu=0x555555824100, msg=0x55555597ad82 "account hipchat off") at irc_user.c:225
        cmd = "account\000hipchat\000off"
#14 0x0000555555572ded in control_channel_privmsg (ic=0x555555835140, msg=0x55555597ad82 "account hipchat off") at irc_channel.c:599
        irc = 0x555555822270
        iu = 0x555555824100
        s = 0x55555597ad89 " hipchat off"
#15 0x0000555555574457 in irc_cmd_privmsg (irc=0x555555822270, cmd=0x555555950540) at irc_commands.c:354
        ic = 0x555555835140
        iu = 0x55555597ad95
#16 0x000055555557597f in irc_exec (irc=0x555555822270, cmd=0x555555950540) at irc_commands.c:798
        i = 14
        n_arg = 2
#17 0x000055555556d227 in irc_process (irc=0x555555822270) at irc.c:393
        conv = 0x55555597ad70 "PRIVMSG"
        lines = 0x5555559869d0
        temp = 0x7fffffffe530 "PRIVMSG &bitlbee :account hipchat off\r\n"
        cmd = 0x555555950540
        i = 0
#18 0x00005555555674b3 in bitlbee_io_current_client_read (data=0x555555822270, fd=10, cond=B_EV_IO_READ) at bitlbee.c:226
        irc = 0x555555822270
        line = 
    "PRIVMSG &bitlbee :account hipchat off\r\n\000.gray@gmail.com/gmail.86FB6FBE\" to=\"agriffis@gmail.com\"><status>http://i.imgur.com/yYwoVJd.jpg</status><show>away</show><priority>0</priority><caps:c node=\"http"...
        st = 39
#19 0x0000555555583935 in gaim_io_invoke (source=0x555555822330, condition=G_IO_IN, data=0x5555558219e0) at events_glib.c:88
        closure = 0x5555558219e0
        gaim_cond = B_EV_IO_READ
        st = 0
#20 0x00007ffff76f5a55 in g_main_dispatch (context=0x555555805200) at gmain.c:2715
        dispatch = 0x7ffff77337e0 <g_io_unix_dispatch>
        was_in_call = 0
        user_data = 0x5555558219e0
        callback = 0x5555555838be <gaim_io_invoke>
        cb_funcs = 0x7ffff79ce9a0 <g_source_callback_funcs>
        cb_data = 0x555555820b80
        current_source_link = {data = 0x5555558223b0, next = 0x0}
        need_destroy = <optimized out>
        source = 0x5555558223b0
        current = 0x555555804f60
        i = 0
#21 g_main_context_dispatch (context=context@entry=0x555555805200) at gmain.c:3219
No locals.
#22 0x00007ffff76f5d88 in g_main_context_iterate (context=0x555555805200, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at gmain.c:3290
        max_priority = 2147483647
        timeout = 49575
        some_ready = 1
        nfds = <optimized out>
        allocated_nfds = <optimized out>
        fds = 0x5555559282a0
#23 0x00007ffff76f6182 in g_main_loop_run (loop=0x5555558050e0) at gmain.c:3484
        __PRETTY_FUNCTION__ = "g_main_loop_run"
#24 0x00005555555838a7 in b_main_run () at events_glib.c:64
No locals.
#25 0x0000555555580fb5 in main (argc=4, argv=0x7fffffffeb28) at unix.c:183
        i = 0
        old_cwd = 0x0
        sig = {__sigaction_handler = {sa_handler = 0x55555558148e <sighandler>, sa_sigaction = 0x55555558148e <sighandler>}, sa_mask = {__val = {
    0 <repeats 16 times>}}, sa_flags = -2147483648, sa_restorer = 0x0}
        old = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0}, sa_mask = {__val = {0, 140733193388033, 0, 140737325298352, 1363826891, 
    1363826891, 140737488349760, 93824992308480, 140737351977445, 140737488349424, 533, 140737488349584, 140737488349424, 17, 152, 140737315451602}}, 
          sa_flags = 0, sa_restorer = 0x3bde435c20}

[Aron Griffis <aron@…>]

Nevermind, ignore that last comment. My source was polluted at that point by various debugging attempts.

However I found the bug, here's the patch:

=== modified file 'lib/ssl_nss.c'
--- lib/ssl_nss.c	2013-02-21 19:15:59 +0000
+++ lib/ssl_nss.c	2013-03-21 01:06:41 +0000
@@ -151,7 +151,7 @@
 	conn->fd = fd;
 	conn->func = func;
 	conn->data = data;
-	conn->hostname = hostname;
+	conn->hostname = g_strdup(hostname);
 
 	/* For now, SSL verification is globally enabled by setting the cafile
 	   setting in bitlbee.conf. Commented out by default because probably

You can see that conn->hostname is initialized with g_strdup() in another code path, but here it's being assigned directly.

[Aron Griffis <aron@…>]

See also ​https://bugzilla.redhat.com/show_bug.cgi?id=922447

[mcepl@…]

suggested patch (just a cosmetic changes from the previous one)

[mcepl@…]

We believe that the attached patch (which is ​http://pkgs.fedoraproject.org/cgit/bitlbee.git/plain/nss-crash-rhbz922447.patch ) is a fix for this issue.

I have done a bit more investigation, and it seems to me (see ​https://bugzilla.redhat.com/attachment.cgi?id=730821 ), that there shouldn't be more memory problems (that 4k leak in NSS_NoDB_Init is per-connection and hard to avoid; it could be a problem on heavily used public servers, but there I believe you have to have a rather beefy machine anyway).

[wilmer]

changeset:devel,987