error loading PHY init data

[ikerbelloso]

HI,
I've been facing some problems with the NVS recently. I've been trying to implementa a Flash log to save some required events. Somehow I have reached a point where the NVS partition was full so the app was stucked and somehow nvs partition end corrupted. So, I erased the full flash. From then, I'm getting errors similar to this one:

(1102) cpu_start: Pro cpu up.
I (1103) cpu_start: Single core mode
I (1104) heap_alloc_caps: Initializing. RAM available for dynamic allocation:
I (1117) heap_alloc_caps: At 3FFAE2A0 len 00001D60 (7 KiB): DRAM
I (1137) heap_alloc_caps: At 3FFC18C0 len 0001E740 (121 KiB): DRAM
I (1158) heap_alloc_caps: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (1180) heap_alloc_caps: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1201) heap_alloc_caps: At 4009B804 len 000047FC (17 KiB): IRAM
check b=0x3ffae2ac size=7496 ok
check b=0x3ffafff4 size=0 ok
check b=0x3ffc18cc size=124712 ok
check b=0x3ffdfff4 size=0 ok
check b=0x3ffe044c size=15272 ok
check b=0x3ffe3ff4 size=0 ok
check b=0x3ffe435c size=113816 ok
check b=0x3ffffff4 size=0 ok
check b=0x4009b810 size=18404 ok
I (1300) cpu_start: Pro cpu start user code
V (1354) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1355) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (1393) intr_alloc: Connected src 56 to int 2 (cpu 0)
V (1443) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1500) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (1574) intr_alloc: Connected src 16 to int 3 (cpu 0)
I (1622) cpu_start: Starting scheduler on PRO CPU.
D (1677) nvs: nvs_flash_init_custom start=9 count=6
I (1689) gpio: GPIO[2]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1691) gpio: GPIO[4]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1700) gpio: GPIO[13]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1709) gpio: GPIO[14]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1719) gpio: GPIO[15]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (1728) gpio: GPIO[12]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0
I (1738) gpio: GPIO[32]| InputEn: 1| OutputEn: 1| OpenDrain: 1| Pullup: 1| Pulldown: 0| Intr:0
I (1747) gpio: GPIO[33]| InputEn: 1| OutputEn: 1| OpenDrain: 1| Pullup: 1| Pulldown: 0| Intr:0
I (1757) gpio: GPIO[36]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2
I (1766) gpio: GPIO[39]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:2
V (1775) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1775) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (1775) intr_alloc: Connected src 22 to int 12 (cpu 0)
D (1795) nvs: nvs_open user_params 1
...
I (2046) emac: mac version 1137a
V (2049) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (2055) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (2063) intr_alloc: Connected src 38 to int 13 (cpu 0)
D (2069) nvs: nvs_open misc 1
D (2075) nvs: nvs_get_str_or_blob log
I (2079) wifi: wifi firmware version: 0b5b6e7
I (2083) wifi: config NVS flash: enabled
I (2087) wifi: config nano formating: disabled
D (2091) nvs: nvs_open nvs.net80211 1
D (2099) nvs: nvs_get opmode 1
D (2102) nvs: nvs_get country 1
D (2105) nvs: nvs_get_str_or_blob sta.ssid
D (2109) nvs: nvs_get_str_or_blob sta.mac
D (2113) nvs: nvs_get sta.authmode 1
D (2117) nvs: nvs_get_str_or_blob sta.pswd
D (2121) nvs: nvs_get_str_or_blob sta.pmk
D (2125) nvs: nvs_get sta.chan 1
D (2129) nvs: nvs_get auto.conn 1
D (2132) nvs: nvs_get bssid.set 1
D (2135) nvs: nvs_get_str_or_blob sta.bssid
D (2140) nvs: nvs_get sta.phym 1
D (2143) nvs: nvs_get sta.phybw 1
D (2146) nvs: nvs_get_str_or_blob sta.apsw
D (2150) nvs: nvs_get_str_or_blob sta.apinfo
D (2155) nvs: nvs_get_str_or_blob ap.ssid
D (2159) nvs: nvs_get_str_or_blob ap.mac
D (2163) nvs: nvs_get_str_or_blob ap.passwd
D (2167) nvs: nvs_get_str_or_blob ap.pmk
D (2171) nvs: nvs_get ap.chan 1
D (2174) nvs: nvs_get ap.authmode 1
D (2178) nvs: nvs_get ap.hidden 1
D (2181) nvs: nvs_get ap.max.conn 1
D (2185) nvs: nvs_get bcn.interval 2
D (2188) nvs: nvs_get ap.phym 1
D (2192) nvs: nvs_get ap.phybw 1
D (2195) nvs: nvs_get ap.sndchan 1
D (2199) nvs: nvs_set_blob sta.mac 6
D (2203) nvs: nvs_set_blob ap.mac 6
I (2206) wifi: Init dynamic tx buffer num: 32
I (2210) wifi: wifi driver task: 3ffca360, prio:23, stack:3584
I (2215) wifi: Init static rx buffer num: 10
I (2219) wifi: Init dynamic rx buffer num: 0
I (2223) wifi: Init rx ampdu len mblock:7
I (2227) wifi: Init lldesc rx ampdu entry mblock:4
I (2232) wifi: wifi power manager task: 0x3ffcf8ac prio: 21 stack: 2560
I (2439) uart: queue free spaces: 10
V (2439) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (2439) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (2439) intr_alloc: Connected src 36 to int 17 (cpu 0)
V (2570) intr_alloc: esp_intr_free: Disabling int, killing handler
I (2671) uart: queue free spaces: 10
V (2671) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (2671) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (2671) intr_alloc: Connected src 36 to int 17 (cpu 0)
...
E (3911) modbusd: Emergency function failed
D (3916) nvs: nvs_set_blob log_slot_0b 143
D (3920) nvs: nvs_get priv_next_log 2
D (3923) nvs: nvs_set priv_next_log 2 12
V (4055) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (4055) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (4058) intr_alloc: Connected src 50 to int 18 (cpu 0)
I (5927) emac: emac start !!!

