espressif / esp-idf

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

esp32-c6 WiFi-6 drops connection in light sleep (IDFGH-10287) #11550

Closed roblatour closed 1 year ago

roblatour commented 1 year ago

Answers checklist.

IDF version.

v5.1-beta1-378-gea5e0ff298

Operating System used.

Windows

How did you build your project?

VS Code IDE

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

None

Development Kit.

esp32-c6 devkitC-1 v1.2

Power Supply used.

USB

What is the expected behavior?

ESP should retain Wi-Fi 6 connect through light sleep.

What is the actual behavior?

ESP is losing Wi-Fi 6 connect through light sleep ( in general when light sleep > 3 minutes).

Steps to reproduce.

Code is here: https://github.com/roblatour/WeatherStation

Run with the following options in general_user_settings.h WORKAROUND 0 GENERAL_USER_SETTINGS_REPORTING_FREQUENCY_IN_MINUTES 15

Here is an example of the log when light sleep is set to 3 minutes:

Note the second and third cycle times are much less than the first cycle thanks to Wi-Fi 6 and the retained session.

ss1

In contrast, here is an example of the (partial) log when light sleep is set to 15 minutes - the full log's text is shown in the next section below:

Note the second cycle time is much greater here than in the first example due to the need to reconnect.

ss2

Debug Logs.

