On Sun, Jun 12, 2011 at 01:10:35PM +0300, Tanya Brokhman wrote: > Hi Sarah, > > Sorry it took me some time to test this, I was working on the SS support > patches that finally got excepted :) Yay! :) > I ran the test with the patch below. The device hangs so I can't say that > the whole "change configuration" procedure is working. I went over the dmesg > log on the host side and saw something strange: > > The full log is attached. > What do you think could have happened here? I didn't manage to retrieve any > logs from the device so I have no idea what happened there. My next move is > to record the USB traffic but I doubt it will show anything useful... Well, it at least shows that the set configuration command didn't cause an oops, so my patches are working. :) But yeah, there are a lot of odd things in the log. > [ 794.101782] xhci_hcd 0000:01:00.0: add ep 0x81, slot id 1, new drop flags = 0x0, new add flags = 0x8, new slot info = 0x18400000 > [ 794.101804] xhci_hcd 0000:01:00.0: add ep 0x1, slot id 1, new drop flags = 0x0, new add flags = 0xc, new slot info = 0x18400000 > [ 794.101826] xhci_hcd 0000:01:00.0: add ep 0x82, slot id 1, new drop flags = 0x0, new add flags = 0x2c, new slot info = 0x28400000 > [ 794.101850] xhci_hcd 0000:01:00.0: add ep 0x2, slot id 1, new drop flags = 0x0, new add flags = 0x3c, new slot info = 0x28400000 ... > [ 794.102933] usb 10-1: adding 10-1:2.0 (config #2, interface 0) The second configuration was successfully added, no crashes this time. BTW, why do you want to have your UAS interface on a separate configuration instead of an alternate interface setting? I'm not sure if the USB core driver matching code will look beyond the first configuration for a driver. Alan, do you know if it does? > [ 794.102969] libusual 10-1:2.0: usb_probe_interface > [ 794.102972] libusual 10-1:2.0: usb_probe_interface - got id > [ 794.103011] uas 10-1:2.0: usb_probe_interface > [ 794.103013] uas 10-1:2.0: usb_probe_interface - got id So the UAS driver was bound to the interface, even through the libusual probe function was called first. > [ 794.104920] Initializing USB Mass Storage driver... I'm not sure what happened here. This is clearly from the BoT driver, but I'm not sure why it would start initializing. > [ 794.106383] scsi8 : uas > [ 794.106440] xhci_hcd 0000:01:00.0: Driver wants 257 stream IDs (including stream 0). > [ 794.106448] xhci_hcd 0000:01:00.0: xHCI HW only supports 32 stream ctx entries. But the UAS driver seems to be loading fine and switching the device endpoints over to streams operation. > [ 794.106451] xhci_hcd 0000:01:00.0: Need 32 stream ctx entries for 32 stream IDs. ... > [ 794.108317] xhci_hcd 0000:01:00.0: Setting number of stream ctx array entries to 32 > [ 794.108319] xhci_hcd 0000:01:00.0: Setting number of stream ctx array entries to 32 > [ 794.108322] xhci_hcd 0000:01:00.0: Setting number of stream ctx array entries to 32 > [ 794.108325] xhci_hcd 0000:01:00.0: Input Context: > [ 794.108328] xhci_hcd 0000:01:00.0: @ffff8800c1838000 (virt) @c1838000 (dma) 0x00002c - drop flags > [ 794.108331] xhci_hcd 0000:01:00.0: @ffff8800c1838004 (virt) @c1838004 (dma) 0x00002d - add flags > [ 794.109247] usb 10-1: Successful Endpoint Configure command > [ 794.109251] xhci_hcd 0000:01:00.0: Slot 1 ep ctx 4 now has streams. > [ 794.109253] xhci_hcd 0000:01:00.0: Slot 1 ep ctx 2 now has streams. > [ 794.109256] xhci_hcd 0000:01:00.0: Slot 1 ep ctx 1 now has streams. It looks like the UAS driver is trying to set up streams for endpoints 0x1, 0x81, and 0x82. According to your lsusb output and the UAS spec (and I may have an outdated copy), that means it's setting up streams for: 0x1 - Data out pipe 0x81 - Data in pipe 0x82 - status pipe Does it also need to set up streams for the command pipe? > [ 794.110050] USB Mass Storage support registered. More output from the BoT driver... > [ 794.113726] xhci_hcd 0000:01:00.0: ep 0x82 - urb len = 0x70 (112), addr = 0x12176c500, num_trbs = 1 > [ 794.113762] xhci_hcd 0000:01:00.0: Ring enq = 0xc1821810 (DMA) > [ 794.113770] xhci_hcd 0000:01:00.0: ep 0x2 - urb len = 0x20 (32), addr = 0x378e83a0, num_trbs = 1 > [ 794.113775] xhci_hcd 0000:01:00.0: Ring enq = 0xc18d4010 (DMA) So the driver submits a transfer to endpoint 0x82 and 0x2. The ring enqueue pointers indicate the 0x82 URB was submitted for stream 1. Endpoint 0x2 has no streams, so the URB is submitted to the only ring segment it has. > [ 794.113786] xhci_hcd 0000:01:00.0: Event ring dequeue ptr: > [ 794.113789] xhci_hcd 0000:01:00.0: @3781b480 00000000 00000000 04000000 01058000 > [ 794.113792] xhci_hcd 0000:01:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc9000064c024, 32'h8, 4'hf); > [ 794.113794] xhci_hcd 0000:01:00.0: In xhci_handle_event > [ 794.113797] xhci_hcd 0000:01:00.0: xhci_handle_event - OS owns TRB > [ 794.113799] xhci_hcd 0000:01:00.0: xhci_handle_event - calling handle_tx_event > [ 794.113802] xhci_hcd 0000:01:00.0: handle_tx_event - ep index = 4 > [ 794.113805] xhci_hcd 0000:01:00.0: ERROR Transfer event for disabled endpoint or incorrect stream ring The transfer event we get back from the host controller is very odd. The slot ID is 1 (your UAS device) and the endpoint ID is 5, which maps to endpoint 0x82. The completion code is 4, which is a USB transaction error. The TRB pointer is 0x0, which is obviously bogus. So something very strange is happening to the xHCI host controller. It's no wonder the xHCI driver gives up and says the event is for an incorrect stream ring. > [ 794.113808] xhci_hcd 0000:01:00.0: xhci_handle_event - returned from handle_tx_event > [ 794.113811] xhci_hcd 0000:01:00.0: Event ring deq = 0x3781b490 (DMA) > [ 794.113821] xhci_hcd 0000:01:00.0: handle_tx_event - ep index = 2 > [ 794.113823] xhci_hcd 0000:01:00.0: ERROR Transfer event for disabled endpoint or incorrect stream ring I can't tell what event was given back here, but there's polling loop output further on in the log. > [ 794.113829] xhci_hcd 0000:01:00.0: Event ring deq = 0x3781b4a0 (DMA) > [ 794.113838] xhci_hcd 0000:01:00.0: handle_tx_event - ep index = 3 > [ 794.113840] xhci_hcd 0000:01:00.0: WARN: transfer error on endpoint > [ 794.113844] xhci_hcd 0000:01:00.0: ep 0x2 - asked for 32 bytes, 32 bytes untransferred The URB for endpoint 0x2 was completed, also with a USB transaction error. Have you used a USB bus analyzer to look at what's actually going over the wire? The xHCI driver has to clean up the endpoint ring, because the driver only issues a reset endpoint command when the endpoint stalls. > [ 794.113852] xhci_hcd 0000:01:00.0: Cleaning up stalled endpoint ring > [ 794.113871] xhci_hcd 0000:01:00.0: Set TR Deq Ptr cmd, new deq seg = ffff880037bc3540 (0xc18d4000 dma), new deq ptr = ffff8800c18d4010 (0xc18d4010 dma), new cycle = 1 ... > [ 794.113975] xhci_hcd 0000:01:00.0: Ignoring reset ep completion code of 1 > [ 794.114030] xhci_hcd 0000:01:00.0: Successful Set TR Deq Ptr cmd, deq = @c18d4011 Lots of uninteresting suspends and resumes of the roothub... > [ 815.120017] scsi 8:0:0:0: uas_eh_abort_handler tag -1 > [ 815.120023] scsi 8:0:0:0: uas_eh_device_reset_handler tag -1 > [ 815.120026] scsi 8:0:0:0: uas_eh_target_reset_handler tag -1 > [ 815.120029] scsi 8:0:0:0: uas_eh_bus_reset_handler tag -1 And finally the SCSI layer times out and tries to reset the device. > [ 815.120045] xhci_hcd 0000:01:00.0: set port reset, actual port 0 status = 0x1311 ... > [ 815.240451] xhci_hcd 0000:01:00.0: Successful reset device command. The stream rings are then freed, since the device was reset. The device is going to operate at configuration 1 now, so the UAS driver really should call usb_set_configuration() in its post-reset method to get the device back into the correct config and re-set up the stream rings. > [ 815.241411] xhci_hcd 0000:01:00.0: Slot ID 1 Input Context: > [ 815.241414] xhci_hcd 0000:01:00.0: @ffff880037949000 (virt) @37949000 (dma) 0x000000 - drop flags > [ 815.241417] xhci_hcd 0000:01:00.0: @ffff880037949004 (virt) @37949004 (dma) 0x000000 - add flags ... > [ 815.241538] xhci_hcd 0000:01:00.0: Command ring enq = 0x3781b390 (DMA) > [ 815.241540] xhci_hcd 0000:01:00.0: // Ding dong! > [ 815.241543] xhci_hcd 0000:01:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc9000064c800, 32'h0, 4'hf); Hey, here's an event ring poll, so we can see what that second bogus event was. > [ 853.920021] xhci_hcd 0000:01:00.0: Event ring: ... > [ 853.920047] xhci_hcd 0000:01:00.0: @000000003781b470 3781b340 00000000 01000000 01008400 > [ 853.920050] xhci_hcd 0000:01:00.0: @000000003781b480 00000000 00000000 04000000 01058000 > [ 853.920053] xhci_hcd 0000:01:00.0: @000000003781b490 00000000 00000000 04000000 01038000 Looks like the second command also had a bogus TRB pointer. > [ 853.920056] xhci_hcd 0000:01:00.0: @000000003781b4a0 c18d4000 00000000 04000020 01048000 > [ 853.920059] xhci_hcd 0000:01:00.0: @000000003781b4b0 3781b350 00000000 01000000 01008400 > [ 853.920062] xhci_hcd 0000:01:00.0: @000000003781b4c0 3781b360 00000000 01000000 01008400 > [ 853.920065] xhci_hcd 0000:01:00.0: @000000003781b4d0 01000000 00000000 01000000 00008800 > [ 853.920068] xhci_hcd 0000:01:00.0: @000000003781b4e0 3781b370 00000000 01000000 01008400 We can also see what command the xHCI host controller had queued: > [ 853.920238] xhci_hcd 0000:01:00.0: Command ring: ... > [ 853.920408] xhci_hcd 0000:01:00.0: @000000003781b370 00000000 00000000 00000000 01004401 > [ 853.920411] xhci_hcd 0000:01:00.0: @000000003781b380 37949000 00000000 00000000 01002c01 The TRB type is 0x1011, or 11, which is an address device command, not an Enable Slot command, as the following snippet suggests: > [ 863.243687] xhci_hcd 0000:01:00.0: Port Status Change Event for port 1 > [ 863.243691] xhci_hcd 0000:01:00.0: Event ring deq = 0x3781b500 (DMA) > [ 863.243701] xhci_hcd 0000:01:00.0: xhci_handle_event - returned from handle_port_status > [ 863.243703] xhci_hcd 0000:01:00.0: In xhci_handle_event > [ 863.243708] xhci_hcd 0000:01:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc9000064c638, 64'h3781b508, 4'hf); > [ 863.243716] hub 10-0:1.0: state 7 ports 2 chg 0000 evt 0002 > [ 865.240011] xhci_hcd 0000:01:00.0: Timeout while waiting for a slot But the address device command timed out, which either indicates an issue with the host controller, or maybe your device just didn't respond to the control transfer? That would jive with your device being hung. In short, I'd recommend hooking up a bus analyzer and seeing what's actually going on. Your host is exhibiting very odd behavior to the software stack, and it's not clear why. 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
