syzbot


INFO: task hung in do_syscall_64

Status: auto-closed as invalid on 2021/04/28 21:23
Reported-by: syzbot+cb710adf8e3e3f4f5265@syzkaller.appspotmail.com
First crash: 584d, last: 542d

Sample crash report:
 sock_sendmsg_nosec net/socket.c:646 [inline]
 sock_sendmsg+0xb5/0x100 net/socket.c:656
 ___sys_sendmsg+0x6c8/0x800 net/socket.c:2062
INFO: task kworker/0:5:14640 blocked for more than 140 seconds.
      Not tainted 4.14.213-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/0:5     D
28272 14640      2 0x80000000
 __sys_sendmsg+0xa3/0x120 net/socket.c:2096
Workqueue: usb_hub_wq hub_event
 SYSC_sendmsg net/socket.c:2107 [inline]
 SyS_sendmsg+0x27/0x40 net/socket.c:2103
Call Trace:
 do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
 entry_SYSCALL_64_after_hwframe+0x46/0xbb
 context_switch kernel/sched/core.c:2808 [inline]
 __schedule+0x88b/0x1de0 kernel/sched/core.c:3384
RIP: 0033:0x45e299
RSP: 002b:00007f85a825fc68 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 000000000045e299
RDX: 0000000000000000 RSI: 0000000020000140 RDI: 0000000000000003
RBP: 00007f85a825fca0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
R13: 00007ffca41860ef R14: 00007f85a82609c0 R15: 000000000119bf8c
Mem-Info:
vhci_hcd: Failed attach request for unsupported USB speed: UNKNOWN
active_anon:17074 inactive_anon:4697 isolated_anon:0
 active_file:6369 inactive_file:28434 isolated_file:0
 unevictable:0 dirty:217 writeback:0 unstable:0
 slab_reclaimable:24711 slab_unreclaimable:108579
 mapped:61420 shmem:4885 pagetables:837 bounce:0
 free:1445131 free_pcp:165 free_cma:0
 schedule+0x8d/0x1b0 kernel/sched/core.c:3428
Node 0 active_anon:68296kB inactive_anon:18788kB active_file:25332kB inactive_file:113736kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:245680kB dirty:864kB writeback:0kB shmem:19540kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 63488kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
 schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:3486
Node 1 active_anon:0kB inactive_anon:0kB active_file:144kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:0kB dirty:4kB writeback:0kB shmem:0kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
 __mutex_lock_common kernel/locking/mutex.c:833 [inline]
 __mutex_lock+0x669/0x1310 kernel/locking/mutex.c:893
Node 0 DMA free:15908kB min:204kB low:252kB high:300kB 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
lowmem_reserve[]: 0 2717 2718 2718 2718
Node 0 DMA32 free:1723128kB min:36200kB low:45248kB high:54296kB active_anon:68296kB inactive_anon:18788kB active_file:25332kB inactive_file:113736kB unevictable:0kB writepending:864kB present:3129332kB managed:2788168kB mlocked:0kB kernel_stack:7616kB pagetables:3200kB bounce:0kB free_pcp:1116kB local_pcp:656kB free_cma:0kB
lowmem_reserve[]: 0 0 0 0 0
Node 0 Normal free:0kB min:4kB low:4kB high:4kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:1048576kB managed:520kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
lowmem_reserve[]: 0 0 0 0 0
Node 1 Normal free:4041152kB min:53696kB low:67120kB high:80544kB active_anon:0kB inactive_anon:0kB active_file:144kB inactive_file:0kB unevictable:0kB writepending:4kB present:4194304kB managed:4128256kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
lowmem_reserve[]: 0 0 0 0 0
Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 1*32kB (U) 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15908kB
Node 0 DMA32: 606*4kB (UME) 202*8kB (UME) 1471*16kB (UME) 1019*32kB (UME) 204*64kB (U) 3*128kB (UME) 3*256kB (U) 6*512kB (UE) 7*1024kB (UM) 2*2048kB (M) 399*4096kB (M) = 1723032kB
Node 0 Normal: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 0kB
Node 1 Normal: 82*4kB (UE) 393*8kB (UME) 301*16kB (UME) 83*32kB (UME) 26*64kB (UM) 23*128kB (UM) 11*256kB (UME) 1*512kB (U) 2*1024kB (ME) 3*2048kB (M) 980*4096kB (M) = 4041152kB
Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Node 0 hugepages_total=4 hugepages_free=4 hugepages_surp=4 hugepages_size=2048kB
Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
22598 total pagecache pages
0 pages in swap cache
Swap cache stats: add 0, delete 0, find 0/0
Free swap  = 0kB
Total swap = 0kB
2097051 pages RAM
0 pages HighMem/MovableOnly
363838 pages reserved
0 pages cma reserved
 hub_port_init+0x15b/0x2970 drivers/usb/core/hub.c:4429
 hub_port_connect drivers/usb/core/hub.c:4905 [inline]
 hub_port_connect_change drivers/usb/core/hub.c:5088 [inline]
 port_event drivers/usb/core/hub.c:5194 [inline]
 hub_event+0x1923/0x3dc0 drivers/usb/core/hub.c:5274
 process_one_work+0x793/0x14a0 kernel/workqueue.c:2116
 worker_thread+0x5cc/0xff0 kernel/workqueue.c:2250
 kthread+0x30d/0x420 kernel/kthread.c:232
 ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404

