[CRASH][v4.4][ESP32-S3] USB root_port_handle_events() aborts when USB device unplugged (IDFGH-7145) #8748

chipweinberger · 2022-04-08T00:30:21Z

ESP32-S3
ESP-IDF release/v4.4 (c29343e) from a few days ago.

Edit: this issue is now tracking a new usb_transfer_t feature. See #9707 to track the abort.

Logs + Backtrace:

E (12638) USBH: Device 1 gone
W (12638) pd usb host service: [client task] device gone! deviceHandle 0x3de4e6e0
I (12648) pd midi 
abort() was called at PC 0x420541ef on core 0
0x420541ef: root_port_handle_events at /components/usb/hub.c:785


Backtrace:0x403762d3:0x3fcb55800x40380a05:0x3fcb55b0 0x4038b825:0x3fcb55e0 0x420541ef:0x3fcb5660 0x42055072:0x3fcb5690 0x4204e428:0x3fcb56c0 0x4201eb27:0x3fcb56f0 0x40385b5e:0x3fcb5720 

0x403762d3: panic_abort at /components/esp_system/panic.c:402

0x40380a05: esp_system_abort at /components/esp_system/esp_system.c:128

0x4038b825: abort at /components/newlib/abort.c:46

0x420541ef: root_port_handle_events at /components/usb/hub.c:785

0x42055072: hub_process at /components/usb/hub.c:986

0x4204e428: usb_host_lib_handle_events at /components/usb/usb_host.c:514

0x4201eb27: PDUsbHostService::usbHostTaskLoop(void*) at /jcommon/usb/PDUsbHostService.cpp:49

0x40385b5e: vPortTaskWrapper at /components/freertos/port/xtensa/port.c:131

