Wifi in STA mode resets

[beg_dk]

Hi all

I am faced with a reset problem yet again. I have followed Kolban's guidance in using the GDB tool but I am sorry to see that all related errors are not traced back to my I own code which makes it more difficult to do something about it.

This is the error as I see it in the terminal window

Code: Select all

I (21538) wifi: wifi timer task: 3ffc4b48, prio:22, stack:3584
assertion "false && "item should have been present in cache"" failed: file "C:/Projects/IoT/esp-idf/components/nvs_flash/src/nvs_item_hash_list.cpp", line 85, function: void nvs::HashList::erase(size_t)
abort() was called at PC 0x400d1e2f on core 0

Backtrace: 0x4008681c:0x3ffbe320 0x400868e7:0x3ffbe340 0x400d1e2f:0x3ffbe360 0x401155b8:0x3ffbe390 0x40115c2e:0x3ffbe3b0 0x40115f09:0x3ffbe3f0 0x40114d79:0x3ffbe440 0x40114fe2:0x3ffbe470 0x401147e1:0x3ffbe4c0 0x40114bad:0x3ffbe4f0 0x4011a583:0x3ffbe510 0x4011a7d6:0x3ffbe580 0x4011a873:0x3ffbe5b0 0x400e8164:0x3ffbe5d0 0x400e81a2:0x3ffbe600 0x400e8743:0x3ffbe630 0x400f7633:0x3ffbe650

Entering gdb stub now.
$T0b#e6

Now running the GDB tool with

Code: Select all

xtensa-esp32-elf-gdb $IDF_PATH/../esp-idf-template/build/app-template.elf -b 115200 -ex 'target remote com5'

... I get

Code: Select all

#0  0x4008681c in bt_track_pll_cap ()
#1  0x400868ea in wifi_track_pll_cap ()
#2  0x400d1e32 in esp_wifi_set_config ()
#3  0x401155bb in ?? ()
#4  0x40115c31 in ?? ()
#5  0x40115f0c in ?? ()
#6  0x40114d7c in ?? ()
#7  0x40114fe5 in ?? ()
#8  0x401147e4 in ?? ()
#9  0x40114bb0 in ?? ()
#10 0x4011a586 in ?? ()
#11 0x4011a7d9 in ?? ()
#12 0x4011a876 in ?? ()
#13 0x400e8167 in etharp_arp_input (netif=0x0, ethaddr=0x3ffb364c, p=0x60e23)
    at C:/Projects/IoT/esp-idf/components/lwip/netif/etharp.c:836
#14 0x400e81a5 in etharp_tmr ()
    at C:/Projects/IoT/esp-idf/components/lwip/netif/etharp.c:198
#15 0x400e8746 in ip4_input (p=0x3ffc3c84, inp=0x400e8190 <etharp_request+16>)
    at C:/Projects/IoT/esp-idf/components/lwip/core/ipv4/ip4.c:475
#16 0x400f7636 in _svfprintf_r (data=<optimized out>, fp=<optimized out>,
    fmt0=<optimized out>, ap=...)
    at ../../../.././newlib/libc/stdio/vfprintf.c:1692

This does not help me much but maybe for the trained eye

Hope you can help me.

Thanks

[kolban]

If this is a repeatable and deterministic issue, then part of our challenge will be to find the source statement in user written code that is throwing the exception (assuming it is being thrown in user code). Perhaps post a pastebin link to the full serial console output log as well as the full GDB log output? For me, if I am not able to determine the exact source statement from GDB, I take the old divide by approach and liberally sprinkle ESP_LOGD statements in my code. This allows me to drill down to find the failing statement.

[ESP_Sprite]

That backtrace doesn't match the error message at all and is actually bullshit: no way printf calls into an ethernet arp function. Are you sure you are feeding gdb the exact same file as you have flashed?

[beg_dk]

If this is a repeatable and deterministic issue, then part of our challenge will be to find the source statement in user written code that is throwing the exception (assuming it is being thrown in user code). Perhaps post a pastebin link to the full serial console output log as well as the full GDB log output? For me, if I am not able to determine the exact source statement from GDB, I take the old divide by approach and liberally sprinkle ESP_LOGD statements in my code. This allows me to drill down to find the failing statement.

