Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ESP32, IDF 5.0: error with nvs_flash_init #2653

Open
mr-sven opened this issue Jul 24, 2023 · 15 comments
Open

ESP32, IDF 5.0: error with nvs_flash_init #2653

mr-sven opened this issue Jul 24, 2023 · 15 comments

Comments

@mr-sven
Copy link
Contributor

mr-sven commented Jul 24, 2023

  • ESP-IDF v5.0-547-g20e8e86c80
  • SOC: Esp32 4MB flash
  • Sming 5.0.0

I have an issue with initialization of Wifi, I used a clean machine and try to deploy the Basic_Wifi sample. The ESP freezes at boot and the WDT is resetting the chip.

commands:

$ git clone https://github.com/SmingHub/Sming /opt/sming
$ INSTALL_IDF_VER=5.0 $SMING_HOME/../Tools/install.sh esp32
$ source /opt/sming/Sming/../Tools/export.sh
$ cd /opt/sming/samples/Basic_WiFi/
$ make SMING_ARCH=Esp32 flash

output of WDT and addresses

W (76) boot.esp32: PRO CPU has been reset by WDT.
W (82) boot.esp32: WDT reset info: PRO CPU PC=0x40082230
W (88) boot.esp32: WDT reset info: APP CPU PC=0x40080240

$ xtensa-esp32-elf-addr2line -fe out/Esp32/esp32/debug/build/app.out 0x40082230
_xt_highint5
/opt/esp-idf-5.0/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vector_defaults.S:192

$ xtensa-esp32-elf-addr2line -fe out/Esp32/esp32/debug/build/app.out 0x40080240
_Level5Vector
/opt/esp-idf-5.0/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1647

In the end I drilled it down to the function nvs_flash_init.
I used the Basic_Blink sample and added the function and it freezes.

#include <nvs_flash.h>

void init()
{
	pinMode(LED_PIN, OUTPUT);
	procTimer.initializeMs(1000, blink).start();
	esp_err_t ret = nvs_flash_init();
}

The crazy thing is, if I use the nvs_rw_value example of the installed IDF it is working.

commands:

$ cd /opt/esp-idf/examples/storage/nvs_rw_value
$ ../../../tools/idf.py set-target esp32
$ ../../../tools/idf.py build
$ ../../../tools/idf.py -p /dev/ttyUSB0 flash monitor
...
I (0) cpu_start: Starting scheduler on APP CPU.

Opening Non-Volatile Storage (NVS) handle... Done
Reading restart counter from NVS ... Done
Restart counter = 1
Updating restart counter in NVS ... Done
Committing updates in NVS ... Done
...
@slaff
Copy link
Contributor

slaff commented Jul 24, 2023

Just for my understanding: Is the Basic_Blink application working for you?
Also why are you adding platform/arch/soc specific code in an application? It will make it hard to use in another architecture.
And finally the nvs initialization for ESP32 is already done behind the scenes for you in Sming Components/Network/Arch/Esp32/Platform/init.cpp?

@mr-sven
Copy link
Contributor Author

mr-sven commented Jul 24, 2023

Ahm, Basic_Blink is working, Basic_Wifi is not working.
As soon as I remove the DISABLE_NETWORK switch form the Basic_Blink, it is also not working.
So I dig into.
In Sming/Arch/Esp32/Components/esp32/src/startup.cpp there is esp_network_initialise which is executed as soon as network is on.
In Sming/Components/Network/Arch/Esp32/Platform/init.cpp the first action is to initialize the NVS, and exactly there it freezes.

So for simple test you can execute the nvs_flash_init in the Basic_Blink and it freezes also.

@slaff
Copy link
Contributor

slaff commented Jul 24, 2023

@mr-sven Thank you.

So for simple test you can execute the nvs_flash_init in the Basic_Blink and it freezes also.

@mikee47 any idea what can cause this issue with IDF 5.0 ?

@mikee47
Copy link
Contributor

mikee47 commented Jul 24, 2023

I've traced it through to the spi_flash_disable_interrupts_caches_and_other_cpu() function (called during loading of the partition table) which hangs on the first spi_flash_disable_cache() call. I have a suspicion there's an interrupt service routine running out of flash, which shouldn't be.

