* INFO: task hung in iterate_supers
@ 2018-07-10 10:30 syzbot
2018-07-10 10:34 ` Tetsuo Handa
0 siblings, 1 reply; 5+ messages in thread
From: syzbot @ 2018-07-10 10:30 UTC (permalink / raw)
To: linux-fsdevel, linux-kernel, syzkaller-bugs, viro
Hello,
syzbot found the following crash on:
HEAD commit: d00d6d9a339d Add linux-next specific files for 20180709
git tree: linux-next
console output: https://syzkaller.appspot.com/x/log.txt?x=111179b2400000
kernel config: https://syzkaller.appspot.com/x/.config?x=94fe2b586beccacd
dashboard link: https://syzkaller.appspot.com/bug?extid=2349f5067b1772c1d8a5
compiler: gcc (GCC) 8.0.1 20180413 (experimental)
syzkaller repro:https://syzkaller.appspot.com/x/repro.syz?x=174329b2400000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=11229044400000
IMPORTANT: if you fix the bug, please add the following tag to the commit:
Reported-by: syzbot+2349f5067b1772c1d8a5@syzkaller.appspotmail.com
INFO: task syz-executor687:4459 blocked for more than 140 seconds.
Not tainted 4.18.0-rc3-next-20180709+ #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor687 D23544 4459 4456 0x00000000
Call Trace:
context_switch kernel/sched/core.c:2853 [inline]
__schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
schedule+0xfb/0x450 kernel/sched/core.c:3545
__rwsem_down_read_failed_common kernel/locking/rwsem-xadd.c:269 [inline]
rwsem_down_read_failed+0x362/0x600 kernel/locking/rwsem-xadd.c:286
call_rwsem_down_read_failed+0x18/0x30 arch/x86/lib/rwsem.S:94
__down_read arch/x86/include/asm/rwsem.h:83 [inline]
down_read+0xc3/0x1d0 kernel/locking/rwsem.c:26
iterate_supers+0xe2/0x290 fs/super.c:728
ksys_sync+0xec/0x1e0 fs/sync.c:113
__ia32_sys_sync+0xe/0x20 fs/sync.c:124
do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x4498c9
Code: e8 1c e8 ff ff 48 83 c4 18 c3 0f 1f 80 00 00 00 00 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 ff
ff 0f 83 ab d2 fb ff c3 66 2e 0f 1f 84 00 00 00 00
RSP: 002b:00007f0ad5912da8 EFLAGS: 00000293 ORIG_RAX: 00000000000000a2
RAX: ffffffffffffffda RBX: 00000000006dac44 RCX: 00000000004498c9
RDX: 00000000004498c9 RSI: 0000000000000000 RDI: 0000000000000000
RBP: 00000000006dac40 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0030656c69662f2e
R13: 3d6e6f6973726576 R14: 64663d736e617274 R15: 0000000000000001
INFO: task syz-executor687:4479 blocked for more than 140 seconds.
Not tainted 4.18.0-rc3-next-20180709+ #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor687 D25408 4479 4456 0x00000000
Call Trace:
context_switch kernel/sched/core.c:2853 [inline]
__schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
schedule+0xfb/0x450 kernel/sched/core.c:3545
__rwsem_down_read_failed_common kernel/locking/rwsem-xadd.c:269 [inline]
rwsem_down_read_failed+0x362/0x600 kernel/locking/rwsem-xadd.c:286
call_rwsem_down_read_failed+0x18/0x30 arch/x86/lib/rwsem.S:94
__down_read arch/x86/include/asm/rwsem.h:83 [inline]
down_read+0xc3/0x1d0 kernel/locking/rwsem.c:26
iterate_supers+0xe2/0x290 fs/super.c:728
ksys_sync+0x10c/0x1e0 fs/sync.c:115
__ia32_sys_sync+0xe/0x20 fs/sync.c:124
do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x4498c9
Code: e8 1c e8 ff ff 48 83 c4 18 c3 0f 1f 80 00 00 00 00 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 ff
ff 0f 83 ab d2 fb ff c3 66 2e 0f 1f 84 00 00 00 00
RSP: 002b:00007f0ad58f1da8 EFLAGS: 00000293 ORIG_RAX: 00000000000000a2
RAX: ffffffffffffffda RBX: 00000000006dac5c RCX: 00000000004498c9
RDX: 00000000004498c9 RSI: 0000000000000000 RDI: 0000000000000000
RBP: 00000000006dac58 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0030656c69662f2e
R13: 3d6e6f6973726576 R14: 64663d736e617274 R15: 0000000000000001
INFO: task syz-executor687:4492 blocked for more than 140 seconds.
Not tainted 4.18.0-rc3-next-20180709+ #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor687 D22992 4492 4456 0x00000000
Call Trace:
context_switch kernel/sched/core.c:2853 [inline]
__schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
schedule+0xfb/0x450 kernel/sched/core.c:3545
__rwsem_down_read_failed_common kernel/locking/rwsem-xadd.c:269 [inline]
rwsem_down_read_failed+0x362/0x600 kernel/locking/rwsem-xadd.c:286
call_rwsem_down_read_failed+0x18/0x30 arch/x86/lib/rwsem.S:94
__down_read arch/x86/include/asm/rwsem.h:83 [inline]
down_read+0xc3/0x1d0 kernel/locking/rwsem.c:26
iterate_supers+0xe2/0x290 fs/super.c:728
ksys_sync+0xec/0x1e0 fs/sync.c:113
__ia32_sys_sync+0xe/0x20 fs/sync.c:124
do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x4498c9
Code: e8 1c e8 ff ff 48 83 c4 18 c3 0f 1f 80 00 00 00 00 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 ff
ff 0f 83 ab d2 fb ff c3 66 2e 0f 1f 84 00 00 00 00
RSP: 002b:00007f0ad58d0da8 EFLAGS: 00000293 ORIG_RAX: 00000000000000a2
RAX: ffffffffffffffda RBX: 00000000006dac74 RCX: 00000000004498c9
RDX: 00000000004498c9 RSI: 0000000000000000 RDI: 0000000000000000
RBP: 00000000006dac70 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0030656c69662f2e
R13: 3d6e6f6973726576 R14: 64663d736e617274 R15: 0000000000000001
INFO: task syz-executor687:4497 blocked for more than 140 seconds.
Not tainted 4.18.0-rc3-next-20180709+ #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor687 D25408 4497 4456 0x00000000
Call Trace:
context_switch kernel/sched/core.c:2853 [inline]
__schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
schedule+0xfb/0x450 kernel/sched/core.c:3545
__rwsem_down_read_failed_common kernel/locking/rwsem-xadd.c:269 [inline]
rwsem_down_read_failed+0x362/0x600 kernel/locking/rwsem-xadd.c:286
call_rwsem_down_read_failed+0x18/0x30 arch/x86/lib/rwsem.S:94
__down_read arch/x86/include/asm/rwsem.h:83 [inline]
down_read+0xc3/0x1d0 kernel/locking/rwsem.c:26
iterate_supers+0xe2/0x290 fs/super.c:728
ksys_sync+0xec/0x1e0 fs/sync.c:113
__ia32_sys_sync+0xe/0x20 fs/sync.c:124
do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x4498c9
Code: e8 1c e8 ff ff 48 83 c4 18 c3 0f 1f 80 00 00 00 00 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 ff
ff 0f 83 ab d2 fb ff c3 66 2e 0f 1f 84 00 00 00 00
RSP: 002b:00007f0ad58afda8 EFLAGS: 00000293 ORIG_RAX: 00000000000000a2
RAX: ffffffffffffffda RBX: 00000000006dac8c RCX: 00000000004498c9
RDX: 00000000004498c9 RSI: 0000000000000000 RDI: 0000000000000000
RBP: 00000000006dac88 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0030656c69662f2e
R13: 3d6e6f6973726576 R14: 64663d736e617274 R15: 0000000000000001
INFO: task syz-executor687:4503 blocked for more than 140 seconds.
Not tainted 4.18.0-rc3-next-20180709+ #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor687 D24512 4503 4456 0x00000000
Call Trace:
context_switch kernel/sched/core.c:2853 [inline]
__schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
schedule+0xfb/0x450 kernel/sched/core.c:3545
__rwsem_down_read_failed_common kernel/locking/rwsem-xadd.c:269 [inline]
rwsem_down_read_failed+0x362/0x600 kernel/locking/rwsem-xadd.c:286
call_rwsem_down_read_failed+0x18/0x30 arch/x86/lib/rwsem.S:94
__down_read arch/x86/include/asm/rwsem.h:83 [inline]
down_read+0xc3/0x1d0 kernel/locking/rwsem.c:26
iterate_supers+0xe2/0x290 fs/super.c:728
ksys_sync+0xec/0x1e0 fs/sync.c:113
__ia32_sys_sync+0xe/0x20 fs/sync.c:124
do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x4498c9
Code: e8 1c e8 ff ff 48 83 c4 18 c3 0f 1f 80 00 00 00 00 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 ff
ff 0f 83 ab d2 fb ff c3 66 2e 0f 1f 84 00 00 00 00
RSP: 002b:00007f0ad588eda8 EFLAGS: 00000293 ORIG_RAX: 00000000000000a2
RAX: ffffffffffffffda RBX: 00000000006daca4 RCX: 00000000004498c9
RDX: 00000000004498c9 RSI: 0000000000000000 RDI: 0000000000000000
RBP: 00000000006daca0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0030656c69662f2e
R13: 3d6e6f6973726576 R14: 64663d736e617274 R15: 0000000000000001
INFO: task syz-executor687:4521 blocked for more than 140 seconds.
Not tainted 4.18.0-rc3-next-20180709+ #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor687 D23648 4521 4456 0x00000000
Call Trace:
context_switch kernel/sched/core.c:2853 [inline]
__schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
schedule+0xfb/0x450 kernel/sched/core.c:3545
__rwsem_down_read_failed_common kernel/locking/rwsem-xadd.c:269 [inline]
rwsem_down_read_failed+0x362/0x600 kernel/locking/rwsem-xadd.c:286
call_rwsem_down_read_failed+0x18/0x30 arch/x86/lib/rwsem.S:94
__down_read arch/x86/include/asm/rwsem.h:83 [inline]
down_read+0xc3/0x1d0 kernel/locking/rwsem.c:26
iterate_supers+0xe2/0x290 fs/super.c:728
ksys_sync+0xec/0x1e0 fs/sync.c:113
__ia32_sys_sync+0xe/0x20 fs/sync.c:124
do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x4498c9
Code: e8 1c e8 ff ff 48 83 c4 18 c3 0f 1f 80 00 00 00 00 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 ff
ff 0f 83 ab d2 fb ff c3 66 2e 0f 1f 84 00 00 00 00
RSP: 002b:00007f0ad586dda8 EFLAGS: 00000293 ORIG_RAX: 00000000000000a2
RAX: ffffffffffffffda RBX: 00000000006dacbc RCX: 00000000004498c9
RDX: 00000000004498c9 RSI: 0000000000000000 RDI: 0000000000000000
RBP: 00000000006dacb8 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0030656c69662f2e
R13: 3d6e6f6973726576 R14: 64663d736e617274 R15: 0000000000000001
INFO: task syz-executor687:4524 blocked for more than 140 seconds.
Not tainted 4.18.0-rc3-next-20180709+ #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor687 D23640 4524 4456 0x00000000
Call Trace:
context_switch kernel/sched/core.c:2853 [inline]
__schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
schedule+0xfb/0x450 kernel/sched/core.c:3545
__rwsem_down_read_failed_common kernel/locking/rwsem-xadd.c:269 [inline]
rwsem_down_read_failed+0x362/0x600 kernel/locking/rwsem-xadd.c:286
call_rwsem_down_read_failed+0x18/0x30 arch/x86/lib/rwsem.S:94
__down_read arch/x86/include/asm/rwsem.h:83 [inline]
down_read+0xc3/0x1d0 kernel/locking/rwsem.c:26
iterate_supers+0xe2/0x290 fs/super.c:728
ksys_sync+0xec/0x1e0 fs/sync.c:113
__ia32_sys_sync+0xe/0x20 fs/sync.c:124
do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x4498c9
Code: e8 1c e8 ff ff 48 83 c4 18 c3 0f 1f 80 00 00 00 00 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 ff
ff 0f 83 ab d2 fb ff c3 66 2e 0f 1f 84 00 00 00 00
RSP: 002b:00007f0ad584cda8 EFLAGS: 00000293 ORIG_RAX: 00000000000000a2
RAX: ffffffffffffffda RBX: 00000000006dacd4 RCX: 00000000004498c9
RDX: 00000000004498c9 RSI: 0000000000000000 RDI: 0000000000000000
RBP: 00000000006dacd0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0030656c69662f2e
R13: 3d6e6f6973726576 R14: 64663d736e617274 R15: 0000000000000001
INFO: task syz-executor687:4534 blocked for more than 140 seconds.
Not tainted 4.18.0-rc3-next-20180709+ #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor687 D23864 4534 4456 0x00000000
Call Trace:
context_switch kernel/sched/core.c:2853 [inline]
__schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
schedule+0xfb/0x450 kernel/sched/core.c:3545
__rwsem_down_read_failed_common kernel/locking/rwsem-xadd.c:269 [inline]
rwsem_down_read_failed+0x362/0x600 kernel/locking/rwsem-xadd.c:286
call_rwsem_down_read_failed+0x18/0x30 arch/x86/lib/rwsem.S:94
__down_read arch/x86/include/asm/rwsem.h:83 [inline]
down_read+0xc3/0x1d0 kernel/locking/rwsem.c:26
iterate_supers+0xe2/0x290 fs/super.c:728
ksys_sync+0xec/0x1e0 fs/sync.c:113
__ia32_sys_sync+0xe/0x20 fs/sync.c:124
do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x4498c9
Code: e8 1c e8 ff ff 48 83 c4 18 c3 0f 1f 80 00 00 00 00 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 ff
ff 0f 83 ab d2 fb ff c3 66 2e 0f 1f 84 00 00 00 00
RSP: 002b:00007f0ad582bda8 EFLAGS: 00000293 ORIG_RAX: 00000000000000a2
RAX: ffffffffffffffda RBX: 00000000006dacec RCX: 00000000004498c9
RDX: 00000000004498c9 RSI: 0000000000000000 RDI: 0000000000000000
RBP: 00000000006dace8 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0030656c69662f2e
R13: 3d6e6f6973726576 R14: 64663d736e617274 R15: 0000000000000001
INFO: task syz-executor687:4548 blocked for more than 140 seconds.
Not tainted 4.18.0-rc3-next-20180709+ #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor687 D25408 4548 4456 0x00000000
Call Trace:
context_switch kernel/sched/core.c:2853 [inline]
__schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
schedule+0xfb/0x450 kernel/sched/core.c:3545
__rwsem_down_read_failed_common kernel/locking/rwsem-xadd.c:269 [inline]
rwsem_down_read_failed+0x362/0x600 kernel/locking/rwsem-xadd.c:286
call_rwsem_down_read_failed+0x18/0x30 arch/x86/lib/rwsem.S:94
__down_read arch/x86/include/asm/rwsem.h:83 [inline]
down_read+0xc3/0x1d0 kernel/locking/rwsem.c:26
iterate_supers+0xe2/0x290 fs/super.c:728
ksys_sync+0xec/0x1e0 fs/sync.c:113
__ia32_sys_sync+0xe/0x20 fs/sync.c:124
do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x4498c9
Code: e8 1c e8 ff ff 48 83 c4 18 c3 0f 1f 80 00 00 00 00 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 ff
ff 0f 83 ab d2 fb ff c3 66 2e 0f 1f 84 00 00 00 00
RSP: 002b:00007f0ad580ada8 EFLAGS: 00000293 ORIG_RAX: 00000000000000a2
RAX: ffffffffffffffda RBX: 00000000006dad04 RCX: 00000000004498c9
RDX: 00000000004498c9 RSI: 0000000000000000 RDI: 0000000000000000
RBP: 00000000006dad00 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0030656c69662f2e
R13: 3d6e6f6973726576 R14: 64663d736e617274 R15: 0000000000000001
INFO: task syz-executor687:4556 blocked for more than 140 seconds.
Not tainted 4.18.0-rc3-next-20180709+ #2
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor687 D24480 4556 4456 0x00000000
Call Trace:
context_switch kernel/sched/core.c:2853 [inline]
__schedule+0x87c/0x1ed0 kernel/sched/core.c:3501
schedule+0xfb/0x450 kernel/sched/core.c:3545
__rwsem_down_read_failed_common kernel/locking/rwsem-xadd.c:269 [inline]
rwsem_down_read_failed+0x362/0x600 kernel/locking/rwsem-xadd.c:286
call_rwsem_down_read_failed+0x18/0x30 arch/x86/lib/rwsem.S:94
__down_read arch/x86/include/asm/rwsem.h:83 [inline]
down_read+0xc3/0x1d0 kernel/locking/rwsem.c:26
iterate_supers+0xe2/0x290 fs/super.c:728
ksys_sync+0xec/0x1e0 fs/sync.c:113
__ia32_sys_sync+0xe/0x20 fs/sync.c:124
do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x4498c9
Code: e8 1c e8 ff ff 48 83 c4 18 c3 0f 1f 80 00 00 00 00 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 ff
ff 0f 83 ab d2 fb ff c3 66 2e 0f 1f 84 00 00 00 00
RSP: 002b:00007f0ad57e9da8 EFLAGS: 00000293 ORIG_RAX: 00000000000000a2
RAX: ffffffffffffffda RBX: 00000000006dad1c RCX: 00000000004498c9
RDX: 00000000004498c9 RSI: 0000000000000000 RDI: 0000000000000000
RBP: 00000000006dad18 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000293 R12: 0030656c69662f2e
R13: 3d6e6f6973726576 R14: 64663d736e617274 R15: 0000000000000001
INFO: lockdep is turned off.
NMI backtrace for cpu 0
CPU: 0 PID: 899 Comm: khungtaskd Not tainted 4.18.0-rc3-next-20180709+ #2
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS
Google 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:77 [inline]
dump_stack+0x1c9/0x2b4 lib/dump_stack.c:113
nmi_cpu_backtrace.cold.5+0x19/0xce lib/nmi_backtrace.c:103
nmi_trigger_cpumask_backtrace+0x151/0x192 lib/nmi_backtrace.c:62
arch_trigger_cpumask_backtrace+0x14/0x20 arch/x86/kernel/apic/hw_nmi.c:38
trigger_all_cpu_backtrace include/linux/nmi.h:143 [inline]
check_hung_uninterruptible_tasks kernel/hung_task.c:204 [inline]
watchdog+0xb39/0x10b0 kernel/hung_task.c:265
kthread+0x345/0x410 kernel/kthread.c:246
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:415
Sending NMI from CPU 0 to CPUs 1:
NMI backtrace for cpu 1 skipped: idling at native_safe_halt+0x6/0x10
arch/x86/include/asm/irqflags.h:54
---
This bug is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzkaller@googlegroups.com.
syzbot will keep track of this bug report. See:
https://goo.gl/tpsmEJ#bug-status-tracking for how to communicate with
syzbot.
syzbot can test patches for this bug, for details see:
https://goo.gl/tpsmEJ#testing-patches
^ permalink raw reply [flat|nested] 5+ messages in thread* Re: INFO: task hung in iterate_supers 2018-07-10 10:30 INFO: task hung in iterate_supers syzbot @ 2018-07-10 10:34 ` Tetsuo Handa 2018-07-11 10:19 ` Tetsuo Handa 0 siblings, 1 reply; 5+ messages in thread From: Tetsuo Handa @ 2018-07-10 10:34 UTC (permalink / raw) To: viro; +Cc: syzbot, linux-fsdevel, linux-kernel, syzkaller-bugs Since syzbot found a C reproducer, I reproduced locally with below change applied. ---------------------------------------- diff --git a/kernel/hung_task.c b/kernel/hung_task.c index 32b4794..aca1cca 100644 --- a/kernel/hung_task.c +++ b/kernel/hung_task.c @@ -115,13 +115,6 @@ static void check_hung_task(struct task_struct *t, unsigned long timeout) sysctl_hung_task_warnings--; pr_err("INFO: task %s:%d blocked for more than %ld seconds.\n", t->comm, t->pid, timeout); - pr_err(" %s %s %.*s\n", - print_tainted(), init_utsname()->release, - (int)strcspn(init_utsname()->version, " "), - init_utsname()->version); - pr_err("\"echo 0 > /proc/sys/kernel/hung_task_timeout_secs\"" - " disables this message.\n"); - sched_show_task(t); hung_task_show_lock = true; } @@ -190,8 +183,20 @@ static void check_hung_uninterruptible_tasks(unsigned long timeout) } unlock: rcu_read_unlock(); - if (hung_task_show_lock) - debug_show_all_locks(); + if (hung_task_show_lock) { + extern void lockdep_print_held_locks(struct task_struct *p); + + rcu_read_lock(); + for_each_process_thread(g, t) { + if (!t->lockdep_depth) + continue; + sched_show_task(t); + lockdep_print_held_locks(t); + touch_nmi_watchdog(); + touch_all_softlockup_watchdogs(); + } + rcu_read_unlock(); + } if (hung_task_call_panic) { trigger_all_cpu_backtrace(); panic("hung_task: blocked tasks"); diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c index 5fa4d31..e3de52d 100644 --- a/kernel/locking/lockdep.c +++ b/kernel/locking/lockdep.c @@ -561,7 +561,7 @@ static void print_lock(struct held_lock *hlock) printk(KERN_CONT ", at: %pS\n", (void *)hlock->acquire_ip); } -static void lockdep_print_held_locks(struct task_struct *p) +void lockdep_print_held_locks(struct task_struct *p) { int i, depth = READ_ONCE(p->lockdep_depth); @@ -575,7 +575,7 @@ static void lockdep_print_held_locks(struct task_struct *p) * and it's not the current task. */ if (p->state == TASK_RUNNING && p != current) - return; + printk("RUNNING TASK\n"); for (i = 0; i < depth; i++) { printk(" #%d: ", i); print_lock(p->held_locks + i); ---------------------------------------- It turned out that, although the reason of stalling v9fs_mount() is currently unknown, the reason of many processes stuck at iterate_supers() is that they are unable to take s->s_umount object due to down_write_nested() below. /* * sget() can have s_umount recursion. * * When it cannot find a suitable sb, it allocates a new * one (this one), and tries again to find a suitable old * one. * * In case that succeeds, it will acquire the s_umount * lock of the old one. Since these are clearly distrinct * locks, and this object isn't exposed yet, there's no * risk of deadlocks. * * Annotate this by putting this lock in a different * subclass. */ down_write_nested(&s->s_umount, SINGLE_DEPTH_NESTING); (The hashed address 00000000d803423d is printed among processes below.) [ 224.224404] INFO: task a.out:5454 blocked for more than 10 seconds. [ 224.230981] INFO: task a.out:5476 blocked for more than 10 seconds. [ 224.237530] INFO: task a.out:5491 blocked for more than 10 seconds. [ 224.242368] INFO: task a.out:5514 blocked for more than 10 seconds. [ 224.246407] INFO: task a.out:5529 blocked for more than 10 seconds. [ 224.250429] INFO: task a.out:5681 blocked for more than 10 seconds. [ 224.254420] INFO: task a.out:5697 blocked for more than 10 seconds. [ 224.258822] INFO: task a.out:5711 blocked for more than 10 seconds. [ 224.262873] INFO: task a.out:5723 blocked for more than 10 seconds. [ 224.266883] INFO: task a.out:5740 blocked for more than 10 seconds. [ 224.270740] INFO: task a.out:5757 blocked for more than 10 seconds. [ 224.272797] INFO: task a.out:5769 blocked for more than 10 seconds. [ 224.274895] INFO: task a.out:5789 blocked for more than 10 seconds. [ 224.276914] INFO: task a.out:5799 blocked for more than 10 seconds. [ 224.278909] INFO: task a.out:5823 blocked for more than 10 seconds. [ 224.280760] INFO: task a.out:5833 blocked for more than 10 seconds. [ 224.282612] INFO: task a.out:5456 blocked for more than 10 seconds. [ 224.284464] INFO: task a.out:5474 blocked for more than 10 seconds. [ 224.286389] INFO: task a.out:5492 blocked for more than 10 seconds. [ 224.288445] INFO: task a.out:5526 blocked for more than 10 seconds. [ 224.290524] INFO: task a.out:5570 blocked for more than 10 seconds. [ 224.292544] INFO: task a.out:5679 blocked for more than 10 seconds. [ 224.294551] INFO: task a.out:5693 blocked for more than 10 seconds. [ 224.296468] INFO: task a.out:5707 blocked for more than 10 seconds. [ 224.298317] INFO: task a.out:5720 blocked for more than 10 seconds. [ 224.300167] INFO: task a.out:5745 blocked for more than 10 seconds. [ 224.302098] INFO: task a.out:5759 blocked for more than 10 seconds. [ 224.304110] INFO: task a.out:5770 blocked for more than 10 seconds. [ 224.306111] INFO: task a.out:5786 blocked for more than 10 seconds. [ 224.308129] INFO: task a.out:5798 blocked for more than 10 seconds. [ 224.310068] INFO: task a.out:5813 blocked for more than 10 seconds. [ 224.312073] INFO: task a.out:5825 blocked for more than 10 seconds. [ 224.313958] INFO: task a.out:5458 blocked for more than 10 seconds. [ 224.315811] INFO: task a.out:5477 blocked for more than 10 seconds. [ 224.317721] INFO: task a.out:5485 blocked for more than 10 seconds. [ 224.319709] INFO: task a.out:5521 blocked for more than 10 seconds. [ 224.321709] INFO: task a.out:5530 blocked for more than 10 seconds. [ 224.323633] INFO: task a.out:5575 blocked for more than 10 seconds. [ 224.325630] INFO: task a.out:5686 blocked for more than 10 seconds. [ 224.327633] INFO: task a.out:5698 blocked for more than 10 seconds. [ 224.329602] INFO: task a.out:5719 blocked for more than 10 seconds. [ 224.331501] INFO: task a.out:5734 blocked for more than 10 seconds. [ 224.333448] INFO: task a.out:5748 blocked for more than 10 seconds. [ 224.335411] INFO: task a.out:5763 blocked for more than 10 seconds. [ 224.337343] INFO: task a.out:5775 blocked for more than 10 seconds. [ 224.339231] INFO: task a.out:5788 blocked for more than 10 seconds. [ 224.341156] INFO: task a.out:5800 blocked for more than 10 seconds. [ 224.343165] INFO: task a.out:5821 blocked for more than 10 seconds. [ 224.345157] INFO: task a.out:5461 blocked for more than 10 seconds. [ 224.347063] INFO: task a.out:5475 blocked for more than 10 seconds. [ 224.348970] INFO: task a.out:5486 blocked for more than 10 seconds. [ 224.351030] INFO: task a.out:5567 blocked for more than 10 seconds. [ 224.353060] INFO: task a.out:5577 blocked for more than 10 seconds. [ 224.354909] INFO: task a.out:5672 blocked for more than 10 seconds. [ 224.356761] INFO: task a.out:5690 blocked for more than 10 seconds. [ 224.358740] INFO: task a.out:5712 blocked for more than 10 seconds. [ 224.360722] INFO: task a.out:5722 blocked for more than 10 seconds. [ 224.362725] INFO: task a.out:5742 blocked for more than 10 seconds. [ 224.364623] INFO: task a.out:5754 blocked for more than 10 seconds. [ 224.366649] INFO: task a.out:5768 blocked for more than 10 seconds. [ 224.368651] INFO: task a.out:5782 blocked for more than 10 seconds. [ 224.370523] INFO: task a.out:5796 blocked for more than 10 seconds. [ 224.372377] INFO: task a.out:5811 blocked for more than 10 seconds. [ 224.374224] INFO: task a.out:5824 blocked for more than 10 seconds. [ 224.376253] INFO: task a.out:5481 blocked for more than 10 seconds. [ 224.378262] INFO: task a.out:5494 blocked for more than 10 seconds. [ 224.380189] INFO: task a.out:5528 blocked for more than 10 seconds. [ 224.382210] INFO: task a.out:5576 blocked for more than 10 seconds. [ 224.384217] INFO: task a.out:5662 blocked for more than 10 seconds. [ 224.386101] INFO: task a.out:5675 blocked for more than 10 seconds. [ 224.387969] INFO: task a.out:5692 blocked for more than 10 seconds. [ 224.389825] INFO: task a.out:5708 blocked for more than 10 seconds. [ 224.391758] INFO: task a.out:5721 blocked for more than 10 seconds. [ 224.393657] INFO: task a.out:5736 blocked for more than 10 seconds. [ 224.395577] INFO: task a.out:5750 blocked for more than 10 seconds. [ 224.397571] INFO: task a.out:5767 blocked for more than 10 seconds. [ 224.399579] INFO: task a.out:5783 blocked for more than 10 seconds. [ 224.401539] INFO: task a.out:5795 blocked for more than 10 seconds. [ 224.403410] INFO: task a.out:5810 blocked for more than 10 seconds. [ 224.405301] INFO: task a.out:5465 blocked for more than 10 seconds. [ 224.407194] INFO: task a.out:5483 blocked for more than 10 seconds. [ 224.409169] INFO: task a.out:5493 blocked for more than 10 seconds. [ 224.411220] INFO: task a.out:5512 blocked for more than 10 seconds. [ 224.413257] INFO: task a.out:5571 blocked for more than 10 seconds. [ 224.415156] INFO: task a.out:5678 blocked for more than 10 seconds. [ 224.417071] INFO: task a.out:5689 blocked for more than 10 seconds. [ 224.418921] INFO: task a.out:5710 blocked for more than 10 seconds. [ 224.420791] INFO: task a.out:5728 blocked for more than 10 seconds. [ 224.422642] INFO: task a.out:5741 blocked for more than 10 seconds. [ 224.424491] INFO: task a.out:5753 blocked for more than 10 seconds. [ 224.426527] INFO: task a.out:5766 blocked for more than 10 seconds. [ 224.428583] INFO: task a.out:5777 blocked for more than 10 seconds. [ 224.430508] INFO: task a.out:5792 blocked for more than 10 seconds. [ 224.432408] INFO: task a.out:5804 blocked for more than 10 seconds. [ 224.434273] INFO: task a.out:5820 blocked for more than 10 seconds. [ 224.436125] INFO: task a.out:5467 blocked for more than 10 seconds. [ 224.437998] INFO: task a.out:5482 blocked for more than 10 seconds. [ 224.439868] INFO: task a.out:5506 blocked for more than 10 seconds. [ 224.441763] INFO: task a.out:5513 blocked for more than 10 seconds. [ 224.443824] INFO: task a.out:5520 blocked for more than 10 seconds. [ 224.445849] INFO: task a.out:5673 blocked for more than 10 seconds. [ 224.447810] INFO: task a.out:5691 blocked for more than 10 seconds. [ 224.449697] INFO: task a.out:5709 blocked for more than 10 seconds. [ 224.451550] INFO: task a.out:5724 blocked for more than 10 seconds. [ 224.453425] INFO: task a.out:5739 blocked for more than 10 seconds. [ 224.455320] INFO: task a.out:5756 blocked for more than 10 seconds. [ 224.457223] INFO: task a.out:5772 blocked for more than 10 seconds. [ 224.459271] INFO: task a.out:5787 blocked for more than 10 seconds. [ 224.461337] INFO: task a.out:5797 blocked for more than 10 seconds. [ 224.463336] INFO: task a.out:5818 blocked for more than 10 seconds. [ 224.465229] INFO: task a.out:5831 blocked for more than 10 seconds. [ 224.467137] INFO: task a.out:5469 blocked for more than 10 seconds. [ 224.468994] INFO: task a.out:5473 blocked for more than 10 seconds. [ 224.470930] INFO: task a.out:5484 blocked for more than 10 seconds. [ 224.472824] INFO: task a.out:5525 blocked for more than 10 seconds. [ 224.475015] INFO: task a.out:5661 blocked for more than 10 seconds. [ 224.477571] INFO: task a.out:5671 blocked for more than 10 seconds. [ 224.479594] INFO: task a.out:5685 blocked for more than 10 seconds. [ 224.481574] INFO: task a.out:5699 blocked for more than 10 seconds. [ 224.483441] INFO: task a.out:5704 blocked for more than 10 seconds. [ 224.485314] INFO: task a.out:5731 blocked for more than 10 seconds. [ 224.487163] INFO: task a.out:5749 blocked for more than 10 seconds. [ 224.489028] INFO: task a.out:5765 blocked for more than 10 seconds. [ 224.490958] INFO: task a.out:5776 blocked for more than 10 seconds. [ 224.493029] INFO: task a.out:5790 blocked for more than 10 seconds. [ 224.495054] INFO: task a.out:5801 blocked for more than 10 seconds. [ 224.497054] INFO: task a.out:5822 blocked for more than 10 seconds. [ 224.498927] khungtaskd R running task 29656 953 2 0x80000000 [ 224.501027] Call Trace: [ 224.501796] sched_show_task+0x33a/0x420 [ 224.503205] watchdog+0x7c7/0xba0 [ 224.504277] kthread+0x2e5/0x3e0 [ 224.505373] ? reset_hung_task_detector+0x30/0x30 [ 224.506836] ? kthread_delayed_work_timer_fn+0x250/0x250 [ 224.508467] ret_from_fork+0x3a/0x50 [ 224.509645] 1 lock held by khungtaskd/953: [ 224.510933] #0: 00000000a7346670 (rcu_read_lock){....}, at: watchdog+0x673/0xba0 [ 224.513358] a.out D27464 5454 1 0x00000004 [ 224.515294] Call Trace: [ 224.516192] __schedule+0xb55/0x1dd0 [ 224.517399] ? pci_mmcfg_check_reserved+0x120/0x120 [ 224.518997] ? mark_held_locks+0xc8/0x120 [ 224.520392] ? _raw_spin_unlock_irq+0x27/0x70 [ 224.522016] schedule+0x8f/0x1b0 [ 224.523319] rwsem_down_read_failed+0x24c/0x3a0 [ 224.524907] ? rwsem_down_write_failed+0xce0/0xce0 [ 224.526626] ? block_ioctl+0xd7/0x130 [ 224.527932] ? __ia32_sys_tee+0x200/0x200 [ 224.529362] call_rwsem_down_read_failed+0x18/0x30 [ 224.530966] ? call_rwsem_down_read_failed+0x18/0x30 [ 224.532587] down_read+0x4e/0xb0 [ 224.533669] ? iterate_supers+0x113/0x210 [ 224.534939] iterate_supers+0x113/0x210 [ 224.536181] ksys_sync+0xa5/0x170 [ 224.537307] ? sync_filesystem+0x200/0x200 [ 224.538701] ? kasan_check_write+0x14/0x20 [ 224.540061] ? fput+0x18/0x130 [ 224.541107] ? entry_SYSCALL_64_after_hwframe+0x59/0xbe [ 224.542818] ? do_syscall_64+0x21/0x4e0 [ 224.544182] __ia32_sys_sync+0x9/0x10 [ 224.545437] do_syscall_64+0xd6/0x4e0 [ 224.546675] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 224.548256] RIP: 0033:0x7f774b2694d9 [ 224.549409] Code: Bad RIP value. [ 224.550481] RSP: 002b:00007f774b966f18 EFLAGS: 00000246 ORIG_RAX: 00000000000000a2 [ 224.552780] RAX: ffffffffffffffda RBX: 0000000000602124 RCX: 00007f774b2694d9 [ 224.554964] RDX: 00007f774b2694d9 RSI: 0000000000000000 RDI: 0000000000000000 [ 224.557068] RBP: 0000000000602120 R08: 00007f774b966f70 R09: 00007f774b966f70 [ 224.559216] R10: 00007f774b966f70 R11: 0000000000000246 R12: 0000000000000000 [ 224.561546] R13: 0000000000008c00 R14: 0000000000000000 R15: 00000000756e0874 [ 224.563801] 1 lock held by a.out/5454: [ 224.564980] #0: 00000000d803423d (&type->s_umount_key#54){.+.+}, at: iterate_supers+0x113/0x210 [ 224.567645] a.out D27464 5476 1 0x00000004 [ 224.569476] Call Trace: [ 224.570350] __schedule+0xb55/0x1dd0 [ 224.571556] ? pci_mmcfg_check_reserved+0x120/0x120 [ 224.573065] ? mark_held_locks+0xc8/0x120 [ 224.574334] ? _raw_spin_unlock_irq+0x27/0x70 [ 224.575721] schedule+0x8f/0x1b0 [ 224.576859] rwsem_down_read_failed+0x24c/0x3a0 [ 224.578280] ? rwsem_down_write_failed+0xce0/0xce0 [ 224.579772] ? lock_downgrade+0x840/0x840 [ 224.581060] ? __ia32_sys_tee+0x200/0x200 [ 224.582311] call_rwsem_down_read_failed+0x18/0x30 [ 224.583831] ? call_rwsem_down_read_failed+0x18/0x30 [ 224.585431] down_read+0x4e/0xb0 [ 224.586487] ? iterate_supers+0x113/0x210 [ 224.587757] iterate_supers+0x113/0x210 [ 224.588984] ksys_sync+0xa5/0x170 [ 224.590073] ? sync_filesystem+0x200/0x200 [ 224.591350] ? entry_SYSCALL_64_after_hwframe+0x59/0xbe [ 224.593043] ? do_syscall_64+0x21/0x4e0 [ 224.594309] __ia32_sys_sync+0x9/0x10 [ 224.595540] do_syscall_64+0xd6/0x4e0 [ 224.596773] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 224.598353] RIP: 0033:0x7f774b2694d9 [ 224.599544] Code: Bad RIP value. [ 224.600702] RSP: 002b:00007f774b945f18 EFLAGS: 00000246 ORIG_RAX: 00000000000000a2 [ 224.603112] RAX: ffffffffffffffda RBX: 000000000060213c RCX: 00007f774b2694d9 [ 224.605199] RDX: 00007f774b2694d9 RSI: ffffffffffffff98 RDI: 0000000000000001 [ 224.607302] RBP: 0000000000602138 R08: 0000000000000000 R09: 0000000000000000 [ 224.609402] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000 [ 224.611694] R13: 0000000000008c00 R14: 0000000000000000 R15: 00000000756e0874 [ 224.613927] 1 lock held by a.out/5476: [ 224.615168] #0: 00000000d803423d (&type->s_umount_key#54){.+.+}, at: iterate_supers+0x113/0x210 [ 224.618055] a.out D27464 5491 1 0x00000004 [ 224.619811] Call Trace: [ 224.620649] __schedule+0xb55/0x1dd0 [ 224.621788] ? pci_mmcfg_check_reserved+0x120/0x120 [ 224.623301] ? mark_held_locks+0xc8/0x120 [ 224.624570] ? _raw_spin_unlock_irq+0x27/0x70 [ 224.625939] schedule+0x8f/0x1b0 [ 224.627059] rwsem_down_read_failed+0x24c/0x3a0 [ 224.628508] ? rwsem_down_write_failed+0xce0/0xce0 [ 224.630102] ? block_ioctl+0xd7/0x130 [ 224.631385] ? __ia32_sys_tee+0x200/0x200 [ 224.632659] call_rwsem_down_read_failed+0x18/0x30 [ 224.634158] ? call_rwsem_down_read_failed+0x18/0x30 [ 224.635732] down_read+0x4e/0xb0 [ 224.636782] ? iterate_supers+0x113/0x210 [ 224.638064] iterate_supers+0x113/0x210 [ 224.639287] ksys_sync+0xa5/0x170 [ 224.640370] ? sync_filesystem+0x200/0x200 [ 224.641665] ? kasan_check_write+0x14/0x20 [ 224.642994] ? fput+0x18/0x130 [ 224.644073] ? entry_SYSCALL_64_after_hwframe+0x59/0xbe [ 224.645787] ? do_syscall_64+0x21/0x4e0 [ 224.647115] __ia32_sys_sync+0x9/0x10 [ 224.648350] do_syscall_64+0xd6/0x4e0 [ 224.649592] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 224.651178] RIP: 0033:0x7f774b2694d9 [ 224.652356] Code: Bad RIP value. [ 224.653414] RSP: 002b:00007f774b924f18 EFLAGS: 00000246 ORIG_RAX: 00000000000000a2 [ 224.655692] RAX: ffffffffffffffda RBX: 0000000000602154 RCX: 00007f774b2694d9 [ 224.657831] RDX: 00007f774b2694d9 RSI: 0000000000000000 RDI: 0000000000000000 [ 224.660026] RBP: 0000000000602150 R08: 0000000000000000 R09: 0000000000000000 [ 224.662220] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000 [ 224.664520] R13: 0000000000008c00 R14: 0000000000000000 R15: 00000000756e0874 [ 224.666681] 1 lock held by a.out/5491: [ 224.667890] #0: 00000000d803423d (&type->s_umount_key#54){.+.+}, at: iterate_supers+0x113/0x210 (...snipped...) [ 227.999265] a.out D27464 5463 1 0x00000004 [ 228.001055] Call Trace: [ 228.001867] __schedule+0xb55/0x1dd0 [ 228.003079] ? trace_hardirqs_on+0xd/0x10 [ 228.004417] ? pci_mmcfg_check_reserved+0x120/0x120 [ 228.006059] ? wait_woken+0x2b0/0x2b0 [ 228.007311] schedule+0x8f/0x1b0 [ 228.008433] p9_client_rpc+0x39a/0x1040 [ 228.009721] ? __free_pages_ok+0xfdc/0x1aa0 [ 228.011141] ? trace_event_raw_event_9p_client_res+0x310/0x310 [ 228.013036] ? p9_parse_header+0x12b/0x4f0 [ 228.014435] ? remove_wait_queue+0x1b0/0x1b0 [ 228.015849] ? mark_held_locks+0xc8/0x120 [ 228.017191] ? p9_fd_cancel+0x50/0x1f0 [ 228.018472] p9_client_flush+0xfa/0x1f0 [ 228.019781] ? p9_client_rpc+0x1040/0x1040 [ 228.021204] ? _raw_spin_unlock+0x22/0x30 [ 228.022543] ? p9_fd_cancel+0x50/0x1f0 [ 228.023799] p9_client_rpc+0x9d8/0x1040 [ 228.025095] ? trace_event_raw_event_9p_client_res+0x310/0x310 [ 228.026997] ? p9_idpool_put+0x31/0x40 [ 228.028255] ? mark_held_locks+0xc8/0x120 [ 228.029598] ? mark_held_locks+0xc8/0x120 [ 228.030977] ? remove_wait_queue+0x1b0/0x1b0 [ 228.032414] ? trace_hardirqs_on_caller+0x442/0x5c0 [ 228.034044] ? trace_hardirqs_on+0xd/0x10 [ 228.035434] ? p9_client_stat+0x1e4/0x4a0 [ 228.036790] ? kasan_check_read+0x11/0x20 [ 228.038127] p9_client_clunk+0x80/0x180 [ 228.039431] v9fs_mount+0x515/0x7d0 [ 228.040615] mount_fs+0x81/0x2b0 [ 228.041733] vfs_kern_mount+0x66/0x3c0 [ 228.043241] do_mount+0x366/0x2910 [ 228.044403] ? copy_mount_string+0x20/0x20 [ 228.045780] ? kmem_cache_alloc_trace+0x33c/0x750 [ 228.047370] ? copy_mount_options+0x55/0x2f0 [ 228.048814] ksys_mount+0x7e/0xd0 [ 228.049997] __x64_sys_mount+0xb9/0x150 [ 228.051328] ? trace_hardirqs_on_caller+0x442/0x5c0 [ 228.052925] do_syscall_64+0xd6/0x4e0 [ 228.054171] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 228.055834] RIP: 0033:0x7f774b2694d9 [ 228.057043] Code: Bad RIP value. [ 228.058164] RSP: 002b:00007f774b966f18 EFLAGS: 00000246 ORIG_RAX: 00000000000000a5 [ 228.060583] RAX: ffffffffffffffda RBX: 0000000000602124 RCX: 00007f774b2694d9 [ 228.062873] RDX: 0000000020000340 RSI: 00000000200000c0 RDI: 0000000000000000 [ 228.065187] RBP: 0000000000602120 R08: 00000000200003c0 R09: 00007f774b966f70 [ 228.067481] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000 [ 228.069793] R13: 0000000000008c00 R14: 0000000000000000 R15: 00000000756e0874 [ 228.072166] 1 lock held by a.out/5463: [ 228.073427] #0: 00000000d803423d (&type->s_umount_key#53/1){+.+.}, at: sget_userns+0x21d/0xb50 (...snipped...) [ 280.160650] a.out D27464 5463 1 0x00000004 [ 280.162434] Call Trace: [ 280.163327] __schedule+0xb55/0x1dd0 [ 280.164569] ? trace_hardirqs_on+0xd/0x10 [ 280.165915] ? pci_mmcfg_check_reserved+0x120/0x120 [ 280.167526] ? wait_woken+0x2b0/0x2b0 [ 280.168818] schedule+0x8f/0x1b0 [ 280.169893] p9_client_rpc+0x39a/0x1040 [ 280.171455] ? __free_pages_ok+0xfdc/0x1aa0 [ 280.172865] ? trace_event_raw_event_9p_client_res+0x310/0x310 [ 280.174679] ? p9_parse_header+0x12b/0x4f0 [ 280.176010] ? remove_wait_queue+0x1b0/0x1b0 [ 280.177452] ? mark_held_locks+0xc8/0x120 [ 280.178830] ? p9_fd_cancel+0x50/0x1f0 [ 280.180109] p9_client_flush+0xfa/0x1f0 [ 280.181436] ? p9_client_rpc+0x1040/0x1040 [ 280.182758] ? _raw_spin_unlock+0x22/0x30 [ 280.184050] ? p9_fd_cancel+0x50/0x1f0 [ 280.185337] p9_client_rpc+0x9d8/0x1040 [ 280.186614] ? trace_event_raw_event_9p_client_res+0x310/0x310 [ 280.188527] ? p9_idpool_put+0x31/0x40 [ 280.189799] ? mark_held_locks+0xc8/0x120 [ 280.191170] ? mark_held_locks+0xc8/0x120 [ 280.192603] ? remove_wait_queue+0x1b0/0x1b0 [ 280.194048] ? trace_hardirqs_on_caller+0x442/0x5c0 [ 280.195666] ? trace_hardirqs_on+0xd/0x10 [ 280.197010] ? p9_client_stat+0x1e4/0x4a0 [ 280.198296] ? kasan_check_read+0x11/0x20 [ 280.199574] p9_client_clunk+0x80/0x180 [ 280.200848] v9fs_mount+0x515/0x7d0 [ 280.202058] mount_fs+0x81/0x2b0 [ 280.203180] vfs_kern_mount+0x66/0x3c0 [ 280.204456] do_mount+0x366/0x2910 [ 280.205664] ? copy_mount_string+0x20/0x20 [ 280.207064] ? kmem_cache_alloc_trace+0x33c/0x750 [ 280.208618] ? copy_mount_options+0x55/0x2f0 [ 280.210027] ksys_mount+0x7e/0xd0 [ 280.211114] __x64_sys_mount+0xb9/0x150 [ 280.212389] ? trace_hardirqs_on_caller+0x442/0x5c0 [ 280.213932] do_syscall_64+0xd6/0x4e0 [ 280.215187] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 280.216849] RIP: 0033:0x7f774b2694d9 [ 280.218063] Code: Bad RIP value. [ 280.219196] RSP: 002b:00007f774b966f18 EFLAGS: 00000246 ORIG_RAX: 00000000000000a5 [ 280.221658] RAX: ffffffffffffffda RBX: 0000000000602124 RCX: 00007f774b2694d9 [ 280.223981] RDX: 0000000020000340 RSI: 00000000200000c0 RDI: 0000000000000000 [ 280.226240] RBP: 0000000000602120 R08: 00000000200003c0 R09: 00007f774b966f70 [ 280.228403] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000 [ 280.230615] R13: 0000000000008c00 R14: 0000000000000000 R15: 00000000756e0874 [ 280.232804] 1 lock held by a.out/5463: [ 280.234032] #0: 00000000d803423d (&type->s_umount_key#53/1){+.+.}, at: sget_userns+0x21d/0xb50 [ 280.236875] a.out D27464 5481 1 0x00000004 [ 280.238721] Call Trace: [ 280.239610] __schedule+0xb55/0x1dd0 [ 280.240798] ? pci_mmcfg_check_reserved+0x120/0x120 [ 280.242368] ? mark_held_locks+0xc8/0x120 [ 280.243712] ? _raw_spin_unlock_irq+0x27/0x70 [ 280.245182] schedule+0x8f/0x1b0 [ 280.246319] rwsem_down_read_failed+0x24c/0x3a0 [ 280.247852] ? rwsem_down_write_failed+0xce0/0xce0 [ 280.249415] ? lock_downgrade+0x840/0x840 [ 280.250785] ? __ia32_sys_tee+0x200/0x200 [ 280.252169] call_rwsem_down_read_failed+0x18/0x30 [ 280.253773] ? call_rwsem_down_read_failed+0x18/0x30 [ 280.255455] down_read+0x4e/0xb0 [ 280.256585] ? iterate_supers+0x113/0x210 [ 280.257931] iterate_supers+0x113/0x210 [ 280.259220] ksys_sync+0xa5/0x170 [ 280.260386] ? sync_filesystem+0x200/0x200 [ 280.261782] ? entry_SYSCALL_64_after_hwframe+0x59/0xbe [ 280.263495] ? do_syscall_64+0x21/0x4e0 [ 280.264874] __ia32_sys_sync+0x9/0x10 [ 280.266117] do_syscall_64+0xd6/0x4e0 [ 280.267364] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 280.269027] RIP: 0033:0x7f774b2694d9 [ 280.270249] Code: Bad RIP value. [ 280.271390] RSP: 002b:00007f774b945f18 EFLAGS: 00000246 ORIG_RAX: 00000000000000a2 [ 280.273819] RAX: ffffffffffffffda RBX: 000000000060213c RCX: 00007f774b2694d9 [ 280.275980] RDX: 00007f774b2694d9 RSI: ffffffffffffff98 RDI: 0000000000000001 [ 280.278234] RBP: 0000000000602138 R08: 0000000000000000 R09: 0000000000000000 [ 280.280421] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000 [ 280.282597] R13: 0000000000008c00 R14: 0000000000000000 R15: 00000000756e0874 [ 280.284843] 1 lock held by a.out/5481: [ 280.286118] #0: 00000000d803423d (&type->s_umount_key#54){.+.+}, at: iterate_supers+0x113/0x210 ^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: INFO: task hung in iterate_supers 2018-07-10 10:34 ` Tetsuo Handa @ 2018-07-11 10:19 ` Tetsuo Handa 2018-07-13 10:09 ` [PATCH] fs: Add to super_blocks list after SB_BORN is set Tetsuo Handa 0 siblings, 1 reply; 5+ messages in thread From: Tetsuo Handa @ 2018-07-11 10:19 UTC (permalink / raw) To: viro; +Cc: syzbot, linux-fsdevel, linux-kernel, syzkaller-bugs On 2018/07/10 19:34, Tetsuo Handa wrote: > It turned out that, although the reason of stalling v9fs_mount() is currently > unknown, the reason of many processes stuck at iterate_supers() is that > they are unable to take s->s_umount object due to down_write_nested() below. > > /* > * sget() can have s_umount recursion. > * > * When it cannot find a suitable sb, it allocates a new > * one (this one), and tries again to find a suitable old > * one. > * > * In case that succeeds, it will acquire the s_umount > * lock of the old one. Since these are clearly distrinct > * locks, and this object isn't exposed yet, there's no > * risk of deadlocks. > * > * Annotate this by putting this lock in a different > * subclass. > */ > down_write_nested(&s->s_umount, SINGLE_DEPTH_NESTING); > Guessing from commit dabe0dc194d5d56d ("vfs: fix the rest of sget() races"), this is an overlooked sget() race. iterate_supers() is calling down_read(&sb_s_umount) on all superblocks found by traversing super_blocks list. But sget_userns() adds "newly created superblock to super_blocks list with ->s_umount held by alloc_super() for write" before "mount_fs() sets SB_BORN flag after returning from type->mount()". Therefore, if type->mount() (e.g. v9fs_mount()) took long after sget() for some reason, processes will be blocked on a superblock on SB_BORN not yet set. Doing the test (which is done after ->s_umount is held) before holding ->s_umount (patch shown below) works for me. Although there seems to be many bugs in v9fs code, I think that making sure that other threads won't try to wait for superblock with SB_BORN not yet set is better. --- fs/super.c | 31 ++++++++++++++++++++++--------- 1 file changed, 22 insertions(+), 9 deletions(-) diff --git a/fs/super.c b/fs/super.c index 50728d9..03c3b3f 100644 --- a/fs/super.c +++ b/fs/super.c @@ -37,6 +37,11 @@ #include <linux/user_namespace.h> #include "internal.h" +static inline bool sb_is_alive(struct super_block *sb) +{ + return sb->s_root && (sb->s_flags & SB_BORN); +} + static int thaw_super_locked(struct super_block *sb); static LIST_HEAD(super_blocks); @@ -407,8 +412,7 @@ static int grab_super(struct super_block *s) __releases(sb_lock) bool trylock_super(struct super_block *sb) { if (down_read_trylock(&sb->s_umount)) { - if (!hlist_unhashed(&sb->s_instances) && - sb->s_root && (sb->s_flags & SB_BORN)) + if (!hlist_unhashed(&sb->s_instances) && sb_is_alive(sb)) return true; up_read(&sb->s_umount); } @@ -590,6 +594,8 @@ static void __iterate_supers(void (*f)(struct super_block *)) spin_lock(&sb_lock); list_for_each_entry(sb, &super_blocks, s_list) { + if (!sb_is_alive(sb)) + continue; if (hlist_unhashed(&sb->s_instances)) continue; sb->s_count++; @@ -620,13 +626,15 @@ void iterate_supers(void (*f)(struct super_block *, void *), void *arg) spin_lock(&sb_lock); list_for_each_entry(sb, &super_blocks, s_list) { + if (!sb_is_alive(sb)) + continue; if (hlist_unhashed(&sb->s_instances)) continue; sb->s_count++; spin_unlock(&sb_lock); down_read(&sb->s_umount); - if (sb->s_root && (sb->s_flags & SB_BORN)) + if (sb_is_alive(sb)) f(sb, arg); up_read(&sb->s_umount); @@ -656,11 +664,13 @@ void iterate_supers_type(struct file_system_type *type, spin_lock(&sb_lock); hlist_for_each_entry(sb, &type->fs_supers, s_instances) { + if (!sb_is_alive(sb)) + continue; sb->s_count++; spin_unlock(&sb_lock); down_read(&sb->s_umount); - if (sb->s_root && (sb->s_flags & SB_BORN)) + if (sb_is_alive(sb)) f(sb, arg); up_read(&sb->s_umount); @@ -689,6 +699,8 @@ static struct super_block *__get_super(struct block_device *bdev, bool excl) if (hlist_unhashed(&sb->s_instances)) continue; if (sb->s_bdev == bdev) { + if (!sb_is_alive(sb)) + continue; sb->s_count++; spin_unlock(&sb_lock); if (!excl) @@ -696,7 +708,7 @@ static struct super_block *__get_super(struct block_device *bdev, bool excl) else down_write(&sb->s_umount); /* still alive? */ - if (sb->s_root && (sb->s_flags & SB_BORN)) + if (sb_is_alive(sb)) return sb; if (!excl) up_read(&sb->s_umount); @@ -813,11 +825,13 @@ struct super_block *user_get_super(dev_t dev) if (hlist_unhashed(&sb->s_instances)) continue; if (sb->s_dev == dev) { + if (!sb_is_alive(sb)) + continue; sb->s_count++; spin_unlock(&sb_lock); down_read(&sb->s_umount); /* still alive? */ - if (sb->s_root && (sb->s_flags & SB_BORN)) + if (sb_is_alive(sb)) return sb; up_read(&sb->s_umount); /* nope, got unmounted */ @@ -916,8 +930,7 @@ int do_remount_sb(struct super_block *sb, int sb_flags, void *data, int force) static void do_emergency_remount_callback(struct super_block *sb) { down_write(&sb->s_umount); - if (sb->s_root && sb->s_bdev && (sb->s_flags & SB_BORN) && - !sb_rdonly(sb)) { + if (sb_is_alive(sb) && sb->s_bdev && !sb_rdonly(sb)) { /* * What lock protects sb->s_flags?? */ @@ -947,7 +960,7 @@ void emergency_remount(void) static void do_thaw_all_callback(struct super_block *sb) { down_write(&sb->s_umount); - if (sb->s_root && sb->s_flags & SB_BORN) { + if (sb_is_alive(sb)) { emergency_thaw_bdev(sb); thaw_super_locked(sb); } else { -- 1.8.3.1 ---------------------------------------- // autogenerated by syzkaller (http://github.com/google/syzkaller) #define _GNU_SOURCE #include <fcntl.h> #include <linux/futex.h> #include <pthread.h> #include <stdio.h> #include <string.h> #include <sys/stat.h> #include <sys/syscall.h> #include <unistd.h> #include <sys/mount.h> #include <signal.h> struct thread_t { int created, running, call; pthread_t th; }; static struct thread_t threads[16]; static void execute_call(int call); static int running; static void* thr(void* arg) { struct thread_t* th = (struct thread_t*)arg; for (;;) { while (!__atomic_load_n(&th->running, __ATOMIC_ACQUIRE)) syscall(SYS_futex, &th->running, FUTEX_WAIT, 0, 0); execute_call(th->call); __atomic_fetch_sub(&running, 1, __ATOMIC_RELAXED); __atomic_store_n(&th->running, 0, __ATOMIC_RELEASE); syscall(SYS_futex, &th->running, FUTEX_WAKE); } return 0; } static void execute(int num_calls) { int call, thread; running = 0; for (call = 0; call < num_calls; call++) { for (thread = 0; thread < sizeof(threads) / sizeof(threads[0]); thread++) { struct thread_t* th = &threads[thread]; if (!th->created) { th->created = 1; pthread_attr_t attr; pthread_attr_init(&attr); pthread_attr_setstacksize(&attr, 128 << 10); pthread_create(&th->th, &attr, thr, th); } if (!__atomic_load_n(&th->running, __ATOMIC_ACQUIRE)) { th->call = call; __atomic_fetch_add(&running, 1, __ATOMIC_RELAXED); __atomic_store_n(&th->running, 1, __ATOMIC_RELEASE); syscall(SYS_futex, &th->running, FUTEX_WAKE); struct timespec ts; ts.tv_sec = 0; ts.tv_nsec = 20 * 1000 * 1000; syscall(SYS_futex, &th->running, FUTEX_WAIT, 1, &ts); if (__atomic_load_n(&running, __ATOMIC_RELAXED)) usleep((call == num_calls - 1) ? 10000 : 1000); break; } } } } static void execute_call(int call) { static int fd[2] = { EOF, EOF }; static char buffer[128] = { }; switch (call) { case 4: sync(); break; case 6: if (pipe(fd) == EOF) kill(0, SIGKILL); break; case 7: mkdir("./file0", 0); break; case 8: snprintf(buffer, sizeof(buffer) - 1, "trans=fd,rfdno=0x%x,wfdno=0x%x,version=9p2000.u,", fd[0], fd[1]); mount(NULL, "./file0", "9p", 0, buffer); break; case 9: write(fd[1], "\x79\x04\x00\x00\x7d\x01\x00\x05\x00\x58\x00\x00\x00\x00\x00\x00" "\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00" "\x00\x00\x00\x00\x00\x00\x00\x00\x23\x00\x00\x00\x00\x39\x00\x00" "\x00\x00\x00\x10\x00\x76\x65\x72\x73\x69\x6f\x6e\x3d\x39\x70\x32" "\x30\x30\x30\x2e\x75\x0d\x00\x77\x6c\x61\x6e\x31\x76\x62\x6f\x78" "\x6e\x65\x74\x30\x03\x00\x39\x70\x00\x05\x00\x72\x66\x64\x6e\x6f" "\x0c\x00\x76\x9a\xae\x6d\x5f\xff\xf0\x68\xa6\xbe\x6b\x2c\xc3\xfd" "\x62\x6f\x78\x6e\x65\x74\x31\x28\x7d\x25\x24\x00\x00\x00\x00\x00" "\x00\x00\x00\x00\x00\x00\x00", 135); break; } } int main(int argc, char *argv[]) { int procid; for (procid = 0; procid < 8; procid++) if (fork() == 0) while (1) execute(10); sleep(1000000); return 0; } ---------------------------------------- By the way, iterate_supers_type() was introduced in v3.1 for fs/ubifs/debug.c /* * TODO: this is racy - the file-system might have already been * unmounted and we'd oops in this case. The plan is to fix it with * help of 'iterate_supers_type()' which we should have in v3.0: when * a debugfs opened, we rember FS's UUID in file->private_data. Then * whenever we access the FS via a debugfs file, we iterate all UBIFS * superblocks and fine the one with the same UUID, and take the * locking right. * * The other way to go suggested by Al Viro is to create a separate * 'ubifs-debug' file-system instead. */ but is still not called. Do we want to remove iterate_supers_type() ? ^ permalink raw reply [flat|nested] 5+ messages in thread
* [PATCH] fs: Add to super_blocks list after SB_BORN is set. 2018-07-11 10:19 ` Tetsuo Handa @ 2018-07-13 10:09 ` Tetsuo Handa 2018-07-13 12:00 ` Al Viro 0 siblings, 1 reply; 5+ messages in thread From: Tetsuo Handa @ 2018-07-13 10:09 UTC (permalink / raw) To: viro; +Cc: syzbot, linux-fsdevel, linux-kernel, syzkaller-bugs More simple version. Is this assumption correct? From 52f10183f2b921cd946dd4c83d9b1d99bc48914e Mon Sep 17 00:00:00 2001 From: Tetsuo Handa <penguin-kernel@I-love.SKAURA.ne.jp> Date: Fri, 13 Jul 2018 12:15:54 +0900 Subject: [PATCH] fs: Add to super_blocks list after SB_BORN is set. syzbot is reporting hung tasks at iterate_supers() [1]. This is because iterate_supers() is calling down_read(&sb->s_umount) on all superblocks found by traversing super_blocks list while sget_userns() adds "newly created superblock to super_blocks list with ->s_umount held by alloc_super() for write" before "mount_fs() sets SB_BORN flag after returning from type->mount()". If type->mount() took long time after returning from sget() for some reason, e.g. sync() request will be blocked on !SB_BORN superblocks. Also, since security_sb_kern_mount() which is called after SB_BORN is set might involve GFP_KERNEL memory allocation, we can't guarantee that up_write(&sb->s_umount) is called as soon as SB_BORN was set. Therefore, this patch makes sure that newly created superblock is added to super_blocks list immediately before calling up_write(&sb->s_umount). [1] https://syzkaller.appspot.com/bug?id=3c0c173ff55822aacb81ce7ae27a6676fba29a5c Signed-off-by: Tetsuo Handa <penguin-kernel@I-love.SKAURA.ne.jp> --- fs/super.c | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/fs/super.c b/fs/super.c index 50728d9..8b2c8cc 100644 --- a/fs/super.c +++ b/fs/super.c @@ -236,6 +236,7 @@ static struct super_block *alloc_super(struct file_system_type *type, int flags, s->s_flags = flags; if (s->s_user_ns != &init_user_ns) s->s_iflags |= SB_I_NODEV; + INIT_LIST_HEAD(&s->s_list); INIT_HLIST_NODE(&s->s_instances); INIT_HLIST_BL_HEAD(&s->s_roots); mutex_init(&s->s_sync_lock); @@ -527,8 +528,6 @@ struct super_block *sget_userns(struct file_system_type *type, } s->s_type = type; strlcpy(s->s_id, type->name, sizeof(s->s_id)); - list_add_tail(&s->s_list, &super_blocks); - hlist_add_head(&s->s_instances, &type->fs_supers); spin_unlock(&sb_lock); get_filesystem(type); register_shrinker_prepared(&s->s_shrink); @@ -1305,6 +1304,12 @@ mount_fs(struct file_system_type *type, int flags, const char *name, void *data) WARN((sb->s_maxbytes < 0), "%s set sb->s_maxbytes to " "negative value (%lld)\n", type->name, sb->s_maxbytes); + if (list_empty(&sb->s_list)) { + spin_lock(&sb_lock); + list_add_tail(&sb->s_list, &super_blocks); + hlist_add_head(&sb->s_instances, &type->fs_supers); + spin_unlock(&sb_lock); + } up_write(&sb->s_umount); free_secdata(secdata); return root; -- 2.7.4 ^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH] fs: Add to super_blocks list after SB_BORN is set. 2018-07-13 10:09 ` [PATCH] fs: Add to super_blocks list after SB_BORN is set Tetsuo Handa @ 2018-07-13 12:00 ` Al Viro 0 siblings, 0 replies; 5+ messages in thread From: Al Viro @ 2018-07-13 12:00 UTC (permalink / raw) To: Tetsuo Handa; +Cc: syzbot, linux-fsdevel, linux-kernel, syzkaller-bugs On Fri, Jul 13, 2018 at 07:09:03PM +0900, Tetsuo Handa wrote: > More simple version. Is this assumption correct? Racy, for obvious reasons (sget/sget) ^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2018-07-13 12:00 UTC | newest] Thread overview: 5+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2018-07-10 10:30 INFO: task hung in iterate_supers syzbot 2018-07-10 10:34 ` Tetsuo Handa 2018-07-11 10:19 ` Tetsuo Handa 2018-07-13 10:09 ` [PATCH] fs: Add to super_blocks list after SB_BORN is set Tetsuo Handa 2018-07-13 12:00 ` Al Viro
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox
Powered by JetHome