Re: [PATCH 0/3] livepatch: cleanup kpl_patch kobject release

From: Joe Lawrence
Date: Fri Oct 29 2021 - 09:52:42 EST


On Thu, Oct 28, 2021 at 08:57:31PM +0800, Ming Lei wrote:
> Hello,
>
> The 1st patch moves module_put() to release handler of klp_patch
> kobject.
>
> The 2nd patch changes to free klp_patch and other kobjects without
> klp_mutex.
>
> The 3rd patch switches to synchronous kobject release for klp_patch.
>

Hi Ming,

I gave the patchset a spin on top of linus tree @ 1fc596a56b33 and ended
up with a stuck task:

Test
----
Enable the livepatch selftests:
$ grep CONFIG_TEST_LIVEPATCH .config
CONFIG_TEST_LIVEPATCH=m

Run a continuous kernel build in the background:
$ while (true); do make clean && make -j$(nproc); done

While continuously executing the selftests:
$ while (true); do make -C tools/testing/selftests/livepatch/ run_tests; done

Results
-------
...
[ 366.862278] ===== TEST: multiple target modules =====
[ 366.877470] % modprobe test_klp_callbacks_busy block_transition=N
[ 366.890468] test_klp_callbacks_busy: test_klp_callbacks_busy_init
[ 366.897280] test_klp_callbacks_busy: busymod_work_func enter
[ 366.903602] test_klp_callbacks_busy: busymod_work_func exit
[ 366.920311] % modprobe test_klp_callbacks_demo
[ 366.931737] livepatch: enabling patch 'test_klp_callbacks_demo'
[ 366.938466] test_klp_callbacks_demo: pre_patch_callback: vmlinux
[ 366.945173] test_klp_callbacks_demo: pre_patch_callback: test_klp_callbacks_busy -> [MODULE_STATE_LIVE] Normal state
[ 366.959322] livepatch: 'test_klp_callbacks_demo': starting patching transition
[ 369.699278] test_klp_callbacks_demo: post_patch_callback: vmlinux
[ 369.706118] test_klp_callbacks_demo: post_patch_callback: test_klp_callbacks_busy -> [MODULE_STATE_LIVE] Normal state
[ 369.718079] livepatch: 'test_klp_callbacks_demo': patching complete
[ 369.786485] % modprobe test_klp_callbacks_mod
[ 369.806918] livepatch: applying patch 'test_klp_callbacks_demo' to loading module 'test_klp_callbacks_mod'
[ 369.818005] test_klp_callbacks_demo: pre_patch_callback: test_klp_callbacks_mod -> [MODULE_STATE_COMING] Full formed, running module_init
[ 369.831826] test_klp_callbacks_demo: post_patch_callback: test_klp_callbacks_mod -> [MODULE_STATE_COMING] Full formed, running module_init
[ 369.846259] test_klp_callbacks_mod: test_klp_callbacks_mod_init
[ 369.865115] % rmmod test_klp_callbacks_mod
[ 369.881713] test_klp_callbacks_mod: test_klp_callbacks_mod_exit
[ 369.888790] test_klp_callbacks_demo: pre_unpatch_callback: test_klp_callbacks_mod -> [MODULE_STATE_GOING] Going away
[ 369.900583] livepatch: reverting patch 'test_klp_callbacks_demo' on unloading module 'test_klp_callbacks_mod'
[ 369.911696] test_klp_callbacks_demo: post_unpatch_callback: test_klp_callbacks_mod -> [MODULE_STATE_GOING] Going away
[ 369.946082] % echo 0 > /sys/kernel/livepatch/test_klp_callbacks_demo/enabled
[ 369.954544] test_klp_callbacks_demo: pre_unpatch_callback: vmlinux
[ 369.962117] test_klp_callbacks_demo: pre_unpatch_callback: test_klp_callbacks_busy -> [MODULE_STATE_LIVE] Normal state
[ 369.974099] livepatch: 'test_klp_callbacks_demo': starting unpatching transition
[ 370.022730] test_klp_callbacks_demo: post_unpatch_callback: vmlinux
[ 370.029763] test_klp_callbacks_demo: post_unpatch_callback: test_klp_callbacks_busy -> [MODULE_STATE_LIVE] Normal state
[ 370.042065] livepatch: 'test_klp_callbacks_demo': unpatching complete
[ 494.498310] INFO: task test-callbacks.:10039 blocked for more than 122 seconds.
[ 494.506489] Tainted: G K 5.15.0-rc7+ #2
[ 494.512834] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 494.521601] task:test-callbacks. state:D stack: 0 pid:10039 ppid: 10036 flags:0x00004000
[ 494.530958] Call Trace:
[ 494.533706] __schedule+0x200/0x540
[ 494.537628] schedule+0x44/0xa0
[ 494.541161] __kernfs_remove.part.0+0x21e/0x2a0
[ 494.546251] ? do_wait_intr_irq+0xa0/0xa0
[ 494.550761] kernfs_remove_by_name_ns+0x50/0x90
[ 494.555852] remove_files+0x2b/0x60
[ 494.559783] sysfs_remove_group+0x38/0x80
[ 494.564300] sysfs_remove_groups+0x29/0x40
[ 494.568908] __kobject_del+0x1b/0x80
[ 494.572933] kobject_cleanup+0x9c/0x130
[ 494.577251] enabled_store+0xdc/0x1a0
[ 494.581379] kernfs_fop_write_iter+0x11c/0x1b0
[ 494.586374] new_sync_write+0x11f/0x1b0
[ 494.590690] ? msr_build_context.constprop.0+0x5d/0xbe
[ 494.596462] vfs_write+0x1ce/0x260
[ 494.600291] ksys_write+0x5f/0xe0
[ 494.604024] do_syscall_64+0x3b/0x90
[ 494.608049] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 494.613719] RIP: 0033:0x7f66cd5aea37
[ 494.617733] RSP: 002b:00007ffe6a5e16c8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[ 494.626209] RAX: ffffffffffffffda RBX: 0000000000000002 RCX: 00007f66cd5aea37
[ 494.634196] RDX: 0000000000000002 RSI: 0000562e8101ba60 RDI: 0000000000000001
[ 494.642177] RBP: 0000562e8101ba60 R08: 0000000000000000 R09: 00007f66cd6634e0
[ 494.650166] R10: 00007f66cd6633e0 R11: 0000000000000246 R12: 0000000000000002
[ 494.658156] R13: 00007f66cd6a85a0 R14: 0000000000000002 R15: 00007f66cd6a87a0
...
[ 1600.420533] INFO: task test-callbacks.:10039 blocked for more than 1228 seconds.

Let me know if you have any questions about the tests. If you look at
the "^%" prefixed kernel messages in the above log, you can get a rough
idea of the commands that the test ran.

Regards,

-- Joe