udisksd sometimes consumes 100% cpu and is unresponsive until killed

[terencode]

When it happens, it starts right after the system is booted and stays like this until the daemon is killed.

Archlinux
linux 5.11.2
udisks2 2.9.2
libatasmart 0.19
gvfs 1.46.2

• udevadm info --export-db : udevadm.txt
• cat /proc/self/mountinfo : mountinfo.txt
• cat /etc/fstab : fstab.txt

udiskctl just hangs so I had to kill udisksd before invoking the next command, which also fixes the issue.

• udisksctl dump : udiskdump.txt

Some journalctl log:

févr. 27 23:52:10 terence-desktop systemd[1]: Created slice system-udisks2\x2dzram\x2dsetup.slice.
févr. 27 23:52:11 terence-desktop systemd[1]: udisks2-zram-setup@zram0.service: Succeeded.
févr. 27 23:52:11 terence-desktop udisksd[643]: udisks daemon version 2.9.2 starting
févr. 27 23:52:11 terence-desktop udisksd[643]: Acquired the name org.freedesktop.UDisks2 on the system message bus
févr. 27 23:52:22 terence-desktop udisksd[643]: Mounted /dev/sdf3 at /run/media/terence/22223b88-1320-44af-afbc-346f50c37002 on behalf of uid 1000
févr. 27 23:52:22 terence-desktop udisksd[643]: Mounted /dev/sdf1 at /run/media/terence/QFLASH on behalf of uid 1000
févr. 27 23:52:22 terence-desktop udisksd[643]: Mounted /dev/sdf2 at /run/media/terence/Data on behalf of uid 1000
févr. 27 23:52:22 terence-desktop ntfs-3g[2318]: Cmdline options: rw,nodev,nosuid,uid=1000,gid=1000,windows_names,uhelper=udisks2
févr. 27 23:52:22 terence-desktop ntfs-3g[2318]: Mount options: rw,nodev,nosuid,uhelper=udisks2,allow_other,nonempty,relatime,default_permissions,fsname=/dev/sdf2,blkdev,blksize=4096
févr. 27 23:52:23 terence-desktop udisksd[643]: Mounted /dev/sde at /run/media/terence/Elements on behalf of uid 1000
févr. 27 23:52:47 terence-desktop gsd-disk-utilit[2199]: Error initializing udisks client: Timeout was reached (g-io-error-quark, 24)

[tbzatek]

Can you please provide stacktrace of udisksd?

https://wiki.gnome.org/Community/GettingInTouch/Bugzilla/GettingTraces
https://wiki.gnome.org/Community/GettingInTouch/Bugzilla/GettingTraces/DistroSpecificInstructions

[terencode]

#1  0x00007f889046d1df in  () at /usr/lib/libbd_utils.so.2
#2  0x00007f889046d795 in bd_utils_exec_and_capture_output () at /usr/lib/libbd_utils.so.2
#3  0x00007f888d411b93 in  () at /usr/lib/libbd_fs.so.2
#4  0x000055b7ecb39673 in get_filesystem_size (object=object@entry=0x55b7ede425d0) at udiskslinuxfilesystem.c:180
        info = <optimized out>
        size = 0
        device = 0x7f8880056180
        dev = 0x55b7ede88220 "/dev/sdf3"
        type = 0x55b7ede7a310 "ext4"
        error = 0x0
#5  0x000055b7ecb3db59 in udisks_linux_filesystem_update (filesystem=0x55b7ede554c0, object=object@entry=0x55b7ede425d0) at udiskslinuxfilesystem.c:278
        mount_monitor = <optimized out>
        device = 0x7f8880056180
        ata = <optimized out>
        p = <optimized out>
        mounts = 0x7f888000aae0 = {0x55b7eddb1ec0}
        l = <optimized out>
        skip_fs_size = <optimized out>
        pm_state = 0 '\000'
#6  0x000055b7ecb2d1a0 in filesystem_update (object=<optimized out>, uevent_action=<optimized out>, _iface=0x55b7ede554c0) at udiskslinuxblockobject.c:748
#7  0x000055b7ecb2d82c in udisks_linux_block_object_uevent (object=0x55b7ede425d0, action=0x0, device=<optimized out>) at udiskslinuxblockobject.c:878
        module_manager = <optimized out>
        modules = <optimized out>
        l = <optimized out>
        __func__ = "udisks_linux_block_object_uevent"
