syzbot


INFO: task hung in handle_userfault

Status: fixed on 2018/05/17 10:02
Subsystems: fs
[Documentation on labels]
Reported-by: syzbot+68cc5a34129d0dbd8524@syzkaller.appspotmail.com
Fix commit: 8236b0ae31c8 bdi: wake up concurrent wb_shutdown() callers.
First crash: 2204d, last: 2182d

Sample crash report:
FAULT_FLAG_ALLOW_RETRY missing 30
audit: type=1326 audit(1525314892.265:7306): auid=4294967295 uid=0 gid=0 ses=4294967295 pid=2083 comm="syz-executor7" exe="/root/syz-executor7" sig=31 arch=c000003e syscall=228 compat=0 ip=0x45879a code=0x0
audit: type=1326 audit(1525314892.265:7307): auid=4294967295 uid=0 gid=0 ses=4294967295 pid=2083 comm="syz-executor7" exe="/root/syz-executor7" sig=31 arch=c000003e syscall=202 compat=0 ip=0x455979 code=0x0
CPU: 0 PID: 2089 Comm: syz-executor6 Not tainted 4.17.0-rc3+ #29
INFO: task kworker/0:3:2105 blocked for more than 120 seconds.
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+0x1b9/0x294 lib/dump_stack.c:113
 handle_userfault.cold.32+0x44/0x5a fs/userfaultfd.c:430
      Not tainted 4.17.0-rc3+ #29
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/0:3     D
19800  2105      2 0x80000000
Workqueue: events cgwb_release_workfn
Call Trace:
 context_switch kernel/sched/core.c:2848 [inline]
 __schedule+0x801/0x1e30 kernel/sched/core.c:3490
 do_anonymous_page mm/memory.c:3147 [inline]
 handle_pte_fault mm/memory.c:3961 [inline]
 __handle_mm_fault+0x38d8/0x4310 mm/memory.c:4087
 handle_mm_fault+0x53a/0xc70 mm/memory.c:4124
 __do_page_fault+0x60b/0xe40 arch/x86/mm/fault.c:1399
 schedule+0xef/0x430 kernel/sched/core.c:3549
 do_page_fault+0xee/0x8a7 arch/x86/mm/fault.c:1474
 page_fault+0x1e/0x30 arch/x86/entry/entry_64.S:1160
RIP: 0010:copy_user_enhanced_fast_string+0xe/0x20 arch/x86/lib/copy_user_64.S:180
RSP: 0018:ffff8801afe5f558 EFLAGS: 00010202
RAX: 0000000000000000 RBX: 00000000000000e8 RCX: 00000000000000e8
RDX: 00000000000000e8 RSI: 0000000020012f18 RDI: ffff8801d8b77cc0
RBP: ffff8801afe5f590 R08: ffffed003b16efb5 R09: ffffed003b16efb5
R10: ffffed003b16efb4 R11: ffff8801d8b77da7 R12: 0000000020013000
R13: 0000000020012f18 R14: ffff8801d8b77cc0 R15: 00007ffffffff000
 copy_from_user include/linux/uaccess.h:147 [inline]
 memdup_user+0x54/0xa0 mm/util.c:164
 xfrm_user_policy+0x1c0/0xae0 net/xfrm/xfrm_state.c:2074
 bit_wait+0x18/0x90 kernel/sched/wait_bit.c:197
 __wait_on_bit+0xb3/0x130 kernel/sched/wait_bit.c:48
 do_ip_setsockopt.isra.13+0x1d87/0x3e50 net/ipv4/ip_sockglue.c:1159
 out_of_line_wait_on_bit+0x204/0x3a0 kernel/sched/wait_bit.c:63
 wait_on_bit include/linux/wait_bit.h:76 [inline]
 wb_shutdown+0x370/0x470 mm/backing-dev.c:366
 ip_setsockopt+0x47/0xf0 net/ipv4/ip_sockglue.c:1246
 tcp_setsockopt+0x93/0xe0 net/ipv4/tcp.c:2890
 sock_common_setsockopt+0x9a/0xe0 net/core/sock.c:3039
 __sys_setsockopt+0x1bd/0x390 net/socket.c:1903
 cgwb_release_workfn+0x87/0x750 mm/backing-dev.c:509
 __do_sys_setsockopt net/socket.c:1914 [inline]
 __se_sys_setsockopt net/socket.c:1911 [inline]
 __x64_sys_setsockopt+0xbe/0x150 net/socket.c:1911
 do_syscall_64+0x1b1/0x800 arch/x86/entry/common.c:287
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
 process_one_work+0xc1e/0x1b50 kernel/workqueue.c:2145
