xhci finding new USB device every second

[beaglejoe]

From my syslog (hrev55711):

KERN: usb hub 7: port 0: new device connected
KERN: usb error xhci 1: AllocateDevice: failed to enable slot
Last message repeated 1 time
KERN: usb hub 7: port 0: new device connected
KERN: usb error xhci 1: AllocateDevice: failed to enable slot
Last message repeated 1 time

Running tail on syslog, this repeats approximately once per second.
The only (externally connected) USB device attached is a wireless keyboard/mouse dongle, which works fine, USB thumbdrives also work fine. Maybe duplicate of #16323

[beaglejoe]

Hardware is an Intel NUC 8

This did not appear in a syslog from hrev55690. It started with hrev55692

[waddlesplash]

That ticket was fixed, this is probably the "underlying problem" I mentioned there. I'm not sure why slots would fail to enable, though, this is an area I'm less familiar with.

[beaglejoe]

It seems to cause no problems (except for bloated syslog). I didn't know if I should set it to "low" priority or if that was for the dev team to decide. I suspect it has always been there and hvre55691 just enabled the trace for it, but I didn't look at the code for that commit.

[waddlesplash]

Looking over the code, it seems there is only one way to get out of this function without an error trace to the syslog, which is that Lock() must be failing. This is extremely strange and should never occur; we should hit some panic asserts in mutex code before that happens; or we have been woken up spuriously with an error condition, which would be strange but I guess is possible.

Can you please upgrade to the latest nightly and re-test this, and see if it still happens, and upload a new syslog if it does?

If it does, can you please show the output of "listimage 1"?

[waddlesplash]

I guess it is also possible we ran out of slots entirely...

[beaglejoe]

Replying to waddlesplash:

Looking over the code, it seems there is only one way to get out of this function without an error trace to the syslog, which is that Lock() must be failing. This is extremely strange and should never occur; we should hit some panic asserts in mutex code before that happens; or we have been woken up spuriously with an error condition, which would be strange but I guess is possible.

Can you please upgrade to the latest nightly and re-test this, and see if it still happens, and upload a new syslog if it does?

If it does, can you please show the output of "listimage 1"?

Updated to hrev55736 via SoftwareUpdater. Attached requested files.

[waddlesplash]

Please see what the error message is after hrev55771.

[beaglejoe]

with hrev55771 (x86-64) I get:

KERN: usb hub 7: port 0: new device connected
KERN: usb error xhci 1: AllocateDevice: failed to enable slot: Operation timed out
Last message repeated 1 time

repeatedly

[waddlesplash]

Please retest under a recent nightly, and upload a new syslog. Please also post the output of "listusb".

[beaglejoe]

Replying to waddlesplash:

Please retest under a recent nightly, and upload a new syslog. Please also post the output of "listusb".

Tested with hrev55959
Still spamming syslog.
Requested files are attached.
Hope it helps.

[waddlesplash]

Ah, so you have 2 XHCI controllers, and it's the second one which keeps hitting these strange timeout problems. The controllers both look pretty similar. Maybe the second one is "stalled" somehow...