espressif / esp-idf

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

ESP32-C6 WiFi Station Error (`wifi:m f null`) (IDFGH-13991) #14817

Open fuzeman opened 2 days ago

fuzeman commented 2 days ago

Answers checklist.

IDF version.

v5.3.1

Espressif SoC revision.

ESP32-C6 (QFN40) (revision v0.0)

Operating System used.

Windows

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

CMD

Development Kit.

ESP32-C6-DevKitC-1

Power Supply used.

USB

What is the expected behavior?

WiFi Station connects to an Access Point and continues operating normally without errors.

What is the actual behavior?

WiFi Station connects to an Access Point, receives an IP Address , and after a 30 seconds starts logging "wifi:m f null" continuously blocking other tasks from operating.

Steps to reproduce.

  1. Build examples/wifi/getting_started/station with ssid + password, and upload to board.
  2. Observe station successfully connects to the Access Point.
  3. Wait 30 seconds for wifi:m f null to start being printed.

Debug Logs.

Build:Sep 19 2022
rst:0x1 (POWERON),boot:0x1c (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:2
load:0x40875720,len�ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x1 (POWERON),boot:0x1c (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:2
load:0x40875720,len:0x1804
load:0x4086c110,len:0xe2c
load:0x4086e610,len:0x2e5c
entry 0x4086c11a
I (23) boot: ESP-IDF v5.3.1-dirty 2nd stage bootloader
I (24) boot: compile time Nov  3 2024 15:59:40
I (24) boot: chip revision: v0.0
I (27) boot.esp32c6: SPI Speed      : 80MHz
I (32) boot.esp32c6: SPI Mode       : DIO
I (36) boot.esp32c6: SPI Flash Size : 2MB
I (41) boot: Enabling RNG early entropy source...
I (47) boot: Partition Table:
I (50) boot: ## Label            Usage          Type ST Offset   Length
I (57) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (65) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (72) boot:  2 factory          factory app      00 00 00010000 00100000
I (80) boot: End of partition table
I (84) esp_image: segment 0: paddr=00010020 vaddr=42088020 size=21dd8h (138712) map
I (121) esp_image: segment 1: paddr=00031e00 vaddr=40800000 size=06218h ( 25112) load
I (128) esp_image: segment 2: paddr=00038020 vaddr=42000020 size=84488h (541832) map
I (240) esp_image: segment 3: paddr=000bc4b0 vaddr=40806218 size=12518h ( 75032) load
I (259) esp_image: segment 4: paddr=000ce9d0 vaddr=40818730 size=03b28h ( 15144) load
I (269) boot: Loaded app from partition at offset 0x10000
I (269) boot: Disabling RNG early entropy source...
I (281) cpu_start: Unicore app
I (290) cpu_start: Pro cpu start user code
I (290) cpu_start: cpu freq: 160000000 Hz
I (290) app_init: Application information:
I (293) app_init: Project name:     wifi_station
I (298) app_init: App version:      v5.3.1-dirty
I (303) app_init: Compile time:     Nov  3 2024 15:59:28
I (309) app_init: ELF file SHA256:  3dac59bd5...
I (314) app_init: ESP-IDF:          v5.3.1-dirty
I (320) efuse_init: Min chip rev:     v0.0
I (324) efuse_init: Max chip rev:     v0.99
I (329) efuse_init: Chip rev:         v0.0
I (334) heap_init: Initializing. RAM available for dynamic allocation:
I (341) heap_init: At 408215C0 len 0005B050 (364 KiB): RAM
I (348) heap_init: At 4087C610 len 00002F54 (11 KiB): RAM
I (354) heap_init: At 50000000 len 00003FE8 (15 KiB): RTCRAM
I (361) spi_flash: detected chip: generic
I (365) spi_flash: flash io: dio
W (369) spi_flash: Detected size(8192k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (382) sleep: Configure to isolate all GPIO pins in sleep state
I (389) sleep: Enable automatic switching of GPIO sleep configuration
I (396) coexist: coex firmware version: 4482466
I (410) coexist: coexist rom version 5b8dcfa
I (411) main_task: Started on CPU0
I (411) main_task: Calling app_main()
I (421) wifi station: ESP_WIFI_MODE_STA
I (421) pp: pp rom version: 5b8dcfa
I (421) net80211: net80211 rom version: 5b8dcfa
I (431) wifi:wifi driver task: 4082a5a0, prio:23, stack:6656, core=0
I (441) wifi:wifi firmware version: ccaebfa
I (441) wifi:wifi certification version: v7.0
I (441) wifi:config NVS flash: enabled
I (441) wifi:config nano formating: disabled
I (441) wifi:mac_version:HAL_MAC_ESP32AX_761,ut_version:N, band:0x1
I (451) wifi:Init data frame dynamic rx buffer num: 32
I (451) wifi:Init static rx mgmt buffer num: 5
I (461) wifi:Init management short buffer num: 32
I (461) wifi:Init dynamic tx buffer num: 32
I (471) wifi:Init static tx FG buffer num: 2
I (471) wifi:Init static rx buffer size: 1700 (rxctrl:92, csi:512)
I (481) wifi:Init static rx buffer num: 10
I (481) wifi:Init dynamic rx buffer num: 32
I (491) wifi_init: rx ba win: 6
I (491) wifi_init: accept mbox: 6
I (491) wifi_init: tcpip mbox: 32
I (501) wifi_init: udp mbox: 6
I (501) wifi_init: tcp mbox: 6
I (501) wifi_init: tcp tx win: 5760
I (511) wifi_init: tcp rx win: 5760
I (511) wifi_init: tcp mss: 1440
I (521) wifi_init: WiFi IRAM OP enabled
I (521) wifi_init: WiFi RX IRAM OP enabled
I (531) wifi_init: WiFi SLP IRAM OP enabled
I (541) phy_init: phy_version 310,dde1ba9,Jun  4 2024,16:38:11
W (581) phy_init: saving new calibration data because of checksum failure, mode(0)
W (631) wifi:ACK_TAB0   :0x   90a0b, QAM16:0x9 (24Mbps), QPSK:0xa (12Mbps), BPSK:0xb (6Mbps)
W (631) wifi:CTS_TAB0   :0x   90a0b, QAM16:0x9 (24Mbps), QPSK:0xa (12Mbps), BPSK:0xb (6Mbps)
W (641) wifi:(agc)0x600a7128:0xd216d9c0, min.avgNF:0xce->0xd2(dB), RCalCount:0x16d, min.RRssi:0x9c0(-100.00)
W (651) wifi:(TB)WDEV_PWR_TB_MCS0:19
W (651) wifi:(TB)WDEV_PWR_TB_MCS1:19
W (651) wifi:(TB)WDEV_PWR_TB_MCS2:19
W (661) wifi:(TB)WDEV_PWR_TB_MCS3:19
W (661) wifi:(TB)WDEV_PWR_TB_MCS4:19
W (661) wifi:(TB)WDEV_PWR_TB_MCS5:19
W (671) wifi:(TB)WDEV_PWR_TB_MCS6:18
W (671) wifi:(TB)WDEV_PWR_TB_MCS7:18
W (671) wifi:(TB)WDEV_PWR_TB_MCS8:17
W (681) wifi:(TB)WDEV_PWR_TB_MCS9:15
W (681) wifi:(TB)WDEV_PWR_TB_MCS10:15
W (681) wifi:(TB)WDEV_PWR_TB_MCS11:15
I (691) wifi:11ax coex: WDEVAX_PTI0(0x55777555), WDEVAX_PTI1(0x00003377).

W (691) wifi:(he)attach, station, phymode:11ax
I (701) wifi:mode : sta (40:4c:ca:40:8e:98)
I (701) wifi:enable tsf
I (701) wifi station: wifi_init_sta finished.
I (1021) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1, snd_ch_cfg:0x0
I (1021) wifi:(connect)dot11_authmode:0x3, pairwise_cipher:0x3, group_cipher:0x3
I (1021) wifi:state: init -> auth (0xb0)
I (1031) wifi:state: auth -> assoc (0x0)
I (1041) wifi:(assoc)RESP, Extended Capabilities length:8, operating_mode_notification:0
I (1041) wifi:(assoc)RESP, Extended Capabilities, MBSSID:0, TWT Responder:0, OBSS Narrow Bandwidth RU In OFDMA Tolerance:0
I (1051) wifi:BSS max idle period:1(1000TU), protected keep alive:FALSE
I (1061) wifi:state: assoc -> run (0x10)
I (1061) wifi:(trc)phytype:CBW20-SGI, snr:45, maxRate:144, highestRateIdx:0
W (1071) wifi:(trc)band:2G, phymode:3, highestRateIdx:0, lowestRateIdx:11, dataSchedTableSize:14
I (1071) wifi:(trc)band:2G, rate(S-MCS7, rateIdx:0), ampdu(rate:S-MCS7, schedIdx(0, stop:8)), snr:45, ampduState:wait operational
I (1091) wifi:ifidx:0, rssi:-52, nf:-97, phytype(0x3, CBW20-SGI), phymode(0x3, 11bgn), max_rate:144, he:0, vht:0, ht:1
I (1101) wifi:(ht)max.RxAMPDULenExponent:3(65535 bytes), MMSS:0(no restriction)
I (1111) wifi:connected with [...], aid = 2, channel 11, BW20, bssid = [...]
I (1111) wifi:cipher(pairwise:0x3, group:0x3), pmf:0, security:WPA2-PSK, phy:11bgn, rssi:-52
I (1131) wifi:pm start, type: 1, twt_start:0

I (1131) wifi:pm start, type:1, aid:0x2, trans-BSSID:[...], BSSID[5]:0x42, mbssid(max-indicator:0, index:0), he:0
I (1141) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us
I (1141) wifi:set rx beacon pti, rx_bcn_pti: 10, bcn_timeout: 25000, mt_pti: 10, mt_time: 10000
I (1151) wifi:[ADDBA]TX addba request, tid:0, dialogtoken:1, bufsize:64, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x0)
I (1161) wifi:[ADDBA]TX addba request, tid:7, dialogtoken:2, bufsize:64, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x20)
I (1171) wifi:[ADDBA]TX addba request, tid:5, dialogtoken:3, bufsize:64, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x0)
I (1191) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (1191) wifi:[ADDBA]RX addba response, status:0, tid:0/tb:1(0xa1), bufsize:64, batimeout:0, txa_wnd:64
I (1201) wifi:[ADDBA]RX addba response, status:0, tid:7/tb:1(0xa1), bufsize:64, batimeout:0, txa_wnd:64
I (1211) wifi:[ADDBA]RX addba response, status:0, tid:5/tb:1(0xa1), bufsize:64, batimeout:0, txa_wnd:64
W (1721) wifi:<ba-add>idx:0, ifx:0, tid:1, TAHI:[...], TALO:[...], (ssn:0, win:64, cur_ssn:0), CONF:0xc0001005
I (2721) esp_netif_handlers: sta ip: 172.29.90.130, mask: 255.255.255.0, gw: 172.29.90.1
I (2721) wifi station: got ip:172.29.90.130
I (2721) wifi station: connected to ap SSID:[...] password:[...]
I (2731) main_task: Returned from app_main()
W (31881) wifi:m f null

