syzbot


INFO: task hung in hub_activate

Status: auto-closed as invalid on 2021/12/23 06:50
Reported-by: syzbot+c3017f57b80a9c7810a8@syzkaller.appspotmail.com
First crash: 983d, last: 975d
Similar bugs (1)
Kernel Title Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream INFO: task hung in hub_activate usb 1 1160d 1160d 0/26 auto-closed as invalid on 2021/05/23 03:29

Sample crash report:
ieee802154 phy1 wpan1: encryption failed: -22
ieee802154 phy0 wpan0: encryption failed: -22
ieee802154 phy1 wpan1: encryption failed: -22
ieee802154 phy0 wpan0: encryption failed: -22
ieee802154 phy1 wpan1: encryption failed: -22
INFO: task kworker/1:1:33 blocked for more than 140 seconds.
      Not tainted 4.19.204-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/1:1     D25768    33      2 0x80000000
Workqueue: events_power_efficient hub_init_func3
Call Trace:
 context_switch kernel/sched/core.c:2828 [inline]
 __schedule+0x887/0x2040 kernel/sched/core.c:3517
 schedule+0x8d/0x1b0 kernel/sched/core.c:3561
 schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:3619
 __mutex_lock_common kernel/locking/mutex.c:1015 [inline]
 __mutex_lock+0x604/0x1200 kernel/locking/mutex.c:1083
 device_lock include/linux/device.h:1173 [inline]
 hub_activate+0xe7a/0x1a40 drivers/usb/core/hub.c:1008
 process_one_work+0x864/0x1570 kernel/workqueue.c:2153
 worker_thread+0x64c/0x1130 kernel/workqueue.c:2296
 kthread+0x33f/0x460 kernel/kthread.c:259
 ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
INFO: task kworker/1:2:3413 blocked for more than 140 seconds.
      Not tainted 4.19.204-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/1:2     D26728  3413      2 0x80000000
Workqueue: usb_hub_wq hub_event
Call Trace:
 context_switch kernel/sched/core.c:2828 [inline]
 __schedule+0x887/0x2040 kernel/sched/core.c:3517
 schedule+0x8d/0x1b0 kernel/sched/core.c:3561
 usb_kill_urb.part.0+0x197/0x220 drivers/usb/core/urb.c:697
 usb_kill_urb+0x7c/0x90 drivers/usb/core/urb.c:692
 usb_start_wait_urb+0x252/0x4c0 drivers/usb/core/message.c:63
 usb_internal_control_msg drivers/usb/core/message.c:101 [inline]
 usb_control_msg+0x31c/0x4a0 drivers/usb/core/message.c:152
 hub_port_init+0x12dc/0x3120 drivers/usb/core/hub.c:4704
 hub_port_connect drivers/usb/core/hub.c:5070 [inline]
 hub_port_connect_change drivers/usb/core/hub.c:5253 [inline]
 port_event drivers/usb/core/hub.c:5361 [inline]
 hub_event+0x1ccd/0x44a0 drivers/usb/core/hub.c:5441
 process_one_work+0x864/0x1570 kernel/workqueue.c:2153
 worker_thread+0x64c/0x1130 kernel/workqueue.c:2296
 kthread+0x33f/0x460 kernel/kthread.c:259
 ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
INFO: task syz-executor.4:16926 blocked for more than 140 seconds.
      Not tainted 4.19.204-syzkaller #0
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syz-executor.4  D26912 16926   8108 0x00000004
Call Trace:
 context_switch kernel/sched/core.c:2828 [inline]
 __schedule+0x887/0x2040 kernel/sched/core.c:3517
 schedule+0x8d/0x1b0 kernel/sched/core.c:3561
 schedule_preempt_disabled+0xf/0x20 kernel/sched/core.c:3619
 __mutex_lock_common kernel/locking/mutex.c:1015 [inline]
 __mutex_lock+0x604/0x1200 kernel/locking/mutex.c:1083
 device_lock include/linux/device.h:1173 [inline]
 usbdev_do_ioctl+0x193/0x3030 drivers/usb/core/devio.c:2393
 usbdev_ioctl+0x21/0x30 drivers/usb/core/devio.c:2585
 vfs_ioctl fs/ioctl.c:46 [inline]
 file_ioctl fs/ioctl.c:501 [inline]
 do_vfs_ioctl+0xcdb/0x12e0 fs/ioctl.c:688
 ksys_ioctl+0x9b/0xc0 fs/ioctl.c:705
 __do_sys_ioctl fs/ioctl.c:712 [inline]
 __se_sys_ioctl fs/ioctl.c:710 [inline]
 __x64_sys_ioctl+0x6f/0xb0 fs/ioctl.c:710
 do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x4665e9
