On Sat, Aug 25, 2012 at 12:31:46PM +0300, Sami Farin wrote: > On Sat, Aug 25, 2012 at 15:10:13 +0800, Andiry Xu wrote: > ... > > > > > > 3.6.0-rc2-g6dab7ede has some funny printk's , but it panics on network use > > > so I am back to 3.5.0-rc7-g84a1caf: > > > > > > <5>[ 5.163846] scsi 10:0:0:0: bad extra_isize (%u != %u)Direct-Access Generic STORAGE DEVICE TS07 PQ: 0 ANSI: 0 > > > <3>[ 2277.412255] sd 10:0:0:1: 6mpf: %llx > > > > > > > > >> This would seem to indicate another type of bug in the host controller. > > >> Apparently it reported normal completion for a transfer that was > > >> cancelled. > > > > > > Can these be worked around in kernel, or is firmware update needed > > > for asmedia? I have latest BIOS from Asus... > > > > A dmesg with CONFIG_USB_DEBUG and CONFIG_USB_XHCI_HCD_DEBUGGING would > > be helpful. > > these with git/torvalds/linux-2.6.git 2d809dcd88f590 > > I plugged rdf8 reader into usb3 port, mounted it (vfat), > cat garbage > out.bin , at the end ls showed a bit over 252000000 byte file, > then empty dir listing (df showed input/output error). When mounted > with rdf8 reader plugged into usb2 port the dir listing was intact, > like it did not manage to write anything when in usb3.. Hi Sami, I'm back from vacation and I took a look at your log. It seems like your device works fine for a while, and then it doesn't respond to a transfer. The usb-storage driver attempts to reset it, and the Set Address command times out, which causes issues in the xHCI driver. > [ 323.724325] xhci_hcd 0000:03:00.0: Cancel URB ffff8803e5bf8300, dev 1, ep 0x2, starting at offset 0x364565f0 > [ 323.724329] xhci_hcd 0000:03:00.0: // Ding dong! > [ 323.724364] xhci_hcd 0000:03:00.0: Stopped on Transfer TRB > [ 323.724485] xhci_hcd 0000:03:00.0: Removing canceled TD starting at 0x364565f0 (dma). > [ 323.724486] xhci_hcd 0000:03:00.0: Finding segment containing stopped TRB. > [ 323.724488] xhci_hcd 0000:03:00.0: Finding endpoint context > [ 323.724489] xhci_hcd 0000:03:00.0: Finding segment containing last TRB in TD. > [ 323.724490] xhci_hcd 0000:03:00.0: Cycle state = 0x1 > [ 323.724491] xhci_hcd 0000:03:00.0: New dequeue segment = ffff880409d9c280 (virtual) > [ 323.724492] xhci_hcd 0000:03:00.0: New dequeue pointer = 0x36456680 (DMA) > [ 323.724494] xhci_hcd 0000:03:00.0: Set TR Deq Ptr cmd, new deq seg = ffff880409d9c280 (0x36456400 dma), new deq ptr = ffff880036456680 (0x36456680 dma), new cycle = 1 > [ 323.724496] xhci_hcd 0000:03:00.0: // Ding dong! Above, you can see that the USB core is attempting to cancel a transfer (probably because the device failed to respond to it). Then the usb-storage driver asks for a port reset: > [ 323.724524] xhci_hcd 0000:03:00.0: set port reset, actual port 0 status = 0x1311 > [ 323.724547] xhci_hcd 0000:03:00.0: Port Status Change Event for port 1 > [ 323.724640] xhci_hcd 0000:03:00.0: Successful Set TR Deq Ptr cmd, deq = @36456681 > [ 323.775271] xhci_hcd 0000:03:00.0: get port status, actual port 0 status = 0x201203 The port status shows the device is still connected, and the port reset bit is set, meaning the reset is complete. > [ 323.775273] xhci_hcd 0000:03:00.0: Get port status returned 0x100203 > [ 323.826221] xhci_hcd 0000:03:00.0: Resetting device with slot ID 1 > [ 323.826223] xhci_hcd 0000:03:00.0: // Ding dong! > [ 323.826814] xhci_hcd 0000:03:00.0: Completed reset device command. > [ 323.826822] xhci_hcd 0000:03:00.0: Successful reset device command. > [ 323.826823] xhci_hcd 0000:03:00.0: Cached old ring, 1 ring cached > [ 323.826825] xhci_hcd 0000:03:00.0: Cached old ring, 2 rings cached > [ 323.826826] xhci_hcd 0000:03:00.0: Output context after successful reset device cmd: > [ 323.826828] xhci_hcd 0000:03:00.0: Slot Context: > [ 323.826829] xhci_hcd 0000:03:00.0: @ffff880036453000 (virt) @36453000 (dma) 0x20400000 - dev_info > [ 323.826831] xhci_hcd 0000:03:00.0: @ffff880036453004 (virt) @36453004 (dma) 0x010000 - dev_info2 > [ 323.826832] xhci_hcd 0000:03:00.0: @ffff880036453008 (virt) @36453008 (dma) 0x000000 - tt_info > [ 323.826833] xhci_hcd 0000:03:00.0: @ffff88003645300c (virt) @3645300c (dma) 0x8000000 - dev_state > [ 323.826835] xhci_hcd 0000:03:00.0: @ffff880036453010 (virt) @36453010 (dma) 0x000000 - rsvd[0] > [ 323.826836] xhci_hcd 0000:03:00.0: @ffff880036453014 (virt) @36453014 (dma) 0x000000 - rsvd[1] > [ 323.826837] xhci_hcd 0000:03:00.0: @ffff880036453018 (virt) @36453018 (dma) 0x000000 - rsvd[2] > [ 323.826839] xhci_hcd 0000:03:00.0: @ffff88003645301c (virt) @3645301c (dma) 0x000000 - rsvd[3] > [ 323.826840] xhci_hcd 0000:03:00.0: Endpoint 00 Context: > [ 323.826841] xhci_hcd 0000:03:00.0: @ffff880036453020 (virt) @36453020 (dma) 0x000001 - ep_info > [ 323.826843] xhci_hcd 0000:03:00.0: @ffff880036453024 (virt) @36453024 (dma) 0x2000026 - ep_info2 > [ 323.826844] xhci_hcd 0000:03:00.0: @ffff880036453028 (virt) @36453028 (dma) 0x364079e1 - deq > [ 323.826845] xhci_hcd 0000:03:00.0: @ffff880036453030 (virt) @36453030 (dma) 0x000000 - tx_info > [ 323.826847] xhci_hcd 0000:03:00.0: @ffff880036453034 (virt) @36453034 (dma) 0x008004 - rsvd[0] > [ 323.826848] xhci_hcd 0000:03:00.0: @ffff880036453038 (virt) @36453038 (dma) 0x030000 - rsvd[1] > [ 323.826849] xhci_hcd 0000:03:00.0: @ffff88003645303c (virt) @3645303c (dma) 0x000000 - rsvd[2] > [ 323.826850] xhci_hcd 0000:03:00.0: Endpoint 01 Context: > [ 323.826852] xhci_hcd 0000:03:00.0: @ffff880036453040 (virt) @36453040 (dma) 0x000000 - ep_info > [ 323.826853] xhci_hcd 0000:03:00.0: @ffff880036453044 (virt) @36453044 (dma) 0x000000 - ep_info2 > [ 323.826854] xhci_hcd 0000:03:00.0: @ffff880036453048 (virt) @36453048 (dma) 0x000000 - deq > [ 323.826855] xhci_hcd 0000:03:00.0: @ffff880036453050 (virt) @36453050 (dma) 0x000000 - tx_info > [ 323.826857] xhci_hcd 0000:03:00.0: @ffff880036453054 (virt) @36453054 (dma) 0x000000 - rsvd[0] > [ 323.826858] xhci_hcd 0000:03:00.0: @ffff880036453058 (virt) @36453058 (dma) 0x000000 - rsvd[1] > [ 323.826859] xhci_hcd 0000:03:00.0: @ffff88003645305c (virt) @3645305c (dma) 0x000000 - rsvd[2] > [ 323.826860] xhci_hcd 0000:03:00.0: Endpoint 02 Context: > [ 323.826861] xhci_hcd 0000:03:00.0: @ffff880036453060 (virt) @36453060 (dma) 0x000000 - ep_info > [ 323.826863] xhci_hcd 0000:03:00.0: @ffff880036453064 (virt) @36453064 (dma) 0x4000436 - ep_info2 > [ 323.826864] xhci_hcd 0000:03:00.0: @ffff880036453068 (virt) @36453068 (dma) 0x364556e1 - deq > [ 323.826865] xhci_hcd 0000:03:00.0: @ffff880036453070 (virt) @36453070 (dma) 0x000000 - tx_info > [ 323.826867] xhci_hcd 0000:03:00.0: @ffff880036453074 (virt) @36453074 (dma) 0x000016 - rsvd[0] > [ 323.826868] xhci_hcd 0000:03:00.0: @ffff880036453078 (virt) @36453078 (dma) 0x030000 - rsvd[1] > [ 323.826869] xhci_hcd 0000:03:00.0: @ffff88003645307c (virt) @3645307c (dma) 0x000000 - rsvd[2] > [ 323.826870] xhci_hcd 0000:03:00.0: Endpoint 03 Context: > [ 323.826871] xhci_hcd 0000:03:00.0: @ffff880036453080 (virt) @36453080 (dma) 0x000000 - ep_info > [ 323.826873] xhci_hcd 0000:03:00.0: @ffff880036453084 (virt) @36453084 (dma) 0x4000416 - ep_info2 > [ 323.826874] xhci_hcd 0000:03:00.0: @ffff880036453088 (virt) @36453088 (dma) 0x36456681 - deq > [ 323.826875] xhci_hcd 0000:03:00.0: @ffff880036453090 (virt) @36453090 (dma) 0x000000 - tx_info > [ 323.826876] xhci_hcd 0000:03:00.0: @ffff880036453094 (virt) @36453094 (dma) 0x00001c - rsvd[0] > [ 323.826878] xhci_hcd 0000:03:00.0: @ffff880036453098 (virt) @36453098 (dma) 0x030000 - rsvd[1] > [ 323.826879] xhci_hcd 0000:03:00.0: @ffff88003645309c (virt) @3645309c (dma) 0x000000 - rsvd[2] > [ 323.826886] xhci_hcd 0000:03:00.0: clear port reset change, actual port 0 status = 0x1203 Then the USB core attempts to send a Set Address command to the device, since the old address was lost during the reset: > [ 323.826890] xhci_hcd 0000:03:00.0: Slot ID 1 Input Context: > [ 323.826891] xhci_hcd 0000:03:00.0: @ffff880036454000 (virt) @36454000 (dma) 0x000000 - drop flags > [ 323.826893] xhci_hcd 0000:03:00.0: @ffff880036454004 (virt) @36454004 (dma) 0x000003 - add flags > [ 323.826894] xhci_hcd 0000:03:00.0: @ffff880036454008 (virt) @36454008 (dma) 0x000000 - rsvd2[0] > [ 323.826895] xhci_hcd 0000:03:00.0: @ffff88003645400c (virt) @3645400c (dma) 0x000000 - rsvd2[1] > [ 323.826897] xhci_hcd 0000:03:00.0: @ffff880036454010 (virt) @36454010 (dma) 0x000000 - rsvd2[2] > [ 323.826898] xhci_hcd 0000:03:00.0: @ffff880036454014 (virt) @36454014 (dma) 0x000000 - rsvd2[3] > [ 323.826899] xhci_hcd 0000:03:00.0: @ffff880036454018 (virt) @36454018 (dma) 0x000000 - rsvd2[4] > [ 323.826901] xhci_hcd 0000:03:00.0: @ffff88003645401c (virt) @3645401c (dma) 0x000000 - rsvd2[5] > [ 323.826902] xhci_hcd 0000:03:00.0: Slot Context: > [ 323.826903] xhci_hcd 0000:03:00.0: @ffff880036454020 (virt) @36454020 (dma) 0x8400000 - dev_info > [ 323.826904] xhci_hcd 0000:03:00.0: @ffff880036454024 (virt) @36454024 (dma) 0x010000 - dev_info2 > [ 323.826905] xhci_hcd 0000:03:00.0: @ffff880036454028 (virt) @36454028 (dma) 0x000000 - tt_info > [ 323.826907] xhci_hcd 0000:03:00.0: @ffff88003645402c (virt) @3645402c (dma) 0x000000 - dev_state > [ 323.826908] xhci_hcd 0000:03:00.0: @ffff880036454030 (virt) @36454030 (dma) 0x000000 - rsvd[0] > [ 323.826909] xhci_hcd 0000:03:00.0: @ffff880036454034 (virt) @36454034 (dma) 0x000000 - rsvd[1] > [ 323.826911] xhci_hcd 0000:03:00.0: @ffff880036454038 (virt) @36454038 (dma) 0x000000 - rsvd[2] > [ 323.826912] xhci_hcd 0000:03:00.0: @ffff88003645403c (virt) @3645403c (dma) 0x000000 - rsvd[3] > [ 323.826913] xhci_hcd 0000:03:00.0: Endpoint 00 Context: > [ 323.826914] xhci_hcd 0000:03:00.0: @ffff880036454040 (virt) @36454040 (dma) 0x000000 - ep_info > [ 323.826915] xhci_hcd 0000:03:00.0: @ffff880036454044 (virt) @36454044 (dma) 0x2000026 - ep_info2 > [ 323.826917] xhci_hcd 0000:03:00.0: @ffff880036454048 (virt) @36454048 (dma) 0x36407ab1 - deq > [ 323.826918] xhci_hcd 0000:03:00.0: @ffff880036454050 (virt) @36454050 (dma) 0x000000 - tx_info > [ 323.826919] xhci_hcd 0000:03:00.0: @ffff880036454054 (virt) @36454054 (dma) 0x000000 - rsvd[0] > [ 323.826920] xhci_hcd 0000:03:00.0: @ffff880036454058 (virt) @36454058 (dma) 0x000000 - rsvd[1] > [ 323.826922] xhci_hcd 0000:03:00.0: @ffff88003645405c (virt) @3645405c (dma) 0x000000 - rsvd[2] > [ 323.826923] xhci_hcd 0000:03:00.0: Endpoint 01 Context: > [ 323.826924] xhci_hcd 0000:03:00.0: @ffff880036454060 (virt) @36454060 (dma) 0x000000 - ep_info > [ 323.826925] xhci_hcd 0000:03:00.0: @ffff880036454064 (virt) @36454064 (dma) 0x000000 - ep_info2 > [ 323.826926] xhci_hcd 0000:03:00.0: @ffff880036454068 (virt) @36454068 (dma) 0x000000 - deq > [ 323.826928] xhci_hcd 0000:03:00.0: @ffff880036454070 (virt) @36454070 (dma) 0x000000 - tx_info > [ 323.826929] xhci_hcd 0000:03:00.0: @ffff880036454074 (virt) @36454074 (dma) 0x000000 - rsvd[0] > [ 323.826930] xhci_hcd 0000:03:00.0: @ffff880036454078 (virt) @36454078 (dma) 0x000000 - rsvd[1] > [ 323.826932] xhci_hcd 0000:03:00.0: @ffff88003645407c (virt) @3645407c (dma) 0x000000 - rsvd[2] > [ 323.826933] xhci_hcd 0000:03:00.0: Endpoint 02 Context: > [ 323.826934] xhci_hcd 0000:03:00.0: @ffff880036454080 (virt) @36454080 (dma) 0x000000 - ep_info > [ 323.826935] xhci_hcd 0000:03:00.0: @ffff880036454084 (virt) @36454084 (dma) 0x000000 - ep_info2 > [ 323.826936] xhci_hcd 0000:03:00.0: @ffff880036454088 (virt) @36454088 (dma) 0x000000 - deq > [ 323.826938] xhci_hcd 0000:03:00.0: @ffff880036454090 (virt) @36454090 (dma) 0x000000 - tx_info > [ 323.826939] xhci_hcd 0000:03:00.0: @ffff880036454094 (virt) @36454094 (dma) 0x000000 - rsvd[0] > [ 323.826940] xhci_hcd 0000:03:00.0: @ffff880036454098 (virt) @36454098 (dma) 0x000000 - rsvd[1] > [ 323.826941] xhci_hcd 0000:03:00.0: @ffff88003645409c (virt) @3645409c (dma) 0x000000 - rsvd[2] > [ 323.826943] xhci_hcd 0000:03:00.0: // Ding dong! > [ 328.020880] usb 4-1: Device not responding to set address. ... > [ 332.614921] usb 4-1: device not accepting address 2, error -71 But the device doesn't respond to the set address command, and the USB core and xHCI driver are out-of-sync WRT the xHCI hardware state. This causes a couple rounds of attempting to reset the device, and the xHCI host refusing to reset the device because it's in the UnAddressed state: > [ 332.614934] xhci_hcd 0000:03:00.0: set port reset, actual port 0 status = 0x1311 > [ 332.614956] xhci_hcd 0000:03:00.0: Port Status Change Event for port 1 > [ 332.665880] xhci_hcd 0000:03:00.0: get port status, actual port 0 status = 0x201203 > [ 332.665882] xhci_hcd 0000:03:00.0: Get port status returned 0x100203 > [ 332.716828] xhci_hcd 0000:03:00.0: Resetting device with slot ID 1 > [ 332.716831] xhci_hcd 0000:03:00.0: // Ding dong! > [ 332.716860] xhci_hcd 0000:03:00.0: Completed reset device command. > [ 332.716868] xhci_hcd 0000:03:00.0: Can't reset device (slot ID 1) in default state At this point, the old Set Address command is still sitting on the command ring, and no new commands will work. The Set Address commands continue to timeout and be left on the command ring. > [ 336.910912] usb 4-1: Device not responding to set address. > [ 341.505526] usb 4-1: device not accepting address 2, error -71 > [ 341.505538] xhci_hcd 0000:03:00.0: set port reset, actual port 0 status = 0x1311 > [ 341.607469] xhci_hcd 0000:03:00.0: Can't reset device (slot ID 1) in default state > [ 345.801512] usb 4-1: Device not responding to set address. > [ 350.396130] usb 4-1: device not accepting address 2, error -71 > [ 350.396143] xhci_hcd 0000:03:00.0: set port reset, actual port 0 status = 0x1311 > [ 350.498078] xhci_hcd 0000:03:00.0: Can't reset device (slot ID 1) in default state > [ 354.692124] usb 4-1: Device not responding to set address. > [ 359.286736] usb 4-1: device not accepting address 2, error -71 And finally the USB core gives up on the device, and issues a logical disconnect, which basically removes your hard drive from the SCSI subsystem: > [ 359.286739] hub 4-0:1.0: logical disconnect on port 1 > [ 359.286748] hub 4-0:1.0: state 7 ports 2 chg 0002 evt 0000 > [ 359.286757] xhci_hcd 0000:03:00.0: get port status, actual port 0 status = 0x1203 > [ 359.286760] xhci_hcd 0000:03:00.0: Get port status returned 0x203 > [ 359.286765] hub 4-0:1.0: port 1, status 0203, change 0000, 5.0 Gb/s > [ 359.286767] usb 4-1: USB disconnect, device number 2 > [ 359.286769] usb 4-1: unregistering device > [ 359.286771] usb 4-1: unregistering interface 4-1:1.0 > [ 359.286823] sd 11:0:0:1: Device offlined - not ready after error recovery >From there, all attempts to access the drive fail. There are patches to abort the timed-out Set Address command, and I think they might fix your issue. I have them queued up for 3.7, and marked for stable, because I think they're a bit big to be going into 3.6 this late in the -rc cycle. Can you try these patches and see if it fixes your issues? You can find them on my for-usb-next branch: git clone git://git.kernel.org/pub/scm/linux/kernel/git/sarah/xhci.git -b for-usb-next If you prefer to stay on 3.5 because of your wifi issues, you can checkout those patches on top of 3.5 with this command: git clone git://git.kernel.org/pub/scm/linux/kernel/git/sarah/xhci.git -b 3.5-plus-set-addr Sarah Sharp -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
