Work at SourceForge, help us to make it a better place! We have an immediate need for a Support Technician in our San Francisco or Denver office.

Close

usbip_eh: blocked for more than 120 seconds

Help
2009-08-24
2013-05-30
  • ###########################################################
    server# usbip --version
    =======STDOUT===========
    usbip err: vhci_attach.c: 586 (main        ) open usb.ids
    usbip 0.1.7 ($Id: vhci_attach.c 42 2007-09-07 12:07:51Z hirofuchi $)
    =======STDOUT-END=======

    server$ uname -a
    =======STDOUT===========
    Linux server 2.6.30-gentoo-r4 #1 Mon Jul 27 03:52:21 MSD 2009 i686 Intel(R) Pentium(R) 4 CPU 2.40GHz GenuineIntel GNU/Linux
    =======STDOUT-END=======

    client# usbip --version
    =======STDOUT===========
    usbip err: vhci_attach.c: 586 (main        ) open usb.ids
    usbip 0.1.7 ($Id: vhci_attach.c 42 2007-09-07 12:07:51Z hirofuchi $)
    =======STDOUT-END=======

    client# uname -a
    =======STDOUT===========
    Linux inspirra 2.6.30-gentoo-r4 #11 PREEMPT Mon Aug 24 00:47:31 MSD 2009 i686 AMD Sempron(tm) Processor 2800+ AuthenticAMD GNU/Linux
    =======STDOUT-END=======

    ###########################################################
    server:vt1# tail -n0  -f /var/log/messages | tee  /tmp/msg.log

    /tmp/msg.log => http://www.pastebin.ca/1541930

    ###########################################################
    server:vt2# modprobe usbip
    server:vt2# usbipd
    =======STDOUT===========
    usbip err: stub_server.c: 433 (do_standalone_mode) open usb.ids
    Bind usbip.ko to a usb device to be exportable!
    listen at [0.0.0.0]:3240
    usbipd start (usbip 0.1.7 ($Id: stub_server.c 42 2007-09-07 12:07:51Z hirofuchi $))
    =======STDOUT-END=======

    =======DMESG===========
    Aug 24 21:16:43 server usbip_common_mod: module is from the staging directory, the quality is unknown, you have been warned.
    Aug 24 21:16:43 server usbip_common_mod: usbip common driver1.0<4>usbip: module is from the staging directory, the quality is unknown, you have been warned.
    Aug 24 21:16:43 server usbip 1-5:1.0: this device 1-5 is not in match_busid table. skip!
    Aug 24 21:16:43 server usbip 1-6:1.0: this device 1-6 is not in match_busid table. skip!
    Aug 24 21:16:43 server usbip 1-7:1.1: this device 1-7 is not in match_busid table. skip!
    Aug 24 21:16:43 server usbcore: registered new interface driver usbip
    Aug 24 21:16:43 server usbip:Stub Driver for USB/IP:1.0
    =======DMESG-END=======

    ###########################################################
    server:vt3#  bind_driver --list
    =======STDOUT===========
    List USB devices
    - busid 1-1 (04b8:0007)
             1-1:1.0 -> usblp

    - busid 1-5 (04b8:012c)
             1-5:1.0 -> none

    - busid 1-6 (04b8:011b)
             1-6:1.0 -> none

    - busid 1-7 (03f0:3817)
             1-7:1.0 -> usblp
             1-7:1.1 -> none

    - busid 3-2 (0764:0501)
             3-2:1.0 -> usbhid
    =======STDOUT-END=======

    ###########################################################
    server:vt3# bind_driver --usbip 1-5
    =======STDOUT===========
    ** (process:4019): DEBUG:  1-5:1.0      -> none
    ** (process:4019): DEBUG: write "add 1-5" to /sys/bus/usb/drivers/usbip/match_busid
    ** Message: bind 1-5 to usbip, complete!
    =======STDOUT-END=======

    =======DMESG===========
    Aug 24 21:17:45 server usbip 1-5:1.0: USB/IP Stub: register a new interface (bus 1 dev 4 ifn 0)
    =======DMESG-END=======

    ###########################################################
    client# modprobe usbip_common_mod
    ======DMESG-START=======
    usbip_common_mod: module is from the staging directory, the quality is unknown, you have been warned.
    usbip_common_mod: usbip common driver1.0
    ======DMESG-STOP========

    ###########################################################
    client# modprobe vhci-hcd
    ======DMESG-START=======
    vhci_hcd: vhci_hcd, 1.0
    usbip: proving...
    vhci_hcd vhci_hcd: USB/IP Virtual Host Contoroller
    vhci_hcd vhci_hcd: new USB bus registered, assigned bus number 3
    usb usb3: configuration #1 chosen from 1 choice
    hub 3-0:1.0: USB hub found
    hub 3-0:1.0: 8 ports detected
    ======DMESG-STOP=======

    ###########################################################
    client# usbip --list server
    =======STDOUT===========
    usbip err: vhci_attach.c: 586 (main        ) open usb.ids
    - server
         1-5: unknown vendor : unknown product (04b8:012c)
            : /sys/devices/pci0000:00/0000:00:1d.7/usb1/1-5
            : unknown class / unknown subclass / unknown protocol (ff/ff/ff)
            :  0 - unknown class / unknown subclass / unknown protocol (ff/ff/ff)
    =======STDOUT-END=======

    ###########################################################
    client#  usbip --attach server 1-5
    =======STDOUT===========
    usbip err: vhci_attach.c: 586 (main        ) open usb.ids
    8 ports available
    port 0 attached
    =======STDOUT-END=======

    =======DMESG===========
    usbip: rhport(0) sockfd(3) devid(65540) speed(3)
    usbip: changed 1
    usb 3-1: new high speed USB device using vhci_hcd and address 2
    usb 3-1: new high speed USB device using vhci_hcd and address 3
    usb 3-1: new high speed USB device using vhci_hcd and address 4
    usb 3-1: SetAddress Request (4) to port 0
    usb 3-1: configuration #1 chosen from 1 choice
    =======DMESG-END=======

    ###########################################################
    # usbip -p
    =======STDOUT===========
    usbip err: vhci_attach.c: 586 (main        ) open usb.ids
    8 ports available

    Port 00: <Port in Use> at High Speed(480Mbps)
           unknown vendor : unknown product (04b8:012c)
           3-1 -> usbip://server:3240/1-5  (remote devid 00010004 (bus/dev 001/004))
           3-1:1.0 used by unknown
               /sys/class/usb_endpoint/usbdev3.4_ep01/device
               /sys/class/usb_endpoint/usbdev3.4_ep82/device
    Port 01: <Port Available>
    Port 02: <Port Available>
    Port 03: <Port Available>
    Port 04: <Port Available>
    Port 05: <Port Available>
    Port 06: <Port Available>
    Port 07: <Port Available>
    =======STDOUT-END=======

    ###########################################################
    client# sane-find-scanner
    =======STDOUT===========
    ...
    found USB scanner (vendor=0x04b8 [EPSON], product=0x012c [EPSON Scanner]) at libusb:003:004
    ...
    =======STDOUT-END=======

    ###########################################################
    client# time scanimage -L
    =======STDOUT===========
    device `epson:libusb:003:004' is a Epson GT-X900 flatbed scanner

    real    0m30.009s #!!!Very long!!!
    user    0m0.002s
    sys     0m0.001s
    =======STDOUT-END=======

    ###########################################################
    client# scanimage -d epson:libusb:003:004 > /dev/null
    =======STDOUT===========
    scanimage: sane_start: Error during device I/O
    =======STDOUT===========

    ###########################################################
    client# usbip --detach 0
    =======STDOUT===========
    usbip err: vhci_attach.c: 586 (main        ) open usb.ids
    8 ports available

    port 0 detached
    =======STDOUT-END=======

    ###########################################################
    client# usbip -p
    =======STDOUT===========
    usbip err: vhci_attach.c: 586 (main        ) open usb.ids
    8 ports available

    Port 00: <Port Available>
    Port 01: <Port Available>
    Port 02: <Port Available>
    Port 03: <Port Available>
    Port 04: <Port Available>
    Port 05: <Port Available>
    Port 06: <Port Available>
    Port 07: <Port Available>
    =======STDOUT-END=======

    ###########################################################
    client# usbip -l server
    =======STDOUT===========
    usbip err: vhci_attach.c: 586 (main        ) open usb.ids
    - server
    =======STDOUT-END=======

    =======SERVER-DMESG====
    Aug 24 21:50:46 server INFO: task usbip_eh:4020 blocked for more than 120 seconds.
    Aug 24 21:50:46 server "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
    Aug 24 21:50:46 server usbip_eh      D c0102da9     0  4020      2                             
    Aug 24 21:50:46 server db85fc00 00000046 db9ec370 c0102da9 df978780 df807850 df978784 7fffffff 
    Aug 24 21:50:46 server 7fffffff 00000000 00000002 c0400c20 c0400cdf c016d0f1 00000206 00000206 
    Aug 24 21:50:46 server defb67b0 dfb33660 defb67b0 dba6ff10 c019207f df4a3000 00000000 c0192214 
    Aug 24 21:50:46 server Call Trace:                                                             
    Aug 24 21:50:46 server [<c0102da9>] ? common_interrupt+0x29/0x30                               
    Aug 24 21:50:46 server [<c0400c20>] ? schedule+0x5/0x13
    Aug 24 21:50:46 server [<c0400cdf>] ? schedule_timeout+0x15/0x146
    Aug 24 21:50:46 server [<c016d0f1>] ? find_inode+0x1b/0x56
    Aug 24 21:50:46 server [<c019207f>] ? release_sysfs_dirent+0x53/0x65
    Aug 24 21:50:46 server [<c0192214>] ? sysfs_addrm_finish+0x161/0x174
    Aug 24 21:50:46 server [<c040089d>] ? wait_for_common+0x95/0xe1
    Aug 24 21:50:46 server [<c0114ab4>] ? default_wake_function+0x0/0x8
    Aug 24 21:50:46 server [<e0bcc181>] ? stub_disconnect+0x5b/0x64 [usbip]
    Aug 24 21:50:46 server [<c033c1a6>] ? usb_unbind_interface+0x32/0x8e
    Aug 24 21:50:46 server [<c02c253d>] ? __device_release_driver+0x55/0x73
    Aug 24 21:50:46 server [<c02c25d3>] ? device_release_driver+0x15/0x1e
    Aug 24 21:50:46 server [<c033c35b>] ? usb_driver_release_interface+0x30/0x7c
    Aug 24 21:50:46 server [<c033c405>] ? usb_forced_unbind_intf+0x10/0x16
    Aug 24 21:50:46 server [<c0336ac1>] ? usb_reset_device+0x61/0xd5
    Aug 24 21:50:46 server [<c0335002>] ? usb_lock_device_for_reset+0x74/0x92
    Aug 24 21:50:46 server [<e0bcc1be>] ? stub_device_reset+0x34/0x83 [usbip]
    Aug 24 21:50:46 server [<e0bbec55>] ? event_handler_loop+0x50/0xfb [usbip_common_mod]
    Aug 24 21:50:46 server [<c0125a0c>] ? autoremove_wake_function+0x0/0x2d
    Aug 24 21:50:46 server [<e0bbeb87>] ? usbip_thread+0x38/0x49 [usbip_common_mod]
    Aug 24 21:50:46 server [<e0bbeb4f>] ? usbip_thread+0x0/0x49 [usbip_common_mod]
    Aug 24 21:50:46 server [<c0102e93>] ? kernel_thread_helper+0x7/0x10
    Aug 24 21:52:46 server INFO: task usbip_eh:4020 blocked for more than 120 seconds.
    Aug 24 21:52:46 server "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
    Aug 24 21:52:46 server usbip_eh      D c0102da9     0  4020      2
    Aug 24 21:52:46 server db85fc00 00000046 db9ec370 c0102da9 df978780 df807850 df978784 7fffffff
    Aug 24 21:52:46 server 7fffffff 00000000 00000002 c0400c20 c0400cdf c016d0f1 00000206 00000206
    Aug 24 21:52:46 server defb67b0 dfb33660 defb67b0 dba6ff10 c019207f df4a3000 00000000 c0192214
    Aug 24 21:52:46 server Call Trace:
    =======SERVER-DMESG-END==============

    =======SERVER-USBIPD-STDOUT===========
    connected from 192.168.2.1:33996
    usbip err: stub_driver.c:  57 (read_attr_usbip_status) open /sys/devices/pci0000:00/0000:00:1d.7/usb1/1-5/1-5:1.0/usbip_status
    usbip err: stub_driver.c: 185 (refresh_exported_devices) usbip_exported_device new
    connected from 192.168.2.1:33999
    usbip err: stub_driver.c:  57 (read_attr_usbip_status) open /sys/devices/pci0000:00/0000:00:1d.7/usb1/1-5/1-5:1.0/usbip_status
    usbip err: stub_driver.c: 185 (refresh_exported_devices) usbip_exported_device new
    =======SERVER-USBIPD-STDOUT-END=======

    ###########################################################
    server:vt2# <CRTL+C> usbipd
    server:vt2# rmmod usbip # !!!hang-up!!!
    =======DMESG===========
    usbcore: deregistering interface driver usbip
    =======DMESG-END=======