singhamit235 - 2010-07-25

Hi,

When using USB Mass Storage devices through usbip, 50% times connection does not happen.

I think i have the same problem as this post "http://sourceforge.net/projects/usbip/forums/forum/418508/topic/1651920"

When connection does not happen, i am getting "USB cable may be bad" or "unlink after no IRQ" after client has sent unlink urb call to server.

after much viewing the debug prints on server side  i found out that seq no. 14 URB, USB core is not calling "stub_complete" completion handler and on client side mass storage driver or scsi driver after waiting for 21 seconds calls unlink_urb for which completion handler will be called. That means for some URBS completion handler is missed they never called and timeout happens which result in urb unlink from client.

Can it is solved?, or what is the reason for completion handler not called at all?. i am using 100Mbps LAN network.

This problem can also be reproduced in loopback mechanism(installing server and client on single PC).

Here is initial scsi commands urb coming from usb mass storage device, this sequence will be followed while scsi scans the device.

1. CBW 31 bytes --                  URB OUT
2. 4k or 8k or 36 bytes                                           URB IN
3. CSW 13 bytes                                                           URB IN

Log is attached:

usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes
NOTE : Sends CBW command from mass storage driver
usb-storage: ***CLIENT*** (drivers/staging/usbip/vhci_hcd.c,560) vhci_urb_enqueue:
usb-storage: ***CLIENT*** (drivers/staging/usbip/vhci_hcd.c,526) vhci_tx_urb:
vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,78) vhci_send_cmd_submit:
vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,53) dequeue_from_priv_tx:
vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,30) setup_cmd_submit_pdu: URB, local devnum 4, remote devid 65538
vhci_tx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,635) usbip_pack_pdu: USBIP_CMD_SUBMIT pack:     
NOTE :  -- vhci sends URB to remote server stub driver

vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,53) dequeue_from_priv_tx:
vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,172) vhci_send_cmd_unlink:
stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,323) valid_request:
stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,477) stub_recv_cmd_submit:                 NOTE :---stub recives the URB
vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,149) dequeue_from_unlink_tx:
stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,343) stub_priv_alloc:
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,635) usbip_pack_pdu: USBIP_CMD_SUBMIT unpack:
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,877) usbip_recv_xbuff: STUB:
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,458) usbip_xmit: Enter
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,496) usbip_xmit: receive
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,827) usbip_recv_iso:
stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,207) tweak_special_requests:
stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,533) stub_recv_cmd_submit: calling ->usb_submit_urb
NOTE :  --submit the urb to usb core

stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,541) stub_recv_cmd_submit: submit urb ok, seqnum 13
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_event.c,145) usbip_event_happened:
stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,569) stub_rx_pdu:
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,458) usbip_xmit: Enter
interrupt : ***SERVER*** (drivers/staging/usbip/stub_tx.c,73) stub_complete: complete! status 0
NOTE :--- URB success, comletion handler called

stub_tx : ***COMMON*** (drivers/staging/usbip/usbip_event.c,145) usbip_event_happened:
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,496) usbip_xmit: receive
stub_tx : ***SERVER*** (drivers/staging/usbip/stub_tx.c,185) stub_send_ret_submit:
stub_tx : ***SERVER*** (drivers/staging/usbip/stub_tx.c,161) dequeue_from_priv_tx:
stub_tx : ***SERVER*** (drivers/staging/usbip/stub_tx.c,138) setup_ret_submit_pdu:
stub_tx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,639) usbip_pack_pdu: USBIP_RET_SUBMIT pack:
NOTE :-- sends back the completed URB to client

stub_tx : ***SERVER*** (drivers/staging/usbip/stub_tx.c,161) dequeue_from_priv_tx:
stub_tx : ***SERVER*** (drivers/staging/usbip/stub_tx.c,29) stub_free_priv_and_urb:
stub_tx : ***SERVER*** (drivers/staging/usbip/stub_tx.c,293) stub_send_ret_unlink:
stub_tx : ***SERVER*** (drivers/staging/usbip/stub_tx.c,268) dequeue_from_unlink_tx:
vhci_rx : ***CLIENT*** (drivers/staging/usbip/vhci_rx.c,79) vhci_recv_ret_submit: vhci_rx : ***CLIENT*** (drivers/staging/usbip/vhci_rx.c,34) pickup_urb_and_free_priv: vhci_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,639) usbip_pack_pdu: USBIP_RET_SUBMIT unpack:
NOTE :-- client vhci recives completed URB and send to mass storage via usbcore

vhci_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,885) usbip_recv_xbuff: VHCI:
vhci_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,827) usbip_recv_iso:
vhci_rx : ***COMMON*** (drivers/staging/usbip/usbip_event.c,145) usbip_event_happened:
vhci_rx : ***CLIENT*** (drivers/staging/usbip/vhci_rx.c,204) vhci_rx_pdu: vhci_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,458) usbip_xmit: Enter
vhci_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,496) usbip_xmit: receive
usb-storage: Status code 0; transferred 31/31
NOTE :-- usb mass storage recives the completed urb and transfer complete.

usb-storage: - transfer complete
usb-storage: Bulk command transfer result=0
usb-storage: usb_stor_bulk_transfer_sglist: xfer 36 bytes, 1 entries
NOTE :- Sends data command from mass storage driver

usb-storage: ***CLIENT*** (drivers/staging/usbip/vhci_hcd.c,560) vhci_urb_enqueue:
usb-storage: ***CLIENT*** (drivers/staging/usbip/vhci_hcd.c,526) vhci_tx_urb:
vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,78) vhci_send_cmd_submit:
vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,53) dequeue_from_priv_tx:
vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,30) setup_cmd_submit_pdu: URB, local devnum 4, remote devid 65538
vhci_tx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,635) usbip_pack_pdu: USBIP_CMD_SUBMIT pack:
NOTE :-- vhci sends URB to remote server stub driver

vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,53) dequeue_from_priv_tx:
vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,172) vhci_send_cmd_unlink:
vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,149) dequeue_from_unlink_tx:
stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,323) valid_request:
stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,477) stub_recv_cmd_submit:
NOTE :--stub recives the URB

stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,343) stub_priv_alloc:
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,635) usbip_pack_pdu: USBIP_CMD_SUBMIT unpack:
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,877) usbip_recv_xbuff: STUB:
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,827) usbip_recv_iso:
stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,207) tweak_special_requests:
stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,533) stub_recv_cmd_submit: calling ->usb_submit_urb
NOTE :--submit the urb to usb core

stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,541) stub_recv_cmd_submit: submit urb ok, seqnum 14
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_event.c,145) usbip_event_happened:
stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,569) stub_rx_pdu:
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,458) usbip_xmit: Enter
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,496) usbip_xmit: receive

NOTE :-------------------------------- No complition handler called for seq no. 14 URB-------------------------------------

usb-storage: command_abort called
NOTE :--- timeout happened usb mass storage driver abort the mass storage operation and sends unlink urb request.

Pid: 19791, comm: scsi_eh_5 Tainted: G C 2.6.34 #1
Call Trace:

? printk+0xf/0x13

command_abort+0x26/0x9a

scsi_error_handler+0x269/0x4a9

? scsi_error_handler+0x0/0x4a9

kthread+0x61/0x66

? kthread+0x0/0x66

kernel_thread_helper+0x6/0x10
usb-storage: usb_stor_stop_transport called
usb-storage: - cancelling sg request
usbip: vhci_hcd: dequeue a urb ea0a8c80
scsi_eh_5 : ***CLIENT*** (drivers/staging/usbip/vhci_hcd.c,714) vhci_urb_dequeue:
vhci_hcd vhci_hcd: Unlink after no-IRQ? Controller is probably using the wrong IRQ.
usbip: vhci_hcd: device ea0bd124 seems to be still connected
vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,78) vhci_send_cmd_submit:
NOTE :-- vhci sends unlink URB to remote server stub driver

vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,53) dequeue_from_priv_tx:
vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,172) vhci_send_cmd_unlink:
vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,149) dequeue_from_unlink_tx:
vhci_tx : ***CLIENT*** (drivers/staging/usbip/vhci_tx.c,149) dequeue_from_unlink_tx:
stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,323) valid_request:
stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,247) stub_recv_cmd_unlink:
usb 1-5: unlink urb ea0a8400
stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,293) stub_recv_cmd_unlink:
NOTE :calling ---> usb-unlink_urb - server stub driver submits unlink urb to usbcore

stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_event.c,145) usbip_event_happened:
stub_rx : ***SERVER*** (drivers/staging/usbip/stub_rx.c,569) stub_rx_pdu:
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,458) usbip_xmit: Enter
stub_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,496) usbip_xmit: receive
interrupt : ***SERVER*** (drivers/staging/usbip/stub_tx.c,73) stub_complete: complete!

NOTE : status -104 -- comletion handler called unlinking successfull

usbip: unlinked by a call of usb_unlink_urb()
interrupt : ***SERVER*** (drivers/staging/usbip/stub_tx.c,42) stub_enqueue_ret_unlink:
interrupt : ***SERVER*** (drivers/staging/usbip/stub_tx.c,29) stub_free_priv_and_urb:
stub_tx : ***COMMON*** (drivers/staging/usbip/usbip_event.c,145) usbip_event_happened:
stub_tx : ***SERVER*** (drivers/staging/usbip/stub_tx.c,185) stub_send_ret_submit:
stub_tx : ***SERVER*** (drivers/staging/usbip/stub_tx.c,161) dequeue_from_priv_tx:
stub_tx : ***SERVER*** (drivers/staging/usbip/stub_tx.c,293) stub_send_ret_unlink:
stub_tx : ***SERVER*** (drivers/staging/usbip/stub_tx.c,268) dequeue_from_unlink_tx:
stub_tx : ***SERVER*** (drivers/staging/usbip/stub_tx.c,147) setup_ret_unlink_pdu:
stub_tx : ***SERVER*** (drivers/staging/usbip/stub_tx.c,268) dequeue_from_unlink_tx:
vhci_rx :(drivers/staging/usbip/usbip_common.c,324) usbip_dump_header: BASE: cmd 4 seq 15 devid 0 dir 0 ep 0
vhci_rx :(drivers/staging/usbip/usbip_common.c,346) usbip_dump_header: RET_UNLINK: status -104
vhci_rx : ***CLIENT*** (drivers/staging/usbip/vhci_rx.c,158) vhci_recv_ret_unlink: vhci_rx : ***CLIENT*** (drivers/staging/usbip/vhci_rx.c,130) dequeue_pending_unlink:
usbip: unlink->seqnum 15
vhci_rx : ***CLIENT*** (drivers/staging/usbip/vhci_rx.c,34) pickup_urb_and_free_priv:
usbip: -104
vhci_rx : ***COMMON*** (drivers/staging/usbip/usbip_event.c,145) usbip_event_happened:
vhci_rx : ***CLIENT*** (drivers/staging/usbip/vhci_rx.c,204) vhci_rx_pdu: vhci_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,458) usbip_xmit: Enter
vhci_rx : ***COMMON*** (drivers/staging/usbip/usbip_common.c,496) usbip_xmit: receive
usb-storage: Status code -104; transferred 0/36
usb-storage: - transfer cancelled
usb-storage: Bulk data transfer result 0x4
usb-storage: - command was aborted
usb-storage: usb_stor_pre_reset
usb-storage: ***CLIENT*** (drivers/staging/usbip/vhci_hcd.c,271) vhci_hub_control:
usb-storage: ***CLIENT*** (drivers/staging/usbip/vhci_hcd.c,271) vhci_hub_control:
hub 6-0:1.0: port 1 not reset yet, waiting 50ms
usb-storage: ***CLIENT*** (drivers/staging/usbip/vhci_hcd.c,271) vhci_hub_control:
hub 6-0:1.0: port 1 not reset yet, waiting 200ms
usb-storage: ***CLIENT*** (drivers/staging/usbip/vhci_hcd.c,271) vhci_hub_control:
hub 6-0:1.0: port 1 not reset yet, waiting 200ms