search

espressif / esp-idf

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

crash after succesful OTA over BLE (IDFGH-1682) #3923

Open chegewara opened 5 years ago

chegewara commented 5 years ago

Hi, i am trying to write OTA over BLE example and it is working, but after restart i have multiple times app crash. Full story:

Here are logs:

I (445) esp_image: segment 5: paddr=0x002675d8 vaddr=0x40080400 size=0x12648 ( 75336) load
I (497) boot: Loaded app from partition at offset 0x190000
I (497) boot: Disabling RNG early entropy source...
I (498) cpu_start: Pro cpu up.
I (501) cpu_start: Application information:
I (506) cpu_start: Project name:     hello-world
I (511) cpu_start: App version:      1
I (516) cpu_start: Compile time:     Aug 14 2019 09:15:39
I (522) cpu_start: ELF file SHA256:  4d3c7dd765532430...
I (528) cpu_start: ESP-IDF:          v4.0-dev-1443-g39f090a
I (534) cpu_start: Starting app cpu, entry point is 0x40081228
0x40081228: call_start_cpu1 at /home/chegewara/esp/esp-idf/components/esp32/cpu_start.c:281

I (524) cpu_start: App cpu up.
I (545) heap_init: Initializing. RAM available for dynamic allocation:
I (552) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (558) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (564) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (570) heap_init: At 3FFBDB5C len 00000004 (0 KiB): DRAM
I (576) heap_init: At 3FFC3870 len 0001C790 (113 KiB): DRAM
I (582) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (588) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (595) heap_init: At 40092A48 len 0000D5B8 (53 KiB): IRAM
I (601) cpu_start: Pro cpu start user code
I (620) spi_flash: detected chip: generic
I (620) spi_flash: flash io: dio
I (621) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (768) phy: phy_version: 4102, 2fa7a43, Jul 15 2019, 13:06:06, 0, 2
// esp_app_desc_t dump from image which is used to flash
E (1958) compare_app_versions: 32 54 cd ab 00 00 00 00 00 00 00 00 00 00 00 00 
E (1958) compare_app_versions: 31 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (1958) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (1968) compare_app_versions: 68 65 6c 6c 6f 2d 77 6f 72 6c 64 00 00 00 00 00 
E (1978) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (1988) compare_app_versions: 30 39 3a 31 35 3a 33 39 00 00 00 00 00 00 00 00 
E (1988) compare_app_versions: 41 75 67 20 31 34 20 32 30 31 39 00 00 00 00 00 
E (1998) compare_app_versions: 76 34 2e 30 2d 64 65 76 2d 31 34 34 33 2d 67 33 
E (2008) compare_app_versions: 39 66 30 39 30 61 00 00 00 00 00 00 00 00 00 00 
E (2018) compare_app_versions: 4d 3c 7d d7 65 53 24 30 08 77 8c 77 f0 9b e9 9a 
E (2028) compare_app_versions: 78 4c e8 e4 e5 39 44 89 bd 1d 5e 48 d1 61 09 1d 
E (2028) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2038) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2048) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2058) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2068) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
// esp_app_desc_t from currently running partition after flash (newly flashed image)
E (2068) compare_app_versions: 32 54 cd ab 00 00 00 00 00 00 00 00 00 00 00 00 
E (2078) compare_app_versions: 31 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2088) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2098) compare_app_versions: 68 65 6c 6c 6f 2d 77 6f 72 6c 64 00 00 00 00 00 
E (2108) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2108) compare_app_versions: 30 39 3a 31 35 3a 33 39 00 00 00 00 00 00 00 00 
E (2118) compare_app_versions: 41 75 67 20 31 34 20 32 30 31 39 00 00 00 00 00 
E (2128) compare_app_versions: 76 34 2e 30 2d 64 65 76 2d 31 34 34 33 2d 67 33 
E (2138) compare_app_versions: 39 66 30 39 30 61 00 00 00 00 00 00 00 00 00 00 
E (2148) compare_app_versions: 4d 3c 7d d7 65 53 24 30 08 77 8c 77 f0 9b e9 9a 
E (2148) compare_app_versions: 78 4c e8 e4 e5 39 44 89 bd 1d 5e 48 d1 61 09 1d 
E (2158) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2168) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2178) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2188) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2188) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2198) TAG: Starting OTA example...
Guru Meditation Error: Core  0 panic'ed (Cache disabled but cached memory region accessed)
Core 0 register dump:
PC      : 0x40127ae8  PS      : 0x00060c34  A0      : 0x800882e1  A1      : 0x3ffbe1f0  
0x40127ae8: r_platform_reset at ??:?

