pqiv-2.12, SIGSEGV in bostree_node_count

[NHOrus]

backtrace

#0  0x000055b03492583a in bostree_node_count (tree=0x55b035e7cdc0) at /var/tmp/portage/media-gfx/pqiv-2.12/work/pqiv-2.12/lib/bostree.c:174
#1  0x000055b03491741d in relative_image_pointer (movement=movement@entry=-1) at /var/tmp/portage/media-gfx/pqiv-2.12/work/pqiv-2.12/pqiv.c:3082
#2  0x000055b03491c70f in image_loader_thread (user_data=<optimized out>) at /var/tmp/portage/media-gfx/pqiv-2.12/work/pqiv-2.12/pqiv.c:2763
#3  0x00007f6a1cc5688d in g_thread_proxy (data=0x55b035cb8600) at ../glib-2.78.3/glib/gthread.c:831
#4  0x00007f6a1c9b1ff9 in start_thread (arg=<optimized out>) at pthread_create.c:444
#5  0x00007f6a1ca25848 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78

[NHOrus]

#0  0x000055b03492583a in bostree_node_count (tree=0x55b035e7cdc0) at /var/tmp/portage/media-gfx/pqiv-2.12/work/pqiv-2.12/lib/bostree.c:174
#1  0x000055b03491741d in relative_image_pointer (movement=movement@entry=-1) at /var/tmp/portage/media-gfx/pqiv-2.12/work/pqiv-2.12/pqiv.c:3082
        count = <optimized out>
        __func__ = "relative_image_pointer"
#2  0x000055b03491c70f in image_loader_thread (user_data=<optimized out>) at /var/tmp/portage/media-gfx/pqiv-2.12/work/pqiv-2.12/pqiv.c:2763
        next = 0x55b036018210 = {0x55b035d8bc50, 0x55b035d8ba90, 0x55b035d8b8d0}
        loaded_node = 0x55b035d90b40
        node_list = 0x55b035ca76f0 = {0x55b035d90b40, 0x55b035d8bc50, 0x55b035d8ba90, 0x55b035d8b8d0}
        it = <optimized out>
        node = 0x55b035d8cf70
        purpose = <optimized out>
#3  0x00007f6a1cc5688d in g_thread_proxy (data=0x55b035cb8600) at ../glib-2.78.3/glib/gthread.c:831
        thread = 0x55b035cb8600
        __func__ = "g_thread_proxy"
#4  0x00007f6a1c9b1ff9 in start_thread (arg=<optimized out>) at pthread_create.c:444
        ret = <optimized out>
        pd = <optimized out>
        out = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140093723188544, 3104218359405873860, -120, 0, 140733298657120, 0, -3042291954929759548, -3044328823323096380}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#5  0x00007f6a1ca25848 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78

[phillipberndt]

Is that the stable version or built from git head? Is there any particular file that causes this?

[NHOrus]

Stable version (Gentoo)
And unable to replicate.
May be caused opening folder while it's content was being downloaded by rsync.

[NHOrus]

Well, it returns, intermitten, from git head.

It happened when I pressed q while paging actively, so I suspect multi-threading issues.

Will apply sanitizers and try to replicate.

Thread 7 (Thread 0x7f256be006c0 (LWP 8565)):
#0  0x00007f258836fc9f in __GI___poll (fds=fds@entry=0x7f254c0071f0, nfds=nfds@entry=2, timeout=timeout@entry=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f25793a94f1 in poll (__timeout=-1, __nfds=2, __fds=0x7f254c0071f0) at /usr/include/bits/poll2.h:39
#2  poll_func (ufds=0x7f254c0071f0, nfds=2, timeout=-1, userdata=0x56390ed9c0d0) at ../pulseaudio-17.0/src/pulse/thread-mainloop.c:70
#3  0x00007f257939a5f4 in pa_mainloop_poll (m=m@entry=0x56390d7460c0) at ../pulseaudio-17.0/src/pulse/mainloop.c:863
#4  0x00007f257939ac86 in pa_mainloop_iterate (m=m@entry=0x56390d7460c0, block=block@entry=1, retval=retval@entry=0x0) at ../pulseaudio-17.0/src/pulse/mainloop.c:945
#5  0x00007f257939ad40 in pa_mainloop_run (m=0x56390d7460c0, retval=retval@entry=0x0) at ../pulseaudio-17.0/src/pulse/mainloop.c:963
#6  0x00007f25793a95c9 in thread (userdata=0x56390ed9c080) at ../pulseaudio-17.0/src/pulse/thread-mainloop.c:101
#7  0x00007f2579347abe in internal_thread_func (userdata=0x56390d7e6c30) at ../pulseaudio-17.0/src/pulsecore/thread-posix.c:81
#8  0x00007f2588308ff9 in start_thread (arg=<optimized out>) at pthread_create.c:444
#9  0x00007f258837ca28 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78