Code: Bad RIP value.
RSP: 002b:00007fbe04a92188 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 000000000056c038 RCX: 00000000004665e9
RDX: 0000000000000000 RSI: 0000000081f8943c RDI: 0000000000000004
RBP: 00000000004bfcc4 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000246 R12: 000000000056c038
R13: 00007fff85f7e90f R14: 00007fbe04a92300 R15: 0000000000022000

Showing all locks held in the system:
3 locks held by kworker/1:1/33:
 #0: 00000000b03c2e96 ((wq_completion)"events_power_efficient"){+.+.}, at: process_one_work+0x767/0x1570 kernel/workqueue.c:2124
 #1: 00000000ce9d1880 ((work_completion)(&(&hub->init_work)->work)#2){+.+.}, at: process_one_work+0x79c/0x1570 kernel/workqueue.c:2128
 #2: 0000000029cca9b6 (&dev->mutex){....}, at: device_lock include/linux/device.h:1173 [inline]
 #2: 0000000029cca9b6 (&dev->mutex){....}, at: hub_activate+0xe7a/0x1a40 drivers/usb/core/hub.c:1008
1 lock held by kworker/u4:2/54:
 #0: 000000002453fc41 (&rq->lock){-.-.}, at: idle_balance kernel/sched/fair.c:9702 [inline]
 #0: 000000002453fc41 (&rq->lock){-.-.}, at: pick_next_task_fair+0x556/0x1570 kernel/sched/fair.c:6841
1 lock held by khungtaskd/1570:
 #0: 00000000db46011f (rcu_read_lock){....}, at: debug_show_all_locks+0x53/0x265 kernel/locking/lockdep.c:4441
5 locks held by kworker/1:2/3413:
 #0: 00000000378f1d74 ((wq_completion)"usb_hub_wq"){+.+.}, at: process_one_work+0x767/0x1570 kernel/workqueue.c:2124
 #1: 00000000891f3591 ((work_completion)(&hub->events)){+.+.}, at: process_one_work+0x79c/0x1570 kernel/workqueue.c:2128
 #2: 0000000029cca9b6 (&dev->mutex){....}, at: device_lock include/linux/device.h:1173 [inline]
 #2: 0000000029cca9b6 (&dev->mutex){....}, at: hub_event+0x11e/0x44a0 drivers/usb/core/hub.c:5387
 #3: 000000005494ab09 (&port_dev->status_lock){+.+.}, at: usb_lock_port drivers/usb/core/hub.c:2983 [inline]
 #3: 000000005494ab09 (&port_dev->status_lock){+.+.}, at: hub_port_connect drivers/usb/core/hub.c:5069 [inline]
 #3: 000000005494ab09 (&port_dev->status_lock){+.+.}, at: hub_port_connect_change drivers/usb/core/hub.c:5253 [inline]
 #3: 000000005494ab09 (&port_dev->status_lock){+.+.}, at: port_event drivers/usb/core/hub.c:5361 [inline]
 #3: 000000005494ab09 (&port_dev->status_lock){+.+.}, at: hub_event+0x1cb8/0x44a0 drivers/usb/core/hub.c:5441
 #4: 00000000db504f6b (hcd->address0_mutex){+.+.}, at: hub_port_init+0x1b9/0x3120 drivers/usb/core/hub.c:4578
1 lock held by in:imklog/7787:
 #0: 00000000ff2b6f9c (&f->f_pos_lock){+.+.}, at: __fdget_pos+0x26f/0x310 fs/file.c:767
1 lock held by syz-executor.4/16926:
 #0: 0000000029cca9b6 (&dev->mutex){....}, at: device_lock include/linux/device.h:1173 [inline]
 #0: 0000000029cca9b6 (&dev->mutex){....}, at: usbdev_do_ioctl+0x193/0x3030 drivers/usb/core/devio.c:2393

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

NMI backtrace for cpu 1
CPU: 1 PID: 1570 Comm: khungtaskd Not tainted 4.19.204-syzkaller #0
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+0x1fc/0x2ef lib/dump_stack.c:118
 nmi_cpu_backtrace.cold+0x63/0xa2 lib/nmi_backtrace.c:101
 nmi_trigger_cpumask_backtrace+0x1a6/0x1f0 lib/nmi_backtrace.c:62
 trigger_all_cpu_backtrace include/linux/nmi.h:146 [inline]
 check_hung_uninterruptible_tasks kernel/hung_task.c:203 [inline]
 watchdog+0x991/0xe60 kernel/hung_task.c:287
 kthread+0x33f/0x460 kernel/kthread.c:259
 ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:415
