espressif / esp-idf

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

USB msc_example - Stack Overflow on Connection of a USB Stick (IDFGH-11176) #12344

Closed dmglogowskiOS closed 11 months ago

dmglogowskiOS commented 1 year ago

Answers checklist.

General issue report

In the example for the USB MSC driver, the task called "usb_events" appears to experience a Stack Overflow, this occurs even after increasing Stack Size of the task to 100kB.

We are running ESP-IDF 5.1.1 and an ESP32S3

Log:

SPIWP:0xee
Octal Flash Mode Enabled
For OPI Flash, Use Default Flash Boot Mode
mode:SLOW_RD, clock div:1
load:0x3fce3818,len:0x16f8
load:0x403c9700,len:0x4
load:0x403c9704,len:0xc00
load:0x403cc700,len:0x2eb0
entry 0x403c9908
I (38) boot: ESP-IDF v5.1.1-dirty 2nd stage bootloader
I (38) boot: compile time Oct  2 2023 13:51:53
I (38) boot: Multicore bootloader
I (41) boot: chip revision: v0.1
I (45) boot.esp32s3: Boot SPI Speed : 80MHz
I (50) boot.esp32s3: SPI Mode       : SLOW READ
I (55) boot.esp32s3: SPI Flash Size : 2MB
I (60) boot: Enabling RNG early entropy source...
I (65) boot: Partition Table:
I (69) boot: ## Label            Usage          Type ST Offset   Length
I (76) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (84) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (91) boot:  2 factory          factory app      00 00 00010000 00100000
I (99) boot: End of partition table
I (103) esp_image: segment 0: paddr=00010020 vaddr=3c040020 size=0f14ch ( 61772) map
I (126) esp_image: segment 1: paddr=0001f174 vaddr=3fc92200 size=00ea4h (  3748) load
I (127) esp_image: segment 2: paddr=00020020 vaddr=42000020 size=31700h (202496) map
I (180) esp_image: segment 3: paddr=00051728 vaddr=3fc930a4 size=01a34h (  6708) load
I (182) esp_image: segment 4: paddr=00053164 vaddr=40374000 size=0e1a0h ( 57760) load
I (208) boot: Loaded app from partition at offset 0x10000
I (208) boot: Disabling RNG early entropy source...
I (219) cpu_start: Multicore app
I (220) cpu_start: Pro cpu up.
I (220) cpu_start: Starting app cpu, entry point is 0x403752d4
0x403752d4: call_start_cpu1 at /opt/esp/idf/components/esp_system/port/cpu_start.c:154

