USB mass storage Problem

Help
2010-07-25
2013-05-30
  • singhamit235
    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