Panic / coredump when calling esp_core_dump_get_summary() with tinyusb CDC . (IEC-261)

[gadget-man]

Answers checklist.

• I have read the component documentation ESP-IDF Components and the issue is not addressed there.
• I am using target and esp-idf version as defined in component's idf_component.yml
• I have searched the issue tracker for a similar issue and not found any related issue.

Which component are you using? If you choose Other, provide details in More Information.

device/esp_tinyusb

ESP-IDF version.

5.4.0

Development Kit.

ESP32S3 DevkIt

Used Component version.

1.7.1

More Information.

I have esp_tinyusb enabled to send serial output over USB. Everything works fine until I call

This is the code I use to initiate tinyusb:

const tinyusb_config_t tusb_cfg = {
            .device_descriptor = NULL,
            .string_descriptor = NULL,
            .external_phy = false, 
            .configuration_descriptor = NULL,
        };
        ESP_ERROR_CHECK(tinyusb_driver_install(&tusb_cfg));
        tinyusb_config_cdcacm_t acm_cfg = {0}; // the configuration uses default values
        acm_cfg.callback_line_state_changed = &tinyusb_cdc_line_state_changed_callback;

        ESP_ERROR_CHECK(tusb_cdc_acm_init(&acm_cfg));

As soon as I call esp_err_t err = esp_core_dump_get_summary(summary);, I get a panic, this is the returned coredump summary:

 ==================== CURRENT THREAD STACK =====================
#0  panic_abort (details=0x3fca385b <port_IntStack+811> "abort() was called at PC 0x40378323 on core 0") at /Users/PaulNeedler/esp/v5.4/esp-idf/components/esp_system/panic.c:466
#1  0x4038590c in esp_system_abort (details=0x3fca385b <port_IntStack+811> "abort() was called at PC 0x40378323 on core 0") at /Users/PaulNeedler/esp/v5.4/esp-idf/components/esp_system/port/esp_system_chip.c:92
#2  0x4038b43c in abort () at /Users/PaulNeedler/esp/v5.4/esp-idf/components/newlib/abort.c:38
#3  0x40378326 in lock_acquire_generic (lock=0x3fca3910 <port_IntStack+992>, delay=4294967295, mutex_type=4 '\004') at /Users/PaulNeedler/esp/v5.4/esp-idf/components/newlib/locks.c:133
#4  0x40378444 in _lock_acquire_recursive (lock=0x3fca3910 <port_IntStack+992>) at /Users/PaulNeedler/esp/v5.4/esp-idf/components/newlib/locks.c:162
#5  0x4037850e in __retarget_lock_acquire_recursive (lock=<optimized out>) at /Users/PaulNeedler/esp/v5.4/esp-idf/components/newlib/locks.c:321
#6  0x4210f136 in _vfprintf_r (data=0x3fcbb060, fp=0x3fcb54e4, fmt0=0x3c1490dc "%s %d: ASSERT FAILED\r
", ap=...) at /builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/newlib/newlib/libc/stdio/vfprintf.c:846
#7  0x420fdfce in printf (fmt=0x3c1490dc "%s %d: ASSERT FAILED\r
") at /builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/newlib/newlib/libc/stdio/printf.c:56
#8  0x42035d4c in queue_event (event=0x3fca3ce0 <port_IntStack+1968>, in_isr=true) at /Users/PaulNeedler/Documents/iParcelBox/3-FIRMWARE/iParcelBox_firmware_v3/managed_components/espressif__tinyusb/src/device/usbd.c:357
#9  dcd_event_handler (event=0x3fca3ce0 <port_IntStack+1968>, in_isr=true) at /Users/PaulNeedler/Documents/iParcelBox/3-FIRMWARE/iParcelBox_firmware_v3/managed_components/espressif__tinyusb/src/device/usbd.c:1229
#10 0x42036fbc in dcd_event_bus_reset (rhport=0 '\000', speed=<optimized out>, in_isr=true) at /Users/PaulNeedler/Documents/iParcelBox/3-FIRMWARE/iParcelBox_firmware_v3/managed_components/espressif__tinyusb/src/device/dcd.h:209
#11 handle_enum_done (rhport=0 '\000') at /Users/PaulNeedler/Documents/iParcelBox/3-FIRMWARE/iParcelBox_firmware_v3/managed_components/espressif__tinyusb/src/portable/synopsys/dwc2/dcd_dwc2.c:713
#12 0x420378c4 in dcd_int_handler (rhport=0 '\000') at /Users/PaulNeedler/Documents/iParcelBox/3-FIRMWARE/iParcelBox_firmware_v3/managed_components/espressif__tinyusb/src/portable/synopsys/dwc2/dcd_dwc2.c:1000
#13 0x420379ae in dwc2_int_handler_wrap (arg=0x100) at /Users/PaulNeedler/Documents/iParcelBox/3-FIRMWARE/iParcelBox_firmware_v3/managed_components/espressif__tinyusb/src/portable/synopsys/dwc2/dwc2_esp32.h:73
#14 0x4037d1a9 in _xt_lowint1 () at /Users/PaulNeedler/esp/v5.4/esp-idf/components/xtensa/xtensa_vectors.S:1240
#15 0x40048836 in ?? ()
#16 0x40048c6c in ?? ()
#17 0x40043d06 in ?? ()
#18 0x40043cd8 in ?? ()
#19 0x40044186 in ?? ()
#20 0x40044284 in ?? ()
#21 0x42013848 in esp_core_dump_parse_note_section (coredump_data=0x3c990018 <error: Cannot access memory at address 0x3c990018>, target_notes=0x3fcc1734, size=2) at /Users/PaulNeedler/esp/v5.4/esp-idf/components/espcoredump/src/core_dump_elf.c:994
#22 0x42014a17 in esp_core_dump_get_summary (summary=0x3fcbb170) at /Users/PaulNeedler/esp/v5.4/esp-idf/components/espcoredump/src/core_dump_elf.c:1059
#23 0x42024e3d in rpc_coredump_worker_task (pvParameters=0x3fce824c) at /Users/PaulNeedler/Documents/iParcelBox/3-FIRMWARE/iParcelBox_firmware_v3/components/ipb_rpc_common/ipb_rpc_common.c:906
#24 0x40385cad in vPortTaskWrapper (pxCode=0x42024e14 <rpc_coredump_worker_task>, pvParameters=0x3fce824c) at /Users/PaulNeedler/esp/v5.4/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:139

