INFO: task hung in path

linux-fsdevel.vger.kernel.org archive mirror
 help / color / mirror / Atom feed

* INFO: task hung in path_openat
@ 2022-01-11  2:15 cruise k
  2022-01-11  3:39 ` Matthew Wilcox
  0 siblings, 1 reply; 6+ messages in thread
From: cruise k @ 2022-01-11  2:15 UTC (permalink / raw)
  To: Alexander Viro, linux-fsdevel, linux-kernel; +Cc: sunhao.th

Hi,

Syzkaller found the following issue:

HEAD commit: 75acfdb Linux 5.16-rc8
git tree: upstream
console output: https://pastebin.com/raw/7TSe1kGF
kernel config: https://pastebin.com/raw/XsnKfdRt

And hope the report log can help you.

INFO: task systemd-udevd:27429 blocked for more than 146 seconds.
      Not tainted 5.16.0-rc8+ #10
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:systemd-udevd   state:D stack:26528 pid:27429 ppid:  3127 flags:0x00000000
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:4972 [inline]
 __schedule+0xcd9/0x2550 kernel/sched/core.c:6253
 schedule+0xd2/0x260 kernel/sched/core.c:6326
 rwsem_down_write_slowpath+0x664/0x1190 kernel/locking/rwsem.c:1151
 __down_write_common kernel/locking/rwsem.c:1268 [inline]
 __down_write_common kernel/locking/rwsem.c:1265 [inline]
 __down_write kernel/locking/rwsem.c:1277 [inline]
 down_write+0x135/0x150 kernel/locking/rwsem.c:1524
 inode_lock include/linux/fs.h:783 [inline]
 open_last_lookups fs/namei.c:3347 [inline]
 path_openat+0xa66/0x26c0 fs/namei.c:3556
 do_filp_open+0x1c1/0x290 fs/namei.c:3586
 do_sys_openat2+0x61b/0x9a0 fs/open.c:1212
 do_sys_open+0xc3/0x140 fs/open.c:1228
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7fde8feb06f0
RSP: 002b:00007ffdc8b61368 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fde8feb06f0
RDX: 0000000000000180 RSI: 00000000000800c2 RDI: 00005624b8ca9880
RBP: 000000000003a2f8 R08: 000000000000fefe R09: 00007fde8ff03740
R10: 0000000000000000 R11: 0000000000000246 R12: 00005624b8ca9895
R13: 8421084210842109 R14: 00000000000800c2 R15: 00007fde8ff3e540
 </TASK>
INFO: task systemd-udevd:27467 blocked for more than 148 seconds.
      Not tainted 5.16.0-rc8+ #10
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:systemd-udevd   state:D stack:27072 pid:27467 ppid:  3127 flags:0x00000000
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:4972 [inline]
 __schedule+0xcd9/0x2550 kernel/sched/core.c:6253
 schedule+0xd2/0x260 kernel/sched/core.c:6326
 rwsem_down_write_slowpath+0x664/0x1190 kernel/locking/rwsem.c:1151
 __down_write_common kernel/locking/rwsem.c:1268 [inline]
 __down_write_common kernel/locking/rwsem.c:1265 [inline]
 __down_write kernel/locking/rwsem.c:1277 [inline]
 down_write+0x135/0x150 kernel/locking/rwsem.c:1524
 inode_lock include/linux/fs.h:783 [inline]
 open_last_lookups fs/namei.c:3347 [inline]
 path_openat+0xa66/0x26c0 fs/namei.c:3556
 do_filp_open+0x1c1/0x290 fs/namei.c:3586
 do_sys_openat2+0x61b/0x9a0 fs/open.c:1212
 do_sys_open+0xc3/0x140 fs/open.c:1228
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7fde8feb06f0
RSP: 002b:00007ffdc8b60d78 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fde8feb06f0
RDX: 0000000000000180 RSI: 00000000000800c2 RDI: 00005624b8c989c0
RBP: 000000000003a2f8 R08: 000000000000fcfe R09: 00007fde8ff03740
R10: 0000000000000000 R11: 0000000000000246 R12: 00005624b8c989d6
R13: 8421084210842109 R14: 00000000000800c2 R15: 00007fde8ff3e540
 </TASK>
INFO: task systemd-udevd:27515 blocked for more than 150 seconds.
      Not tainted 5.16.0-rc8+ #10
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:systemd-udevd   state:D stack:27584 pid:27515 ppid:  3127 flags:0x00004000
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:4972 [inline]
 __schedule+0xcd9/0x2550 kernel/sched/core.c:6253
 schedule+0xd2/0x260 kernel/sched/core.c:6326
 rwsem_down_write_slowpath+0x664/0x1190 kernel/locking/rwsem.c:1151
 __down_write_common kernel/locking/rwsem.c:1268 [inline]
 __down_write_common kernel/locking/rwsem.c:1265 [inline]
 __down_write kernel/locking/rwsem.c:1277 [inline]
 down_write+0x135/0x150 kernel/locking/rwsem.c:1524
 inode_lock include/linux/fs.h:783 [inline]
 open_last_lookups fs/namei.c:3347 [inline]
 path_openat+0xa66/0x26c0 fs/namei.c:3556
 do_filp_open+0x1c1/0x290 fs/namei.c:3586
 do_sys_openat2+0x61b/0x9a0 fs/open.c:1212
 do_sys_open+0xc3/0x140 fs/open.c:1228
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7fde8feb06f0
RSP: 002b:00007ffdc8b60d78 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fde8feb06f0
RDX: 0000000000000180 RSI: 00000000000800c2 RDI: 00005624b8cad110
RBP: 000000000003a2f8 R08: 000000000000fefe R09: 00007fde8ff03740
R10: 0000000000000000 R11: 0000000000000246 R12: 00005624b8cad126
R13: 8421084210842109 R14: 00000000000800c2 R15: 00007fde8ff3e540
 </TASK>
INFO: task systemd-udevd:27530 blocked for more than 153 seconds.
      Not tainted 5.16.0-rc8+ #10
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
task:systemd-udevd   state:D stack:26048 pid:27530 ppid:  3127 flags:0x00000000
Call Trace:
 <TASK>
 context_switch kernel/sched/core.c:4972 [inline]
 __schedule+0xcd9/0x2550 kernel/sched/core.c:6253
 schedule+0xd2/0x260 kernel/sched/core.c:6326
 rwsem_down_write_slowpath+0x664/0x1190 kernel/locking/rwsem.c:1151
 __down_write_common kernel/locking/rwsem.c:1268 [inline]
 __down_write_common kernel/locking/rwsem.c:1265 [inline]
 __down_write kernel/locking/rwsem.c:1277 [inline]
 down_write+0x135/0x150 kernel/locking/rwsem.c:1524
 inode_lock include/linux/fs.h:783 [inline]
 open_last_lookups fs/namei.c:3347 [inline]
 path_openat+0xa66/0x26c0 fs/namei.c:3556
 do_filp_open+0x1c1/0x290 fs/namei.c:3586
 do_sys_openat2+0x61b/0x9a0 fs/open.c:1212
 do_sys_open+0xc3/0x140 fs/open.c:1228
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x44/0xae
RIP: 0033:0x7fde8feb06f0
RSP: 002b:00007ffdc8b61368 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fde8feb06f0
RDX: 0000000000000180 RSI: 00000000000800c2 RDI: 00005624b8ca9880
RBP: 000000000003a2f8 R08: 000000000000fefe R09: 00007fde8ff03740
R10: 0000000000000000 R11: 0000000000000246 R12: 00005624b8ca9896
R13: 8421084210842109 R14: 00000000000800c2 R15: 00007fde8ff3e540
 </TASK>

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: INFO: task hung in path_openat
  2022-01-11  2:15 INFO: task hung in path_openat cruise k
@ 2022-01-11  3:39 ` Matthew Wilcox
       [not found]   ` <CANp29Y5tjwYLk3WdfjmsQy3qXbk6V8vW1vERRSTHsAhpzzMGpg@mail.gmail.com>
  0 siblings, 1 reply; 6+ messages in thread
From: Matthew Wilcox @ 2022-01-11  3:39 UTC (permalink / raw)
  To: cruise k, Dmitry Vyukov
  Cc: Alexander Viro, linux-fsdevel, linux-kernel, sunhao.th, syzkaller

Dmitry,

Please stop syzbot from playing with the SCHED_FIFO setting.
We're being inundated with these useless bug reports.

On Tue, Jan 11, 2022 at 10:15:26AM +0800, cruise k wrote:
> Hi,
> 
> Syzkaller found the following issue:
> 
> HEAD commit: 75acfdb Linux 5.16-rc8
> git tree: upstream
> console output: https://pastebin.com/raw/7TSe1kGF
> kernel config: https://pastebin.com/raw/XsnKfdRt
> 
> And hope the report log can help you.
> 
> INFO: task systemd-udevd:27429 blocked for more than 146 seconds.
>       Not tainted 5.16.0-rc8+ #10
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:systemd-udevd   state:D stack:26528 pid:27429 ppid:  3127 flags:0x00000000
> Call Trace:
>  <TASK>
>  context_switch kernel/sched/core.c:4972 [inline]
>  __schedule+0xcd9/0x2550 kernel/sched/core.c:6253
>  schedule+0xd2/0x260 kernel/sched/core.c:6326
>  rwsem_down_write_slowpath+0x664/0x1190 kernel/locking/rwsem.c:1151
>  __down_write_common kernel/locking/rwsem.c:1268 [inline]
>  __down_write_common kernel/locking/rwsem.c:1265 [inline]
>  __down_write kernel/locking/rwsem.c:1277 [inline]
>  down_write+0x135/0x150 kernel/locking/rwsem.c:1524
>  inode_lock include/linux/fs.h:783 [inline]
>  open_last_lookups fs/namei.c:3347 [inline]
>  path_openat+0xa66/0x26c0 fs/namei.c:3556
>  do_filp_open+0x1c1/0x290 fs/namei.c:3586
>  do_sys_openat2+0x61b/0x9a0 fs/open.c:1212
>  do_sys_open+0xc3/0x140 fs/open.c:1228
>  do_syscall_x64 arch/x86/entry/common.c:50 [inline]
>  do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80
>  entry_SYSCALL_64_after_hwframe+0x44/0xae
> RIP: 0033:0x7fde8feb06f0
> RSP: 002b:00007ffdc8b61368 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
> RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fde8feb06f0
> RDX: 0000000000000180 RSI: 00000000000800c2 RDI: 00005624b8ca9880
> RBP: 000000000003a2f8 R08: 000000000000fefe R09: 00007fde8ff03740
> R10: 0000000000000000 R11: 0000000000000246 R12: 00005624b8ca9895
> R13: 8421084210842109 R14: 00000000000800c2 R15: 00007fde8ff3e540
>  </TASK>
> INFO: task systemd-udevd:27467 blocked for more than 148 seconds.
>       Not tainted 5.16.0-rc8+ #10
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:systemd-udevd   state:D stack:27072 pid:27467 ppid:  3127 flags:0x00000000
> Call Trace:
>  <TASK>
>  context_switch kernel/sched/core.c:4972 [inline]
>  __schedule+0xcd9/0x2550 kernel/sched/core.c:6253
>  schedule+0xd2/0x260 kernel/sched/core.c:6326
>  rwsem_down_write_slowpath+0x664/0x1190 kernel/locking/rwsem.c:1151
>  __down_write_common kernel/locking/rwsem.c:1268 [inline]
>  __down_write_common kernel/locking/rwsem.c:1265 [inline]
>  __down_write kernel/locking/rwsem.c:1277 [inline]
>  down_write+0x135/0x150 kernel/locking/rwsem.c:1524
>  inode_lock include/linux/fs.h:783 [inline]
>  open_last_lookups fs/namei.c:3347 [inline]
>  path_openat+0xa66/0x26c0 fs/namei.c:3556
>  do_filp_open+0x1c1/0x290 fs/namei.c:3586
>  do_sys_openat2+0x61b/0x9a0 fs/open.c:1212
>  do_sys_open+0xc3/0x140 fs/open.c:1228
>  do_syscall_x64 arch/x86/entry/common.c:50 [inline]
>  do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80
>  entry_SYSCALL_64_after_hwframe+0x44/0xae
> RIP: 0033:0x7fde8feb06f0
> RSP: 002b:00007ffdc8b60d78 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
> RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fde8feb06f0
> RDX: 0000000000000180 RSI: 00000000000800c2 RDI: 00005624b8c989c0
> RBP: 000000000003a2f8 R08: 000000000000fcfe R09: 00007fde8ff03740
> R10: 0000000000000000 R11: 0000000000000246 R12: 00005624b8c989d6
> R13: 8421084210842109 R14: 00000000000800c2 R15: 00007fde8ff3e540
>  </TASK>
> INFO: task systemd-udevd:27515 blocked for more than 150 seconds.
>       Not tainted 5.16.0-rc8+ #10
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:systemd-udevd   state:D stack:27584 pid:27515 ppid:  3127 flags:0x00004000
> Call Trace:
>  <TASK>
>  context_switch kernel/sched/core.c:4972 [inline]
>  __schedule+0xcd9/0x2550 kernel/sched/core.c:6253
>  schedule+0xd2/0x260 kernel/sched/core.c:6326
>  rwsem_down_write_slowpath+0x664/0x1190 kernel/locking/rwsem.c:1151
>  __down_write_common kernel/locking/rwsem.c:1268 [inline]
>  __down_write_common kernel/locking/rwsem.c:1265 [inline]
>  __down_write kernel/locking/rwsem.c:1277 [inline]
>  down_write+0x135/0x150 kernel/locking/rwsem.c:1524
>  inode_lock include/linux/fs.h:783 [inline]
>  open_last_lookups fs/namei.c:3347 [inline]
>  path_openat+0xa66/0x26c0 fs/namei.c:3556
>  do_filp_open+0x1c1/0x290 fs/namei.c:3586
>  do_sys_openat2+0x61b/0x9a0 fs/open.c:1212
>  do_sys_open+0xc3/0x140 fs/open.c:1228
>  do_syscall_x64 arch/x86/entry/common.c:50 [inline]
>  do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80
>  entry_SYSCALL_64_after_hwframe+0x44/0xae
> RIP: 0033:0x7fde8feb06f0
> RSP: 002b:00007ffdc8b60d78 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
> RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fde8feb06f0
> RDX: 0000000000000180 RSI: 00000000000800c2 RDI: 00005624b8cad110
> RBP: 000000000003a2f8 R08: 000000000000fefe R09: 00007fde8ff03740
> R10: 0000000000000000 R11: 0000000000000246 R12: 00005624b8cad126
> R13: 8421084210842109 R14: 00000000000800c2 R15: 00007fde8ff3e540
>  </TASK>
> INFO: task systemd-udevd:27530 blocked for more than 153 seconds.
>       Not tainted 5.16.0-rc8+ #10
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> task:systemd-udevd   state:D stack:26048 pid:27530 ppid:  3127 flags:0x00000000
> Call Trace:
>  <TASK>
>  context_switch kernel/sched/core.c:4972 [inline]
>  __schedule+0xcd9/0x2550 kernel/sched/core.c:6253
>  schedule+0xd2/0x260 kernel/sched/core.c:6326
>  rwsem_down_write_slowpath+0x664/0x1190 kernel/locking/rwsem.c:1151
>  __down_write_common kernel/locking/rwsem.c:1268 [inline]
>  __down_write_common kernel/locking/rwsem.c:1265 [inline]
>  __down_write kernel/locking/rwsem.c:1277 [inline]
>  down_write+0x135/0x150 kernel/locking/rwsem.c:1524
>  inode_lock include/linux/fs.h:783 [inline]
>  open_last_lookups fs/namei.c:3347 [inline]
>  path_openat+0xa66/0x26c0 fs/namei.c:3556
>  do_filp_open+0x1c1/0x290 fs/namei.c:3586
>  do_sys_openat2+0x61b/0x9a0 fs/open.c:1212
>  do_sys_open+0xc3/0x140 fs/open.c:1228
>  do_syscall_x64 arch/x86/entry/common.c:50 [inline]
>  do_syscall_64+0x35/0xb0 arch/x86/entry/common.c:80
>  entry_SYSCALL_64_after_hwframe+0x44/0xae
> RIP: 0033:0x7fde8feb06f0
> RSP: 002b:00007ffdc8b61368 EFLAGS: 00000246 ORIG_RAX: 0000000000000002
> RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fde8feb06f0
> RDX: 0000000000000180 RSI: 00000000000800c2 RDI: 00005624b8ca9880
> RBP: 000000000003a2f8 R08: 000000000000fefe R09: 00007fde8ff03740
> R10: 0000000000000000 R11: 0000000000000246 R12: 00005624b8ca9896
> R13: 8421084210842109 R14: 00000000000800c2 R15: 00007fde8ff3e540
>  </TASK>

^ permalink raw reply	[flat|nested] 6+ messages in thread

[parent not found: <CANp29Y5tjwYLk3WdfjmsQy3qXbk6V8vW1vERRSTHsAhpzzMGpg@mail.gmail.com>]

* Re: INFO: task hung in path_openat
       [not found]   ` <CANp29Y5tjwYLk3WdfjmsQy3qXbk6V8vW1vERRSTHsAhpzzMGpg@mail.gmail.com>