log showing activity associated with at 15 minute light sleep

ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x1 (POWERON),boot:0xc (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:2
load:0x4086c410,len:0xa98
load:0x4086e610,len:0x2404
load:0x40875720,len:0x4e8
entry 0x4086c410
I (253) cpu_start: Unicore app
I (253) cpu_start: Pro cpu up.
W (262) clk: esp_perip_clk_init() has not been implemented yet
I (269) cpu_start: Pro cpu start user code
I (269) cpu_start: cpu freq: 160000000 Hz
I (269) cpu_start: Application information:
I (272) cpu_start: Project name:     WeatherStation
I (277) cpu_start: App version:      1
I (282) cpu_start: Compile time:     May 30 2023 14:49:17
I (288) cpu_start: ELF file SHA256:  fe74b1a78817b79a...
I (294) cpu_start: ESP-IDF:          v5.1-beta1-378-gea5e0ff298-dirt
I (301) cpu_start: Min chip rev:     v0.0
I (305) cpu_start: Max chip rev:     v0.99 
I (310) cpu_start: Chip rev:         v0.0
I (315) heap_init: Initializing. RAM available for dynamic allocation:
I (322) heap_init: At 4081BDA0 len 00060870 (386 KiB): D/IRAM
I (329) heap_init: At 4087C610 len 00002F54 (11 KiB): STACK/DIRAM
I (335) heap_init: At 50000078 len 00003F88 (15 KiB): RTCRAM
I (343) spi_flash: detected chip: generic
I (346) spi_flash: flash io: dio
W (350) spi_flash: Detected size(8192k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (364) sleep: Configure to isolate all GPIO pins in sleep state
I (370) sleep: Enable automatic switching of GPIO sleep configuration
I (377) coexist: coex firmware version: ebddf30
I (383) coexist: coexist rom version 5b8dcfa
I (388) app_start: Starting scheduler on CPU0
I (393) main_task: Started on CPU0
I (397) main_task: Calling app_main()
I (401) Weather Station: 
************************
* Weather Station v1.0 *
************************
W (411) Weather Station: Sleep time between cycles: 900 seconds
W (418) Weather Station: Safety sleep (at startup only): 0 seconds
I (433) gpio: GPIO[12]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (434) Weather Station: Turn on Wi-Fi
I (440) pp: pp rom version: 5b8dcfa
I (489) net80211: net80211 rom version: 5b8dcfa
I (490) wifi:wifi driver task: 40822578, prio:23, stack:6656, core=0
I (491) wifi:wifi firmware version: 10c8635
I (493) wifi:wifi certification version: v7.0
I (497) wifi:config NVS flash: disabled
I (500) wifi:config nano formating: disabled
I (504) wifi:mac_version:HAL_MAC_ESP32AX_761,ut_version:N
I (510) wifi:Init data frame dynamic rx buffer num: 38
I (514) wifi:Init management frame dynamic rx buffer num: 38
I (520) wifi:Init management short buffer num: 32
I (524) wifi:Init dynamic tx buffer num: 35
I (528) wifi:Init static tx FG buffer num: 2
I (532) wifi:Init static rx buffer size: 1700
I (536) wifi:Init static rx buffer num: 20
I (540) wifi:Init dynamic rx buffer num: 38
I (544) wifi_init: rx ba win: 20
I (548) wifi_init: tcpip mbox: 64
I (552) wifi_init: udp mbox: 64
I (556) wifi_init: tcp mbox: 64
I (559) wifi_init: tcp tx win: 30000
I (564) wifi_init: tcp rx win: 34000
I (568) wifi_init: tcp mss: 1440
I (572) wifi_init: WiFi IRAM OP enabled
I (576) wifi_init: WiFi RX IRAM OP enabled
I (581) wifi_init: WiFi SLP IRAM OP enabled
I (587) wifi:set country: cc=CA schan=1 nchan=11 policy=0

I (591) wifi:Set ps type: 2

I (594) phy_init: phy_version 202,b4b3263,May 17 2023,20:14:14
W (646) esp_adapter: wifi_reset_mac_wrapper() has not been implemented yet
W (647) wifi:(bf)761:0x600a7cac:0x01b4b4b0
W (647) wifi:(agc)0x600a7128:0xd21f0c20, min.avgNF:0xce->0xd2(dB), RCalCount:0x1f0, min.RRssi:0xc20(-62.00)
W (656) wifi:(TB)WDEV_PWR_TB_MCS0:19
W (660) wifi:(TB)WDEV_PWR_TB_MCS1:19
W (663) wifi:(TB)WDEV_PWR_TB_MCS2:19
W (666) wifi:(TB)WDEV_PWR_TB_MCS3:19
W (669) wifi:(TB)WDEV_PWR_TB_MCS4:19
W (673) wifi:(TB)WDEV_PWR_TB_MCS5:19
W (676) wifi:(TB)WDEV_PWR_TB_MCS6:18
W (679) wifi:(TB)WDEV_PWR_TB_MCS7:18
W (683) wifi:(TB)WDEV_PWR_TB_MCS8:17
W (686) wifi:(TB)WDEV_PWR_TB_MCS9:15
W (689) wifi:(TB)WDEV_PWR_TB_MCS10:15
W (693) wifi:(TB)WDEV_PWR_TB_MCS11:15
I (696) wifi:11ax coex: WDEVAX_PTI0(0x55777555), WDEVAX_PTI1(0x00003377).

I (703) wifi:mode : sta (40:4c:ca:40:29:00)
I (707) wifi:enable tsf
I (710) Weather Station: Wi-Fi started
I (713) Weather Station: Connecting to Latour
I (845) wifi:(mac)omc_ul_mu_data_disable_rx:1
I (846) wifi:(phy)ppe_thresholds_present:1, nominal_packet_padding:0
I (846) wifi:(phy)dcm tx(constellation:0, nss:0), dcm rx(constellation:0, nss:0)
I (852) wifi:(phy)rx_mcs_map:0xfffa(for_1_ss:2), tx_mcs_map:0xfffa, stbc_tx:0, bfmer(su:1, mu:1), ldpc:1
I (861) wifi:(phy)nsts:1, ru_index_bitmap:0x7(242:1, 484:1, 996:1, 2*996:0)
I (868) wifi:(phy)threshold_bits:36, nsts_num:2, ru_num:3, he_cap->len:28, ppe_threshold_len:6(6,11,4)
I (877) wifi:(ppe)RU242, NSTS0, PPE16:0, PPE8:7, nominal_packet_padding:2
I (883) wifi:(opr)len:7, TWT Required:0, VHT Operation Present:0, 6GHz Info Present:0, Co-Hosted BSS:0, Basic MCS and NSS:0xfffc
I (894) wifi:(opr)len:7, Default PE Duration:4, TXOP RTS Threshold:0(0 us), ER-SU-Disable:0
I (902) wifi:(opr)len:7, BSS Color:40, disabled:0, Partial BSS Color:0
I (910) wifi:(mac)omc_ul_mu_data_disable_rx:1
I (913) wifi:(phy)ppe_thresholds_present:1, nominal_packet_padding:0
I (919) wifi:(phy)dcm tx(constellation:0, nss:0), dcm rx(constellation:0, nss:0)
I (926) wifi:(phy)rx_mcs_map:0xfffa(for_1_ss:2), tx_mcs_map:0xfffa, stbc_tx:0, bfmer(su:1, mu:0), ldpc:1
I (935) wifi:(phy)nsts:1, ru_index_bitmap:0x7(242:1, 484:1, 996:1, 2*996:0)
I (942) wifi:(phy)threshold_bits:36, nsts_num:2, ru_num:3, he_cap->len:28, ppe_threshold_len:6(6,11,4)
I (951) wifi:(ppe)RU242, NSTS0, PPE16:0, PPE8:7, nominal_packet_padding:2
I (957) wifi:(opr)len:7, TWT Required:0, VHT Operation Present:0, 6GHz Info Present:0, Co-Hosted BSS:0, Basic MCS and NSS:0xfffc
I (969) wifi:(opr)len:7, Default PE Duration:4, TXOP RTS Threshold:0(0 us), ER-SU-Disable:0
I (977) wifi:(opr)len:7, BSS Color:54, disabled:0, Partial BSS Color:0
I (985) wifi:new:<2,0>, old:<1,0>, ap:<255,255>, sta:<2,0>, prof:1
I (989) wifi:(connect)dot11_authmode:0x3, pairwise_cipher:0x3, group_cipher:0x3
I (1573) wifi:state: init -> auth (b0)
I (1577) wifi:state: auth -> assoc (0)
I (1585) wifi:Extended Capabilities length:8, subtype:0x10, a4:2b:b0:2f:da:6e, Operating mode notification Support
I (1586) wifi:state: assoc -> run (10)
I (1587) wifi:(he)ppe_thresholds_present:1, nominal_packet_padding(rx:0, cfg:2)
I (1594) wifi:(trc)phytype:CBW20-SGI, snr:73, maxRate:86, highestRateIdx:0
I (1601) wifi:(trc)rate(S-MCS7, schedIdx:0), ampdu(rate:S-MCS7, schedIdx(0, stop:8)), snr:73, ampduState:wait operational
I (1612) wifi:ifidx:0, rssi:-21, nf:-94, phytype(0x3, CBW20-SGI), phymode(0x5, 11ax), max_rate:860, he:1
I (1621) wifi:max ampdu length exponent:3(65535 bytes), mmss:5(4 us)
I (1663) wifi:(extcap)mbssid:0, enhanced_mbssid_advertise:0, complete_nontxbssid_profiles:0
I (1663) wifi:connected with Latour, aid = 19, channel 2, BW20, bssid = a4:2b:b0:2f:da:6e
I (1668) wifi:cipher(pairwise:0x3, group:0x3), pmf:0, security:WPA2-PSK, phy:11ax, rssi:-21
I (1676) wifi:pm start, type: 2, itwt_start:0

I (1680) wifi:pm start, type:2, aid:0x13, trans-BSSID:a4:2b:b0:2f:da:6e, BSSID[5]:0x6e, mbssid(max-indicator:0, index:0), he:1
I (1691) wifi:set rx beacon pti, rx_bcn_pti: 10, bcn_timeout: 25000, mt_pti: 10, mt_time: 10000
I (1700) wifi:[ADDBA]TX addba request, tid:0, dialogtoken:1, bufsize:32, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x0)
I (1711) wifi:[ADDBA]TX addba request, tid:7, dialogtoken:2, bufsize:32, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x30)
I (1722) wifi:[ADDBA]TX addba request, tid:5, dialogtoken:3, bufsize:32, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x0)
I (1733) wifi:BcnInt:102400, DTIM:1
I (1737) wifi:[ADDBA]RX addba response, status:0, tid:0/tb:1(0xa1), bufsize:32, batimeout:0, txa_wnd:32
I (1745) wifi:[ADDBA]RX addba response, status:0, tid:7/tb:1(0xa1), bufsize:32, batimeout:0, txa_wnd:32
I (1754) wifi:[ADDBA]RX addba response, status:0, tid:5/tb:1(0xa1), bufsize:32, batimeout:0, txa_wnd:32
I (1764) Weather Station: Wi-Fi connected
W (1768) wifi:<ba-add>idx:0, ifx:0, tid:0, TAHI:0x1006eda, TALO:0x2fb02ba4, (ssn:0, win:64, cur_ssn:0), CONF:0xc0000005
I (2764) esp_netif_handlers: sta ip: 192.168.200.248, mask: 255.255.255.0, gw: 192.168.200.1
I (2765) Weather Station: Got IP address: 192.168.200.248
I (2769) Weather Station: 802.11ax HE20
I (2773) Weather Station: Wi-Fi 6 Targeted Wake Time setup succeeded!
I (2780) gpio: GPIO[20]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (2790) Weather Station: BME680 powered on
I (2819) Weather Station: taking BME680 readings
I (3072) Weather Station: BME680 powered off
I (3092) Weather Station: readings: Temperature: 26.50 °C   Humidity: 33.67 %   Pressure: 1007.76 hPa
I (3112) Weather Station: Attempting to connect to MQTT (attempt 1 of 3)
I (3112) Weather Station: Starting MQTT client
I (3113) Weather Station: MQTT_EVENT_BEFORE_CONNECT
I (3468) Weather Station: MQTT_EVENT_CONNECTED
I (3482) Weather Station: MQTT connected (attempt 1 of 3)
I (4251) wifi:(extcap)mbssid:0, enhanced_mbssid_advertise:0, complete_nontxbssid_profiles:0
I (4251) wifi:connected with Latour, aid = 20, channel 2, BW20, bssid = a4:2b:b0:2f:da:6e
I (4256) wifi:cipher(pairwise:0x3, group:0x3), pmf:0, security:WPA2-PSK, phy:11ax, rssi:-27
I (4264) wifi:pm start, type: 2, itwt_start:0