======================== THREADS INFO =========================
  Id   Target Id          Frame 
* 1    process 1070313468 panic_abort (details=0x3fca385b <port_IntStack+811> "abort() was called at PC 0x40378323 on core 0") at /Users/PaulNeedler/esp/v5.4/esp-idf/components/esp_system/panic.c:466
  2    process 1070400748 tu_fifo_set_overwritable (f=<error reading variable: Cannot access memory at address 0x60417>, overwritable=true) at /Users/PaulNeedler/Documents/iParcelBox/3-FIRMWARE/iParcelBox_firmware_v3/managed_components/espressif__tinyusb/src/common/tusb_fifo.c:922
  3    process 1070319684 0x4038137e in esp_cpu_wait_for_intr () at /Users/PaulNeedler/esp/v5.4/esp-idf/components/esp_hw_support/cpu.c:64
  4    process 1070321724 0x4038137e in esp_cpu_wait_for_intr () at /Users/PaulNeedler/esp/v5.4/esp-idf/components/esp_hw_support/cpu.c:64
  5    process 1070379204 0x400559e0 in ?? ()
  6    process 1070495376 0x400559e0 in ?? ()
  7    process 1070313096 0x400559e0 in ?? ()
  8    process 1070292968 0x400559e0 in ?? ()
  9    process 1070324276 0x4212348a in prvProcessTimerOrBlockTask (xNextExpireTime=0, xListWasEmpty=1) at /Users/PaulNeedler/esp/v5.4/esp-idf/components/xtensa/include/xt_utils.h:41
  10   process 1070305304 0x400559e0 in ?? ()
  11   process 1070496252 0x400559e0 in ?? ()
  12   process 1070458528 0x400559e0 in ?? ()
  13   process 1070363540 0x400559e0 in ?? ()
  14   process 1070294688 0x400559e0 in ?? ()
  15   process 1070401504 0x400559e0 in ?? ()
  16   process 1070437992 0x400559e0 in ?? ()
  17   process 1070443744 0x400559e0 in ?? ()
  18   process 1070483992 xEventGroupWaitBits (xEventGroup=0x3fcdb7c0, uxBitsToWaitFor=2, xClearOnExit=1, xWaitForAllBits=0, xTicksToWait=4294967295) at /Users/PaulNeedler/esp/v5.4/esp-idf/components/freertos/FreeRTOS-Kernel/event_groups.c:439
  19   process 1070492212 0x400559e0 in ?? ()
  20   process 1070398300 0x400559e0 in ?? ()
  21   process 1070402700 0x400559e0 in ?? ()
  22   process 1070489540 0x400559e0 in ?? ()

