GTestDBus dbus daemon causes child process to hang when using verbose output
Tests in xdg-desktop-portal
may hang when using G_DEBUG_MESSAGES=all
because the daemon is hanging while trying to write to stdout (that is a pipe that probably needs to be flushed), leading to a dead-lock (see how thread 5 and 6 are waiting for thread 7 to complete the write):
Backtrace
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
__futex_abstimed_wait_common64 (private=128, cancel=true, abstime=0x0, op=265, expected=12284, futex_word=0x7fa93e1fc910) at futex-internal.c:57
57 futex-internal.c: No such file or directory.
(gdb) bt
#0 __futex_abstimed_wait_common64
(private=128, cancel=true, abstime=0x0, op=265, expected=12284, futex_word=0x7fa93e1fc910)
at futex-internal.c:57
#1 __futex_abstimed_wait_common
(cancel=true, private=128, abstime=0x0, clockid=0, expected=12284, futex_word=0x7fa93e1fc910)
at futex-internal.c:87
#2 __GI___futex_abstimed_wait_cancelable64
(futex_word=futex_word@entry=0x7fa93e1fc910, expected=12284, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=128) at futex-internal.c:139
#3 0x00007fa9431bc464 in __pthread_clockjoin_ex
(threadid=140364868470336, thread_return=0x0, clockid=0, abstime=0x0, block=<optimized out>)
at pthread_join_common.c:105
#4 0x00007fa943411e4c in g_system_thread_wait (thread=0x61d00000af60) at ../../../glib/gthread-posix.c:1368
#5 g_thread_join (thread=0x61d00000af60) at ../../../glib/gthread.c:1006
#6 0x000055c84b31058c in xdp_fuse_exit ()
#7 0x000055c84b2f21f5 in main ()
(gdb) thread apply all bt
Thread 7 (Thread 0x7fa93c9f9640 (LWP 12287) "fuse mainloop"):
#0 __GI___libc_write (nbytes=113, buf=0x62100000dd00, fd=1) at ../sysdeps/unix/sysv/linux/write.c:26
#1 __GI___libc_write (fd=1, buf=0x62100000dd00, nbytes=113) at ../sysdeps/unix/sysv/linux/write.c:24
#2 0x00007fa9431b0e6d in _IO_new_file_write (f=0x7fa94333b760 <_IO_2_1_stdout_>, data=0x62100000dd00, n=113) at fileops.c:1181
#3 0x00007fa9431b2971 in new_do_write (to_do=113, data=0x62100000dd00 "(/usr/local/libexec/xdg-document-portal:12274): xdg-desktop-portal-DEBUG: 13:49:12.805: GETATTR 1e51cc0813c018ca\nNLY\nc0813c018ca\nd-1\nca\n0644\named-1', resuse_existing: 1, persistent: 0, directory: 0\n 0"..., fp=0x7fa94333b760 <_IO_2_1_stdout_>) at libioP.h:947
#4 _IO_new_do_write (to_do=113, data=0x62100000dd00 "(/usr/local/libexec/xdg-document-portal:12274): xdg-desktop-portal-DEBUG: 13:49:12.805: GETATTR 1e51cc0813c018ca\nNLY\nc0813c018ca\nd-1\nca\n0644\named-1', resuse_existing: 1, persistent: 0, directory: 0\n 0"..., fp=0x7fa94333b760 <_IO_2_1_stdout_>) at fileops.c:426
#5 _IO_new_do_write (fp=0x7fa94333b760 <_IO_2_1_stdout_>, data=0x62100000dd00 "(/usr/local/libexec/xdg-document-portal:12274): xdg-desktop-portal-DEBUG: 13:49:12.805: GETATTR 1e51cc0813c018ca\nNLY\nc0813c018ca\nd-1\nca\n0644\named-1', resuse_existing: 1, persistent: 0, directory: 0\n 0"..., to_do=113) at fileops.c:423
#6 0x00007fa9431b0458 in _IO_new_file_sync (fp=0x7fa94333b760 <_IO_2_1_stdout_>) at fileops.c:799
#7 0x00007fa9431a522f in __GI__IO_fflush (fp=0x7fa94333b760 <_IO_2_1_stdout_>) at libioP.h:947
#8 0x00007fa9437aadd6 in __interceptor_fflush (fp=0x7fa94333b760 <_IO_2_1_stdout_>) at ../../../../src/libsanitizer/sanitizer_common/sanitizer_common_interceptors.inc:6214
#9 __interceptor_fflush(__sanitizer::__sanitizer_FILE*) (fp=0x7fa94333b760 <_IO_2_1_stdout_>) at ../../../../src/libsanitizer/sanitizer_common/sanitizer_common_interceptors.inc:6211
#10 0x00007fa9433ed701 in g_log_writer_standard_streams (log_level=log_level@entry=G_LOG_LEVEL_DEBUG, fields=fields@entry=0x7fa93c9f8720, n_fields=n_fields@entry=4, user_data=user_data@entry=0x0) at ../../../glib/gmessages.c:2601
#11 0x00007fa9433ed818 in g_log_writer_default (log_level=G_LOG_LEVEL_DEBUG, fields=0x7fa93c9f8720, n_fields=4, user_data=0x0) at ../../../glib/gmessages.c:2781
#12 0x00007fa9433e9633 in g_log_structured_array (n_fields=4, fields=0x7fa93c9f8720, log_level=G_LOG_LEVEL_DEBUG) at ../../../glib/gmessages.c:1964
#13 g_log_structured_array (log_level=G_LOG_LEVEL_DEBUG, fields=0x7fa93c9f8720, n_fields=4) at ../../../glib/gmessages.c:1937
#14 0x00007fa9433e9939 in g_log_default_handler (log_domain=log_domain@entry=0x55c84b346aa0 "xdg-desktop-portal", log_level=log_level@entry=G_LOG_LEVEL_DEBUG, message=message@entry=0x60300002e7e0 "GETATTR 1e51cc0813c018ca", unused_data=unused_data@entry=0x0) at ../../../glib/gmessages.c:3236
#15 0x00007fa9433ead6a in g_logv (log_domain=0x55c84b346aa0 "xdg-desktop-portal", log_level=G_LOG_LEVEL_DEBUG, format=<optimized out>, args=<optimized out>) at ../../../glib/gmessages.c:1382
#16 0x00007fa9433eb053 in g_log (log_domain=<optimized out>, log_level=<optimized out>, format=<optimized out>) at ../../../glib/gmessages.c:1451
#17 0x000055c84b300860 in xdp_fuse_getattr ()
#18 0x00007fa943363308 in do_getattr (req=<optimized out>, nodeid=<optimized out>, inarg=<optimized out>) at ./lib/fuse_lowlevel.c:1045
#19 0x00007fa94336369c in fuse_ll_process_buf (data=0x618000000080, buf=0x7fa93c9f8cc0, ch=<optimized out>) at ./lib/fuse_lowlevel.c:2443
#20 0x00007fa94336021d in fuse_do_work (data=0x60400000a1d0) at ./lib/fuse_loop_mt.c:117
#21 0x00007fa9431ba927 in start_thread (arg=<optimized out>) at pthread_create.c:435
#22 0x00007fa94324a9e4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
Thread 6 (Thread 0x7fa93d1fa640 (LWP 12286) "fuse mainloop"):
#0 futex_wait (private=0, expected=2, futex_word=0x7fa94333d730 <_IO_stdfile_1_lock>) at ../sysdeps/nptl/futex-internal.h:146
#1 __GI___lll_lock_wait_private (futex=0x7fa94333d730 <_IO_stdfile_1_lock>) at lowlevellock.c:35
#2 0x00007fa94319cddc in __vfprintf_internal (s=0x7fa94333b760 <_IO_2_1_stdout_>, format=0x7fa943446b44 "%s\n", ap=0x7fa93d1f9750, mode_flags=0) at vfprintf-internal.c:1401
#3 0x00007fa943778890 in __interceptor_vfprintf(__sanitizer::__sanitizer_FILE *, const char *, typedef __va_list_tag __va_list_tag *) (stream=0x7fa94333b760 <_IO_2_1_stdout_>, format=<optimized out>, ap=0x7fa93d1f9750) at ../../../../src/libsanitizer/sanitizer_common/sanitizer_common_interceptors.inc:1664
#4 0x00007fa943778adf in __interceptor___fprintf_chk(__sanitizer::__sanitizer_FILE*, SIZE_T, char const*, ...) (stream=stream@entry=0x7fa94333b760 <_IO_2_1_stdout_>, size=size@entry=1, format=format@entry=0x7fa943446b44 "%s\n") a--Type <RET> for more, q to quit, c to continue without paging--
t ../../../../src/libsanitizer/sanitizer_common/sanitizer_common_interceptors.inc:1726
#5 0x00007fa9433ed6f9 in fprintf (__fmt=0x7fa943446b44 "%s\n", __stream=0x7fa94333b760 <_IO_2_1_stdout_>) at /usr/include/x86_64-linux-gnu/bits/stdio2.h:105
#6 g_log_writer_standard_streams (log_level=log_level@entry=G_LOG_LEVEL_DEBUG, fields=fields@entry=0x7fa93d1f98e0, n_fields=n_fields@entry=4, user_data=user_data@entry=0x0) at ../../../glib/gmessages.c:2600
#7 0x00007fa9433ed818 in g_log_writer_default (log_level=G_LOG_LEVEL_DEBUG, fields=0x7fa93d1f98e0, n_fields=4, user_data=0x0) at ../../../glib/gmessages.c:2781
#8 0x00007fa9433e9633 in g_log_structured_array (n_fields=4, fields=0x7fa93d1f98e0, log_level=G_LOG_LEVEL_DEBUG) at ../../../glib/gmessages.c:1964
#9 g_log_structured_array (log_level=G_LOG_LEVEL_DEBUG, fields=0x7fa93d1f98e0, n_fields=4) at ../../../glib/gmessages.c:1937
#10 0x00007fa9433e9939 in g_log_default_handler (log_domain=log_domain@entry=0x55c84b346aa0 "xdg-desktop-portal", log_level=log_level@entry=G_LOG_LEVEL_DEBUG, message=message@entry=0x602000045390 "FORGET_MULTI 2", unused_data=unused_data@entry=0x0) at ../../../glib/gmessages.c:3236
#11 0x00007fa9433ead6a in g_logv (log_domain=0x55c84b346aa0 "xdg-desktop-portal", log_level=G_LOG_LEVEL_DEBUG, format=<optimized out>, args=<optimized out>) at ../../../glib/gmessages.c:1382
#12 0x00007fa9433eb053 in g_log (log_domain=<optimized out>, log_level=<optimized out>, format=<optimized out>) at ../../../glib/gmessages.c:1451
#13 0x000055c84b306ebc in xdp_fuse_forget_multi ()
#14 0x00007fa94336369c in fuse_ll_process_buf (data=0x618000000080, buf=0x7fa93d1f9cc0, ch=<optimized out>) at ./lib/fuse_lowlevel.c:2443
#15 0x00007fa94336029d in fuse_do_work (data=0x60400000a010) at ./lib/fuse_loop_mt.c:117
#16 0x00007fa9431ba927 in start_thread (arg=<optimized out>) at pthread_create.c:435
#17 0x00007fa94324a9e4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
Thread 5 (Thread 0x7fa93d9fb640 (LWP 12285) "fuse mainloop"):
#0 futex_wait (private=0, expected=2, futex_word=0x7fa94333d730 <_IO_stdfile_1_lock>) at ../sysdeps/nptl/futex-internal.h:146
#1 __GI___lll_lock_wait_private (futex=0x7fa94333d730 <_IO_stdfile_1_lock>) at lowlevellock.c:35
#2 0x00007fa94319cddc in __vfprintf_internal (s=0x7fa94333b760 <_IO_2_1_stdout_>, format=0x7fa943446b44 "%s\n", ap=0x7fa93d9fa750, mode_flags=0) at vfprintf-internal.c:1401
#3 0x00007fa943778890 in __interceptor_vfprintf(__sanitizer::__sanitizer_FILE *, const char *, typedef __va_list_tag __va_list_tag *) (stream=0x7fa94333b760 <_IO_2_1_stdout_>, format=<optimized out>, ap=0x7fa93d9fa750) at ../../../../src/libsanitizer/sanitizer_common/sanitizer_common_interceptors.inc:1664
#4 0x00007fa943778adf in __interceptor___fprintf_chk(__sanitizer::__sanitizer_FILE*, SIZE_T, char const*, ...) (stream=stream@entry=0x7fa94333b760 <_IO_2_1_stdout_>, size=size@entry=1, format=format@entry=0x7fa943446b44 "%s\n") at ../../../../src/libsanitizer/sanitizer_common/sanitizer_common_interceptors.inc:1726
#5 0x00007fa9433ed6f9 in fprintf (__fmt=0x7fa943446b44 "%s\n", __stream=0x7fa94333b760 <_IO_2_1_stdout_>) at /usr/include/x86_64-linux-gnu/bits/stdio2.h:105
#6 g_log_writer_standard_streams (log_level=log_level@entry=G_LOG_LEVEL_DEBUG, fields=fields@entry=0x7fa93d9fa8e0, n_fields=n_fields@entry=4, user_data=user_data@entry=0x0) at ../../../glib/gmessages.c:2600
#7 0x00007fa9433ed818 in g_log_writer_default (log_level=G_LOG_LEVEL_DEBUG, fields=0x7fa93d9fa8e0, n_fields=4, user_data=0x0) at ../../../glib/gmessages.c:2781
#8 0x00007fa9433e9633 in g_log_structured_array (n_fields=4, fields=0x7fa93d9fa8e0, log_level=G_LOG_LEVEL_DEBUG) at ../../../glib/gmessages.c:1964
#9 g_log_structured_array (log_level=G_LOG_LEVEL_DEBUG, fields=0x7fa93d9fa8e0, n_fields=4) at ../../../glib/gmessages.c:1937
#10 0x00007fa9433e9939 in g_log_default_handler (log_domain=log_domain@entry=0x55c84b346aa0 "xdg-desktop-portal", log_level=log_level@entry=G_LOG_LEVEL_DEBUG, message=message@entry=0x602000046270 "FORGET_MULTI 2", unused_data=unused_data@entry=0x0) at ../../../glib/gmessages.c:3236
#11 0x00007fa9433ead6a in g_logv (log_domain=0x55c84b346aa0 "xdg-desktop-portal", log_level=G_LOG_LEVEL_DEBUG, format=<optimized out>, args=<optimized out>) at ../../../glib/gmessages.c:1382
#12 0x00007fa9433eb053 in g_log (log_domain=<optimized out>, log_level=<optimized out>, format=<optimized out>) at ../../../glib/gmessages.c:1451
#13 0x000055c84b306ebc in xdp_fuse_forget_multi ()
#14 0x00007fa94336369c in fuse_ll_process_buf (data=0x618000000080, buf=0x7fa93d9facc0, ch=<optimized out>) at ./li--Type <RET> for more, q to quit, c to continue without paging--
b/fuse_lowlevel.c:2443
#15 0x00007fa94336029d in fuse_do_work (data=0x604000008010) at ./lib/fuse_loop_mt.c:117
#16 0x00007fa9431ba927 in start_thread (arg=<optimized out>) at pthread_create.c:435
#17 0x00007fa94324a9e4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
Thread 4 (Thread 0x7fa93e1fc640 (LWP 12284) "fuse mainloop"):
#0 __futex_abstimed_wait_common64 (private=128, cancel=true, abstime=0x0, op=265, expected=12285, futex_word=0x7fa93d9fb910) at futex-internal.c:57
#1 __futex_abstimed_wait_common (cancel=true, private=128, abstime=0x0, clockid=0, expected=12285, futex_word=0x7fa93d9fb910) at futex-internal.c:87
#2 __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x7fa93d9fb910, expected=12285, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=128) at futex-internal.c:139
#3 0x00007fa9431bc464 in __pthread_clockjoin_ex (threadid=140364860077632, thread_return=0x0, clockid=0, abstime=0x0, block=<optimized out>) at pthread_join_common.c:105
#4 0x00007fa9433604cb in fuse_join_worker (w=0x604000008010, mt=0x7fa93e1fbb50) at ./lib/fuse_loop_mt.c:211
#5 fuse_session_loop_mt (se=0x607000007330) at ./lib/fuse_loop_mt.c:251
#6 0x000055c84b30f860 in xdp_fuse_mainloop ()
#7 0x00007fa943410a81 in g_thread_proxy (data=0x61d00000af60) at ../../../glib/gthread.c:826
#8 0x00007fa9431ba927 in start_thread (arg=<optimized out>) at pthread_create.c:435
#9 0x00007fa94324a9e4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
Thread 3 (Thread 0x7fa93f1fe640 (LWP 12276) "gdbus"):
#0 0x00007fa94323dcdf in __GI___poll (fds=0x6020000050f0, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1 0x00007fa94377ae30 in __interceptor_poll(__sanitizer::__sanitizer_pollfd*, __sanitizer::__sanitizer_nfds_t, int) (fds=0x6020000050f0, nfds=1, timeout=-1) at ../../../../src/libsanitizer/sanitizer_common/sanitizer_common_interceptors.inc:3961
#2 0x00007fa943435ea6 in g_main_context_poll (priority=<optimized out>, n_fds=1, fds=0x6020000050f0, timeout=<optimized out>, context=0x60f0000004f0) at ../../../glib/gmain.c:4434
#3 g_main_context_iterate.constprop.0 (context=0x60f0000004f0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../../../glib/gmain.c:4126
#4 0x00007fa9433e1e43 in g_main_loop_run (loop=0x602000004310) at ../../../glib/gmain.c:4329
#5 0x00007fa94362e12a in gdbus_shared_thread_func (user_data=0x6030000041b0) at ../../../gio/gdbusprivate.c:280
#6 0x00007fa943410a81 in g_thread_proxy (data=0x61d000007c60) at ../../../glib/gthread.c:826
#7 0x00007fa9431ba927 in start_thread (arg=<optimized out>) at pthread_create.c:435
#8 0x00007fa94324a9e4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
Thread 2 (Thread 0x7fa93f9ff640 (LWP 12275) "gmain"):
#0 0x00007fa94323dcdf in __GI___poll (fds=0x602000002030, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1 0x00007fa94377ae30 in __interceptor_poll(__sanitizer::__sanitizer_pollfd*, __sanitizer::__sanitizer_nfds_t, int) (fds=0x602000002030, nfds=1, timeout=-1) at ../../../../src/libsanitizer/sanitizer_common/sanitizer_common_interceptors.inc:3961
#2 0x00007fa943435ea6 in g_main_context_poll (priority=<optimized out>, n_fds=1, fds=0x602000002030, timeout=<optimized out>, context=0x60f000000310) at ../../../glib/gmain.c:4434
#3 g_main_context_iterate.constprop.0 (context=context@entry=0x60f000000310, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../../../glib/gmain.c:4126
#4 0x00007fa9433e0003 in g_main_context_iteration (context=0x60f000000310, may_block=may_block@entry=1) at ../../../glib/gmain.c:4196
#5 0x00007fa9433e0051 in glib_worker_main (data=<optimized out>) at ../../../glib/gmain.c:6089
#6 0x00007fa943410a81 in g_thread_proxy (data=0x61d000001980) at ../../../glib/gthread.c:826
#7 0x00007fa9431ba927 in start_thread (arg=<optimized out>) at pthread_create.c:435
#8 0x00007fa94324a9e4 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100
Thread 1 (Thread 0x7fa942e37880 (LWP 12274) "xdg-document-po"):
#0 __futex_abstimed_wait_common64 (private=128, cancel=true, abstime=0x0, op=265, expected=12284, futex_word=0x7fa--Type <RET> for more, q to quit, c to continue without paging--
93e1fc910) at futex-internal.c:57
#1 __futex_abstimed_wait_common (cancel=true, private=128, abstime=0x0, clockid=0, expected=12284, futex_word=0x7fa93e1fc910) at futex-internal.c:87
#2 __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x7fa93e1fc910, expected=12284, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=128) at futex-internal.c:139
#3 0x00007fa9431bc464 in __pthread_clockjoin_ex (threadid=140364868470336, thread_return=0x0, clockid=0, abstime=0x0, block=<optimized out>) at pthread_join_common.c:105
#4 0x00007fa943411e4c in g_system_thread_wait (thread=0x61d00000af60) at ../../../glib/gthread-posix.c:1368
#5 g_thread_join (thread=0x61d00000af60) at ../../../glib/gthread.c:1006
#6 0x000055c84b31058c in xdp_fuse_exit ()
#7 0x000055c84b2f21f5 in main ()
So ideally dbus-daemon
must be fork'ed (but this is not supported in windows) or another fd other than stdout should be used for getting the address.