Sending NMI from CPU 1 to CPUs 0:
NMI backtrace for cpu 0
CPU: 0 PID: 4693 Comm: systemd-journal Not tainted 4.19.204-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
RIP: 0010:zonelist_zone include/linux/mmzone.h:957 [inline]
RIP: 0010:get_page_from_freelist+0x73b/0x4170 mm/page_alloc.c:3292
Code: 08 3c 03 0f 8e 35 29 00 00 48 8b 44 24 10 3b 70 18 0f 82 c7 08 00 00 48 89 6c 24 10 48 8b 44 24 10 48 c1 e8 03 42 80 3c 38 00 <0f> 85 41 29 00 00 48 8b 44 24 10 4c 8b 30 4d 85 f6 0f 85 27 fa ff
RSP: 0018:ffff8880a0f3f960 EFLAGS: 00000046
RAX: 1ffff11027fffcbc RBX: ffff88813fffc3e0 RCX: ffffffff817f05b6
RDX: 0000000000000000 RSI: 0000000000000002 RDI: ffff88813fffe5e8
RBP: ffff88813fffe5e0 R08: 0000000000000000 R09: 0000000000000001
R10: ffff88813fffc3e7 R11: 0000000000000000 R12: 0000000000000000
R13: 0000000000000002 R14: ffff88813fffbd80 R15: dffffc0000000000
FS:  00007f9e5a6c38c0(0000) GS:ffff8880ba000000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f9e57bdc000 CR3: 00000000a0c56000 CR4: 00000000001426f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Call Trace:
 __alloc_pages_nodemask+0x387/0x2890 mm/page_alloc.c:4399
 __alloc_pages include/linux/gfp.h:496 [inline]
 __alloc_pages_node include/linux/gfp.h:509 [inline]
 kmem_getpages mm/slab.c:1412 [inline]
 cache_grow_begin+0xa4/0x8a0 mm/slab.c:2682
 cache_alloc_refill+0x273/0x340 mm/slab.c:3049
 ____cache_alloc mm/slab.c:3132 [inline]
 __do_cache_alloc mm/slab.c:3354 [inline]
 slab_alloc mm/slab.c:3389 [inline]
 kmem_cache_alloc+0x346/0x370 mm/slab.c:3557
 getname_flags+0xce/0x590 fs/namei.c:140
 getname fs/namei.c:211 [inline]
 user_path_create fs/namei.c:3696 [inline]
 do_mkdirat+0x8d/0x2d0 fs/namei.c:3834
 do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
 entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x7f9e5997e687
Code: 00 b8 ff ff ff ff c3 0f 1f 40 00 48 8b 05 09 d8 2b 00 64 c7 00 5f 00 00 00 b8 ff ff ff ff c3 0f 1f 40 00 b8 53 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d e1 d7 2b 00 f7 d8 64 89 01 48
RSP: 002b:00007ffd43888838 EFLAGS: 00000293 ORIG_RAX: 0000000000000053
RAX: ffffffffffffffda RBX: 00007ffd4388b8a0 RCX: 00007f9e5997e687
RDX: 0000000000000000 RSI: 00000000000001ed RDI: 00005654a35e78a0
RBP: 00007ffd43888870 R08: 00005654a2a763e5 R09: 0000000000000018
R10: 0000000000000069 R11: 0000000000000293 R12: 0000000000000000
R13: 0000000000000001 R14: 00005654a35e78a0 R15: 00007ffd43888eb0
----------------
Code disassembly (best guess):
   0:	08 3c 03             	or     %bh,(%rbx,%rax,1)
   3:	0f 8e 35 29 00 00    	jle    0x293e
   9:	48 8b 44 24 10       	mov    0x10(%rsp),%rax
   e:	3b 70 18             	cmp    0x18(%rax),%esi
  11:	0f 82 c7 08 00 00    	jb     0x8de
  17:	48 89 6c 24 10       	mov    %rbp,0x10(%rsp)
  1c:	48 8b 44 24 10       	mov    0x10(%rsp),%rax
  21:	48 c1 e8 03          	shr    $0x3,%rax
  25:	42 80 3c 38 00       	cmpb   $0x0,(%rax,%r15,1)
* 2a:	0f 85 41 29 00 00    	jne    0x2971 <-- trapping instruction
  30:	48 8b 44 24 10       	mov    0x10(%rsp),%rax
  35:	4c 8b 30             	mov    (%rax),%r14
  38:	4d 85 f6             	test   %r14,%r14
  3b:	0f                   	.byte 0xf
  3c:	85 27                	test   %esp,(%rdi)
  3e:	fa                   	cli
  3f:	ff                   	.byte 0xff

Crashes (3):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2021/08/25 06:49 linux-4.19.y 59456c9cc40c b599f2fc .config console log report info ci2-linux-4-19 INFO: task hung in hub_activate
2021/08/24 19:16 linux-4.19.y 59456c9cc40c b599f2fc .config console log report info ci2-linux-4-19 INFO: task hung in hub_activate
2021/08/17 11:38 linux-4.19.y 59456c9cc40c 33c26cb7 .config console log report info ci2-linux-4-19 INFO: task hung in hub_activate
* Struck through repros no longer work on HEAD.