Following kernel crash noticed on x86_64 while running selftests ftracetests
running 6.6.0-rc7-next-20231026.
Reported-by: Linux Kernel Functional Testing <[email protected]>
log:
-----
# ok 44 ftrace - test for function traceon/off triggers
# ok 45 ftrace - test tracing error log support
# ok 46 Test creation and deletion of trace instances while setting an event
[ 1402.419605] BUG: kernel NULL pointer dereference, address: 0000000000000097
[ 1402.426574] #PF: supervisor read access in kernel mode
[ 1402.431715] #PF: error_code(0x0000) - not-present page
[ 1402.436852] PGD 0 P4D 0
[ 1402.439393] Oops: 0000 [#1] PREEMPT SMP PTI
[ 1402.443578] CPU: 0 PID: 18196 Comm: ls Not tainted 6.6.0-rc7-next-20231026 #1
[ 1402.450711] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.7 12/07/2021
[ 1402.458102] RIP: 0010:__lock_acquire (kernel/locking/lockdep.c:5005)
[ 1402.462722] Code: 4d d4 53 45 85 f6 0f 84 a5 06 00 00 44 8b 2d 8d
c2 bf 02 45 89 c2 49 89 fb 89 f3 41 89 d6 45 89 c8 45 85 ed 0f 84 ca
02 00 00 <48> 81 3f c0 2b f1 af 44 0f 44 d0 83 fb 01 0f 86 c2 02 00 00
31 d2
All code
========
0: 4d d4 rex.WRB (bad)
2: 53 push %rbx
3: 45 85 f6 test %r14d,%r14d
6: 0f 84 a5 06 00 00 je 0x6b1
c: 44 8b 2d 8d c2 bf 02 mov 0x2bfc28d(%rip),%r13d # 0x2bfc2a0
13: 45 89 c2 mov %r8d,%r10d
16: 49 89 fb mov %rdi,%r11
19: 89 f3 mov %esi,%ebx
1b: 41 89 d6 mov %edx,%r14d
1e: 45 89 c8 mov %r9d,%r8d
21: 45 85 ed test %r13d,%r13d
24: 0f 84 ca 02 00 00 je 0x2f4
2a:* 48 81 3f c0 2b f1 af cmpq $0xffffffffaff12bc0,(%rdi) <--
trapping instruction
31: 44 0f 44 d0 cmove %eax,%r10d
35: 83 fb 01 cmp $0x1,%ebx
38: 0f 86 c2 02 00 00 jbe 0x300
3e: 31 d2 xor %edx,%edx
Code starting with the faulting instruction
===========================================
0: 48 81 3f c0 2b f1 af cmpq $0xffffffffaff12bc0,(%rdi)
7: 44 0f 44 d0 cmove %eax,%r10d
b: 83 fb 01 cmp $0x1,%ebx
e: 0f 86 c2 02 00 00 jbe 0x2d6
14: 31 d2 xor %edx,%edx
[ 1402.481497] RSP: 0018:ffff9b3041327998 EFLAGS: 00010002
[ 1402.486719] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[ 1402.493843] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000097
[ 1402.500967] RBP: ffff9b3041327a38 R08: 0000000000000000 R09: 0000000000000000
[ 1402.508092] R10: 0000000000000001 R11: 0000000000000097 R12: ffff8de420f38040
[ 1402.515225] R13: 0000000000000001 R14: 0000000000000000 R15: 0000000000000000
[ 1402.522348] FS: 00007f52d72a1d00(0000) GS:ffff8de767a00000(0000)
knlGS:0000000000000000
[ 1402.530438] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1402.536224] CR2: 0000000000000097 CR3: 000000012201e005 CR4: 00000000003706f0
[ 1402.543354] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 1402.550479] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 1402.557602] Call Trace:
[ 1402.560049] <TASK>
[ 1402.562153] ? show_regs (arch/x86/kernel/dumpstack.c:479)
[ 1402.565559] ? __die (arch/x86/kernel/dumpstack.c:421
arch/x86/kernel/dumpstack.c:434)
[ 1402.568611] ? page_fault_oops (arch/x86/mm/fault.c:707)
[ 1402.572711] ? __lock_acquire (kernel/locking/lockdep.c:186
kernel/locking/lockdep.c:3872 kernel/locking/lockdep.c:5136)
[ 1402.576811] ? do_user_addr_fault (arch/x86/mm/fault.c:1264)
[ 1402.581170] ? exc_page_fault (arch/x86/include/asm/irqflags.h:26
arch/x86/include/asm/irqflags.h:67 arch/x86/include/asm/irqflags.h:127
arch/x86/mm/fault.c:1513 arch/x86/mm/fault.c:1561)
[ 1402.585094] ? asm_exc_page_fault (arch/x86/include/asm/idtentry.h:570)
[ 1402.589283] ? __lock_acquire (kernel/locking/lockdep.c:5005)
[ 1402.593296] ? lock_acquire (kernel/locking/lockdep.c:467
(discriminator 4) kernel/locking/lockdep.c:5755 (discriminator 4)
kernel/locking/lockdep.c:5718 (discriminator 4))
[ 1402.597045] ? create_dir_dentry.part.0
(fs/tracefs/event_inode.c:357 (discriminator 1))
[ 1402.601928] lock_acquire (kernel/locking/lockdep.c:467
(discriminator 4) kernel/locking/lockdep.c:5755 (discriminator 4)
kernel/locking/lockdep.c:5718 (discriminator 4))
[ 1402.605503] ? d_invalidate (fs/dcache.c:1725 (discriminator 1))
[ 1402.609170] ? lock_release (kernel/locking/lockdep.c:5429
kernel/locking/lockdep.c:5773)
[ 1402.612923] ? create_dir_dentry.part.0 (fs/tracefs/event_inode.c:387)
[ 1402.617803] _raw_spin_lock (include/linux/spinlock_api_smp.h:134
kernel/locking/spinlock.c:154)
[ 1402.621467] ? d_invalidate (fs/dcache.c:1725 (discriminator 1))
[ 1402.625126] d_invalidate (fs/dcache.c:1725 (discriminator 1))
[ 1402.628619] create_dir_dentry.part.0 (fs/tracefs/event_inode.c:390)
[ 1402.633324] dcache_dir_open_wrapper (fs/tracefs/event_inode.c:586)
[ 1402.637945] ? __pfx_dcache_dir_open_wrapper (fs/tracefs/event_inode.c:536)
[ 1402.643081] do_dentry_open (fs/open.c:948)
[ 1402.646924] vfs_open (fs/open.c:1083)
[ 1402.650069] path_openat (fs/namei.c:3623 fs/namei.c:3779)
[ 1402.653648] do_filp_open (fs/namei.c:3810 (discriminator 2))
[ 1402.657233] do_sys_openat2 (fs/open.c:1441 (discriminator 1))
[ 1402.660911] __x64_sys_openat (fs/open.c:1466)
[ 1402.664749] do_syscall_64 (arch/x86/entry/common.c:51
arch/x86/entry/common.c:82)
[ 1402.668328] ? syscall_exit_to_user_mode (kernel/entry/common.c:299)
[ 1402.673120] ? do_syscall_64 (arch/x86/entry/common.c:101)
[ 1402.676864] ? do_syscall_64 (arch/x86/entry/common.c:101)
[ 1402.680607] ? do_syscall_64 (arch/x86/entry/common.c:101)
[ 1402.684352] ? syscall_exit_to_user_mode (kernel/entry/common.c:299)
[ 1402.689136] ? do_syscall_64 (arch/x86/entry/common.c:101)
[ 1402.692880] ? syscall_exit_to_user_mode (kernel/entry/common.c:299)
[ 1402.697666] ? do_syscall_64 (arch/x86/entry/common.c:101)
[ 1402.701440] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:129)
[ 1402.706512] RIP: 0033:0x7f52d7439df1
[ 1402.710082] Code: 44 24 18 31 c0 41 83 e2 40 75 3e 89 f0 25 00 00
41 00 3d 00 00 41 00 74 30 89 f2 b8 01 01 00 00 48 89 fe bf 9c ff ff
ff 0f 05 <48> 3d 00 f0 ff ff 77 3f 48 8b 54 24 18 64 48 2b 14 25 28 00
00 00
All code
========
0: 44 24 18 rex.R and $0x18,%al
3: 31 c0 xor %eax,%eax
5: 41 83 e2 40 and $0x40,%r10d
9: 75 3e jne 0x49
b: 89 f0 mov %esi,%eax
d: 25 00 00 41 00 and $0x410000,%eax
12: 3d 00 00 41 00 cmp $0x410000,%eax
17: 74 30 je 0x49
19: 89 f2 mov %esi,%edx
1b: b8 01 01 00 00 mov $0x101,%eax
20: 48 89 fe mov %rdi,%rsi
23: bf 9c ff ff ff mov $0xffffff9c,%edi
28: 0f 05 syscall
2a:* 48 3d 00 f0 ff ff cmp $0xfffffffffffff000,%rax <--
trapping instruction
30: 77 3f ja 0x71
32: 48 8b 54 24 18 mov 0x18(%rsp),%rdx
37: 64 48 2b 14 25 28 00 sub %fs:0x28,%rdx
3e: 00 00
Code starting with the faulting instruction
===========================================
0: 48 3d 00 f0 ff ff cmp $0xfffffffffffff000,%rax
6: 77 3f ja 0x47
8: 48 8b 54 24 18 mov 0x18(%rsp),%rdx
d: 64 48 2b 14 25 28 00 sub %fs:0x28,%rdx
14: 00 00
[ 1402.728821] RSP: 002b:00007fff2270ba90 EFLAGS: 00000287 ORIG_RAX:
0000000000000101
[ 1402.736388] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f52d7439df1
[ 1402.743520] RDX: 0000000000090800 RSI: 0000558fb3992090 RDI: 00000000ffffff9c
[ 1402.750651] RBP: 0000000000000000 R08: 0000000000000007 R09: 0000558fb3992250
[ 1402.757775] R10: 0000000000000000 R11: 0000000000000287 R12: 00007f52d72a1b98
[ 1402.764900] R13: 00007fff2270bee0 R14: 0000558fb3992090 R15: 0000558fb28aafc8
[ 1402.772027] </TASK>
[ 1402.774216] Modules linked in: x86_pkg_temp_thermal fuse configfs
[last unloaded: trace_printk]
[ 1402.782908] CR2: 0000000000000097
[ 1402.786220] ---[ end trace 0000000000000000 ]---
[ 1402.790839] RIP: 0010:__lock_acquire (kernel/locking/lockdep.c:5005)
[ 1402.795468] Code: 4d d4 53 45 85 f6 0f 84 a5 06 00 00 44 8b 2d 8d
c2 bf 02 45 89 c2 49 89 fb 89 f3 41 89 d6 45 89 c8 45 85 ed 0f 84 ca
02 00 00 <48> 81 3f c0 2b f1 af 44 0f 44 d0 83 fb 01 0f 86 c2 02 00 00
31 d2
All code
========
0: 4d d4 rex.WRB (bad)
2: 53 push %rbx
3: 45 85 f6 test %r14d,%r14d
6: 0f 84 a5 06 00 00 je 0x6b1
c: 44 8b 2d 8d c2 bf 02 mov 0x2bfc28d(%rip),%r13d # 0x2bfc2a0
13: 45 89 c2 mov %r8d,%r10d
16: 49 89 fb mov %rdi,%r11
19: 89 f3 mov %esi,%ebx
1b: 41 89 d6 mov %edx,%r14d
1e: 45 89 c8 mov %r9d,%r8d
21: 45 85 ed test %r13d,%r13d
24: 0f 84 ca 02 00 00 je 0x2f4
2a:* 48 81 3f c0 2b f1 af cmpq $0xffffffffaff12bc0,(%rdi) <--
trapping instruction
31: 44 0f 44 d0 cmove %eax,%r10d
35: 83 fb 01 cmp $0x1,%ebx
38: 0f 86 c2 02 00 00 jbe 0x300
3e: 31 d2 xor %edx,%edx
Code starting with the faulting instruction
===========================================
0: 48 81 3f c0 2b f1 af cmpq $0xffffffffaff12bc0,(%rdi)
7: 44 0f 44 d0 cmove %eax,%r10d
b: 83 fb 01 cmp $0x1,%ebx
e: 0f 86 c2 02 00 00 jbe 0x2d6
14: 31 d2 xor %edx,%edx
[ 1402.814213] RSP: 0018:ffff9b3041327998 EFLAGS: 00010002
[ 1402.819439] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000000
[ 1402.826587] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000097
[ 1402.833711] RBP: ffff9b3041327a38 R08: 0000000000000000 R09: 0000000000000000
[ 1402.840836] R10: 0000000000000001 R11: 0000000000000097 R12: ffff8de420f38040
[ 1402.847959] R13: 0000000000000001 R14: 0000000000000000 R15: 0000000000000000
[ 1402.855083] FS: 00007f52d72a1d00(0000) GS:ffff8de767a00000(0000)
knlGS:0000000000000000
[ 1402.863161] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1402.868897] CR2: 0000000000000097 CR3: 000000012201e005 CR4: 00000000003706f0
[ 1402.876023] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 1402.883154] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 1402.890280] Kernel panic - not syncing: Fatal exception
[ 1402.895543] Kernel Offset: 0x2b000000 from 0xffffffff81000000
(relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[ 1402.906322] ---[ end Kernel panic - not syncing: Fatal exception ]---
Links:
- https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20231026/testrun/20823466/suite/log-parser-test/tests/
- https://lkft.validation.linaro.org/scheduler/job/6974183#L5240
metadata:
git_ref: master
git_repo: https://gitlab.com/Linaro/lkft/mirrors/next/linux-next
git_sha: 2ef7141596eed0b4b45ef18b3626f428a6b0a822
git_describe: next-20231026
kernel-config:
https://storage.tuxsuite.com/public/linaro/lkft/builds/2XHt24sNSdog7DYY3FLKFZpZmjG/config
artifact-location:
https://storage.tuxsuite.com/public/linaro/lkft/builds/2XHt24sNSdog7DYY3FLKFZpZmjG/
toolchain: gcc-13
--
Linaro LKFT
https://lkft.linaro.org
On Fri, Oct 27, 2023, at 13:47, Naresh Kamboju wrote:
> Following kernel crash noticed on x86_64 while running selftests ftracetests
> running 6.6.0-rc7-next-20231026.
>
> Reported-by: Linux Kernel Functional Testing <[email protected]>
My guess would be that this is caused by 5790b1fb3d67 ("eventfs:
Remove eventfs_file and just use eventfs_inode"), in which
Steven Rostedt recently added the create_dir_dentry() function
through a rewrite:
> log:
> -----
> # ok 44 ftrace - test for function traceon/off triggers
> # ok 45 ftrace - test tracing error log support
> # ok 46 Test creation and deletion of trace instances while setting an event
> [ 1402.419605] BUG: kernel NULL pointer dereference, address: 0000000000000097
> [ 1402.426574] #PF: supervisor read access in kernel mode
...
> [ 1402.581170] ? exc_page_fault (arch/x86/include/asm/irqflags.h:26
> arch/x86/include/asm/irqflags.h:67 arch/x86/include/asm/irqflags.h:127
> arch/x86/mm/fault.c:1513 arch/x86/mm/fault.c:1561)
> [ 1402.585094] ? asm_exc_page_fault (arch/x86/include/asm/idtentry.h:570)
> [ 1402.589283] ? __lock_acquire (kernel/locking/lockdep.c:5005)
> [ 1402.593296] ? lock_acquire (kernel/locking/lockdep.c:467
> (discriminator 4) kernel/locking/lockdep.c:5755 (discriminator 4)
> kernel/locking/lockdep.c:5718 (discriminator 4))
The lock passed to spin_lock() and lock_acquire() is a NULL
pointer.
> [ 1402.597045] ? create_dir_dentry.part.0
> (fs/tracefs/event_inode.c:357 (discriminator 1))
> [ 1402.601928] lock_acquire (kernel/locking/lockdep.c:467
> (discriminator 4) kernel/locking/lockdep.c:5755 (discriminator 4)
> kernel/locking/lockdep.c:5718 (discriminator 4))
> [ 1402.605503] ? d_invalidate (fs/dcache.c:1725 (discriminator 1))
This lock is part of the dentry passed to d_invalidate()
> [ 1402.609170] ? lock_release (kernel/locking/lockdep.c:5429
> kernel/locking/lockdep.c:5773)
> [ 1402.612923] ? create_dir_dentry.part.0 (fs/tracefs/event_inode.c:387)
> [ 1402.617803] _raw_spin_lock (include/linux/spinlock_api_smp.h:134
> kernel/locking/spinlock.c:154)
> [ 1402.621467] ? d_invalidate (fs/dcache.c:1725 (discriminator 1))
> [ 1402.625126] d_invalidate (fs/dcache.c:1725 (discriminator 1))
> [ 1402.628619] create_dir_dentry.part.0 (fs/tracefs/event_inode.c:390)
Which is called by create_dir_dentry(). I don't see a bug
in that function, but maybe Steve has an idea.
Arnd
On Fri, 27 Oct 2023 14:55:14 +0200
"Arnd Bergmann" <[email protected]> wrote:
> This lock is part of the dentry passed to d_invalidate()
>
> > [ 1402.609170] ? lock_release (kernel/locking/lockdep.c:5429
> > kernel/locking/lockdep.c:5773)
> > [ 1402.612923] ? create_dir_dentry.part.0 (fs/tracefs/event_inode.c:387)
> > [ 1402.617803] _raw_spin_lock (include/linux/spinlock_api_smp.h:134
> > kernel/locking/spinlock.c:154)
> > [ 1402.621467] ? d_invalidate (fs/dcache.c:1725 (discriminator 1))
> > [ 1402.625126] d_invalidate (fs/dcache.c:1725 (discriminator 1))
> > [ 1402.628619] create_dir_dentry.part.0 (fs/tracefs/event_inode.c:390)
>
> Which is called by create_dir_dentry(). I don't see a bug
> in that function, but maybe Steve has an idea.
>
>
I see a bug ;-)
Can you test this patch?
Thanks!
-- Steve
diff --git a/fs/tracefs/event_inode.c b/fs/tracefs/event_inode.c
index 4d2da7480e5f..ef003149e4d3 100644
--- a/fs/tracefs/event_inode.c
+++ b/fs/tracefs/event_inode.c
@@ -234,6 +234,10 @@ create_file_dentry(struct eventfs_inode *ei, struct dentry **e_dentry,
bool invalidate = false;
mutex_lock(&eventfs_mutex);
+ if (ei->is_freed) {
+ mutex_unlock(&eventfs_mutex);
+ return NULL;
+ }
/* If the e_dentry already has a dentry, use it */
if (*e_dentry) {
/* lookup does not need to up the ref count */
@@ -333,6 +337,10 @@ create_dir_dentry(struct eventfs_inode *ei, struct dentry *parent, bool lookup)
struct dentry *dentry = NULL;
mutex_lock(&eventfs_mutex);
+ if (ei->is_freed) {
+ mutex_unlock(&eventfs_mutex);
+ return NULL;
+ }
if (ei->dentry) {
/* If the dentry already has a dentry, use it */
dentry = ei->dentry;
--
2.42.0