I (4268) wifi:pm start, type:2, aid:0x14, trans-BSSID:a4:2b:b0:2f:da:6e, BSSID[5]:0x6e, mbssid(max-indicator:0, index:0), he:1
I (4279) wifi:set rx beacon pti, rx_bcn_pti: 10, bcn_timeout: 25000, mt_pti: 10, mt_time: 10000
I (4288) wifi:[ADDBA]TX addba request, tid:0, dialogtoken:4, bufsize:32, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x0)
I (4299) wifi:[ADDBA]TX addba request, tid:7, dialogtoken:5, bufsize:32, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x30)
I (4310) wifi:[ADDBA]TX addba request, tid:5, dialogtoken:6, bufsize:32, A-MSDU:0(not supported), policy:1(IMR), ssn:0(0x0)
I (4322) Weather Station: Wi-Fi connected
I (4322) wifi:[ADDBA]RX addba response, status:0, tid:7/tb:1(0xa1), bufsize:32, batimeout:0, txa_wnd:32
I (4334) wifi:[ADDBA]RX addba response, status:0, tid:5/tb:1(0xa1), bufsize:32, batimeout:0, txa_wnd:32
I (4343) wifi:[ADDBA]RX addba response, status:0, tid:0/tb:1(0xa1), bufsize:32, batimeout:0, txa_wnd:32
W (4352) wifi:<ba-add>idx:0, ifx:0, tid:0, TAHI:0x1006eda, TALO:0x2fb02ba4, (ssn:0, win:64, cur_ssn:0), CONF:0xc0000005
I (4363) wifi:BcnInt:102400, DTIM:1
I (5322) esp_netif_handlers: sta ip: 192.168.200.248, mask: 255.255.255.0, gw: 192.168.200.1
I (5323) Weather Station: Got IP address: 192.168.200.248
I (5327) Weather Station: 802.11ax HE20
I (5331) Weather Station: Wi-Fi 6 Targeted Wake Time setup succeeded!
I (5338) Weather Station: MQTT failed to connected (attempt 1 of 3)
I (5365) Weather Station: Attempting to connect to MQTT (attempt 2 of 3)
I (5365) Weather Station: Starting MQTT client
I (5366) Weather Station: MQTT_EVENT_BEFORE_CONNECT
I (6469) Weather Station: MQTT_EVENT_CONNECTED
I (6474) Weather Station: MQTT connected (attempt 2 of 3)
I (6474) Weather Station: publish: WeatherStation/temperature 26.04
I (6478) Weather Station: publish: WeatherStation/humidity 32.522
I (6484) Weather Station: publish: WeatherStation/pressure 1007.6
I (6503) Weather Station: MQTT publishing complete
I (6559) Weather Station: publish via PWSWeather is switched off
W (6559) Weather Station: cycle 2 processing time: 2.967039 seconds
I (6561) Weather Station: begin light sleep for 900 seconds