#8  0x00007f8890050072 in g_closure_invoke (closure=0x55b7ede803d0, return_value=0x0, n_param_values=2, param_values=0x7ffd350137f0, invocation_hint=0x7ffd35013770) at ../glib/gobject/gclosure.c:810
        marshal = 0x7f8890052410 <g_cclosure_marshal_VOID__OBJECT>
        marshal_data = 0x0
        in_marshal = 0
        real_closure = 0x55b7ede803b0
        __func__ = "g_closure_invoke"
#9  0x00007f8890078a85 in signal_emit_unlocked_R.isra.0
    (node=node@entry=0x55b7edd8f0a0, detail=detail@entry=0, instance=instance@entry=0x55b7edd7adc0, emission_return=emission_return@entry=0x0, instance_and_params=instance_and_params@entry=0x7ffd350137f0)
    at ../glib/gobject/gsignal.c:3739
        tmp = <optimized out>
        handler = 0x55b7ede59100
        accumulator = 0x0
        emission = {next = 0x7f8876ffcb10, instance = 0x55b7edd7adc0, ihint = {signal_id = 15, detail = 0, run_type = G_SIGNAL_RUN_FIRST}, state = EMISSION_RUN, chain_type = 0x4 [None]}
        class_closure = 0x55b7edd903d0
        hlist = <optimized out>
        handler_list = 0x55b7ede4b280
        return_accu = 0x0
        accu = 
              {g_type = 0x0, data = {{v_int = 0, v_uint = 0, v_long = 0, v_ulong = 0, v_int64 = 0, v_uint64 = 0, v_float = 0, v_double = 0, v_pointer = 0x0}, {v_int = 0, v_uint = 0, v_long = 0, v_ulong = 0, v_int64 = 0, v_uint64 = 0, v_float = 0, v_double = 0, v_pointer = 0x0}}}
        signal_id = 15
        max_sequential_handler_number = 182
        return_value_altered = <optimized out>
#10 0x00007f889006c5dd in g_signal_emit_valist (instance=<optimized out>, signal_id=<optimized out>, detail=<optimized out>, var_args=var_args@entry=0x7ffd350139b0) at ../glib/gobject/gsignal.c:3495
        instance_and_params = 0x7ffd350137f0
        signal_return_type = <optimized out>
        param_values = 0x7ffd35013808
        node = <optimized out>
        i = <optimized out>
        n_params = <optimized out>
        __func__ = "g_signal_emit_valist"
#11 0x00007f889006cb40 in g_signal_emit (instance=instance@entry=0x55b7edd7adc0, signal_id=<optimized out>, detail=detail@entry=0) at ../glib/gobject/gsignal.c:3551
        var_args = {{gp_offset = 32, fp_offset = 48, overflow_arg_area = 0x7ffd35013a90, reg_save_area = 0x7ffd350139d0}}
--Type <RET> for more, q to quit, c to continue without paging--
#12 0x000055b7ecb57f7f in reload_mounts (monitor=0x55b7edd7adc0) at udisksmountmonitor.c:275
        mount = <optimized out>
        cur_mounts = 0x55b7eddb2340 = {0x55b7edf03e70, 0x55b7edf03f30, 0x55b7edf03d50, 0x55b7edf03d80, 0x55b7edf04000, 0x55b7edf03e10}
        added = 0x7f8878001460 = {0x55b7edf04000}
        removed = 0x0
        l = 0x7f8878001460 = {0x55b7edf04000}
#13 0x000055b7ecb582ba in mounts_changed_event (channel=<optimized out>, cond=<optimized out>, user_data=0x55b7edd7adc0) at udisksmountmonitor.c:293
        monitor = <optimized out>
#14 0x00007f888ff5bb84 in g_main_dispatch (context=0x55b7edd692d0) at ../glib/glib/gmain.c:3325
        dispatch = 0x7f888ffae790 <g_io_unix_dispatch>
        prev_source = 0x0
        begin_time_nsec = 36182785176
        was_in_call = <optimized out>
        user_data = 0x55b7edd7adc0
        callback = 0x55b7ecb58290 <mounts_changed_event>
        cb_funcs = 0x7f889003b3a0 <g_source_callback_funcs>
        cb_data = 0x55b7edd8f760
        need_destroy = <optimized out>
        source = 0x55b7edd95140
        current = 0x55b7edd74660
        i = 0
#15 g_main_context_dispatch (context=0x55b7edd692d0) at ../glib/glib/gmain.c:4043
#16 0x00007f888ffafc21 in g_main_context_iterate.constprop.0 (context=0x55b7edd692d0, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib/glib/gmain.c:4119
        max_priority = 2147483647
        timeout = 567841
        some_ready = 1
        nfds = 6
        allocated_nfds = 6
        fds = 0x55b7ede64e00
        begin_time_nsec = 36159370008
