espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.33k stars 7.2k forks source link

usb_host_install() abort at 0x4037d9df on core 0 (IDFGH-11445) #12581

Closed TRYOKETHEPEN closed 10 months ago

TRYOKETHEPEN commented 10 months ago

Answers checklist.

IDF version.

v5.1.1

Espressif SoC revision.

ESP32-S3

Operating System used.

Windows

How did you build your project?

VS Code IDE

If you are using Windows, please specify command line type.

None

Development Kit.

ESP32-S3-DevKitC-1 v1.1

Power Supply used.

USB

What is the expected behavior?

My project create 3 freeRTOS tasks at app_main(): [task1] RC522 scann rf-id. [task2] LCD display & touch, with LVGL. [task3] USB_HOST, which calls usb_host_install() that triggers this abortion.

My project file: project1.zip task1 code based on https://github.com/abobija/esp-idf-rc522. task2 code based on "spi_lcd_touch" example. task3 code based on "hid" example.

When I build&flash&monitor, the expected monitor log should be: _2023-11-14 14:04:32 I (902) main_task: Started on CPU0 2023-11-14 14:04:32 I (912) main_task: Calling app_main() 2023-11-14 14:04:32 W (912) 主程序: >>>开启RC522读卡任务(异步) 2023-11-14 14:04:32 I (922) rc522: versionReg: 0xb2 2023-11-14 14:04:32 I (922) rc522: Initialized (firmware v2.0) 2023-11-14 14:04:32 W (932) 主程序: >>>开启LCD 2023-11-14 14:04:32 I (932) lcd_touch_lvgl_init: 初始化SPI 2023-11-14 14:04:32 I (942) lcd_touch_lvgl_init: 初始化LCD panel 2023-11-14 14:04:32 I (942) gpio: GPIO[4]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 2023-11-14 14:04:32 I (952) lcd_touch_lvgl_init: 安装panel驱动:ILI9341
2023-11-14 14:04:32 I (962) gpio: GPIO[6]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 2023-11-14 14:04:32 I (1092) lcd_touch_lvgl_init: 初始化LCD触控panel 2023-11-14 14:04:32 I (1092) lcd_touch_lvgl_init: 安装panel驱动:XPT2046
2023-11-14 14:04:32 I (1092) lcd_touch_lvgl_init: 初始化LVGL绘制缓冲区
2023-11-14 14:04:32 I (1092) lcd_touch_lvgl_init: 初始化&注册LVGL显示驱动器 2023-11-14 14:04:32 I (1102) lcd_touch_lvgl_init: 初始化LVGL定时器 2023-11-14 14:04:32 I (1112) lcd_touch_lvgl_init: 初始化LVGL触控驱动器
2023-11-14 14:04:32 W (1112) 主程序: >>>开启USB HOST HID 2023-11-14 14:04:32 I (1122) usb_hid: 安装USB HOST驱动 2023-11-14 14:04:32 I (1122) usb_hid: 执行任务usb_events 2023-11-14 14:04:32 I (1162) usb_hid: 安装USB HOST驱动成功 2023-11-14 14:04:32 I (1162) usb_hid: 安装HID驱动 2023-11-14 14:04:32 I (1162) usb_hid: 创建HID任务 2023-11-14 14:04:32 I (1162) usb_hid: 执行任务hidtask

What is the actual behavior?

If I create USB_HOST task at CPU0, it panics like the 【error log】.

