Hang when cancelling a message
Submitted by Ross Lagerwall
Assigned to David Zeuthen
Link to original bug (#747419)
Description
Created attachment 301028 program to reproduce the problem
Occasionally, gvfs hits a hang with cancellation and gdbus, where send_message_with_reply_cleanup() calls g_cancellable_disconnect() with the connection lock held. g_cancellable_disconnect() blocks waiting for another thread which is blocked waiting for the connection lock...
Note that this bug existed before gdbus was ported to GTask.
Thread 2 (Thread 0x7fe07b0c3700 (LWP 9171)):
#0 0x00007fe07d296f89 in syscall () from /usr/lib/libc.so.6
#1 0x00007fe07d81b63b in g_cond_wait (cond=0x7fe07e0ec0d0 <cancellable_cond>, mutex=0x7fe07e0ec0c0 <cancellable_mutex>) at gthread-posix.c:1395
#2 0x00007fe07dd6492e in g_cancellable_disconnect (cancellable=0x7fe06c00a0a0, handler_id=744542) at gcancellable.c:632
#3 0x00007fe07de2fafe in send_message_with_reply_cleanup (task=0x2657860, remove=1) at gdbusconnection.c:1790
#4 0x00007fe07de2fbd6 in send_message_data_deliver_reply_unlocked (task=0x2657860, reply=0x7fe06c004400) at gdbusconnection.c:1818
#5 0x00007fe07de30759 in on_worker_message_received (worker=0x7fe070003400, message=0x7fe06c004400, user_data=0x260f160) at gdbusconnection.c:2267
#6 0x00007fe07de48c4c in _g_dbus_worker_emit_message_received (worker=0x7fe070003400, message=0x7fe06c004400) at gdbusprivate.c:456
#7 0x00007fe07de48cf8 in _g_dbus_worker_queue_or_deliver_received_message (worker=0x7fe070003400, message=0x7fe06c004400) at gdbusprivate.c:484
#8 0x00007fe07de4969b in _g_dbus_worker_do_read_cb (input_stream=0x2614670, res=0x7fe06c003100, user_data=0x7fe070003400) at gdbusprivate.c:769
#9 0x00007fe07ddcc351 in g_task_return_now (task=0x7fe06c003100) at gtask.c:1106
#10 0x00007fe07ddcc3ad in complete_in_idle_cb (task=0x7fe06c003100) at gtask.c:1120
#11 0x00007fe07d7c8f82 in g_idle_dispatch (source=0x7fe06c02dcb0, callback=0x7fe07ddcc395 <complete_in_idle_cb>, user_data=0x7fe06c003100) at gmain.c:5397
#12 0x00007fe07d7c65ec in g_main_dispatch (context=0x261b530) at gmain.c:3122
#13 0x00007fe07d7c741a in g_main_context_dispatch (context=0x261b530) at gmain.c:3737
#14 0x00007fe07d7c75ff in g_main_context_iterate (context=0x261b530, block=1, dispatch=1, self=0x261a4a0) at gmain.c:3808
#15 0x00007fe07d7c7a26 in g_main_loop_run (loop=0x2618360) at gmain.c:4002
#16 0x00007fe07de48922 in gdbus_shared_thread_func (user_data=0x26183a0) at gdbusprivate.c:246
#17 0x00007fe07d7f5382 in g_thread_proxy (data=0x261a4a0) at gthread.c:764
#18 0x00007fe07d55d374 in start_thread () from /usr/lib/libpthread.so.0
#19 0x00007fe07d29b27d in clone () from /usr/lib/libc.so.6
Thread 1 (Thread 0x7fe07e2dc700 (LWP 9169)):
#0 0x00007fe07d296f89 in syscall () from /usr/lib/libc.so.6
#1 0x00007fe07d81b4c3 in g_mutex_lock_slowpath (mutex=0x260f178) at gthread-posix.c:1313
#2 0x00007fe07d81b564 in g_mutex_lock (mutex=0x260f178) at gthread-posix.c:1337
#3 0x00007fe07de3275e in g_dbus_connection_signal_subscribe (connection=0x260f160, sender=0x0, interface_name=0x7fe07dea7a18 "org.freedesktop.DBus.Properties", member=0x7fe07dea7b8f "PropertiesChanged",
object_path=0x2658430 "/org/gtk/vfs/Daemon", arg0=0x2658560 "org.gtk.vfs.Daemon", flags=G_DBUS_SIGNAL_FLAGS_NONE, callback=0x7fe07de448ed <on_properties_changed>, user_data=0x261b230,
user_data_free_func=0x7fe07de43184 <signal_subscription_unref>) at gdbusconnection.c:3405
#4 0x00007fe07de45d2d in async_initable_init_first (initable=0x260aa90) at gdbusproxy.c:1739
#5 0x00007fe07de460d6 in async_initable_init_async (initable=0x260aa90, io_priority=0, cancellable=0x0, callback=0x7fe07c55c312 <cancelled_got_proxy>, user_data=0x7f206) at gdbusproxy.c:1861
#6 0x00007fe07dd5ef09 in g_async_initable_init_async (initable=0x260aa90, io_priority=0, cancellable=0x0, callback=0x7fe07c55c312 <cancelled_got_proxy>, user_data=0x7f206) at gasyncinitable.c:213
#7 0x00007fe07dd5f509 in g_async_initable_new_valist_async (object_type=39873840, first_property_name=0x7fe07c32b812 "g-flags", var_args=0x7ffd6904a028, io_priority=0, cancellable=0x0,
callback=0x7fe07c55c312 <cancelled_got_proxy>, user_data=0x7f206) at gasyncinitable.c:425
#8 0x00007fe07dd5f3c2 in g_async_initable_new_async (object_type=39873840, io_priority=0, cancellable=0x0, callback=0x7fe07c55c312 <cancelled_got_proxy>, user_data=0x7f206,
first_property_name=0x7fe07c32b812 "g-flags") at gasyncinitable.c:339
#9 0x00007fe07c315164 in gvfs_dbus_daemon_proxy_new (connection=0x260f160, flags=G_DBUS_PROXY_FLAGS_NONE, name=0x0, object_path=0x7fe07c56b7a4 "/org/gtk/vfs/Daemon", cancellable=0x0,
callback=0x7fe07c55c312 <cancelled_got_proxy>, user_data=0x7f206) at gvfsdbus.c:1201
#10 0x00007fe07c55c41f in async_call_cancelled_cb (cancellable=0x7fe06c00a0a0, _data=0x2656870) at gvfsdaemondbus.c:376
#11 0x00007fe07dae72ed in g_cclosure_marshal_VOID__VOID (closure=0x2649660, return_value=0x0, n_param_values=1, param_values=0x7ffd6904a400, invocation_hint=0x7ffd6904a340, marshal_data=0x0) at gmarshal.c:875
---Type <return> to continue, or q <return> to quit---
#12 0x00007fe07dae4348 in g_closure_invoke (closure=0x2649660, return_value=0x0, n_param_values=1, param_values=0x7ffd6904a400, invocation_hint=0x7ffd6904a340) at gclosure.c:801
#13 0x00007fe07db00f35 in signal_emit_unlocked_R (node=0x2617c60, detail=0, instance=0x7fe06c00a0a0, emission_return=0x0, instance_and_params=0x7ffd6904a400) at gsignal.c:3549
#14 0x00007fe07db00288 in g_signal_emit_valist (instance=0x7fe06c00a0a0, signal_id=10, detail=0, var_args=0x7ffd6904a6b8) at gsignal.c:3305
#15 0x00007fe07db007c5 in g_signal_emit (instance=0x7fe06c00a0a0, signal_id=10, detail=0) at gsignal.c:3361
#16 0x00007fe07dd6473a in g_cancellable_cancel (cancellable=0x7fe06c00a0a0) at gcancellable.c:508
#17 0x0000000000400fb1 in cancel_func (data=0x0) at cancel.c:12
#18 0x00007fe07d7c83da in g_timeout_dispatch (source=0x264fb90, callback=0x400f96 <cancel_func>, user_data=0x0) at gmain.c:4545
#19 0x00007fe07d7c65ec in g_main_dispatch (context=0x25f4d50) at gmain.c:3122
#20 0x00007fe07d7c741a in g_main_context_dispatch (context=0x25f4d50) at gmain.c:3737
#21 0x00007fe07d7c75ff in g_main_context_iterate (context=0x25f4d50, block=1, dispatch=1, self=0x25ffc70) at gmain.c:3808
#22 0x00007fe07d7c7a26 in g_main_loop_run (loop=0x25f4e90) at gmain.c:4002
#23 0x000000000040145b in main (argc=2, argv=0x7ffd6904aa58) at cancel.c:134
Attached is a reproducer which typically hits the bug after about 10000 iterations for me. Run like: ./cancel sftp://ross@192.168.1.48/usr/bin
Attachment 301028, "program to reproduce the problem":
cancel.c
Version: 2.44.x