Showing all locks held in the system:
5 locks held by kworker/0:1/24:
 #0:  ("usb_hub_wq"){+.+.}, at: [<ffffffff81373630>] process_one_work+0x6b0/0x14a0 kernel/workqueue.c:2087
 #1:  ((&hub->events)){+.+.}, at: [<ffffffff81373666>] process_one_work+0x6e6/0x14a0 kernel/workqueue.c:2091
 #2:  (&dev->mutex){....}, at: [<ffffffff8452cd08>] device_lock include/linux/device.h:1081 [inline]
 #2:  (&dev->mutex){....}, at: [<ffffffff8452cd08>] hub_event+0x108/0x3dc0 drivers/usb/core/hub.c:5220
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8452e50e>] usb_lock_port drivers/usb/core/hub.c:2934 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8452e50e>] hub_port_connect drivers/usb/core/hub.c:4904 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8452e50e>] hub_port_connect_change drivers/usb/core/hub.c:5088 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8452e50e>] port_event drivers/usb/core/hub.c:5194 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8452e50e>] hub_event+0x190e/0x3dc0 drivers/usb/core/hub.c:5274
 #4:  (hcd->address0_mutex){+.+.}, at: [<ffffffff8452284b>] hub_port_init+0x15b/0x2970 drivers/usb/core/hub.c:4429
1 lock held by khungtaskd/1531:
 #0:  (tasklist_lock){.+.+}, at: [<ffffffff81430dd4>] debug_show_all_locks+0x7c/0x21a kernel/locking/lockdep.c:4548
5 locks held by kworker/1:2/3623:
 #0:  ("usb_hub_wq"){+.+.}, at: [<ffffffff81373630>] process_one_work+0x6b0/0x14a0 kernel/workqueue.c:2087
 #1:  ((&hub->events)){+.+.}, at: [<ffffffff81373666>] process_one_work+0x6e6/0x14a0 kernel/workqueue.c:2091
 #2:  (&dev->mutex){....}, at: [<ffffffff8452cd08>] device_lock include/linux/device.h:1081 [inline]
 #2:  (&dev->mutex){....}, at: [<ffffffff8452cd08>] hub_event+0x108/0x3dc0 drivers/usb/core/hub.c:5220
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8452e50e>] usb_lock_port drivers/usb/core/hub.c:2934 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8452e50e>] hub_port_connect drivers/usb/core/hub.c:4904 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8452e50e>] hub_port_connect_change drivers/usb/core/hub.c:5088 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8452e50e>] port_event drivers/usb/core/hub.c:5194 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8452e50e>] hub_event+0x190e/0x3dc0 drivers/usb/core/hub.c:5274
 #4:  (hcd->address0_mutex){+.+.}, at: [<ffffffff8452284b>] hub_port_init+0x15b/0x2970 drivers/usb/core/hub.c:4429
1 lock held by in:imklog/7685:
 #0:  (&f->f_pos_lock){+.+.}, at: [<ffffffff818f8bbb>] __fdget_pos+0x1fb/0x2b0 fs/file.c:769
5 locks held by kworker/0:5/14640:
 #0:  ("usb_hub_wq"){+.+.}, at: [<ffffffff81373630>] process_one_work+0x6b0/0x14a0 kernel/workqueue.c:2087
 #1:  ((&hub->events)){+.+.}, at: [<ffffffff81373666>] process_one_work+0x6e6/0x14a0 kernel/workqueue.c:2091
 #2:  (&dev->mutex){....}, at: [<ffffffff8452cd08>] device_lock include/linux/device.h:1081 [inline]
 #2:  (&dev->mutex){....}, at: [<ffffffff8452cd08>] hub_event+0x108/0x3dc0 drivers/usb/core/hub.c:5220
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8452e50e>] usb_lock_port drivers/usb/core/hub.c:2934 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8452e50e>] hub_port_connect drivers/usb/core/hub.c:4904 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8452e50e>] hub_port_connect_change drivers/usb/core/hub.c:5088 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8452e50e>] port_event drivers/usb/core/hub.c:5194 [inline]
 #3:  (&port_dev->status_lock){+.+.}, at: [<ffffffff8452e50e>] hub_event+0x190e/0x3dc0 drivers/usb/core/hub.c:5274
 #4:  (hcd->address0_mutex){+.+.}, at: [<ffffffff8452284b>] hub_port_init+0x15b/0x2970 drivers/usb/core/hub.c:4429

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

NMI backtrace for cpu 1
CPU: 1 PID: 1531 Comm: khungtaskd Not tainted 4.14.213-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 __dump_stack lib/dump_stack.c:17 [inline]
 dump_stack+0x1b2/0x283 lib/dump_stack.c:58
 nmi_cpu_backtrace.cold+0x57/0x93 lib/nmi_backtrace.c:101
 nmi_trigger_cpumask_backtrace+0x13a/0x17f lib/nmi_backtrace.c:62
 trigger_all_cpu_backtrace include/linux/nmi.h:140 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:195 [inline]
 watchdog+0x5b9/0xb40 kernel/hung_task.c:274