@ 2022-01-11 13:38     ` Matthew Wilcox
  2022-01-11 13:29       ` KCSAN: data-race in step_into / vfs_unlink Kaia Yadira
  0 siblings, 1 reply; 6+ messages in thread
From: Matthew Wilcox @ 2022-01-11 13:38 UTC (permalink / raw)
  To: Aleksandr Nogikh
  Cc: cruise k, Dmitry Vyukov, Alexander Viro, linux-fsdevel, LKML,
	sunhao.th, syzkaller

On Tue, Jan 11, 2022 at 10:38:02AM +0100, Aleksandr Nogikh wrote:
> Hi Matthew,
> 
> That report was not sent by syzbot, rather by someone else. syzbot tries to
> be much more careful with the INFO: reports.
> 
> During the past couple of weeks there has been some outburst of similar
> reports from various senders - this is the third different sender I see,
> probably there are also much more.

Right.  Perhaps syzcaller could *not* call sched_setscheduler() by
default.  Require an --i-know-what-im-doing-and-wont-submit-bogus-reports
flag to be specified by the user in order to call that syscall?

^ permalink raw reply	[flat|nested] 6+ messages in thread

* KCSAN: data-race in step_into / vfs_unlink
@ 2022-01-11 13:29       ` Kaia Yadira
  2022-01-11 14:10         ` KCSAN: data-race in task_mem / unmap_region Christian Brauner
  0 siblings, 1 reply; 6+ messages in thread