A2      : 0x00000000  A3      : 0x40127ae8  A4      : 0x00000000  A5      : 0x00000014  
0x40127ae8: r_platform_reset at ??:?

A6      : 0x3ffb93cc  A7      : 0x3ffb8360  A8      : 0x80019fb8  A9      : 0x0000205c  
A10     : 0xf2f2f2f2  A11     : 0x0000a55a  A12     : 0x00000001  A13     : 0x00000020  
A14     : 0x000002dc  A15     : 0x3ffb8360  SAR     : 0x00000015  EXCCAUSE: 0x00000007  
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  
Core 0 was running in ISR context:
EPC1    : 0x400900b7  EPC2    : 0x00000000  EPC3    : 0x00000000  EPC4    : 0x40127ae8
0x400900b7: portENTER_CRITICAL_NESTED at /home/chegewara/esp/esp-idf/components/freertos/include/freertos/portmacro.h:324
 (inlined by) xPortInIsrContext at /home/chegewara/esp/esp-idf/components/freertos/port.c:338

0x40127ae8: r_platform_reset at ??:?

ELF file SHA256: ad0bd0baad0bd0baad0bd0baad0bd0baad0bd0baad0bd0baad0bd0baad0bd0ba

Backtrace: 0x40127ae5:0x3ffbe1f0 0x400882de:0x3ffbe220 0x40087b6d:0x3ffbe260 0x400875b2:0x3ffbe280 0x400888c6:0x3ffbe2a0 0x4008973b:0x3ffbe2c0 0x40082a15:0x3ffbe2e0 0x4008346c:0x3ffb7e10 0x4008212b:0x3ffb7e30 0x4008ffbd:0x3ffb7e50
0x40127ae5: r_get_stack_usage at ??:?

0x400882de: r_lld_pdu_rx_handler at ??:?

0x40087b6d: r_lld_evt_end at ??:?

0x400875b2: r_lld_evt_end_isr at ??:?

0x400888c6: r_rwble_isr at ??:?

0x4008973b: r_rwbtdm_isr_wrapper at intc.c:?

0x40082a15: _xt_lowint1 at /home/chegewara/esp/esp-idf/components/freertos/xtensa_vectors.S:1153

0x4008346c: spi_flash_op_block_func at /home/chegewara/esp/esp-idf/components/spi_flash/cache_utils.c:82 (discriminator 1)

0x4008212b: ipc_task at /home/chegewara/esp/esp-idf/components/esp_common/src/ipc.c:62

0x4008ffbd: vPortTaskWrapper at /home/chegewara/esp/esp-idf/components/freertos/port.c:143

Rebooting...
ets Jun  8 2016 00:22:57

