I am a beginner interested in usb/ip testing. I apologize if the following is a trivial problem.
I am trying to use a usb flash storage device via localhost usbip (i.e. server and client are the same machine)
I think this is the flow of the driver layers, correct me if I am wrong
client server
(usb-storage <-> vhci_hcd) <-> ( stub/usbip <-> ehci_hcd <-> device)
(testing drivers/staging/usbip from linux-2.6-kgdb/kgdb-dev git branch 2.6.29-rc7)
# lsusb
Bus 002 Device 009: ID 1307:0163 Transcend Information, Inc. 512MB USB Flash Drive
# usbip_bind_driver --list
List USB devices
- busid 2-5 (1307:0163)
2-5:1.0 -> usb-storage
# usbip_bind_driver --usbip 2-5
** (process:6857): DEBUG: 2-5:1.0 -> usb-storage
** (process:6857): DEBUG: unbinding interface
** (process:6857): DEBUG: write "add 2-5" to /sys/bus/usb/drivers/usbip/match_busid
** Message: bind 2-5 to usbip, complete!
relevant dmesg output:
[ 1618.078271] usbip_bind_driv:(drivers/staging/usbip/stub_main.c,148) store_match_busid: add busid 2-5
[ 1618.078337] usbip 2-5:1.0: usb_probe_interface
[ 1618.078340] usbip 2-5:1.0: usb_probe_interface - got id
[ 1618.078342] usbip 2-5:1.0: Enter
[ 1618.078344] usbip 2-5:1.0: allocating stub device<7>usbip_eh :(drivers/staging/usbip/usbip_event.c,24) event_handler: enter
[ 1618.078384] usbip_bind_driv:(drivers/staging/usbip/stub_dev.c,359) stub_device_alloc: register new interface
[ 1618.078387] usbip 2-5:1.0: USB/IP Stub: register a new interface (bus 2 dev 9 ifn 0)
Then from the client side I try to attach the device (usbip daemon already running)
# usbip -p
8 ports available
8 ports available
Port 00: <Port in Use> at High Speed(480Mbps)
Transcend Information, Inc. : 512MB USB Flash Drive (1307:0163)
3-1 -> usbip://localhost:3240/2-5 (remote devid 00020009 (bus/dev 002/009))
3-1:1.0 used by usb-storage
/sys/devices/platform/vhci_hcd/usb3/3-1/3-1:1.0/host5/scsi_host/host5/device
/sys/devices/platform/vhci_hcd/usb3/3-1/3-1:1.0/usb_endpoint/usbdev3.4_ep01/device
/sys/devices/platform/vhci_hcd/usb3/3-1/3-1:1.0/usb_endpoint/usbdev3.4_ep82/device
/sys/devices/platform/vhci_hcd/usb3/3-1/3-1:1.0/usb_endpoint/usbdev3.4_ep83/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>
[ 1641.342757] usbip 2-5:1.0: stub up
....
[ 1642.072535] usb 3-1: adding 3-1:1.0 (config #1, interface 0)
[ 1642.072564] usb 3-1:1.0: uevent
[ 1642.072586] usb-storage 3-1:1.0: usb_probe_interface
[ 1642.072591] usb-storage 3-1:1.0: usb_probe_interface - got id
[ 1642.072662] scsi5 : SCSI emulation for USB Mass Storage devices
[ 1642.072869] drivers/usb/core/inode.c: creating file '004'
[ 1642.072929] usb-storage: device found at 4
[ 1642.072930] usb-storage: waiting for device to settle before scanning
I never get a "device scan complete" from usb-storage. The device is reset, or maybe usb-storage keeps trying
to reset it for some reason. Part of dmesg follows (full dmesg is attached)
[ 1652.816024] usbip: vhci_hcd: dequeue a urb ffff8800a99e6d80
[ 1652.816029] vhci_hcd vhci_hcd: Unlink after no-IRQ? Controller is probably using the wrong IRQ.
[ 1652.816032] usbip: vhci_hcd: device ffff8800a658c1b0 seems to be still connected
[ 1652.816037] scsi_eh_5 :(drivers/staging/usbip/vhci_hcd.c,803) vhci_urb_dequeue: leave
[ 1652.816050] vhci_tx :(drivers/staging/usbip/vhci_tx.c,237) vhci_tx_loop: pending urbs ?, now wake up
[ 1652.816055] vhci_tx :(drivers/staging/usbip/vhci_tx.c,180) vhci_send_cmd_unlink: setup cmd unlink, 15
[ 1652.816090] vhci_tx :(drivers/staging/usbip/vhci_tx.c,205) vhci_send_cmd_unlink: send txdata
[ 1652.816108] stub_rx :usbip_xmit: receiving....
[ 1652.816110] 00 00 00 02 | 00 00 00 0f | 00 02 00 09 | 00 00 00 00 | 00 00 00 00 | 00 00 00 0e |
[ 1652.816123] 00 00 00 00 | 00 00 00 00 | 00 00 00 00 | 00 00 00 00 | 00 00 00 00 | 00 00 00 00 |
[ 1652.816136]
[ 1652.816137] usbip_xmit: received, osize 48 ret 48 size 0 total 48
[ 1652.816141] stub_rx :(drivers/staging/usbip/usbip_common.c,345) usbip_dump_header: BASE: cmd 2 seq 15 devid 131081 dir 0 ep 0
[ 1652.816144] stub_rx :(drivers/staging/usbip/usbip_common.c,357) usbip_dump_header: CMD_UNLINK: seq 14
[ 1652.816147] usb 2-5: unlink urb ffff8800a99e6680
[ 1652.816155] stub_rx :(drivers/staging/usbip/stub_rx.c,556) stub_rx_pdu: Enter
[ 1652.816157] stub_rx :(drivers/staging/usbip/usbip_common.c,474) usbip_xmit: enter
[ 1652.816226] interrupt :(drivers/staging/usbip/stub_tx.c,69) stub_complete: complete! status -104
[ 1652.816228] usbip: unlinked by a call of usb_unlink_urb()
[ 1652.816239] stub_tx :(drivers/staging/usbip/stub_tx.c,290) stub_send_ret_unlink: setup ret unlink 15
[ 1652.816248] stub_tx :(drivers/staging/usbip/stub_tx.c,311) stub_send_ret_unlink: send txdata
[ 1652.816253] vhci_rx :usbip_xmit: receiving....
[ 1652.816255] 00 00 00 04 | 00 00 00 0f | 00 00 00 00 | 00 00 00 00 | 00 00 00 00 | ff ff ff 98 |
[ 1652.816267] 00 00 00 00 | 00 00 00 00 | 00 00 00 00 | 00 00 00 00 | 00 00 00 00 | 00 00 00 00 |
[ 1652.816280]
[ 1652.816281] usbip_xmit: received, osize 48 ret 48 size 0 total 48
[ 1652.816284] vhci_rx :(drivers/staging/usbip/usbip_common.c,345) usbip_dump_header: BASE: cmd 4 seq 15 devid 0 dir 0 ep 0
[ 1652.816287] vhci_rx :(drivers/staging/usbip/usbip_common.c,366) usbip_dump_header: RET_UNLINK: status -104
[ 1652.816290] vhci_rx :(drivers/staging/usbip/usbip_common.c,345) usbip_dump_header: BASE: cmd 4 seq 15 devid 0 dir 0 ep 0
[ 1652.816293] vhci_rx :(drivers/staging/usbip/usbip_common.c,366) usbip_dump_header: RET_UNLINK: status -104
[ 1652.816296] usbip: unlink->seqnum 15
[ 1652.816298] vhci_rx :(drivers/staging/usbip/vhci_rx.c,131) dequeue_pending_unlink: found pending unlink, 15
[ 1652.816301] vhci_rx :(drivers/staging/usbip/vhci_rx.c,40) pickup_urb_and_free_priv: find urb ffff8800a99e6d80 vurb ffff8800a98e4f80 seqnum 14
[ 1652.816305] vhci_rx :(drivers/staging/usbip/vhci_rx.c,169) vhci_recv_ret_unlink: now giveback urb ffff8800a99e6d80
[ 1652.816307] usbip: -104
[ 1652.816312] vhci_rx :(drivers/staging/usbip/vhci_rx.c,196) vhci_rx_pdu: Enter
[ 1652.816315] vhci_rx :(drivers/staging/usbip/usbip_common.c,474) usbip_xmit: enter
[ 1652.816329] usb-storage:(drivers/staging/usbip/vhci_hcd.c,279) vhci_hub_control: typeReq 2303 wValue 4 wIndex 1
[ 1652.816333] usb-storage:(drivers/staging/usbip/vhci_hcd.c,442) vhci_hub_control: SetPortFeature: USB_PORT_FEAT_RESET
[ 1652.816336] usb-storage:(drivers/staging/usbip/vhci_hcd.c,463) vhci_hub_control: SetPortFeature: default 4
[ 1652.816338] port 0
[ 1652.816340] status 00000503: CONNECTION ENABLE POWER HIGHSPEED
[ 1652.816343] status 00000111: CONNECTION RESET POWER
[ 1652.816347] usb-storage:(drivers/staging/usbip/vhci_hcd.c,483) vhci_hub_control: bye
[ 1652.872523] usb-storage:(drivers/staging/usbip/vhci_hcd.c,279) vhci_hub_control: typeReq a300 wValue 0 wIndex 1
[ 1652.872528] usb-storage:(drivers/staging/usbip/vhci_hcd.c,345) vhci_hub_control: GetPortStatus port 1
[ 1652.872531] usb-storage:(drivers/staging/usbip/vhci_hcd.c,419) vhci_hub_control: GetPortStatus bye 101 10
[ 1652.872533] port 0
[ 1652.872534] status 00000111: CONNECTION RESET POWER
[ 1652.872538] status 00100101: CONNECTION POWER C_RESET
[ 1652.872541] usb-storage:(drivers/staging/usbip/vhci_hcd.c,483) vhci_hub_control: bye
[ 1652.872547] hub 3-0:1.0: port 1 not reset yet, waiting 50ms
[ 1652.928523] usb-storage:(drivers/staging/usbip/vhci_hcd.c,279) vhci_hub_control: typeReq a300 wValue 0 wIndex 1
[ 1652.928528] usb-storage:(drivers/staging/usbip/vhci_hcd.c,345) vhci_hub_control: GetPortStatus port 1
[ 1652.928531] usb-storage:(drivers/staging/usbip/vhci_hcd.c,419) vhci_hub_control: GetPortStatus bye 101 10
[ 1652.928533] port 0
[ 1652.928535] status 00100101: CONNECTION POWER C_RESET
[ 1652.928538] status 00100101: CONNECTION POWER C_RESET
[ 1652.928542] usb-storage:(drivers/staging/usbip/vhci_hcd.c,483) vhci_hub_control: bye
[ 1652.928547] hub 3-0:1.0: port 1 not reset yet, waiting 200ms
[ 1653.132026] usb-storage:(drivers/staging/usbip/vhci_hcd.c,279) vhci_hub_control: typeReq a300 wValue 0 wIndex 1
[ 1653.132031] usb-storage:(drivers/staging/usbip/vhci_hcd.c,345) vhci_hub_control: GetPortStatus port 1
[ 1653.132034] usb-storage:(drivers/staging/usbip/vhci_hcd.c,419) vhci_hub_control: GetPortStatus bye 101 10
[ 1653.132036] port 0
[ 1653.132037] status 00100101: CONNECTION POWER C_RESET
[ 1653.132041] status 00100101: CONNECTION POWER C_RESET
[ 1653.132044] usb-storage:(drivers/staging/usbip/vhci_hcd.c,483) vhci_hub_control: bye
[ 1653.132050] hub 3-0:1.0: port 1 not reset yet, waiting 200ms
[ 1653.336522] usb-storage:(drivers/staging/usbip/vhci_hcd.c,279) vhci_hub_control: typeReq a300 wValue 0 wIndex 1
[ 1653.336527] usb-storage:(drivers/staging/usbip/vhci_hcd.c,345) vhci_hub_control: GetPortStatus port 1
[ 1653.336530] usb-storage:(drivers/staging/usbip/vhci_hcd.c,419) vhci_hub_control: GetPortStatus bye 101 10
[ 1653.336532] port 0
[ 1653.336533] status 00100101: CONNECTION POWER C_RESET
[ 1653.336536] status 00100101: CONNECTION POWER C_RESET
[ 1653.336540] usb-storage:(drivers/staging/usbip/vhci_hcd.c,483) vhci_hub_control: bye
[ 1653.336545] hub 3-0:1.0: port 1 not reset yet, waiting 200ms
[ 1653.336547] hub 3-0:1.0: port_wait_reset: err = -16
[ 1653.336549] hub 3-0:1.0: port 1 not enabled, trying reset again...
[ 1653.336552] usb-storage:(drivers/staging/usbip/vhci_hcd.c,279) vhci_hub_control: typeReq 2303 wValue 4 wIndex 1
[ 1653.336555] usb-storage:(drivers/staging/usbip/vhci_hcd.c,442) vhci_hub_control: SetPortFeature: USB_PORT_FEAT_RESET
[ 1653.336558] usb-storage:(drivers/staging/usbip/vhci_hcd.c,463) vhci_hub_control: SetPortFeature: default 4
[ 1653.336560] port 0
[ 1653.336561] status 00100101: CONNECTION POWER C_RESET
[ 1653.336564] status 00100111: CONNECTION RESET POWER C_RESET
[ 1653.336567] usb-storage:(drivers/staging/usbip/vhci_hcd.c,483) vhci_hub_control: bye
[ 1653.540523] usb-storage:(drivers/staging/usbip/vhci_hcd.c,279) vhci_hub_control: typeReq a300 wValue 0 wIndex 1
[ 1653.540527] usb-storage:(drivers/staging/usbip/vhci_hcd.c,345) vhci_hub_control: GetPortStatus port 1
[ 1653.540530] usb-storage:(drivers/staging/usbip/vhci_hcd.c,419) vhci_hub_control: GetPortStatus bye 101 10
[ 1653.540533] port 0
[ 1653.540534] status 00100111: CONNECTION RESET POWER C_RESET
[ 1653.540537] status 00100101: CONNECTION POWER C_RESET
[ 1653.540541] usb-storage:(drivers/staging/usbip/vhci_hcd.c,483) vhci_hub_control: bye
[ 1653.540547] hub 3-0:1.0: port 1 not reset yet, waiting 200ms
[ 1653.744525] usb-storage:(drivers/staging/usbip/vhci_hcd.c,279) vhci_hub_control: typeReq a300 wValue 0 wIndex 1
[ 1653.744529] usb-storage:(drivers/staging/usbip/vhci_hcd.c,345) vhci_hub_control: GetPortStatus port 1
[ 1653.744532] usb-storage:(drivers/staging/usbip/vhci_hcd.c,419) vhci_hub_control: GetPortStatus bye 101 10
[ 1653.744534] port 0
[ 1653.744536] status 00100101: CONNECTION POWER C_RESET
[ 1653.744539] status 00100101: CONNECTION POWER C_RESET
[ 1653.744542] usb-storage:(drivers/staging/usbip/vhci_hcd.c,483) vhci_hub_control: bye
[ 1653.744548] hub 3-0:1.0: port 1 not reset yet, waiting 200ms
[ 1653.948024] usb-storage:(drivers/staging/usbip/vhci_hcd.c,279) vhci_hub_control: typeReq a300 wValue 0 wIndex 1
[ 1653.948029] usb-storage:(drivers/staging/usbip/vhci_hcd.c,345) vhci_hub_control: GetPortStatus port 1
[ 1653.948032] usb-storage:(drivers/staging/usbip/vhci_hcd.c,419) vhci_hub_control: GetPortStatus bye 101 10
[ 1653.948034] port 0
[ 1653.948036] status 00100101: CONNECTION POWER C_RESET
[ 1653.948039] status 00100101: CONNECTION POWER C_RESET
[ 1653.948042] usb-storage:(drivers/staging/usbip/vhci_hcd.c,483) vhci_hub_control: bye
[ 1653.948048] hub 3-0:1.0: port 1 not reset yet, waiting 200ms
[ 1653.948050] hub 3-0:1.0: port_wait_reset: err = -16
[ 1653.948052] hub 3-0:1.0: port 1 not enabled, trying reset again...
usb-storage/khubd seem to keep trying to reset the port.
Finally
....
[ 1678.804022] hub 3-0:1.0: hub_suspend
[ 1678.804031] usb usb3: bus auto-suspend
[ 1678.804033] usb usb3: vhci_bus_suspend
lsusb appears to be non-responsivea after this, maybe vhci_hcd or some other driver is stuck.
# usbip -p
8 ports available
usbip err: vhci_driver.c: 19 (imported_device_init) sysfs_open_device 3-1
usbip err: vhci_driver.c: 102 (parse_status) init new device
Is the problem caused by a flash device device reset?
I don't know if the following sysfs variables of the flash device are relevant, but here goes:
# cat /sys/devices/pci0000\:00/0000\:00\:02.1/usb2/2-5/power/level
on
# cat /sys/devices/pci0000\:00/0000\:00\:02.1/usb2/2-5/power/autosuspend
2
# cat /sys/devices/pci0000\:00/0000\:00\:02.1/usb2/2-5/power/persist
1
this may be related to:
http://sourceforge.net/forum/forum.php?thread_id=1784650&forum_id=418507
Have other people faced issues with using flash-storage devices over usbip? THe post above talks about other devices.
Btw I managed to get the same device stable over usbip for one and only one attempt. I can't reproduce success.
I get the same problem with another flash device:
Bus 001 Device 008: ID 0204:6025 Chipsbank Microelectronics Co., Ltd CBM2080 Flash drive controller
Both devices are usable with normal USB i.e. not over usbip.
thanks for any help,
- Vasilis
Attachment:
dmesg-usbip-storage.gz
Description: Binary data
