syzbot


INFO: task hung in do_vfs_ioctl

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

Sample crash report:
 __vmalloc_node_range+0x45e/0x750 mm/vmalloc.c:1775
 __vmalloc_node mm/vmalloc.c:1804 [inline]
 __vmalloc_node_flags_caller+0x75/0x90 mm/vmalloc.c:1826
 kvmalloc_node+0xde/0x100 mm/util.c:430
 kvmalloc include/linux/mm.h:550 [inline]
 kvzalloc include/linux/mm.h:558 [inline]
 kvm_arch_create_memslot+0xa3/0x4e0 arch/x86/kvm/x86.c:8874
 __kvm_set_memory_region+0x1d1b/0x2e50 arch/x86/kvm/../../../virt/kvm/kvm_main.c:988
INFO: task kworker/0:1:24 blocked for more than 120 seconds.
 kvm_set_memory_region+0x2e/0x50 arch/x86/kvm/../../../virt/kvm/kvm_main.c:1060
      Not tainted 4.17.0-rc3+ #28
 kvm_vm_ioctl_set_memory_region arch/x86/kvm/../../../virt/kvm/kvm_main.c:1072 [inline]
 kvm_vm_ioctl+0x668/0x1d90 arch/x86/kvm/../../../virt/kvm/kvm_main.c:2959
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/0:1     D
19800    24      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
 vfs_ioctl fs/ioctl.c:46 [inline]
 file_ioctl fs/ioctl.c:500 [inline]
 do_vfs_ioctl+0x1cf/0x16a0 fs/ioctl.c:684
 ksys_ioctl+0xa9/0xd0 fs/ioctl.c:701
 __do_sys_ioctl fs/ioctl.c:708 [inline]
 __se_sys_ioctl fs/ioctl.c:706 [inline]
 __x64_sys_ioctl+0x73/0xb0 fs/ioctl.c:706
 do_syscall_64+0x1b1/0x800 arch/x86/entry/common.c:287
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x455979
RSP: 002b:00007ffb43d0ec68 EFLAGS: 00000246
 schedule+0xef/0x430 kernel/sched/core.c:3549
 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007ffb43d0f6d4 RCX: 0000000000455979
RDX: 0000000020005fe0 RSI: 000000004020ae46 RDI: 0000000000000016
RBP: 000000000072bf50 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
R13: 000000000000029a R14: 00000000006f7f10 R15: 0000000000000001
TCP: request_sock_TCPv6: Possible SYN flooding on port 20002. Sending cookies.  Check SNMP counters.
 bit_wait+0x18/0x90 kernel/sched/wait_bit.c:197
 __wait_on_bit+0xb3/0x130 kernel/sched/wait_bit.c:48
 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
syz-executor4: vmalloc: allocation failure: 8589934592 bytes, mode:0x14080c0(GFP_KERNEL|__GFP_ZERO), nodemask=(null)
 cgwb_release_workfn+0x87/0x750 mm/backing-dev.c:509
syz-executor4 cpuset=
 process_one_work+0xc1e/0x1b50 kernel/workqueue.c:2145
syz4
 mems_allowed=0
