Bug 77191

Summary: ftdi-sio (usbserial) over usbip hung after disconnect while in use
Product: Drivers Reporter: Hendrik Borghorst (hendrikborghorst)
Component: USBAssignee: Greg Kroah-Hartman (greg)
Status: NEW ---    
Severity: normal CC: alexander.lochmann
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 3.14.1 Subsystem:
Regression: No Bisected commit-id:

Description Hendrik Borghorst 2014-06-02 09:39:26 UTC 
We are currently evaluating a new thinclient setup where we use usbip vhci-hcd hostdriver to enable the support for usb devices over the network.

We are testing several fpga programmers. One is an usb->serial adapter which uses the ftdi_sio driver. 

After disconnecting the dongle on the thinclient, the kernel on the vhci_hcd host got stuck.

I really can't say if this is related to the vhci_hcd host driver but for me it doesn't look like it. I think this problem is eventually related to usbserial or usbcore.


Here is a kernel snip from connecting to disconnect:



[1295781.598738] vhci_hcd: changed 0
[1295782.368860] vhci_hcd vhci_hcd: rhport(0) sockfd(3) devid(327691) speed(3)
[1295782.369126] vhci_hcd: changed 1
[1295782.475482] vhci_hcd: changed 0
[1295782.583659] usb 3-1: new high-speed USB device number 38 using vhci_hcd
[1295782.807841] usb 3-1: new high-speed USB device number 39 using vhci_hcd
[1295783.031955] usb 3-1: new high-speed USB device number 40 using vhci_hcd
[1295783.032008] usb 3-1: SetAddress Request (40) to port 0
[1295783.055278] usb 3-1: New USB device found, idVendor=0403, idProduct=6014
[1295783.055329] usb 3-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[1295783.055398] usb 3-1: Product: Digilent USB Device
[1295783.055439] usb 3-1: Manufacturer: Digilent
[1295783.055478] usb 3-1: SerialNumber: 210248471470
[1295783.058652] ftdi_sio 3-1:1.0: FTDI USB Serial Device converter detected
[1295783.058770] usb 3-1: Detected FT232H
[1295783.058809] usb 3-1: Number of endpoints 2
[1295783.058848] usb 3-1: Endpoint 1 MaxPacketSize 512
[1295783.058889] usb 3-1: Endpoint 2 MaxPacketSize 512
[1295783.058929] usb 3-1: Setting MaxPacketSize 512
[1295783.059746] usb 3-1: FTDI USB Serial Device converter now attached to ttyUSB0
[1295810.281891] usb 3-1: seqnum max
[1295855.427428] vhci_hcd: dequeue a urb ffff880f09d9fc80
[1295855.427485] vhci_hcd: device ffff880efb664268 seems to be still connected
[1295855.501236] vhci_hcd: unlink->seqnum 117833
[1295855.501286] vhci_hcd: urb->status -104
[1295855.501405] vhci_hcd: dequeue a urb ffff880ef1dd2c00
[1295855.501461] vhci_hcd: device ffff880efb664268 seems to be still connected
[1295855.575760] vhci_hcd: unlink->seqnum 117908
[1295855.575806] vhci_hcd: urb->status -104
[1295855.575907] vhci_hcd: dequeue a urb ffff880ef2c04c00
[1295937.360069] vhci_hcd: connection closed
[1295937.360227] vhci_hcd: stop threads
[1295937.360299] vhci_hcd: release socket
[1295937.360339] vhci_hcd: changed 1
[1295937.360381] vhci_hcd: disconnect device
[1295937.360599] usb 3-1: USB disconnect, device number 40
[1295937.360744] vhci_hcd: dequeue a urb ffff880ef1f64ec0
[1295937.360786] vhci_hcd: device ffff880efb664268 seems to be disconnected
[1295937.360831] vhci_hcd: gives back urb ffff880ef1f64ec0
[1296024.627193] INFO: task modem-manager:6025 blocked for more than 120 seconds.
[1296024.627270]       Tainted: G         C   3.14-1-amd64 #1
[1296024.627311] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[1296024.627381] modem-manager   D ffff88303edc6768     0  6025      1 0x20020000
[1296024.627462]  ffff88303edc6350 0000000000000086 0000000000014380 0000000000014380
[1296024.627558]  ffff88303eed7fd8 ffff88303edc6350 ffff880ef2c04c00 ffff88103d849180
[1296024.627647]  ffff880a59c81000 0000000000000000 ffff883078925920 ffff880f82171860
[1296024.627738] Call Trace:
[1296024.627850]  [<ffffffffa0015be5>] ? usb_kill_urb+0x55/0x90 [usbcore]
[1296024.627905]  [<ffffffff8109e400>] ? prepare_to_wait_event+0xf0/0xf0
[1296024.627960]  [<ffffffffa05fb7e3>] ? usb_serial_generic_close+0x63/0x80 [usbserial]
[1296024.628036]  [<ffffffff81332ca5>] ? tty_port_shutdown+0x65/0xa0
[1296024.628083]  [<ffffffff813335b3>] ? tty_port_close+0x23/0x50
[1296024.628130]  [<ffffffff8132a855>] ? tty_release+0xf5/0x5b0
[1296024.628179]  [<ffffffff813bd62a>] ? SYSC_sendto+0xda/0x140
[1296024.628228]  [<ffffffff811873f5>] ? __fput+0xc5/0x210
[1296024.628279]  [<ffffffff8107cda7>] ? task_work_run+0x97/0xd0
[1296024.628330]  [<ffffffff81013979>] ? do_notify_resume+0x59/0x90
[1296024.628378]  [<ffffffff814c7732>] ? int_signal+0x12/0x17
[1296144.718142] INFO: task khubd:734 blocked for more than 120 seconds.
[1296144.718196]       Tainted: G         C   3.14-1-amd64 #1
[1296144.718238] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[1296144.718308] khubd           D ffff88403e53d078     0   734      2 0x00000000
[1296144.718388]  ffff88403e53cc60 0000000000000046 0000000000014380 0000000000014380
[1296144.718482]  ffff88403e545fd8 ffff88403e53cc60 ffff880a59c81088 ffff88403e545c10
[1296144.718572]  ffff880a59c8108c ffff88403e53cc60 00000000ffffffff ffff880a59c81090
[1296144.718662] Call Trace:
[1296144.718714]  [<ffffffff814bc740>] ? schedule_preempt_disabled+0x20/0x70
[1296144.718764]  [<ffffffff814be1b3>] ? __mutex_lock_slowpath+0x133/0x1b0
[1296144.718812]  [<ffffffff814be246>] ? mutex_lock+0x16/0x25
[1296144.718859]  [<ffffffff81329259>] ? __tty_hangup+0x59/0x440
[1296144.718911]  [<ffffffffa05f9ebf>] ? usb_serial_disconnect+0x7f/0x130 [usbserial]
[1296144.719045]  [<ffffffffa001995b>] ? usb_unbind_interface+0x5b/0x1c0 [usbcore]
[1296144.719121]  [<ffffffff81365b05>] ? __device_release_driver+0x75/0xf0
[1296144.719168]  [<ffffffff81365b99>] ? device_release_driver+0x19/0x30
[1296144.719214]  [<ffffffff813654f2>] ? bus_remove_device+0xf2/0x140
[1296144.719265]  [<ffffffff8136260e>] ? device_del+0x10e/0x1b0
[1296144.719319]  [<ffffffffa00176d4>] ? usb_disable_device+0x94/0x1f0 [usbcore]
[1296144.719375]  [<ffffffffa000de7e>] ? usb_disconnect+0x8e/0x190 [usbcore]
[1296144.719431]  [<ffffffffa001098e>] ? hub_thread+0x53e/0x1320 [usbcore]
[1296144.719483]  [<ffffffff8109e400>] ? prepare_to_wait_event+0xf0/0xf0
[1296144.719537]  [<ffffffffa0010450>] ? usb_reset_device+0x170/0x170 [usbcore]
[1296144.719589]  [<ffffffff8107f911>] ? kthread+0xc1/0xe0
[1296144.719633]  [<ffffffff8107f850>] ? kthread_create_on_node+0x180/0x180
[1296144.719681]  [<ffffffff814c73cc>] ? ret_from_fork+0x7c/0xb0
[1296144.719726]  [<ffffffff8107f850>] ? kthread_create_on_node+0x180/0x180
[1296144.719851] INFO: task modem-manager:6025 blocked for more than 120 seconds.
[1296144.719919]       Tainted: G         C   3.14-1-amd64 #1
[1296144.719959] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[1296144.720028] modem-manager   D ffff88303edc6768     0  6025      1 0x20020000
[1296144.720105]  ffff88303edc6350 0000000000000086 0000000000014380 0000000000014380
[1296144.720195]  ffff88303eed7fd8 ffff88303edc6350 ffff880ef2c04c00 ffff88103d849180
[1296144.720285]  ffff880a59c81000 0000000000000000 ffff883078925920 ffff880f82171860
[1296144.720374] Call Trace:
[1296144.720426]  [<ffffffffa0015be5>] ? usb_kill_urb+0x55/0x90 [usbcore]
[1296144.720475]  [<ffffffff8109e400>] ? prepare_to_wait_event+0xf0/0xf0
[1296144.720528]  [<ffffffffa05fb7e3>] ? usb_serial_generic_close+0x63/0x80 [usbserial]
[1296144.720601]  [<ffffffff81332ca5>] ? tty_port_shutdown+0x65/0xa0
[1296144.720648]  [<ffffffff813335b3>] ? tty_port_close+0x23/0x50
[1296144.720694]  [<ffffffff8132a855>] ? tty_release+0xf5/0x5b0
[1296144.720742]  [<ffffffff813bd62a>] ? SYSC_sendto+0xda/0x140
[1296144.720789]  [<ffffffff811873f5>] ? __fput+0xc5/0x210
[1296144.720836]  [<ffffffff8107cda7>] ? task_work_run+0x97/0xd0
[1296144.720885]  [<ffffffff81013979>] ? do_notify_resume+0x59/0x90
[1296144.720931]  [<ffffffff814c7732>] ? int_signal+0x12/0x17
[1296144.721371] INFO: task adb:22930 blocked for more than 120 seconds.
[1296144.721416]       Tainted: G         C   3.14-1-amd64 #1
[1296144.721456] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[1296144.721525] adb             D ffff88403dc9c668     0 22930      1 0x20020000
[1296144.721602]  ffff88403dc9c250 0000000000200086 0000000000014380 0000000000014380
[1296144.721691]  ffff88403d37ffd8 ffff88403dc9c250 ffff880ef24318e8 ffff88403d37fc38
[1296144.721781]  ffff880ef24318ec ffff88403dc9c250 00000000ffffffff ffff880ef24318f0
[1296144.721870] Call Trace:
[1296144.721909]  [<ffffffff814bc740>] ? schedule_preempt_disabled+0x20/0x70
[1296144.721958]  [<ffffffff814be1b3>] ? __mutex_lock_slowpath+0x133/0x1b0
[1296144.722022]  [<ffffffff814be246>] ? mutex_lock+0x16/0x25
[1296144.722091]  [<ffffffffa001dccc>] ? usbdev_open+0xbc/0x210 [usbcore]
[1296144.722148]  [<ffffffff81189ded>] ? chrdev_open+0x9d/0x180
[1296144.722194]  [<ffffffff81189d50>] ? cdev_put+0x30/0x30
[1296144.722239]  [<ffffffff811835aa>] ? do_dentry_open+0x1ba/0x2c0
[1296144.722284]  [<ffffffff81183878>] ? finish_open+0x28/0x40
[1296144.722331]  [<ffffffff811940cc>] ? do_last+0xa5c/0x11c0
[1296144.722376]  [<ffffffff81190839>] ? link_path_walk+0x69/0x840
[1296144.722425]  [<ffffffff811948e6>] ? path_openat+0xb6/0x670
[1296144.722471]  [<ffffffff8101287e>] ? __switch_to+0x41e/0x4b0
[1296144.722518]  [<ffffffff814bbe96>] ? __schedule+0x2a6/0x6e0
[1296144.722564]  [<ffffffff81195655>] ? do_filp_open+0x35/0x80
[1296144.722614]  [<ffffffff8119e729>] ? touch_atime+0x69/0x140
[1296144.722660]  [<ffffffff811a0ebc>] ? __alloc_fd+0x7c/0x120
[1296144.722706]  [<ffffffff81184ec4>] ? do_sys_open+0x124/0x210
[1296144.722754]  [<ffffffff814c8fec>] ? sysenter_dispatch+0x7/0x21
[1296264.813162] INFO: task khubd:734 blocked for more than 120 seconds.
[1296264.813215]       Tainted: G         C   3.14-1-amd64 #1
[1296264.813257] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[1296264.813327] khubd           D ffff88403e53d078     0   734      2 0x00000000
[1296264.813407]  ffff88403e53cc60 0000000000000046 0000000000014380 0000000000014380
[1296264.813503]  ffff88403e545fd8 ffff88403e53cc60 ffff880a59c81088 ffff88403e545c10
[1296264.813593]  ffff880a59c8108c ffff88403e53cc60 00000000ffffffff ffff880a59c81090
[1296264.813683] Call Trace:
[1296264.813732]  [<ffffffff814bc740>] ? schedule_preempt_disabled+0x20/0x70
[1296264.813782]  [<ffffffff814be1b3>] ? __mutex_lock_slowpath+0x133/0x1b0
[1296264.813830]  [<ffffffff814be246>] ? mutex_lock+0x16/0x25
[1296264.813877]  [<ffffffff81329259>] ? __tty_hangup+0x59/0x440
[1296264.813928]  [<ffffffffa05f9ebf>] ? usb_serial_disconnect+0x7f/0x130 [usbserial]
[1296264.814064]  [<ffffffffa001995b>] ? usb_unbind_interface+0x5b/0x1c0 [usbcore]
[1296264.814139]  [<ffffffff81365b05>] ? __device_release_driver+0x75/0xf0
[1296264.814185]  [<ffffffff81365b99>] ? device_release_driver+0x19/0x30
[1296264.814232]  [<ffffffff813654f2>] ? bus_remove_device+0xf2/0x140
[1296264.814281]  [<ffffffff8136260e>] ? device_del+0x10e/0x1b0
[1296264.814335]  [<ffffffffa00176d4>] ? usb_disable_device+0x94/0x1f0 [usbcore]
[1296264.814392]  [<ffffffffa000de7e>] ? usb_disconnect+0x8e/0x190 [usbcore]
[1296264.814448]  [<ffffffffa001098e>] ? hub_thread+0x53e/0x1320 [usbcore]
[1296264.814500]  [<ffffffff8109e400>] ? prepare_to_wait_event+0xf0/0xf0
[1296264.814555]  [<ffffffffa0010450>] ? usb_reset_device+0x170/0x170 [usbcore]
[1296264.814606]  [<ffffffff8107f911>] ? kthread+0xc1/0xe0
[1296264.814650]  [<ffffffff8107f850>] ? kthread_create_on_node+0x180/0x180
[1296264.814698]  [<ffffffff814c73cc>] ? ret_from_fork+0x7c/0xb0
[1296264.814744]  [<ffffffff8107f850>] ? kthread_create_on_node+0x180/0x180
Comment 1 Greg Kroah-Hartman 2014-06-02 14:24:07 UTC 
On Mon, Jun 02, 2014 at 09:39:26AM +0000, bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=77191
> 
>             Bug ID: 77191
>            Summary: ftdi-sio (usbserial) over usbip hung after disconnect
>                     while in use

Please send this to the linux-usb@vger.kernel.org mailing list.