More Information.

I have tested with each of: esp_wifi_set_ps(WIFI_PS_MAX_MODEM); esp_wifi_set_ps(WIFI_PS_MIN_MODEM); esp_wifi_set_ps(WIFI_PS_NONE); and with not setting the ps option at all same results in all cases.

Wi-Fi connection is established using my country code (CA for Canada)

The problem appears to happen less often with shorter sleep periods (for example once every 3 minutes or less), but definitely happen with longer sleep periods (for example 15 minutes).

The problem does not occur if instead of a 15 minute light sleep, the code uses a 15 minute VTaskDelay.

igrr commented 1 year ago

Regarding https://github.com/roblatour/WeatherStation/blob/cdf04e0e0bd931095254a0b11b61f24d7053ff7d/main/main.c#L845, please do note that we don't support entering light sleep manually when communication peripherals (such as Wi-Fi) are working.

Quoting the docs,

Before entering Deep-sleep or Light-sleep modes, the application must disable Wi-Fi and Bluetooth using the appropriate calls

Basically, communication drivers make no attempt to preserve the connection if the drivers weren't stopped (e.g. esp_wifi_stop) before entering light sleep.

Note that there is another mechanism, automatic light sleep, which allows the system to enter light sleep whenever all tasks are idle. In automatic light sleep more communication drivers can preserve the connection, and will automatically wake up the chip when appropriate, for example to receive a beacon frame. Note that this mechanism is already enabled by default in the itwt example.