I (5927) emac: emac reseting ....
I (5927) emac: emac reset done
...
I (5929) emac: emac start success !!!
V (5932) event: enter default callback
V (5939) event: exit default callback
I (10944) wifi: wifi timer task: 3ffd5b2c, prio:22, stack:3584
D (10944) phy_init: loading PHY init data from application binary
D (10945) nvs: nvs_open phy 0
D (10952) nvs: nvs_get cal_version 4
V (10955) phy_init: phy_get_rf_cal_version: 329

D (10960) nvs: nvs_get_str_or_blob cal_mac
D (10964) nvs: nvs_get_str_or_blob cal_data
D (10969) nvs: nvs_close 6
V (10971) phy_init: register_chipv7_phy, init_data=0x3f417968, cal_data=0x3ffd5cb8, mode=0
abort() was called at PC 0x40081841
Guru Meditation Error: Core 0 panic'ed (abort)

I've been trying to modify the PHY configuration in menuconfig ( I think I've tried all available combinations) but I'm not able to solve this one.

[ESP_igrr]

I don't see any red flags in NVS log messages... The only problem is the "abort() was called at PC 0x40081841" message.

Is this message the same every time you reset the board? If it is, you may want to check the backtrace. You should be getting a backtrace line after the "Guru meditation" line, should look similar to this one:

Code: Select all

Backtrace: 0x400d1184:0x3ffb0ba0 0x4008405e:0x3ffb0bc0 0x400811c4:0x3ffb0be0 0x400817a9:0x3ffb0c00

If you copy the part after "Backtrace:" and feed it into xtensa-esp32-elf-addr2line like this, you should get a readable backtrace: (replace your-app-name.elf with the name of your application)

Code: Select all

xtensa-esp32-elf-addr2line -pfia -e build/your-app-name.elf 0x400d1184:0x3ffb0ba0 0x4008405e:0x3ffb0bc0 0x400811c4:0x3ffb0be0 0x400817a9:0x3ffb0c00
0x400d1184: esp_vApplicationIdleHook at /Users/ivan/e/esp-idf/components/esp32/./freertos_hooks.c:75
0x4008405e: vTaskEnterCritical at /Users/ivan/e/esp-idf/components/freertos/./tasks.c:4425
0x400811c4: rtc_cpu_freq_up_isr_impl at /Users/ivan/e/esp-idf/components/esp32/./freertos_hooks.c:120
0x400817a9: _xt_lowint1 at xtensa_vectors.o:?

If the abort line is not the same (crash happens at random places), this probably indicates that the CPU browns out during RF calibration, which may happen because of power supply issues.

[ikerbelloso]

First of all thank you for your reply, it helped a lot.
I've got this from the backtrace:
0x40009203
??
??:0
0x4008be31
rfcal_txiq
??:?
0x4008195c
_lock_try_acquire
/home/ibl/esp32/esp-idf/components/newlib/./locks.c:165
0x400d7c09
_vfprintf_r
/Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/vfprintf.c:860
0x400d50c4
vprintf
/Users/ivan/e/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/vprintf.c:38 (discriminator 2)
0x4008160c
esp_log_early_timestamp
/home/ibl/esp32/esp-idf/components/log/./log.c:297
0x40082621
gpio_btn1_isr_handler
/home/ibl/esp32/ETH_BLE_Wifi_Gateway/main/./main.c:215
0x400826ae
gpio_intr_service
/home/ibl/esp32/esp-idf/components/driver/./gpio.c:431
0x4008139c
_xt_lowint1
xtensa_vectors.o:?