From: Kaia Yadira @ 2022-01-11 13:29 UTC (permalink / raw)
  To: viro, linux-fsdevel, linux-kernel, syzkaller-bugs; +Cc: sunhao.th

Hello,

When using Syzkaller to fuzz the latest Linux kernel, the following
crash was triggered.

HEAD commit: a7904a538933 Linux 5.16-rc6
git tree: upstream
console output: KCSAN: data-race in step_into / vfs_unlink
kernel config: https://paste.ubuntu.com/p/QB39MJKWKb/plain/
Syzlang reproducer: https://paste.ubuntu.com/p/qQPrVRrYfb/plain/

If you fix this issue, please add the following tag to the commit:

Reported-by: Hypericum <hypericumperforatum4444@gmail.com>

I think the program data race at the both reading and read/write at
the dentry->d_flags

reproducer log: https://paste.ubuntu.com/p/2xsqF6W3sB/plain/
reproducer report:

==================================================================
BUG: KCSAN: data-race in step_into / vfs_unlink

read-write to 0xffff88810a3899c0 of 4 bytes by task 5771 on cpu 1:
 dont_mount include/linux/dcache.h:358 [inline]
 vfs_unlink+0x28e/0x440 fs/namei.c:4102
 do_unlinkat+0x278/0x540 fs/namei.c:4167
 __do_sys_unlink fs/namei.c:4215 [inline]
 __se_sys_unlink fs/namei.c:4213 [inline]
 __x64_sys_unlink+0x2c/0x30 fs/namei.c:4213
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x44/0xd0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x44/0xae