@mikee47
Copy link
Contributor

mikee47 commented Jul 24, 2023

I've attempted to load the partition table as early as possible by calling esp_partition_find directly from app_main, but just hangs there instead.

A temporary fix is to run make sdk-menuconfig and set FREERTOS_UNICORE=y.

@mr-sven
Copy link
Contributor Author

mr-sven commented Jul 24, 2023

Yes, that works for the moment.
That was also my idea that anything stuck at task level or an ISR, because the WDT PC addresses are always at some interrupts.

@mr-sven
Copy link
Contributor Author

mr-sven commented Jul 25, 2023

I've diffed the sdkconfig from IDF and Sming.
The only settings what points me are CONFIG_ESP_SYSTEM_CHECK_INT_LEVEL_4 and CONFIG_ESP_SYSTEM_CHECK_INT_LEVEL_5, some WDT and FREERTOS Flags.

--- idf.sdkconfig       2023-07-25 11:25:11.701113817 +0200
+++ sming.sdkconfig     2023-07-25 11:29:56.472197308 +0200
@@ -16,4 +15,0 @@
-CONFIG_APPTRACE_DEST_NONE=y
-CONFIG_APPTRACE_DEST_UART_NONE=y
-CONFIG_APPTRACE_LOCK_ENABLE=y
-CONFIG_APPTRACE_UART_TASK_PRIO=1
@@ -37,2 +33,2 @@
-CONFIG_COMPILER_OPTIMIZATION_DEFAULT=y
-CONFIG_COMPILER_OPTIMIZATION_LEVEL_DEBUG=y
+CONFIG_COMPILER_OPTIMIZATION_LEVEL_RELEASE=y
+CONFIG_COMPILER_OPTIMIZATION_SIZE=y
@@ -46,2 +41,0 @@
-CONFIG_ESP32_APPTRACE_DEST_NONE=y
-CONFIG_ESP32_APPTRACE_LOCK_ENABLE=y
@@ -115 +108,0 @@
-CONFIG_ESP_HTTP_CLIENT_ENABLE_HTTPS=y
@@ -136,3 +128,0 @@
-CONFIG_ESP_PROTOCOMM_SUPPORT_SECURITY_VERSION_0=y
-CONFIG_ESP_PROTOCOMM_SUPPORT_SECURITY_VERSION_1=y
-CONFIG_ESP_PROTOCOMM_SUPPORT_SECURITY_VERSION_2=y
@@ -152 +142 @@
-CONFIG_ESP_SYSTEM_EVENT_TASK_STACK_SIZE=2304
+CONFIG_ESP_SYSTEM_EVENT_TASK_STACK_SIZE=16384
@@ -165 +154,0 @@
-CONFIG_ESP_TLS_USING_MBEDTLS=y
@@ -181,19 +169,0 @@
-CONFIG_ETH_DMA_BUFFER_SIZE=512
-CONFIG_ETH_DMA_RX_BUFFER_NUM=10
-CONFIG_ETH_DMA_TX_BUFFER_NUM=10
-CONFIG_ETH_ENABLED=y
-CONFIG_ETH_PHY_INTERFACE_RMII=y
-CONFIG_ETH_RMII_CLK_IN_GPIO=0
-CONFIG_ETH_RMII_CLK_INPUT=y
-CONFIG_ETH_USE_ESP32_EMAC=y
-CONFIG_ETH_USE_SPI_ETHERNET=y
-CONFIG_FATFS_AUTO_TYPE=y
-CONFIG_FATFS_CODEPAGE=437
-CONFIG_FATFS_CODEPAGE_437=y
-CONFIG_FATFS_FS_LOCK=0
-CONFIG_FATFS_LFN_NONE=y
-CONFIG_FATFS_PER_FILE_CACHE=y
-CONFIG_FATFS_SECTOR_4096=y
-CONFIG_FATFS_SECTORS_PER_CLUSTER_1=y
-CONFIG_FATFS_TIMEOUT_MS=10000
-CONFIG_FATFS_VOLUME_COUNT=2
@@ -207,0 +178 @@
+CONFIG_FREERTOS_GENERATE_RUN_TIME_STATS=y
@@ -214,0 +186 @@
+CONFIG_FREERTOS_RUN_TIME_STATS_USING_ESP_TIMER=y
@@ -217 +188,0 @@
-CONFIG_FREERTOS_TASK_FUNCTION_WRAPPER=y
@@ -222,0 +194,4 @@
+CONFIG_FREERTOS_USE_STATS_FORMATTING_FUNCTIONS=y
+CONFIG_FREERTOS_USE_TRACE_FACILITY=y
+CONFIG_FREERTOS_VTASKLIST_INCLUDE_COREID=y
+CONFIG_FREERTOS_WATCHPOINT_END_OF_STACK=y
@@ -228,4 +202,0 @@
-CONFIG_HTTPD_ERR_RESP_NO_DELAY=y
-CONFIG_HTTPD_MAX_REQ_HDR_LEN=512
-CONFIG_HTTPD_MAX_URI_LEN=512
-CONFIG_HTTPD_PURGE_BUF_LEN=32
@@ -242 +212,0 @@
-CONFIG_LCD_PANEL_IO_FORMAT_BUF_SIZE=32
@@ -293 +263 @@
-CONFIG_LWIP_TCPIP_TASK_STACK_SIZE=3072
+CONFIG_LWIP_TCPIP_TASK_STACK_SIZE=8192
@@ -311,3 +280,0 @@
-CONFIG_MBEDTLS_CERTIFICATE_BUNDLE_DEFAULT_FULL=y
-CONFIG_MBEDTLS_CERTIFICATE_BUNDLE_MAX_CERTS=200
-CONFIG_MBEDTLS_CERTIFICATE_BUNDLE=y
@@ -365,4 +331,0 @@
-CONFIG_MQTT_PROTOCOL_311=y
-CONFIG_MQTT_TRANSPORT_SSL=y
-CONFIG_MQTT_TRANSPORT_WEBSOCKET_SECURE=y
-CONFIG_MQTT_TRANSPORT_WEBSOCKET=y
@@ -375 +338 @@
-CONFIG_OPTIMIZATION_LEVEL_DEBUG=y
+CONFIG_OPTIMIZATION_LEVEL_RELEASE=y
@@ -393 +355,0 @@
-CONFIG_SEMIHOSTFS_MAX_MOUNT_POINTS=1
@@ -573,11 +534,0 @@
-CONFIG_SPIFFS_CACHE_WR=y
-CONFIG_SPIFFS_CACHE=y
-CONFIG_SPIFFS_GC_MAX_RUNS=10
-CONFIG_SPIFFS_MAX_PARTITIONS=3
-CONFIG_SPIFFS_META_LENGTH=4
-CONFIG_SPIFFS_OBJ_NAME_LEN=32
-CONFIG_SPIFFS_PAGE_CHECK=y
-CONFIG_SPIFFS_PAGE_SIZE=256
-CONFIG_SPIFFS_USE_MAGIC_LENGTH=y
-CONFIG_SPIFFS_USE_MAGIC=y
-CONFIG_SPIFFS_USE_MTIME=y
@@ -597,0 +549 @@
+CONFIG_SPI_MASTER_IN_IRAM=y
@@ -601,2 +552,0 @@
-CONFIG_SUPPORT_TERMIOS=y
-CONFIG_SUPPRESS_SELECT_DEBUG_OUTPUT=y
@@ -604 +554 @@
-CONFIG_SYSTEM_EVENT_TASK_STACK_SIZE=2304
+CONFIG_SYSTEM_EVENT_TASK_STACK_SIZE=16384
@@ -611 +561 @@
-CONFIG_TCPIP_TASK_STACK_SIZE=3072
+CONFIG_TCPIP_TASK_STACK_SIZE=8192
@@ -631,14 +580,0 @@
-CONFIG_UNITY_ENABLE_DOUBLE=y
-CONFIG_UNITY_ENABLE_FLOAT=y
-CONFIG_UNITY_ENABLE_IDF_TEST_RUNNER=y
-CONFIG_VFS_SEMIHOSTFS_MAX_MOUNT_POINTS=1
-CONFIG_VFS_SUPPORT_DIR=y
-CONFIG_VFS_SUPPORT_IO=y
-CONFIG_VFS_SUPPORT_SELECT=y
-CONFIG_VFS_SUPPORT_TERMIOS=y
-CONFIG_VFS_SUPPRESS_SELECT_DEBUG_OUTPUT=y
-CONFIG_WIFI_PROV_AUTOSTOP_TIMEOUT=30
-CONFIG_WIFI_PROV_SCAN_MAX_ENTRIES=16
-CONFIG_WIFI_PROV_STA_ALL_CHANNEL_SCAN=y
-CONFIG_WL_SECTOR_SIZE=4096
-CONFIG_WL_SECTOR_SIZE_4096=y
@@ -647,2 +582,0 @@
-CONFIG_WS_BUFFER_SIZE=1024
-CONFIG_WS_TRANSPORT=y

