I routinely connect and disconnect USB devices many times when debugging and programming firmware. The devices tend to be things like USB to UART adapters, Arduino's, and ISP/JTAG/SWD programmers.
To facilitate this I use a powered hub with individual power buttons. The one I have currently is a J.Burrows 7 Port USB 3.0 Hub:
This allows me to leave several devices plugged in and swap between them with the power button. I have the hub plugged in via its USB-A cable into a port on my Mac Studio running Ventura 13.4.1, with hub power supplied by a dedicated wall wart. I also saw the same behaviour on at least one predecessor Mac desktop (an iMac), though it might have been the same hub.
Inevitably, at some stage one of the devices will fail to enumerate. It powers up, but never appears in the device tree in System Information nor in the /dev/ directory.
Then, plugging the same device into a different port on the same hub succeeds! Eventually it fails in the same way, and I move ports again, until I run out of combinations. The only fix I've found at that point is a system reboot, which resets everything to normal.
There doesn't seem to be a pattern to which device or port fails, or why. But after it fails, if I try again I see this in the Console:
error 21:01:34.461045+1000 kernel AppleUSBXHCICommandRing: AppleUSBXHCICommandRing::executeCommand: command[227] 0x0000000000180000 00000000 58002c01 got result 0x0000000000068e30 04000000 58008400 after 5ms (enqueued 0ms)
error 21:01:34.461061+1000 kernel AppleUSBXHCICommandRing: AppleUSBXHCICommandRing::setAddress: completed with result code 4
error 21:01:34.461258+1000 kernel AppleUSBXHCICommandRing: AppleUSBXHCICommandRing::executeCommand: command[228] 0x0000000000000000 00000000 58013c01 got result 0x0000000000068e40 13000000 58008400 after 0ms (enqueued 0ms)
error 21:01:34.461261+1000 kernel AppleUSBXHCICommandRing: AppleUSBXHCICommandRing::stopEndpoint: completed with result code 19
default 21:01:34.464715+1000 kernel AppleUSB20HubPort@08333400: AppleUSBHostPort::createDevice: failed to create device (0xe00002bc)
default 21:01:34.464724+1000 kernel AppleUSB20HubPort@08333400: AppleUSB20HubPort::resetAndCreateDevice: failed to create device, disabling port
I'm not sure how to debug this further, but the messages lead me to suspect the behaviour is not specific to my hub. Or at least, a potential resolution is not! My theory is that the device behaves badly at some point (plausible, since I'm bringing up devices that are under development), and gets blacklisted by the system. You can imagine how confusing this is when you're debugging a suspect device!
Is there a way to undo the "disabling" of the port mentioned in the error message? Or a way to disprove my theory?
The ideas here made no difference: Reset USB bus without reboot (MacBook ignores display)
Addendum 1: plugging a device that has failed into another port (where it succeeds) produces this in the console, though I'm not sure how much of it is relevant. I haven't caught logs of a device failing, and not sure how I would achieve that.
error 21:31:42.650033+1000 kernel AppleUSBXHCICommandRing: AppleUSBXHCICommandRing::executeCommand: command[236] 0x0000000000000000 00000000 5a013c01 got result 0x0000000000068ec0 13000000 5a008401 after 0ms (enqueued 0ms)
error 21:31:42.650083+1000 kernel AppleUSBXHCICommandRing: AppleUSBXHCICommandRing::stopEndpoint: completed with result code 19
default 21:31:42.671041+1000 heard -[AXHeardController shutdownIfPossible]:337 BT not yet ready, delaying shutdown check
error 21:31:42.681257+1000 kernel AppleUSBXHCIRequest: AppleUSBXHCIRequest::finish: transfer completed with status 0xe0005000
error 21:31:42.682199+1000 kernel IOUSBHostDevice@08332000: IOUSBHostDevice::getDescriptorGated: type 0x03 index 2 length 2 completed with 0xe0005000 bytesTransferred 0 type 0x01
error 21:31:42.683166+1000 kernel AppleUSBXHCIEndpoint: AppleUSBXHCIEndpoint::waitForStateChange: 90-1 endpoint did not start
error 21:31:42.708642+1000 kernel AppleUSBXHCIRequest: AppleUSBXHCIRequest::finish: transfer completed with status 0xe0005000
error 21:31:42.735338+1000 kernel IOUSBHostDevice@08332000: IOUSBHostDevice::getDescriptorGated: type 0x03 index 2 length 2 completed with 0xe0005000 bytesTransferred 0 type 0x01
error 21:31:42.736255+1000 kernel AppleUSBXHCIEndpoint: AppleUSBXHCIEndpoint::waitForStateChange: 90-1 endpoint did not start
error 21:31:42.761735+1000 kernel AppleUSBXHCIRequest: AppleUSBXHCIRequest::finish: transfer completed with status 0xe0005000
error 21:31:42.788460+1000 kernel IOUSBHostDevice@08332000: IOUSBHostDevice::getDescriptorGated: type 0x03 index 2 length 2 completed with 0xe0005000 bytesTransferred 0 type 0x01
error 21:31:42.788499+1000 kernel IOUSBHostDevice@08332000: IOUSBHostDevice::getDescriptorGated: type 0x03 index 2 length 2 completed with 0xe0005000 bytesTransferred 0 type 0x01
error 21:31:42.789357+1000 kernel AppleUSBXHCIEndpoint: AppleUSBXHCIEndpoint::waitForStateChange: 90-1 endpoint did not start
default 21:31:42.817236+1000 kernel AppleUSB20HubPort@08332000: AppleUSBHostPort::enumerateDeviceComplete_block_invoke: enumerated 0x2341/0043/0001 (IOUSBHostDevice / 90) at 12 Mbps
default 21:31:42.820175+1000 kernel IOTimeSyncTimeSyncTimePort(0x9c760e45d22b0008): Other 0xe0034150
default 21:31:42.821959+1000 kernel IOUSBHostDevice@08332000: IOUSBHostDevice::setConfigurationGated: AppleUSBCDCCompositeDevice selected configuration 1
error 21:31:42.822602+1000 kernel IOUSBHostDevice@08332000: IOUSBHostDevice::getDescriptorGated: type 0x03 index 2 length 2 completed with 0xe00002cd bytesTransferred 0 type 0x00
default 21:31:42.825164+1000 kernel IOTimeSyncTimeSyncTimePort(0x9c760e45d22b0008): Other 0xe0034150
default 21:31:42.826144+1000 kernel IOTimeSyncTimeSyncTimePort(0x9c760e45d22b0008): Other 0xe0034150
error 21:31:42.827331+1000 kernel IOUSBHostDevice@08332000: IOUSBHostDevice::getDescriptorGated: type 0x03 index 2 length 2 completed with 0xe00002cd bytesTransferred 0 type 0x00
default 21:31:42.828670+1000 kernelmanagerd Received kext load notification: com.apple.DriverKit.AppleUserECM
error 21:31:42.841610+1000 com.apple.ifdreader Failed to find AppleUSBAlternateServiceRegistryID.
default 21:31:42.844515+1000 kernel Driver com.apple.DriverKit.AppleUserECM has crashed 0 time(s)
default 21:31:42.844578+1000 kernel DK: AppleUserECMData-0x1000053f0 waiting for server com.apple.DriverKit.AppleUserECM.data-1000053f0
default 21:31:42.847119+1000 kernelmanagerd Found 1 dexts with bundle identifier com.apple.DriverKit.AppleUserECM
default 21:31:42.847259+1000 kernelmanagerd Using unique id 7d560a96077260bbdd14afd27f38a79044a066c873ef01c63359cd396d15ed73 to pick dext matching bundle identifier com.apple.DriverKit.AppleUserECM
default 21:31:42.847744+1000 kernelmanagerd Picked matching dext for bundle identifier com.apple.DriverKit.AppleUserECM: Dext com.apple.DriverKit.AppleUserECM v1 in executable dext bundle com.apple.DriverKit.AppleUserECM at /System/Library/DriverExtensions/com.apple.DriverKit.AppleUserECM.dext
default 21:31:42.847873+1000 kernelmanagerd Launching driver extension: Dext com.apple.DriverKit.AppleUserECM v1 in executable dext bundle com.apple.DriverKit.AppleUserECM at /System/Library/DriverExtensions/com.apple.DriverKit.AppleUserECM.dext
default 21:31:42.851361+1000 kernel memorystatus_update(enter): pid 40954, priority 210, dirty=0x0, Active(-1MB NF), Inactive(-1MB, NF)
default 21:31:42.851392+1000 kernel memorystatus_update: init: limit on pid 40954 (-1MB F ) targeting priority(210) dirty?=0x0
default 21:31:42.862335+1000 kernel /System/Library/DriverExtensions/com.apple.DriverKit.AppleUserECM.dext/com.apple.DriverKit.AppleUserECM[40954] ==> com.apple.dext
default 21:31:42.871046+1000 kernel memorystatus_update(enter): pid 40954, priority 150, dirty=0x0, Active(-1MB NF), Inactive(-1MB, NF)
default 21:31:42.871078+1000 kernel memorystatus_update: init: limit on pid 40954 (-1MB F ) targeting priority(150) dirty?=0x0
default 21:31:42.871603+1000 kernelmanagerd <OSLaunchdJob | handle=58015A93-8CB7-4CD3-9E0A-E1BB4AB3A3D9>: submitAndStart completed, info=running, pid=40954
default 21:31:42.874747+1000 kernel Boot args:
default 21:31:42.874773+1000 kernel debug=0x0
default 21:31:42.874839+1000 kernel Found class: IOBufferMemoryDescriptor
default 21:31:42.874844+1000 kernel Found class: IOCommand
default 21:31:42.874847+1000 kernel Found class: IOCommandPool
default 21:31:42.874984+1000 kernel Found class: IODMACommand
default 21:31:42.875046+1000 kernel Found class: IODataQueueDispatchSource
default 21:31:42.875113+1000 kernel Found class: IODispatchQueue
default 21:31:42.875160+1000 kernel Found class: IODispatchSource
default 21:31:42.875222+1000 kernel Found class: IOInterruptDispatchSource
default 21:31:42.875334+1000 kernel Found class: IOMemoryDescriptor
default 21:31:42.875395+1000 kernel Found class: IOMemoryMap
default 21:31:42.875472+1000 kernel Found class: IOReporter
default 21:31:42.875514+1000 kernel Found class: IOSimpleReporter
default 21:31:42.875587+1000 kernel Found class: IOStateReporter
default 21:31:42.875631+1000 kernel Found class: IOHistogramReporter
default 21:31:42.875704+1000 kernel Found class: IOReportLegend
default 21:31:42.875746+1000 kernel Found class: IOService
default 21:31:42.875819+1000 kernel Found class: IOServiceNotificationDispatchSource
default 21:31:42.875864+1000 kernel Found class: IOServiceStateNotificationDispatchSource
default 21:31:42.876364+1000 kernel Found class: IOTimerDispatchSource
default 21:31:42.876451+1000 kernel Found class: IOUserClient
default 21:31:42.876534+1000 kernel Found class: OSAction_IOUserClient_KernelCompletion
default 21:31:42.876580+1000 kernel Found class: IOUserServer
default 21:31:42.876657+1000 kernel Found class: OSAction
default 21:31:42.876703+1000 kernel Found class: OSArray
default 21:31:42.876775+1000 kernel Found class: OSBoolean
default 21:31:42.876820+1000 kernel Found class: OSBundle
default 21:31:42.876899+1000 kernel Found class: OSCollection
default 21:31:42.876985+1000 kernel Found class: OSContainer
default 21:31:42.877028+1000 kernel Found class: OSData
default 21:31:42.877104+1000 kernel Found class: OSDictionary
default 21:31:42.877147+1000 kernel Found class: OSMappedFile
default 21:31:42.877223+1000 kernel Found class: OSNumber
default 21:31:42.877266+1000 kernel Found class: OSObject
default 21:31:42.877341+1000 kernel Found class: OSOrderedSet
default 21:31:42.877386+1000 kernel Found class: OSSerialization
default 21:31:42.877461+1000 kernel Found class: OSSet
default 21:31:42.877505+1000 kernel Found class: OSString
default 21:31:42.877577+1000 kernel Found class: _IOBlockStorageDevice
default 21:31:42.877621+1000 kernel Found class: OSAction__IOBlockStorageDevice_KernelCompletion
default 21:31:42.877693+1000 kernel Found class: IOEventLink
default 21:31:42.877825+1000 kernel Found class: IOThread
default 21:31:42.877907+1000 kernel Found class: IOWorkGroup
default 21:31:42.879080+1000 kernel Found class: AppleUserECMData
default 21:31:42.879131+1000 kernel Found class: AppleUserECM
default 21:31:42.879205+1000 kernel Found class: OSAction_AppleUserECM_TxPacketsAvailable
default 21:31:42.879251+1000 kernel Found class: OSAction_AppleUserECM_RxPacketsAvailable
default 21:31:42.879327+1000 kernel Found class: OSAction_AppleUserECM_TxComplete
default 21:31:42.879635+1000 kernel Found class: OSAction_AppleUserECM_RxComplete
default 21:31:42.880292+1000 kernel Found class: OSAction_AppleUserECM_InterruptReadComplete
default 21:31:42.880321+1000 kernel Found class: OSAction_AppleUserECM_InterruptReadTimerOccurred
default 21:31:42.880343+1000 kernel Found class: IOUserNetworkPacket
default 21:31:42.880350+1000 kernel Found class: IOUserNetworkEthernet
default 21:31:42.880390+1000 kernel Found class: OSAction_IOUserNetworkEthernet__RxSQDataAvailable
default 21:31:42.880403+1000 kernel Found class: OSAction_IOUserNetworkEthernet__TxSQDataAvailable
default 21:31:42.880409+1000 kernel Found class: OSAction_IOUserNetworkEthernet__DataAvailable
default 21:31:42.880414+1000 kernel Found class: IOUserNetworkPacketBufferPool
default 21:31:42.880419+1000 kernel Found class: IOUserNetworkPacketQueue
default 21:31:42.880422+1000 kernel Found class: IOUserNetworkPacketPoller
default 21:31:42.880425+1000 kernel Found class: OSAction_IOUserNetworkPacketPoller_TimerOccurred
default 21:31:42.880430+1000 kernel Found class: IOUserNetworkTxSubmissionQueue
default 21:31:42.880435+1000 kernel Found class: IOUserNetworkTxCompletionQueue
default 21:31:42.880439+1000 kernel Found class: IOUserNetworkQueueSet
default 21:31:42.880445+1000 kernel Found class: IOUserNetworkRxSubmissionQueue
default 21:31:42.880449+1000 kernel Found class: IOUserNetworkRxCompletionQueue
default 21:31:42.880486+1000 kernel Found class: IOUserNetworkLogicalLink
default 21:31:42.880491+1000 kernel Found class: IOUserNetworkWLAN
default 21:31:42.880497+1000 kernel Found class: IOUSBHostPipe
default 21:31:42.880502+1000 kernel Found class: IOUSBHostDevice
default 21:31:42.880506+1000 kernel Found class: IOUSBHostInterface
default 21:31:42.882055+1000 kernel OnQueue SDK version 0x160500
default 21:31:42.883152+1000 kernel no services left, exiting
default 21:31:42.883399+1000 kernel DK: IOUserServer(com.apple.DriverKit.AppleUserECM.data-0x1000053f0)::terminate(AppleUserECMData-0x1000053f0) server exit before start()
default 21:31:42.883529+1000 kernel DK: AppleUserECMData-0x1000053f0::start(IOUSBHostInterface-0x1000053ee) fail
default 21:31:42.886472+1000 contextstored Restart preventer: <private>
default 21:31:43.056178+1000 kernel com.apple.p2p: isInfraRealtimePacketThresholdAllowed allowed:1 option:32 threshold:50 noRegistrations:1 cachedPeerCount:0 fastDiscoveryInactive:1 fastDiscoveryOnSince:32734095
default 21:31:43.056219+1000 kernel com.apple.p2p: currentInfraTrafficType:8087 checking if realtime upgrade required with inputPackets:0 outputPackets:0 packetThreshold:50
error 21:31:43.085110+1000 kernel AppleUSBXHCIRequest: AppleUSBXHCIRequest::finish: transfer completed with status 0xe0005000
error 21:31:43.086055+1000 kernel IOUSBHostDevice@08332000: IOUSBHostDevice::getDescriptorGated: type 0x03 index 2 length 2 completed with 0xe0005000 bytesTransferred 0 type 0x01
error 21:31:43.086185+1000 kernel AppleUSBXHCIRequest: AppleUSBXHCIRequest::finish: transfer completed with status 0xe0005000
error 21:31:43.086973+1000 kernel IOUSBHostDevice@08332000: IOUSBHostDevice::getDescriptorGated: type 0x03 index 2 length 2 completed with 0xe0005000 bytesTransferred 0 type 0x01
error 21:31:43.087095+1000 kernel AppleUSBXHCIRequest: AppleUSBXHCIRequest::finish: transfer completed with status 0xe0005000
error 21:31:43.087908+1000 kernel IOUSBHostDevice@08332000: IOUSBHostDevice::getDescriptorGated: type 0x03 index 2 length 2 completed with 0xe0005000 bytesTransferred 0 type 0x01
error 21:31:43.087925+1000 kernel IOUSBHostDevice@08332000: IOUSBHostDevice::getDescriptorGated: type 0x03 index 2 length 2 completed with 0xe0005000 bytesTransferred 0 type 0x01
default 21:31:43.089976+1000 kernel IOTimeSyncTimeSyncTimePort(0x9c760e45d22b0008): Other 0xe0034150
default 21:31:43.090075+1000 kernel IOTimeSyncTimeSyncTimePort(0x9c760e45d22b0008): Other 0xe0034150
default 21:31:43.090954+1000 kernel IOTimeSyncTimeSyncTimePort(0x9c760e45d22b0008): Other 0xe0034150
error 21:31:43.098866+1000 kernel AppleUSBXHCIRequest: AppleUSBXHCIRequest::finish: transfer completed with status 0xe0005000
default 21:31:43.106508+1000 icdd Device DB | Creating local devices
default 21:31:43.108072+1000 icdd Device DB | Creating bonjour devices
default 21:31:43.108032+1000 kernel Sandbox: icdd(3155) allow file-read-data /Library/Image Capture/Devices
default 21:31:43.108396+1000 icdd => [Matching] | [ 0x00,0x00,0x00 ]
default 21:31:43.108439+1000 icdd Added | 0x100000d0 - [USB][ IOUSBHostDevice ] ( 0, 0, 0) @ 0x8332000 |
default 21:31:43.108555+1000 icdd Autolaunch | 38353133-3833-3133-3933-333335313331 => (null)
default 21:31:43.108586+1000 icdd => [Matching] | [ 0x0a,0x00,0x00 ]
default 21:31:43.108608+1000 icdd Inferior | 0x100000d1 - [USB][ IOUSBHostDevice ] ( a, 0, 0) @ 0x8332000 |
default 21:31:43.108637+1000 icdd => [Matching] | [ 0x02,0x02,0x01 ]
default 21:31:43.108678+1000 icdd Inferior | 0x100000d3 - [USB][ IOUSBHostDevice ] ( 2, 2, 1) @ 0x8332000 |
default 21:31:43.108989+1000 icdd --Local-- | [0000]
default 21:31:43.109009+1000 icdd --Bonjour-- | [0000]
Addendum 2: to cause a failure, it is enough to launch Arduino IDE. In particular, if I plug a device in, use it from the command line (with avrdude), and then launch Arduino IDE, the device disappears from the bus in the manner described in this question.