read to 0xffff88810a3899c0 of 4 bytes by task 1537 on cpu 5:
 __follow_mount_rcu fs/namei.c:1429 [inline]
 handle_mounts fs/namei.c:1486 [inline]
 step_into+0xf4/0xea0 fs/namei.c:1800
 walk_component+0x1a1/0x360 fs/namei.c:1976
 lookup_last fs/namei.c:2425 [inline]
 path_lookupat+0x12d/0x3c0 fs/namei.c:2449
 filename_lookup+0x130/0x310 fs/namei.c:2478
 user_path_at_empty+0x3e/0x110 fs/namei.c:2801
 do_readlinkat+0x97/0x210 fs/stat.c:443
 __do_sys_readlink fs/stat.c:476 [inline]
 __se_sys_readlink fs/stat.c:473 [inline]
 __x64_sys_readlink+0x43/0x50 fs/stat.c:473
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x44/0xd0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x44/0xae

value changed: 0x00600008 -> 0x00008008

Reported by Kernel Concurrency Sanitizer on:
CPU: 5 PID: 1537 Comm: systemd-udevd Not tainted 5.16.0-rc8+ #11
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.13.0-1ubuntu1.1 04/01/2014
==================================================================

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: KCSAN: data-race in task_mem / unmap_region
  2022-01-11 13:29       ` KCSAN: data-race in step_into / vfs_unlink Kaia Yadira
@ 2022-01-11 14:10         ` Christian Brauner
  0 siblings, 0 replies; 6+ messages in thread