Edit: I removed the WDT Initialization from startup.cpp and enabled the IDF WDT in config, but the bug is still there.

@mr-sven
Copy link
Contributor Author

mr-sven commented Jul 25, 2023

I don't know but at the moment I have no clue.
One difference I found is, that the IDF Sample bootloader output ends with the following:

I (29) boot: ESP-IDF v5.0-547-g20e8e86c80 2nd stage bootloader
I (29) boot: compile time 11:47:34
I (29) boot: chip revision: v1.0
I (33) boot.esp32: SPI Speed      : 40MHz
I (38) boot.esp32: SPI Mode       : DIO
I (42) boot.esp32: SPI Flash Size : 4MB
I (47) boot: Enabling RNG early entropy source...
I (52) boot: Partition Table:
I (56) boot: ## Label            Usage          Type ST Offset   Length
I (63) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (71) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (78) boot:  2 factory          factory app      00 00 00010000 00100000
I (86) boot: End of partition table
I (90) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=08edch ( 36572) map
I (112) esp_image: segment 1: paddr=00018f04 vaddr=3ffb0000 size=01e8ch (  7820) load
I (115) esp_image: segment 2: paddr=0001ad98 vaddr=40080000 size=05280h ( 21120) load
I (126) esp_image: segment 3: paddr=00020020 vaddr=400d0020 size=19e60h (106080) map
I (165) esp_image: segment 4: paddr=00039e88 vaddr=40085280 size=06db4h ( 28084) load
I (183) boot: Loaded app from partition at offset 0x10000
I (183) boot: Disabling RNG early entropy source...
I (194) cpu_start: Pro cpu up.
I (194) cpu_start: Starting app cpu, entry point is 0x40081160
I (180) cpu_start: App cpu up.
I (209) cpu_start: Pro cpu start user code
I (209) cpu_start: cpu freq: 160000000 Hz
I (209) cpu_start: Application information:
I (213) cpu_start: Project name:     nvs_rw_value
I (219) cpu_start: App version:      v5.0-547-g20e8e86c80
I (225) cpu_start: Compile time:     Jul 25 2023 11:47:30
I (231) cpu_start: ELF file SHA256:  2f3b43f724c4c6c4...
I (237) cpu_start: ESP-IDF:          v5.0-547-g20e8e86c80
I (243) cpu_start: Min chip rev:     v0.0
I (248) cpu_start: Max chip rev:     v3.99
I (253) cpu_start: Chip rev:         v1.0
I (258) heap_init: Initializing. RAM available for dynamic allocation:
I (265) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (271) heap_init: At 3FFB27C0 len 0002D840 (182 KiB): DRAM
I (277) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (283) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (290) heap_init: At 4008C034 len 00013FCC (79 KiB): IRAM
I (297) spi_flash: detected chip: generic
I (301) spi_flash: flash io: dio
I (305) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.