The only and strange thing I saw is that one of my gpio interrupts has been called even if the push button has not been pressed, I removed the interrupt initialization and everything goes fine now.
I will research what is going on with that interrupt, because it seemed to work fine till now.
Regards

[ESP_igrr]

I see you are using ESP_LOGx in your gpio_btn1_isr_handler function... You shouldn't log or otherwise use IO functions from the interrupt handlers. The "abort()" you saw above was triggered when the function used to lock standard output (to prevent multiple tasks from printing at the same time) realized that it is called from an ISR, where waiting on locks is not possible.
Suggest rewriting your code to avoid any IO in ISRs.
If you absolutely need to log something (for debugging purposes, it happens...), use "ets_printf" function defined in "rom/ets_sys.h" instead. It doesn't do any locking, so you can get garbage output, but still it can be used in ISRs. Not a good practice, but useful sometimes.
There are also ESP_EARLY_LOGx macros similar to ESP_LOGx, which use ets_printf internally and as such may be used from ISRs.

[ikerbelloso]

You are right, I noticed it immediately when I saw the backtrace.
All comes from some other strange phenomenon I had, where a first spurious interrupt was called after boot. Like in the backtrace, the interrupt shouldn't been triggered. I will try to figure out what is happening...
Thank you

[ikerbelloso]

Hi again,
as expected, solving my gaffe has brought back my former problem. I have two tact switches in my board used to start some functionalities. This is more or less my code:

Code: Select all

void IRAM_ATTR gpio_btn_isr_handler(void* arg){
	uint8_t pio = (uint8_t)((int)arg);
	portBASE_TYPE high_priority_task_awoken = 0;
	msg.type = BTN_ISR;
	msg.ext = pio;
	xQueueSendFromISR(dest_queue_h, &msg, &high_priority_task_awoken);
	if (high_priority_task_awoken == pdTRUE) {
		portYIELD_FROM_ISR();
	}
}
int init_int_gpio(void){
	gpio_config_t io_conf;
	io_conf.intr_type = GPIO_PIN_INTR_NEGEDGE;
	io_conf.pin_bit_mask = GPIO_SEL_36;
	io_conf.mode = GPIO_MODE_INPUT;
	gpio_config(&io_conf);

	io_conf.intr_type = GPIO_PIN_INTR_NEGEDGE;
	io_conf.pin_bit_mask = GPIO_SEL_39;
	io_conf.mode = GPIO_MODE_INPUT;
	gpio_config(&io_conf);

	//install gpio isr service
	gpio_install_isr_service(0);
	//hook isr handler for specific gpio pin
	gpio_isr_handler_add(BTN1_GPIO, gpio_btn_isr_handler, (void*)GPIO_NUM_36 );
	gpio_isr_handler_add(BTN2_GPIO, gpio_btn_isr_handler, (void*) GPIO_NUM_39);
	return ESP_OK;
}

It happens that while I leave the Wifi stoped, the interrupts are working as expected, but if I start Wifi Im getting continuous interrupt calls.
I paid attention to your mention about power supply so I'v switched to a battery and I've got the same result...

[ESP_Sprite]

Do you have an (external or internal) pullup or -down connected to your button? If not, the GPIO will be, as they say, flapping in the breeze and will pick up any disturbance that comes across it, for example WiFi waves from the antenna a few mm next to it.

[ikerbelloso]

Hi again,
yes I do ,10K pull ups, and I have verified with the oscilloscope that the level is not varying...

[ikerbelloso]

Hi again,
I have some more information,
It seems that the interrupt call arises in the time from when I configure and start the interface until i get the SYSTEM_EVENT_STA_START.

I (4324) wifi: Init ampdu: 1
I (4325) wifi: mode : sta (24:0a:c4:03:68:80)
D (4331) main_task(main_handler_esp_system_msgs[704]) : BUtton pressed
D (4344) main_task(main_handler_esp_system_msgs[704]) : BUtton pressed
D (4358) main_task(main_handler_esp_system_msgs[704]) : BUtton pressed
D (4372) main_task(main_handler_esp_system_msgs[704]) : BUtton pressed
D (4385) main_task(main_handler_esp_system_event_msg[480]) : Event SYSTEM_EVENT_STA_START
I (4515) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (5172) wifi: state: init -> auth (b0)

[ESP_Sprite]

Interesting. I see no reason why it should do this. Can you figure out which of the GPIOs (36 or 39) is giving you the interrupt?