Bug#926938: reboot hangs, hung task, ohci_urb_dequeue
Package: src:linux
Version: 4.9.144-3.1
I have two machines in the Xen Project CI lab which fail to reboot
using the stock stretch kernel.
They both hang, printing a message like the one belwo to their serial
console. The appearance of a new usb device during kernel reboot is
rather odd.
Full logs
http://logs.test-lab.xenproject.org/osstest/logs/134652/test-amd64-amd64-xl-multivcpu/info.html
http://logs.test-lab.xenproject.org/osstest/logs/134652/test-amd64-amd64-xl-multivcpu/serial-joubertin0.log
http://logs.test-lab.xenproject.org/osstest/logs/134651/test-xtf-amd64-amd64-1/info.html
http://logs.test-lab.xenproject.org/osstest/logs/134651/test-xtf-amd64-amd64-1/serial-merlot1.log
Look at or near the end of each serial log. The "client
0x55dcddf30100 connected" messages are a result of my CI system
deciding that the host isn't going reboot, and making connections to
the serial concentrator to try to collect debug information.
BTW, my Citrix email address has an often-malfunctioning spamfilter.
Sadly I have not been able to get corporiate IT to fix it. Please CC
ijackson@chiark.greenend.org.uk (especially if you get bounces). If
ijackson@chiark bounces, talk to postmaster@chiark and I will fix my
personal spamfilter so it lets you through. Sorry for any
inconvenience.
If you would like me to test any workaround or something, please let
me know.
Thanks,
Ian.
Apr 12 01:23:40.224056 Unmounting local filesystems...done.
Apr 12 01:23:40.224074 [ 523.410355] EXT4-fs (dm-1): re-mounted. Opts: (null)
Apr 12 01:23:40.260056 Will now restart.
Apr 12 01:23:40.464036 [ 526.126589] kvm: exiting hardware virtualization
Apr 12 01:23:42.976057 [ 599.629542] usb 3-2: new full-speed USB device number 2 using ohci-pci
Apr 12 01:24:56.488055 [ 741.973018] INFO: task kworker/0:2:370 blocked for more than 120 seconds.
Apr 12 01:27:18.840086 [ 741.980517] Not tainted 4.9.0-8-amd64 #1 Debian 4.9.144-3.1
Apr 12 01:27:18.840111 [ 741.988437] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Apr 12 01:27:18.852090 [ 741.997540] kworker/0:2 D 0 370 2 0x00000000
Apr 12 01:27:18.864081 [ 742.004100] Workqueue: usb_hub_wq hub_event [usbcore]
Apr 12 01:27:18.864102 [ 742.009689] ffff9d7431996580 0000000000000000 ffff9d7231d68100 ffff9d7237c18980
Apr 12 01:27:18.876085 [ 742.017972] ffff9d722ac85080 ffffc2a742443ba0 ffffffffbe2144b9 ffffffffc03241c2
Apr 12 01:27:18.876110 [ 742.026553] 00ff9d723244d600 ffff9d7237c18980 ffffffffc02a40b0 ffff9d7231d68100
Apr 12 01:27:18.888092 [ 742.035477] Call Trace:
Apr 12 01:27:18.888109 [ 742.038273] [<ffffffffbe2144b9>] ? __schedule+0x239/0x6f0
Apr 12 01:27:18.900084 [ 742.044656] [<ffffffffc03241c2>] ? ohci_urb_dequeue+0x72/0xa0 [ohci_hcd]
Apr 12 01:27:18.912078 [ 742.052929] [<ffffffffbe2149a2>] ? schedule+0x32/0x80
Apr 12 01:27:18.912100 [ 742.058956] [<ffffffffc0287506>] ? usb_kill_urb+0x86/0xc0 [usbcore]
Apr 12 01:27:18.924088 [ 742.066682] [<ffffffffbdcbd350>] ? prepare_to_wait_event+0xf0/0xf0
Apr 12 01:27:18.924110 [ 742.074339] [<ffffffffc0287b62>] ? usb_start_wait_urb+0xe2/0x170 [usbcore]
Apr 12 01:27:18.936094 [ 742.082688] [<ffffffffc0287ccd>] ? usb_control_msg+0xdd/0x140 [usbcore]
Apr 12 01:27:18.948080 [ 742.090724] [<ffffffffc027d003>] ? hub_port_init+0x323/0xbd0 [usbcore]
Apr 12 01:27:18.960073 [ 742.098831] [<ffffffffc027a8b2>] ? usb_alloc_dev+0x1e2/0x300 [usbcore]
Apr 12 01:27:18.960098 [ 742.106802] [<ffffffffc02812bd>] ? hub_event+0xb5d/0x15c0 [usbcore]
Apr 12 01:27:18.972083 [ 742.114258] [<ffffffffbdc9427a>] ? process_one_work+0x18a/0x430
Apr 12 01:27:18.972106 [ 742.121552] [<ffffffffbdc9456d>] ? worker_thread+0x4d/0x490
Apr 12 01:27:18.984084 [ 742.128767] [<ffffffffbdc94520>] ? process_one_work+0x430/0x430
Apr 12 01:27:18.996072 [ 742.136056] [<ffffffffbdc9a5d9>] ? kthread+0xd9/0xf0
Apr 12 01:27:18.996093 [ 742.142505] [<ffffffffbdc9a500>] ? kthread_park+0x60/0x60
Apr 12 01:27:19.008069 [ 742.149159] [<ffffffffbe2193e4>] ? ret_from_fork+0x44/0x70
Apr 12 01:27:19.008091 [ 864.055852] INFO: task kworker/0:2:370 blocked for more than 120 seconds.
Apr 12 01:29:20.920082 [ 864.063321] Not tainted 4.9.0-8-amd64 #1 Debian 4.9.144-3.1
Apr 12 01:29:20.932081 [ 864.071672] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Apr 12 01:29:20.944079 [ 864.080284] kworker/0:2 D 0 370 2 0x00000000
Apr 12 01:29:20.944100 [ 864.087479] Workqueue: usb_hub_wq hub_event [usbcore]
Apr 12 01:29:20.956081 [ 864.093070] ffff9d7431996580 0000000000000000 ffff9d7231d68100 ffff9d7237c18980
Apr 12 01:29:20.968086 [ 864.102238] ffff9d722ac85080 ffffc2a742443ba0 ffffffffbe2144b9 ffffffffc03241c2
Apr 12 01:29:20.968110 [ 864.112078] 00ff9d723244d600 ffff9d7237c18980 ffffffffc02a40b0 ffff9d7231d68100
Apr 12 01:29:20.980083 [ 864.121397] Call Trace:
Apr 12 01:29:20.980100 [ 864.124094] [<ffffffffbe2144b9>] ? __schedule+0x239/0x6f0
Apr 12 01:29:20.992082 [ 864.131348] [<ffffffffc03241c2>] ? ohci_urb_dequeue+0x72/0xa0 [ohci_hcd]
Apr 12 01:29:21.004079 [ 864.139310] [<ffffffffbe2149a2>] ? schedule+0x32/0x80
Apr 12 01:29:21.004099 [ 864.145826] [<ffffffffc0287506>] ? usb_kill_urb+0x86/0xc0 [usbcore]
Apr 12 01:29:21.016080 [ 864.153651] [<ffffffffbdcbd350>] ? prepare_to_wait_event+0xf0/0xf0
Apr 12 01:29:21.016102 [ 864.161827] [<ffffffffc0287b62>] ? usb_start_wait_urb+0xe2/0x170 [usbcore]
Apr 12 01:29:21.028082 [ 864.170386] [<ffffffffc0287ccd>] ? usb_control_msg+0xdd/0x140 [usbcore]
Apr 12 01:29:21.040079 [ 864.178877] [<ffffffffc027d003>] ? hub_port_init+0x323/0xbd0 [usbcore]
Apr 12 01:29:21.052076 [ 864.187127] [<ffffffffc027a8b2>] ? usb_alloc_dev+0x1e2/0x300 [usbcore]
Apr 12 01:29:21.052098 [ 864.195455] [<ffffffffc02812bd>] ? hub_event+0xb5d/0x15c0 [usbcore]
Apr 12 01:29:21.064080 [ 864.203331] [<ffffffffbdc9427a>] ? process_one_work+0x18a/0x430
Apr 12 01:29:21.076075 [ 864.210313] [<ffffffffbdc9456d>] ? worker_thread+0x4d/0x490
Apr 12 01:29:21.076097 [ 864.217388] [<ffffffffbdc94520>] ? process_one_work+0x430/0x430
Apr 12 01:29:21.088076 [ 864.224109] [<ffffffffbdc9a5d9>] ? kthread+0xd9/0xf0
Apr 12 01:29:21.088096 [ 864.230718] [<ffffffffbdc9a500>] ? kthread_park+0x60/0x60
Apr 12 01:29:21.100075 [ 864.236875] [<ffffffffbe2193e4>] ? ret_from_fork+0x44/0x70
Reply to: