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

[Ming Lei <ming.lei@redhat.com>]

On Mon, Nov 01, 2021 at 12:44:00PM -0400, Joe Lawrence wrote:
> On Mon, Nov 01, 2021 at 07:25:45PM +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.
> > 
> > 
> > V3:
> > 	- one line fix on check of list_empty() in enabled_store(), 3/3
> > 
> > V2:
> > 	- remove enabled attribute before deleting this klp_patch kobject,
> > 	for avoiding deadlock in deleting me
> 
> Hi Ming,
> 
> Another interesting wedge (doesn't seem to happen w/o system load):
> 
> # different kernel tree build
> $ while(true); do make clean && make -j$(nproc); done
> 
> vs.
> 
> # loop the basic tests
> $ while(true); do ./tools/testing/selftests/livepatch/test-livepatch.sh || break; done
> TEST: basic function patching ... ok
> TEST: multiple livepatches ... ok
> TEST: atomic replace livepatch ... ERROR: failed to unload module test_klp_livepatch (refcnt)
> 
> $ lsmod | grep test_klp
> test_klp_atomic_replace    16384  1
> test_klp_livepatch     16384  1
> 
> $ head /sys/kernel/livepatch/*/enabled
> ==> /sys/kernel/livepatch/test_klp_atomic_replace/enabled <==
> 1
> 
> ==> /sys/kernel/livepatch/test_klp_livepatch/enabled <==
> 0
> 
> [  307.818060] livepatch: kernel.ftrace_enabled = 1
> [  307.849759] ===== TEST: basic function patching =====
> [  307.876520] % modprobe test_klp_livepatch
> [  307.889014] test_klp_livepatch: tainting kernel with TAINT_LIVEPATCH
> [  307.915450] livepatch: enabling patch 'test_klp_livepatch'
> [  307.923991] livepatch: 'test_klp_livepatch': starting patching transition
> [  308.768730] livepatch: 'test_klp_livepatch': patching complete
> [  308.779476] % echo 0 > /sys/kernel/livepatch/test_klp_livepatch/enabled
> [  308.787378] livepatch: 'test_klp_livepatch': starting unpatching transition
> [  308.828968] livepatch: 'test_klp_livepatch': unpatching complete
> [  308.838284] % rmmod test_klp_livepatch
> [  308.921367] ===== TEST: multiple livepatches =====
> [  308.936056] % modprobe test_klp_livepatch
> [  308.968419] livepatch: enabling patch 'test_klp_livepatch'
> [  308.976976] livepatch: 'test_klp_livepatch': starting patching transition
> [  309.779754] livepatch: 'test_klp_livepatch': patching complete
> [  309.827765] test_klp_livepatch: this has been live patched
> [  309.853678] % modprobe test_klp_atomic_replace replace=0
> [  309.887697] livepatch: enabling patch 'test_klp_atomic_replace'
> [  309.897090] livepatch: 'test_klp_atomic_replace': starting patching transition
> [  309.906310] livepatch: 'test_klp_atomic_replace': patching complete
> [  309.919386] test_klp_livepatch: this has been live patched
> [  309.928124] test_klp_atomic_replace: this has been live patched
> [  309.935306] % echo 0 > /sys/kernel/livepatch/test_klp_atomic_replace/enabled
> [  309.943882] livepatch: 'test_klp_atomic_replace': starting unpatching transition
> [  310.842939] livepatch: 'test_klp_atomic_replace': unpatching complete
> [  310.875590] % rmmod test_klp_atomic_replace
> [  310.910489] test_klp_livepatch: this has been live patched
> [  310.919444] % echo 0 > /sys/kernel/livepatch/test_klp_livepatch/enabled
> [  310.927157] livepatch: 'test_klp_livepatch': starting unpatching transition
> [  311.795931] livepatch: 'test_klp_livepatch': unpatching complete
> [  311.858463] % rmmod test_klp_livepatch
> [  311.941334] ===== TEST: atomic replace livepatch =====
> [  311.959647] % modprobe test_klp_livepatch
> [  311.992469] livepatch: enabling patch 'test_klp_livepatch'
> [  312.001464] livepatch: 'test_klp_livepatch': starting patching transition
> [  312.787758] livepatch: 'test_klp_livepatch': patching complete
> [  312.854237] test_klp_livepatch: this has been live patched
> [  312.872939] % modprobe test_klp_atomic_replace replace=1
> [  312.926957] livepatch: enabling patch 'test_klp_atomic_replace'
> [  312.936289] livepatch: 'test_klp_atomic_replace': starting patching transition
> [  312.968876] livepatch: 'test_klp_atomic_replace': patching complete
> [  312.975898] ------------[ cut here ]------------
> [  312.981073] WARNING: CPU: 16 PID: 35260 at kernel/livepatch/core.c:996 __klp_enable_patch.cold+0xbd/0x132
> [  312.991781] Modules linked in: test_klp_atomic_replace(K+) test_klp_livepatch(K) rfkill intel_rapl_msr intel_rapl_common sb_edac x86_pkg_]
> [  313.060963] CPU: 16 PID: 35260 Comm: modprobe Kdump: loaded Tainted: G              K   5.15.0-rc7+ #1
> [  313.071375] Hardware name: Dell Inc. PowerEdge T620/0MX4YF, BIOS 1.0.4 02/21/2012
> [  313.079756] RIP: 0010:__klp_enable_patch.cold+0xbd/0x132
> [  313.085718] Code: dc ff ff e8 2a d4 78 ff e9 a2 b1 78 ff e8 b0 d8 78 ff c6 85 80 00 00 00 01 48 89 df e8 91 d4 78 ff 48 8b 04 24 48 39 d8f
> [  313.106703] RSP: 0018:ffffa99ac8e0fd68 EFLAGS: 00010216
> [  313.112564] RAX: ffffffffc098d020 RBX: ffffa99ac8e0fd68 RCX: 0000000000000000
> [  313.120554] RDX: ffffa99ac8e0fd68 RSI: ffffa99ac8e0fd68 RDI: ffffffffc098d020
> [  313.128552] RBP: ffffffffc0a9d000 R08: ffffa99ac8e0fd68 R09: ffffa99ac8e0fd68
> [  313.136545] R10: ffffa99ac8e0fb50 R11: ffffffffb45e5648 R12: 0000000000000000
> [  313.144528] R13: ffffffffc0a9d070 R14: ffffffffc0a9cfe8 R15: ffffffffc0a9d2f8
> [  313.152517] FS:  00007fa4a968e740(0000) GS:ffff8b469fc00000(0000) knlGS:0000000000000000
> [  313.161576] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [  313.168017] CR2: 00000000013fb008 CR3: 000000012b7da005 CR4: 00000000000606e0
> [  313.176008] Call Trace:
> [  313.178765]  klp_enable_patch+0x2d7/0x340
> [  313.183272]  ? livepatch_meminfo_proc_show+0x30/0x30 [test_klp_atomic_replace]
> [  313.191367]  do_one_initcall+0x44/0x1d0
> [  313.195685]  ? load_module+0xab3/0xb60
> [  313.199899]  ? __cond_resched+0x16/0x40
> [  313.204207]  ? kmem_cache_alloc_trace+0x44/0x3d0
> [  313.209391]  do_init_module+0x5c/0x270
> [  313.213600]  __do_sys_finit_module+0xae/0x110
> [  313.218490]  do_syscall_64+0x3b/0x90
> [  313.222505]  entry_SYSCALL_64_after_hwframe+0x44/0xae
> [  313.228167] RIP: 0033:0x7fa4a979e0cd
> [  313.232180] Code: 5b 41 5c c3 66 0f 1f 84 00 00 00 00 00 f3 0f 1e fa 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 088
> [  313.253166] RSP: 002b:00007fff515d0488 EFLAGS: 00000246 ORIG_RAX: 0000000000000139
> [  313.261658] RAX: ffffffffffffffda RBX: 0000562e0d532900 RCX: 00007fa4a979e0cd
> [  313.269654] RDX: 0000000000000000 RSI: 0000562e0d532d90 RDI: 0000000000000003
> [  313.277648] RBP: 0000000000040000 R08: 0000000000000000 R09: 00007fff00000002
> [  313.285628] R10: 0000000000000003 R11: 0000000000000246 R12: 0000562e0d532d90
> [  313.293617] R13: 0000562e0d532b40 R14: 0000562e0d532900 R15: 0000562e0d532db0
> [  313.301612] ---[ end trace d4ec8b943e8d24cc ]---
> [  313.315675] test_klp_atomic_replace: this has been live patched
> [  375.850221] ERROR: failed to unload module test_klp_livepatch (refcnt)
> 
>  949 static int __klp_enable_patch(struct klp_patch *patch)
>  ...
>  993         klp_start_transition();
>  994         patch->enabled = true;
>  995         klp_try_complete_transition(&unused);
>  996         WARN_ON_ONCE(!list_empty(&unused));

Got it, in case of replace mode, patch can be freed even during
enabling, we can address it here by calling klp_free_patches()
in klp_enable_patch() without holding klp_mutex.

I have run the test for one hour after applying the above change, not
see the issue any more.

Will post v4 soon.

thanks,
Ming