rst:0x3 (SW_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
flash read err, 1000
ets_main.c 371 
ets Jun  8 2016 00:22:57

rst:0x7 (TG0WDT_SYS_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 188777542, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:6560
ho 0 tail 12 room 4
load:0x40078000,len:11368
ho 0 tail 12 room 4
load:0x40080400,len:6692
entry 0x40080770
W (33) boot: PRO CPU has been reset by WDT.
W (33) boot: WDT reset info: PRO CPU PC=0x4008db3b
0x4008db3b: esp_panic_dig_reset at /home/chegewara/esp/esp-idf/components/esp32/panic.c:444 (discriminator 1)

W (34) boot: WDT reset info: APP CPU PC=0x4008dcc4
0x4008dcc4: panicHandler at /home/chegewara/esp/esp-idf/components/esp32/panic.c:256 (discriminator 2)

I (39) boot: ESP-IDF v4.0-dev-1443-g39f090a 2nd stage bootloader
I (46) boot: compile time 09:27:26
I (50) boot: Enabling RNG early entropy source...
I (55) boot: SPI Speed      : 40MHz
I (60) boot: SPI Mode       : DIO
I (64) boot: SPI Flash Size : 4MB
I (68) boot: Partition Table:
I (71) boot: ## Label            Usage          Type ST Offset   Length
I (79) boot:  0 otadata          OTA data         01 00 00009000 00002000
I (86) boot:  1 phy_init         RF data          01 01 0000b000 00001000
I (93) boot:  2 ota_0            OTA app          00 10 00010000 00180000
I (101) boot:  3 ota_1            OTA app          00 11 00190000 00180000
I (108) boot:  4 storage          WiFi data        01 02 00310000 00010000
I (116) boot:  5 nvs              WiFi data        01 02 00320000 00006000
I (124) boot: End of partition table
I (128) esp_image: segment 0: paddr=0x00190020 vaddr=0x3f400020 size=0x2e924 (190756) map
I (205) esp_image: segment 1: paddr=0x001be94c vaddr=0x3ffbdb60 size=0x016c4 (  5828) load
I (208) esp_image: segment 2: paddr=0x001c0018 vaddr=0x400d0018 size=0xa5c20 (678944) map
0x400d0018: _stext at ??:?

I (455) esp_image: segment 3: paddr=0x00265c40 vaddr=0x3ffbf224 size=0x01588 (  5512) load
I (457) esp_image: segment 4: paddr=0x002671d0 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _WindowOverflow4 at /home/chegewara/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

I (462) esp_image: segment 5: paddr=0x002675d8 vaddr=0x40080400 size=0x12648 ( 75336) load
I (513) boot: Loaded app from partition at offset 0x190000
I (513) boot: Disabling RNG early entropy source...
I (514) cpu_start: Pro cpu up.
I (517) cpu_start: Application information:
I (522) cpu_start: Project name:     hello-world
I (528) cpu_start: App version:      1
I (532) cpu_start: Compile time:     Aug 14 2019 09:15:39
I (538) cpu_start: ELF file SHA256:  4d3c7dd765532430...
I (544) cpu_start: ESP-IDF:          v4.0-dev-1443-g39f090a
I (550) cpu_start: Starting app cpu, entry point is 0x40081228
0x40081228: call_start_cpu1 at /home/chegewara/esp/esp-idf/components/esp32/cpu_start.c:281

I (0) cpu_start: App cpu up.
I (561) heap_init: Initializing. RAM available for dynamic allocation:
I (568) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (574) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (580) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (586) heap_init: At 3FFBDB5C len 00000004 (0 KiB): DRAM
I (592) heap_init: At 3FFC3870 len 0001C790 (113 KiB): DRAM
I (598) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (605) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (611) heap_init: At 40092A48 len 0000D5B8 (53 KiB): IRAM
I (617) cpu_start: Pro cpu start user code
I (636) spi_flash: detected chip: generic
I (637) spi_flash: flash io: dio
I (637) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (794) phy: phy_version: 4102, 2fa7a43, Jul 15 2019, 13:06:06, 0, 2
// esp_app_desc_t dump from image which is used to flash
E (1924) compare_app_versions: 32 54 cd ab 00 00 00 00 00 00 00 00 00 00 00 00 
E (1924) compare_app_versions: 31 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (1924) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (1934) compare_app_versions: 68 65 6c 6c 6f 2d 77 6f 72 6c 64 00 00 00 00 00 
E (1944) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (1954) compare_app_versions: 30 39 3a 31 35 3a 33 39 00 00 00 00 00 00 00 00 
E (1964) compare_app_versions: 41 75 67 20 31 34 20 32 30 31 39 00 00 00 00 00 
E (1964) compare_app_versions: 76 34 2e 30 2d 64 65 76 2d 31 34 34 33 2d 67 33 
E (1974) compare_app_versions: 39 66 30 39 30 61 00 00 00 00 00 00 00 00 00 00 
E (1984) compare_app_versions: 4d 3c 7d d7 65 53 24 30 08 77 8c 77 f0 9b e9 9a 
E (1994) compare_app_versions: 78 4c e8 e4 e5 39 44 89 bd 1d 5e 48 d1 61 09 1d 
E (2004) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2004) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2014) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2024) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2034) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
// esp_app_desc_t from currently running partition after flash (newly flashed image)
E (2044) compare_app_versions: 32 54 cd ab 00 00 00 00 00 00 00 00 00 00 00 00 
E (2044) compare_app_versions: 31 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2054) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2064) compare_app_versions: 68 65 6c 6c 6f 2d 77 6f 72 6c 64 00 00 00 00 00 
E (2074) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2084) compare_app_versions: 30 39 3a 31 35 3a 33 39 00 00 00 00 00 00 00 00 
E (2084) compare_app_versions: 41 75 67 20 31 34 20 32 30 31 39 00 00 00 00 00 
E (2094) compare_app_versions: 76 34 2e 30 2d 64 65 76 2d 31 34 34 33 2d 67 33 
E (2104) compare_app_versions: 39 66 30 39 30 61 00 00 00 00 00 00 00 00 00 00 
E (2114) compare_app_versions: 4d 3c 7d d7 65 53 24 30 08 77 8c 77 f0 9b e9 9a 
E (2114) compare_app_versions: 78 4c e8 e4 e5 39 44 89 bd 1d 5e 48 d1 61 09 1d 
E (2124) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2134) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2144) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2154) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2154) compare_app_versions: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (2164) TAG: Starting OTA example...
Guru Meditation Error: Core  0 panic'ed (Cache disabled but cached memory region accessed)
Core 0 register dump:
PC      : 0x40127ae8  PS      : 0x00060e34  A0      : 0x800466c6  A1      : 0x3ffbe210  
0x40127ae8: r_platform_reset at ??:?