W (31881) wifi:m f null

W (31881) wifi:m f null

W (31881) wifi:m f null

W (31881) wifi:m f null

W (31881) wifi:m f null

W (31881) wifi:m f null

W (31891) wifi:m f null

W (31891) wifi:m f null

W (31891) wifi:m f null

W (31891) wifi:m f null

W (31891) wifi:m f null

W (31901) wifi:m f null

[...]

W (3E (36811) task_wdt: Task watchdog got triggered. The following tasks/users did not reset the watchdog in time:
E (36811) task_wdt:  - IDLE (CPU 0)
E (36811) task_wdt: Tasks currently running:
E (36811) task_wdt: CPU 0: wifi
E (36811) task_wdt: Print CPU 0 (current core) backtrace
Print CPU 0 (current core) registers
Core  0 register dump:
MEPC    : 0x4200823a  RA      : 0x42009362  SP      : 0x40829e60  GP      : 0x40818f34
--- Stack dump detected
--- 0x4200823a: uart_ll_get_txfifo_len at [...]/esp-idf/master/components/hal/esp32c6/include/hal/uart_ll.h:588
 (inlined by) uart_tx_char at [...]/esp-idf/master/components/esp_driver_uart/src/uart_vfs.c:170
0x42009362: uart_write at [...]/esp-idf/master/components/esp_driver_uart/src/uart_vfs.c:215 (discriminator 2)

--- 0x40028140: __retarget_lock_acquire_recursive in ROM

TP      : 0x4082a590  T0      : 0x40028140  T1      : 0x4082a04c  T2      : 0x01000000
S0/FP   : 0x00000004  S1      : 0x00000000  A0      : 0x00000000  A1      : 0x00000036
A2      : 0x00000000  A3      : 0x00000080  A4      : 0x60000000  A5      : 0x607f8000
A6      : 0x420092ee  A7      : 0x0000000a  S2      : 0x00000036  S3      : 0x00000018
--- 0x420092ee: uart_write at [...]/esp-idf/master/components/esp_driver_uart/src/uart_vfs.c:207

S4      : 0x40823640  S5      : 0x4082a040  S6      : 0x420a8504  S7      : 0x00000000
S8      : 0x00000009  S9      : 0x00000000  S10     : 0x4082a054  S11     : 0x00000000
T3      : 0x00000000  T4      : 0x0fffffff  T5      : 0x00000000  T6      : 0x00000000
MSTATUS : 0x00000000  MTVEC   : 0x00000004  MCAUSE  : 0x40829eac  MTVAL   : 0x36009322
MHARTID : 0x40823640
6811) wifi:m f null