As ESP_Sprite is writing there must be somethin wrong with how GDB hooks up to the file that has been flashed or I do it wrong somehow. Nowhere is the code that GDB prints out related to my source code therefore GDB gave me no hint as to where the problem lies. I think I will do as you suggest - sprinkle ESP_LOGD statements in my code and take it from there.

[beg_dk]

That backtrace doesn't match the error message at all and is actually bullshit: no way printf calls into an ethernet arp function. Are you sure you are feeding gdb the exact same file as you have flashed?

You are right, it does seem strange - I might be doing something wrong that I am not able to see at the moment. At an another try earlier on I saw this output from GDP (warning: Source file is more recent than executable.)

Here is complete output...

Code: Select all

GNU gdb (crosstool-NG crosstool-ng-1.22.0-61-gab8375a) 7.10
Copyright (C) 2015 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "--host=i686-host_pc-mingw32 --target=xtensa-esp32-elf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from C:/Projects/IoT/esp-idf/../esp-idf-template/build/app-template.elf...done.
Remote debugging using com5
etharp_query (netif=0x3ffc3c54, ipaddr=0x1, q=0x0)
    at C:/Projects/IoT/esp-idf/components/lwip/netif/etharp.c:1115
warning: Source file is more recent than executable.
1115        /* try to resolve it; send out ARP request */
(gdb) bt
#0  etharp_query (netif=0x3ffc3c54, ipaddr=0x1, q=0x0)
    at C:/Projects/IoT/esp-idf/components/lwip/netif/etharp.c:1115
#1  0x400e1b54 in pm_rx_beacon_process ()
#2  0x400df7f5 in cnx_auth_done ()
#3  0x400e132c in pm_sent_null_process ()
#4  0x400e1368 in pm_sent_null_process ()


#0  0x4008681c in bt_track_pll_cap ()
#1  0x400868ea in wifi_track_pll_cap ()
#2  0x400d1e32 in esp_wifi_set_config ()
#3  0x401155bb in ?? ()
#4  0x40115c31 in ?? ()
#5  0x40115f0c in ?? ()
#6  0x40114d7c in ?? ()
#7  0x40114fe5 in ?? ()
#8  0x401147e4 in ?? ()
#9  0x40114bb0 in ?? ()
#10 0x4011a586 in ?? ()
#11 0x4011a7d9 in ?? ()
#12 0x4011a876 in ?? ()
#13 0x400e8167 in etharp_arp_input (netif=0x0, ethaddr=0x3ffb364c, p=0x60e23)
    at C:/Projects/IoT/esp-idf/components/lwip/netif/etharp.c:836
#14 0x400e81a5 in etharp_tmr ()
    at C:/Projects/IoT/esp-idf/components/lwip/netif/etharp.c:198
#15 0x400e8746 in ip4_input (p=0x3ffc3c84, inp=0x400e8190 <etharp_request+16>)
    at C:/Projects/IoT/esp-idf/components/lwip/core/ipv4/ip4.c:475
#16 0x400f7636 in _svfprintf_r (data=<optimized out>, fp=<optimized out>,
    fmt0=<optimized out>, ap=...)
    at ../../../.././newlib/libc/stdio/vfprintf.c:1692

I forgot to tell you in the first post that I have dev board from EzSBC where the code runs fine... which makes it even more odd I think.

Thanks

[ESP_Sprite]

In that case, I'll ask the old standby question: is the power supply to your ESP32 powerful enough and connected over thick enough wires? If it's not, it tends to give problems with WiFi startup.

[beg_dk]

In that case, I'll ask the old standby question: is the power supply to your ESP32 powerful enough and connected over thick enough wires? If it's not, it tends to give problems with WiFi startup.

I am using this http://www.ebay.co.uk/itm/AMS1117-3-3V- ... 7675.l2557 which should supply more than enough. I have 1A and 5 volts supplying the AMS1117 module.

Thanks for your answer

[beg_dk]

Do you have any recommendations as to the thickness / length of wires - any capacitors that must be provided - is the mentioned voltage regulator step down module not suitable?

Thanks

[beg_dk]