The Sming sample bootloader output:

I (57) boot: ESP-IDF v5.0-547-g20e8e86c80 2nd stage bootloader
I (58) boot: compile time 11:46:08
I (58) boot: chip revision: v1.0
I (62) boot.esp32: SPI Speed      : 40MHz
I (67) boot.esp32: SPI Mode       : DIO
I (72) boot.esp32: SPI Flash Size : 4MB
I (94) boot: Enabling RNG early entropy source...
I (99) boot: Partition Table:
I (103) boot: ## Label            Usage          Type ST Offset   Length
I (110) boot:  0 spiFlash         unknown          02 01 00000000 00400000
I (117) boot:  1 nvs              WiFi data        01 02 00009000 00006000
I (125) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (133) boot:  3 factory          factory app      00 00 00010000 000f0000
I (140) boot: End of partition table
I (144) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=0804ch ( 32844) map
I (165) esp_image: segment 1: paddr=00018074 vaddr=3ffb0000 size=01bech (  7148) load
I (168) esp_image: segment 2: paddr=00019c68 vaddr=40080000 size=063b0h ( 25520) load
I (183) esp_image: segment 3: paddr=00020020 vaddr=400d0020 size=09f64h ( 40804) map
I (198) esp_image: segment 4: paddr=00029f8c vaddr=400863b0 size=04c28h ( 19496) load
I (211) boot: Loaded app from partition at offset 0x10000
I (212) boot: Disabling RNG early entropy source...
I (223) cpu_start: Pro cpu up.
I (223) cpu_start: Starting app cpu, entry point is 0x40080f0c
I (0) cpu_start: App cpu up.
I (237) cpu_start: Pro cpu start user code
I (237) cpu_start: cpu freq: 160000000 Hz
I (237) cpu_start: Application information:
I (242) cpu_start: Project name:     Sming
I (247) cpu_start: App version:      4.0.0-rc4-539-ge1b0f2b2-dirty
I (254) cpu_start: Compile time:     Jul 25 2023 11:46:11
I (260) cpu_start: ELF file SHA256:  7240a6988c72f902...
I (266) cpu_start: ESP-IDF:          v5.0-547-g20e8e86c80
I (272) cpu_start: Min chip rev:     v0.0
I (277) cpu_start: Max chip rev:     v3.99
I (282) cpu_start: Chip rev:         v1.0
I (286) heap_init: Initializing. RAM available for dynamic allocation:
I (294) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (300) heap_init: At 3FFB2570 len 0002DA90 (182 KiB): DRAM
I (306) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (312) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (319) heap_init: At 4008AFD8 len 00015028 (84 KiB): IRAM
I (0) cpu_start: Starting scheduler on APP CPU.