RIP: 0033:0x455979
RSP: 002b:00007f1ceb88ec68 EFLAGS: 00000246 ORIG_RAX: 0000000000000036
RAX: ffffffffffffffda RBX: 00007f1ceb88f6d4 RCX: 0000000000455979
RDX: 0000000000000010 RSI: 0000000000000000 RDI: 0000000000000017
RBP: 000000000072bea0 R08: 00000000000000e8 R09: 0000000000000000
R10: 0000000020012f18 R11: 0000000000000246 R12: 00000000ffffffff
R13: 00000000000005b4 R14: 00000000006fc980 R15: 0000000000000000
IPVS: set_ctl: invalid protocol: 44 172.20.20.170:20000 sed
IPVS: set_ctl: invalid protocol: 44 172.20.20.170:20000 sed
 worker_thread+0x1cc/0x1440 kernel/workqueue.c:2279
 kthread+0x345/0x410 kernel/kthread.c:238
 ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:412

Showing all locks held in the system:
2 locks held by khungtaskd/893:
 #0: 00000000e02ae6e4 (rcu_read_lock){....}, at: check_hung_uninterruptible_tasks kernel/hung_task.c:175 [inline]
 #0: 00000000e02ae6e4 (rcu_read_lock){....}, at: watchdog+0x1ff/0xf60 kernel/hung_task.c:249
 #1: 000000000b2bc01d (tasklist_lock){.+.+}, at: debug_show_all_locks+0xde/0x34a kernel/locking/lockdep.c:4470
2 locks held by kworker/0:3/2105:
 #0: 00000000ce57c193 ((wq_completion)"events"){+.+.}, at: __write_once_size include/linux/compiler.h:215 [inline]
 #0: 00000000ce57c193 ((wq_completion)"events"){+.+.}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
 #0: 00000000ce57c193 ((wq_completion)"events"){+.+.}, at: atomic64_set include/asm-generic/atomic-instrumented.h:40 [inline]
 #0: 00000000ce57c193 ((wq_completion)"events"){+.+.}, at: atomic_long_set include/asm-generic/atomic-long.h:57 [inline]
 #0: 00000000ce57c193 ((wq_completion)"events"){+.+.}, at: set_work_data kernel/workqueue.c:617 [inline]
 #0: 00000000ce57c193 ((wq_completion)"events"){+.+.}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
 #0: 00000000ce57c193 ((wq_completion)"events"){+.+.}, at: process_one_work+0xaef/0x1b50 kernel/workqueue.c:2116
 #1: 00000000ab087552 ((work_completion)(&wb->release_work)){+.+.}, at: process_one_work+0xb46/0x1b50 kernel/workqueue.c:2120
2 locks held by getty/4460:
 #0: 000000009378d1d2 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 00000000cf66612c (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by getty/4461:
 #0: 0000000045db1e4a (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 00000000c7b0e88a (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by getty/4462:
 #0: 00000000207b5fcb (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 00000000933b9fde (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by getty/4463:
 #0: 0000000058b80ec8 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 000000007989aa5d (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by getty/4464:
 #0: 00000000c55c161c (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 0000000061776a13 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by getty/4465:
 #0: 00000000fd32d24d (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 00000000b4a385c3 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by getty/4466:
 #0: 00000000d4d02f8f (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 000000002a1013bc (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by kworker/0:5/19399:
 #0: 000000006a774790 ((wq_completion)"rcu_gp"){+.+.}, at: __write_once_size include/linux/compiler.h:215 [inline]
 #0: 000000006a774790 ((wq_completion)"rcu_gp"){+.+.}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
 #0: 000000006a774790 ((wq_completion)"rcu_gp"){+.+.}, at: atomic64_set include/asm-generic/atomic-instrumented.h:40 [inline]
 #0: 000000006a774790 ((wq_completion)"rcu_gp"){+.+.}, at: atomic_long_set include/asm-generic/atomic-long.h:57 [inline]
 #0: 000000006a774790 ((wq_completion)"rcu_gp"){+.+.}, at: set_work_data kernel/workqueue.c:617 [inline]
 #0: 000000006a774790 ((wq_completion)"rcu_gp"){+.+.}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
 #0: 000000006a774790 ((wq_completion)"rcu_gp"){+.+.}, at: process_one_work+0xaef/0x1b50 kernel/workqueue.c:2116
 #1: 0000000086cb501b ((work_completion)(&rew.rew_work)){+.+.}, at: process_one_work+0xb46/0x1b50 kernel/workqueue.c:2120
1 lock held by syz-executor0/2116:
 #0: 00000000e9ce86a3 (rcu_sched_state.exp_mutex){+.+.}, at: exp_funnel_lock kernel/rcu/tree_exp.h:281 [inline]
 #0: 00000000e9ce86a3 (rcu_sched_state.exp_mutex){+.+.}, at: _synchronize_rcu_expedited.constprop.73+0x9dd/0xad0 kernel/rcu/tree_exp.h:616
1 lock held by syz-executor1/2177:
 #0: 00000000392c6156 (event_mutex){+.+.}, at: perf_trace_destroy+0x28/0x100 kernel/trace/trace_event_perf.c:235
3 locks held by syz-executor4/2182:
 #0: 00000000e3109d66 (&sig->cred_guard_mutex){+.+.}, at: __do_sys_perf_event_open+0x129f/0x2fa0 kernel/events/core.c:10475
 #1: 0000000034650357 (&pmus_srcu){....}, at: perf_event_alloc.part.91+0xfa4/0x3090 kernel/events/core.c:10034
 #2: 00000000392c6156 (event_mutex){+.+.}, at: perf_trace_init+0x50/0x250 kernel/trace/trace_event_perf.c:217

=============================================

NMI backtrace for cpu 1
CPU: 1 PID: 893 Comm: khungtaskd Not tainted 4.17.0-rc3+ #29
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+0x1b9/0x294 lib/dump_stack.c:113
 nmi_cpu_backtrace.cold.4+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:138 [inline]
 check_hung_task kernel/hung_task.c:132 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:190 [inline]
 watchdog+0xc10/0xf60 kernel/hung_task.c:249
 kthread+0x345/0x410 kernel/kthread.c:238
 ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:412
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 4537 Comm: syz-executor1 Not tainted 4.17.0-rc3+ #29
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
RIP: 0010:accumulate_sum kernel/sched/fair.c:3146 [inline]
RIP: 0010:___update_load_sum kernel/sched/fair.c:3226 [inline]
RIP: 0010:__update_load_avg_cfs_rq.isra.35+0x18c/0x590 kernel/sched/fair.c:3332
RSP: 0018:ffff8801943aeed0 EFLAGS: 00000006
RAX: 0000000000000014 RBX: ffff8801dae2c740 RCX: 0000000000000000
RDX: dffffc0000000000 RSI: ffff8801dae2c7d0 RDI: ffff8801dae2c7d0
RBP: ffff8801943aef08 R08: 000000000000022a R09: 0000000000000001
R10: 00000000000001f2 R11: 0000000000000001 R12: 000000000000023e
R13: 00000000000168b4 R14: 0000000000001209 R15: 0000000000000000
FS:  00000000012ad940(0000) GS:ffff8801dae00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fa4b683aa20 CR3: 0000000194263000 CR4: 00000000001426f0
DR0: 0000000020000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000600
Call Trace:
 update_cfs_rq_load_avg kernel/sched/fair.c:3708 [inline]
 update_load_avg+0x2d9/0x2570 kernel/sched/fair.c:3809
 dequeue_entity+0xe1/0x15c0 kernel/sched/fair.c:4269
 dequeue_task_fair+0xea/0x9c0 kernel/sched/fair.c:5419
 dequeue_task kernel/sched/core.c:757 [inline]
 deactivate_task+0xf3/0x330 kernel/sched/core.c:773
 __schedule+0x939/0x1e30 kernel/sched/core.c:3440
 schedule+0xef/0x430 kernel/sched/core.c:3549
 freezable_schedule include/linux/freezer.h:172 [inline]
 do_nanosleep+0x20b/0x730 kernel/time/hrtimer.c:1689
 hrtimer_nanosleep+0x2cc/0x610 kernel/time/hrtimer.c:1743
 __do_sys_nanosleep kernel/time/hrtimer.c:1775 [inline]
 __se_sys_nanosleep kernel/time/hrtimer.c:1762 [inline]
 __x64_sys_nanosleep+0x1df/0x270 kernel/time/hrtimer.c:1762
 do_syscall_64+0x1b1/0x800 arch/x86/entry/common.c:287
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x481080
RSP: 002b:0000000000a3ea98 EFLAGS: 00000246 ORIG_RAX: 0000000000000023
RAX: ffffffffffffffda RBX: 000000000000032d RCX: 0000000000481080
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000a3eaa0
RBP: 000000000007864a R08: 0000000000000001 R09: 00000000012ad940
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000000009 R14: 0000000000000b2a R15: 00000000000785f2
Code: 00 0f 85 e7 03 00 00 4c 0f af e8 4c 01 ab 88 00 00 00 4d 85 f6 74 2d 48 8d bb 90 00 00 00 48 ba 00 00 00 00 00 fc ff df 48 89 fe <48> c1 ee 03 80 3c 16 00 0f 85 cf 03 00 00 4c 0f af f0 4c 01 b3 

Crashes (3):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2018/05/03 02:35 upstream 2d618bdf7163 d5b114b4 .config console log report ci-upstream-kasan-gce
2018/04/20 09:43 upstream 87ef12027b9b eae05cb0 .config console log report ci-upstream-kasan-gce
2018/04/10 09:46 upstream c18bb396d3d2 b9f65507 .config console log report ci-upstream-kasan-gce
* Struck through repros no longer work on HEAD.