#17 0x00007f888ff5b0d3 in g_main_loop_run (loop=0x55b7edd64960) at ../glib/glib/gmain.c:4317
        __func__ = "g_main_loop_run"
#18 0x000055b7ecb262fd in main (argc=<optimized out>, argv=<optimized out>) at main.c:184
        error = 0x0
        opt_context = 0x55b7edd68fb0
        ret = 1
        name_owner_id = 1
        sigint_id = 1
        __func__ = "main"

[tbzatek]

Thanks. One last thing - can you start udevadm monitor on a side terminal and see if there's a constant flow of events while udisksd is consuming 100% CPU?

[terencode]

udevadm monitor doesn't show any event when udiskd is stuck.

However while looking at my debug packages I found that I had a systemd-debug package installed for systemd 247 while the regular systemd package is at 247.3.
When I removed it and rebooted and I couldn't reproduce the bug anymore. To be sure I installed it again and next reboot, udisks was back at 100% cpu.

So the issues seems to come from there but why?

Nevermind can still reproduce.

[terencode]

Today I caught udisk2 also frozen right after booting (udiskctl status just hangs and then prints Error connecting to the udisks daemon: Timeout was reached) but this time not consuming any cpu.
I didn't have the debug symbols installed so I couldn't get a complete trace. However it looks a lot like it:

#0  0x00007f36046c837f in poll () at /usr/lib/libc.so.6
#1  0x00007f3604d311df in  () at /usr/lib/libbd_utils.so.2
#2  0x00007f3604d31795 in bd_utils_exec_and_capture_output () at /usr/lib/libbd_utils.so.2
#3  0x00007f3601cc5b93 in  () at /usr/lib/libbd_fs.so.2
#4  0x00005624ce01c673 in  ()
#5  0x00005624ce020b59 in udisks_linux_filesystem_update ()
#6  0x00005624ce0101a0 in  ()
#7  0x00005624ce01082c in udisks_linux_block_object_uevent ()
#8  0x00007f360490cddf in g_closure_invoke () at /usr/lib/libgobject-2.0.so.0
#9  0x00007f3604935fbd in  () at /usr/lib/libgobject-2.0.so.0
#10 0x00007f3604929cad in g_signal_emit_valist () at /usr/lib/libgobject-2.0.so.0
#11 0x00007f360492a210 in g_signal_emit () at /usr/lib/libgobject-2.0.so.0
#12 0x00005624ce03af7f in  ()
#13 0x00005624ce03b2ba in  ()
#14 0x00007f3604816044 in g_main_context_dispatch () at /usr/lib/libglib-2.0.so.0
#15 0x00007f360486be61 in  () at /usr/lib/libglib-2.0.so.0
#16 0x00007f3604815593 in g_main_loop_run () at /usr/lib/libglib-2.0.so.0
#17 0x00005624ce0092fd in main ()

[tbzatek]

Similar problem here: https://bugzilla.redhat.com/show_bug.cgi?id=1896373

One other idea is to attach strace to a process stuck in an endless loop. Or perhaps even before it starts the loop, e.g. before logging into a desktop session letting upper layers automount the volumes (/run/media/terence/*):

strace -p `pidof udisksd`

[Michaelpalacce]

Has anyone found a solution for this? I am also having the same issue

[tbzatek]

Getting back to this after some time - can you please confirm you have the following fix?
storaged-project/libblockdev#572

Released as libblockdev-2.25: https://github.com/storaged-project/libblockdev/releases/tag/2.25-1

[Michaelpalacce]

Hey @tbzatek It seems that yes I do have it

libblockdev-crypto2/impish,now 2.25-2build1 arm64 [installed,automatic]
libblockdev-fs2/impish,now 2.25-2build1 arm64 [installed,automatic]
libblockdev-loop2/impish,now 2.25-2build1 arm64 [installed,automatic]
libblockdev-part-err2/impish,now 2.25-2build1 arm64 [installed,automatic]
libblockdev-part2/impish,now 2.25-2build1 arm64 [installed,automatic]
libblockdev-swap2/impish,now 2.25-2build1 arm64 [installed,automatic]
libblockdev-utils2/impish,now 2.25-2build1 arm64 [installed,automatic]
libblockdev2/impish,now 2.25-2build1 arm64 [installed,automatic]

this is everything that is installed with libblockdev and the version seems to match.

[Michaelpalacce]

@tbzatek I also did a full reinstall of the OS and the issue is still there

[tbzatek]

This might possibly be another manifestation of #946