To conclude, if you need to keep Wi-Fi connection (especially with Wi-Fi 6 and ITWT), do not use esp_light_sleep_start) and let the system use the automatic light sleep mode, instead. In this case association with the AP will be maintained.

roblatour commented 1 year ago

Thank you, I had missed that.

I am currently in the process of updating my program to use automatic light sleep.

When I have it updated, I will run some power comparisons for using automatic light sleep to keep the WiFi 6 connection alive, vs using deep sleep and having the program need to reconnect and post them on my github page referenced above - this to help anyone who stumbles across this post in the future.

As an aside, in working my way thru the itwt example (https://github.com/espressif/esp-idf/blob/release/v5.1/examples/wifi/itwt/main/itwt.c ) I notice the following code which I though a little odd:

static void connect_handler(void *arg, esp_event_base_t event_base, int32_t event_id, void *event_data) { ESP_LOGI(TAG, "sta connect to %s", DEFAULT_SSID); esp_wifi_connect(); }

More specifically, the that connect handler calls esp_wifi_connect().

In my code I have taken this line out and it works fine.

Is there a reason that it is there?

esp-lis commented 1 year ago

@roblatour esp_wifi_connect may be called elsewhere in your code, need to check it.

dgduncan commented 1 year ago

@roblatour More often then not, esp_wifi_connect is often used in the handlers to deal with reconnections; however, in this case I believe the name connect_handler is a bit of a misnomer as it has nothing to do with "connecting" but instead catching the event when the WIFI_STATION actually starts and is ready to connect to the AP. But I can see how this could be up to personal interpretation.

roblatour commented 1 year ago

@dgduncan @esp-lis Thanks I hadn't noticed that in the itwt example the connect_handler was being assigned to handle the start event.

In my code, I had added the esp_wifi_connect() within an event handler I had more appropriately named start_handler, so it was working fine - but I got confused when I looked back at the example and the esp_wifi_connect() was under the (I agree misnamed) connect_handler.