A2      : 0x00000000  A3      : 0x40127ae8  A4      : 0x00000000  A5      : 0x00000010  
0x40127ae8: r_platform_reset at ??:?

A6      : 0x3ffb93cc  A7      : 0x3ffb8360  A8      : 0x80019fb8  A9      : 0x00002060  
A10     : 0xf2f2f2f2  A11     : 0x0000a55a  A12     : 0x00000001  A13     : 0x00000022  
A14     : 0x00001600  A15     : 0x3ffb8360  SAR     : 0x00000013  EXCCAUSE: 0x00000007  
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  
Core 0 was running in ISR context:
EPC1    : 0x400900b7  EPC2    : 0x00000000  EPC3    : 0x00000000  EPC4    : 0x40127ae8
0x400900b7: portENTER_CRITICAL_NESTED at /home/chegewara/esp/esp-idf/components/freertos/include/freertos/portmacro.h:324
 (inlined by) xPortInIsrContext at /home/chegewara/esp/esp-idf/components/freertos/port.c:338

0x40127ae8: r_platform_reset at ??:?

ELF file SHA256: ad0bd0baad0bd0baad0bd0baad0bd0baad0bd0baad0bd0baad0bd0baad0bd0ba

Backtrace: 0x40127ae5:0x3ffbe210 0x400466c3:0x3ffbe240 |<-CORRUPTED
0x40127ae5: r_get_stack_usage at ??:?
chegewara commented 5 years ago

Hi @Weijian-Espressif i think i found something useful that can help track the cause of this issue:

mvonflotow commented 5 years ago

Hi @chegewara Were you able to solve this? I am experiencing a very similar problem when trying to use either the SPI flash API or OTA APIs in a separate task from an active BLE server.

I can stop the crash from happening by calling these APIs from my BLE server callback function, such that the callback does not return before the APIs are called.

chegewara commented 5 years ago

Hi @mvonflotow like i described above, when i change log level then i dont see crashes anymore, also it takes 2 or 3 crashes on restart (only right after OTA update) and then runs normally.

mvonflotow commented 5 years ago

Thanks for the input, @chegewara. Unfortunately my crash still occurs even with the log verbosity set to "error," as you suggested above.

This seems to be related to the coexistence of WiFi and BLE in my project. Can you tell me if you had both of these protocols active when your crashes occurred? What is your setting in menuconfig -> component config -> Wi-Fi -> Software controls WiFi/Bluetooth coexistence?

chegewara commented 5 years ago

https://github.com/chegewara/esp32-OTA-over-BLE

mvonflotow commented 5 years ago

I was able to stop this bug from occurring by setting CONFIG_FREERTOS_UNICORE in make menuconfig ("Run Freertos only on first core").

Not a long-term solution, but certainly a work around.

chegewara commented 5 years ago

Yes, i can confirm that unicore works as workaround.

AxelLin commented 2 years ago

@Alvin1Zhang

Why do you close this issue? The espressif-bot added "Resolution: Done", so what is the resolution? Note, CONFIG_FREERTOS_UNICORE=y is not a resolution at all, it's just a workaround with sacrifice of hw performance.

AxelLin commented 1 year ago

@Alvin1Zhang @blueMoodBHD How is the progress of this issue since it's marked as "In Progress" for 1 year?

xiewenxiang commented 1 year ago

The Bluetooth library was rebuilt based on IDF version(v4.0-dev-1443-g39f090a). You can replace the library and retest it. libbtdm_app.a.zip

jack0c commented 1 year ago

@AxelLin I think this was closed since it was considered same as https://github.com/espressif/esp-idf/issues/7335, and closed by bot

AxelLin commented 1 year ago

@AxelLin I think this was closed since it was considered same as #7335, and closed by bot

https://github.com/espressif/esp-idf/issues/7335#issuecomment-1057536196 explictly mentioned BLE is not used in https://github.com/espressif/esp-idf/issues/7335, so I don't think it's the same issue.

In additional, a duplicated issue should be marked as "Resolution: Duplicate" rather than "Resolution: Done"