FAULT_INJECTION: forcing a failure.
name failslab, interval 1, probability 0, space 0, times 0
 kthread+0x30d/0x420 kernel/kthread.c:232
 ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404
Sending NMI from CPU 1 to CPUs 0:
CPU: 0 PID: 12611 Comm: syz-executor.0 Not tainted 4.14.213-syzkaller #0
NMI backtrace for cpu 0
CPU: 0 PID: 12611 Comm: syz-executor.0 Not tainted 4.14.213-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
task: ffff88809877a080 task.stack: ffff888096fb8000
RIP: 0010:validate_chain kernel/locking/lockdep.c:2471 [inline]
RIP: 0010:__lock_acquire+0x82c/0x3f20 kernel/locking/lockdep.c:3491
RSP: 0018:ffff888096fbf448 EFLAGS: 00000046
RAX: 1ffffffff1670123 RBX: ffffffff8b380900 RCX: 0000000000002608
RDX: 1ffffffff1733760 RSI: 000000008f1231aa RDI: ffffffff8b380918
RBP: dffffc0000000000 R08: ffffffff8b99bb00 R09: 00000000000c0007
R10: ffff88809877a930 R11: ffff88809877a080 R12: ffff88809877a948
R13: 0000000000000000 R14: cfcc7579b77aa771 R15: ffffffff8beb4d40
FS:  00007f85a8260700(0000) GS:ffff8880ba400000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00000000015a0004 CR3: 000000008f9b8000 CR4: 00000000001406f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
 __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
 _raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:152
 console_lock_spinning_enable kernel/printk/printk.c:1583 [inline]
 console_unlock+0x332/0xf20 kernel/printk/printk.c:2397
 vprintk_emit+0x224/0x620 kernel/printk/printk.c:1923
 vprintk_func+0x58/0x152 kernel/printk/printk_safe.c:401
 printk+0x9e/0xbc kernel/printk/printk.c:1996
 dump_stack_print_info+0x8d/0xe0 kernel/printk/printk.c:3300
 __dump_stack lib/dump_stack.c:16 [inline]
 dump_stack+0x1a9/0x283 lib/dump_stack.c:58
 fail_dump lib/fault-inject.c:51 [inline]
 should_fail.cold+0x10a/0x154 lib/fault-inject.c:149
 should_failslab+0xd6/0x130 mm/failslab.c:32
 slab_pre_alloc_hook mm/slab.h:421 [inline]
 slab_alloc_node mm/slab.c:3297 [inline]
 kmem_cache_alloc_node_trace+0x25a/0x400 mm/slab.c:3659
 kmalloc_node include/linux/slab.h:526 [inline]
 alloc_vmap_area+0xf0/0x7c0 mm/vmalloc.c:420
 __get_vm_area_node+0x126/0x340 mm/vmalloc.c:1414
 __vmalloc_node_range mm/vmalloc.c:1762 [inline]
 __vmalloc_node mm/vmalloc.c:1818 [inline]
 __vmalloc_node_flags mm/vmalloc.c:1832 [inline]
 vmalloc+0x98/0x150 mm/vmalloc.c:1854
 netlink_alloc_large_skb net/netlink/af_netlink.c:1164 [inline]
 netlink_sendmsg+0x41a/0xb80 net/netlink/af_netlink.c:1853
 sock_sendmsg_nosec net/socket.c:646 [inline]
 sock_sendmsg+0xb5/0x100 net/socket.c:656
 ___sys_sendmsg+0x6c8/0x800 net/socket.c:2062
 __sys_sendmsg+0xa3/0x120 net/socket.c:2096
 SYSC_sendmsg net/socket.c:2107 [inline]
 SyS_sendmsg+0x27/0x40 net/socket.c:2103
 do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
 entry_SYSCALL_64_after_hwframe+0x46/0xbb
RIP: 0033:0x45e299
RSP: 002b:00007f85a825fc68 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 000000000045e299
RDX: 0000000000000000 RSI: 0000000020000140 RDI: 0000000000000003
RBP: 00007f85a825fca0 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000001
R13: 00007ffca41860ef R14: 00007f85a82609c0 R15: 000000000119bf8c
Code: 54 24 30 48 c1 ea 03 0f b6 04 02 84 c0 74 08 3c 03 0f 8e 4b 27 00 00 41 8b 42 20 25 00 80 04 00 3d 00 00 04 00 0f 84 f9 01 00 00 <48> c7 c2 20 fb 3c 89 48 b8 00 00 00 00 00 fc ff df 48 c1 ea 03 

Crashes (2):
Manager Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Title
ci2-linux-4-14 2020/12/29 21:22 linux-4.14.y 1752938529c6 80910769 .config log report info
ci2-linux-4-14 2020/11/17 13:16 linux-4.14.y 27ce4f2a6817 bd2a760b .config log report info