Aborts here, in hub.c (in the default case)

        case HCD_PORT_EVENT_OVERCURRENT: {
            bool pass_event_to_usbh = false;
            HUB_DRIVER_ENTER_CRITICAL();
            switch (p_hub_driver_obj->dynamic.driver_state) {
                case HUB_DRIVER_STATE_ROOT_POWERED: //This occurred before enumeration
                case HUB_DRIVER_STATE_ROOT_ENUM_FAILED: //This occurred after a failed enumeration.
                    //Therefore, there's no device and we can go straight to port recovery
                    p_hub_driver_obj->dynamic.flags.actions |= HUB_DRIVER_FLAG_ACTION_PORT_RECOVER;
                    break;
                case HUB_DRIVER_STATE_ROOT_ENUM:
                    //This occurred during enumeration. Therefore, we need to recover the failed enumeration
                    p_hub_driver_obj->dynamic.flags.actions |= HUB_DRIVER_FLAG_ACTION_ENUM_EVENT;
                    p_hub_driver_obj->single_thread.enum_ctrl.stage = ENUM_STAGE_CLEANUP_FAILED;
                    break;
                case HUB_DRIVER_STATE_ROOT_ACTIVE:
                    //There was an enumerated device. We need to indicate to USBH that the device is gone
                    pass_event_to_usbh = true;
                    break;
                default:
                    abort();    //Should never occur
                    break;
            }

The text was updated successfully, but these errors were encountered:

chipweinberger · 2022-04-08T00:32:32Z

I'm hitting this pretty often... But not every time, so might be a race condition.

chipweinberger · 2022-04-08T01:51:17Z

I logged every call I make to USBH.

In these logs I hit the case where it does not crash, but instead usb_host_uninstall() fails.

(Not sure why usb_host_uninstall() is failing. maybe related)

Detailed Logs. Plug in midi USB device, then unplug.

I (3962) pd usbh: openSingleDevice called
I (3972) pd usbh: [init] usb_host_install()
I (4002) pd usbh: [init] xTaskCreate(usbHostTaskLoop)

I (4002) pd usbh: [host task] started...
I (4022) pd usbh: [host task] usb_host_lib_handle_events()

I (4022) pd usbh: [init] usb_host_transfer_alloc(buf: 264, isoc: 0, ...)
I (4032) pd usbh: [init] usb_host_transfer_alloc(buf: 264, isoc: 0, ...)
I (4052) pd usbh: [init] usb_host_transfer_alloc(buf: 264, isoc: 0, ...)
I (4062) pd usbh: [init] usb_host_transfer_alloc(buf: 264, isoc: 0, ...)
I (4062) pd usbh: [init] usb_host_client_register(...)
I (4072) pd usbh: [init] clientHandle 0x3de4e68c
I (4072) pd usbh: [init] xTaskCreate(clientEventsLoop)

I (4072) pd usbh: [openSingleDevice] waiting usb connection....

//
// << This is where I plugged in the device >>
//

I (4072) pd usbh: [client task] started...
I (4092) pd usbh: [client task] usb_host_client_handle_events(client:0x3de4e68c)

I (8432) pd usbh: [host task] usb_host_lib_handle_events()
I (8492) pd usbh: [host task] usb_host_lib_handle_events()
I (8492) pd usbh: [host task] usb_host_lib_handle_events()
I (8492) pd usbh: [host task] usb_host_lib_handle_events()
I (8502) pd usbh: [host task] usb_host_lib_handle_events()
I (8502) pd usbh: [host task] usb_host_lib_handle_events()
I (8512) pd usbh: [host task] usb_host_lib_handle_events()
I (8522) pd usbh: [host task] usb_host_lib_handle_events()
I (8532) pd usbh: [host task] usb_host_lib_handle_events()
I (8532) pd usbh: [host task] usb_host_lib_handle_events()
I (8542) pd usbh: [host task] usb_host_lib_handle_events()
I (8542) pd usbh: [host task] usb_host_lib_handle_events()
I (8542) pd usbh: [host task] usb_host_lib_handle_events()
I (8562) pd usbh: [host task] usb_host_lib_handle_events()
I (8562) pd usbh: [host task] usb_host_lib_handle_events()
I (8572) pd usbh: [host task] usb_host_lib_handle_events()

I (8562) pd usbh: [client task] USB_HOST_CLIENT_EVENT - NEW_DEV! addr: 1

I (8582) pd usbh: [openSingleDevice] usb_host_device_open(0x3de4e68c, usbAddress: 1, ..)
I (8582) pd usbh: [openSingleDevice] deviceHandle 0x3de4e6e0

I (8582) pd usbh: [client task] usb_host_client_handle_events(client:0x3de4e68c)

I (8592) pd usbh [device]: usb_host_get_device_descriptor(dev:0x3de4e6e0)

Device descriptor:
Length: 18
Descriptor type: 1 (Device)
USB version: 0x110 (1.10)
Device class: 0x00 (Generic Device)
Device subclass: 0x00 ()
Device protocol: 0x00
EP0 max packet size: 16
VID: 0x09e8
PID: 0x0076
Revision number: 1.0
Manufacturer id: 1
Product id: 2
Serial id: 0
Num Configurations: 1

I (8632) pd usbh [device]: getStringDescriptor(idx: 1)
I (8642) pd usbh: usb_host_transfer_submit_control(client: 0x3de4e68c, transfer: 0x3de4e64c)

I (8652) pd usbh: [host task] usb_host_lib_handle_events()

manufacturer: 'AKAI professional LLC�'

I (8662) pd usbh: [client task] usb_host_client_handle_events(client:0x3de4e68c)

I (8662) pd usbh [device]: getStringDescriptor(idx: 2)
I (8672) pd usbh: usb_host_transfer_submit_control(client: 0x3de4e68c, transfer: 0x3de4e64c)

I (8682) pd usbh: [host task] usb_host_lib_handle_events()
I (8682) pd usbh: [client task] usb_host_client_handle_events(client:0x3de4e68c)

product: 'LPK25p'

I (8692) pd usbh [device]: getStringDescriptor(idx: 0)
I (8712) pd usbh: usb_host_transfer_submit_control(client: 0x3de4e68c, transfer: 0x3de4e64c)

I (8712) pd usbh: [host task] usb_host_lib_handle_events()
I (8712) pd usbh: [client task] usb_host_client_handle_events(client:0x3de4e68c)

serial: '       P'


I (8722) pd usbh [device]: getConfigDescriptor(idx: 0)
I (8732) pd usbh: usb_host_transfer_submit_control(client: 0x3de4e68c, transfer: 0x3de4e64c)

I (8742) pd usbh: [host task] usb_host_lib_handle_events()
I (8752) pd usbh: [client task] usb_host_client_handle_events(client:0x3de4e68c)

Configuration:
Length: 9
Descriptor type: 2 (Config)
Total Length: 101
bNumInterfaces: 2
bConfigurationValue: 1
iConfiguration (string): 0
bmAttributes: 0xa0
bMaxPower: 100 mA

Interface:
Length: 9
Descriptor type: 4 (Interface)
bInterfaceNumber: 0
bAlternateSetting: 0
bNumEndpoints: 0
bInterfaceClass: 0x01 (Audio)
bInterfaceSubclass: 0x01 (Audio Control)
bInterfaceProtocol: 0x00
iInterface (string): 0

         Audio Control Interface:
         Length: 9
         Descriptor type: 0x24 (CS Interface)
         Descriptor Subtype: 0x1 (Header)
         bcdADC: 0x901 (AC Spec Rev 9.1)
         wTotalLength: 256
         Streaming Interfaces: 1
         AC Interface Idx: 120

Interface:
Length: 9
Descriptor type: 4 (Interface)
bInterfaceNumber: 1
bAlternateSetting: 0
bNumEndpoints: 2
bInterfaceClass: 0x01 (Audio)
bInterfaceSubclass: 0x03 (Midi Streaming)
bInterfaceProtocol: 0x00
iInterface (string): 0

        Endpoint:
        Length: 9
        Descriptor type: 5 (Endpoint)
        bEndpointAddress: 0x01 (addr: 1 Dir: Out)
        bmAttributes: 0x02 (Bulk)
        bDescriptorType: 5
        wMaxPacketSize: 64
        bInterval: 0 ms
               
        Endpoint:
        Length: 9
        Descriptor type: 5 (Endpoint)
        bEndpointAddress: 0x81 (addr: 1 Dir: In)
        bmAttributes: 0x02 (Bulk)
        bDescriptorType: 5
        wMaxPacketSize: 64
        bInterval: 0 ms
               
I (9042) pd midi usb: midi interfaces found: 1
I (9042) pd midi usb: Found midi 1.0 endpoint. 0x81

I (9052) pd usbh [device]: setActiveConfigValue(idx: 1)
I (9052) pd usbh: usb_host_transfer_submit_control(client: 0x3de4e68c, transfer: 0x3de4e64c)
I (9062) pd usbh: [client task] usb_host_client_handle_events(client:0x3de4e68c)

I (9072) pd usbh: usb_host_interface_claim(0x3de4e68c, deviceHandle:0x3de4e6e0 bInterfaceNumber: 1 bAlternateSetting: 0)

I (9072) pd usbh: [host task] usb_host_lib_handle_events()
I (9092) pd usbh: usb_host_transfer_submit(client: 0x3de4e68c, transfer: 0x3de4e64c)

I (9092) pd midi usb: midiInEpAddr: 129

I (9112) pd usbh: [client task] usb_host_client_handle_events(client:0x3de4e68c)
I (9372) pd usbh: usb_host_transfer_submit(client: 0x3de4e68c, transfer: 0x3de4e64c)

I (10122) pd usbh: [openSingleDevice] called
I (10122) pd usbh: [openSingleDevice] waiting for existing devices to close...

//
// << Hitting some notes on the piano >>
//

I (10892) pd usbh: [client task] usb_host_client_handle_events(client:0x3de4e68c)
I (10892) pd usbh: usb_host_transfer_submit(client: 0x3de4e68c, transfer: 0x3de4e64c)

[In]                 10.887 | Cb:0 Ch:0  | Note On G4 vel:1

I (12212) pd usbh: [client task] usb_host_client_handle_events(client:0x3de4e68c)
I (12212) pd usbh: usb_host_transfer_submit(client: 0x3de4e68c, transfer: 0x3de4e64c)

[In]                 12.207 | Cb:0 Ch:0  | Note Off G4

//
// << This is where I unplugged the device, and try to fully clean up USB>>
//

I (13522) pd usbh: [client task] usb_host_client_handle_events(client:0x3de4e68c)

E (13522) pd midi usb: xfer midi IN pipe failed

E (13522) : e1 : [pd usbh] USB_TRANSFER_STATUS_ERROR
e2 : [pd usbh dev] submitTransferAndWait() failed

E (13522) USBH: Device 1 gone
I (13552) pd usbh: [host task] usb_host_lib_handle_events()

//
// << This is where we sometimes crash!>>
//

W (13552) pd usbh: [client task] USB_HOST_CLIENT_EVENT - DEV_GONE dev_hdl: 0x3de4e6e0
W (13562) pd usbh: [client task] dev gone - unblocking usb transfer 3

I (13562) pd usbh: usb_host_interface_release(0x3de4e68c, device: 0x3de4e6e0, bInterfaceNumber: 1

I (13572) pd usbh: [client task] usb_host_device_close(client:0x3de4e68c,dev:0x3de4e6e0)
I (13592) pd usbh: [client task] 0 devices still open
I (13592) pd usbh: [client task] usb_host_client_handle_events(client:0x3de4e68c)

I (13592) pd usbh: [host task] event: USB_HOST_LIB_EVENT_FLAGS - ALL_FREE
I (13612) pd usbh: [host task] usb_host_lib_handle_events()

I (8442) pd usbh: [openSingleDevice] all devices closed. unblocked. continuing...
I (8442) pd usbh: [openSingleDevice] uninitializing (alwaysReinit == True)

I (13622) pd usbh: [uninitialize] called
I (13622) pd usbh: [uninitialize] Stopping xUsbClientTask...
I (13632) pd usbh: [uninitialize] usb_host_client_unblock(client:0x3de4e68c)
I (13642) pd usbh: [client task] vTaskDelete()

E (14042) pd midi usb: xfer fail. stopping xferInTask_loop until replugged

I (14642) pd usbh: [uninitialize] 0 devices need closing
I (14642) pd usbh: [uninitialize] usb_host_client_deregister(client:0x3de4e68c)
I (14652) pd usbh: [uninitialize] Stopping xUsbHostTask...
I (14652) pd usbh: [uninitialize] usb_host_lib_unblock()

I (14652) pd usbh: [host task] event: USB_HOST_LIB_EVENT_FLAGS - NO_CLIENTS
I (14662) pd usbh: [host task] usb_host_device_free_all()
I (14672) pd usbh: [host task] vTaskDelete()

I (15662) pd usbh: [uninitialize] usb_host_uninstall() 

 // usb_host_uninstall() fails
 // returns ESP_ERR_INVALID_STATE
 // p_host_lib_obj->dynamic.process_pending_flags != 0;

chipweinberger · 2022-04-08T01:52:34Z

@Dazza0

chipweinberger · 2022-04-08T02:16:05Z

I just tried not unintializing, leaving USBH fully "up", and doing a few unplugs & replugs. I still hit the same crash after a few tries.

chipweinberger · 2022-07-11T23:19:22Z

Bump @Dazza0 @igrr

This was caused by me accidentally modifying and submitting the same usb_transfer_t object multiple times for different requests, without waiting for the transfer object to complete.

It seems worthwhile to guard against improper API usage. Maybe make a copy of the transfer object when we submit. Or keep track of which transfer objects are "live" in some separate array, and throw an error if we try to submit the same object while already "in-flight".

Aborting at a "random" place is never very easy to debug.

If not worthwhile, feel free to close this.

thoughts?

Dazza0 · 2022-07-20T04:18:08Z

@chipweinberger I'm hesitant to make a copy of the usb_transfer_t as

These objects can get quite large for Isochronous transfers since we need to copy all of the usb_isoc_packet_desc_t descriptors as well
When the transfer is complete, the internal copy of the transfer object will need to overwrite the user's copy which could also lead to its own bugs.

IMO the following changes below. Please let me know these look OK.

The internal urb_t object wraps the public usb_transfer_t object, thus I think the urb_t would be a good place to add a variable that tracks the transfer's current "progress" without needing to reveal the variable to the user.
usb_host_transfer_submit() will check the "progress" variable of urb_t and return an error if the transfer was already submitted.
Add a public function usb_host_transfer_check_progress(usb_transfer_t *transfer) to query the progress of a transfer. Users can call this before attempting to modify a transfer object.

chipweinberger · 2022-07-20T04:29:16Z

That sounds like a good and easy solution.

Btw, after fixing the above issue I mentioned, I recently managed to hit the same abort() again after making some other changes to my shutdown code & inserting and removing the USB device many times. It's on my todo list to debug it further and give you something more actionable.

chipweinberger · 2022-08-24T23:56:12Z

@Dazza0, I still sometimes abort in root_port_handle_events() in v4.4.2.

It's on my todo list to debug it further

The abort happens because we are in HUB_DRIVER_STATE_ROOT_RECOVERY state, which is not handled by root_port_handle_events() switch statement. Note: this abort happens when I unplug the USB device.

Do you know why?


I (109451) : e1 : [pd usbh] USB TRANSFER FAILED - no device
e2 : [pd usbh [device]] submitTransferAndWait() failed
e3 : [pd midi usb IN] xfer IN task: DEV GONE

I (109471) pd midi usb IN: xferInTask_loop ended. wait for usb replug.
I (109471) pd usbh: cancelAllTransfers()
I (109481) pd_buzz: USB Device Removed Sound
buzz F 4 698Hz 100ms
E (109451) USBH: Device 1 gone
W (109491) pd usbh: [client task] DEV_GONE dev_hdl: 0x3debc3f0
W (109491) pd usbh: [close device] closing, dev_hdl: 0x3debc3f0

abort() was called at PC 0x4207d12a on core 1

Backtrace:0x4207d12a:0x3fcd4770 0x4207dfca:0x3fcd47a0 0x420772a8:0x3fcd47d0 0x4203dd68:0x3fcd4800 0x40388252:0x3fcd4830 

0x4207d12a: root_port_handle_events at /esp-idf/components/usb/hub.c:789

0x4207dfca: hub_process at /esp-idf/components/usb/hub.c:994

0x420772a8: usb_host_lib_handle_events at /esp-idf/components/usb/usb_host.c:514

0x4203dd68: PDUsbHostService::usbHostTaskLoop(void*) at /jcommon/usb/PDUsbHostService.cpp:59 (discriminator 11)

0x40388252: vPortTaskWrapper at /esp-idf/components/freertos/port/xtensa/port.c:131

Dazza0 · 2022-09-02T11:33:32Z

@chipweinberger Seems like a double HCD Port event. The hub only goes into the HUB_DRIVER_STATE_ROOT_RECOVERY state when the root port has an error (e.g., DISCONNECTION, ERROR, OVERCURRENT).

However, while hub driver is recovering the root port, there's another HCD_PORT_EVENT_... occurring, thus leading to the switch case calling the abort: Could you log what port_event is happening when the abort() is called?

Note: this abort happens when I unplug the USB device.

Do you know if this is happening every time you unplug the USB device? Usually, when you first unblock the USB device, a HCD_PORT_EVENT_DISCONNECTION event occurs which puts Hub driver into recovery. However, once disconnected, there shouldn't be any further HCD Port events.

So maybe there's an edge case missing where an HCD_PORT_EVENT_ERROR occurs first, followed rapidly by a HCD_PORT_EVENT_DISCONNECTION (it could happen the disconnection happens slowly).

@chipweinberger BTW, could you also open a separate Github issue to track this. I want to current issue to track the usb_transfer_t status feature mentioned above.

chipweinberger · 2022-09-02T21:21:16Z

New Issue: #9707

I Answered the questions in that new thread.

chipweinberger · 2022-09-02T22:33:07Z

This issue is reserved for tracking the usb_transfer_t feature.

This commit adds a simple flag/check in the USB Host Library that prevents users from submitting a transfer that is already inflight. - A transfer is considered inflight as soon as it is submitted by calling usb_host_transfer_submit() or usb_host_transfer_submit_control() - An inflight transfer remains inflight up until right before its callback is called by one of the USB Host Library handler functions. Closes #8748

chipweinberger · 2022-12-05T05:26:59Z

commit: e17e066

This commit adds a simple flag/check in the USB Host Library that prevents users from submitting a transfer that is already inflight. - A transfer is considered inflight as soon as it is submitted by calling usb_host_transfer_submit() or usb_host_transfer_submit_control() - An inflight transfer remains inflight up until right before its callback is called by one of the USB Host Library handler functions. Closes #8748

chipweinberger changed the title ~~[CRASH][v4.4][ESP32-S3] root_port_handle_events() aborts when device unplugged~~ [CRASH][v4.4][ESP32-S3] root_port_handle_events() aborts when USB device unplugged Apr 8, 2022

chipweinberger changed the title ~~[CRASH][v4.4][ESP32-S3] root_port_handle_events() aborts when USB device unplugged~~ [CRASH][v4.4][ESP32-S3] USB root_port_handle_events() aborts when device unplugged Apr 8, 2022

chipweinberger changed the title ~~[CRASH][v4.4][ESP32-S3] USB root_port_handle_events() aborts when device unplugged~~ [CRASH][v4.4][ESP32-S3] USB root_port_handle_events() aborts when USB device unplugged Apr 8, 2022

espressif-bot added the Status: Opened Issue is new label Apr 8, 2022

github-actions bot changed the title ~~[CRASH][v4.4][ESP32-S3] USB root_port_handle_events() aborts when USB device unplugged~~ [CRASH][v4.4][ESP32-S3] USB root_port_handle_events() aborts when USB device unplugged (IDFGH-7145) Apr 8, 2022

espressif-bot assigned 0xjakob and Dazza0 Apr 22, 2022

espressif-bot added Status: Selected for Development Issue is selected for development and removed Status: Opened Issue is new labels Aug 22, 2022

chipweinberger mentioned this issue Sep 2, 2022

[USB][ABORT][v4.4.2] root_port_handle_events() hits HUB_DRIVER_STATE_ROOT_RECOVERY (IDFGH-8214) #9707

Open

espressif-bot closed this as completed in e17e066 Nov 11, 2022

espressif-bot added Status: Done Issue is done internally Resolution: Done Issue is done internally and removed Status: Selected for Development Issue is selected for development labels Nov 30, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[CRASH][v4.4][ESP32-S3] USB root_port_handle_events() aborts when USB device unplugged (IDFGH-7145) #8748

[CRASH][v4.4][ESP32-S3] USB root_port_handle_events() aborts when USB device unplugged (IDFGH-7145) #8748

chipweinberger commented Apr 8, 2022 •

edited

Loading

chipweinberger commented Apr 8, 2022 •

edited

Loading

chipweinberger commented Apr 8, 2022 •

edited

Loading

chipweinberger commented Apr 8, 2022

chipweinberger commented Apr 8, 2022

chipweinberger commented Jul 11, 2022 •

edited

Loading

Dazza0 commented Jul 20, 2022

chipweinberger commented Jul 20, 2022 •

edited

Loading

chipweinberger commented Aug 24, 2022 •

edited

Loading

Dazza0 commented Sep 2, 2022

chipweinberger commented Sep 2, 2022 •

edited

Loading

chipweinberger commented Sep 2, 2022

chipweinberger commented Dec 5, 2022

[CRASH][v4.4][ESP32-S3] USB root_port_handle_events() aborts when USB device unplugged (IDFGH-7145) #8748

[CRASH][v4.4][ESP32-S3] USB root_port_handle_events() aborts when USB device unplugged (IDFGH-7145) #8748

Comments

chipweinberger commented Apr 8, 2022 • edited Loading

chipweinberger commented Apr 8, 2022 • edited Loading

chipweinberger commented Apr 8, 2022 • edited Loading

chipweinberger commented Apr 8, 2022

chipweinberger commented Apr 8, 2022

chipweinberger commented Jul 11, 2022 • edited Loading

Dazza0 commented Jul 20, 2022

chipweinberger commented Jul 20, 2022 • edited Loading

chipweinberger commented Aug 24, 2022 • edited Loading

Dazza0 commented Sep 2, 2022

chipweinberger commented Sep 2, 2022 • edited Loading

chipweinberger commented Sep 2, 2022

chipweinberger commented Dec 5, 2022

chipweinberger commented Apr 8, 2022 •

edited

Loading

chipweinberger commented Apr 8, 2022 •

edited

Loading

chipweinberger commented Apr 8, 2022 •

edited

Loading

chipweinberger commented Jul 11, 2022 •

edited

Loading

chipweinberger commented Jul 20, 2022 •

edited

Loading

chipweinberger commented Aug 24, 2022 •

edited

Loading

chipweinberger commented Sep 2, 2022 •

edited

Loading