CPU: 0 PID: 31441 Comm: syz-executor4 Not tainted 4.17.0-rc3+ #28
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
 warn_alloc.cold.118+0xb2/0x1b8 mm/page_alloc.c:3436
 __vmalloc_node_range+0x45e/0x750 mm/vmalloc.c:1775
 __vmalloc_node mm/vmalloc.c:1804 [inline]
 __vmalloc_node_flags_caller+0x75/0x90 mm/vmalloc.c:1826
 kvmalloc_node+0xde/0x100 mm/util.c:430
 kvmalloc include/linux/mm.h:550 [inline]
 kvzalloc include/linux/mm.h:558 [inline]
 kvm_arch_create_memslot+0xa3/0x4e0 arch/x86/kvm/x86.c:8874
 __kvm_set_memory_region+0x1d1b/0x2e50 arch/x86/kvm/../../../virt/kvm/kvm_main.c:988
 worker_thread+0x1cc/0x1440 kernel/workqueue.c:2279
 kvm_set_memory_region+0x2e/0x50 arch/x86/kvm/../../../virt/kvm/kvm_main.c:1060
 kvm_vm_ioctl_set_memory_region arch/x86/kvm/../../../virt/kvm/kvm_main.c:1072 [inline]
 kvm_vm_ioctl+0x668/0x1d90 arch/x86/kvm/../../../virt/kvm/kvm_main.c:2959
 kthread+0x345/0x410 kernel/kthread.c:238
 vfs_ioctl fs/ioctl.c:46 [inline]
 file_ioctl fs/ioctl.c:500 [inline]
 do_vfs_ioctl+0x1cf/0x16a0 fs/ioctl.c:684
 ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:412
 ksys_ioctl+0xa9/0xd0 fs/ioctl.c:701
 __do_sys_ioctl fs/ioctl.c:708 [inline]
 __se_sys_ioctl fs/ioctl.c:706 [inline]
 __x64_sys_ioctl+0x73/0xb0 fs/ioctl.c:706
 do_syscall_64+0x1b1/0x800 arch/x86/entry/common.c:287

Showing all locks held in the system:
2 locks held by kworker/0:1/24:
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x455979
 #0: 
RSP: 002b:00007ffb43d2fc68 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 00007ffb43d306d4 RCX: 0000000000455979
RDX: 0000000020005fe0 RSI: 000000004020ae46 RDI: 0000000000000014
000000003ddecc4b
RBP: 000000000072bea0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 00000000ffffffff
R13: 000000000000029a R14: 00000000006f7f10 R15: 0000000000000000
warn_alloc_show_mem: 1 callbacks suppressed
Mem-Info:
 (
active_anon:76059 inactive_anon:76 isolated_anon:0
 active_file:3757 inactive_file:12593 isolated_file:0
 unevictable:0 dirty:60 writeback:0 unstable:0
 slab_reclaimable:11038 slab_unreclaimable:105168
 mapped:73874 shmem:88 pagetables:1089 bounce:0
 free:1323938 free_pcp:464 free_cma:0
(wq_completion)"events"
Node 0 active_anon:304236kB inactive_anon:304kB active_file:15028kB inactive_file:50372kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:295496kB dirty:240kB writeback:0kB shmem:352kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 135168kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
){+.+.}
Node 0 DMA free:15908kB min:164kB low:204kB high:244kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15908kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
, at: __write_once_size include/linux/compiler.h:215 [inline]
, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
, at: atomic64_set include/asm-generic/atomic-instrumented.h:40 [inline]
, at: atomic_long_set include/asm-generic/atomic-long.h:57 [inline]
, at: set_work_data kernel/workqueue.c:617 [inline]
, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
, at: process_one_work+0xaef/0x1b50 kernel/workqueue.c:2116
lowmem_reserve[]: 0 2830
 #1: 
 6335 6335
000000009912bf79
Node 0 
 (
DMA32 free:2900416kB min:30116kB low:37644kB high:45172kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:3129292kB managed:2901148kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:732kB local_pcp:656kB free_cma:0kB
lowmem_reserve[]:
(work_completion)(&wb->release_work)
 0 0
){+.+.}
 3505 3505
, at: process_one_work+0xb46/0x1b50 kernel/workqueue.c:2120
Node 0 
2 locks held by khungtaskd/891:
Normal free:2379428kB min:37300kB low:46624kB high:55948kB active_anon:304236kB inactive_anon:304kB active_file:15028kB inactive_file:50372kB unevictable:0kB writepending:124kB present:4718592kB managed:3589432kB mlocked:0kB kernel_stack:5792kB pagetables:4356kB bounce:0kB free_pcp:1124kB local_pcp:464kB free_cma:0kB
lowmem_reserve[]:
 #0: 00000000c509000b
 0 0
 (
 0 0
rcu_read_lock
Node 0 
){....}
DMA: 1*4kB 
, at: check_hung_uninterruptible_tasks kernel/hung_task.c:175 [inline]
, at: watchdog+0x1ff/0xf60 kernel/hung_task.c:249
(U) 0*8kB 
 #1: 
