Problems after updating to latest master (reproduced in IDF example code)

[permal]

Increasing the stack as suggested seems to have made the iperf example stable. However, there is definitely something more going on since I'm still experiencing problems with my own application, one that was running fine before the update.

It looks like another stack overflow or similar. What task prints the "wifi" -tag in its log messages? I can't seem to find that string anywhere in the IDF source..,

Here's what it looks like when it now hangs:

Code: Select all

rst:0x10 (RTCWDT_RTC_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:0x3fff0010,len:4
load:0x3fff0014,len:5544
load:0x40078000,len:0
ho 12 tail 0 room 4
load:0x40078000,len:12484
entry 0x40078f7c
W (54) rtc_clk: Possibly invalid CONFIG_ESP32_XTAL_FREQ setting (26MHz). Detected 26 MHz.
I (39) boot: ESP-IDF v3.0-dev-806-gde750e9 2nd stage bootloader
I (39) boot: compile time 21:35:42
I (48) boot: Enabling RNG early entropy source...
I (48) boot: SPI Speed      : 40MHz
I (49) boot: SPI Mode       : DIO
I (53) boot: SPI Flash Size : 4MB
I (57) boot: Partition Table:
I (61) boot: ## Label            Usage          Type ST Offset   Length
I (68) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (75) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (83) boot:  2 factory          factory app      00 00 00010000 00100000
I (90) boot: End of partition table
I (95) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x1dfd0 (122832) map
I (127) esp_image: segment 1: paddr=0x0002dff8 vaddr=0x3ffb0000 size=0x02018 (  8216) load
I (129) esp_image: segment 2: paddr=0x00030018 vaddr=0x400d0018 size=0x4e7e8 (321512) map
0x400d0018: _flash_cache_start at ??:?

I (197) esp_image: segment 3: paddr=0x0007e808 vaddr=0x3ffb2018 size=0x01284 (  4740) load
I (198) esp_image: segment 4: paddr=0x0007fa94 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _WindowOverflow4 at /home/permal/esp/esp-idf/components/freertos/./xtensa_vectors.S:1675

I (204) esp_image: segment 5: paddr=0x0007fe9c vaddr=0x40080400 size=0x0feb0 ( 65200) load
I (227) esp_image: segment 6: paddr=0x0008fd54 vaddr=0x400c0000 size=0x00000 (     0) load
I (230) boot: Loaded app from partition at offset 0x10000
I (231) boot: Disabling RNG early entropy source...
I (236) cpu_start: Pro cpu up.
I (240) cpu_start: Starting app cpu, entry point is 0x40081110
0x40081110: call_start_cpu1 at /home/permal/esp/esp-idf/components/esp32/./cpu_start.c:219

I (0) cpu_start: App cpu up.
I (250) heap_init: Initializing. RAM available for dynamic allocation:
D (257) heap_init: New heap initialised at 0x3ffae6e0
I (262) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
D (269) heap_init: New heap initialised at 0x3ffb8e10
I (274) heap_init: At 3FFB8E10 len 000271F0 (156 KiB): DRAM
I (280) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (286) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
D (293) heap_init: New heap initialised at 0x400902b0
I (298) heap_init: At 400902B0 len 0000FD50 (63 KiB): IRAM
I (304) cpu_start: Pro cpu start user code
D (316) clk: RTC_SLOW_CLK calibration value: 3255690
V (27) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (27) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (32) intr_alloc: Connected src 46 to int 2 (cpu 0)
V (37) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (43) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xC0E
D (51) intr_alloc: Connected src 57 to int 3 (cpu 0)
V (58) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (62) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (70) intr_alloc: Connected src 16 to int 9 (cpu 0)
V (75) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (82) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (90) intr_alloc: Connected src 24 to int 12 (cpu 0)
I (95) cpu_start: Starting scheduler on PRO CPU.
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E
D (10) intr_alloc: Connected src 25 to int 2 (cpu 1)
I (10) cpu_start: Starting scheduler on APP CPU.
D (145) heap_init: New heap initialised at 0x3ffe0440
D (145) heap_init: New heap initialised at 0x3ffe4350
V (155) Queue: Creating queue 'system_event-TaskEventQueue', with 10 items of size 48.
D (165) nvs: nvs_flash_init_custom partition=nvs start=9 count=6
V (185) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (185) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (185) intr_alloc: Connected src 22 to int 13 (cpu 0)
V (195) Task: Initializing task 'main', 0x3ffbfb98
V (205) Queue: Creating queue 'SocketDispatcher-TaskEventQueue', with 10 items of size 48.
D (215) nvs: nvs_open_from_partition misc 1
D (215) nvs: nvs_get_str_or_blob log
I (215) wifi: wifi firmware version: ee52423
I (225) wifi: config NVS flash: enabled
I (225) wifi: config nano formating: disabled
I (225) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (235) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
D (245) nvs: nvs_open_from_partition nvs.net80211 1
D (255) nvs: nvs_get opmode 1
D (255) nvs: nvs_get_str_or_blob sta.ssid
D (265) nvs: nvs_get_str_or_blob sta.mac
D (265) nvs: nvs_get sta.authmode 1
D (265) nvs: nvs_get_str_or_blob sta.pswd
D (275) nvs: nvs_get_str_or_blob sta.pmk
D (275) nvs: nvs_get sta.chan 1
D (275) nvs: nvs_get auto.conn 1
D (285) nvs: nvs_get bssid.set 1
D (285) nvs: nvs_get_str_or_blob sta.bssid
D (295) nvs: nvs_get sta.phym 1
D (295) nvs: nvs_get sta.phybw 1
D (295) nvs: nvs_get_str_or_blob sta.apsw
D (305) nvs: nvs_get_str_or_blob sta.apinfo
D (305) nvs: nvs_get_str_or_blob ap.ssid
D (305) nvs: nvs_get_str_or_blob ap.mac
D (315) nvs: nvs_get_str_or_blob ap.passwd
D (315) nvs: nvs_get_str_or_blob ap.pmk
D (325) nvs: nvs_get ap.chan 1
D (325) nvs: nvs_get ap.authmode 1
D (325) nvs: nvs_get ap.hidden 1
D (335) nvs: nvs_get ap.max.conn 1
D (335) nvs: nvs_get bcn.interval 2
D (335) nvs: nvs_get ap.phym 1
D (345) nvs: nvs_get ap.phybw 1
D (345) nvs: nvs_get ap.sndchan 1
D (345) nvs: nvs_set_blob sta.mac 6
D (365) nvs: nvs_set_blob ap.mac 6
I (365) wifi: Init dynamic tx buffer num: 32
I (365) wifi: Init data frame dynamic rx buffer num: 32
I (365) wifi: Init management frame dynamic rx buffer num: 32
I (365) wifi: wifi driver task: 3ffc6230, prio:23, stack:4096
I (375) wifi: Init static rx buffer num: 10
I (375) wifi: Init dynamic rx buffer num: 32
I (385) wifi: Init rx ampdu len mblock:7
I (385) wifi: Init lldesc rx ampdu entry mblock:4
I (395) wifi: wifi power manager task: 0x3ffcb81c prio: 21 stack: 2560
D (395) phy_init: loading PHY init data from application binary
D (405) nvs: nvs_open_from_partition phy 0
D (405) nvs: nvs_get cal_version 4
V (415) phy_init: phy_get_rf_cal_version: 359

D (415) nvs: nvs_get_str_or_blob cal_mac
D (415) nvs: nvs_get_str_or_blob cal_data
D (425) nvs: nvs_close 3
V (425) phy_init: register_chipv7_phy, init_data=0x3f40e640, cal_data=0x3ffcba10, mode=0
I (445) phy: phy_version: 359.0, e79c19d, Aug 31 2017, 17:06:07, 1, 0
I (455) wifi: mode : sta (24:0a:c4:05:a8:9c)
D (455) event: SYSTEM_EVENT_STA_START
V (455) event: enter default callback
D (455) tcpip_adapter: check: local, if=0 fn=0x40112018
0x40112018: tcpip_adapter_start_api at /home/permal/esp/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:990


V (455) Task: Task 'main' initialized, 0x3ffbfb98
D (465) tcpip_adapter: call api in lwip: ret=0x0, give sem
D (475) tcpip_adapter: check: remote, if=0 fn=0x40112018
0x40112018: tcpip_adapter_start_api at /home/permal/esp/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:990


D (475) tcpip_adapter: stack headroom 1384
V (475) event: exit default callback
V (485) Application: ESP32 station start
I (1475) Task: MainTask: 1400
I (1785) wifi: n:11 0, o:1 0, ap:255 255, sta:11 0, prof:1
I (2435) wifi: state: init -> auth (b0)
I (����J���i: state: auth �.> assoc (0)
I (2455) wifi: state: assoc -> run (10)
I (2465) wifi: connected with Our place, channel 11
D (2475) event: SYSTEM_EVENT_STA_CONNECTED, ssid:Our place, ssid_len:9, bssid:f0:9f:c2:aa:b0:3f, channel:11, authmode:3
V (2475) event: enter default callback
D (2475) tcpip_adapter: check: local, if=0 fn=0x40112268
0x40112268: tcpip_adapter_up_api at /home/permal/esp/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:990


D (2485) tcpip_adapter: call api in lwip: ret=0x0, give sem
D (2485) tcpip_adapter: check: remote, if=0 fn=0x40112268
0x40112268: tcpip_adapter_up_api at /home/permal/esp/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:990


D (2485) tcpip_adapter: stack headroom 1384
D (2495) tcpip_adapter: check: local, if=0 fn=0x4011271c
0x4011271c: tcpip_adapter_dhcpc_start_api at /home/permal/esp/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:990


D (2505) tcpip_adapter: dhcp client init ip/mask/gw to all-0
D (2515) tcpip_adapter: if0 start ip lost tmr: enter
D (2515) tcpip_adapter: if0 start ip lost tmr: no need start because netif=0x3ffcbf04 in�e�v�l=1b0 ip=0
D (2525) tcpip_>apter�"�k
                           �,p���с�W,.]`4�=X�Y~͙��.+m��j5RIS�LMJ��cp��}�1W.W6s�i�X�� apɁ2-
                                                                                             �ݥ�!�������b:OZ�Y��fm�j5R"��2535) tc���}����ѕ���.yack Е��ɽ��
                                                                                                                                                               R�304[�ԫH�D�-| r��ѕ��]<=0 fn=0xt�����5Rڴj5R�B����J*ٕ��'�*�с"����Ҭ,[[�XX}��@$%�MMMJ���+��X]Z�K��*�&&H.�a����
                                                                                                          i��ˋ�cted to A�u�j5

Sometimes it keeps going for a few seconds before it hangs. "Task: MainTask: 1400" is my task printing its highwater stack mark.

Code: Select all

D (415) nvs: nvs_get_str_or_blob cal_mac
D (415) nvs: nvs_get_str_or_blob cal_data
D (425) nvs: nvs_close 3
V (425) phy_init: register_chipv7_phy, init_data=0x3f40e640, cal_data=0x3ffcba10, mode=0
I (445) phy: phy_version: 359.0, e79c19d, Aug 31 2017, 17:06:07, 1, 0
I (455) wifi: mode : sta (24:0a:c4:05:a8:9c)
D (455) event: SYSTEM_EVENT_STA_START
V (455) event: enter default callback
D (455) tcpip_adapter: check: local, if=0 fn=0x40112014
0x40112014: tcpip_adapter_start_api at /home/permal/esp/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:990


V (455) Task: Task 'main' initialized, 0x3ffbfb98
D (465) tcpip_adapter: call api in lwip: ret=0x0, give sem
D (475) tcpip_adapter: check: remote, if=0 fn=0x40112014
0x40112014: tcpip_adapter_start_api at /home/permal/esp/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:990


D (475) tcpip_adapter: stack headroom 1384
V (475) event: exit default callback
I (1475) Task: MainTask: 1400
I (1785) wifi: n:11 0, o:1 0, ap:255 255, sta:11 0, prof:1
I (2435) wif���хѕ�
��it ->�ѡ�B�Jj��I (2445) wifi: state: auth -> assoc (0)
I (2455) wifi: state: assoc -> run (10)
I (2465) wifi: connected with Our place, channel 11
D (2465) event: SYSTEM_EVENT_STA_CONNECTED, ssid:Our place, ssid_len:9, bssid:f0:9f:c2:aa:b0:3f, channel:11, authmode:3
V (2475) event: enter default callback
D (2475) tcpip_adapter: check: local, if=0 fn=0x40112264
0x40112264: tcpip_adapter_up_api at /home/permal/esp/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:990


D (2485) tcpip_adapter: call api in lwip: ret=0x0, give sem
D (2485) tcpip_adapter: check: remote, if=0 fn=0x40112264
0x40112264: tcpip_adapter_up_api at /home/permal/esp/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:990


D (2485) tcpip_adapter: stack headroom 1384
D (2495) tcpip_adapter: check: local, if=0 fn=0x40112718
0x40112718: tcpip_adapter_dhcpc_start_api at /home/permal/esp/esp-idf/components/tcpip_adapter/./tcpip_adapter_lwip.c:990


D (2505) tcpip_adapter: dhcp client init ip/mask/gw to all-0
D (2505) tcpip_adapter: if0 start ip lost tmr: enter
D (2515) tcpip_adapter: if0 start ip lost tmr: no need start because netif=0x3ffcbf04 interval=120 ip=0
D (2525) tcpip_adapte���.�<��6�'�Y�с�х�с�Ս���͙ձ��m��j5R"B����J�����}����ѕ������
���J��bݥ���������b:�ٕ����m��j5R"B����J�����}����ѕ���х���B���ɽ�������ڴj5R"B����J�����}����ѕ�����������ѕ�J���2����т������j���j5R�B����J*ٕ���*��с"���ձс�������m��j5R�I (3475) Task: MainTask: 1400
I (5455) wifi: pm start, type:0

I (5475) Task: MainTask: 1400
I (7475) Task: MainTask: 1400
I (9475) Task: MainTask: 1400
I (11475) Task: MainTask: 1400
I (13475) Task: MainTask: 1400
I (15475) Task: MainTask: 1400
I (17475) Task: MainTask: 1400
D (18745) tcpip_adapter: if0 dhcpc cb
D (18745) tcpip_adapter: if0 ip changed=1
D (18745) event: SYSTEM_EVENT_STA_GOT_IP, ip:192.168.10.25, mask:255.255.255.0, gw:192.168.10.254
V (18745) event: enter default callback
I (18755) event: ip: 192.168.10.25, mask: 255.255.255.0, gw: 192.168.10.254
V (18755) event: exit default callback
I (19475) Task: MainTask: 1400
I (21475) Task: MainTask: 1400
I (23475) Task: MainTask: 1400
I (25475) Task: MainTask: 1400
I (27475) Task: MainTask: 1400
I (29475) Task: MainTask: 1400
I (31475) Task: MainTask: 1400
I (33475) Task: MainTask: 1400
I (35475) Task: MainTask: 1400
I (37475) Task: MainTask: 1400
I (39475) Task: MainTask: 1400
I (41475) Task: MainTask: 1400

I will keep digging more during the weekend.

[permal]

Going to attribute this last issue to another too small stack. I had forgotten that I had increased the main task stack in my old config and when I reset my config as part of this investigation that got lost.

There is however another very early in the boot processes, but I'll take that in another thread.

[soc_f_hardware]

Does anyone know a timeline when the logging will be fixed? I went down the same rabbit hole and eventually discovered in "lib_printf.c"...

Code: Select all

lib_printf.c
" * This file contains library-specific printf functions
 * used by WiFi libraries in the lib directory.
 * These function are used to catch any output which gets printed
  by libraries, and redirect it to ESP_LOG macros.
 * Eventually WiFi libraries will use ESP_LOG functions internally
 * and these definitions will be removed."

This had a few problems for me. One, am trying to implement an interactive console and drove myself nuts not realizing those were printf statements to UART and no actual ESP logs (i had production logging verbosity set to off). Also, security reasons, why would we want to dump the wifi information status and firmware versions openly on UART (especially in production systems).

Really I want to know, is there any way to turn off the (I) wifi type logs?

if not, any clever work arounds?...temporarily rerouting putc to a garbage collection buffer upon initialization? Hopefully this is on the list to get fixed soon...but for now im not sure what I could do to stop the info drop on the console.

[Raimundo]

After get the new master (3.0), the heap memory issues was solved in my code but, now, with HTTP_REQUEST example, I'm getting:
I (2140007) event: station ip lost. After few minutes running. I've ran in four esp roow32, 5.1V 850mA; 5.1V 700mA; USB; 5V 1000mA. All whit the same resuult error:
I (2140007) event: station ip lost.
If I get a downgrade, I will solve that issue but get back memory leak. Please, could somebody help me?

Regards