It looks as though there's an issue with an ISR running which causes the USB to fail.

[igi540]

Hi @gadget-man,

The crash is likely caused by calling printf() inside an ISR (dcd_int_handler). printf() is not ISR-safe because it attempts to acquire a lock (_lock_acquire_recursive), which is not permitted in an ISR, leading to a panic.

To resolve this, use ets_printf() instead of printf(). ets_printf() is a low-level function that does not require mutexes and is safe to use in an ISR.

Try replacing printf() with the following:

// Replace:
printf("ISR log: something happened\n");

// With:
ets_printf("ISR log: something happened\n");

[gadget-man]

Yes I understand that, but dcd_int_handler and esp_core_dump_get_summary are both functions from existing libraries, not functions I've coded myself - does this therefore mean there is a bug in one of these?

[tore-espressif]

Yes, it is a bug in our configuration where we use default printf for debugging logs. Will fix in next release of esp_tinusb

[tore-espressif]

@gadget-man Could you try if #132 fixes your problem?

If you want to add the change to your project:

1. Clone the repo and checkout branch from fix(esp_tinyusb): Call esp_rom_printf in TinyUSB logging #132
2. Modify your projects idf_componentl.yml so it points to esp_tinyusb from this repo
   With windows style path it could look like this

## IDF Component Manager Manifest File
dependencies:
  espressif/esp_tinyusb:
    version: "*"
    path: "C:\\github_repos\\esp-usb\\device\\esp_tinyusb" # Update to your path
  idf: "^5.0"

[gadget-man]

#132 has only partially fixed the problem. With tinyUSB active and logging enabled on ACM_1 (i.e. cable is connected), if I call a function to dump the coredump summary from a separate channel (e.g. I can make RPC calls over secure MQTT), then it still crashes. However, if I do the same thing with tinyUSB configured but no usb cable attached, it works OK.

I wonder if this is due to our configuration of logging. In addition to logging either to USBC or UART (depending on which is connected), we also log via UDP. I therefore have the below function:

original_log_vprintf = esp_log_set_vprintf(udp_log_vprintf);

int udp_log_vprintf(const char *fmt, va_list args)
{

    // First, log to UART
    va_list args_copy;
    va_copy(args_copy, args);
    int uart_len = 0;
    if (usb_type == LOG_NONE)
    {
        char usb_buffer[MAX_LOG_MSG_LENGTH];
        uart_len = vsnprintf(usb_buffer, MAX_LOG_MSG_LENGTH, fmt, args_copy);
    }
    else if (usb_type == LOG_USB)
    {
        char usb_buffer[MAX_LOG_MSG_LENGTH];
        uart_len = vsnprintf(usb_buffer, MAX_LOG_MSG_LENGTH, fmt, args_copy);
        if (uart_len > 0 && tud_ready())
        {
            // Send the message to the USB CDC ACM
            tud_cdc_n_write(TINYUSB_CDC_ACM_1, usb_buffer, uart_len);
            tud_cdc_n_write_flush(TINYUSB_CDC_ACM_1);
        }
    }
    else
    {
        uart_len = original_log_vprintf(fmt, args_copy);
    }
    va_end(args_copy);
etc....

(please excuse this very sloppy coding - I'll tidy it up properly when everything is working!)

Could the way I'm sending the logs over USB be causing the remaining issue?

[gadget-man]

Correction, it's not crashing when the usb cable is connected, but it is rebooting due to interrupt watchdog.

Also, if I call the coredump RPC function over usb-serial command it fails and the usb disconnects. If I call it over MQTT, the usb disconnects immediately, but then the function does often run OK and the device stays online, sometimes failing due to the interrupt watchdog.

[tore-espressif]

@gadget-man

I suspect the problem is that calls to TinyUSB API are not thread safe. However, udp_log_vprintf() is invoked in parallel from multiple tasks context - this is on our todo list, but I can't commit to any timeline yet.

BTW, if you use USB only for logging, you can use USB-Serial-JTAG, it has better support for logging support. You can enable it in menuconfig in (Top) → Component config → ESP System Settings → Channel for console output menu