* [PATCH] [RFC] usb: Broaden range of vendor codes for xhci @ 2011-05-30 9:56 Maarten Lankhorst 2011-05-31 0:34 ` Xu, Andiry 0 siblings, 1 reply; 11+ messages in thread From: Maarten Lankhorst @ 2011-05-30 9:56 UTC (permalink / raw) To: linux-usb; +Cc: Sarah Sharp, linux-kernel, Maarten Lankhorst My asrock P67 chipset sends code 192 on device reset. Allowing >= 192 to be treated as success fixes it, and allows me to use my USB3 port. Signed-off-by: Maarten Lankhorst <m.b.lankhorst@gmail.com> --- There still appears to be a possible regression though. I can't currently use my usb headset, but since my xhci port never worked, I can't tell for sure if it ever worked. Resending, forgot to add relevant maintainers. --- drivers/usb/host/xhci-ring.c | 2 +- 1 files changed, 1 insertions(+), 1 deletions(-) diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c index 7437386..f8b9f79 100644 --- a/drivers/usb/host/xhci-ring.c +++ b/drivers/usb/host/xhci-ring.c @@ -1464,7 +1464,7 @@ static int xhci_requires_manual_halt_cleanup(struct xhci_hcd *xhci, int xhci_is_vendor_info_code(struct xhci_hcd *xhci, unsigned int trb_comp_code) { - if (trb_comp_code >= 224 && trb_comp_code <= 255) { + if (trb_comp_code >= 192 && trb_comp_code <= 255) { /* Vendor defined "informational" completion code, * treat as not-an-error. */ -- 1.7.4.1 ^ permalink raw reply related [flat|nested] 11+ messages in thread
* RE: [PATCH] [RFC] usb: Broaden range of vendor codes for xhci 2011-05-30 9:56 [PATCH] [RFC] usb: Broaden range of vendor codes for xhci Maarten Lankhorst @ 2011-05-31 0:34 ` Xu, Andiry 2011-05-31 13:47 ` [PATCH] [RFC] usb: Do not attempt to reset the device while it is disabled Maarten Lankhorst 0 siblings, 1 reply; 11+ messages in thread From: Xu, Andiry @ 2011-05-31 0:34 UTC (permalink / raw) To: Maarten Lankhorst, linux-usb; +Cc: Sarah Sharp, linux-kernel > -----Original Message----- > From: linux-usb-owner@vger.kernel.org [mailto:linux-usb- > owner@vger.kernel.org] On Behalf Of Maarten Lankhorst > Sent: Monday, May 30, 2011 5:57 PM > To: linux-usb@vger.kernel.org > Cc: Sarah Sharp; linux-kernel@vger.kernel.org; Maarten Lankhorst > Subject: [PATCH] [RFC] usb: Broaden range of vendor codes for xhci > > My asrock P67 chipset sends code 192 on device reset. Allowing >= 192 > to be treated as success fixes it, and allows me to use my USB3 port. > TRB completion code 192-223 is defined as Vendor defined error. Your host controller returns a error - don't know what causes the error since it's vendor defined. > Signed-off-by: Maarten Lankhorst <m.b.lankhorst@gmail.com> > > --- > There still appears to be a possible regression though. I can't > currently use my usb headset, but since my xhci port never worked, I > can't tell for sure if it ever worked. > > Resending, forgot to add relevant maintainers. > --- > drivers/usb/host/xhci-ring.c | 2 +- > 1 files changed, 1 insertions(+), 1 deletions(-) > > diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci- > ring.c > index 7437386..f8b9f79 100644 > --- a/drivers/usb/host/xhci-ring.c > +++ b/drivers/usb/host/xhci-ring.c > @@ -1464,7 +1464,7 @@ static int > xhci_requires_manual_halt_cleanup(struct xhci_hcd *xhci, > > int xhci_is_vendor_info_code(struct xhci_hcd *xhci, unsigned int > trb_comp_code) > { > - if (trb_comp_code >= 224 && trb_comp_code <= 255) { > + if (trb_comp_code >= 192 && trb_comp_code <= 255) { > /* Vendor defined "informational" completion code, > * treat as not-an-error. > */ > -- You may need to create another function, maybe xhci_is_vendor_error_code(), because trb_comp_code between 192-223(Vendor Defined Error) and 224-255 (Vendor defined Info) has different meanings. Thanks, Andiry > 1.7.4.1 > > -- > To unsubscribe from this list: send the line "unsubscribe linux-usb" in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html ^ permalink raw reply [flat|nested] 11+ messages in thread
* [PATCH] [RFC] usb: Do not attempt to reset the device while it is disabled 2011-05-31 0:34 ` Xu, Andiry @ 2011-05-31 13:47 ` Maarten Lankhorst 2011-05-31 17:14 ` Sarah Sharp 0 siblings, 1 reply; 11+ messages in thread From: Maarten Lankhorst @ 2011-05-31 13:47 UTC (permalink / raw) To: Xu, Andiry; +Cc: linux-usb, Sarah Sharp, linux-kernel Hey Andiry, Op 31-05-11 02:34, Xu, Andiry schreef: >> -----Original Message----- >> From:linux-usb-owner@vger.kernel.org [mailto:linux-usb- >> owner@vger.kernel.org] On Behalf Of Maarten Lankhorst >> Sent: Monday, May 30, 2011 5:57 PM >> To:linux-usb@vger.kernel.org >> Cc: Sarah Sharp;linux-kernel@vger.kernel.org; Maarten Lankhorst >> Subject: [PATCH] [RFC] usb: Broaden range of vendor codes for xhci >> >> My asrock P67 chipset sends code 192 on device reset. Allowing>= 192 >> to be treated as success fixes it, and allows me to use my USB3 port. >> > TRB completion code 192-223 is defined as Vendor defined error. Your > host > controller returns a error - don't know what causes the error since it's > vendor defined. Ahh, making it the same as COMP_EBADSLT/COMP_CTX_STATE I get this: [72677.470421] xhci_hcd 0000:04:00.0: Can't reset device (slot ID 1) in enabled/disabled state Should reset_device even be called when in that state? The comments above claim: /* The Reset Device command can't fail, according to the 0.95/0.96 spec, * unless we tried to reset a slot ID that wasn't enabled, * or the device wasn't in the addressed or configured state. */ Ignoring the error seems to make it work fine. It seems to me that device reset shouldn't even be attempted since it hasn't been brought up yet. The reset that fails is the one that happens on the original hub_port_init when it calls hub_port_reset which calls xhci_discover_or_reset_device. The failure I'm getting seems to be a vendor specific variant of "you're trying to reset the device while it wasn't enabled". Signed-off-by: Maarten Lankhorst<m.b.lankhorst@gmail.com> --- index 81b976e..9a869b2 100644 --- a/drivers/usb/host/xhci.c +++ b/drivers/usb/host/xhci.c @@ -2307,6 +2307,10 @@ int xhci_discover_or_reset_device(struct usb_hcd *hcd, struct usb_device *udev) return -EINVAL; } + if (GET_SLOT_STATE(xhci_get_slot_ctx(xhci, virt_dev->out_ctx)->dev_state) == 0&& + (xhci_get_ep_ctx(xhci, virt_dev->out_ctx, 0)->ep_info& EP_STATE_MASK) == EP_STATE_DISABLED) + return 0; + xhci_dbg(xhci, "Resetting device with slot ID %u\n", slot_id); /* Allocate the command structure that holds the struct completion. * Assume we're in process context, since the normal device reset ^ permalink raw reply related [flat|nested] 11+ messages in thread
* Re: [PATCH] [RFC] usb: Do not attempt to reset the device while it is disabled 2011-05-31 13:47 ` [PATCH] [RFC] usb: Do not attempt to reset the device while it is disabled Maarten Lankhorst @ 2011-05-31 17:14 ` Sarah Sharp 2011-05-31 17:41 ` Maarten Lankhorst 0 siblings, 1 reply; 11+ messages in thread From: Sarah Sharp @ 2011-05-31 17:14 UTC (permalink / raw) To: Maarten Lankhorst; +Cc: Xu, Andiry, linux-usb, linux-kernel On Tue, May 31, 2011 at 03:47:18PM +0200, Maarten Lankhorst wrote: > Hey Andiry, > > Op 31-05-11 02:34, Xu, Andiry schreef: > >>-----Original Message----- > >>From:linux-usb-owner@vger.kernel.org [mailto:linux-usb- > >>owner@vger.kernel.org] On Behalf Of Maarten Lankhorst > >>Sent: Monday, May 30, 2011 5:57 PM > >>To:linux-usb@vger.kernel.org > >>Cc: Sarah Sharp;linux-kernel@vger.kernel.org; Maarten Lankhorst > >>Subject: [PATCH] [RFC] usb: Broaden range of vendor codes for xhci > >> > >>My asrock P67 chipset sends code 192 on device reset. Allowing>= 192 > >>to be treated as success fixes it, and allows me to use my USB3 port. > >> > >TRB completion code 192-223 is defined as Vendor defined error. Your > >host > >controller returns a error - don't know what causes the error since it's > >vendor defined. > Ahh, making it the same as COMP_EBADSLT/COMP_CTX_STATE I get this: > [72677.470421] xhci_hcd 0000:04:00.0: Can't reset device (slot ID 1) > in enabled/disabled state Yes, because that's what those error codes mean. But your host controller did not return that error code, it returned a vendor-specific error code. > Should reset_device even be called when in that state? The comments > above claim: > /* The Reset Device command can't fail, according to the 0.95/0.96 spec, > * unless we tried to reset a slot ID that wasn't enabled, > * or the device wasn't in the addressed or configured state. > */ The code shouldn't happen, but we cover the error condition in case there is a future bug in the USB core, or a buggy host controller. But that's really beside the point. Your host returned a different error code, and there's no telling what that means without vendor specific documentation. Can you send me the lspci for the host? > Ignoring the error seems to make it work fine. It seems to me that > device reset shouldn't even be attempted since it hasn't been > brought up yet. The reset that fails is the one that happens on the > original hub_port_init when it calls hub_port_reset which calls > xhci_discover_or_reset_device. The failure I'm getting seems to be a > vendor specific variant of "you're trying to reset the device while > it wasn't enabled". Yes, the USB core resets a device during the standard enumeration process. The host controller is supposed to be able to handle that case. Why it returns a vendor specific error is something that company needs to answer. Can you send me the full dmesg with CONFIG_USB_XHCI_HCD_DEBUGGING turned on? I'd like to see the full debug log for this and see if the host or driver is falling over in an earlier spot. > Signed-off-by: Maarten Lankhorst<m.b.lankhorst@gmail.com> > > --- > index 81b976e..9a869b2 100644 > --- a/drivers/usb/host/xhci.c > +++ b/drivers/usb/host/xhci.c > @@ -2307,6 +2307,10 @@ int xhci_discover_or_reset_device(struct usb_hcd *hcd, struct usb_device *udev) > return -EINVAL; > } > > + if (GET_SLOT_STATE(xhci_get_slot_ctx(xhci, virt_dev->out_ctx)->dev_state) == 0&& > + (xhci_get_ep_ctx(xhci, virt_dev->out_ctx, 0)->ep_info& EP_STATE_MASK) == EP_STATE_DISABLED) > + return 0; > + Why are you looking at the endpoint state? The control endpoint state has nothing to do with the outcome of the Reset Device command. The host controller is only allowed to reject the command if the device slot is not in the addressed or configured state (according to the 0.96 spec, I assume this host isn't a 1.0 host). So the control endpoint state should have nothing to do with whether the command succeeds. I'm also confused as to why this code works. The control endpoint is never disabled until the USB core deallocates a device. Once the xHCI driver allocates a slot and issues an Address Device command, the control endpoint's output context should move from the disabled state to the running state. But if this conditional actually ran, then either the host controller didn't update the output context for the control endpoint, the Address Device command failed, or something very strange is going on. Full dmesg with the xHCI driver debug will help me figure this out. What kernel are you running? Sarah Sharp ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH] [RFC] usb: Do not attempt to reset the device while it is disabled 2011-05-31 17:14 ` Sarah Sharp @ 2011-05-31 17:41 ` Maarten Lankhorst 2011-05-31 18:18 ` Sarah Sharp 0 siblings, 1 reply; 11+ messages in thread From: Maarten Lankhorst @ 2011-05-31 17:41 UTC (permalink / raw) To: Sarah Sharp; +Cc: Xu, Andiry, linux-usb, linux-kernel Hi Sarah, Op 31-05-11 19:14, Sarah Sharp schreef: > On Tue, May 31, 2011 at 03:47:18PM +0200, Maarten Lankhorst wrote: >> Hey Andiry, >> >> Op 31-05-11 02:34, Xu, Andiry schreef: >>>> -----Original Message----- >>>> From:linux-usb-owner@vger.kernel.org [mailto:linux-usb- >>>> owner@vger.kernel.org] On Behalf Of Maarten Lankhorst >>>> Sent: Monday, May 30, 2011 5:57 PM >>>> To:linux-usb@vger.kernel.org >>>> Cc: Sarah Sharp;linux-kernel@vger.kernel.org; Maarten Lankhorst >>>> Subject: [PATCH] [RFC] usb: Broaden range of vendor codes for xhci >>>> >>>> My asrock P67 chipset sends code 192 on device reset. Allowing>= 192 >>>> to be treated as success fixes it, and allows me to use my USB3 port. >>>> >>> TRB completion code 192-223 is defined as Vendor defined error. Your >>> host >>> controller returns a error - don't know what causes the error since it's >>> vendor defined. >> Ahh, making it the same as COMP_EBADSLT/COMP_CTX_STATE I get this: >> [72677.470421] xhci_hcd 0000:04:00.0: Can't reset device (slot ID 1) >> in enabled/disabled state > Yes, because that's what those error codes mean. But your host > controller did not return that error code, it returned a vendor-specific > error code. > >> Should reset_device even be called when in that state? The comments >> above claim: >> /* The Reset Device command can't fail, according to the 0.95/0.96 spec, >> * unless we tried to reset a slot ID that wasn't enabled, >> * or the device wasn't in the addressed or configured state. >> */ > The code shouldn't happen, but we cover the error condition in case > there is a future bug in the USB core, or a buggy host controller. But > that's really beside the point. Your host returned a different error > code, and there's no telling what that means without vendor specific > documentation. Can you send me the lspci for the host? > >> Ignoring the error seems to make it work fine. It seems to me that >> device reset shouldn't even be attempted since it hasn't been >> brought up yet. The reset that fails is the one that happens on the >> original hub_port_init when it calls hub_port_reset which calls >> xhci_discover_or_reset_device. The failure I'm getting seems to be a >> vendor specific variant of "you're trying to reset the device while >> it wasn't enabled". > Yes, the USB core resets a device during the standard enumeration > process. The host controller is supposed to be able to handle that > case. Why it returns a vendor specific error is something that company > needs to answer. > > Can you send me the full dmesg with CONFIG_USB_XHCI_HCD_DEBUGGING turned > on? I'd like to see the full debug log for this and see if the host or > driver is falling over in an earlier spot. I'm on linux 2.6.39, relevant dmesg spits out this: xhci_hcd 0000:04:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17 xhci_hcd 0000:04:00.0: setting latency timer to 64 xhci_hcd 0000:04:00.0: xHCI Host Controller xhci_hcd 0000:04:00.0: new USB bus registered, assigned bus number 3 xhci_hcd 0000:04:00.0: irq 17, io mem 0xfa100000 xhci_hcd 0000:04:00.0: Failed to enable MSI-X xhci_hcd 0000:04:00.0: irq 47 for MSI/MSI-X xHCI xhci_add_endpoint called for root hub xHCI xhci_check_bandwidth called for root hub hub 3-0:1.0: USB hub found hub 3-0:1.0: 2 ports detected xhci_hcd 0000:04:00.0: xHCI Host Controller xhci_hcd 0000:04:00.0: new USB bus registered, assigned bus number 4 xHCI xhci_add_endpoint called for root hub xHCI xhci_check_bandwidth called for root hub hub 4-0:1.0: USB hub found hub 4-0:1.0: 2 ports detected xhci_hcd 0000:04:00.0: Unknown completion code 192 for reset device command. usb 3-1: Cannot reset HCD device state xhci_hcd 0000:04:00.0: Unknown completion code 192 for reset device command. usb 3-1: Cannot reset HCD device state xhci_hcd 0000:04:00.0: Unknown completion code 192 for reset device command. usb 3-1: Cannot reset HCD device state xhci_hcd 0000:04:00.0: Unknown completion code 192 for reset device command. usb 3-1: Cannot reset HCD device state xhci_hcd 0000:04:00.0: Unknown completion code 192 for reset device command. usb 3-1: Cannot reset HCD device state hub 3-0:1.0: Cannot enable port 1. Maybe the USB cable is bad? >> Signed-off-by: Maarten Lankhorst<m.b.lankhorst@gmail.com> >> >> --- >> index 81b976e..9a869b2 100644 >> --- a/drivers/usb/host/xhci.c >> +++ b/drivers/usb/host/xhci.c >> @@ -2307,6 +2307,10 @@ int xhci_discover_or_reset_device(struct usb_hcd *hcd, struct usb_device *udev) >> return -EINVAL; >> } >> >> + if (GET_SLOT_STATE(xhci_get_slot_ctx(xhci, virt_dev->out_ctx)->dev_state) == 0&& >> + (xhci_get_ep_ctx(xhci, virt_dev->out_ctx, 0)->ep_info& EP_STATE_MASK) == EP_STATE_DISABLED) >> + return 0; >> + > Why are you looking at the endpoint state? The control endpoint state > has nothing to do with the outcome of the Reset Device command. The > host controller is only allowed to reject the command if the device slot > is not in the addressed or configured state (according to the 0.96 spec, > I assume this host isn't a 1.0 host). So the control endpoint state > should have nothing to do with whether the command succeeds. > > I'm also confused as to why this code works. The control endpoint is > never disabled until the USB core deallocates a device. Once the xHCI > driver allocates a slot and issues an Address Device command, the > control endpoint's output context should move from the disabled state to > the running state. But if this conditional actually ran, then either > the host controller didn't update the output context for the control > endpoint, the Address Device command failed, or something very strange > is going on. > > Full dmesg with the xHCI driver debug will help me figure this out. > What kernel are you running? I think it happens because hub_port_reset is called in hub_port_init since commit 07194ab7be63a972096309ab0ea747df455c6a20, so I'd say that is what causes the reset to be called in this state? ~Maarten ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH] [RFC] usb: Do not attempt to reset the device while it is disabled 2011-05-31 17:41 ` Maarten Lankhorst @ 2011-05-31 18:18 ` Sarah Sharp 2011-05-31 19:07 ` Maarten Lankhorst 0 siblings, 1 reply; 11+ messages in thread From: Sarah Sharp @ 2011-05-31 18:18 UTC (permalink / raw) To: Maarten Lankhorst; +Cc: Xu, Andiry, linux-usb, linux-kernel On Tue, May 31, 2011 at 07:41:14PM +0200, Maarten Lankhorst wrote: > Hi Sarah, > > Op 31-05-11 19:14, Sarah Sharp schreef: > > On Tue, May 31, 2011 at 03:47:18PM +0200, Maarten Lankhorst wrote: > > Can you send me the full dmesg with CONFIG_USB_XHCI_HCD_DEBUGGING turned > > on? I'd like to see the full debug log for this and see if the host or > > driver is falling over in an earlier spot. > I'm on linux 2.6.39, relevant dmesg spits out this: Do you also have CONFIG_USB_DEBUGGING turned on and have you run `sudo dmesg -n 8`? There should be much more debugging here. > >> Signed-off-by: Maarten Lankhorst<m.b.lankhorst@gmail.com> > >> > >> --- > >> index 81b976e..9a869b2 100644 > >> --- a/drivers/usb/host/xhci.c > >> +++ b/drivers/usb/host/xhci.c > >> @@ -2307,6 +2307,10 @@ int xhci_discover_or_reset_device(struct usb_hcd *hcd, struct usb_device *udev) > >> return -EINVAL; > >> } > >> > >> + if (GET_SLOT_STATE(xhci_get_slot_ctx(xhci, virt_dev->out_ctx)->dev_state) == 0&& > >> + (xhci_get_ep_ctx(xhci, virt_dev->out_ctx, 0)->ep_info& EP_STATE_MASK) == EP_STATE_DISABLED) > >> + return 0; > >> + > > Why are you looking at the endpoint state? The control endpoint state > > has nothing to do with the outcome of the Reset Device command. The > > host controller is only allowed to reject the command if the device slot > > is not in the addressed or configured state (according to the 0.96 spec, > > I assume this host isn't a 1.0 host). So the control endpoint state > > should have nothing to do with whether the command succeeds. > > > > I'm also confused as to why this code works. The control endpoint is > > never disabled until the USB core deallocates a device. Once the xHCI > > driver allocates a slot and issues an Address Device command, the > > control endpoint's output context should move from the disabled state to > > the running state. But if this conditional actually ran, then either > > the host controller didn't update the output context for the control > > endpoint, the Address Device command failed, or something very strange > > is going on. > > > > Full dmesg with the xHCI driver debug will help me figure this out. > > What kernel are you running? > I think it happens because hub_port_reset is called in hub_port_init since > commit 07194ab7be63a972096309ab0ea747df455c6a20, so I'd say that is > what causes the reset to be called in this state? Yes, but every host controller I've run into, except yours, can handle this patch, and the xHCI specification says the host should be able to handle this, so my inclination is that your hardware is just broken. I'd like to know exactly which host controller it is (`lspci -vvv` will help with that), and then we can hopefully track down an engineer from that company and ask them what that error code means. Once we do receive confirmation that the error code is just a fluke, we can create a quirk for that specific host controller to ignore that error condition for the reset device command. Sarah Sharp ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH] [RFC] usb: Do not attempt to reset the device while it is disabled 2011-05-31 18:18 ` Sarah Sharp @ 2011-05-31 19:07 ` Maarten Lankhorst 2011-05-31 22:35 ` Sarah Sharp 0 siblings, 1 reply; 11+ messages in thread From: Maarten Lankhorst @ 2011-05-31 19:07 UTC (permalink / raw) To: Sarah Sharp; +Cc: Xu, Andiry, linux-usb, linux-kernel Op 31-05-11 20:18, Sarah Sharp schreef: > On Tue, May 31, 2011 at 07:41:14PM +0200, Maarten Lankhorst wrote: >> Hi Sarah, >> >> Op 31-05-11 19:14, Sarah Sharp schreef: >>> On Tue, May 31, 2011 at 03:47:18PM +0200, Maarten Lankhorst wrote: >>> Can you send me the full dmesg with CONFIG_USB_XHCI_HCD_DEBUGGING turned >>> on? I'd like to see the full debug log for this and see if the host or >>> driver is falling over in an earlier spot. >> I'm on linux 2.6.39, relevant dmesg spits out this: > Do you also have CONFIG_USB_DEBUGGING turned on and have you run `sudo > dmesg -n 8`? There should be much more debugging here. > >>>> Signed-off-by: Maarten Lankhorst<m.b.lankhorst@gmail.com> >>>> >>>> --- >>>> index 81b976e..9a869b2 100644 >>>> --- a/drivers/usb/host/xhci.c >>>> +++ b/drivers/usb/host/xhci.c >>>> @@ -2307,6 +2307,10 @@ int xhci_discover_or_reset_device(struct usb_hcd *hcd, struct usb_device *udev) >>>> return -EINVAL; >>>> } >>>> >>>> + if (GET_SLOT_STATE(xhci_get_slot_ctx(xhci, virt_dev->out_ctx)->dev_state) == 0&& >>>> + (xhci_get_ep_ctx(xhci, virt_dev->out_ctx, 0)->ep_info& EP_STATE_MASK) == EP_STATE_DISABLED) >>>> + return 0; >>>> + >>> Why are you looking at the endpoint state? The control endpoint state >>> has nothing to do with the outcome of the Reset Device command. The >>> host controller is only allowed to reject the command if the device slot >>> is not in the addressed or configured state (according to the 0.96 spec, >>> I assume this host isn't a 1.0 host). So the control endpoint state >>> should have nothing to do with whether the command succeeds. >>> >>> I'm also confused as to why this code works. The control endpoint is >>> never disabled until the USB core deallocates a device. Once the xHCI >>> driver allocates a slot and issues an Address Device command, the >>> control endpoint's output context should move from the disabled state to >>> the running state. But if this conditional actually ran, then either >>> the host controller didn't update the output context for the control >>> endpoint, the Address Device command failed, or something very strange >>> is going on. >>> >>> Full dmesg with the xHCI driver debug will help me figure this out. >>> What kernel are you running? >> I think it happens because hub_port_reset is called in hub_port_init since >> commit 07194ab7be63a972096309ab0ea747df455c6a20, so I'd say that is >> what causes the reset to be called in this state? > Yes, but every host controller I've run into, except yours, can handle > this patch, and the xHCI specification says the host should be able to > handle this, so my inclination is that your hardware is just broken. > > I'd like to know exactly which host controller it is (`lspci -vvv` will > help with that), and then we can hopefully track down an engineer from > that company and ask them what that error code means. Once we do > receive confirmation that the error code is just a fluke, we can create > a quirk for that specific host controller to ignore that error condition > for the reset device command. My xhci controller is this one: 04:00.0 USB Controller: Device 1b6f:7023 (rev 01) (prog-if 30 [XHCI]) Subsystem: ASRock Incorporation Device 7023 After plugging in a simple bluetooth dongle, until the first failure: [ 545.440655] xhci_hcd 0000:04:00.0: op reg status = 00000018 [ 545.440659] xhci_hcd 0000:04:00.0: Event ring dequeue ptr: [ 545.440663] xhci_hcd 0000:04:00.0: @bac3f400 01000000 00000000 01000000 00008801 [ 545.440666] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0024, 32'h18, 4'hf); [ 545.440670] xhci_hcd 0000:04:00.0: In xhci_handle_event [ 545.440672] xhci_hcd 0000:04:00.0: xhci_handle_event - OS owns TRB [ 545.440674] xhci_hcd 0000:04:00.0: xhci_handle_event - calling handle_port_status [ 545.440677] xhci_hcd 0000:04:00.0: Port Status Change Event for port 1 [ 545.440682] xhci_hcd 0000:04:00.0: resume root hub [ 545.440688] xhci_hcd 0000:04:00.0: Event ring deq = 0xbac3f410 (DMA) [ 545.440697] xhci_hcd 0000:04:00.0: xhci_handle_event - returned from handle_port_status [ 545.440699] xhci_hcd 0000:04:00.0: In xhci_handle_event [ 545.440706] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2038, 64'hbac3f418, 4'hf); [ 545.440716] usb usb3: usb wakeup-resume [ 545.440721] usb usb3: usb auto-resume [ 545.440723] xhci_hcd 0000:04:00.0: resume USB 2.0 root hub [ 545.440728] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0020, 32'h1, 4'hf); [ 545.440733] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0430, 32'h2a0, 4'hf); [ 545.440739] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0434, 32'h0, 4'hf); [ 545.440744] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0420, 32'h2e1, 4'hf); [ 545.440750] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0424, 32'h0, 4'hf); [ 545.440757] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0020, 32'h5, 4'hf); [ 545.450951] hub 3-0:1.0: hub_resume [ 545.450963] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x202a0 [ 545.450966] xhci_hcd 0000:04:00.0: Get port status returned 0x10100 [ 545.450976] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0420, 32'h202a0, 4'hf); [ 545.450982] xhci_hcd 0000:04:00.0: clear port connect change, actual port 0 status = 0x2a0 [ 545.450988] xhci_hcd 0000:04:00.0: get port status, actual port 1 status = 0x2a0 [ 545.450991] xhci_hcd 0000:04:00.0: Get port status returned 0x100 [ 545.551999] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 545.560146] xhci_hcd 0000:04:00.0: op reg status = 00000018 [ 545.560150] xhci_hcd 0000:04:00.0: Event ring dequeue ptr: [ 545.560153] xhci_hcd 0000:04:00.0: @bac3f410 01000000 00000000 01000000 00008801 [ 545.560157] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0024, 32'h18, 4'hf); [ 545.560160] xhci_hcd 0000:04:00.0: In xhci_handle_event [ 545.560162] xhci_hcd 0000:04:00.0: xhci_handle_event - OS owns TRB [ 545.560164] xhci_hcd 0000:04:00.0: xhci_handle_event - calling handle_port_status [ 545.560167] xhci_hcd 0000:04:00.0: Port Status Change Event for port 1 [ 545.560172] xhci_hcd 0000:04:00.0: Event ring deq = 0xbac3f420 (DMA) [ 545.560186] xhci_hcd 0000:04:00.0: xhci_handle_event - returned from handle_port_status [ 545.560189] xhci_hcd 0000:04:00.0: In xhci_handle_event [ 545.560195] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2038, 64'hbac3f428, 4'hf); [ 545.560206] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0002 [ 545.560214] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x202e1 [ 545.560217] xhci_hcd 0000:04:00.0: Get port status returned 0x10101 [ 545.560224] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0420, 32'h202e1, 4'hf); [ 545.560230] xhci_hcd 0000:04:00.0: clear port connect change, actual port 0 status = 0x2e1 [ 545.560234] hub 3-0:1.0: port 1, status 0101, change 0001, 12 Mb/s [ 545.560240] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x2e1 [ 545.560242] xhci_hcd 0000:04:00.0: Get port status returned 0x101 [ 545.585947] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x2e1 [ 545.585952] xhci_hcd 0000:04:00.0: Get port status returned 0x101 [ 545.611948] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x2e1 [ 545.611952] xhci_hcd 0000:04:00.0: Get port status returned 0x101 [ 545.637948] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x2e1 [ 545.637952] xhci_hcd 0000:04:00.0: Get port status returned 0x101 [ 545.663952] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x2e1 [ 545.663957] xhci_hcd 0000:04:00.0: Get port status returned 0x101 [ 545.663963] hub 3-0:1.0: debounce: port 1: total 100ms stable 100ms status 0x101 [ 545.663967] xhci_hcd 0000:04:00.0: Endpoint state = 0x1 [ 545.663971] xhci_hcd 0000:04:00.0: Command ring enq = 0xbac3f010 (DMA) [ 545.663973] xhci_hcd 0000:04:00.0: // Ding dong! [ 545.663976] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce3000, 32'h0, 4'hf); [ 545.663989] xhci_hcd 0000:04:00.0: op reg status = 00000008 [ 545.663991] xhci_hcd 0000:04:00.0: Event ring dequeue ptr: [ 545.663994] xhci_hcd 0000:04:00.0: @bac3f420 bac3f000 00000000 01000000 01008401 [ 545.663997] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0024, 32'h8, 4'hf); [ 545.664000] xhci_hcd 0000:04:00.0: In xhci_handle_event [ 545.664002] xhci_hcd 0000:04:00.0: xhci_handle_event - OS owns TRB [ 545.664005] xhci_hcd 0000:04:00.0: xhci_handle_event - calling handle_cmd_completion [ 545.664009] xhci_hcd 0000:04:00.0: Command ring deq = 0xbac3f010 (DMA) [ 545.664012] xhci_hcd 0000:04:00.0: xhci_handle_event - returned from handle_cmd_completion [ 545.664014] xhci_hcd 0000:04:00.0: Event ring deq = 0xbac3f430 (DMA) [ 545.664017] xhci_hcd 0000:04:00.0: In xhci_handle_event [ 545.664023] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2038, 64'hbac3f438, 4'hf); [ 545.664034] xhci_hcd 0000:04:00.0: Slot 1 output ctx = 0xbac21000 (dma) [ 545.664038] xhci_hcd 0000:04:00.0: Slot 1 input ctx = 0xbac22000 (dma) [ 545.664041] xhci_hcd 0000:04:00.0: Allocating ring at ffff8801c7d7ccc0 [ 545.664044] xhci_hcd 0000:04:00.0: Allocating priv segment structure at ffff8801e2e26c40 [ 545.664047] xhci_hcd 0000:04:00.0: // Allocating segment at ffff8800bac3f800 (virtual) 0xbac3f800 (DMA) [ 545.664053] xhci_hcd 0000:04:00.0: Linking segment 0xbac3f800 to segment 0xbac3f800 (DMA) [ 545.664056] xhci_hcd 0000:04:00.0: Wrote link toggle flag to segment ffff8801e2e26c40 (virtual), 0xbac3f800 (DMA) [ 545.664059] xhci_hcd 0000:04:00.0: Set slot id 1 dcbaa entry ffff8800bac3e008 to 0xbac21000 [ 545.664070] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0420, 32'h2f1, 4'hf); [ 545.664075] xhci_hcd 0000:04:00.0: set port reset, actual port 0 status = 0x2f1 [ 545.699907] xhci_hcd 0000:04:00.0: op reg status = 00000018 [ 545.699911] xhci_hcd 0000:04:00.0: Event ring dequeue ptr: [ 545.699915] xhci_hcd 0000:04:00.0: @bac3f430 01000000 00000000 01000000 00008801 [ 545.699918] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0024, 32'h18, 4'hf); [ 545.699921] xhci_hcd 0000:04:00.0: In xhci_handle_event [ 545.699923] xhci_hcd 0000:04:00.0: xhci_handle_event - OS owns TRB [ 545.699926] xhci_hcd 0000:04:00.0: xhci_handle_event - calling handle_port_status [ 545.699928] xhci_hcd 0000:04:00.0: Port Status Change Event for port 1 [ 545.699933] xhci_hcd 0000:04:00.0: Event ring deq = 0xbac3f440 (DMA) [ 545.699941] xhci_hcd 0000:04:00.0: xhci_handle_event - returned from handle_port_status [ 545.699943] xhci_hcd 0000:04:00.0: In xhci_handle_event [ 545.699950] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2038, 64'hbac3f448, 4'hf); [ 545.714950] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x200603 [ 545.714954] xhci_hcd 0000:04:00.0: Get port status returned 0x103 [ 545.765950] xhci_hcd 0000:04:00.0: Resetting device with slot ID 1 [ 545.765955] xhci_hcd 0000:04:00.0: Endpoint state = 0x1 [ 545.765959] xhci_hcd 0000:04:00.0: Command ring enq = 0xbac3f020 (DMA) [ 545.765961] xhci_hcd 0000:04:00.0: // Ding dong! [ 545.765964] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce3000, 32'h0, 4'hf); [ 545.765977] xhci_hcd 0000:04:00.0: op reg status = 00000008 [ 545.765979] xhci_hcd 0000:04:00.0: Event ring dequeue ptr: [ 545.765982] xhci_hcd 0000:04:00.0: @bac3f440 bac3f010 00000000 c0000000 01008401 [ 545.765985] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0024, 32'h8, 4'hf); [ 545.765988] xhci_hcd 0000:04:00.0: In xhci_handle_event [ 545.765990] xhci_hcd 0000:04:00.0: xhci_handle_event - OS owns TRB [ 545.765992] xhci_hcd 0000:04:00.0: xhci_handle_event - calling handle_cmd_completion [ 545.765995] xhci_hcd 0000:04:00.0: Completed reset device command. [ 545.765999] xhci_hcd 0000:04:00.0: Command ring deq = 0xbac3f020 (DMA) [ 545.766002] xhci_hcd 0000:04:00.0: xhci_handle_event - returned from handle_cmd_completion [ 545.766005] xhci_hcd 0000:04:00.0: Event ring deq = 0xbac3f450 (DMA) [ 545.766007] xhci_hcd 0000:04:00.0: In xhci_handle_event [ 545.766013] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2038, 64'hbac3f458, 4'hf); [ 545.766019] xhci_hcd 0000:04:00.0: Unknown completion code 192 for reset device command. [ 545.766023] usb 3-1: Cannot reset HCD device state ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH] [RFC] usb: Do not attempt to reset the device while it is disabled 2011-05-31 19:07 ` Maarten Lankhorst @ 2011-05-31 22:35 ` Sarah Sharp 2011-05-31 22:55 ` Maarten Lankhorst 2011-05-31 23:57 ` Maarten Lankhorst 0 siblings, 2 replies; 11+ messages in thread From: Sarah Sharp @ 2011-05-31 22:35 UTC (permalink / raw) To: Maarten Lankhorst; +Cc: Xu, Andiry, linux-usb, linux-kernel On Tue, May 31, 2011 at 09:07:32PM +0200, Maarten Lankhorst wrote: > Op 31-05-11 20:18, Sarah Sharp schreef: > > On Tue, May 31, 2011 at 07:41:14PM +0200, Maarten Lankhorst wrote: > My xhci controller is this one: > 04:00.0 USB Controller: Device 1b6f:7023 (rev 01) (prog-if 30 [XHCI]) > Subsystem: ASRock Incorporation Device 7023 Ok, the PCI SIGG says that vendor ID is assigned to Etron. Congrats, that's the first xHCI host controller I've seen from that company. :) > After plugging in a simple bluetooth dongle, until the first failure: Are you sure you have the dmesg log level set to 8? Because there still should be more debugging about input and output contexts in this log. Are you capturing via /var/log/kern.log? > [ 545.440655] xhci_hcd 0000:04:00.0: op reg status = 00000018 > [ 545.440659] xhci_hcd 0000:04:00.0: Event ring dequeue ptr: > [ 545.440663] xhci_hcd 0000:04:00.0: @bac3f400 01000000 00000000 01000000 00008801 > [ 545.440666] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0024, 32'h18, 4'hf); > [ 545.440670] xhci_hcd 0000:04:00.0: In xhci_handle_event > [ 545.440672] xhci_hcd 0000:04:00.0: xhci_handle_event - OS owns TRB > [ 545.440674] xhci_hcd 0000:04:00.0: xhci_handle_event - calling handle_port_status > [ 545.440677] xhci_hcd 0000:04:00.0: Port Status Change Event for port 1 > [ 545.440682] xhci_hcd 0000:04:00.0: resume root hub > [ 545.440688] xhci_hcd 0000:04:00.0: Event ring deq = 0xbac3f410 (DMA) > [ 545.440697] xhci_hcd 0000:04:00.0: xhci_handle_event - returned from handle_port_status > [ 545.440699] xhci_hcd 0000:04:00.0: In xhci_handle_event > [ 545.440706] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2038, 64'hbac3f418, 4'hf); > [ 545.440716] usb usb3: usb wakeup-resume > [ 545.440721] usb usb3: usb auto-resume > [ 545.440723] xhci_hcd 0000:04:00.0: resume USB 2.0 root hub > [ 545.440728] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0020, 32'h1, 4'hf); > [ 545.440733] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0430, 32'h2a0, 4'hf); > [ 545.440739] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0434, 32'h0, 4'hf); > [ 545.440744] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0420, 32'h2e1, 4'hf); > [ 545.440750] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0424, 32'h0, 4'hf); > [ 545.440757] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0020, 32'h5, 4'hf); > [ 545.450951] hub 3-0:1.0: hub_resume > [ 545.450963] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x202a0 > [ 545.450966] xhci_hcd 0000:04:00.0: Get port status returned 0x10100 > [ 545.450976] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0420, 32'h202a0, 4'hf); > [ 545.450982] xhci_hcd 0000:04:00.0: clear port connect change, actual port 0 status = 0x2a0 > [ 545.450988] xhci_hcd 0000:04:00.0: get port status, actual port 1 status = 0x2a0 > [ 545.450991] xhci_hcd 0000:04:00.0: Get port status returned 0x100 > [ 545.551999] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 545.560146] xhci_hcd 0000:04:00.0: op reg status = 00000018 > [ 545.560150] xhci_hcd 0000:04:00.0: Event ring dequeue ptr: > [ 545.560153] xhci_hcd 0000:04:00.0: @bac3f410 01000000 00000000 01000000 00008801 > [ 545.560157] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0024, 32'h18, 4'hf); > [ 545.560160] xhci_hcd 0000:04:00.0: In xhci_handle_event > [ 545.560162] xhci_hcd 0000:04:00.0: xhci_handle_event - OS owns TRB > [ 545.560164] xhci_hcd 0000:04:00.0: xhci_handle_event - calling handle_port_status > [ 545.560167] xhci_hcd 0000:04:00.0: Port Status Change Event for port 1 > [ 545.560172] xhci_hcd 0000:04:00.0: Event ring deq = 0xbac3f420 (DMA) > [ 545.560186] xhci_hcd 0000:04:00.0: xhci_handle_event - returned from handle_port_status > [ 545.560189] xhci_hcd 0000:04:00.0: In xhci_handle_event > [ 545.560195] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2038, 64'hbac3f428, 4'hf); > [ 545.560206] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0002 > [ 545.560214] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x202e1 > [ 545.560217] xhci_hcd 0000:04:00.0: Get port status returned 0x10101 > [ 545.560224] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0420, 32'h202e1, 4'hf); > [ 545.560230] xhci_hcd 0000:04:00.0: clear port connect change, actual port 0 status = 0x2e1 > [ 545.560234] hub 3-0:1.0: port 1, status 0101, change 0001, 12 Mb/s > [ 545.560240] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x2e1 > [ 545.560242] xhci_hcd 0000:04:00.0: Get port status returned 0x101 > [ 545.585947] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x2e1 > [ 545.585952] xhci_hcd 0000:04:00.0: Get port status returned 0x101 > [ 545.611948] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x2e1 > [ 545.611952] xhci_hcd 0000:04:00.0: Get port status returned 0x101 > [ 545.637948] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x2e1 > [ 545.637952] xhci_hcd 0000:04:00.0: Get port status returned 0x101 > [ 545.663952] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x2e1 > [ 545.663957] xhci_hcd 0000:04:00.0: Get port status returned 0x101 > [ 545.663963] hub 3-0:1.0: debounce: port 1: total 100ms stable 100ms status 0x101 > [ 545.663967] xhci_hcd 0000:04:00.0: Endpoint state = 0x1 > [ 545.663971] xhci_hcd 0000:04:00.0: Command ring enq = 0xbac3f010 (DMA) > [ 545.663973] xhci_hcd 0000:04:00.0: // Ding dong! > [ 545.663976] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce3000, 32'h0, 4'hf); > [ 545.663989] xhci_hcd 0000:04:00.0: op reg status = 00000008 > [ 545.663991] xhci_hcd 0000:04:00.0: Event ring dequeue ptr: > [ 545.663994] xhci_hcd 0000:04:00.0: @bac3f420 bac3f000 00000000 01000000 01008401 > [ 545.663997] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0024, 32'h8, 4'hf); > [ 545.664000] xhci_hcd 0000:04:00.0: In xhci_handle_event > [ 545.664002] xhci_hcd 0000:04:00.0: xhci_handle_event - OS owns TRB > [ 545.664005] xhci_hcd 0000:04:00.0: xhci_handle_event - calling handle_cmd_completion > [ 545.664009] xhci_hcd 0000:04:00.0: Command ring deq = 0xbac3f010 (DMA) > [ 545.664012] xhci_hcd 0000:04:00.0: xhci_handle_event - returned from handle_cmd_completion > [ 545.664014] xhci_hcd 0000:04:00.0: Event ring deq = 0xbac3f430 (DMA) > [ 545.664017] xhci_hcd 0000:04:00.0: In xhci_handle_event > [ 545.664023] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2038, 64'hbac3f438, 4'hf); > [ 545.664034] xhci_hcd 0000:04:00.0: Slot 1 output ctx = 0xbac21000 (dma) > [ 545.664038] xhci_hcd 0000:04:00.0: Slot 1 input ctx = 0xbac22000 (dma) Ok, so the xHCI driver does successfully get a slot from the host controller. > [ 545.664041] xhci_hcd 0000:04:00.0: Allocating ring at ffff8801c7d7ccc0 > [ 545.664044] xhci_hcd 0000:04:00.0: Allocating priv segment structure at ffff8801e2e26c40 > [ 545.664047] xhci_hcd 0000:04:00.0: // Allocating segment at ffff8800bac3f800 (virtual) 0xbac3f800 (DMA) > [ 545.664053] xhci_hcd 0000:04:00.0: Linking segment 0xbac3f800 to segment 0xbac3f800 (DMA) > [ 545.664056] xhci_hcd 0000:04:00.0: Wrote link toggle flag to segment ffff8801e2e26c40 (virtual), 0xbac3f800 (DMA) > [ 545.664059] xhci_hcd 0000:04:00.0: Set slot id 1 dcbaa entry ffff8800bac3e008 to 0xbac21000 > [ 545.664070] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0420, 32'h2f1, 4'hf); But I don't see an Address Device command complete here. The command submission probably caused that memory write, but there really should be more debugging here. I'll have to look through the hub initialization and see if there is any error path that would make it skip setting the device address. Have you tried on Linux 3.0-rc1? > [ 545.664075] xhci_hcd 0000:04:00.0: set port reset, actual port 0 status = 0x2f1 > [ 545.699907] xhci_hcd 0000:04:00.0: op reg status = 00000018 > [ 545.699911] xhci_hcd 0000:04:00.0: Event ring dequeue ptr: > [ 545.699915] xhci_hcd 0000:04:00.0: @bac3f430 01000000 00000000 01000000 00008801 > [ 545.699918] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0024, 32'h18, 4'hf); > [ 545.699921] xhci_hcd 0000:04:00.0: In xhci_handle_event > [ 545.699923] xhci_hcd 0000:04:00.0: xhci_handle_event - OS owns TRB > [ 545.699926] xhci_hcd 0000:04:00.0: xhci_handle_event - calling handle_port_status > [ 545.699928] xhci_hcd 0000:04:00.0: Port Status Change Event for port 1 > [ 545.699933] xhci_hcd 0000:04:00.0: Event ring deq = 0xbac3f440 (DMA) > [ 545.699941] xhci_hcd 0000:04:00.0: xhci_handle_event - returned from handle_port_status > [ 545.699943] xhci_hcd 0000:04:00.0: In xhci_handle_event > [ 545.699950] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2038, 64'hbac3f448, 4'hf); > [ 545.714950] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x200603 > [ 545.714954] xhci_hcd 0000:04:00.0: Get port status returned 0x103 > [ 545.765950] xhci_hcd 0000:04:00.0: Resetting device with slot ID 1 > [ 545.765955] xhci_hcd 0000:04:00.0: Endpoint state = 0x1 > [ 545.765959] xhci_hcd 0000:04:00.0: Command ring enq = 0xbac3f020 (DMA) > [ 545.765961] xhci_hcd 0000:04:00.0: // Ding dong! > [ 545.765964] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce3000, 32'h0, 4'hf); > [ 545.765977] xhci_hcd 0000:04:00.0: op reg status = 00000008 > [ 545.765979] xhci_hcd 0000:04:00.0: Event ring dequeue ptr: > [ 545.765982] xhci_hcd 0000:04:00.0: @bac3f440 bac3f010 00000000 c0000000 01008401 > [ 545.765985] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0024, 32'h8, 4'hf); > [ 545.765988] xhci_hcd 0000:04:00.0: In xhci_handle_event > [ 545.765990] xhci_hcd 0000:04:00.0: xhci_handle_event - OS owns TRB > [ 545.765992] xhci_hcd 0000:04:00.0: xhci_handle_event - calling handle_cmd_completion > [ 545.765995] xhci_hcd 0000:04:00.0: Completed reset device command. > [ 545.765999] xhci_hcd 0000:04:00.0: Command ring deq = 0xbac3f020 (DMA) > [ 545.766002] xhci_hcd 0000:04:00.0: xhci_handle_event - returned from handle_cmd_completion > [ 545.766005] xhci_hcd 0000:04:00.0: Event ring deq = 0xbac3f450 (DMA) > [ 545.766007] xhci_hcd 0000:04:00.0: In xhci_handle_event > [ 545.766013] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2038, 64'hbac3f458, 4'hf); > [ 545.766019] xhci_hcd 0000:04:00.0: Unknown completion code 192 for reset device command. > [ 545.766023] usb 3-1: Cannot reset HCD device state Sarah Sharp ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH] [RFC] usb: Do not attempt to reset the device while it is disabled 2011-05-31 22:35 ` Sarah Sharp @ 2011-05-31 22:55 ` Maarten Lankhorst 2011-05-31 23:57 ` Maarten Lankhorst 1 sibling, 0 replies; 11+ messages in thread From: Maarten Lankhorst @ 2011-05-31 22:55 UTC (permalink / raw) To: Sarah Sharp; +Cc: Xu, Andiry, linux-usb, linux-kernel Op 01-06-11 00:35, Sarah Sharp schreef: > On Tue, May 31, 2011 at 09:07:32PM +0200, Maarten Lankhorst wrote: >> Op 31-05-11 20:18, Sarah Sharp schreef: >>> On Tue, May 31, 2011 at 07:41:14PM +0200, Maarten Lankhorst wrote: >> My xhci controller is this one: >> 04:00.0 USB Controller: Device 1b6f:7023 (rev 01) (prog-if 30 [XHCI]) >> Subsystem: ASRock Incorporation Device 7023 > Ok, the PCI SIGG says that vendor ID is assigned to Etron. Congrats, > that's the first xHCI host controller I've seen from that company. :) > >> After plugging in a simple bluetooth dongle, until the first failure: > Are you sure you have the dmesg log level set to 8? Because there still > should be more debugging about input and output contexts in this log. > Are you capturing via /var/log/kern.log? I skipped the part where the device was initialized, it had a whole lot of stuff there. The log I had was from the input part forward.. Fuller log at the bottom. I was using dmesg to grab the log. > Ok, so the xHCI driver does successfully get a slot from the host > controller. > >> [ 545.664041] xhci_hcd 0000:04:00.0: Allocating ring at ffff8801c7d7ccc0 >> [ 545.664044] xhci_hcd 0000:04:00.0: Allocating priv segment structure at ffff8801e2e26c40 >> [ 545.664047] xhci_hcd 0000:04:00.0: // Allocating segment at ffff8800bac3f800 (virtual) 0xbac3f800 (DMA) >> [ 545.664053] xhci_hcd 0000:04:00.0: Linking segment 0xbac3f800 to segment 0xbac3f800 (DMA) >> [ 545.664056] xhci_hcd 0000:04:00.0: Wrote link toggle flag to segment ffff8801e2e26c40 (virtual), 0xbac3f800 (DMA) >> [ 545.664059] xhci_hcd 0000:04:00.0: Set slot id 1 dcbaa entry ffff8800bac3e008 to 0xbac21000 >> [ 545.664070] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0420, 32'h2f1, 4'hf); > But I don't see an Address Device command complete here. The command > submission probably caused that memory write, but there really should be > more debugging here. I'll have to look through the hub initialization > and see if there is any error path that would make it skip setting the > device address. > > Have you tried on Linux 3.0-rc1? If I backtrace it I get this: hub_port_init calls hub_port_reset which issues the device reset in xhci_discover_or_reset_device, it is called BEFORE the device is being initialized.. Haven't tried 3.0rc1 yet, will give it a shot slightly fuller dmesg log: [14254.214609] xhci_hcd 0000:04:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17 [14254.214639] xhci_hcd 0000:04:00.0: setting latency timer to 64 [14254.214644] xhci_hcd 0000:04:00.0: xHCI Host Controller [14254.214649] xhci_hcd 0000:04:00.0: new USB bus registered, assigned bus number 3 [14254.220705] xhci_hcd 0000:04:00.0: xHCI capability registers at ffffc90001ce0000: [14254.220711] xhci_hcd 0000:04:00.0: CAPLENGTH AND HCIVERSION 0x1000020: [14254.220712] xhci_hcd 0000:04:00.0: CAPLENGTH: 0x20 [14254.220713] xhci_hcd 0000:04:00.0: HCIVERSION: 0x100 [14254.220716] xhci_hcd 0000:04:00.0: HCSPARAMS 1: 0x4000440 [14254.220717] xhci_hcd 0000:04:00.0: Max device slots: 64 [14254.220718] xhci_hcd 0000:04:00.0: Max interrupters: 4 [14254.220718] xhci_hcd 0000:04:00.0: Max ports: 4 [14254.220721] xhci_hcd 0000:04:00.0: HCSPARAMS 2: 0x240000f9 [14254.220722] xhci_hcd 0000:04:00.0: Isoc scheduling threshold: 9 [14254.220723] xhci_hcd 0000:04:00.0: Maximum allowed segments in event ring: 15 [14254.220726] xhci_hcd 0000:04:00.0: HCSPARAMS 3 0x7ff0003: [14254.220727] xhci_hcd 0000:04:00.0: Worst case U1 device exit latency: 3 [14254.220728] xhci_hcd 0000:04:00.0: Worst case U2 device exit latency: 2047 [14254.220731] xhci_hcd 0000:04:00.0: HCC PARAMS 0x40050af: [14254.220732] xhci_hcd 0000:04:00.0: HC generates 64 bit addresses [14254.220732] xhci_hcd 0000:04:00.0: FIXME: more HCCPARAMS debugging [14254.220735] xhci_hcd 0000:04:00.0: RTSOFF 0x2000: [14254.220736] xhci_hcd 0000:04:00.0: xHCI operational registers at ffffc90001ce0020: [14254.220739] xhci_hcd 0000:04:00.0: USBCMD 0x0: [14254.220740] xhci_hcd 0000:04:00.0: HC is being stopped [14254.220741] xhci_hcd 0000:04:00.0: HC has finished hard reset [14254.220742] xhci_hcd 0000:04:00.0: Event Interrupts disabled [14254.220743] xhci_hcd 0000:04:00.0: Host System Error Interrupts disabled [14254.220743] xhci_hcd 0000:04:00.0: HC has finished light reset [14254.220746] xhci_hcd 0000:04:00.0: USBSTS 0x11: [14254.220747] xhci_hcd 0000:04:00.0: Event ring is empty [14254.220748] xhci_hcd 0000:04:00.0: No Host System Error [14254.220749] xhci_hcd 0000:04:00.0: HC is halted [14254.220752] xhci_hcd 0000:04:00.0: ffffc90001ce0420 port status reg = 0x202e1 [14254.220755] xhci_hcd 0000:04:00.0: ffffc90001ce0424 port power reg = 0x0 [14254.220758] xhci_hcd 0000:04:00.0: ffffc90001ce0428 port link reg = 0x0 [14254.220761] xhci_hcd 0000:04:00.0: ffffc90001ce042c port reserved reg = 0x0 [14254.220765] xhci_hcd 0000:04:00.0: ffffc90001ce0430 port status reg = 0x2a0 [14254.220768] xhci_hcd 0000:04:00.0: ffffc90001ce0434 port power reg = 0x0 [14254.220771] xhci_hcd 0000:04:00.0: ffffc90001ce0438 port link reg = 0x0 [14254.220775] xhci_hcd 0000:04:00.0: ffffc90001ce043c port reserved reg = 0x0 [14254.220778] xhci_hcd 0000:04:00.0: ffffc90001ce0440 port status reg = 0x2a0 [14254.220781] xhci_hcd 0000:04:00.0: ffffc90001ce0444 port power reg = 0x0 [14254.220784] xhci_hcd 0000:04:00.0: ffffc90001ce0448 port link reg = 0x0 [14254.220788] xhci_hcd 0000:04:00.0: ffffc90001ce044c port reserved reg = 0x0 [14254.220791] xhci_hcd 0000:04:00.0: ffffc90001ce0450 port status reg = 0x2a0 [14254.220794] xhci_hcd 0000:04:00.0: ffffc90001ce0454 port power reg = 0x0 [14254.220798] xhci_hcd 0000:04:00.0: ffffc90001ce0458 port link reg = 0x0 [14254.220801] xhci_hcd 0000:04:00.0: ffffc90001ce045c port reserved reg = 0x0 [14254.220803] xhci_hcd 0000:04:00.0: // Halt the HC [14254.220808] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0020, 32'h0, 4'hf); [14254.220812] xhci_hcd 0000:04:00.0: Resetting HCD [14254.220814] xhci_hcd 0000:04:00.0: // Reset the HC [14254.220817] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0020, 32'h2, 4'hf); [14254.220824] xhci_hcd 0000:04:00.0: Wait for controller to be ready for doorbell rings [14254.220827] xhci_hcd 0000:04:00.0: Reset complete [14254.220830] xhci_hcd 0000:04:00.0: Enabling 64-bit DMA addresses. [14254.220831] xhci_hcd 0000:04:00.0: Calling HCD init [14254.220832] xhci_hcd 0000:04:00.0: xhci_init [14254.220833] xhci_hcd 0000:04:00.0: xHCI doesn't need link TRB QUIRK [14254.220836] xhci_hcd 0000:04:00.0: Supported page size register = 0x1 [14254.220837] xhci_hcd 0000:04:00.0: Supported page size of 4K [14254.220838] xhci_hcd 0000:04:00.0: HCD page size set to 4K [14254.220841] xhci_hcd 0000:04:00.0: // xHC can handle at most 64 device slots. [14254.220844] xhci_hcd 0000:04:00.0: // Setting Max device slots reg = 0x40. [14254.220845] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0058, 32'h40, 4'hf); [14254.220849] xhci_hcd 0000:04:00.0: // Device context base array address = 0xbac41000 (DMA), ffff8800bac41000 (virt) [14254.220850] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce0050, 64'hbac41000, 4'hf); [14254.220853] xhci_hcd 0000:04:00.0: Allocating ring at ffff88022fb25180 [14254.220855] xhci_hcd 0000:04:00.0: Allocating priv segment structure at ffff8801c2f455e0 [14254.220857] xhci_hcd 0000:04:00.0: // Allocating segment at ffff8800bac45000 (virtual) 0xbac45000 (DMA) [14254.220861] xhci_hcd 0000:04:00.0: Linking segment 0xbac45000 to segment 0xbac45000 (DMA) [14254.220862] xhci_hcd 0000:04:00.0: Wrote link toggle flag to segment ffff8801c2f455e0 (virtual), 0xbac45000 (DMA) [14254.220863] xhci_hcd 0000:04:00.0: Allocated command ring at ffff88022fb25180 [14254.220864] xhci_hcd 0000:04:00.0: First segment DMA is 0xbac45000 [14254.220869] xhci_hcd 0000:04:00.0: // Setting command ring address to 0x40 [14254.220870] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce0038, 64'hbac45001, 4'hf); [14254.220876] xhci_hcd 0000:04:00.0: // xHC command ring deq ptr low bits + flags = @00000000 [14254.220877] xhci_hcd 0000:04:00.0: // xHC command ring deq ptr high bits = @00000000 [14254.220880] xhci_hcd 0000:04:00.0: // Doorbell array is located at offset 0x3000 from cap regs base addr [14254.220881] xhci_hcd 0000:04:00.0: // xHCI capability registers at ffffc90001ce0000: [14254.220884] xhci_hcd 0000:04:00.0: // @ffffc90001ce0000 = 0x1000020 (CAPLENGTH AND HCIVERSION) [14254.220885] xhci_hcd 0000:04:00.0: // CAPLENGTH: 0x20 [14254.220886] xhci_hcd 0000:04:00.0: // xHCI operational registers at ffffc90001ce0020: [14254.220889] xhci_hcd 0000:04:00.0: // @ffffc90001ce0018 = 0x2000 RTSOFF [14254.220890] xhci_hcd 0000:04:00.0: // xHCI runtime registers at ffffc90001ce2000: [14254.220893] xhci_hcd 0000:04:00.0: // @ffffc90001ce0014 = 0x3000 DBOFF [14254.220894] xhci_hcd 0000:04:00.0: // Doorbell array at ffffc90001ce3000: [14254.220895] xhci_hcd 0000:04:00.0: xHCI runtime registers at ffffc90001ce2000: [14254.220899] xhci_hcd 0000:04:00.0: ffffc90001ce2000: Microframe index = 0x0 [14254.220915] xhci_hcd 0000:04:00.0: // Allocating event ring [14254.220917] xhci_hcd 0000:04:00.0: Allocating ring at ffff88022fb25ea0 [14254.220918] xhci_hcd 0000:04:00.0: Allocating priv segment structure at ffff8801c2f45a00 [14254.220919] xhci_hcd 0000:04:00.0: // Allocating segment at ffff8800bac45400 (virtual) 0xbac45400 (DMA) [14254.220920] xhci_hcd 0000:04:00.0: Linking segment 0xbac45400 to segment 0xbac45400 (DMA) [14254.220922] xhci_hcd 0000:04:00.0: TRB math tests passed. [14254.220924] xhci_hcd 0000:04:00.0: // Allocated event ring segment table at 0xbac44000 [14254.220925] xhci_hcd 0000:04:00.0: Set ERST to 0; private num segs = 1, virt addr = ffff8800bac44000, dma addr = 0xbac44000 [14254.220928] xhci_hcd 0000:04:00.0: // Write ERST size = 1 to ir_set 0 (some bits preserved) [14254.220929] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce2028, 32'h1, 4'hf); [14254.220930] xhci_hcd 0000:04:00.0: // Set ERST entries to point to event ring. [14254.220931] xhci_hcd 0000:04:00.0: // Set ERST base address for ir_set 0 = 0xbac44000 [14254.220937] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2030, 64'hbac44000, 4'hf); [14254.220942] xhci_hcd 0000:04:00.0: // Write event ring dequeue pointer, preserving EHB bit [14254.220943] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2038, 64'hbac45400, 4'hf); [14254.220944] xhci_hcd 0000:04:00.0: Wrote ERST address to ir_set 0. [14254.220948] xhci_hcd 0000:04:00.0: Allocating 4 scratchpad buffers [14254.220962] xhci_hcd 0000:04:00.0: Ext Cap ffffc90001ce1010, port offset = 1, count = 2, revision = 0x2 [14254.220968] xhci_hcd 0000:04:00.0: Ext Cap ffffc90001ce1020, port offset = 3, count = 2, revision = 0x3 [14254.220969] xhci_hcd 0000:04:00.0: Found 2 USB 2.0 ports and 2 USB 3.0 ports. [14254.220970] xhci_hcd 0000:04:00.0: USB 2.0 port at index 0, addr = ffffc90001ce0420 [14254.220971] xhci_hcd 0000:04:00.0: USB 2.0 port at index 1, addr = ffffc90001ce0430 [14254.220973] xhci_hcd 0000:04:00.0: USB 3.0 port at index 2, addr = ffffc90001ce0440 [14254.220974] xhci_hcd 0000:04:00.0: USB 3.0 port at index 3, addr = ffffc90001ce0450 [14254.220975] xhci_hcd 0000:04:00.0: Finished xhci_init [14254.220976] xhci_hcd 0000:04:00.0: Called HCD init [14254.220980] xhci_hcd 0000:04:00.0: Got SBRN 48 [14254.220988] xhci_hcd 0000:04:00.0: MWI active [14254.220988] xhci_hcd 0000:04:00.0: Finished xhci_pci_reinit [14254.220990] xhci_hcd 0000:04:00.0: supports USB remote wakeup [14254.220998] xhci_hcd 0000:04:00.0: irq 17, io mem 0xfa100000 [14254.220999] xhci_hcd 0000:04:00.0: xhci_run [14254.221025] xhci_hcd 0000:04:00.0: Failed to enable MSI-X [14254.221102] xhci_hcd 0000:04:00.0: irq 47 for MSI/MSI-X [14254.221132] xhci_hcd 0000:04:00.0: Setting event ring polling timer [14254.221135] xhci_hcd 0000:04:00.0: Command ring memory map follows: [14254.221137] xhci_hcd 0000:04:00.0: @bac45000 00000000 00000000 00000000 00000000 [14254.221138] xhci_hcd 0000:04:00.0: @bac45010 00000000 00000000 00000000 00000000 [14254.221139] xhci_hcd 0000:04:00.0: @bac45020 00000000 00000000 00000000 00000000 [14254.221140] xhci_hcd 0000:04:00.0: @bac45030 00000000 00000000 00000000 00000000 [14254.221141] xhci_hcd 0000:04:00.0: @bac45040 00000000 00000000 00000000 00000000 [14254.221142] xhci_hcd 0000:04:00.0: @bac45050 00000000 00000000 00000000 00000000 [14254.221143] xhci_hcd 0000:04:00.0: @bac45060 00000000 00000000 00000000 00000000 [14254.221144] xhci_hcd 0000:04:00.0: @bac45070 00000000 00000000 00000000 00000000 [14254.221145] xhci_hcd 0000:04:00.0: @bac45080 00000000 00000000 00000000 00000000 [14254.221146] xhci_hcd 0000:04:00.0: @bac45090 00000000 00000000 00000000 00000000 [14254.221147] xhci_hcd 0000:04:00.0: @bac450a0 00000000 00000000 00000000 00000000 [14254.221148] xhci_hcd 0000:04:00.0: @bac450b0 00000000 00000000 00000000 00000000 [14254.221149] xhci_hcd 0000:04:00.0: @bac450c0 00000000 00000000 00000000 00000000 [14254.221150] xhci_hcd 0000:04:00.0: @bac450d0 00000000 00000000 00000000 00000000 [14254.221151] xhci_hcd 0000:04:00.0: @bac450e0 00000000 00000000 00000000 00000000 [14254.221152] xhci_hcd 0000:04:00.0: @bac450f0 00000000 00000000 00000000 00000000 [14254.221153] xhci_hcd 0000:04:00.0: @bac45100 00000000 00000000 00000000 00000000 [14254.221154] xhci_hcd 0000:04:00.0: @bac45110 00000000 00000000 00000000 00000000 [14254.221155] xhci_hcd 0000:04:00.0: @bac45120 00000000 00000000 00000000 00000000 [14254.221156] xhci_hcd 0000:04:00.0: @bac45130 00000000 00000000 00000000 00000000 [14254.221157] xhci_hcd 0000:04:00.0: @bac45140 00000000 00000000 00000000 00000000 [14254.221158] xhci_hcd 0000:04:00.0: @bac45150 00000000 00000000 00000000 00000000 [14254.221159] xhci_hcd 0000:04:00.0: @bac45160 00000000 00000000 00000000 00000000 [14254.221160] xhci_hcd 0000:04:00.0: @bac45170 00000000 00000000 00000000 00000000 [14254.221161] xhci_hcd 0000:04:00.0: @bac45180 00000000 00000000 00000000 00000000 [14254.221162] xhci_hcd 0000:04:00.0: @bac45190 00000000 00000000 00000000 00000000 [14254.221163] xhci_hcd 0000:04:00.0: @bac451a0 00000000 00000000 00000000 00000000 [14254.221164] xhci_hcd 0000:04:00.0: @bac451b0 00000000 00000000 00000000 00000000 [14254.221165] xhci_hcd 0000:04:00.0: @bac451c0 00000000 00000000 00000000 00000000 [14254.221166] xhci_hcd 0000:04:00.0: @bac451d0 00000000 00000000 00000000 00000000 [14254.221167] xhci_hcd 0000:04:00.0: @bac451e0 00000000 00000000 00000000 00000000 [14254.221168] xhci_hcd 0000:04:00.0: @bac451f0 00000000 00000000 00000000 00000000 [14254.221169] xhci_hcd 0000:04:00.0: @bac45200 00000000 00000000 00000000 00000000 [14254.221170] xhci_hcd 0000:04:00.0: @bac45210 00000000 00000000 00000000 00000000 [14254.221171] xhci_hcd 0000:04:00.0: @bac45220 00000000 00000000 00000000 00000000 [14254.221172] xhci_hcd 0000:04:00.0: @bac45230 00000000 00000000 00000000 00000000 [14254.221173] xhci_hcd 0000:04:00.0: @bac45240 00000000 00000000 00000000 00000000 [14254.221174] xhci_hcd 0000:04:00.0: @bac45250 00000000 00000000 00000000 00000000 [14254.221175] xhci_hcd 0000:04:00.0: @bac45260 00000000 00000000 00000000 00000000 [14254.221176] xhci_hcd 0000:04:00.0: @bac45270 00000000 00000000 00000000 00000000 [14254.221177] xhci_hcd 0000:04:00.0: @bac45280 00000000 00000000 00000000 00000000 [14254.221178] xhci_hcd 0000:04:00.0: @bac45290 00000000 00000000 00000000 00000000 [14254.221179] xhci_hcd 0000:04:00.0: @bac452a0 00000000 00000000 00000000 00000000 [14254.221180] xhci_hcd 0000:04:00.0: @bac452b0 00000000 00000000 00000000 00000000 [14254.221181] xhci_hcd 0000:04:00.0: @bac452c0 00000000 00000000 00000000 00000000 [14254.221182] xhci_hcd 0000:04:00.0: @bac452d0 00000000 00000000 00000000 00000000 [14254.221183] xhci_hcd 0000:04:00.0: @bac452e0 00000000 00000000 00000000 00000000 [14254.221184] xhci_hcd 0000:04:00.0: @bac452f0 00000000 00000000 00000000 00000000 [14254.221185] xhci_hcd 0000:04:00.0: @bac45300 00000000 00000000 00000000 00000000 [14254.221186] xhci_hcd 0000:04:00.0: @bac45310 00000000 00000000 00000000 00000000 [14254.221187] xhci_hcd 0000:04:00.0: @bac45320 00000000 00000000 00000000 00000000 [14254.221188] xhci_hcd 0000:04:00.0: @bac45330 00000000 00000000 00000000 00000000 [14254.221189] xhci_hcd 0000:04:00.0: @bac45340 00000000 00000000 00000000 00000000 [14254.221190] xhci_hcd 0000:04:00.0: @bac45350 00000000 00000000 00000000 00000000 [14254.221191] xhci_hcd 0000:04:00.0: @bac45360 00000000 00000000 00000000 00000000 [14254.221192] xhci_hcd 0000:04:00.0: @bac45370 00000000 00000000 00000000 00000000 [14254.221193] xhci_hcd 0000:04:00.0: @bac45380 00000000 00000000 00000000 00000000 [14254.221194] xhci_hcd 0000:04:00.0: @bac45390 00000000 00000000 00000000 00000000 [14254.221195] xhci_hcd 0000:04:00.0: @bac453a0 00000000 00000000 00000000 00000000 [14254.221196] xhci_hcd 0000:04:00.0: @bac453b0 00000000 00000000 00000000 00000000 [14254.221197] xhci_hcd 0000:04:00.0: @bac453c0 00000000 00000000 00000000 00000000 [14254.221198] xhci_hcd 0000:04:00.0: @bac453d0 00000000 00000000 00000000 00000000 [14254.221199] xhci_hcd 0000:04:00.0: @bac453e0 00000000 00000000 00000000 00000000 [14254.221200] xhci_hcd 0000:04:00.0: @bac453f0 bac45000 00000000 00000000 00001802 [14254.221201] xhci_hcd 0000:04:00.0: Ring has not been updated [14254.221202] xhci_hcd 0000:04:00.0: Ring deq = ffff8800bac45000 (virt), 0xbac45000 (dma) [14254.221203] xhci_hcd 0000:04:00.0: Ring deq updated 0 times [14254.221204] xhci_hcd 0000:04:00.0: Ring enq = ffff8800bac45000 (virt), 0xbac45000 (dma) [14254.221205] xhci_hcd 0000:04:00.0: Ring enq updated 0 times [14254.221210] xhci_hcd 0000:04:00.0: // xHC command ring deq ptr low bits + flags = @00000000 [14254.221211] xhci_hcd 0000:04:00.0: // xHC command ring deq ptr high bits = @00000000 [14254.221212] xhci_hcd 0000:04:00.0: ERST memory map follows: [14254.221213] xhci_hcd 0000:04:00.0: @bac44000 bac45400 00000000 00000040 00000000 [14254.221214] xhci_hcd 0000:04:00.0: Event ring: [14254.221215] xhci_hcd 0000:04:00.0: @bac45400 00000000 00000000 00000000 00000000 [14254.221216] xhci_hcd 0000:04:00.0: @bac45410 00000000 00000000 00000000 00000000 [14254.221217] xhci_hcd 0000:04:00.0: @bac45420 00000000 00000000 00000000 00000000 [14254.221218] xhci_hcd 0000:04:00.0: @bac45430 00000000 00000000 00000000 00000000 [14254.221219] xhci_hcd 0000:04:00.0: @bac45440 00000000 00000000 00000000 00000000 [14254.221220] xhci_hcd 0000:04:00.0: @bac45450 00000000 00000000 00000000 00000000 [14254.221221] xhci_hcd 0000:04:00.0: @bac45460 00000000 00000000 00000000 00000000 [14254.221222] xhci_hcd 0000:04:00.0: @bac45470 00000000 00000000 00000000 00000000 [14254.221223] xhci_hcd 0000:04:00.0: @bac45480 00000000 00000000 00000000 00000000 [14254.221224] xhci_hcd 0000:04:00.0: @bac45490 00000000 00000000 00000000 00000000 [14254.221225] xhci_hcd 0000:04:00.0: @bac454a0 00000000 00000000 00000000 00000000 [14254.221227] xhci_hcd 0000:04:00.0: @bac454b0 00000000 00000000 00000000 00000000 [14254.221228] xhci_hcd 0000:04:00.0: @bac454c0 00000000 00000000 00000000 00000000 [14254.221229] xhci_hcd 0000:04:00.0: @bac454d0 00000000 00000000 00000000 00000000 [14254.221230] xhci_hcd 0000:04:00.0: @bac454e0 00000000 00000000 00000000 00000000 [14254.221231] xhci_hcd 0000:04:00.0: @bac454f0 00000000 00000000 00000000 00000000 [14254.221232] xhci_hcd 0000:04:00.0: @bac45500 00000000 00000000 00000000 00000000 [14254.221233] xhci_hcd 0000:04:00.0: @bac45510 00000000 00000000 00000000 00000000 [14254.221234] xhci_hcd 0000:04:00.0: @bac45520 00000000 00000000 00000000 00000000 [14254.221235] xhci_hcd 0000:04:00.0: @bac45530 00000000 00000000 00000000 00000000 [14254.221236] xhci_hcd 0000:04:00.0: @bac45540 00000000 00000000 00000000 00000000 [14254.221237] xhci_hcd 0000:04:00.0: @bac45550 00000000 00000000 00000000 00000000 [14254.221238] xhci_hcd 0000:04:00.0: @bac45560 00000000 00000000 00000000 00000000 [14254.221239] xhci_hcd 0000:04:00.0: @bac45570 00000000 00000000 00000000 00000000 [14254.221240] xhci_hcd 0000:04:00.0: @bac45580 00000000 00000000 00000000 00000000 [14254.221241] xhci_hcd 0000:04:00.0: @bac45590 00000000 00000000 00000000 00000000 [14254.221242] xhci_hcd 0000:04:00.0: @bac455a0 00000000 00000000 00000000 00000000 [14254.221243] xhci_hcd 0000:04:00.0: @bac455b0 00000000 00000000 00000000 00000000 [14254.221244] xhci_hcd 0000:04:00.0: @bac455c0 00000000 00000000 00000000 00000000 [14254.221245] xhci_hcd 0000:04:00.0: @bac455d0 00000000 00000000 00000000 00000000 [14254.221246] xhci_hcd 0000:04:00.0: @bac455e0 00000000 00000000 00000000 00000000 [14254.221247] xhci_hcd 0000:04:00.0: @bac455f0 00000000 00000000 00000000 00000000 [14254.221248] xhci_hcd 0000:04:00.0: @bac45600 00000000 00000000 00000000 00000000 [14254.221249] xhci_hcd 0000:04:00.0: @bac45610 00000000 00000000 00000000 00000000 [14254.221250] xhci_hcd 0000:04:00.0: @bac45620 00000000 00000000 00000000 00000000 [14254.221251] xhci_hcd 0000:04:00.0: @bac45630 00000000 00000000 00000000 00000000 [14254.221252] xhci_hcd 0000:04:00.0: @bac45640 00000000 00000000 00000000 00000000 [14254.221253] xhci_hcd 0000:04:00.0: @bac45650 00000000 00000000 00000000 00000000 [14254.221254] xhci_hcd 0000:04:00.0: @bac45660 00000000 00000000 00000000 00000000 [14254.221255] xhci_hcd 0000:04:00.0: @bac45670 00000000 00000000 00000000 00000000 [14254.221256] xhci_hcd 0000:04:00.0: @bac45680 00000000 00000000 00000000 00000000 [14254.221257] xhci_hcd 0000:04:00.0: @bac45690 00000000 00000000 00000000 00000000 [14254.221258] xhci_hcd 0000:04:00.0: @bac456a0 00000000 00000000 00000000 00000000 [14254.221259] xhci_hcd 0000:04:00.0: @bac456b0 00000000 00000000 00000000 00000000 [14254.221260] xhci_hcd 0000:04:00.0: @bac456c0 00000000 00000000 00000000 00000000 [14254.221261] xhci_hcd 0000:04:00.0: @bac456d0 00000000 00000000 00000000 00000000 [14254.221262] xhci_hcd 0000:04:00.0: @bac456e0 00000000 00000000 00000000 00000000 [14254.221263] xhci_hcd 0000:04:00.0: @bac456f0 00000000 00000000 00000000 00000000 [14254.221264] xhci_hcd 0000:04:00.0: @bac45700 00000000 00000000 00000000 00000000 [14254.221265] xhci_hcd 0000:04:00.0: @bac45710 00000000 00000000 00000000 00000000 [14254.221266] xhci_hcd 0000:04:00.0: @bac45720 00000000 00000000 00000000 00000000 [14254.221267] xhci_hcd 0000:04:00.0: @bac45730 00000000 00000000 00000000 00000000 [14254.221268] xhci_hcd 0000:04:00.0: @bac45740 00000000 00000000 00000000 00000000 [14254.221269] xhci_hcd 0000:04:00.0: @bac45750 00000000 00000000 00000000 00000000 [14254.221270] xhci_hcd 0000:04:00.0: @bac45760 00000000 00000000 00000000 00000000 [14254.221271] xhci_hcd 0000:04:00.0: @bac45770 00000000 00000000 00000000 00000000 [14254.221272] xhci_hcd 0000:04:00.0: @bac45780 00000000 00000000 00000000 00000000 [14254.221273] xhci_hcd 0000:04:00.0: @bac45790 00000000 00000000 00000000 00000000 [14254.221274] xhci_hcd 0000:04:00.0: @bac457a0 00000000 00000000 00000000 00000000 [14254.221275] xhci_hcd 0000:04:00.0: @bac457b0 00000000 00000000 00000000 00000000 [14254.221276] xhci_hcd 0000:04:00.0: @bac457c0 00000000 00000000 00000000 00000000 [14254.221277] xhci_hcd 0000:04:00.0: @bac457d0 00000000 00000000 00000000 00000000 [14254.221278] xhci_hcd 0000:04:00.0: @bac457e0 00000000 00000000 00000000 00000000 [14254.221279] xhci_hcd 0000:04:00.0: @bac457f0 00000000 00000000 00000000 00000000 [14254.221280] xhci_hcd 0000:04:00.0: Ring has not been updated [14254.221281] xhci_hcd 0000:04:00.0: Ring deq = ffff8800bac45400 (virt), 0xbac45400 (dma) [14254.221282] xhci_hcd 0000:04:00.0: Ring deq updated 0 times [14254.221283] xhci_hcd 0000:04:00.0: Ring enq = ffff8800bac45400 (virt), 0xbac45400 (dma) [14254.221284] xhci_hcd 0000:04:00.0: Ring enq updated 0 times [14254.221289] xhci_hcd 0000:04:00.0: ERST deq = 64'hbac45400 [14254.221290] xhci_hcd 0000:04:00.0: // Set the interrupt modulation register [14254.221293] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce2024, 32'ha0, 4'hf); [14254.221296] xhci_hcd 0000:04:00.0: // Enable interrupts, cmd = 0x4. [14254.221297] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0020, 32'h4, 4'hf); [14254.221300] xhci_hcd 0000:04:00.0: // Enabling event ring interrupter ffffc90001ce2020 by writing 0x2 to irq_pending [14254.221301] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce2020, 32'h2, 4'hf); [14254.221305] xhci_hcd 0000:04:00.0: ffffc90001ce2020: ir_set[0] [14254.221306] xhci_hcd 0000:04:00.0: ffffc90001ce2020: ir_set.pending = 0x2 [14254.221309] xhci_hcd 0000:04:00.0: ffffc90001ce2024: ir_set.control = 0xa0 [14254.221312] xhci_hcd 0000:04:00.0: ffffc90001ce2028: ir_set.erst_size = 0x1 [14254.221319] xhci_hcd 0000:04:00.0: ffffc90001ce2030: ir_set.erst_base = @bac44000 [14254.221325] xhci_hcd 0000:04:00.0: ffffc90001ce2038: ir_set.erst_dequeue = @bac45400 [14254.221326] xhci_hcd 0000:04:00.0: Finished xhci_run for USB2 roothub [14254.221353] usb usb3: default language 0x0409 [14254.221357] usb usb3: udev 1, busnum 3, minor = 256 [14254.221359] usb usb3: New USB device found, idVendor=1d6b, idProduct=0002 [14254.221360] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [14254.221361] usb usb3: Product: xHCI Host Controller [14254.221362] usb usb3: Manufacturer: Linux 2.6.39-patser+ xhci_hcd [14254.221363] usb usb3: SerialNumber: 0000:04:00.0 [14254.221627] usb usb3: usb_probe_device [14254.221633] usb usb3: configuration #1 chosen from 1 choice [14254.221642] xHCI xhci_add_endpoint called for root hub [14254.221644] xHCI xhci_check_bandwidth called for root hub [14254.221652] usb usb3: adding 3-0:1.0 (config #1, interface 0) [14254.221684] hub 3-0:1.0: usb_probe_interface [14254.221686] hub 3-0:1.0: usb_probe_interface - got id [14254.221689] hub 3-0:1.0: USB hub found [14254.221702] hub 3-0:1.0: 2 ports detected [14254.221704] hub 3-0:1.0: standalone hub [14254.221705] hub 3-0:1.0: individual port power switching [14254.221705] hub 3-0:1.0: individual port over-current protection [14254.221706] hub 3-0:1.0: Single TT [14254.221707] hub 3-0:1.0: TT requires at most 8 FS bit times (666 ns) [14254.221708] hub 3-0:1.0: power on to power good time: 20ms [14254.221712] hub 3-0:1.0: local power source is good [14254.221714] hub 3-0:1.0: enabling power on all ports [14254.221719] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0420, 32'h2e1, 4'hf); [14254.221723] xhci_hcd 0000:04:00.0: set port power, actual port 0 status = 0x202e1 [14254.221730] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0430, 32'h2a0, 4'hf); [14254.221734] xhci_hcd 0000:04:00.0: set port power, actual port 1 status = 0x2a0 [14254.221799] xhci_hcd 0000:04:00.0: xHCI Host Controller [14254.221803] xhci_hcd 0000:04:00.0: new USB bus registered, assigned bus number 4 [14254.228707] xhci_hcd 0000:04:00.0: Enabling 64-bit DMA addresses. [14254.228710] xhci_hcd 0000:04:00.0: supports USB remote wakeup [14254.228714] xhci_hcd 0000:04:00.0: // Turn on HC, cmd = 0x5. [14254.228715] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0020, 32'h5, 4'hf); [14254.228718] xhci_hcd 0000:04:00.0: Finished xhci_run for USB3 roothub [14254.228728] xhci_hcd 0000:04:00.0: op reg status = 00000018 [14254.228730] usb usb4: skipped 1 descriptor after endpoint [14254.228731] xhci_hcd 0000:04:00.0: Event ring dequeue ptr: [14254.228732] usb usb4: default language 0x0409 [14254.228734] xhci_hcd 0000:04:00.0: @bac45400 01000000 00000000 01000000 00008801 [14254.228735] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0024, 32'h18, 4'hf); [14254.228736] usb usb4: udev 1, busnum 4, minor = 384 [14254.228737] usb usb4: New USB device found, idVendor=1d6b, idProduct=0003 [14254.228738] usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [14254.228739] usb usb4: Product: xHCI Host Controller [14254.228740] usb usb4: Manufacturer: Linux 2.6.39-patser+ xhci_hcd [14254.228741] usb usb4: SerialNumber: 0000:04:00.0 [14254.228742] xhci_hcd 0000:04:00.0: In xhci_handle_event [14254.228743] xhci_hcd 0000:04:00.0: xhci_handle_event - OS owns TRB [14254.228744] xhci_hcd 0000:04:00.0: xhci_handle_event - calling handle_port_status [14254.228745] xhci_hcd 0000:04:00.0: Port Status Change Event for port 1 [14254.228749] xhci_hcd 0000:04:00.0: Event ring deq = 0xbac45410 (DMA) [14254.228755] xhci_hcd 0000:04:00.0: xhci_handle_event - returned from handle_port_status [14254.228756] xhci_hcd 0000:04:00.0: In xhci_handle_event [14254.228760] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2038, 64'hbac45418, 4'hf); [14254.228805] usb usb4: usb_probe_device [14254.228806] usb usb4: configuration #1 chosen from 1 choice [14254.228809] xHCI xhci_add_endpoint called for root hub [14254.228810] xHCI xhci_check_bandwidth called for root hub [14254.228813] usb usb4: adding 4-0:1.0 (config #1, interface 0) [14254.228826] hub 4-0:1.0: usb_probe_interface [14254.228827] hub 4-0:1.0: usb_probe_interface - got id [14254.228828] hub 4-0:1.0: USB hub found [14254.228834] hub 4-0:1.0: 2 ports detected [14254.228835] hub 4-0:1.0: standalone hub [14254.228836] hub 4-0:1.0: individual port power switching [14254.228837] hub 4-0:1.0: individual port over-current protection [14254.228838] hub 4-0:1.0: TT requires at most 8 FS bit times (666 ns) [14254.228839] hub 4-0:1.0: power on to power good time: 20ms [14254.228841] hub 4-0:1.0: local power source is good [14254.228842] hub 4-0:1.0: enabling power on all ports [14254.228846] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0440, 32'h2a0, 4'hf); [14254.228849] xhci_hcd 0000:04:00.0: set port power, actual port 0 status = 0x2a0 [14254.228855] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0450, 32'h2a0, 4'hf); [14254.228859] xhci_hcd 0000:04:00.0: set port power, actual port 1 status = 0x2a0 [14254.321691] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x202e1 [14254.321697] xhci_hcd 0000:04:00.0: Get port status returned 0x10101 [14254.321703] hub 3-0:1.0: port 1: status 0101 change 0001 [14254.321709] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0420, 32'h202e1, 4'hf); [14254.321713] xhci_hcd 0000:04:00.0: clear port connect change, actual port 0 status = 0x2e1 [14254.321717] xhci_hcd 0000:04:00.0: get port status, actual port 1 status = 0x2a0 [14254.321718] xhci_hcd 0000:04:00.0: Get port status returned 0x100 [14254.328682] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x2a0 [14254.328687] xhci_hcd 0000:04:00.0: Get port status returned 0x100 [14254.328696] xhci_hcd 0000:04:00.0: get port status, actual port 1 status = 0x2a0 [14254.328699] xhci_hcd 0000:04:00.0: Get port status returned 0x100 [14254.328713] hub 4-0:1.0: state 7 ports 2 chg 0000 evt 0000 [14254.421740] hub 3-0:1.0: state 7 ports 2 chg 0002 evt 0000 [14254.421768] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x2e1 [14254.421771] xhci_hcd 0000:04:00.0: Get port status returned 0x101 [14254.421779] hub 3-0:1.0: port 1, status 0101, change 0000, 12 Mb/s [14254.421787] xhci_hcd 0000:04:00.0: Endpoint state = 0x1 [14254.421792] xhci_hcd 0000:04:00.0: Command ring enq = 0xbac45010 (DMA) [14254.421793] xhci_hcd 0000:04:00.0: // Ding dong! [14254.421794] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce3000, 32'h0, 4'hf); [14254.421811] xhci_hcd 0000:04:00.0: op reg status = 00000008 [14254.421813] xhci_hcd 0000:04:00.0: Event ring dequeue ptr: [14254.421815] xhci_hcd 0000:04:00.0: @bac45410 bac45000 00000000 01000000 01008401 [14254.421816] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0024, 32'h8, 4'hf); [14254.421820] xhci_hcd 0000:04:00.0: In xhci_handle_event [14254.421821] xhci_hcd 0000:04:00.0: xhci_handle_event - OS owns TRB [14254.421823] xhci_hcd 0000:04:00.0: xhci_handle_event - calling handle_cmd_completion [14254.421827] xhci_hcd 0000:04:00.0: Command ring deq = 0xbac45010 (DMA) [14254.421828] xhci_hcd 0000:04:00.0: xhci_handle_event - returned from handle_cmd_completion [14254.421829] xhci_hcd 0000:04:00.0: Event ring deq = 0xbac45420 (DMA) [14254.421830] xhci_hcd 0000:04:00.0: In xhci_handle_event [14254.421836] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2038, 64'hbac45428, 4'hf); [14254.421850] xhci_hcd 0000:04:00.0: Slot 1 output ctx = 0xa6088000 (dma) [14254.421854] xhci_hcd 0000:04:00.0: Slot 1 input ctx = 0xa60b4000 (dma) [14254.421857] xhci_hcd 0000:04:00.0: Allocating ring at ffff8801c5843de0 [14254.421860] xhci_hcd 0000:04:00.0: Allocating priv segment structure at ffff880216ba3a60 [14254.421863] xhci_hcd 0000:04:00.0: // Allocating segment at ffff8800bac45800 (virtual) 0xbac45800 (DMA) [14254.421867] xhci_hcd 0000:04:00.0: Linking segment 0xbac45800 to segment 0xbac45800 (DMA) [14254.421868] xhci_hcd 0000:04:00.0: Wrote link toggle flag to segment ffff880216ba3a60 (virtual), 0xbac45800 (DMA) [14254.421870] xhci_hcd 0000:04:00.0: Set slot id 1 dcbaa entry ffff8800bac41008 to 0xa6088000 [14254.421889] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0420, 32'h2f1, 4'hf); [14254.421893] xhci_hcd 0000:04:00.0: set port reset, actual port 0 status = 0x2f1 [14254.457707] xhci_hcd 0000:04:00.0: op reg status = 00000018 [14254.457710] xhci_hcd 0000:04:00.0: Event ring dequeue ptr: [14254.457712] xhci_hcd 0000:04:00.0: @bac45420 01000000 00000000 01000000 00008801 [14254.457714] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0024, 32'h18, 4'hf); [14254.457715] xhci_hcd 0000:04:00.0: In xhci_handle_event [14254.457716] xhci_hcd 0000:04:00.0: xhci_handle_event - OS owns TRB [14254.457718] xhci_hcd 0000:04:00.0: xhci_handle_event - calling handle_port_status [14254.457719] xhci_hcd 0000:04:00.0: Port Status Change Event for port 1 [14254.457725] xhci_hcd 0000:04:00.0: Event ring deq = 0xbac45430 (DMA) [14254.457732] xhci_hcd 0000:04:00.0: xhci_handle_event - returned from handle_port_status [14254.457733] xhci_hcd 0000:04:00.0: In xhci_handle_event [14254.457739] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2038, 64'hbac45438, 4'hf); [14254.472687] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x200603 [14254.472692] xhci_hcd 0000:04:00.0: Get port status returned 0x103 [14254.523694] xhci_hcd 0000:04:00.0: Resetting device with slot ID 1 [14254.523700] xhci_hcd 0000:04:00.0: Endpoint state = 0x1 [14254.523702] xhci_hcd 0000:04:00.0: Command ring enq = 0xbac45020 (DMA) [14254.523703] xhci_hcd 0000:04:00.0: // Ding dong! [14254.523704] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce3000, 32'h0, 4'hf); [14254.523714] xhci_hcd 0000:04:00.0: op reg status = 00000008 [14254.523716] xhci_hcd 0000:04:00.0: Event ring dequeue ptr: [14254.523717] xhci_hcd 0000:04:00.0: @bac45430 bac45010 00000000 c0000000 01008401 [14254.523718] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0024, 32'h8, 4'hf); [14254.523720] xhci_hcd 0000:04:00.0: In xhci_handle_event [14254.523720] xhci_hcd 0000:04:00.0: xhci_handle_event - OS owns TRB [14254.523721] xhci_hcd 0000:04:00.0: xhci_handle_event - calling handle_cmd_completion [14254.523723] xhci_hcd 0000:04:00.0: Completed reset device command. [14254.523725] xhci_hcd 0000:04:00.0: Command ring deq = 0xbac45020 (DMA) [14254.523726] xhci_hcd 0000:04:00.0: xhci_handle_event - returned from handle_cmd_completion [14254.523727] xhci_hcd 0000:04:00.0: Unknown completion code 192 for reset device command. [14254.523729] xhci_hcd 0000:04:00.0: Event ring deq = 0xbac45440 (DMA) [14254.523730] usb 3-1: Cannot reset HCD device state [14254.523731] hub 3-0:1.0: port 1 not enabled, trying reset again... [14254.523732] xhci_hcd 0000:04:00.0: In xhci_handle_event [14254.523737] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 64'hffffc90001ce2038, 64'hbac45448, 4'hf); [14254.523742] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0420, 32'h611, 4'hf); [14254.523746] xhci_hcd 0000:04:00.0: set port reset, actual port 0 status = 0x2006f1 [14254.724682] xhci_hcd 0000:04:00.0: get port status, actual port 0 status = 0x200603 [14254.724688] xhci_hcd 0000:04:00.0: Get port status returned 0x103 [14254.775660] xhci_hcd 0000:04:00.0: Resetting device with slot ID 1 [14254.775666] xhci_hcd 0000:04:00.0: Endpoint state = 0x1 [14254.775668] xhci_hcd 0000:04:00.0: Command ring enq = 0xbac45030 (DMA) [14254.775669] xhci_hcd 0000:04:00.0: // Ding dong! [14254.775670] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce3000, 32'h0, 4'hf); [14254.775680] xhci_hcd 0000:04:00.0: op reg status = 00000008 [14254.775681] xhci_hcd 0000:04:00.0: Event ring dequeue ptr: [14254.775683] xhci_hcd 0000:04:00.0: @bac45440 bac45020 00000000 c0000000 01008401 [14254.775684] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0024, 32'h8, 4'hf); [14254.775685] xhci_hcd 0000:04:00.0: In xhci_handle_event [14254.775686] xhci_hcd 0000:04:00.0: xhci_handle_event - OS owns TRB [14254.775687] xhci_hcd 0000:04:00.0: xhci_handle_event - calling handle_cmd_completion [14254.775688] xhci_hcd 0000:04:00.0: Completed reset device command. [14254.775690] xhci_hcd 0000:04:00.0: Command ring deq = 0xbac45030 (DMA) [14254.775691] xhci_hcd 0000:04:00.0: Unknown completion code 192 for reset device command. [14254.775692] xhci_hcd 0000:04:00.0: xhci_handle_event - returned from handle_cmd_completion [14254.775693] usb 3-1: Cannot reset HCD device state [14254.775694] hub 3-0:1.0: port 1 not enabled, trying reset again... ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH] [RFC] usb: Do not attempt to reset the device while it is disabled 2011-05-31 22:35 ` Sarah Sharp 2011-05-31 22:55 ` Maarten Lankhorst @ 2011-05-31 23:57 ` Maarten Lankhorst 2011-06-01 19:39 ` Sarah Sharp 1 sibling, 1 reply; 11+ messages in thread From: Maarten Lankhorst @ 2011-05-31 23:57 UTC (permalink / raw) To: Sarah Sharp; +Cc: Xu, Andiry, linux-usb, linux-kernel Op 01-06-11 00:35, Sarah Sharp schreef: > On Tue, May 31, 2011 at 09:07:32PM +0200, Maarten Lankhorst wrote: >> Op 31-05-11 20:18, Sarah Sharp schreef: >>> On Tue, May 31, 2011 at 07:41:14PM +0200, Maarten Lankhorst wrote: >> My xhci controller is this one: >> 04:00.0 USB Controller: Device 1b6f:7023 (rev 01) (prog-if 30 [XHCI]) >> Subsystem: ASRock Incorporation Device 7023 > Ok, the PCI SIGG says that vendor ID is assigned to Etron. Congrats, > that's the first xHCI host controller I've seen from that company. :) Hooray. > Ok, so the xHCI driver does successfully get a slot from the host > controller. > >> [ 545.664041] xhci_hcd 0000:04:00.0: Allocating ring at ffff8801c7d7ccc0 >> [ 545.664044] xhci_hcd 0000:04:00.0: Allocating priv segment structure at ffff8801e2e26c40 >> [ 545.664047] xhci_hcd 0000:04:00.0: // Allocating segment at ffff8800bac3f800 (virtual) 0xbac3f800 (DMA) >> [ 545.664053] xhci_hcd 0000:04:00.0: Linking segment 0xbac3f800 to segment 0xbac3f800 (DMA) >> [ 545.664056] xhci_hcd 0000:04:00.0: Wrote link toggle flag to segment ffff8801e2e26c40 (virtual), 0xbac3f800 (DMA) >> [ 545.664059] xhci_hcd 0000:04:00.0: Set slot id 1 dcbaa entry ffff8800bac3e008 to 0xbac21000 >> [ 545.664070] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0420, 32'h2f1, 4'hf); > But I don't see an Address Device command complete here. The command > submission probably caused that memory write, but there really should be > more debugging here. I'll have to look through the hub initialization > and see if there is any error path that would make it skip setting the > device address. > > Have you tried on Linux 3.0-rc1? Same problem with 3.0rc1 it seems. Just look at hub_port_init, that appears to be where it's going wrong: First it calls: retval = hub_port_reset(hub, port1, udev, delay); Which does the device reset.. Then lower in that function: if (udev->wusb == 0) { for (j = 0; j < SET_ADDRESS_TRIES; ++j) { retval = hub_set_address(udev, devnum); if (retval >= 0) break; msleep(200); } It seems to me that is why I get the reset call failing BEFORE the address is set. However I'm unsure what would be a proper fix for it would be. ~Maarten ^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH] [RFC] usb: Do not attempt to reset the device while it is disabled 2011-05-31 23:57 ` Maarten Lankhorst @ 2011-06-01 19:39 ` Sarah Sharp 0 siblings, 0 replies; 11+ messages in thread From: Sarah Sharp @ 2011-06-01 19:39 UTC (permalink / raw) To: Maarten Lankhorst; +Cc: Xu, Andiry, linux-usb, linux-kernel On Wed, Jun 01, 2011 at 01:57:00AM +0200, Maarten Lankhorst wrote: > Op 01-06-11 00:35, Sarah Sharp schreef: > > On Tue, May 31, 2011 at 09:07:32PM +0200, Maarten Lankhorst wrote: > >> Op 31-05-11 20:18, Sarah Sharp schreef: > >>> On Tue, May 31, 2011 at 07:41:14PM +0200, Maarten Lankhorst wrote: > >> My xhci controller is this one: > >> 04:00.0 USB Controller: Device 1b6f:7023 (rev 01) (prog-if 30 [XHCI]) > >> Subsystem: ASRock Incorporation Device 7023 > > Ok, the PCI SIGG says that vendor ID is assigned to Etron. Congrats, > > that's the first xHCI host controller I've seen from that company. :) > Hooray. > > Ok, so the xHCI driver does successfully get a slot from the host > > controller. > > > >> [ 545.664041] xhci_hcd 0000:04:00.0: Allocating ring at ffff8801c7d7ccc0 > >> [ 545.664044] xhci_hcd 0000:04:00.0: Allocating priv segment structure at ffff8801e2e26c40 > >> [ 545.664047] xhci_hcd 0000:04:00.0: // Allocating segment at ffff8800bac3f800 (virtual) 0xbac3f800 (DMA) > >> [ 545.664053] xhci_hcd 0000:04:00.0: Linking segment 0xbac3f800 to segment 0xbac3f800 (DMA) > >> [ 545.664056] xhci_hcd 0000:04:00.0: Wrote link toggle flag to segment ffff8801e2e26c40 (virtual), 0xbac3f800 (DMA) > >> [ 545.664059] xhci_hcd 0000:04:00.0: Set slot id 1 dcbaa entry ffff8800bac3e008 to 0xbac21000 > >> [ 545.664070] xhci_hcd 0000:04:00.0: `MEM_WRITE_DWORD(3'b000, 32'hffffc90001ce0420, 32'h2f1, 4'hf); > > But I don't see an Address Device command complete here. The command > > submission probably caused that memory write, but there really should be > > more debugging here. I'll have to look through the hub initialization > > and see if there is any error path that would make it skip setting the > > device address. > > > > Have you tried on Linux 3.0-rc1? > Same problem with 3.0rc1 it seems. Just look at hub_port_init, that appears to be where it's going wrong: > > First it calls: > retval = hub_port_reset(hub, port1, udev, delay); > > Which does the device reset.. > > Then lower in that function: > if (udev->wusb == 0) { > for (j = 0; j < SET_ADDRESS_TRIES; ++j) { > retval = hub_set_address(udev, devnum); > if (retval >= 0) > break; > msleep(200); > } > > It seems to me that is why I get the reset call failing BEFORE the address is set. However I'm unsure what > would be a proper fix for it would be. I think your second patch was on the right track. It's true that the xHCI driver shouldn't be issuing a Reset Device command before the Address Device command completes. The NEC host controller just handles it as the xHCI specification requires, by giving back a completion code that means the slot is in the enabled/disabled state: [ 127.025732] xhci_hcd 0000:03:00.0: Set slot id 1 dcbaa entry ffff880033853008 to 0x3387c000 [ 127.025771] xhci_hcd 0000:03:00.0: set port reset, actual port 1 status = 0x791 [ 127.080956] xhci_hcd 0000:03:00.0: Port Status Change Event for port 2 [ 127.085207] xhci_hcd 0000:03:00.0: get port status, actual port 1 status = 0x200e03 [ 127.085237] xhci_hcd 0000:03:00.0: Get port status returned 0x100503 [ 127.145059] xhci_hcd 0000:03:00.0: Resetting device with slot ID 1 [ 127.145090] xhci_hcd 0000:03:00.0: // Ding dong! [ 127.145112] xhci_hcd 0000:03:00.0: Command completion. Event ring dequeue ptr: 33854010 00000000 13000000 01008401 [ 127.145122] xhci_hcd 0000:03:00.0: Completed reset device command. [ 127.145163] xhci_hcd 0000:03:00.0: Can't reset device (slot ID 1) in enabled/disabled state [ 127.145172] xhci_hcd 0000:03:00.0: Not freeing device rings. The rings don't get freed, which is fine because there are no rings to free anyway in that case. It's just the Etron host uses a vendor specific error condition, and the xHCI driver doesn't know what to make of it. I'm not inclined to assume that particular error code always means the same thing, so let's not add handling for that code to xhci_discover_or_reset_device(). I think the correct solution is for the xHCI driver does need to check the output context's slot state before issuing a Reset Device command. Can you respin your second patch to only check the slot's dev_state field, and not the state of the control endpoint? Also, please add a #define in xhci.h for the enabled/disabled state instead of hard-coding it to zero. I know that xhci-dbg.c's xhci_get_slot_state() uses hard-coded states, but it shouldn't. Feel free to update it in a separate patch if you have the time. One last thing: please run your patch through checkpatch.pl, as your last one violated kernel coding style WRT to line length and spaces around operators like & and &&. See Documentation/CodingStyle. Sarah Sharp ^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2011-06-01 19:39 UTC | newest] Thread overview: 11+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2011-05-30 9:56 [PATCH] [RFC] usb: Broaden range of vendor codes for xhci Maarten Lankhorst 2011-05-31 0:34 ` Xu, Andiry 2011-05-31 13:47 ` [PATCH] [RFC] usb: Do not attempt to reset the device while it is disabled Maarten Lankhorst 2011-05-31 17:14 ` Sarah Sharp 2011-05-31 17:41 ` Maarten Lankhorst 2011-05-31 18:18 ` Sarah Sharp 2011-05-31 19:07 ` Maarten Lankhorst 2011-05-31 22:35 ` Sarah Sharp 2011-05-31 22:55 ` Maarten Lankhorst 2011-05-31 23:57 ` Maarten Lankhorst 2011-06-01 19:39 ` Sarah Sharp
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox