USB problems with 8.2

[Момчил Иванов]

At Tue, 27 Dec 2011 15:51:10 +0100,
Hans Petter Selasky wrote:
> Hi,
> 
> If you compile a kernel with "options USB_DEBUG". Then when the problem 
> appears, you enable umass debugging:
> 
> sysctl hw.usb.umass.debug=15
> 
> OR:
> 
> Check activity with usbdump upon failure:
> 
> usbdump -i usbusX -vvv > log.txt
> 
> 
> cat log.txt | grep USB_ERR
> 
> Some USB HDDs might have firmware failures. Most USB HDD enclosures are not 
> 100% hardware and usually contains a small CPU to do USB.

Hi,

I took the second option, since I didn't want to recompile the kernel. I've run "usbdump -i usbus6 -vvv" and there are no USB_ERR whatsoever, it shows nothing during the stall. Here are some dumps around some time holes:


16:11:16.007239 usbus6.2 DONE-BULK-EP=00000081,SPD=HIGH,NFR=1,SLEN=16,IVAL=0,ERR=0
 frame[0] READ 13 bytes
 0000  55 53 42 53 13 FC 01 00  00 00 00 00 00 -- -- --  |USBS.........   |
 flags 0x2 <SHORT_XFER_OK|0>
 status 0xeb021 <OPEN|STARTED|SHORT_XFER_OK|BDMA_ENABLE|BDMA_SETUP|CURR_DMA_SET|CAN_CANCEL_IMMED|DOING_CALLBACK|0>