Then I tried different combinations(I don't know how to change the CPU where the LVGL task created, it seems always running at CPU0):

When USB_HOST is set at CPU1, the project running well. When USB_HOST is set at CPU0 or NO_AFFINITY, the project aborts at usb_host_install(), unless one of the taks1&taks2 is cancelled. _I say "cancelled", what actually I did: [cancel task1]: Annotate "rfid_start_scann();" at app_main(). [cancel task2]: Annotate "lcd_touch_lvgl_start();" at appmain().

I don't know why USB_HOST task running at CPU0 is complict with other tasks, could it be because of stack overflow?

Steps to reproduce.

\

Debug Logs.

【error log】
2023-11-14 11:43:49 I (902) main_task: Started on CPU0
2023-11-14 11:43:49 I (912) main_task: Calling app_main()
2023-11-14 11:43:49 W (912) 主程序: >>>开启RC522读卡任务(异步)
2023-11-14 11:43:49 I (922) rc522: versionReg: 0xb2
2023-11-14 11:43:49 I (922) rc522: Initialized (firmware v2.0)
2023-11-14 11:43:49 W (932) 主程序: >>>开启LCD
2023-11-14 11:43:49 I (932) lcd_touch_lvgl_init: 初始化SPI
2023-11-14 11:43:49 I (942) lcd_touch_lvgl_init: 初始化LCD panel
2023-11-14 11:43:49 I (942) gpio: GPIO[4]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
2023-11-14 11:43:49 I (952) lcd_touch_lvgl_init: 安装panel驱动:ILI9341       
2023-11-14 11:43:49 I (962) gpio: GPIO[6]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
2023-11-14 11:43:50 I (1092) lcd_touch_lvgl_init: 初始化LCD触控panel
2023-11-14 11:43:50 I (1092) lcd_touch_lvgl_init: 安装panel驱动:XPT2046      
2023-11-14 11:43:50 I (1092) lcd_touch_lvgl_init: 初始化LVGL绘制缓冲区       
2023-11-14 11:43:50 I (1092) lcd_touch_lvgl_init: 初始化&注册LVGL显示驱动器
2023-11-14 11:43:50 I (1102) lcd_touch_lvgl_init: 初始化LVGL定时器
2023-11-14 11:43:50 I (1112) lcd_touch_lvgl_init: 初始化LVGL触控驱动器       
2023-11-14 11:43:50 W (1112) 主程序: >>>开启USB HOST HID
2023-11-14 11:43:50 I (1122) usb_hid: 安装USB HOST驱动
2023-11-14 11:43:50 I (1122) usb_hid: 执行任务usb_events
2023-11-14 11:43:50 ESP_ERROR_CHECK failed: esp_err_t 0x105 (ESP_ERR_NOT_FOUND) at 0x4200ae2a
2023-11-14 11:43:50 0x4200ae2a: task_usb_host_lib at D:/ESPIDFprojects/project1/main/custom_usb_hid.c:392 (discriminator 1)

2023-11-14 11:43:50 file: "./main/custom_usb_hid.c" line 392
2023-11-14 11:43:50 func: task_usb_host_lib
2023-11-14 11:43:50 expression: usb_host_install(&host_config)
2023-11-14 11:43:50
2023-11-14 11:43:50 abort() was called at PC 0x4037d9df on core 0
2023-11-14 11:43:50 0x4037d9df: _esp_error_check_failed at D:/espressif/Espressif/frameworks/esp-idf-v5.1.1/components/esp_system/esp_err.c:50

2023-11-14 11:43:50
2023-11-14 11:43:50
2023-11-14 11:43:50 Backtrace: 0x40375c7e:0x3fca9370 0x4037d9e9:0x3fca9390 0x40384856:0x3fca93b0 0x4037d9df:0x3fca9420 0x4200ae2a:0x3fca9450 0x4038029d:0x3fca9480
2023-11-14 11:43:50 0x40375c7e: panic_abort at D:/espressif/Espressif/frameworks/esp-idf-v5.1.1/components/esp_system/panic.c:452

2023-11-14 11:43:50 0x4037d9e9: esp_system_abort at D:/espressif/Espressif/frameworks/esp-idf-v5.1.1/components/esp_system/port/esp_system_chip.c:84      

2023-11-14 11:43:50 0x40384856: abort at D:/espressif/Espressif/frameworks/esp-idf-v5.1.1/components/newlib/abort.c:38

2023-11-14 11:43:50 0x4037d9df: _esp_error_check_failed at D:/espressif/Espressif/frameworks/esp-idf-v5.1.1/components/esp_system/esp_err.c:50

2023-11-14 11:43:50 0x4200ae2a: task_usb_host_lib at D:/ESPIDFprojects/project1/main/custom_usb_hid.c:392 (discriminator 1)

2023-11-14 11:43:50 0x4038029d: vPortTaskWrapper at D:/espressif/Espressif/frameworks/esp-idf-v5.1.1/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

2023-11-14 11:43:50
2023-11-14 11:43:50
2023-11-14 11:43:50
2023-11-14 11:43:50
2023-11-14 11:43:50 ELF file SHA256: 473c4fb0d95f68be
2023-11-14 11:43:50 
2023-11-14 11:43:50 Rebooting...
2023-11-14 11:43:50 ESP-ROM:esp32s3-20210327
2023-11-14 11:43:50 Build:Mar 27 2021
2023-11-14 11:43:50 rst:0x3 (RTC_SW_SYS_RST),boot:0x29 (SPI_FAST_FLASH_BOOT) 
2023-11-14 11:43:50 Saved PC:0x40375b00
2023-11-14 11:43:50 0x40375b00: esp_restart_noos_dig at D:/espressif/Espressif/frameworks/esp-idf-v5.1.1/components/esp_system/port/esp_system_chip.c:57 (discriminator 1)

2023-11-14 11:43:50 SPIWP:0xee
2023-11-14 11:43:50 mode:DIO, clock div:1
2023-11-14 11:43:50 load:0x3fce3818,len:0x16e8
2023-11-14 11:43:50 load:0x403c9700,len:0x4
2023-11-14 11:43:50 load:0x403c9704,len:0xc00
2023-11-14 11:43:50 load:0x403cc700,len:0x2eb0
2023-11-14 11:43:50 SHA-256 comparison failed:
2023-11-14 11:43:50 Calculated: 833c20ee676e165911f76cdadffe0842c17f7514316fae0e99d2e7503a2639c4
2023-11-14 11:43:50 Expected: ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
2023-11-14 11:43:50 Attempting to boot anyway...
2023-11-14 11:43:50 entry 0x403c9908
2023-11-14 11:43:50 I (50) boot: ESP-IDF v5.1.1-dirty 2nd stage bootloader   
2023-11-14 11:43:50 I (50) boot: compile time Nov 14 2023 11:34:16
2023-11-14 11:43:50 I (50) boot: Multicore bootloader
2023-11-14 11:43:50 I (53) boot: chip revision: v0.1
2023-11-14 11:43:50 I (57) boot.esp32s3: Boot SPI Speed : 80MHz
2023-11-14 11:43:50 I (62) boot.esp32s3: SPI Mode       : DIO
2023-11-14 11:43:50 I (67) boot.esp32s3: SPI Flash Size : 8MB
2023-11-14 11:43:50 I (71) boot: Enabling RNG early entropy source...        
2023-11-14 11:43:50 I (77) boot: Partition Table:
2023-11-14 11:43:50 I (80) boot: ## Label            Usage          Type ST Offset   Length
2023-11-14 11:43:50 I (88) boot:  0 nvs              WiFi data        01 02 00009000 00006000
2023-11-14 11:43:50 I (95) boot:  1 phy_init         RF data          01 01 0000f000 00001000
2023-11-14 11:43:50 I (103) boot:  2 factory          factory app      00 00 
00010000 00300000
2023-11-14 11:43:50 I (110) boot: End of partition table
2023-11-14 11:43:50 I (115) esp_image: segment 0: paddr=00010020 vaddr=3c070020 size=1ab9ch (109468) map
2023-11-14 11:43:50 I (135) esp_image: segment 1: paddr=0002abc4 vaddr=3fc96d00 size=0349ch ( 13468) load
2023-11-14 11:43:50 I (138) esp_image: segment 2: paddr=0002e068 vaddr=40374000 size=01fb0h (  8112) load
2023-11-14 11:43:50 I (142) esp_image: segment 3: paddr=00030020 vaddr=42000020 size=6dc98h (449688) map
2023-11-14 11:43:50 I (200) esp_image: segment 4: paddr=0009dcc0 vaddr=40375fb0 size=10cc0h ( 68800) load
2023-11-14 11:43:50 I (218) boot: Loaded app from partition at offset 0x100002023-11-14 11:43:50 I (219) boot: Disabling RNG early entropy source...      
2023-11-14 11:43:50 I (230) cpu_start: Multicore app
2023-11-14 11:43:50 I (230) octal_psram: vendor id    : 0x0d (AP)
2023-11-14 11:43:50 I (230) octal_psram: dev id       : 0x02 (generation 3)  
2023-11-14 11:43:50 I (234) octal_psram: density      : 0x03 (64 Mbit)       
2023-11-14 11:43:50 I (239) octal_psram: good-die     : 0x01 (Pass)
2023-11-14 11:43:50 I (244) octal_psram: Latency      : 0x01 (Fixed)
2023-11-14 11:43:50 I (250) octal_psram: VCC          : 0x01 (3V)
2023-11-14 11:43:50 I (255) octal_psram: SRF          : 0x01 (Fast Refresh)  
2023-11-14 11:43:50 I (261) octal_psram: BurstType    : 0x01 (Hybrid Wrap)   
2023-11-14 11:43:50 I (266) octal_psram: BurstLen     : 0x01 (32 Byte)       
2023-11-14 11:43:50 I (272) octal_psram: Readlatency  : 0x02 (10 cycles@Fixed)
2023-11-14 11:43:50 I (278) octal_psram: DriveStrength: 0x00 (1/1)
2023-11-14 11:43:50 I (284) MSPI Timing: PSRAM timing tuning index: 5        
2023-11-14 11:43:50 I (288) esp_psram: Found 8MB PSRAM device
2023-11-14 11:43:50 I (293) esp_psram: Speed: 80MHz
2023-11-14 11:43:50 I (344) mmu_psram: Instructions copied and mapped to SPIRAM
2023-11-14 11:43:50 I (358) mmu_psram: Read only data copied and mapped to SPIRAM
2023-11-14 11:43:50 I (358) cpu_start: Pro cpu up.
2023-11-14 11:43:50 I (358) cpu_start: Starting app cpu, entry point is 0x403756e0
2023-11-14 11:43:50 0x403756e0: call_start_cpu1 at D:/espressif/Espressif/frameworks/esp-idf-v5.1.1/components/esp_system/port/cpu_start.c:154

2023-11-14 11:43:50 I (0) cpu_start: App cpu up.
2023-11-14 11:43:50 I (784) esp_psram: SPI SRAM memory test OK
2023-11-14 11:43:50 I (792) cpu_start: Pro cpu start user code
2023-11-14 11:43:50 I (792) cpu_start: cpu freq: 240000000 Hz
2023-11-14 11:43:50 I (792) cpu_start: Application information:
2023-11-14 11:43:50 I (795) cpu_start: Project name:     project1
2023-11-14 11:43:50 I (800) cpu_start: App version:      1
2023-11-14 11:43:50 I (805) cpu_start: Compile time:     Nov 14 2023 11:33:412023-11-14 11:43:50 I (811) cpu_start: ELF file SHA256:  473c4fb0d95f68be... 
2023-11-14 11:43:50 I (817) cpu_start: ESP-IDF:          v5.1.1-dirty
2023-11-14 11:43:50 I (822) cpu_start: Min chip rev:     v0.0
2023-11-14 11:43:50 I (827) cpu_start: Max chip rev:     v0.99 
2023-11-14 11:43:50 I (832) cpu_start: Chip rev:         v0.1
2023-11-14 11:43:50 I (837) heap_init: Initializing. RAM available for dynamic allocation:
2023-11-14 11:43:50 I (844) heap_init: At 3FC9BCA8 len 0004DA68 (310 KiB): DRAM
2023-11-14 11:43:50 I (850) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
2023-11-14 11:43:50 I (857) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
2023-11-14 11:43:50 I (863) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM
2023-11-14 11:43:51 I (869) spi_flash: detected chip: generic
2023-11-14 11:43:51 I (874) spi_flash: flash io: dio
2023-11-14 11:43:51 I (878) sleep: Configure to isolate all GPIO pins in sleep state
2023-11-14 11:43:51 I (884) sleep: Enable automatic switching of GPIO sleep configuration
2023-11-14 11:43:51 I (892) coexist: coex firmware version: 80b0d89
2023-11-14 11:43:51 I (897) coexist: coexist rom version e7ae62f
2023-11-14 11:43:51 I (902) app_start: Starting scheduler on CPU0
2023-11-14 11:43:51 I (907) app_start: Starting scheduler on CPU1
2023-11-14 11:43:51 I (907) main_task: Started on CPU0
2023-11-14 11:43:51 I (917) main_task: Calling app_main()

More Information.

No response

tore-espressif commented 10 months ago

hi @TRYOKETHEPEN , thanks for the issue and log.

So far, the only case when we saw usb_host_install failing is because of failed interrupt allocation. Symptoms of your problem are the same. Here's a very good explanation of what is going on and how to debug it, from one of our colleagues https://github.com/espressif/esp-idf/issues/10903#issuecomment-1456176716

TLDR:

When USB_HOST is set at CPU1, the project running well.

The easiest solution for you is to pin the USB task to CPU1

acautomacaoecontrole commented 1 month ago

I have experienced something similar to what was reported here.

A project that contains a webserver and a USB HID host was crashing at the very moment usb_host_install() was called. If webserver code was removed, everything was ok. usb_host_install() was called from a task defined to run on CPU 0. After changing to CPU 1, problem is gone. Thanks to this issue registry, I could solve by now the problem, but it would be better to get a real solution for this. Hope you soon can do that.

DEBUG dump below:

ESP_ERROR_CHECK failed: esp_err_t 0x105 (ESP_ERR_NOT_FOUND) at 0x4200a1af 0x4200a1af: usb_lib_task at D:/.../main/hid_host_example.c:923 (discriminator 1)

file: "./main/hid_host_example.c" line 923 func: usb_lib_task expression: usb_host_install(&host_config)

abort() was called at PC 0x4037d0e7 on core 0 0x4037d0e7: _esp_error_check_failed at C:/Users/Admin/esp/v5.1.4/esp-idf/components/esp_system/esp_err.c:50

Backtrace: 0x40375a8a:0x3fcb5ec0 0x4037d0f1:0x3fcb5ee0 0x403847ba:0x3fcb5f00 0x4037d0e7:0x3fcb5f70 0x4200a1af:0x3fcb5fa0 0x4037dc85:0x3fcb5fd0
0x40375a8a: panic_abort at C:/Users/Admin/esp/v5.1.4/esp-idf/components/esp_system/panic.c:466 0x4037d0f1: esp_system_abort at C:/Users/Admin/esp/v5.1.4/esp-idf/components/esp_system/port/esp_system_chip.c:84 0x403847ba: abort at C:/Users/Admin/esp/v5.1.4/esp-idf/components/newlib/abort.c:38 0x4037d0e7: _esp_error_check_failed at C:/Users/Admin/esp/v5.1.4/esp-idf/components/esp_system/esp_err.c:50 0x4200a1af: usb_lib_task at D:/.../main/hid_host_example.c:923 (discriminator 1) 0x4037dc85: vPortTaskWrapper at C:/Users/Admin/esp/v5.1.4/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

ELF file SHA256: 62590826

Rebooting... ESP-ROM:esp32s3-20210327 Build:Mar 27 2021 rst:0x3 (RTC_SW_SYS_RST),boot:0x8 (SPI_FAST_FLASH_BOOT) Saved PC:0x4037590c 0x4037590c: esp_restart_noos_dig at C:/Users/Admin/esp/v5.1.4/esp-idf/components/esp_system/port/esp_system_chip.c:57 (discriminator 1)

SPIWP:0xee mode:DIO, clock div:1 load:0x3fce3818,len:0x1750 load:0x403c9700,len:0x4 load:0x403c9704,len:0xc00 load:0x403cc700,len:0x2e0c entry 0x403c9908