So there is the spi_flash output missing.

@mr-sven
Copy link
Contributor Author

mr-sven commented Jul 25, 2023

Ok, that was also not the problem. Its only caused because the message is enclosed in ESP_LOGI and not ESP_EARLY_LOGI.

@mr-sven
Copy link
Contributor Author

mr-sven commented Jul 31, 2023

I've tried hard on setting sdkconfig switches, but nothing helped. It looks like there are some compiler switches missing or any other thing. I'm totally lost at the moment.

@mikee47
Copy link
Contributor

mikee47 commented Jul 31, 2023

Do you need both CPUs? If not, stick to unicore for now.

@mikee47
Copy link
Contributor

mikee47 commented Jul 31, 2023

Getting rid of FreeRTOS entirely would be ideal, but the WiFi stack is closed-source and has some embedded dependencies on RTOS operation.

Consipiracy edit: Strategy by Espressif to ensure they have a closed-source BLOB which gets them full control if required.

@profjmer
Copy link

Other samples reset the ESP32 too. Those using WiFi.
I had a functional web site running on ESP32, but the new version brakes the code and ESP32 is always resetting.
How can we identify Sming version from the uart log ?

@mr-sven
Copy link
Contributor Author

mr-sven commented Aug 12, 2023

Afaik. the problem is located in the SPI flash access. I currently had no chance to test against IDF 4.4, I think it is caused by IDF 5.

@mikee47
Copy link
Contributor

mikee47 commented Jan 6, 2024

Afaik. the problem is located in the SPI flash access. I currently had no chance to test against IDF 4.4, I think it is caused by IDF 5.

I've updated sming IDF 4.4 to latest Espressif release (date 3/1/24) and can confirm that the above issue is still present, however the same fix applies and Basic_Ssl sample is working.

To update existing IDF installation manually:

cd /opt/esp-idf-4.4
git pull
git submodule update --init --recursive
python3 tools/idf_tools.py --non-interactive install-python-env

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants