Random nautilus test suite failures involving GUnixMountMonitor
This is a continuation of nautilus!516 (merged).
The test-file-operations-move-files
and test-file-operations-copy-files
nautilus test cases randomly crash with the following error (just line number differs), which causes often GitLab CI pipeline failures (see https://gitlab.gnome.org/GNOME/nautilus/-/jobs):
Bail out! GLib-FATAL-CRITICAL: g_source_is_destroyed: assertion 'g_atomic_int_get (&source->ref_count) > 0' failed
(/nautilus/_build/test/automated/displayless/test-file-operations-move-files:885): GLib-CRITICAL **: 13:03:28.527: g_source_is_destroyed: assertion 'g_atomic_int_get (&source->ref_count) > 0' failed
To reproduce this locally, one has to start the test suite with GIO_USE_VOLUME_MONITOR=unix
(e.g. RUNNING_TESTS=TRUE GIO_USE_VOLUME_MONITOR=unix ./test-file-operations-move-files
. The problem seems to be that GUnixMountMonitor
is not thread-safe and Nautilus calls g_file_query_filesystem_info
on a thread, which unfortunately uses GUnixMountMonitor
. When GIO_USE_VOLUME_MONITOR=unix
is used then also g_volume_monitor_get
uses GUnixMountMonitor
. It is not clear to me what was changed and where that this started happening after changing runtime from gnome:3.34
to gnome:master
. Maybe this relates somehow to the gnome-build-meta@0133fe16 change, that gvfs is now built with -Dudisks2=false
, so it fallbacks to the unix monitor automatically. But that change is 1 year old...
The reason why Nautilus calls g_file_query_filesystem_info
on a thread is the fact that NautilusFileUndoManager
is based on synchronous GIO API. It is a bit weird and it is not clear to me why it rather doesn't use asynchronous methods directly. Although using synchronous API on a thread is not probably against the documentation, it leads to those issues among others. So the right fix is probably to add locks around the source in the GUnixMountMonitor
code. @pwithnall, I am right?
Thread 3 (Thread 0x7ffff2b8a700 (LWP 887)):
#0 g_logv (log_domain=0x7ffff7f2900e "GLib", log_level=G_LOG_LEVEL_CRITICAL, format=<optimized out>, args=<optimized out>) at ../glib/gmessages.c:1377
#1 0x00007ffff7ee1273 in g_log (log_domain=log_domain@entry=0x7ffff7f2900e "GLib", log_level=log_level@entry=G_LOG_LEVEL_CRITICAL, format=format@entry=0x7ffff7f336ff "%s: assertion '%s' failed") at ../glib/gmessages.c:1415
#2 0x00007ffff7ee1a6d in g_return_if_fail_warning (log_domain=log_domain@entry=0x7ffff7f2900e "GLib", pretty_function=pretty_function@entry=0x7ffff7f31ab0 <__func__.14400> "g_source_is_destroyed", expression=expression@entry=0x7ffff7f30ec8 "g_atomic_int_get (&source->ref_count) > 0") at ../glib/gmessages.c:2771
#3 0x00007ffff7ed8aba in g_source_is_destroyed (source=<optimized out>) at ../glib/gmain.c:3141
#4 0x00007ffff737f43c in proc_mounts_watch_is_running () at ../gio/gunixmounts.c:1714
#5 get_mounts_timestamp () at ../gio/gunixmounts.c:1496
#6 0x00007ffff73806f2 in g_unix_mounts_get (time_read=time_read@entry=0x7ffff2b89838) at ../gio/gunixmounts.c:1544
#7 0x00007ffff7380727 in g_unix_mount_at (mount_path=mount_path@entry=0x7fffe405d9b0 "/", time_read=time_read@entry=0x7ffff2b89838) at ../gio/gunixmounts.c:1570
#8 0x00007ffff73e27fe in get_mount_info (matcher=0x7fffe400c780, path=0x6f1050 "/tmp/move_dir", fs_info=0x7fffe4002330 [GFileInfo]) at ../gio/glocalfile.c:800
#9 g_local_file_query_filesystem_info (file=<optimized out>, attributes=<optimized out>, cancellable=<optimized out>, error=<optimized out>) at ../gio/glocalfile.c:1110
#10 0x00000000004512e0 in verify_destination (job=0x6e1810, dest=0x7fffe808fac0, dest_fs_id=0x0, required_size=0) at ../src/nautilus-file-operations.c:3642
#11 0x000000000045661c in nautilus_file_operations_move (task=0x616490 [GTask], source_object=0x0, task_data=0x6e1810, cancellable=0x676360 [GCancellable]) at ../src/nautilus-file-operations.c:6493
#12 0x00007ffff735d5f2 in g_task_thread_pool_thread (thread_data=0x616490, pool_data=<optimized out>) at ../gio/gtask.c:1412
#13 0x00007ffff7f040b4 in g_thread_pool_thread_proxy (data=<optimized out>) at ../glib/gthreadpool.c:354
#14 0x00007ffff7f037b2 in g_thread_proxy (data=0x5fcaa0) at ../glib/gthread.c:807
#15 0x00007ffff704f432 in start_thread (arg=<optimized out>) at pthread_create.c:477
#16 0x00007ffff6f7b833 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
Thread 1 (Thread 0x7ffff33a0f80 (LWP 885)):
#0 0x00007ffff6f709cf in __GI___poll (fds=0x6d24c0, nfds=1, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1 0x00007ffff7ed9afe in g_main_context_poll (priority=<optimized out>, n_fds=1, fds=0x6d24c0, timeout=<optimized out>, context=0x6d24e0) at ../glib/gmain.c:4309
#2 g_main_context_iterate (context=0x6d24e0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib/gmain.c:4005
#3 0x00007ffff7ed9e83 in g_main_loop_run (loop=0x6d25a0) at ../glib/gmain.c:4204
#4 0x0000000000449abc in test_operation_undo_redo () at ../test/automated/displayless/test-utilities.c:196
#5 0x00000000004441c2 in test_move_directories_small_undo_redo () at ../test/automated/displayless/test-file-operations-move-files.c:735
#6 0x00007ffff7f0225e in test_case_run (tc=0x61e810) at ../glib/gtestutils.c:2633
#7 g_test_run_suite_internal (suite=suite@entry=0x610ec0, path=path@entry=0x0) at ../glib/gtestutils.c:2721
#8 0x00007ffff7f0205b in g_test_run_suite_internal (suite=suite@entry=0x610b00, path=path@entry=0x0) at ../glib/gtestutils.c:2733
#9 0x00007ffff7f0274a in g_test_run_suite (suite=0x610b00) at ../glib/gtestutils.c:2808
#10 0x00007ffff7f02765 in g_test_run () at ../glib/gtestutils.c:2043
#11 0x00000000004490f1 in main (argc=1, argv=0x7fffffffe658) at ../test/automated/displayless/test-file-operations-move-files.c:1945