From: Christian Brauner @ 2022-01-11 14:10 UTC (permalink / raw)
  To: Kaia Yadira, Matthew Wilcox, syzkaller
  Cc: jgg, rcampbell, aarcange, david, apopple, will, linux-kernel,
	linux-fsdevel, syzkaller-bugs, sunhao.th, Aleksandr Nogikh,
	cruise k, Dmitry Vyukov, Alexander Viro

On Tue, Jan 11, 2022 at 09:56:59PM +0800, Kaia Yadira wrote:
> Hello,
> 
> When using Syzkaller to fuzz the latest Linux kernel, the following
> crash was triggered.
> 
> HEAD commit: a7904a538933 Linux 5.16-rc6
> git tree: upstream
> console output: KCSAN: data-race in task_mem / unmap_region
> kernel config: https://paste.ubuntu.com/p/QB39MJKWKb/plain/
> Syzlang reproducer: https://paste.ubuntu.com/p/q2DVwVh6hr/plain/
> 
> If you fix this issue, please add the following tag to the commit:
> 
> Reported-by: Hypericum <hypericumperforatum4444@gmail.com>
> 
> I think fs/proc/task_mmu.c visits the variable mm without locking and
> another mmap visits mm->hiwater_vm resulting in a data race.
> 
> reproducer log: https://paste.ubuntu.com/p/Sp6RDWKDfy/plain/
> reproducer report:
> ==================================================================
> BUG: KCSAN: data-race in task_mem / unmap_region
> 
> write to 0xffff8881095008b0 of 8 bytes by task 3712 on cpu 4:
>  update_hiwater_rss include/linux/mm.h:2102 [inline]
>  unmap_region+0x12b/0x1e0 mm/mmap.c:2648
>  __do_munmap+0xe6e/0x12b0 mm/mmap.c:2883
>  __vm_munmap mm/mmap.c:2906 [inline]
>  __do_sys_munmap+0x9f/0x160 mm/mmap.c:2932
>  __se_sys_munmap mm/mmap.c:2928 [inline]
>  __x64_sys_munmap+0x2d/0x40 mm/mmap.c:2928
>  do_syscall_x64 arch/x86/entry/common.c:50 [inline]
>  do_syscall_64+0x44/0xd0 arch/x86/entry/common.c:80
>  entry_SYSCALL_64_after_hwframe+0x44/0xae
> 
> read to 0xffff8881095008b0 of 8 bytes by task 1512 on cpu 7:
>  task_mem+0xfb/0x3d0 fs/proc/task_mmu.c:50
>  proc_pid_status+0x890/0x14d0 fs/proc/array.c:438
>  proc_single_show+0x84/0x100 fs/proc/base.c:778
>  seq_read_iter+0x2e3/0x930 fs/seq_file.c:230
>  seq_read+0x234/0x280 fs/seq_file.c:162
>  vfs_read+0x1e6/0x730 fs/read_write.c:479
>  ksys_read+0xd9/0x190 fs/read_write.c:619
>  __do_sys_read fs/read_write.c:629 [inline]
>  __se_sys_read fs/read_write.c:627 [inline]
>  __x64_sys_read+0x3e/0x50 fs/read_write.c:627
>  do_syscall_x64 arch/x86/entry/common.c:50 [inline]
>  do_syscall_64+0x44/0xd0 arch/x86/entry/common.c:80
>  entry_SYSCALL_64_after_hwframe+0x44/0xae
> 
> value changed: 0x000000000000065b -> 0x0000000000000662
> 
> Reported by Kernel Concurrency Sanitizer on:
> CPU: 7 PID: 1512 Comm: systemd-journal Not tainted 5.16.0-rc8+ #11
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
> 1.13.0-1ubuntu1.1 04/01/2014
> ==================================================================

