Re: [Syzkaller & bisect] There is "register_kprobe" WARNING in v6.2-rc3 mainline kernel

From: Google
Date: Thu Jan 19 2023 - 18:57:57 EST

Next message: David Vernet: "[PATCH bpf-next 0/8] Enable cpumasks to be used as kptrs"
Previous message: Bryan O'Donoghue: "Re: [PATCH] interconnect: Skip call into provider if initial bw is zero"
In reply to: Pengfei Xu: "[Syzkaller & bisect] There is "register_kprobe" WARNING in v6.2-rc3 mainline kernel"
Next in thread: Masami Hiramatsu (Google): "[PATCH] kprobes: Fix to handle forcibly unoptimized kprobes on freeing_list"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Mon, 16 Jan 2023 16:57:24 +0800
Pengfei Xu <pengfei.xu@xxxxxxxxx> wrote:

> Hi Masami Hiramatsu,
>
> There is "register_kprobe" WARNING in v6.2-rc3 in guest.
> [ 120.736243] ------------[ cut here ]------------
> [ 120.736691] WARNING: CPU: 0 PID: 366 at kernel/kprobes.c:589 kprobe_optimizer+0x26b/0x400
> [ 120.737161] Modules linked in:
> [ 120.737339] CPU: 0 PID: 366 Comm: kworker/0:7 Not tainted 6.2.0-rc3-b7bfaa761d76 #1
> [ 120.737831] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
> [ 120.738416] Workqueue: events kprobe_optimizer
> [ 120.738683] RIP: 0010:kprobe_optimizer+0x26b/0x400
> [ 120.739026] Code: c3 ff ff 4c 8b 25 25 28 b5 02 4d 8b 2c 24 49 8d 5c 24 80 4d 8d 75 80 49 81 fc f0 7e e1 83 75 2f e9 a9 00 00 00 e8 75 c3 ff ff <0f> 0b e8 6e c
> [ 120.740035] RSP: 0018:ffffc90000ebfe10 EFLAGS: 00010246
> [ 120.740394] RAX: 0000000000000000 RBX: ffff88800d094180 RCX: ffffffff812c5752
> [ 120.740763] RDX: 0000000000000000 RSI: ffff88800eed8000 RDI: 0000000000000002
> [ 120.741129] RBP: ffffc90000ebfe38 R08: 0000000000000001 R09: 0000000000000001
> [ 120.741552] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000000
> [ 120.741953] R13: ffffffff83e17ef0 R14: ffffffff83e17e70 R15: ffff88807dc3a400
> [ 120.742319] FS: 0000000000000000(0000) GS:ffff88807dc00000(0000) knlGS:0000000000000000
> [ 120.742778] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 120.743125] CR2: 00007ffff951d3f8 CR3: 00000000131bc006 CR4: 0000000000770ef0
> [ 120.743503] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 120.743868] DR3: 0000000000000000 DR6: 00000000ffff07f0 DR7: 0000000000000400
> [ 120.744339] PKRU: 55555554
> [ 120.744495] Call Trace:
> [ 120.744633] <TASK>
> [ 120.744764] process_one_work+0x3b1/0x960
> [ 120.745002] worker_thread+0x52/0x660
> [ 120.745228] ? __pfx_worker_thread+0x10/0x10
> [ 120.745536] kthread+0x161/0x1a0
> [ 120.745748] ? __pfx_kthread+0x10/0x10
> [ 120.745968] ret_from_fork+0x29/0x50
> [ 120.746192] </TASK>
> [ 120.746321] irq event stamp: 71069
> [ 120.746523] hardirqs last enabled at (71077): [<ffffffff811d4891>] __up_console_sem+0x91/0xb0
> [ 120.747078] hardirqs last disabled at (71084): [<ffffffff811d4876>] __up_console_sem+0x76/0xb0
> [ 120.747529] softirqs last enabled at (70986): [<ffffffff82f9d213>] __do_softirq+0x323/0x48a
> [ 120.748051] softirqs last disabled at (71101): [<ffffffff81123142>] irq_exit_rcu+0xd2/0x100
> [ 120.748562] ---[ end trace 0000000000000000 ]---
> [ 149.825325] ------------[ cut here ]------------
> [ 149.825894] WARNING: CPU: 0 PID: 2872 at kernel/kprobes.c:777 register_kprobe+0x9a2/0x9b0
> [ 149.826370] Modules linked in:
> [ 149.826548] CPU: 0 PID: 2872 Comm: repro Tainted: G W 6.2.0-rc3-b7bfaa761d76 #1
> [ 149.827010] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.14.0-0-g155821a1990b-prebuilt.qemu.org 04/01/2014
> [ 149.827602] RIP: 0010:register_kprobe+0x9a2/0x9b0
> [ 149.827874] Code: 4d 89 74 24 08 e8 de 91 ff ff 45 89 ec 48 b8 22 01 00 00 00 00 ad de 48 89 43 08 e8 48 e4 f3 ff e9 d2 fd ff ff e8 be 91 ff ff <0f> 0b e9 4e 0
> [ 149.828872] RSP: 0018:ffffc90001aafc40 EFLAGS: 00010246
> [ 149.829162] RAX: 0000000000000000 RBX: ffff88800cefeb18 RCX: ffffffff812c86ba
> [ 149.829541] RDX: 0000000000000000 RSI: ffff88801324a340 RDI: 0000000000000002
> [ 149.829924] RBP: ffffc90001aafc88 R08: 0000000000000001 R09: 0000000000000001
> [ 149.830311] R10: ffffc90001aafc30 R11: 0000000000000001 R12: 0000000000000000
> [ 149.830697] R13: ffff88800d0949c0 R14: ffff88800cefeb28 R15: 0000000000000002
> [ 149.831089] FS: 00007fdc0d3c9740(0000) GS:ffff88807dc00000(0000) knlGS:0000000000000000
> [ 149.831525] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 149.831844] CR2: 00007fdc0d5841d3 CR3: 000000000d70c006 CR4: 0000000000770ef0
> [ 149.832260] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 149.832637] DR3: 0000000000000000 DR6: 00000000ffff07f0 DR7: 0000000000000400
> [ 149.833021] PKRU: 55555554
> [ 149.833179] Call Trace:
> [ 149.833323] <TASK>
> [ 149.833458] ? knl_uncore_pci_init+0x9/0x90
> [ 149.833712] ? knl_uncore_pci_init+0x9/0x90
> [ 149.833959] __register_trace_kprobe+0x183/0x190
> [ 149.834241] create_local_trace_kprobe+0x107/0x190
> [ 149.834519] perf_kprobe_init+0xa7/0x160
> [ 149.834753] perf_kprobe_event_init+0x98/0x120
> [ 149.835024] perf_try_init_event+0x88/0x280
> [ 149.835274] perf_event_alloc+0xf0a/0x1c50
> [ 149.835514] ? __do_sys_perf_event_open+0x9ca/0x1870
> [ 149.835805] ? __this_cpu_preempt_check+0x20/0x30
> [ 149.836102] __do_sys_perf_event_open+0x3b6/0x1870
> [ 149.836388] ? knl_uncore_pci_init+0x9/0x90
> [ 149.836636] __x64_sys_perf_event_open+0x2f/0x40
> [ 149.836905] do_syscall_64+0x3b/0x90
> [ 149.837115] entry_SYSCALL_64_after_hwframe+0x72/0xdc
> [ 149.837417] RIP: 0033:0x7fdc0d4ee59d
> [ 149.837630] 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
> [ 149.838602] RSP: 002b:00007ffff951d3f8 EFLAGS: 00000246 ORIG_RAX: 000000000000012a
> [ 149.839036] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fdc0d4ee59d
> [ 149.839420] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 00000000200002c0
> [ 149.839800] RBP: 00007ffff951d410 R08: 0000000000000000 R09: 00007ffff951d410
> [ 149.840203] R10: 00000000ffffffff R11: 0000000000000246 R12: 00000000004011a0
> [ 149.840593] R13: 00007ffff951d530 R14: 0000000000000000 R15: 0000000000000000
> [ 149.840984] </TASK>
> [ 149.841120] irq event stamp: 1631
> [ 149.841303] hardirqs last enabled at (1639): [<ffffffff811d4891>] __up_console_sem+0x91/0xb0
> [ 149.841825] hardirqs last disabled at (1646): [<ffffffff811d4876>] __up_console_sem+0x76/0xb0
> [ 149.842279] softirqs last enabled at (1304): [<ffffffff82f9d213>] __do_softirq+0x323/0x48a
> [ 149.842723] softirqs last disabled at (1295): [<ffffffff81123142>] irq_exit_rcu+0xd2/0x100
> [ 149.843179] ---[ end trace 0000000000000000 ]---
>
> Bisect and found that bad commit is:
> 63dc6325ff41ee9e570bde705ac34a39c5dbeb44
> x86/kprobes: Fix optprobe optimization check with CONFIG_RETHUNK

Oops, thanks for reporting. Let me check why this happened.

>
> After reverted the above commit on top of v6.2-rc3 kernel, this issue was gone.
>
> The reproduced code, kconfig, bisect info, and v6.2-rc3 reproduced log are in
> attached email.
>
> And all the detailed logs are in link:
> https://github.com/xupengfe/syzkaller_logs/tree/main/230113_100005_register_kprobe

Great, thanks!

>
> I hope it's helpful.
>
> Thanks!
> BR.

--
Masami Hiramatsu (Google) <mhiramat@xxxxxxxxxx>

Next message: David Vernet: "[PATCH bpf-next 0/8] Enable cpumasks to be used as kptrs"
Previous message: Bryan O'Donoghue: "Re: [PATCH] interconnect: Skip call into provider if initial bw is zero"
In reply to: Pengfei Xu: "[Syzkaller & bisect] There is "register_kprobe" WARNING in v6.2-rc3 mainline kernel"
Next in thread: Masami Hiramatsu (Google): "[PATCH] kprobes: Fix to handle forcibly unoptimized kprobes on freeing_list"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]