16:11:16.037357 usbus6.2 SUBM-BULK-EP=00000002,SPD=HIGH,NFR=1,SLEN=32,IVAL=0
 frame[0] WRITE 31 bytes
 0000  55 53 42 43 14 FC 01 00  00 90 00 00 80 00 0A 28  |USBC...........(|
 0010  00 19 4E E3 C0 00 00 48  00 A0 B0 00 00 00 00 --  |..N....H....... |
 flags 0 <0>
 status 0xca023 <OPEN|TRANSFERRING|STARTED|BDMA_ENABLE|BDMA_SETUP|CAN_CANCEL_IMMED|DOING_CALLBACK|0>
16:11:16.037492 usbus6.2 DONE-BULK-EP=00000002,SPD=HIGH,NFR=1,SLEN=0,IVAL=0,ERR=0
 frame[0] WRITE 31 bytes
 flags 0 <0>
 status 0xea021 <OPEN|STARTED|BDMA_ENABLE|BDMA_SETUP|CURR_DMA_SET|CAN_CANCEL_IMMED|DOING_CALLBACK|0>
16:11:16.037495 usbus6.2 SUBM-BULK-EP=00000081,SPD=HIGH,NFR=1,SLEN=0,IVAL=0
 frame[0] READ 36864 bytes
 flags 0x32 <SHORT_XFER_OK|PROXY_BUFFER|EXT_BUFFER|0>
 status 0xcb023 <OPEN|TRANSFERRING|STARTED|SHORT_XFER_OK|BDMA_ENABLE|BDMA_SETUP|CAN_CANCEL_IMMED|DOING_CALLBACK|0>

*** time hole ***

16:12:19.574864 usbus6.2 DONE-BULK-EP=00000081,SPD=HIGH,NFR=0,SLEN=0,IVAL=0,ERR=TIMEOUT
 flags 0x32 <SHORT_XFER_OK|PROXY_BUFFER|EXT_BUFFER|0>
 status 0xab025 <OPEN|DID_DMA_DELAY|STARTED|SHORT_XFER_OK|BDMA_ENABLE|BDMA_SETUP|CURR_DMA_SET|DOING_CALLBACK|0>
16:12:19.574880 usbus6.2 SUBM-CTRL-EP=00000000,SPD=HIGH,NFR=1,SLEN=8,IVAL=0
 frame[0] WRITE 8 bytes
 0000  02 01 00 00 81 00 00 00  -- -- -- -- -- -- -- --  |........        |
 flags 0 <0>
 status 0xea1a3 <OPEN|TRANSFERRING|STARTED|CONTROL_XFR|CONTROL_HDR|BDMA_ENABLE|BDMA_SETUP|CURR_DMA_SET|CAN_CANCEL_IMMED|DOING_CALLBACK|0>
16:12:19.575006 usbus6.2 DONE-CTRL-EP=00000000,SPD=HIGH,NFR=1,SLEN=0,IVAL=0,ERR=0
 frame[0] WRITE 8 bytes
 flags 0 <0>
 status 0xca1a1 <OPEN|STARTED|CONTROL_XFR|CONTROL_HDR|BDMA_ENABLE|BDMA_SETUP|CAN_CANCEL_IMMED|DOING_CALLBACK|0>
16:12:19.575010 usbus6.2 SUBM-BULK-EP=00000081,SPD=HIGH,NFR=1,SLEN=0,IVAL=0
 frame[0] READ 13 bytes
 flags 0x2 <SHORT_XFER_OK|0>
 status 0xeb023 <OPEN|TRANSFERRING|STARTED|SHORT_XFER_OK|BDMA_ENABLE|BDMA_SETUP|CURR_DMA_SET|CAN_CANCEL_IMMED|DOING_CALLBACK|0>


.....


16:12:23.942561 usbus6.2 SUBM-BULK-EP=00000081,SPD=HIGH,NFR=1,SLEN=0,IVAL=0
 frame[0] READ 13 bytes
 flags 0x2 <SHORT_XFER_OK|0>
 status 0xcb023 <OPEN|TRANSFERRING|STARTED|SHORT_XFER_OK|BDMA_ENABLE|BDMA_SETUP|CAN_CANCEL_IMMED|DOING_CALLBACK|0>
16:12:23.942620 usbus6.2 DONE-BULK-EP=00000081,SPD=HIGH,NFR=1,SLEN=16,IVAL=0,ERR=0
 frame[0] READ 13 bytes
 0000  55 53 42 53 AD FF 01 00  00 00 00 00 00 -- -- --  |USBS.........   |
 flags 0x2 <SHORT_XFER_OK|0>
 status 0xeb021 <OPEN|STARTED|SHORT_XFER_OK|BDMA_ENABLE|BDMA_SETUP|CURR_DMA_SET|CAN_CANCEL_IMMED|DOING_CALLBACK|0>
16:12:23.971480 usbus6.2 SUBM-BULK-EP=00000002,SPD=HIGH,NFR=1,SLEN=32,IVAL=0
 frame[0] WRITE 31 bytes
 0000  55 53 42 43 AE FF 01 00  00 90 00 00 80 00 0A 28  |USBC...........(|
 0010  00 09 92 D7 E0 00 00 48  00 A0 B0 00 00 00 00 --  |.......H....... |
 flags 0 <0>
 status 0xca023 <OPEN|TRANSFERRING|STARTED|BDMA_ENABLE|BDMA_SETUP|CAN_CANCEL_IMMED|DOING_CALLBACK|0>
16:12:23.971634 usbus6.2 DONE-BULK-EP=00000002,SPD=HIGH,NFR=1,SLEN=0,IVAL=0,ERR=0
 frame[0] WRITE 31 bytes
 flags 0 <0>
 status 0xea021 <OPEN|STARTED|BDMA_ENABLE|BDMA_SETUP|CURR_DMA_SET|CAN_CANCEL_IMMED|DOING_CALLBACK|0>
16:12:23.971639 usbus6.2 SUBM-BULK-EP=00000081,SPD=HIGH,NFR=1,SLEN=0,IVAL=0
 frame[0] READ 36864 bytes
 flags 0x32 <SHORT_XFER_OK|PROXY_BUFFER|EXT_BUFFER|0>
 status 0xcb023 <OPEN|TRANSFERRING|STARTED|SHORT_XFER_OK|BDMA_ENABLE|BDMA_SETUP|CAN_CANCEL_IMMED|DOING_CALLBACK|0>

*** time hole ***

16:13:27.509643 usbus6.2 DONE-BULK-EP=00000081,SPD=HIGH,NFR=0,SLEN=0,IVAL=0,ERR=TIMEOUT
 flags 0x32 <SHORT_XFER_OK|PROXY_BUFFER|EXT_BUFFER|0>
 status 0xab025 <OPEN|DID_DMA_DELAY|STARTED|SHORT_XFER_OK|BDMA_ENABLE|BDMA_SETUP|CURR_DMA_SET|DOING_CALLBACK|0>
16:13:27.509660 usbus6.2 SUBM-CTRL-EP=00000000,SPD=HIGH,NFR=1,SLEN=8,IVAL=0
 frame[0] WRITE 8 bytes
 0000  02 01 00 00 81 00 00 00  -- -- -- -- -- -- -- --  |........        |
 flags 0 <0>
 status 0xca1a3 <OPEN|TRANSFERRING|STARTED|CONTROL_XFR|CONTROL_HDR|BDMA_ENABLE|BDMA_SETUP|CAN_CANCEL_IMMED|DOING_CALLBACK|0>
16:13:27.509764 usbus6.2 DONE-CTRL-EP=00000000,SPD=HIGH,NFR=1,SLEN=0,IVAL=0,ERR=0
 frame[0] WRITE 8 bytes
 flags 0 <0>
 status 0xea1a1 <OPEN|STARTED|CONTROL_XFR|CONTROL_HDR|BDMA_ENABLE|BDMA_SETUP|CURR_DMA_SET|CAN_CANCEL_IMMED|DOING_CALLBACK|0>