On Tue, Jan 11, 2022 at 01:38:28PM +0000, Matthew Wilcox wrote:
> On Tue, Jan 11, 2022 at 10:38:02AM +0100, Aleksandr Nogikh wrote:
> > Hi Matthew,
> > 
> > That report was not sent by syzbot, rather by someone else. syzbot tries to
> > be much more careful with the INFO: reports.
> > 
> > During the past couple of weeks there has been some outburst of similar
> > reports from various senders - this is the third different sender I see,
> > probably there are also much more.
> 
> Right.  Perhaps syzcaller could *not* call sched_setscheduler() by
> default.  Require an --i-know-what-im-doing-and-wont-submit-bogus-reports
> flag to be specified by the user in order to call that syscall?

Yeah, can we stop reports from this particular non-"official" syzkaller
instance, please? We've received at least 3 or 4 of those just today and
frankly the reports generated here are not very useful in debugging
these issues; especially when contrasted with syzkaller "proper".
Frankly, it's pretty difficult to even tell they're legitimate. At first
I thought this is spam.

Honestly, I think we need to require that static analyzer, fuzzers and
so on need to register themselves with kernel.org or some other way
before allowing them to spam mailing lists.

^ permalink raw reply	[flat|nested] 6+ messages in thread

* KCSAN: data-race in task_mem / unmap_region
@ 2022-01-11 13:56 Kaia Yadira
  0 siblings, 0 replies; 6+ messages in thread
