Happy Eyeballs failure in gsocketclient-slow test
The gsocketclient-slow
test is currently intermittently failing with an assertion failure on maybe 1 in 3 runs:
$ meson test -C /opt/gnome/build/glib/ gsocketclient-slow --repeat 500 --gdb
ninja: Entering directory `/opt/gnome/build/glib'
ninja: no work to do.
Reading symbols from /opt/gnome/build/glib/gio/tests/gsocketclient-slow...done.
(gdb) run
Starting program: /opt/gnome/build/glib/gio/tests/gsocketclient-slow --tap
Missing separate debuginfos, use: dnf debuginfo-install glibc-2.28-26.fc29.x86_64
warning: File "/opt/gnome/build/glib/glib/libglib-2.0.so.0.5903.0-gdb.py" auto-loading has been declined by your `auto-load safe-path' set to "$debugdir:$datadir/auto-load".
To enable execution of this file add
add-auto-load-safe-path /opt/gnome/build/glib/glib/libglib-2.0.so.0.5903.0-gdb.py
line to your configuration file "/home/philip/.gdbinit".
To completely disable this security protection add
set auto-load safe-path /
line to your configuration file "/home/philip/.gdbinit".
For more information about this security protection see the
"Auto-loading safe path" section in the GDB manual. E.g., run from the shell:
info "(gdb)Auto-loading safe path"
warning: File "/opt/gnome/build/glib/gobject/libgobject-2.0.so.0.5903.0-gdb.py" auto-loading has been declined by your `auto-load safe-path' set to "$debugdir:$datadir/auto-load".
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
warning: Loadable section ".note.gnu.property" outside of ELF segments
warning: Loadable section ".note.gnu.property" outside of ELF segments
warning: Loadable section ".note.gnu.property" outside of ELF segments
# random seed: R02S0d80ed970623f56ab06dff4914030af7
1..2
# Start of socket-client tests
# Start of happy-eyeballs tests
[New Thread 0x7ffff7274700 (LWP 19463)]
# GLib-GIO-DEBUG: _g_io_module_get_default: Found default implementation dummy (GDummyProxyResolver) for ?gio-proxy-resolver?
[New Thread 0x7ffff6a73700 (LWP 19464)]
[New Thread 0x7ffff6272700 (LWP 19465)]
[Thread 0x7ffff6272700 (LWP 19465) exited]
ok 1 /socket-client/happy-eyeballs/slow
[New Thread 0x7ffff6272700 (LWP 19512)]
[Thread 0x7ffff6a73700 (LWP 19464) exited]
# GLib-GIO-DEBUG: IPv4 DNS error: Operation was cancelled
Bail out! GLib-GIO-FATAL-CRITICAL: g_task_return_error_if_cancelled: assertion '!task->ever_returned' failed
(/opt/gnome/build/glib/gio/tests/gsocketclient-slow:19257): GLib-GIO-CRITICAL **: 14:50:42.502: g_task_return_error_if_cancelled: assertion '!task->ever_returned' failed
Thread 1 "gsocketclient-s" received signal SIGTRAP, Trace/breakpoint trap.
0x00007ffff7e5d507 in _g_log_abort (breakpoint=1) at ../../source/glib/glib/gmessages.c:554
554 G_BREAKPOINT ();
Missing separate debuginfos, use: dnf debuginfo-install libblkid-2.32.1-1.fc29.x86_64 libffi-3.1-18.fc29.x86_64 libmount-2.32.1-1.fc29.x86_64 libselinux-2.8-6.fc29.x86_64 libuuid-2.32.1-1.fc29.x86_64 pcre-8.42-6.fc29.x86_64 zlib-1.2.11-14.fc29.x86_64
(gdb) t a a b
Thread 5 (Thread 0x7ffff6272700 (LWP 19512)):
Breakpoint 1 at 0x7ffff7e5d507: file ../../source/glib/glib/gmessages.c, line 554.
Thread 2 (Thread 0x7ffff7274700 (LWP 19463)):
Note: breakpoint 1 also set at pc 0x7ffff7e5d507.
Breakpoint 2 at 0x7ffff7e5d507: file ../../source/glib/glib/gmessages.c, line 554.
Thread 1 (Thread 0x7ffff7276040 (LWP 19257)):
Note: breakpoints 1 and 2 also set at pc 0x7ffff7e5d507.
Breakpoint 3 at 0x7ffff7e5d507: file ../../source/glib/glib/gmessages.c, line 554.
(gdb) d
Delete all breakpoints? (y or n) y
(gdb) t a a bt
Thread 5 (Thread 0x7ffff6272700 (LWP 19512)):
#0 0x00007ffff77d5efd in syscall () from /lib64/libc.so.6
#1 0x00007ffff7ed0494 in g_cond_wait_until (cond=0x40fad8, mutex=0x40fad0, end_time=81898440016) at ../../source/glib/glib/gthread-posix.c:1460
#2 0x00007ffff7e06f74 in g_async_queue_pop_intern_unlocked (queue=0x40fad0, wait=1, end_time=81898440016) at ../../source/glib/glib/gasyncqueue.c:422
#3 0x00007ffff7e072fc in g_async_queue_timeout_pop (queue=0x40fad0, timeout=15000000) at ../../source/glib/glib/gasyncqueue.c:545
#4 0x00007ffff7e95779 in g_thread_pool_wait_for_new_pool () at ../../source/glib/glib/gthreadpool.c:168
#5 0x00007ffff7e95bb3 in g_thread_pool_thread_proxy (data=0x413600) at ../../source/glib/glib/gthreadpool.c:365
#6 0x00007ffff7e95266 in g_thread_proxy (data=0x4226d0) at ../../source/glib/glib/gthread.c:805
#7 0x00007ffff78ae58e in start_thread () from /lib64/libpthread.so.0
#8 0x00007ffff77db6a3 in clone () from /lib64/libc.so.6
Thread 2 (Thread 0x7ffff7274700 (LWP 19463)):
#0 0x00007ffff77d0421 in poll () from /lib64/libc.so.6
#1 0x00007ffff7e6be31 in g_poll (fds=0x423300, nfds=1, timeout=-1) at ../../source/glib/glib/gpoll.c:125
#2 0x00007ffff7e52de5 in g_main_context_poll (context=0x4221b0, timeout=-1, priority=2147483647, fds=0x423300, n_fds=1) at ../../source/glib/glib/gmain.c:4228
#3 0x00007ffff7e52422 in g_main_context_iterate (context=0x4221b0, block=1, dispatch=1, self=0x422400) at ../../source/glib/glib/gmain.c:3922
#4 0x00007ffff7e525b3 in g_main_context_iteration (context=0x4221b0, may_block=1) at ../../source/glib/glib/gmain.c:3988
#5 0x00007ffff7e55081 in glib_worker_main (data=0x0) at ../../source/glib/glib/gmain.c:5868
#6 0x00007ffff7e95266 in g_thread_proxy (data=0x422400) at ../../source/glib/glib/gthread.c:805
#7 0x00007ffff78ae58e in start_thread () from /lib64/libpthread.so.0
#8 0x00007ffff77db6a3 in clone () from /lib64/libc.so.6
Thread 1 (Thread 0x7ffff7276040 (LWP 19257)):
#0 0x00007ffff7e5d507 in _g_log_abort (breakpoint=1) at ../../source/glib/glib/gmessages.c:554
#1 0x00007ffff7e5ec1b in g_logv (log_domain=0x7ffff7b97597 "GLib-GIO", log_level=G_LOG_LEVEL_CRITICAL, format=0x7ffff7ee023d "%s: assertion '%s' failed", args=0x7fffffffc548)
at ../../source/glib/glib/gmessages.c:1371
#2 0x00007ffff7e5ed41 in g_log (log_domain=0x7ffff7b97597 "GLib-GIO", log_level=G_LOG_LEVEL_CRITICAL, format=0x7ffff7ee023d "%s: assertion '%s' failed") at ../../source/glib/glib/gmessages.c:1413
#3 0x00007ffff7e61535 in g_return_if_fail_warning (log_domain=0x7ffff7b97597 "GLib-GIO", pretty_function=0x7ffff7b97a00 <__FUNCTION__.15408> "g_task_return_error_if_cancelled",
expression=0x7ffff7b9762b "!task->ever_returned") at ../../source/glib/glib/gmessages.c:2767
#4 0x00007ffff7a7068d in g_task_return_error_if_cancelled (task=0x423ce0) at ../../source/glib/gio/gtask.c:1908
#5 0x00007ffff7a5c8bb in task_completed_or_cancelled (task=0x423ce0) at ../../source/glib/gio/gsocketclient.c:1552
#6 0x00007ffff7a5d0c5 in g_socket_client_enumerator_callback (object=0x423e20, result=0x42f2f0, user_data=0x422630) at ../../source/glib/gio/gsocketclient.c:1704
#7 0x00007ffff7a6eabd in g_task_return_now (task=0x42f2f0) at ../../source/glib/gio/gtask.c:1202
#8 0x00007ffff7a6eb50 in complete_in_idle_cb (task=0x42f2f0) at ../../source/glib/gio/gtask.c:1216
#9 0x00007ffff7e54bb1 in g_idle_dispatch (source=0x42e970, callback=0x7ffff7a6eb2f <complete_in_idle_cb>, user_data=0x42f2f0) at ../../source/glib/glib/gmain.c:5627
#10 0x00007ffff7e50bb8 in g_main_dispatch (context=0x418fc0) at ../../source/glib/glib/gmain.c:3189
#11 0x00007ffff7e52188 in g_main_context_dispatch (context=0x418fc0) at ../../source/glib/glib/gmain.c:3854
#12 0x00007ffff7e52468 in g_main_context_iterate (context=0x418fc0, block=1, dispatch=1, self=0x418120) at ../../source/glib/glib/gmain.c:3927
#13 0x00007ffff7e52ab0 in g_main_loop_run (loop=0x4190b0) at ../../source/glib/glib/gmain.c:4123
#14 0x0000000000402990 in test_happy_eyeballs_cancel () at ../../source/glib/gio/tests/gsocketclient-slow.c:110
#15 0x00007ffff7e90c01 in test_case_run (tc=0x418030) at ../../source/glib/glib/gtestutils.c:2597
#16 0x00007ffff7e9113e in g_test_run_suite_internal (suite=0x416e60, path=0x0) at ../../source/glib/glib/gtestutils.c:2685
#17 0x00007ffff7e9122f in g_test_run_suite_internal (suite=0x416e40, path=0x0) at ../../source/glib/glib/gtestutils.c:2697
#18 0x00007ffff7e9122f in g_test_run_suite_internal (suite=0x416e20, path=0x0) at ../../source/glib/glib/gtestutils.c:2697
#19 0x00007ffff7e914f1 in g_test_run_suite (suite=0x416e20) at ../../source/glib/glib/gtestutils.c:2772
#20 0x00007ffff7e8f903 in g_test_run () at ../../source/glib/glib/gtestutils.c:2007
#21 0x0000000000402a63 in main (argc=1, argv=0x7fffffffcc08) at ../../source/glib/gio/tests/gsocketclient-slow.c:126
(gdb) frame 4
#4 0x00007ffff7a7068d in g_task_return_error_if_cancelled (task=0x423ce0)
at ../../source/glib/gio/gtask.c:1908
1908 g_return_val_if_fail (!task->ever_returned, FALSE);
(gdb) print *task
$1 = {parent_instance = {g_type_instance = {g_class = 0x423480}, ref_count = 3, qdata = 0x0},
source_object = 0x40aa80, source_tag = 0x7ffff7a5d636 <g_socket_client_connect_async>, name = 0x0,
task_data = 0x422630, task_data_destroy = 0x7ffff7a5bc9f <g_socket_client_async_connect_data_free>,
context = 0x418fc0, creation_time = 0, priority = 0, cancellable = 0x4188a0,
callback = 0x402696 <on_connected_cancelled>, callback_data = 0x4190b0, task_func = 0x0, lock = {
p = 0x0, i = {0, 0}}, cond = {p = 0x0, i = {0, 0}}, thread_cancelled = 0, check_cancellable = -1,
completed = 0, return_on_cancel = 0, synchronous = 0, thread_complete = 0, blocking_other_task = 0,
had_error = 0, result_set = 0, ever_returned = -1, error = 0x42a460, result = {pointer = 0x0,
size = 0, boolean = 0}, result_destroy = 0x0}
(gdb) frame 6
#6 0x00007ffff7a5d0c5 in g_socket_client_enumerator_callback (object=0x423e20, result=0x42f2f0,
user_data=0x422630) at ../../source/glib/gio/gsocketclient.c:1704
1704 if (task_completed_or_cancelled (data->task))
(gdb) print *data
$2 = {task = 0x423ce0, client = 0x40aa80, connectable = 0x422610, enumerator = 0x423e20,
proxy_addr = 0x0, socket = 0x0, connection = 0x0, connection_attempts = 0x42a4a0, last_error = 0x0}
(gdb)
Re-reviewing the code, task_completed_or_cancelled()
is faulty: a GTask
which is not-completed may have returned, because the completed
boolean in GTask
is set after the task’s user callback has returned; whereas the ever_returned
boolean (which is checked by g_task_return_*()
) is set by a call to g_task_return_*()
. So there is a period in a GTask
’s life when ever_returned
is true, but completed
is false.
There is no way to access ever_returned
from outside the GTask
API, and I think it should stay that way, as it’s an implementation detail. Users of GTask
should be able to keep track of whether they have ever called g_task_return_*()
on a GTask
instance themselves.
Apologies for not spotting this in code review before. I suggest you run all future network tests with --repeat 500
before being satisfied that they pass.
This is a blocker for 2.60.0.
/cc @pgriffis /cc @mcatanzaro