Hi

I am using ESP32D0WDQ6 (revision 0). Are there any issues with that particular revision?

Also I have tried to pinpoint where the problem is but inserting log statements as you suggested Kolban. This are my findings so far.

As part of the wifi initialisation the event_handler is created, just the standard way

Code: Select all

ESP_ERROR_CHECK( esp_event_loop_init(event_handler, NULL) );

... and it is here in the event_handler the reset is done. To pinpoint it more accurately I have inserted some log statements here as well like so...

Code: Select all

static esp_err_t event_handler(void *ctx, system_event_t *event)
{
    switch(event->event_id) {
    case SYSTEM_EVENT_STA_START:
    	ESP_LOGI(SOLARLAMP_SENSOR_ALERT, "SYSTEM_EVENT_STA_START");
    	esp_err_t status;
    	status = esp_wifi_connect();
    	switch ( status ) {
    			case ESP_ERR_WIFI_NOT_INIT: {
    					printf("WiFi is not initialized by eps_wifi_init\n");
    					break;
    			}
    			case ESP_ERR_WIFI_NOT_STARTED: {
    					printf("WiFi is not started by esp_wifi_start\n");
    					break;
    			}
    			case ESP_ERR_WIFI_CONN: {
    					printf("WiFi internal error, station or soft-AP control block wrong\n");
    					break;
    			}
    			case ESP_ERR_WIFI_SSID: {
    					printf("SSID of AP which station connects is invalid\n");
    					break;
    			}
    			default: {
    				printf("Something else\n");
    			}
    		}
        break;
    case SYSTEM_EVENT_STA_GOT_IP:
    	ESP_LOGI(SOLARLAMP_SENSOR_ALERT, "SYSTEM_EVENT_STA_GOT_IP");
        xEventGroupSetBits(wifi_event_group, CONNECTED_BIT);
        break;
    case SYSTEM_EVENT_STA_DISCONNECTED:
    	ESP_LOGI(SOLARLAMP_SENSOR_ALERT, "SYSTEM_EVENT_STA_DISCONNECTED");
        /* This is a workaround as ESP32 WiFi libs don't currently
           auto-reassociate. */
        esp_wifi_connect();
        xEventGroupClearBits(wifi_event_group, CONNECTED_BIT);
        break;
    default:
        break;
    }
    return ESP_OK;
}

... and from this I can tell you that it fails in SYSTEM_EVENT_STA_START right after the

Code: Select all

ESP_LOGI(SOLARLAMP_SENSOR_ALERT, "SYSTEM_EVENT_STA_START");

... so I guess it is the esp_wifi_connect() that causes the problem. To track it further I have inserted the switch statement but of course this is never reached as it is a reset going on.

Here is the output from the UART serial terminal

Code: Select all

I (448) SENSOR_ALERT_CLIENT: SYSTEM_EVENT_STA_START
ets Jun  8 2016 00:22:57