From: Kaia Yadira @ 2022-01-11 13:56 UTC (permalink / raw)
  To: jgg, rcampbell, aarcange, david, apopple, will, linux-kernel,
	linux-fsdevel, syzkaller-bugs
  Cc: sunhao.th

Hello,

When using Syzkaller to fuzz the latest Linux kernel, the following
crash was triggered.

HEAD commit: a7904a538933 Linux 5.16-rc6
git tree: upstream
console output: KCSAN: data-race in task_mem / unmap_region
kernel config: https://paste.ubuntu.com/p/QB39MJKWKb/plain/
Syzlang reproducer: https://paste.ubuntu.com/p/q2DVwVh6hr/plain/

If you fix this issue, please add the following tag to the commit:

Reported-by: Hypericum <hypericumperforatum4444@gmail.com>

I think fs/proc/task_mmu.c visits the variable mm without locking and
another mmap visits mm->hiwater_vm resulting in a data race.

reproducer log: https://paste.ubuntu.com/p/Sp6RDWKDfy/plain/
reproducer report:
==================================================================
BUG: KCSAN: data-race in task_mem / unmap_region

write to 0xffff8881095008b0 of 8 bytes by task 3712 on cpu 4:
 update_hiwater_rss include/linux/mm.h:2102 [inline]
 unmap_region+0x12b/0x1e0 mm/mmap.c:2648
 __do_munmap+0xe6e/0x12b0 mm/mmap.c:2883
 __vm_munmap mm/mmap.c:2906 [inline]
 __do_sys_munmap+0x9f/0x160 mm/mmap.c:2932
 __se_sys_munmap mm/mmap.c:2928 [inline]
 __x64_sys_munmap+0x2d/0x40 mm/mmap.c:2928
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x44/0xd0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x44/0xae