Thread 6 (Thread 0x7f2581a006c0 (LWP 8266)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f2588c748e0 in g_cond_wait (cond=cond@entry=0x56390d865a58, mutex=mutex@entry=0x56390d865a50) at ../glib-2.78.4/glib/gthread-posix.c:1552
#2  0x00007f2588be024b in g_async_queue_pop_intern_unlocked (queue=0x56390d865a50, wait=1, end_time=-1) at ../glib-2.78.4/glib/gasyncqueue.c:425
#3  0x00007f2588c45f12 in g_thread_pool_spawn_thread (data=<optimized out>) at ../glib-2.78.4/glib/gthreadpool.c:311
#4  0x00007f2588c458ad in g_thread_proxy (data=0x56390d865aa0) at ../glib-2.78.4/glib/gthread.c:831
#5  0x00007f2588308ff9 in start_thread (arg=<optimized out>) at pthread_create.c:444
#6  0x00007f258837ca28 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78

Thread 5 (Thread 0x7f25810006c0 (LWP 8267)):
#0  0x00007f258836fc9f in __GI___poll (fds=0x7f256c000b90, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f2588c17487 in g_main_context_poll_unlocked (priority=<optimized out>, n_fds=1, fds=0x7f256c000b90, timeout=<optimized out>, context=0x56390d804720) at ../glib-2.78.4/glib/gmain.c:4653
#2  g_main_context_iterate_unlocked (context=context@entry=0x56390d804720, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib-2.78.4/glib/gmain.c:4344
#3  0x00007f2588c17b4c in g_main_context_iteration (context=context@entry=0x56390d804720, may_block=may_block@entry=1) at ../glib-2.78.4/glib/gmain.c:4414
#4  0x00007f25824f3aad in dconf_gdbus_worker_thread (user_data=0x56390d804720) at ../dconf-0.40.0/gdbus/dconf-gdbus-thread.c:82
#5  0x00007f2588c458ad in g_thread_proxy (data=0x56390d8048e0) at ../glib-2.78.4/glib/gthread.c:831
#6  0x00007f2588308ff9 in start_thread (arg=<optimized out>) at pthread_create.c:444
#7  0x00007f258837ca28 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78

Thread 4 (Thread 0x7f25824006c0 (LWP 8265)):
#0  0x00007f258836fc9f in __GI___poll (fds=0x56390d7cea20, nfds=2, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f2588c17487 in g_main_context_poll_unlocked (priority=<optimized out>, n_fds=2, fds=0x56390d7cea20, timeout=<optimized out>, context=0x56390d780be0) at ../glib-2.78.4/glib/gmain.c:4653
#2  g_main_context_iterate_unlocked (context=context@entry=0x56390d780be0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib-2.78.4/glib/gmain.c:4344
#3  0x00007f2588c17b4c in g_main_context_iteration (context=0x56390d780be0, may_block=may_block@entry=1) at ../glib-2.78.4/glib/gmain.c:4414
#4  0x00007f2588c17b91 in glib_worker_main (data=<optimized out>) at ../glib-2.78.4/glib/gmain.c:6574
#5  0x00007f2588c458ad in g_thread_proxy (data=0x56390d7362d0) at ../glib-2.78.4/glib/gthread.c:831
#6  0x00007f2588308ff9 in start_thread (arg=<optimized out>) at pthread_create.c:444
#7  0x00007f258837ca28 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78

Thread 3 (Thread 0x7f257be006c0 (LWP 8268)):
#0  0x00007f258836fc9f in __GI___poll (fds=0x7f2564000b90, nfds=2, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x00007f2588c17487 in g_main_context_poll_unlocked (priority=<optimized out>, n_fds=2, fds=0x7f2564000b90, timeout=<optimized out>, context=0x56390d8f5a30) at ../glib-2.78.4/glib/gmain.c:4653
#2  g_main_context_iterate_unlocked (context=0x56390d8f5a30, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib-2.78.4/glib/gmain.c:4344
#3  0x00007f2588c17e0f in g_main_loop_run (loop=0x56390d8f5b60) at ../glib-2.78.4/glib/gmain.c:4551
#4  0x00007f25890fa7f6 in gdbus_shared_thread_func (user_data=0x56390d8fb710) at ../glib-2.78.4/gio/gdbusprivate.c:284
#5  0x00007f2588c458ad in g_thread_proxy (data=0x56390d89a6f0) at ../glib-2.78.4/glib/gthread.c:831
#6  0x00007f2588308ff9 in start_thread (arg=<optimized out>) at pthread_create.c:444
#7  0x00007f258837ca28 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78

Thread 2 (Thread 0x7f2582a2de80 (LWP 8264)):
#0  DestroyWandIds () at MagickWand/wand.c:121
#1  0x00007f258895cdd9 in MagickWandTerminus () at MagickWand/magick-wand.c:1048
#2  0x000056390cf5d255 in file_type_wand_exit_handler () at /home/nho/workshop/pqiv/backends/wand.c:300
#3  0x00007f25882bd375 in __run_exit_handlers (status=0, listp=0x7f258843b680 <__exit_funcs>, run_list_atexit=run_list_atexit@entry=true, run_dtors=run_dtors@entry=true) at exit.c:111
#4  0x00007f25882bd4ca in __GI_exit (status=<optimized out>) at exit.c:141
#5  0x00007f25882a4ef1 in __libc_start_call_main (main=main@entry=0x56390cf43da0 <main>, argc=argc@entry=3, argv=argv@entry=0x7ffcf1f91d98) at ../sysdeps/nptl/libc_start_call_main.h:74
#6  0x00007f25882a4fa5 in __libc_start_main_impl (main=0x56390cf43da0 <main>, argc=3, argv=0x7ffcf1f91d98, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffcf1f91d88) at ../csu/libc-start.c:360
#7  0x000056390cf440a1 in _start ()

Thread 1 (Thread 0x7f25790006c0 (LWP 8564)):
#0  0x000056390cf5799a in bostree_node_count (tree=0x56390d908c50) at /home/nho/workshop/pqiv/lib/bostree.c:174
#1  0x000056390cf4616a in relative_image_pointer (movement=-1) at /home/nho/workshop/pqiv/pqiv.c:3092
#2  0x000056390cf4d468 in image_loader_thread (user_data=<optimized out>) at /home/nho/workshop/pqiv/pqiv.c:2773
#3  0x00007f2588c458ad in g_thread_proxy (data=0x56390d6ed010) at ../glib-2.78.4/glib/gthread.c:831
#4  0x00007f2588308ff9 in start_thread (arg=<optimized out>) at pthread_create.c:444
#5  0x00007f258837ca28 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78

[NHOrus]

Built pqiv with CFLAGS="-O3 -D_FORTIFY_SOURCE=2 -pipe -march=native -ggdb -fsanitize=thread,undefined -fPIC -pie" LDFLAGS="-fsanitize=thread,undefined -fPIC -pie" ./configure --without-libav --prefix=/home/nho/.local/ for options. Ran on same corpus that caused crash first time. Got a bunch of warnings, especially notable for this case is

==================
WARNING: ThreadSanitizer: data race (pid=16569)
  Write of size 8 at 0x7b0800026400 by main thread:
    #0 free /var/tmp/portage/sys-devel/gcc-13.2.1_p20240210/work/gcc-13-20240210/libsanitizer/tsan/tsan_interceptors_posix.cpp:740 (libtsan.so.2+0x3afab)
    #1 bostree_destroy /home/nho/workshop/pqiv/lib/bostree.c:170 (pqiv+0x63ea2)
    #2 main /home/nho/workshop/pqiv/pqiv.c:8280 (pqiv+0x33202)

  Previous read of size 8 at 0x7b0800026400 by thread T6:
    #0 bostree_node_count /home/nho/workshop/pqiv/lib/bostree.c:174 (pqiv+0x62c79)
    #1 relative_image_pointer /home/nho/workshop/pqiv/pqiv.c:3092 (pqiv+0x391a1)
    #2 image_loader_thread /home/nho/workshop/pqiv/pqiv.c:2773 (pqiv+0x4554b)
    #3 g_thread_proxy ../glib-2.78.4/glib/gthread.c:831 (libglib-2.0.so.0+0x898ac)

  Thread T6 'image-loader' (tid=16576, running) created by main thread at:
    #0 pthread_create /var/tmp/portage/sys-devel/gcc-13.2.1_p20240210/work/gcc-13-20240210/libsanitizer/tsan/tsan_interceptors_posix.cpp:1036 (libtsan.so.2+0x3b962)
    #1 g_system_thread_new ../glib-2.78.4/glib/gthread-posix.c:1298 (libglib-2.0.so.0+0xb8577)
    #2 initialize_gui /home/nho/workshop/pqiv/pqiv.c:7396 (pqiv+0x56e24)
    #3 inner_main /home/nho/workshop/pqiv/pqiv.c:8116 (pqiv+0x5707d)
    #4 gdk_threads_dispatch ../gtk+-3.24.41/gdk/gdk.c:769 (libgdk-3.so.0+0x30756)
    #5 __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58 (libc.so.6+0x27ee9)

SUMMARY: ThreadSanitizer: data race /home/nho/workshop/pqiv/lib/bostree.c:170 in bostree_destroy

but without crash yet.

[phillipberndt]

Rather than trying to understand how exactly this can happen (it should not 🤔), I went for the simplest possible approach for fixing this: Joining the thread that's racing with the free call before making it. If that doesn't work,

Could you check if this change fixes the issue for you?