W (36961) wifi:m f null

W (36971) wifi:m f null

W (36971) wifi:m f null

W (36971) wifi:m f null

W (36971) wifi:m f null

W (36971) wifi:m f null

W (36981) wifi:m f null

W (36981) wifi:m f null

W (36981) wifi:m f null

W (36981) wifi:m f null

[...]

More Information.

I've tested various wifi configurations and versions of esp-idf to narrow down this issue and discovered esp_wifi_set_ps may have some impact on this issue, with esp-idf <= 5.2.1 working as long as WIFI_PS_MIN_MODEM or WIFI_PS_MAX_MODEM is used.

Noticeably esp-idf v5.3+ has a longer delay (30 seconds) before this issue presents allowing STA_GOT_IP to be emitted, but esp_wifi_set_ps has no effect with all power saving modes eventually returning the same wifi:m f null errors.

ESP-IDF State esp_wifi_set_ps
Default (not set) WIFI_PS_NONE WIFI_PS_MIN_MODEM WIFI_PS_MAX_MODEM
v5.1.1 STA_GOT_IP ✔️ OK ❌ NO ✔️ OK ✔️ OK
WiFi ✔️ OK ❌ ERROR (>3s)
(m f null, wdt)
✔️ OK ✔️ OK
v5.1.2 STA_GOT_IP ✔️ OK ❌ NO ✔️ OK ✔️ OK
WiFi ✔️ OK ❌ ERROR (>3s)
(m f null, wdt)
✔️ OK ✔️ OK
v5.2.1 STA_GOT_IP ✔️ OK ❌ NO ✔️ OK ✔️ OK
WiFi ✔️ OK ❌ ERROR (>3s)
(m f null, wdt)
✔️ OK ✔️ OK
v5.3 STA_GOT_IP ✔️ OK ✔️ OK ✔️ OK ✔️ OK
WiFi ❌ ERROR (>30s)
(m f null, wdt)
❌ ERROR (>30s)
(m f null, wdt)
❌ ERROR (>30s)
(m f null, wdt)
❌ ERROR (>30s)
(m f null, wdt)
v5.3.1 STA_GOT_IP ✔️ OK ✔️ OK ✔️ OK ✔️ OK
WiFi ❌ ERROR (>30s)
(m f null, wdt)
❌ ERROR (>30s)
(m f null, wdt)
❌ ERROR (>30s)
(m f null, wdt)
❌ ERROR (>30s)
(m f null, wdt)

