On Sun, Jun 05, 2011 at 03:55:09PM +0300, Tanya Brokhman wrote: > Hi Sarah > > I'm testing our UAS gadget driver at the moment and I encountered an issue > with the host I was hoping you could assist me with. > Our device registers with 2 configurations: in the first configuration MS > operates according to BOT protocol and in the second configuration it > operates according to UAS protocol. Of course when it's connected to the > host the first (BOT) configuration is chosen. > I'm trying to switch to the second configuration using sysfs (by writing to > bConfigurationValue in /sys/bus/usb/devices/10-1/). Oh, interesting, I wasn't aware users could do that. > This fails because the > endpoints aren't disabled properly. In dmesg I saw the following error from > xhci_configure_endpoint_result(): > "ERROR: Endpoint drop flag = 0, add flag = 1, and endpoint is not > disabled" > This is because the command_status is COMP_TRB_ERR. > Attached is the full dmesg with CONFIG_USB_XHCI_HCD_DEBUGGING turned on. > > Do you have any ideas what might cause this? Let's take a look at the log: ... > [ 65.670139] xhci_hcd 0000:01:00.0: Slot ID 1 Input Context: > [ 65.670142] xhci_hcd 0000:01:00.0: @ffff8800c5090000 (virt) @c5090000 (dma) 0x000000 - drop flags > [ 65.670146] xhci_hcd 0000:01:00.0: @ffff8800c5090004 (virt) @c5090004 (dma) 0x000003 - add flags Adding control endpoint 0. > [ 65.694680] xhci_hcd 0000:01:00.0: Wrote link toggle flag to segment ffff880122acc460 (virtual), 0xc5021000 (DMA) > [ 65.694683] xhci_hcd 0000:01:00.0: WARN no SS endpoint bMaxBurst Do you have a SuperSpeed Endpoint Companion descriptor for all your endpoints? Because this message seems to indicate you don't. Can you send me the lsusb -vvv for your device? > [ 65.694686] xhci_hcd 0000:01:00.0: add ep 0x81, slot id 1, new drop flags = 0x0, new add flags = 0x8, new slot info = 0x18400000 > [ 65.694708] xhci_hcd 0000:01:00.0: add ep 0x1, slot id 1, new drop flags = 0x0, new add flags = 0xc, new slot info = 0x18400000 Adding endpoints 0x81 and 0x01. > [ 66.825383] usb-storage: Command MODE_SENSE (6 bytes) > [ 66.825385] usb-storage: 1a 00 3f 00 c0 00 > [ 66.825391] usb-storage: Bulk Command S 0x43425355 T 0x7 L 192 F 128 Trg 0 LUN 0 CL 6 > [ 66.825393] usb-storage: usb_stor_bulk_transfer_buf: xfer 31 bytes ... > [ 66.825465] usb-storage: Status code 0; transferred 31/31 > [ 66.825466] usb-storage: -- transfer complete > [ 66.825468] usb-storage: Bulk command transfer result=0 > [ 66.825470] usb-storage: usb_stor_bulk_transfer_sglist: xfer 192 bytes, 1 entries ... > [ 66.825577] usb-storage: Status code -121; transferred 16/192 > [ 66.825578] usb-storage: -- short read transfer > [ 66.825580] usb-storage: Bulk data transfer result 0x1 > [ 66.825582] usb-storage: Attempting to get CSW... > [ 66.825584] usb-storage: usb_stor_bulk_transfer_buf: xfer 13 bytes ... > [ 97.040026] usb-storage: command_abort called > [ 97.040029] usb-storage: usb_stor_stop_transport called > [ 97.040031] usb-storage: -- cancelling URB > [ 97.040037] xhci_hcd 0000:01:00.0: Cancel URB ffff880122a1cb40 Your device ignored the Status phase of the Mode Sense command after issuing a short read on the Data phase, which isn't related to your current problem, but it's something you might want to look into. > [ 97.040581] usb-storage: Status code -104; transferred 0/13 > [ 97.040583] usb-storage: -- transfer cancelled > [ 97.040585] usb-storage: Bulk status result = 4 > [ 97.040586] usb-storage: -- command was aborted > [ 97.040590] usb-storage: usb_stor_pre_reset ... > [ 97.160494] xhci_hcd 0000:01:00.0: Output context after successful reset device cmd: Device was reset, which would drop endpoints 0x81 and 0x1. > [ 97.160497] xhci_hcd 0000:01:00.0: Slot Context: > [ 97.160510] xhci_hcd 0000:01:00.0: @ffff8800c50b0004 (virt) @c50b0004 (dma) 0x010000 - dev_info2 > [ 97.160514] xhci_hcd 0000:01:00.0: @ffff8800c50b0008 (virt) @c50b0008 (dma) 0x000000 - tt_info > [ 97.160517] xhci_hcd 0000:01:00.0: @ffff8800c50b000c (virt) @c50b000c (dma) 0x8000000 - dev_state > [ 97.160520] xhci_hcd 0000:01:00.0: @ffff8800c50b0010 (virt) @c50b0010 (dma) 0x000000 - rsvd[0] > [ 97.160523] xhci_hcd 0000:01:00.0: @ffff8800c50b0014 (virt) @c50b0014 (dma) 0x000000 - rsvd[1] > [ 97.160526] xhci_hcd 0000:01:00.0: @ffff8800c50b0018 (virt) @c50b0018 (dma) 0x000000 - rsvd[2] > [ 97.160529] xhci_hcd 0000:01:00.0: @ffff8800c50b001c (virt) @c50b001c (dma) 0x000000 - rsvd[3] > [ 97.160532] xhci_hcd 0000:01:00.0: Endpoint 00 Context: > [ 97.160535] xhci_hcd 0000:01:00.0: @ffff8800c50b0020 (virt) @c50b0020 (dma) 0x000001 - ep_info > [ 97.160538] xhci_hcd 0000:01:00.0: @ffff8800c50b0024 (virt) @c50b0024 (dma) 0x2000026 - ep_info2 > [ 97.160541] xhci_hcd 0000:01:00.0: @ffff8800c50b0028 (virt) @c50b0028 (dma) 0x3781b801 - deq > [ 97.160544] xhci_hcd 0000:01:00.0: @ffff8800c50b0030 (virt) @c50b0030 (dma) 0x000000 - tx_info > [ 97.160547] xhci_hcd 0000:01:00.0: @ffff8800c50b0034 (virt) @c50b0034 (dma) 0x000000 - rsvd[0] > [ 97.160550] xhci_hcd 0000:01:00.0: @ffff8800c50b0038 (virt) @c50b0038 (dma) 0x000000 - rsvd[1] > [ 97.160553] xhci_hcd 0000:01:00.0: @ffff8800c50b003c (virt) @c50b003c (dma) 0x000000 - rsvd[2] ... > [ 97.161222] xhci_hcd 0000:01:00.0: Successful Address Device command Not sure why a Configure Endpoint command was issued here with no added or dropped endpoints. Should be harmless though. > [ 97.161236] xhci_hcd 0000:01:00.0: Slot ID 1 Input Context: > [ 97.161239] xhci_hcd 0000:01:00.0: @ffff8800c5090000 (virt) @c5090000 (dma) 0x000000 - drop flags > [ 97.161242] xhci_hcd 0000:01:00.0: @ffff8800c5090004 (virt) @c5090004 (dma) 0x000000 - add flags ... > [ 97.182099] xhci_hcd 0000:01:00.0: xhci_drop_endpoint called for udev ffff880122d7c000 > [ 97.182102] xhci_hcd 0000:01:00.0: xHCI xhci_drop_endpoint called with disabled ep ffff880037bfd9c0 > [ 97.182105] xhci_hcd 0000:01:00.0: xhci_drop_endpoint called for udev ffff880122d7c000 > [ 97.182108] xhci_hcd 0000:01:00.0: xHCI xhci_drop_endpoint called with disabled ep ffff880037bfd980 The USB core is asking the xHCI driver to drop endpoints 0x81 and 0x01, which aren't enabled yet. Kind of odd, but also harmless. > [ 97.182111] xhci_hcd 0000:01:00.0: Allocating ring at ffff88003796d8a0 > [ 97.182114] xhci_hcd 0000:01:00.0: Allocating priv segment structure at ffff880037bcea60 > [ 97.182118] xhci_hcd 0000:01:00.0: // Allocating segment at ffff8800c5021800 (virtual) 0xc5021800 (DMA) > [ 97.182122] xhci_hcd 0000:01:00.0: Linking segment 0xc5021800 to segment 0xc5021800 (DMA) > [ 97.182125] xhci_hcd 0000:01:00.0: Wrote link toggle flag to segment ffff880037bcea60 (virtual), 0xc5021800 (DMA) > [ 97.182128] xhci_hcd 0000:01:00.0: WARN no SS endpoint bMaxBurst > [ 97.182131] xhci_hcd 0000:01:00.0: add ep 0x81, slot id 1, new drop flags = 0x0, new add flags = 0x8, new slot info = 0x18400000 > [ 97.182134] xhci_hcd 0000:01:00.0: Allocating ring at ffff88003796d900 > [ 97.182137] xhci_hcd 0000:01:00.0: Allocating priv segment structure at ffff880037bcebe0 > [ 97.182141] xhci_hcd 0000:01:00.0: // Allocating segment at ffff880037a93000 (virtual) 0x37a93000 (DMA) > [ 97.182146] xhci_hcd 0000:01:00.0: Linking segment 0x37a93000 to segment 0x37a93000 (DMA) > [ 97.182149] xhci_hcd 0000:01:00.0: Wrote link toggle flag to segment ffff880037bcebe0 (virtual), 0x37a93000 (DMA) > [ 97.182151] xhci_hcd 0000:01:00.0: WARN no SS endpoint bMaxBurst > [ 97.182154] xhci_hcd 0000:01:00.0: add ep 0x1, slot id 1, new drop flags = 0x0, new add flags = 0xc, new slot info = 0x18400000 And then endpoints 0x81 and 0x01 are added back, so that's fine. That Configure Endpoint command succeeds fine. > [ 108.740530] usb-storage: -- usb_stor_release_resources > [ 108.740531] usb-storage: -- sending exit command to thread > [ 108.740700] usb-storage: *** thread awakened. > [ 108.740703] usb-storage: -- exiting > [ 108.742086] usb-storage: -- dissociate_dev > [ 108.742123] usb 10-1: usb_disable_device nuking non-ep0 URBs > [ 108.742129] xhci_hcd 0000:01:00.0: Allocating ring at ffff8800c515b3c0 > [ 108.742132] xhci_hcd 0000:01:00.0: Allocating priv segment structure at ffff880037bde560 > [ 108.742135] xhci_hcd 0000:01:00.0: // Allocating segment at ffff880037a93400 (virtual) 0x37a93400 (DMA) > [ 108.742140] xhci_hcd 0000:01:00.0: Linking segment 0x37a93400 to segment 0x37a93400 (DMA) > [ 108.742142] xhci_hcd 0000:01:00.0: Wrote link toggle flag to segment ffff880037bde560 (virtual), 0x37a93400 (DMA) > [ 108.742146] xhci_hcd 0000:01:00.0: WARN no SS endpoint bMaxBurst More issues with the SuperSpeed Endpoint Companion descriptors here. > [ 108.742149] xhci_hcd 0000:01:00.0: add ep 0x81, slot id 1, new drop flags = 0x0, new add flags = 0x8, new slot info = 0x18400000 > [ 108.742152] xhci_hcd 0000:01:00.0: Allocating ring at ffff8800c515b420 > [ 108.742155] xhci_hcd 0000:01:00.0: Allocating priv segment structure at ffff880037bde580 > [ 108.742158] xhci_hcd 0000:01:00.0: // Allocating segment at ffff880037a93800 (virtual) 0x37a93800 (DMA) > [ 108.742162] xhci_hcd 0000:01:00.0: Linking segment 0x37a93800 to segment 0x37a93800 (DMA) > [ 108.742165] xhci_hcd 0000:01:00.0: Wrote link toggle flag to segment ffff880037bde580 (virtual), 0x37a93800 (DMA) > [ 108.742168] xhci_hcd 0000:01:00.0: WARN no SS endpoint bMaxBurst > [ 108.742171] xhci_hcd 0000:01:00.0: add ep 0x1, slot id 1, new drop flags = 0x0, new add flags = 0xc, new slot info = 0x18400000 > [ 108.742174] xhci_hcd 0000:01:00.0: Allocating ring at ffff8800c515b480 > [ 108.742176] xhci_hcd 0000:01:00.0: Allocating priv segment structure at ffff880037bdede0 > [ 108.742181] xhci_hcd 0000:01:00.0: // Allocating segment at ffff8800c51ec000 (virtual) 0xc51ec000 (DMA) > [ 108.742185] xhci_hcd 0000:01:00.0: Linking segment 0xc51ec000 to segment 0xc51ec000 (DMA) > [ 108.742188] xhci_hcd 0000:01:00.0: Wrote link toggle flag to segment ffff880037bdede0 (virtual), 0xc51ec000 (DMA) > [ 108.742191] xhci_hcd 0000:01:00.0: WARN no SS endpoint bMaxBurst Same problem here. > [ 108.742194] xhci_hcd 0000:01:00.0: add ep 0x82, slot id 1, new drop flags = 0x0, new add flags = 0x2c, new slot info = 0x28400000 > [ 108.742197] xhci_hcd 0000:01:00.0: Allocating ring at ffff8800c515b4e0 > [ 108.742200] xhci_hcd 0000:01:00.0: Allocating priv segment structure at ffff880037bdea40 > [ 108.742203] xhci_hcd 0000:01:00.0: // Allocating segment at ffff8800c51ec400 (virtual) 0xc51ec400 (DMA) > [ 108.742207] xhci_hcd 0000:01:00.0: Linking segment 0xc51ec400 to segment 0xc51ec400 (DMA) > [ 108.742210] xhci_hcd 0000:01:00.0: Wrote link toggle flag to segment ffff880037bdea40 (virtual), 0xc51ec400 (DMA) > [ 108.742213] xhci_hcd 0000:01:00.0: WARN no SS endpoint bMaxBurst And here. > [ 108.742216] xhci_hcd 0000:01:00.0: add ep 0x2, slot id 1, new drop flags = 0x0, new add flags = 0x3c, new slot info = 0x28400000 I'm a bit surprised that the endpoints from the previous configuration weren't dropped before this new configuration was added. But drivers usually go through usb_set_configuration(), and maybe the sysfs interface hits a different path? I'll have to look into the code flow. It's not surprising that the xHCI host controller rejected this Configure Endpoint command. The BOT driver had added endpoints 0x81 and 0x01, and then the UAS configuration tried to add endpoints 0x81, 0x01, and 0x82. The host controller probably said, "But wait you're re-adding endpoints without dropping them?" and barfed. Ideally, the xHCI driver should have caught the fact that the endpoints were already enabled without being dropped in xhci_add_endpoint(). The documentation explicitly says that endpoints must be dropped before they are re-added, so I probably need a patch to do that. > [ 108.742219] xhci_hcd 0000:01:00.0: xhci_check_bandwidth called for udev ffff880122d7c000 > [ 108.742222] xhci_hcd 0000:01:00.0: New Input Control Context: > [ 108.742225] xhci_hcd 0000:01:00.0: @ffff8800c5090000 (virt) @c5090000 (dma) 0x000000 - drop flags ... > [ 108.742483] xhci_hcd 0000:01:00.0: Completed config ep cmd > [ 108.742488] xhci_hcd 0000:01:00.0: Command ring deq = 0x3781b180 (DMA) > [ 108.742490] xhci_hcd 0000:01:00.0: xhci_handle_event - returned from handle_cmd_completion > [ 108.742493] xhci_hcd 0000:01:00.0: Event ring deq = 0x3781b580 (DMA) > [ 108.742495] xhci_hcd 0000:01:00.0: In xhci_handle_event > [ 108.742500] xhci_hcd 0000:01:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc9000067c638, 64'h3781b588, 4'hf); > [ 108.744152] usb 10-1: ERROR: Endpoint drop flag = 0, add flag = 1, and endpoint is not disabled. Ok, I'll take a look into fixing this tomorrow. I'll probably send you two patches: one to add an additional check in xhci_add_endpoint(), and another once I figure out the root cause of why the first configuration isn't getting removed. Can you test with just the first patch, to make sure the check works? 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
