Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.debian.kernel > #63828 > unrolled thread
| Started by | Ian Jackson <ian.jackson@citrix.com> |
|---|---|
| First post | 2019-04-12 15:30 +0200 |
| Last post | 2019-04-17 20:30 +0200 |
| Articles | 2 — 1 participant |
Back to article view | Back to linux.debian.kernel
Bug#926938: reboot hangs, hung task, ohci_urb_dequeue Ian Jackson <ian.jackson@citrix.com> - 2019-04-12 15:30 +0200
Bug#926938: reboot hangs, hung task, ohci_urb_dequeue [and 1 more messages] Ian Jackson <ian.jackson@citrix.com> - 2019-04-17 20:30 +0200
| From | Ian Jackson <ian.jackson@citrix.com> |
|---|---|
| Date | 2019-04-12 15:30 +0200 |
| Subject | Bug#926938: reboot hangs, hung task, ohci_urb_dequeue |
| Message-ID | <xM4pH-4Ei-5@gated-at.bofh.it> |
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
[toc] | [next] | [standalone]
| From | Ian Jackson <ian.jackson@citrix.com> |
|---|---|
| Date | 2019-04-17 20:30 +0200 |
| Subject | Bug#926938: reboot hangs, hung task, ohci_urb_dequeue [and 1 more messages] |
| Message-ID | <xNXtM-1e7-9@gated-at.bofh.it> |
| In reply to | #63828 |
Ian Jackson writes ("reboot hangs, hung task, ohci_urb_dequeue"):
> 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.
...
> 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
I have now seen a very similar failure but this time for various
unrelated reasons, my test run stopped and kept the machine in hand
after it timed out, rather than 1. power cycling it to try to get some
logs out of it and then 2. throwing the machine back into the test
pool.
The log shows a series of these hung task messages. There are many at
about 2 minute intervals. They all seem to have very similar stack
traces.
After 20 minutes, it seems to give up and continue with the reboot,
which then proceeds normally.
Apr 17 11:02:49.598500 Will now restart.
Apr 17 11:04:02.250645 [ 1352.738179] INFO: task kworker/0:1:4984 blocked for more than 120 seconds.
...
Apr 17 11:18:24.210345 [ 2092.867350] INFO: task kworker/0:1:4984 blocked for more than 120 seconds.
...
Apr 17 11:22:27.534529 [ 2214.647354] [<ffffffff878193e4>] ? ret_from_fork+0x44/0x70
Apr 17 11:22:27.534565 [ 2224.618473] reboot: Restarting system
Apr 17 11:22:37.503601 [ 2224.622513] reboot: machine restart
[binary gibberish from the firmare]
Apr 17 11:23:54.856013 Copyright 1982, 2014 Hewlett-Packard Development Company, L.P.
Ian.
[toc] | [prev] | [standalone]
Back to top | Article view | linux.debian.kernel
csiph-web