0*16kB 1*32kB 
00000000011ef05f
(U) 2*64kB 
 (
(U) 1*128kB 
tasklist_lock
(U) 1*256kB 
){.+.+}
(U) 0*512kB 
, at: debug_show_all_locks+0xde/0x34a kernel/locking/lockdep.c:4470
1*1024kB (U) 
2 locks held by getty/4466:
1*2048kB (M) 
 #0: 
3*4096kB (M) 
000000000bb09ac6
= 15908kB
Node 0 
 (
DMA32: 6*4kB 
&tty->ldisc_sem
(UM) 5*8kB 
){++++}
(M) 2*16kB 
, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
(M) 5*32kB 
 #1: 000000009b271e39
(UM) 
 (
3*64kB 
&ldata->atomic_read_lock
(UM) 2*128kB 
){+.+.}
(M) 5*256kB 
, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
(UM) 3*512kB 
2 locks held by getty/4467:
(UM) 3*1024kB 
 #0: 
(UM) 3*2048kB 
00000000fbcf53cc
(UM) 705*4096kB 
 (
(M) = 2900416kB
&tty->ldisc_sem
Node 0 Normal: 
){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
2011*4kB 
 #1: 
(UME) 3222*8kB 
0000000021941b4e
(UME) 2853*16kB 
 (
(UME) 3033*32kB 
&ldata->atomic_read_lock
(UME) 1467*64kB 
){+.+.}
(UM) 304*128kB 
, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
(UM) 196*256kB 
2 locks held by getty/4468:
(UME) 105*512kB 
 #0: 
(UME) 68*1024kB 
00000000439c3448
(UM) 50*2048kB 
 (
(UM) 438*4096kB 
&tty->ldisc_sem
(UM) = 2379340kB
){++++}
Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
16437 total pagecache pages
0 pages in swap cache
 #1: 
Swap cache stats: add 0, delete 0, find 0/0
Free swap  = 0kB
00000000657b0922
Total swap = 0kB
1965969 pages RAM
 (
0 pages HighMem/MovableOnly
339347 pages reserved
&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by getty/4469:
 #0: 000000007f26b411 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 000000005de02711 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by getty/4470:
 #0: 000000004e64684f (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 0000000011c820a4 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by getty/4471:
 #0: 000000005d2982a9 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 000000007aa3a524 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by getty/4472:
 #0: 0000000024b8f1d5 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 drivers/tty/tty_ldsem.c:365
 #1: 000000002512cc4a (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0x321/0x1cc0 drivers/tty/n_tty.c:2131
2 locks held by kworker/0:3/4928:
 #0: 000000003ddecc4b ((wq_completion)"events"){+.+.}, at: __write_once_size include/linux/compiler.h:215 [inline]
 #0: 000000003ddecc4b ((wq_completion)"events"){+.+.}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
 #0: 000000003ddecc4b ((wq_completion)"events"){+.+.}, at: atomic64_set include/asm-generic/atomic-instrumented.h:40 [inline]
 #0: 000000003ddecc4b ((wq_completion)"events"){+.+.}, at: atomic_long_set include/asm-generic/atomic-long.h:57 [inline]
 #0: 000000003ddecc4b ((wq_completion)"events"){+.+.}, at: set_work_data kernel/workqueue.c:617 [inline]
 #0: 000000003ddecc4b ((wq_completion)"events"){+.+.}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
 #0: 000000003ddecc4b ((wq_completion)"events"){+.+.}, at: process_one_work+0xaef/0x1b50 kernel/workqueue.c:2116
 #1: 00000000640473fb ((work_completion)(&wb->release_work)){+.+.}, at: process_one_work+0xb46/0x1b50 kernel/workqueue.c:2120
2 locks held by kworker/u4:5/8671:
 #0: 00000000f9188dee ((wq_completion)"events_unbound"){+.+.}, at: __write_once_size include/linux/compiler.h:215 [inline]
 #0: 00000000f9188dee ((wq_completion)"events_unbound"){+.+.}, at: arch_atomic64_set arch/x86/include/asm/atomic64_64.h:34 [inline]
 #0: 00000000f9188dee ((wq_completion)"events_unbound"){+.+.}, at: atomic64_set include/asm-generic/atomic-instrumented.h:40 [inline]
 #0: 00000000f9188dee ((wq_completion)"events_unbound"){+.+.}, at: atomic_long_set include/asm-generic/atomic-long.h:57 [inline]
 #0: 00000000f9188dee ((wq_completion)"events_unbound"){+.+.}, at: set_work_data kernel/workqueue.c:617 [inline]
 #0: 00000000f9188dee ((wq_completion)"events_unbound"){+.+.}, at: set_work_pool_and_clear_pending kernel/workqueue.c:644 [inline]
 #0: 00000000f9188dee ((wq_completion)"events_unbound"){+.+.}, at: process_one_work+0xaef/0x1b50 kernel/workqueue.c:2116
 #1: 000000004bfccd35 ((reaper_work).work){+.+.}, at: process_one_work+0xb46/0x1b50 kernel/workqueue.c:2120
1 lock held by syz-executor3/31449:
 #0: 00000000aff553de (&tu->ioctl_lock){+.+.}, at: snd_timer_user_ioctl+0x51/0x7d sound/core/timer.c:1991

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

NMI backtrace for cpu 1
CPU: 1 PID: 891 Comm: khungtaskd Not tainted 4.17.0-rc3+ #28
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: 4544 Comm: syz-executor1 Not tainted 4.17.0-rc3+ #28
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
RIP: 0010:trace_hardirqs_on_caller+0x6e/0x5c0 kernel/locking/lockdep.c:2848
RSP: 0018:ffff88019224f9e0 EFLAGS: 00000807
RAX: dffffc0000000000 RBX: ffff880192242280 RCX: ffffffff815e189e
RDX: 0000000000000000 RSI: 0000000000000004 RDI: ffff880192242ab4
RBP: ffff88019224f9f0 R08: fffffbfff150b4ee R09: fffffbfff150b4ed
R10: fffffbfff150b4ed R11: ffffffff8a85a76b R12: ffffffff876ed634
R13: 0000000000064f80 R14: ffffffff8a85a760 R15: ffff880174e90d58
FS:  0000000000cee940(0000) GS:ffff8801dae00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000020000100 CR3: 00000001920b2000 CR4: 00000000001426f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 trace_hardirqs_on+0xd/0x10 kernel/locking/lockdep.c:2890
 __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
 _raw_spin_unlock_irqrestore+0x74/0xc0 kernel/locking/spinlock.c:184
 __debug_object_init+0x57f/0x12c0 lib/debugobjects.c:416
 debug_object_init_on_stack+0x19/0x20 lib/debugobjects.c:444
 hrtimer_init_on_stack kernel/time/hrtimer.c:435 [inline]
 hrtimer_nanosleep+0x163/0x610 kernel/time/hrtimer.c:1741
 __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: 00000000000002b8 RCX: 0000000000481080
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000a3eaa0
RBP: 0000000000096a87 R08: 0000000000000001 R09: 0000000000cee940
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000000002 R14: 00000000000009ba R15: 0000000000096a81
Code: 0f 84 68 02 00 00 65 48 8b 1c 25 c0 ed 01 00 48 8d bb 34 08 00 00 48 b8 00 00 00 00 00 fc ff df 48 89 fa 48 c1 ea 03 0f b6 14 02 <48> 89 f8 83 e0 07 83 c0 03 38 d0 7c 08 84 d2 0f 85 2a 04 00 00 

Crashes (2):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2018/05/02 02:15 upstream f2125992e7cb d5b114b4 .config console log report ci-upstream-kasan-gce
2018/04/14 06:04 upstream 1bad9ce155a7 7a67784c .config console log report ci-upstream-kasan-gce
* Struck through repros no longer work on HEAD.