uTox aborts on toxcore restart

Since toxcore 17e8195 uTox (uTox/uTox@55b0222) aborts when it tries to restart toxcore. That is, when a setting changes (I toggle the UDP switch in advanced settings). The abort can be provoked 100% of the tries.

Here is what utox -vvvv outputs:

Toxcore:      Restarting Toxcore
Toxcore:      Using unencrypted save file
Toxcore:      Creating New Toxcore instance.
                IPv6 : 0
                UDP  : 1
                Proxy: 0 127.0.0.1 9050
Friend:       Initializing friend list.
Friend:       Initializing friend: 0
[…]
Friend:       Friendlist sucessfully initialized with 14 friends.
utox: /[…]/TokTok/c-toxcore/toxcore/logger.c:107: logger_write: Assertion `!"NULL logger not permitted"' failed.
Aborted (core dumped)

Here is an example of what I get in dmesg:

traps: utox[25996] general protection ip:7f2f5f44d7a8 sp:7f2f5ab46400 error:0 in libtoxcore.so.2.6.0[7f2f5f43d000+69000]

As a result, it is impossible to change any settings in uTox.

Is there anything that uTox can do, or is this a bug in toxcore only?

This is the line in uTox which leads to the abort: https://github.com/uTox/uTox/blob/55b0222e30e7a0974ca1ca3ced229646b264cacd/src/av/utox_av.c#L55

I don't know if other clients are affected.

[iphydf]

The commit you point at only changed a test, no toxcore production code. Are you sure that's the commit at which the crash started happening?

In fact, it wasn't. Now the earliest commit that I found is this: 064ffe5. I couldn't reproduce it at the commit one earlier than this, now. Maybe later it will work. It seems that the abort happens rarer the earlier the commit.

[iphydf]

Thanks, that commit makes sense. Does it fail with current master? Can you provide a stack trace (gdb) for that?

Yes, it fails with current master (uTox/uTox@55b0222).

(gdb) bt full
#0  0x00007ff6371b7920 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
        set =
            {__val = {0, 140695439454832, 140695439460096, 140695463495876, 140698761134080, 140695075557152, 140695075557253, 140695075557152, 140695075557152, 140695075557299, 140695075557452, 140695075557152, 140695075557452, 0, 0, 0}}
        pid = <optimized out>
        tid = <optimized out>
#1  0x00007ff6371b8ffd in __GI_abort () at abort.c:90
        save_stage = 2
        act =
          {__sigaction_handler = {sa_handler = 0x7ff620001060, sa_sigaction = 0x7ff620001060}, sa_mask = {__val = {0, 0, 140695075557472, 93877637682560, 140695463529856, 0, 0, 0, 140695439455032, 140695439454864, 140695464585808, 21474836480, 880344120563138560, 0, 140695518679040, 140695516321065}}, sa_flags = 107, sa_restorer = 0x7ff63a459548 <__PRETTY_FUNCTION__.2417>}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x00007ff6371b0147 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x7ff63a459529 "!\"NULL logger not permitted\"", file=file@entry=0x7ff63a4594e0 "[…]/TokTok/c-toxcore/toxcore/logger.c", line=line@entry=107, function=function@entry=0x7ff63a459548 <__PRETTY_FUNCTION__.2417> "logger_write")
    at assert.c:92
        str = 0x7ff620001060 ""
        total = 4096
#3  0x00007ff6371b01f2 in __GI___assert_fail (assertion=0x7ff63a459529 "!\"NULL logger not permitted\"", file=0x7ff63a4594e0 "[…]/TokTok/c-toxcore/toxcore/logger.c", line=107, function=0x7ff63a459548 <__PRETTY_FUNCTION__.2417> "logger_write") at assert.c:101
#4  0x00007ff63a412861 in logger_write () at /usr/local/lib64/libtoxcore.so.2
#5  0x00007ff63a44ec30 in msi_kill () at /usr/local/lib64/libtoxcore.so.2
#6  0x00007ff63a453ddc in toxav_kill () at /usr/local/lib64/libtoxcore.so.2
#7  0x00005561958043e4 in utox_av_ctrl_thread (UNUSED_args=0x0) at […]/avoidr/uTox/src/av/utox_av.c:55
        msg = 0x556195bd56b0 <toxav_msg>
        av = 0x7ff6281114d0
        call_count = 0
        audio_in = false
#8  0x00007ff639947568 in start_thread (arg=0x7ff635b0c700) at pthread_create.c:465
        pd = 0x7ff635b0c700
        now = <optimized out>
        unwind_buf =
              {cancel_jmp_buf = {{jmp_buf = {140695439460096, 7337533894261557514, 140724067165614, 140724067165615, 140695438409728, 140695439460096, -7334037973237151478, -7334011819423872758}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#9  0x00007ff63727752f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

[iphydf]

Thanks that's very useful. I'll look into it.

Thank you, I'm glad.

[iphydf]

@avoidr can you recompile toxcore with debug symbols, so I can see which line in msi_kill is calling the logger, and so I can see the locals there?

(gdb) bt full
#0  0x00007f0d80751920 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:51
        set =
            {__val = {0, 139695942685296, 139695942690560, 139695966726340, 139698033754112, 139695556136736, 139695556136837, 139695556136736, 139695556136736, 139695556136883, 139695556137036, 139695556136736, 139695556137036, 0, 0, 0}}
        pid = <optimized out>
        tid = <optimized out>
#1  0x00007f0d80752ffd in __GI_abort () at abort.c:90
        save_stage = 2
        act =
          {__sigaction_handler = {sa_handler = 0x7f0d68001060, sa_sigaction = 0x7f0d68001060}, sa_mask = {__val = {0, 0, 139695556137056, 94711305191520, 139695966760320, 0, 0, 0, 139695942685496, 139695942685328, 139695967816272, 21474836480, 7370331512508498432, 0, 139696021921792, 139696019559513}}, sa_flags = 107, sa_restorer = 0x7f0d839f5478 <__PRETTY_FUNCTION__.2417>}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x00007f0d8074a147 in __assert_fail_base (fmt=<optimized out>, assertion=assertion@entry=0x7f0d839f5459 "!\"NULL logger not permitted\"", file=file@entry=0x7f0d839f5410 "[…]/TokTok/c-toxcore/toxcore/logger.c", line=line@entry=107, function=function@entry=0x7f0d839f5478 <__PRETTY_FUNCTION__.2417> "logger_write")
    at assert.c:92
        str = 0x7f0d68001060 ""
        total = 4096
#3  0x00007f0d8074a1f2 in __GI___assert_fail (assertion=0x7f0d839f5459 "!\"NULL logger not permitted\"", file=0x7f0d839f5410 "[…]/TokTok/c-toxcore/toxcore/logger.c", line=107, function=0x7f0d839f5478 <__PRETTY_FUNCTION__.2417> "logger_write") at assert.c:101
#4  0x00007f0d839ac8a1 in logger_write (log=0x0, level=LOGGER_LEVEL_DEBUG, file=0x7f0d839f7000 "[…]/TokTok/c-toxcore/toxav/msi.c", line=169, func=0x7f0d839f75b8 <__func__.6905> "msi_kill", format=0x7f0d839f70dc "Terminated session: %p") at /home/robert/Documents/Source_Code/git/TokTok/c-toxcore/toxcore/logger.c:107
        __PRETTY_FUNCTION__ = "logger_write"
        filename = 0x0
        msg = '\000' <repeats 312 times>...
        args = {{gp_offset = 0, fp_offset = 0, overflow_arg_area = 0x0, reg_save_area = 0x0}}
#5  0x00007f0d839eaa64 in msi_kill (session=0x7f0d70116710, log=0x0) at […]/TokTok/c-toxcore/toxav/msi.c:169
        __func__ = "msi_kill"
#6  0x00007f0d839efc3d in toxav_kill (av=0x7f0d70118c80) at […]/TokTok/c-toxcore/toxav/toxav.c:212
#7  0x00005623b09d420f in utox_av_ctrl_thread (UNUSED_args=0x0) at […]/avoidr/uTox/src/av/utox_av.c:55
        msg = 0x5623b0da56b0 <toxav_msg>
        av = 0x7f0d70118c80
        call_count = 0
        audio_in = false
#8  0x00007f0d82ee1568 in start_thread (arg=0x7f0d7f0a6700) at pthread_create.c:465
        pd = 0x7f0d7f0a6700
        now = <optimized out>
        unwind_buf =
              {cancel_jmp_buf = {{jmp_buf = {139695942690560, 2362667920212334357, 140735868016750, 140735868016751, 139695941640192, 139695942690560, -2390531929476196587, -2390597588776151275}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
        pagesize_m1 = <optimized out>
        sp = <optimized out>
        freesize = <optimized out>
        __PRETTY_FUNCTION__ = "start_thread"
#9  0x00007f0d8081152f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

[iphydf]

Can you try with #1153?

[iphydf]

Actually never mind, I see the passed logger is null. Thanks.

[iphydf]

@avoidr can you try with #1154? It will still crash, but I want to know when.