Bug#884654: glib2.0: FTBFS on amd64 buildd: gdbus-peer test: assertion 'source->ref_count > 0' failed

Mon Dec 18 18:18:41 UTC 2017

Control: tags -1 + confirmed

On Mon, 18 Dec 2017 at 09:17:46 +0000, Simon McVittie wrote:
> The failure on the buildd is new, although I think I might have seen it
> before in local testing (but never reproducibly). It's probably some
> rarely-hit race condition?

I can reproduce this by running the gdbus-peer test in a loop (this is
with GLib git master, not Debian's GLib, but that's close enough). I'm
not convinced it's RC, but I'll leave it at serious severity for now.

(gdb) thread apply all bt

Thread 7 (Thread 0x7f4576854700 (LWP 19643)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f457aa3cadd in g_cond_wait_until (cond=cond at entry=0x5617ef3f0be8, mutex=mutex at entry=0x5617ef3f0be0, end_time=end_time at entry=280830465587) at /home/smcv/src/glib/glib/gthread-posix.c:1449
#2  0x00007f457a9c9a8e in g_async_queue_pop_intern_unlocked (queue=queue at entry=0x5617ef3f0be0, wait=wait at entry=1, end_time=280830465587) at /home/smcv/src/glib/glib/gasyncqueue.c:422
#3  0x00007f457a9ca119 in g_async_queue_timeout_pop_unlocked (queue=0x5617ef3f0be0, timeout=timeout at entry=500000) at /home/smcv/src/glib/glib/gasyncqueue.c:570
#4  0x00007f457aa1ef01 in g_thread_pool_wait_for_new_task (pool=pool at entry=0x5617ef4072a0) at /home/smcv/src/glib/glib/gthreadpool.c:262
#5  0x00007f457aa1f10b in g_thread_pool_thread_proxy (data=<optimized out>) at /home/smcv/src/glib/glib/gthreadpool.c:296
#6  0x00007f457aa1e5fd in g_thread_proxy (data=0x5617ef3f8d40) at /home/smcv/src/glib/glib/gthread.c:784
#7  0x00007f457a51a519 in start_thread (arg=0x7f4576854700) at pthread_create.c:456
#8  0x00007f45799afa4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Thread 6 (Thread 0x7f4578a6a700 (LWP 19641)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f457aa3c9ce in g_cond_wait (cond=cond at entry=0x7f457b8dd2b0 <cancellable_cond>, mutex=mutex at entry=0x7f457b8dd2c0 <cancellable_mutex>) at /home/smcv/src/glib/glib/gthread-posix.c:1402
#2  0x00007f457b574975 in g_cancellable_disconnect (cancellable=0x5617ef3fca80, handler_id=59) at /home/smcv/src/glib/gio/gcancellable.c:632
#3  0x00007f457b5749ae in cancellable_source_finalize (source=0x5617ef407e00) at /home/smcv/src/glib/gio/gcancellable.c:675
#4  0x00007f457a9f3af9 in g_source_unref_internal (source=source at entry=0x5617ef407e00, context=context at entry=0x5617ef3f2000, have_lock=have_lock at entry=1) at /home/smcv/src/glib/glib/gmain.c:2119
#5  0x00007f457a9f3ef3 in g_child_source_remove_internal (child_source=0x5617ef407e00, context=context at entry=0x5617ef3f2000) at /home/smcv/src/glib/glib/gmain.c:1510
#6  0x00007f457a9f3e5b in g_source_destroy_internal (source=0x5617ef4082f0, context=0x5617ef3f2000, have_lock=have_lock at entry=0) at /home/smcv/src/glib/glib/gmain.c:1273
#7  0x00007f457a9f4e79 in g_source_destroy (source=source at entry=0x5617ef4082f0) at /home/smcv/src/glib/glib/gmain.c:1304
#8  0x00007f457b5bf1b7 in free_sources (sources=0x0) at /home/smcv/src/glib/gio/gsocketlistener.c:616
#9  0x00007f457b5c6003 in g_task_finalize (object=0x5617ef3e80e0) at /home/smcv/src/glib/gio/gtask.c:641
#10 0x00007f457b2ea752 in g_object_unref (_object=_object at entry=0x5617ef3e80e0) at /home/smcv/src/glib/gobject/gobject.c:3338
#11 0x00007f457b5bf308 in accept_ready (accept_socket=<optimized out>, condition=<optimized out>, user_data=0x5617ef3e80e0) at /home/smcv/src/glib/gio/gsocketlistener.c:786
#12 0x00007f457b5b6bd5 in socket_source_dispatch (source=source at entry=0x5617ef4082f0, callback=0x7f457b5bf259 <accept_ready>, user_data=0x5617ef3e80e0) at /home/smcv/src/glib/gio/gsocket.c:3818
#13 0x00007f457a9f459c in g_main_dispatch (context=context at entry=0x5617ef3f2000) at /home/smcv/src/glib/glib/gmain.c:3183
#14 0x00007f457a9f6de0 in g_main_context_dispatch (context=context at entry=0x5617ef3f2000) at /home/smcv/src/glib/glib/gmain.c:3848
#15 0x00007f457a9f6f39 in g_main_context_iterate (context=0x5617ef3f2000, block=block at entry=1, dispatch=dispatch at entry=1, self=self at entry=0x5617ef3f8b70) at /home/smcv/src/glib/glib/gmain.c:3921
#16 0x00007f457a9f72d8 in g_main_loop_run (loop=0x5617ef3f0b40) at /home/smcv/src/glib/glib/gmain.c:4117
#17 0x00005617edf15430 in run_service_loop (service_context=0x5617ef3f2000) at /home/smcv/src/glib/gio/tests/gdbus-peer.c:365
#18 0x00005617edf16b72 in nonce_tcp_service_thread_func (user_data=0x7fff9d4ed060) at /home/smcv/src/glib/gio/tests/gdbus-peer.c:1235
#19 0x00007f457aa1e5fd in g_thread_proxy (data=0x5617ef3f8b70) at /home/smcv/src/glib/glib/gthread.c:784
#20 0x00007f457a51a519 in start_thread (arg=0x7f4578a6a700) at pthread_create.c:456
#21 0x00007f45799afa4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Thread 5 (Thread 0x7f4577267700 (LWP 19642)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f457aa3cadd in g_cond_wait_until (cond=cond at entry=0x5617ef3ce578, mutex=mutex at entry=0x5617ef3ce570, end_time=end_time at entry=280830465124) at /home/smcv/src/glib/glib/gthread-posix.c:1449
#2  0x00007f457a9c9a8e in g_async_queue_pop_intern_unlocked (queue=queue at entry=0x5617ef3ce570, wait=wait at entry=1, end_time=280830465124) at /home/smcv/src/glib/glib/gasyncqueue.c:422
#3  0x00007f457a9ca119 in g_async_queue_timeout_pop_unlocked (queue=0x5617ef3ce570, timeout=timeout at entry=500000) at /home/smcv/src/glib/glib/gasyncqueue.c:570
#4  0x00007f457aa1ef01 in g_thread_pool_wait_for_new_task (pool=pool at entry=0x5617ef3d2800) at /home/smcv/src/glib/glib/gthreadpool.c:262
#5  0x00007f457aa1f10b in g_thread_pool_thread_proxy (data=<optimized out>) at /home/smcv/src/glib/glib/gthreadpool.c:296
#6  0x00007f457aa1e5fd in g_thread_proxy (data=0x5617ef3f8de0) at /home/smcv/src/glib/glib/gthread.c:784
#7  0x00007f457a51a519 in start_thread (arg=0x7f4577267700) at pthread_create.c:456
#8  0x00007f45799afa4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Thread 4 (Thread 0x7f4577a68700 (LWP 19639)):
#0  0x00007f45799a5a5d in poll () at ../sysdeps/unix/syscall-template.S:84
#1  0x00007f457aa06ddc in g_poll (fds=fds at entry=0x5617ef3f0bb0, nfds=nfds at entry=1, timeout=timeout at entry=-1) at /home/smcv/src/glib/glib/gpoll.c:124
#2  0x00007f457a9f46e3 in g_main_context_poll (context=context at entry=0x5617ef3f0800, timeout=-1, priority=<optimized out>, fds=fds at entry=0x5617ef3f0bb0, n_fds=n_fds at entry=1) at /home/smcv/src/glib/glib/gmain.c:4222
#3  0x00007f457a9f6ef6 in g_main_context_iterate (context=0x5617ef3f0800, block=block at entry=1, dispatch=dispatch at entry=1, self=self at entry=0x5617ef3d2cf0) at /home/smcv/src/glib/glib/gmain.c:3916
#4  0x00007f457a9f72d8 in g_main_loop_run (loop=0x5617ef3f2120) at /home/smcv/src/glib/glib/gmain.c:4117
#5  0x00007f457b60be61 in gdbus_shared_thread_func (user_data=0x5617ef3f2160) at /home/smcv/src/glib/gio/gdbusprivate.c:275
#6  0x00007f457aa1e5fd in g_thread_proxy (data=0x5617ef3d2cf0) at /home/smcv/src/glib/glib/gthread.c:784
#7  0x00007f457a51a519 in start_thread (arg=0x7f4577a68700) at pthread_create.c:456
#8  0x00007f45799afa4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Thread 3 (Thread 0x7f4578269700 (LWP 19638)):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x00007f457aa3cadd in g_cond_wait_until (cond=cond at entry=0x5617ef3edf08, mutex=mutex at entry=0x5617ef3edf00, end_time=end_time at entry=280830358684) at /home/smcv/src/glib/glib/gthread-posix.c:1449
#2  0x00007f457a9c9a8e in g_async_queue_pop_intern_unlocked (queue=queue at entry=0x5617ef3edf00, wait=wait at entry=1, end_time=280830358684) at /home/smcv/src/glib/glib/gasyncqueue.c:422
#3  0x00007f457a9ca119 in g_async_queue_timeout_pop_unlocked (queue=0x5617ef3edf00, timeout=timeout at entry=500000) at /home/smcv/src/glib/glib/gasyncqueue.c:570
#4  0x00007f457aa1ef01 in g_thread_pool_wait_for_new_task (pool=pool at entry=0x5617ef3e6720) at /home/smcv/src/glib/glib/gthreadpool.c:262
#5  0x00007f457aa1f10b in g_thread_pool_thread_proxy (data=<optimized out>) at /home/smcv/src/glib/glib/gthreadpool.c:296
#6  0x00007f457aa1e5fd in g_thread_proxy (data=0x5617ef3d3280) at /home/smcv/src/glib/glib/gthread.c:784
#7  0x00007f457a51a519 in start_thread (arg=0x7f4578269700) at pthread_create.c:456
#8  0x00007f45799afa4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Thread 2 (Thread 0x7f457926b700 (LWP 19635)):
#0  0x00007f45799a5a5d in poll () at ../sysdeps/unix/syscall-template.S:84
#1  0x00007f457aa06ddc in g_poll (fds=fds at entry=0x5617ef3d26f0, nfds=nfds at entry=1, timeout=timeout at entry=-1) at /home/smcv/src/glib/glib/gpoll.c:124
#2  0x00007f457a9f46e3 in g_main_context_poll (context=context at entry=0x5617ef3d2960, timeout=-1, priority=<optimized out>, fds=fds at entry=0x5617ef3d26f0, n_fds=n_fds at entry=1) at /home/smcv/src/glib/glib/gmain.c:4222
#3  0x00007f457a9f6ef6 in g_main_context_iterate (context=context at entry=0x5617ef3d2960, block=block at entry=1, dispatch=dispatch at entry=1, self=<optimized out>) at /home/smcv/src/glib/glib/gmain.c:3916
#4  0x00007f457a9f6fb7 in g_main_context_iteration (context=0x5617ef3d2960, may_block=may_block at entry=1) at /home/smcv/src/glib/glib/gmain.c:3982
#5  0x00007f457a9f6fe9 in glib_worker_main (data=<optimized out>) at /home/smcv/src/glib/glib/gmain.c:5791
#6  0x00007f457aa1e5fd in g_thread_proxy (data=0x5617ef3d2c00) at /home/smcv/src/glib/glib/gthread.c:784
#7  0x00007f457a51a519 in start_thread (arg=0x7f457926b700) at pthread_create.c:456
#8  0x00007f45799afa4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

Thread 1 (Thread 0x7f457baba840 (LWP 19620)):
#0  _g_log_abort (breakpoint=breakpoint at entry=1) at /home/smcv/src/glib/glib/gmessages.c:583
#1  0x00007f457a9fde07 in g_logv (log_domain=0x7f457aa3f40e "GLib", log_level=G_LOG_LEVEL_CRITICAL, format=<optimized out>, args=args at entry=0x7fff9d4ecaa8) at /home/smcv/src/glib/glib/gmessages.c:1391
#2  0x00007f457a9fdff3 in g_log (log_domain=log_domain at entry=0x7f457aa3f40e "GLib", log_level=log_level at entry=G_LOG_LEVEL_CRITICAL, format=format at entry=0x7f457aa49398 "%s: assertion '%s' failed") at /home/smcv/src/glib/glib/gmessages.c:1432
#3  0x00007f457a9fe3e9 in g_return_if_fail_warning (log_domain=log_domain at entry=0x7f457aa3f40e "GLib", pretty_function=pretty_function at entry=0x7f457aa47a70 <__func__.12136> "g_source_set_ready_time", expression=expression at entry=0x7f457aa4749e "source->ref_count > 0") at /home/smcv/src/glib/glib/gmessages.c:2752
#4  0x00007f457a9f5663 in g_source_set_ready_time (source=0x5617ef407e00, ready_time=ready_time at entry=0) at /home/smcv/src/glib/glib/gmain.c:1845
#5  0x00007f457b5740ee in cancellable_source_cancelled (cancellable=cancellable at entry=0x5617ef3fca80, user_data=<optimized out>) at /home/smcv/src/glib/gio/gcancellable.c:653
#6  0x00007f457b2e77d9 in g_cclosure_marshal_VOID__VOID (closure=0x5617ef407220, return_value=<optimized out>, n_param_values=<optimized out>, param_values=<optimized out>, invocation_hint=<optimized out>, marshal_data=<optimized out>) at /home/smcv/src/glib/gobject/gmarshal.c:875
#7  0x00007f457b2e59ba in g_closure_invoke (closure=0x5617ef407220, return_value=return_value at entry=0x0, n_param_values=1, param_values=param_values at entry=0x7fff9d4ecd90, invocation_hint=invocation_hint at entry=0x7fff9d4ecd30) at /home/smcv/src/glib/gobject/gclosure.c:804
#8  0x00007f457b2f9a6f in signal_emit_unlocked_R (node=node at entry=0x5617ef3e6d50, detail=detail at entry=0, instance=instance at entry=0x5617ef3fca80, emission_return=emission_return at entry=0x0, instance_and_params=instance_and_params at entry=0x7fff9d4ecd90) at /home/smcv/src/glib/gobject/gsignal.c:3635
#9  0x00007f457b3029d0 in g_signal_emit_valist (instance=0x5617ef3fca80, signal_id=<optimized out>, detail=0, var_args=var_args at entry=0x7fff9d4ecf08) at /home/smcv/src/glib/gobject/gsignal.c:3391
#10 0x00007f457b302c24 in g_signal_emit (instance=instance at entry=0x5617ef3fca80, signal_id=<optimized out>, detail=detail at entry=0) at /home/smcv/src/glib/gobject/gsignal.c:3447
#11 0x00007f457b5747da in g_cancellable_cancel (cancellable=0x5617ef3fca80) at /home/smcv/src/glib/gio/gcancellable.c:508
#12 0x00007f457b5c43d1 in set_active (service=service at entry=0x5617ef3f9d50, active=active at entry=0) at /home/smcv/src/glib/gio/gsocketservice.c:163
#13 0x00007f457b5c48a5 in g_socket_service_stop (service=0x5617ef3f9d50) at /home/smcv/src/glib/gio/gsocketservice.c:299
#14 0x00007f457b61343c in g_dbus_server_stop (server=0x5617ef3e4810) at /home/smcv/src/glib/gio/gdbusserver.c:613
#15 0x00005617edf16784 in test_nonce_tcp () at /home/smcv/src/glib/gio/tests/gdbus-peer.c:1355
#16 0x00007f457aa1d26e in test_case_run (tc=tc at entry=0x5617ef3d0660) at /home/smcv/src/glib/glib/gtestutils.c:2255
#17 0x00007f457aa1d47f in g_test_run_suite_internal (suite=suite at entry=0x5617ef3ceae0, path=path at entry=0x0) at /home/smcv/src/glib/glib/gtestutils.c:2339
#18 0x00007f457aa1d49a in g_test_run_suite_internal (suite=suite at entry=0x5617ef3ceb40, path=path at entry=0x0) at /home/smcv/src/glib/glib/gtestutils.c:2351
#19 0x00007f457aa1d5ee in g_test_run_suite (suite=0x5617ef3ceb40) at /home/smcv/src/glib/glib/gtestutils.c:2426
#20 0x00007f457aa1d603 in g_test_run () at /home/smcv/src/glib/glib/gtestutils.c:1692
#21 0x00005617edf190f1 in main (argc=<optimized out>, argv=<optimized out>) at /home/smcv/src/glib/gio/tests/gdbus-peer.c:1759

Regards,
    smcv