12488, #12464, #11615 report similar wifi:m f null issues, but all appear to have fixes implemented or were caused by memory exhaustion outside of the esp-idf framework.

fuzeman commented 1 day ago

Looking at other similar issues, there was a suggestion in https://github.com/espressif/esp-idf/issues/11615#issuecomment-1612718659 to log the result of esp_get_free_internal_heap_size inside malloc_internal_wrapper to confirm memory usage. Which was added as follows:

void *IRAM_ATTR esp_coex_common_malloc_internal_wrapper(size_t size)
{
    void * result = heap_caps_malloc(size, MALLOC_CAP_8BIT | MALLOC_CAP_DMA | MALLOC_CAP_INTERNAL);

    printf("m.%d\n", esp_get_free_internal_heap_size());
    fflush(stdout);

    return result;
}

This provides the following results which show free memory usage stabilizing to ~252 KB:

[...]
W (46481) wifi:m f null

m.252848
m.253032
m.253032
m.252848
W (46481) wifi:m f null

m.252848
m.252848
m.252848
m.252848
m.252848
m.252848
W (46491) wifi:m f null

m.252848
m.252848
m.252848
W (46491) wifi:m f null

m.252848
m.252848
m.252848
m.252848
m.252848
m.252848
W (46501) wifi:m f null

m.252848
m.252848
m.252848
m.252848
m.252848
W (46511) wifi:m f null

m.252848
m.252848
m.252848
W (46511) wifi:m f null

m.252848
m.252848
m.252848
m.252848
W (46521) wifi:m f null
[...]