I (0) cpu_start: App cpu up.
I (238) cpu_start: Pro cpu start user code
I (238) cpu_start: cpu freq: 160000000 Hz
I (238) cpu_start: Application information:
I (241) cpu_start: Project name:     usb-msc
I (246) cpu_start: App version:      v5.1.1-dirty
I (251) cpu_start: Compile time:     Oct  2 2023 13:51:50
I (257) cpu_start: ELF file SHA256:  3235364810c15a2f...
I (263) cpu_start: ESP-IDF:          v5.1.1-dirty
I (268) cpu_start: Min chip rev:     v0.0
I (273) cpu_start: Max chip rev:     v0.99 
I (278) cpu_start: Chip rev:         v0.1
I (283) heap_init: Initializing. RAM available for dynamic allocation:
I (290) heap_init: At 3FC953A0 len 00054370 (336 KiB): DRAM
I (296) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (303) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (309) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM
W (316) spi_flash: Octal flash chip is using but dio mode is selected, will automatically swich to Octal mode
I (326) spi_flash: detected chip: mxic (opi)
I (331) spi_flash: flash io: opi_str
W (335) spi_flash: Detected size(32768k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (348) sleep: Configure to isolate all GPIO pins in sleep state
I (355) sleep: Enable automatic switching of GPIO sleep configuration
I (362) app_start: Starting scheduler on CPU0
I (367) app_start: Starting scheduler on CPU1
I (367) main_task: Started on CPU0
I (377) main_task: Calling app_main()
I (377) gpio: GPIO[10]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (417) example: Waiting for USB stick to be connected
I (797) example: MSC device connected

***ERROR*** A stack overflow in task USB MSC has been detected.

Backtrace: 0x4037581e:0x3fcb3e80 0x40379c51:0x3fcb3ea0 0x4037c686:0x3fcb3ec0 0x4037b1cf:0x3fcb3f40 0x4037c794:0x3fcb3f60 0x4037c78a:0x00000000 |<-CORRUPTED
0x4037581e: panic_abort at /opt/esp/idf/components/esp_system/panic.c:452

0x40379c51: esp_system_abort at /opt/esp/idf/components/esp_system/port/esp_system_chip.c:84

0x4037c686: vApplicationStackOverflowHook at /opt/esp/idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:581

0x4037b1cf: vTaskSwitchContext at /opt/esp/idf/components/freertos/FreeRTOS-Kernel/tasks.c:3729

0x4037c794: _frxt_dispatch at /opt/esp/idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/portasm.S:450

0x4037c78a: _frxt_int_exit at /opt/esp/idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/portasm.S:245

ELF file SHA256: 3235364810c15a2f

Rebooting...

This might be related to the issue described in 10718

igrr commented 1 year ago

@dmglogowskiOS To get a more useful backtrace, could you please try enabling CONFIG_FREERTOS_WATCHPOINT_END_OF_STACK=y option? It should hopefully catch the moment when the stack overflow occurs.

dmglogowskiOS commented 1 year ago

@igrr It appears as though that as soon as that option is enabled, the example works as intended?

Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x28 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
Octal Flash Mode Enabled
For OPI Flash, Use Default Flash Boot Mode
mode:SLOW_RD, clock div:1
load:0x3fce3818,len:0x16f8
load:0x403c9700,len:0x4
load:0x403c9704,len:0xc00
load:0x403cc700,len:0x2eb0
entry 0x403c9908
I (33) boot: ESP-IDF v5.1.1-dirty 2nd stage bootloader
I (33) boot: compile time Oct  4 2023 07:58:59
I (33) boot: Multicore bootloader
I (37) boot: chip revision: v0.1
I (41) boot.esp32s3: Boot SPI Speed : 80MHz
I (46) boot.esp32s3: SPI Mode       : SLOW READ
I (51) boot.esp32s3: SPI Flash Size : 2MB
I (56) boot: Enabling RNG early entropy source...
I (61) boot: Partition Table:
I (65) boot: ## Label            Usage          Type ST Offset   Length
I (72) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (79) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (87) boot:  2 factory          factory app      00 00 00010000 00100000
I (94) boot: End of partition table
I (98) esp_image: segment 0: paddr=00010020 vaddr=3c040020 size=0f1b4h ( 61876) map
I (122) esp_image: segment 1: paddr=0001f1dc vaddr=3fc92200 size=00e3ch (  3644) load
I (123) esp_image: segment 2: paddr=00020020 vaddr=42000020 size=31840h (202816) map
I (176) esp_image: segment 3: paddr=00051868 vaddr=3fc9303c size=01a9ch (  6812) load
I (178) esp_image: segment 4: paddr=0005330c vaddr=40374000 size=0e1d4h ( 57812) load
I (203) boot: Loaded app from partition at offset 0x10000
I (204) boot: Disabling RNG early entropy source...
I (215) cpu_start: Multicore app
I (215) cpu_start: Pro cpu up.
I (215) cpu_start: Starting app cpu, entry point is 0x403752d8
0x403752d8: call_start_cpu1 at /opt/esp/idf/components/esp_system/port/cpu_start.c:154

I (0) cpu_start: App cpu up.
I (233) cpu_start: Pro cpu start user code
I (233) cpu_start: cpu freq: 160000000 Hz
I (233) cpu_start: Application information:
I (236) cpu_start: Project name:     usb-msc
I (241) cpu_start: App version:      v5.1.1-dirty
I (247) cpu_start: Compile time:     Oct  4 2023 07:58:55
I (253) cpu_start: ELF file SHA256:  8779ddabe681ccd1...
I (259) cpu_start: ESP-IDF:          v5.1.1-dirty
I (264) cpu_start: Min chip rev:     v0.0
I (269) cpu_start: Max chip rev:     v0.99 
I (274) cpu_start: Chip rev:         v0.1
I (278) heap_init: Initializing. RAM available for dynamic allocation:
I (286) heap_init: At 3FC953A0 len 00054370 (336 KiB): DRAM
I (292) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (298) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (305) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM
W (311) spi_flash: Octal flash chip is using but dio mode is selected, will automatically swich to Octal mode
I (322) spi_flash: detected chip: mxic (opi)
I (326) spi_flash: flash io: opi_str
W (331) spi_flash: Detected size(32768k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (344) sleep: Configure to isolate all GPIO pins in sleep state
I (351) sleep: Enable automatic switching of GPIO sleep configuration
I (358) app_start: Starting scheduler on CPU0
I (363) app_start: Starting scheduler on CPU1
I (363) main_task: Started on CPU0
I (373) main_task: Calling app_main()
I (373) gpio: GPIO[10]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (413) example: Waiting for USB stick to be connected
E (22763) HUB: Root port reset failed
I (23283) example: MSC device connected
I (23283) example: connection...
*** Device descriptor ***
bLength 18
bDescriptorType 1
bcdUSB 2.10
bDeviceClass 0x0
bDeviceSubClass 0x0
bDeviceProtocol 0x0
bMaxPacketSize0 64
idVendor 0x781
idProduct 0x55a9
bcdDevice 1.00
iManufacturer 1
iProduct 2
iSerialNumber 3
bNumConfigurations 1
*** Configuration descriptor ***
bLength 9
bDescriptorType 2
wTotalLength 32
bNumInterfaces 1
bConfigurationValue 1
iConfiguration 0
bmAttributes 0x80
bMaxPower 224mA
        *** Interface descriptor ***
        bLength 9
        bDescriptorType 4
        bInterfaceNumber 0
        bAlternateSetting 0
        bNumEndpoints 2
        bInterfaceClass 0x8
        bInterfaceSubClass 0x6
        bInterfaceProtocol 0x50
        iInterface 0
                *** Endpoint descriptor ***
                bLength 7
                bDescriptorType 5
                bEndpointAddress 0x81   EP 1 IN
                bmAttributes 0x2        BULK
                wMaxPacketSize 64
                bInterval 0
                *** Endpoint descriptor ***
                bLength 7
                bDescriptorType 5
                bEndpointAddress 0x2    EP 2 OUT
                bmAttributes 0x2        BULK
                wMaxPacketSize 64
                bInterval 0
Device info:
         Capacity: 29357 MB
         Sector size: 512
         Sector count: 60125183
         PID: 0x55A9 
         VID: 0x 781 
         iProduct:  SanDisk 3.2Gen1 
         iManufacturer:  USB 
         iSerialNumber: 0401bfbebc88f72b2990b25380611bf 
I (25723) example: Creating file
I (25763) example: Reading file
I (25763) example: Read from file: 'Hello World!'

I can also no longer replicate the issue, by disableing that option?

I am very confused as to how this apparently fixed itself, because the only change I made to the example code was increasing stack size to 100kB. However decreasing it back to the default of 2kB doesn't seem to make a change.

roma-jam commented 1 year ago

Hi everyone, Can the problem be related to the same issue, described here, https://github.com/espressif/esp-idf/issues/12082?

dmglogowskiOS commented 1 year ago

It is certainly possible, that the issues are related, considering their very similar behaviours.

tore-espressif commented 11 months ago

Fixed by https://github.com/espressif/esp-idf/commit/e6fde2e13e667281932effccb7324814b558075d

Feel free to reopen if the problem persists

dmglogowskiOS commented 11 months ago

Works like a charm in that commit!