Re: [Syzkaller & bisect] There is " __disarm_kprobe_ftrace" WARNING in v6.2-rc7 kernel
From: Pengfei Xu
Date: Wed Feb 08 2023 - 09:05:17 EST
Hi Greg KH,
On 2023-02-08 at 10:30:01 +0100, Greg KH wrote:
> On Wed, Feb 08, 2023 at 05:03:52PM +0800, Pengfei Xu wrote:
> > Hi Greg KH and kernel expert,
> >
> > Greeting!
> >
> > There is " __disarm_kprobe_ftrace" WARNING in v6.2-rc7 kernel in fault
> > injection test by syzkaller:
> > [ 30.404796] FAULT_INJECTION: forcing a failure.
>
> So you forced a fault and something crashed. What were you expecting?
As before, I just tested regular(no fault injection) syzkaller testing, and
there was no problem.
And recently I enabled fault injection and found this WARNING, I should
check the fault injection related issue carefully next time, and confirm it's
really an issue and report.
>
> > [ 30.404796] name failslab, interval 1, probability 0, space 0, times 1
> > [ 30.405595] CPU: 1 PID: 510 Comm: repro Not tainted 6.2.0-rc7-4ec5183ec486 #1
> > [ 30.406044] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
> > [ 30.406724] Call Trace:
> > [ 30.406890] <TASK>
> > [ 30.407032] dump_stack_lvl+0xa7/0xdb
> > [ 30.407310] dump_stack+0x19/0x1f
> > [ 30.407532] should_fail_ex.cold.5+0x5/0xa
> > [ 30.407820] __should_failslab+0xca/0x120
> > [ 30.408091] should_failslab+0x12/0x30
> > [ 30.408341] __kmem_cache_alloc_node+0x62/0x280
> > [ 30.408636] ? alloc_ftrace_hash+0x4f/0x170
> > [ 30.408916] kmalloc_trace+0x2e/0x120
> > [ 30.409161] alloc_ftrace_hash+0x4f/0x170
> > [ 30.409426] alloc_and_copy_ftrace_hash.constprop.87+0x23/0x310
> > [ 30.409804] ? write_comp_data+0x2f/0x90
> > [ 30.410078] ftrace_set_hash+0x445/0x590
> > [ 30.410350] ? __sanitizer_cov_trace_pc+0x25/0x60
> > [ 30.410671] ftrace_set_filter_ip+0xcd/0x1a0
> > [ 30.410967] ? __pfx_ftrace_set_filter_ip+0x10/0x10
> > [ 30.411295] ? match_dev_by_uuid+0x4/0x100
> > [ 30.411574] ? unregister_ftrace_function+0x83/0x3c0
> > [ 30.411906] ? __this_cpu_preempt_check+0x20/0x30
> > [ 30.412228] ? write_comp_data+0x2f/0x90
> > [ 30.412507] __disarm_kprobe_ftrace.isra.24+0xe4/0x250
> > [ 30.412851] disarm_kprobe+0x24a/0x2d0
> > [ 30.413112] __disable_kprobe+0x2de/0x4b0
> > [ 30.413390] disable_kprobe+0x31/0x80
> > [ 30.413643] __disable_trace_kprobe+0xfb/0x1c0
> > [ 30.413965] disable_trace_kprobe+0x1f0/0x300
> > [ 30.414266] kprobe_register+0x4e/0xf0
> > [ 30.414528] perf_trace_event_unreg.isra.3+0xb6/0x1f0
> > [ 30.414870] perf_kprobe_destroy+0xcb/0x200
> > [ 30.415156] ? __pfx_perf_kprobe_destroy+0x10/0x10
> > [ 30.415482] _free_event+0x220/0x11c0
> > [ 30.415754] put_event+0x4d/0x60
> > [ 30.415993] perf_event_release_kernel+0x5d9/0x860
> > [ 30.416330] ? __pfx_perf_event_release_kernel+0x10/0x10
> > [ 30.416680] ? write_comp_data+0x2f/0x90
> > [ 30.416950] ? __sanitizer_cov_trace_pc+0x25/0x60
> > [ 30.417292] ? __pfx_perf_release+0x10/0x10
> > [ 30.417579] perf_release+0x40/0x50
> > [ 30.417830] __fput+0x26d/0xa40
> > [ 30.418080] ____fput+0x1e/0x30
> > [ 30.418303] task_work_run+0x1a4/0x2d0
> > [ 30.418565] ? write_comp_data+0x2f/0x90
> > [ 30.418836] ? __pfx_task_work_run+0x10/0x10
> > [ 30.419138] ? __this_cpu_preempt_check+0x20/0x30
> > [ 30.419463] ? lockdep_hardirqs_on+0x8a/0x110
> > [ 30.419751] ? exit_to_user_mode_prepare+0x100/0x210
> > [ 30.420080] exit_to_user_mode_prepare+0x200/0x210
> > [ 30.420392] syscall_exit_to_user_mode+0x2d/0x60
> > [ 30.420698] do_syscall_64+0x4a/0x90
> > [ 30.420944] entry_SYSCALL_64_after_hwframe+0x72/0xdc
> > [ 30.421282] RIP: 0033:0x7f3840f1059d
> > [ 30.421537] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 90 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 08 0f 05 <48> 3d 01 f0 8
> > [ 30.422690] RSP: 002b:00007ffd19fb73a8 EFLAGS: 00000202 ORIG_RAX: 0000000000000003
> > [ 30.423179] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00007f3840f1059d
> > [ 30.423630] RDX: 0000000000000010 RSI: 00007ffd19fb7370 RDI: 0000000000000003
> > [ 30.424081] RBP: 00007ffd19fb73c0 R08: 0000000000000001 R09: 00007ffd19fb73c0
> > [ 30.424531] R10: 0000000000000000 R11: 0000000000000202 R12: 0000000000401180
> > [ 30.424984] R13: 00007ffd19fb74e0 R14: 0000000000000000 R15: 0000000000000000
> > [ 30.425459] </TASK>
> > [ 30.425891] ------------[ cut here ]------------
> > [ 30.426223] Failed to disarm kprobe-ftrace at match_dev_by_uuid+0x4/0x100 (error -12)
> > [ 30.426785] WARNING: CPU: 1 PID: 510 at kernel/kprobes.c:1130 __disarm_kprobe_ftrace.isra.24+0x1ed/0x250
> > [ 30.427381] Modules linked in:
> > [ 30.427595] CPU: 1 PID: 510 Comm: repro Not tainted 6.2.0-rc7-4ec5183ec486 #1
> > [ 30.428052] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
> > [ 30.428759] RIP: 0010:__disarm_kprobe_ftrace.isra.24+0x1ed/0x250
> > [ 30.429156] Code: 37 f5 05 01 48 b8 00 00 00 00 00 fc ff df 48 c1 ea 03 80 3c 02 00 75 64 49 8b 75 00 89 da 48 c7 c7 80 67 6f 85 e8 12 72 bf 03 <0f> 0b e9 03 a
> > [ 30.430300] RSP: 0018:ffff88800c387a90 EFLAGS: 00010282
> > [ 30.430642] RAX: 0000000000000000 RBX: 00000000fffffff4 RCX: ffffffff813dde2e
> > [ 30.431124] RDX: 0000000000000000 RSI: ffff8880125e0000 RDI: 0000000000000002
> > [ 30.431575] RBP: ffff88800c387ab0 R08: ffffed1001870f0b R09: ffffed1001870f0b
> > [ 30.432028] R10: ffff88800c387857 R11: ffffed1001870f0a R12: 0000000000000000
> > [ 30.432483] R13: ffff88800a4a9040 R14: ffffffff875a0ea0 R15: ffff88800a4a9090
> > [ 30.432940] FS: 00007f3840deb740(0000) GS:ffff88806cd00000(0000) knlGS:0000000000000000
> > [ 30.433467] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [ 30.433847] CR2: 00007f3840e4d700 CR3: 0000000011a84001 CR4: 0000000000770ee0
> > [ 30.434301] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > [ 30.434782] DR3: 0000000000000000 DR6: 00000000ffff07f0 DR7: 0000000000000400
> > [ 30.435234] PKRU: 55555554
> > [ 30.435418] Call Trace:
> > [ 30.435588] <TASK>
> > [ 30.435743] disarm_kprobe+0x24a/0x2d0
> > [ 30.436011] __disable_kprobe+0x2de/0x4b0
> > [ 30.436295] disable_kprobe+0x31/0x80
> > [ 30.436552] __disable_trace_kprobe+0xfb/0x1c0
> > [ 30.436862] disable_trace_kprobe+0x1f0/0x300
> > [ 30.437165] kprobe_register+0x4e/0xf0
> > [ 30.437429] perf_trace_event_unreg.isra.3+0xb6/0x1f0
> > [ 30.437778] perf_kprobe_destroy+0xcb/0x200
> > [ 30.438077] ? __pfx_perf_kprobe_destroy+0x10/0x10
> > [ 30.438407] _free_event+0x220/0x11c0
> > [ 30.438707] put_event+0x4d/0x60
> > [ 30.438938] perf_event_release_kernel+0x5d9/0x860
> > [ 30.439275] ? __pfx_perf_event_release_kernel+0x10/0x10
> > [ 30.439633] ? write_comp_data+0x2f/0x90
> > [ 30.439913] ? __sanitizer_cov_trace_pc+0x25/0x60
> > [ 30.440245] ? __pfx_perf_release+0x10/0x10
> > [ 30.440533] perf_release+0x40/0x50
> > [ 30.440780] __fput+0x26d/0xa40
> > [ 30.441020] ____fput+0x1e/0x30
> > [ 30.441246] task_work_run+0x1a4/0x2d0
> > [ 30.441509] ? write_comp_data+0x2f/0x90
> > [ 30.441794] ? __pfx_task_work_run+0x10/0x10
> > [ 30.442090] ? __this_cpu_preempt_check+0x20/0x30
> > [ 30.442389] ? lockdep_hardirqs_on+0x8a/0x110
> > [ 30.442705] ? exit_to_user_mode_prepare+0x100/0x210
> > [ 30.443042] exit_to_user_mode_prepare+0x200/0x210
> > [ 30.443366] syscall_exit_to_user_mode+0x2d/0x60
> > [ 30.443683] do_syscall_64+0x4a/0x90
> > [ 30.443937] entry_SYSCALL_64_after_hwframe+0x72/0xdc
> > [ 30.444281] RIP: 0033:0x7f3840f1059d
> > [ 30.444530] Code: 00 c3 66 2e 0f 1f 84 00 00 00 00 00 90 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 08 0f 05 <48> 3d 01 f0 8
> > [ 30.445701] RSP: 002b:00007ffd19fb73a8 EFLAGS: 00000202 ORIG_RAX: 0000000000000003
> > [ 30.446211] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00007f3840f1059d
> > [ 30.446716] RDX: 0000000000000010 RSI: 00007ffd19fb7370 RDI: 0000000000000003
> > [ 30.447193] RBP: 00007ffd19fb73c0 R08: 0000000000000001 R09: 00007ffd19fb73c0
> > [ 30.447661] R10: 0000000000000000 R11: 0000000000000202 R12: 0000000000401180
> > [ 30.448128] R13: 00007ffd19fb74e0 R14: 0000000000000000 R15: 0000000000000000
> > [ 30.448618] </TASK>
> > [ 30.448787] irq event stamp: 2017
> > [ 30.449020] hardirqs last enabled at (2025): [<ffffffff813dd0a1>] __up_console_sem+0x91/0xb0
> > [ 30.449594] hardirqs last disabled at (2032): [<ffffffff813dd086>] __up_console_sem+0x76/0xb0
> > [ 30.450803] softirqs last enabled at (1974): [<ffffffff8536af3f>] __do_softirq+0x53f/0x836
> > [ 30.452095] softirqs last disabled at (1965): [<ffffffff812498b0>] irq_exit_rcu+0x100/0x140
> > [ 30.453375] ---[ end trace 0000000000000000 ]---
> >
> > Bisected and found the first bad commit is:
> > 71a7507afbc3f27c346898f13ab9bfd918613c34
> > Merge tag 'driver-core-6.2-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/driver-core
>
> A merge point is usually not a problem, unless the merge point actually
> has changed code? Are you sure your bisection is correct?
>
> But again, you are injecting faults, and a fault happened, what are you
> trying to actually test here?
Yes, there is no abnormal behavior in regular test in this merge point.
I didn't change the code and it may not be a real problem since it's a test
triggered by fault injection.
Please ignore this email and I will confirm that fault injection related
incidents are real issues and report them next time.
Thanks!
BR.
>
> thanks,
>
> greg k-h