read to 0xffff8881095008b0 of 8 bytes by task 1512 on cpu 7:
 task_mem+0xfb/0x3d0 fs/proc/task_mmu.c:50
 proc_pid_status+0x890/0x14d0 fs/proc/array.c:438
 proc_single_show+0x84/0x100 fs/proc/base.c:778
 seq_read_iter+0x2e3/0x930 fs/seq_file.c:230
 seq_read+0x234/0x280 fs/seq_file.c:162
 vfs_read+0x1e6/0x730 fs/read_write.c:479
 ksys_read+0xd9/0x190 fs/read_write.c:619
 __do_sys_read fs/read_write.c:629 [inline]
 __se_sys_read fs/read_write.c:627 [inline]
 __x64_sys_read+0x3e/0x50 fs/read_write.c:627
 do_syscall_x64 arch/x86/entry/common.c:50 [inline]
 do_syscall_64+0x44/0xd0 arch/x86/entry/common.c:80
 entry_SYSCALL_64_after_hwframe+0x44/0xae

value changed: 0x000000000000065b -> 0x0000000000000662

Reported by Kernel Concurrency Sanitizer on:
CPU: 7 PID: 1512 Comm: systemd-journal Not tainted 5.16.0-rc8+ #11
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS
1.13.0-1ubuntu1.1 04/01/2014
==================================================================

^ permalink raw reply	[flat|nested] 6+ messages in thread

end of thread, other threads:[~2022-01-11 14:10 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2022-01-11  2:15 INFO: task hung in path_openat cruise k
2022-01-11  3:39 ` Matthew Wilcox
     [not found]   ` <CANp29Y5tjwYLk3WdfjmsQy3qXbk6V8vW1vERRSTHsAhpzzMGpg@mail.gmail.com>
2022-01-11 13:38     ` Matthew Wilcox
2022-01-11 13:29       ` KCSAN: data-race in step_into / vfs_unlink Kaia Yadira
2022-01-11 14:10         ` KCSAN: data-race in task_mem / unmap_region Christian Brauner
  -- strict thread matches above, loose matches on Subject: below --
2022-01-11 13:56 Kaia Yadira

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).