rst:0x8 (TG1WDT_SYS_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
ets Jun  8 2016 00:22:57

rst:0x7 (TG0WDT_SYS_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, 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:0x3fff0008,len:8
load:0x3fff0010,len:4400
load:0x40078000,len:11072
load:0x40080000,len:252
entry 0x40080034
W (90) boot: PRO CPU has been reset by WDT.
W (90) boot: WDT reset info: PRO CPU PC=0x40059b6f
W (90) boot: WDT reset info: APP CPU PC=0x400803c0
I (109) boot: ESP-IDF v3.0-dev-20-g9b955f4-dirty 2nd stage bootloader
I (131) boot: compile time 00:45:11
I (144) boot: Enabling RNG early entropy source...
I (161) boot: SPI Speed      : 40MHz
I (173) boot: SPI Mode       : DIO
I (186) boot: SPI Flash Size : 4MB
I (199) boot: Partition Table:
I (210) boot: ## Label            Usage          Type ST Offset   Length
I (233) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (256) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (279) boot:  2 factory          factory app      00 00 00010000 00100000
I (303) boot: End of partition table
I (316) boot: Disabling RNG early entropy source...
I (333) boot: Loading app partition at offset 00010000
I (1331) boot: segment 0: paddr=0x00010018 vaddr=0x00000000 size=0x0ffe8 ( 65512)
I (1332) boot: segment 1: paddr=0x00020008 vaddr=0x3f400010 size=0x19e40 (106048) map
I (1348) boot: segment 2: paddr=0x00039e50 vaddr=0x3ffb0000 size=0x02bb8 ( 11192) load
I (1379) boot: segment 3: paddr=0x0003ca10 vaddr=0x40080000 size=0x00400 (  1024) load
I (1402) boot: segment 4: paddr=0x0003ce18 vaddr=0x40080400 size=0x12d5c ( 77148) load
I (1464) boot: segment 5: paddr=0x0004fb7c vaddr=0x400c0000 size=0x00000 (     0) load
I (1465) boot: segment 6: paddr=0x0004fb84 vaddr=0x00000000 size=0x00484 (  1156)
I (1486) boot: segment 7: paddr=0x00050010 vaddr=0x400d0018 size=0x6b4a4 (439460) map
I (1512) cpu_start: Pro cpu up.
I (1524) cpu_start: Starting app cpu, entry point is 0x40080e68
I (0) cpu_start: App cpu up.
I (1557) heap_alloc_caps: Initializing. RAM available for dynamic allocation:
I (1579) heap_alloc_caps: At 3FFAE2A0 len 00001D60 (7 KiB): DRAM
I (1600) heap_alloc_caps: At 3FFB8488 len 00027B78 (158 KiB): DRAM
I (1621) heap_alloc_caps: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (1642) heap_alloc_caps: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1664) heap_alloc_caps: At 4009315C len 0000CEA4 (51 KiB): IRAM
I (1685) cpu_start: Pro cpu start user code
I (1740) cpu_start: Starting scheduler on PRO CPU.
I (198) cpu_start: Starting scheduler on APP CPU.
I (318) wifi: wifi firmware version: 72ddf26
I (318) wifi: config NVS flash: enabled
I (318) wifi: config nano formating: disabled
I (318) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (328) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (368) wifi: Init dynamic tx buffer num: 32
I (368) wifi: Init dynamic rx buffer num: 32
I (368) wifi: wifi driver task: 3ffbe6e8, prio:23, stack:4096
I (368) wifi: Init static rx buffer num: 10
I (378) wifi: Init dynamic rx buffer num: 32
I (378) wifi: Init rx ampdu len mblock:7
I (388) wifi: Init lldesc rx ampdu entry mblock:4
I (388) wifi: wifi power manager task: 0x3ffc3ab0 prio: 21 stack: 2560
I (398) SENSOR_ALERT_CLIENT: Setting WiFi configuration SSID bmv8...
I (398) wifi: wifi timer task: 3ffc4b30, prio:22, stack:3584
I (448) phy: phy_version: 355.1, 59464c5, Jun 14 2017, 20:25:06, 0, 0
I (448) wifi: mode : sta (24:0a:c4:03:87:74)

... and this is repeated over and over again except for the third time the output changes a bit

Code: Select all

I (448) SENSOR_ALERT_CLIENT: SYSTEM_EVENT_STA_START
Something else
ets Jun  8 2016 00:22:57

rst:0x8 (TG1WDT_SYS_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
ets Jun  8 2016 00:22:57

rst:0x7 (TG0WDT_SYS_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, 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:0x3fff0008,len:8
load:0x3fff0010,len:4400
load:0x40078000,len:11072
load:0x40080000,len:252
entry 0x40080034
W (90) boot: PRO CPU has been reset by WDT.
W (90) boot: WDT reset info: PRO CPU PC=0x40086a52
W (90) boot: WDT reset info: APP CPU PC=0x40081610

... notice the "Something else" that means that this time the event_handler enters the switch statement and resolves to the default case.

I have also pulled from the esp-idf repository and updated submodules, erased flash on the ESP32, make clean but the outcome is the same.

I would be thankful if you could help me.

Thanks

[beg_dk]

Hi

My apologies, it turned out to be the voltage supply that caused the trouble or at least something that made the voltage supplying the ESP32 too low to operate.

I did not have any reason to suspect the voltage supply because I have used this setup many times without problems.

Thanks for your help and support.