esp-idf: ESP32-C6 - WiFi 6 - Target Wait Time (TWT) - Teardown function causes intermitent connection timeouts (IDFGH-12310)

Answers checklist.

I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

5.1.3

Espressif SoC revision.

ESP32-C6-FH4

Operating System used.

Windows

How did you build your project?

Eclipse IDE

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

None

Development Kit.

DFROBOT FireBeetle 2 ESP32 C6 IoT Development Board

Power Supply used.

USB

What is the expected behavior?

Calling esp_wifi_sta_itwt_teardown(flow_id) tears down the selected Targeted Wake Time and allows network traffic to flow freely through the wifi interface on receiving a WIFI_EVENT_ITWT_TEARDOWN event.

What is the actual behavior?

Calling esp_wifi_sta_itwt_teardown(flow_id) intermittently causes select() timeouts when creating new connections.

See the attached DEBUG Logs of an application I’ve been working on that integrates the itwt and mqtt tcp examples and sits in a loop publishing data from a sensor to a MQTT broker then sleeping for 5minutes.

In the Debug Logs:

The first iteration works without issue.
The 2nd fails to connect to the broker after 3 attempts over ~600ms after tearing down the TWT.
Finally, the last iteration connects to the broker on the 2nd attempt.

Steps to reproduce.

Setup and start wifi. Create a non trivial TWT agreement with an AP using a service period of around 5mins (e.g. 46875 << 13) , then in a loop:

Call _esp_wifi_sta_itwt_teardown()
Create a new TCP connection (e.g. using mqtt_client to publish some data)
Intermittently receive connection timeout (e.g. ESP_ERR_ESP_TLS_CONNECTION_TIMEOUT)
Try recovering by creating a new connection after a failure but often continue to receive a timeout.
Give up and create a new TWT agreement via a call to esp_wifi_sta_itwt_setup()
vTaskDelay() for a period of time, invoking automatic light sleep to minimise power consumption
GOTO step 1, restart the loop and hope the next iteration is more successful / wastes less time & power being awake.

Debug Logs.

D (37) app_main: Main task executing [boot:33203µs]
V (49) app_main: Wireless executing
I (55) wireless: Set static ip: 192.168.2.20, netmask: 255.255.255.0, gw: 192.168.2.1
I (103) wireless: WIFI_EVENT_STA_START
I (1589) wireless: WIFI_EVENT_STA_CONNECTED, ssid: 1337_2U
I (1639) wireless: IP_EVENT_STA_GOT_IP
I (1640) wireless: itwt setup, flow_id: 1, err: 0x0
I (1710) wireless: WIFI_EVENT_ITWT_SETUP twt_id: 0, flow_id: 1, trigger-enabled, announced, wake_dura: 255, wake_dura_unit: 0, wake_invl_e: 13, wake_invl_m: 46875
I (1715) wireless: WIFI_EVENT_ITWT_SETUP target wake time: 2533095219200, wake duration: 65280us, service period: 384000000us
V (1727) app_main: Wireless outputs: exec timer: 1678ms
V (1733) app_main: ADC executing
V (1737) app_main: ADC outputs: VCC = 3.722V, read timer: 582us
V (1744) app_main: SensorShtc init executing
V (1750) app_main: SensorShtc init outputs: low-power-mode-enabled, sleep-enabled, init timer: 1126us
V (1758) app_main: SensorShtc run executing
V (1765) app_main: SensorShtc run outputs: temperature = 24.55°C, humidity = 36.54% rH, read timer: 1525us
V (1774) app_main: Mqtt executing
I (1778) wireless: itwt teardown, flow_id: 8, err: 0x0
I (1779) wireless: WIFI_EVENT_ITWT_TEARDOWN flow_id 8(all twt)
I (1791) mqtt: MQTT_EVENT_BEFORE_CONNECT
I (1870) mqtt: MQTT_EVENT_CONNECTED
I (1871) mqtt: Sent publish, msg_id=36802
I (1875) mqtt: MQTT_EVENT_PUBLISHED, msg_id=36802
I (1879) mqtt: Destroyed client
I (1880) wireless: itwt setup, flow_id: 1, err: 0x0
I (1951) wireless: WIFI_EVENT_ITWT_SETUP twt_id: 0, flow_id: 1, trigger-enabled, announced, wake_dura: 255, wake_dura_unit: 0, wake_invl_e: 13, wake_invl_m: 46875
I (2002) wireless: WIFI_EVENT_ITWT_SETUP target wake time: 2533095526400, wake duration: 65280us, service period: 384000000us
V (2007) app_main: Mqtt outputs: data sent = '1, 0,24.5,36.5,3.722,-40,-1', msg id = 36802, exec timer: 229ms
V (2018) app_main: Iteration exec time: 284ms
V (2023) app_main: Heap max alloc: 123.3086 / 382.5547Kb
V (2029) app_main: Stack max alloc: 2.5195 / 8.0000Kb
D (2034) app_main: Delay until next iteration: 299716ms
V (301756) app_main: ADC executing
V (301756) app_main: ADC outputs: VCC = 3.720V, read timer: 556us
V (301805) app_main: SensorShtc init executing
V (301807) app_main: SensorShtc init outputs: low-power-mode-enabled, sleep-enabled, init timer: 1104us
V (301809) app_main: SensorShtc run executing
V (301816) app_main: SensorShtc run outputs: temperature = 23.79°C, humidity = 36.49% rH, read timer: 1525us
V (301825) app_main: Mqtt executing
I (301829) wireless: itwt teardown, flow_id: 8, err: 0x0
I (301830) wireless: WIFI_EVENT_ITWT_TEARDOWN flow_id 8(all twt)
I (301843) mqtt: MQTT_EVENT_BEFORE_CONNECT
E (301949) esp-tls: [sock=54] select() timeout
E (301949) transport_base: Failed to open a new connection: 32774
E (301950) mqtt_client: Error transport connect
I (301955) mqtt: MQTT_EVENT_ERROR
E (302005) mqtt: Last error reported from esp-tls: 0x8006 ESP_ERR_ESP_TLS_CONNECTION_TIMEOUT
I (302005) mqtt: MQTT_EVENT_DISCONNECTED
W (302008) app_main: mqtt ERROR_BIT | DISCONNECTED_BIT set during start(), retrying...
I (302018) mqtt: Destroyed client
I (302021) mqtt: MQTT_EVENT_BEFORE_CONNECT
E (302127) esp-tls: [sock=54] select() timeout
E (302127) transport_base: Failed to open a new connection: 32774
E (302128) mqtt_client: Error transport connect
I (302133) mqtt: MQTT_EVENT_ERROR
E (302137) mqtt: Last error reported from esp-tls: 0x8006 ESP_ERR_ESP_TLS_CONNECTION_TIMEOUT
I (302146) mqtt: MQTT_EVENT_DISCONNECTED
W (302150) app_main: mqtt ERROR_BIT | DISCONNECTED_BIT set during start(), retrying...
I (302160) mqtt: Destroyed client
I (302163) mqtt: MQTT_EVENT_BEFORE_CONNECT
E (302270) esp-tls: [sock=54] select() timeout
E (302270) transport_base: Failed to open a new connection: 32774
E (302365) mqtt_client: Error transport connect
I (302365) mqtt: MQTT_EVENT_ERROR
E (302365) mqtt: Last error reported from esp-tls: 0x8006 ESP_ERR_ESP_TLS_CONNECTION_TIMEOUT
I (302372) mqtt: MQTT_EVENT_DISCONNECTED
E (302377) app_main: mqtt ERROR_BIT | DISCONNECTED_BIT set during start() after 3 attempts
I (302386) mqtt: Destroyed client
I (302390) wireless: itwt setup, flow_id: 1, err: 0x0
I (302463) wireless: WIFI_EVENT_ITWT_SETUP twt_id: 0, flow_id: 1, trigger-enabled, announced, wake_dura: 255, wake_dura_unit: 0, wake_invl_e: 13, wake_invl_m: 46875
I (302514) wireless: WIFI_EVENT_ITWT_SETUP target wake time: 2533395763200, wake duration: 65280us, service period: 384000000us
V (302519) app_main: Mqtt outputs: data sent = 'NULL', msg id = 0, exec timer: 688ms
W (302528) app_main: Iteration exec time: 771ms
V (302533) app_main: Heap max alloc: 125.2617 / 382.5547Kb
V (302539) app_main: Stack max alloc: 2.5195 / 8.0000Kb
D (302545) app_main: Delay until next iteration: 299229ms
V (601780) app_main: ADC executing
V (601780) app_main: ADC outputs: VCC = 3.720V, read timer: 556us
V (601830) app_main: SensorShtc init executing
V (601831) app_main: SensorShtc init outputs: low-power-mode-enabled, sleep-enabled, init timer: 1102us
V (601834) app_main: SensorShtc run executing
V (601841) app_main: SensorShtc run outputs: temperature = 23.53°C, humidity = 39.46% rH, read timer: 1524us
V (601850) app_main: Mqtt executing
I (601854) wireless: itwt teardown, flow_id: 8, err: 0x0
I (601855) wireless: WIFI_EVENT_ITWT_TEARDOWN flow_id 8(all twt)
I (601868) mqtt: MQTT_EVENT_BEFORE_CONNECT
E (601974) esp-tls: [sock=54] select() timeout
E (601974) transport_base: Failed to open a new connection: 32774
E (601975) mqtt_client: Error transport connect
I (601980) mqtt: MQTT_EVENT_ERROR
E (602030) mqtt: Last error reported from esp-tls: 0x8006 ESP_ERR_ESP_TLS_CONNECTION_TIMEOUT
I (602030) mqtt: MQTT_EVENT_DISCONNECTED
W (602033) app_main: mqtt ERROR_BIT | DISCONNECTED_BIT set during start(), retrying...
I (602043) mqtt: Destroyed client
I (602046) mqtt: MQTT_EVENT_BEFORE_CONNECT
I (602057) mqtt: MQTT_EVENT_CONNECTED
I (602059) mqtt: Sent publish, msg_id=49687
I (602062) mqtt: MQTT_EVENT_PUBLISHED, msg_id=49687
I (602068) mqtt: Destroyed client
I (602069) wireless: itwt setup, flow_id: 1, err: 0x0
I (602142) wireless: WIFI_EVENT_ITWT_SETUP twt_id: 0, flow_id: 1, trigger-enabled, announced, wake_dura: 255, wake_dura_unit: 0, wake_invl_e: 13, wake_invl_m: 46875
I (602193) wireless: WIFI_EVENT_ITWT_SETUP target wake time: 2533695283200, wake duration: 65280us, service period: 384000000us
V (602198) app_main: Mqtt outputs: data sent = '3,60,23.5,39.5,3.720,-40,771', msg id = 49687, exec timer: 343ms
V (602209) app_main: Iteration exec time: 428ms
V (602214) app_main: Heap max alloc: 125.5039 / 382.5547Kb
V (602221) app_main: Stack max alloc: 2.5195 / 8.0000Kb
D (602227) app_main: Delay until next iteration: 299572ms

More Information.

I’ve tried many things to work round the issue including turning off various power saving techniques to omit them as a possible cause:

esp_pm_lock_create(ESP_PM_NO_LIGHT_SLEEP …)
esp_wifi_set_ps(WIFI_PS_NONE)
CONFIG_PM_POWER_DOWN_PERIPHERAL_IN_LIGHT_SLEEP=n

I’ve also tried idling after a teardown with vTaskDelay() before creating a connecting. Finally, I’ve tried using esp_wifi_sta_itwt_teardown(FLOW_ID_ALL) to no effect. It also doesn’t matter what timeout I give (100ms or 10000ms) when creating a tcp mqtt connection, it still fails taking the full timeout duration.

For context the wifi connection seems OK and is to a Ubiquiti UniFi U6 Enterprise AP with ~-40dbm RSSI and ~20% TX retries. Finally and anecdotally, the errors “seem” to come in waves as if related to interference? I’ve attached my sdkconfig.zip from the application I’m experiencing the issue in case I’ve missed anything.

On a related note, I’m also experiencing strange behaviour and fairly high power consumption in auto light sleep during TWT, ~110ua vs ~35ua as advertised, with a period of 1s:

110ua

These don’t seem to be ARP related as per: https://github.com/espressif/esp-idf/issues/12441#issuecomment-1775029218. Setting ARP_TMR_INTERVAL to any other value, currently set at 2000ms in the graph, does not change the interval shown on the graph. I’ve also seen strange transitions to auto light sleep after setting up a TWT that looks similar to https://github.com/espressif/esp-idf/issues/11858#issuecomment-1640244734 where the MODEM power domain is not powering down and thus current draw is around ~300ua. This can be seen earlier in the same current trace as above in the previous iteration:

300ua

Furthermore, I’ve tried switching dev boards vendors (both exhibit the same power draw), disconnected all peripherals and disabled/floated/hold all relevant GPIO to no avail. I’ve also edited sleep_modem.c with esp_sleep_cpu_retention_init() and get the same power draw without initialising wifi and manually invoking light sleep but strangely without the 1 second pulse in current consumption.

Hopefully someone can point me in the right direction, if I haven’t provide enough detail.

About this issue

Original URL
State: open
Created 4 months ago
Comments: 28

Most upvoted comments

Hi @xuxiao111,

Furthermore, we’re experiencing issues with several other aspects of HE wifi on the C6, these are some rx stats during longer testing:
I (20458958) wireless: [tid 0] legacy:9, su(su:8, su_txbf:5, su_stbc:3, su_retry:0/0.00%, ersu:0, ersu_dcm:0, su_noeb:0/0.00%)
...
I (20508968) wireless: [tid 0] legacy:0, su(su:36, su_txbf:0, su_stbc:36, su_retry:35/97.22%, ersu:0, ersu_dcm:0, su_noeb:0/0.00%)
...
I (22709735) wireless: [tid 0] legacy:0, su(su:36, su_txbf:0, su_stbc:36, su_retry:35/97.22%, ersu:0, ersu_dcm:0, su_noeb:0/0.00%)
...
W (24040213) wireless: No rx statistics available
I (24040214) wireless: [tid 0] legacy:1, ht(ht:0, ht_retry:0/0.00%, ht_noeb:0/0.00%)
I (24040215) wireless: [tid 0] legacy:1, su(su:0, su_txbf:0, su_stbc:0, su_retry:0/0.00%, ersu:147, ersu_dcm:147, su_noeb:0/0.00%)
I (24040216) wireless: [tid 0] legacy:1, mu(mu:0, mimo:0, non-mimo:0, txbf:0, stbc:0, mu_retry:0/0.00%, mu_noeb:0/0.00%)
They don’t reflect the TX retries from the AP that hover around ~15% and as can be seen in the log above after some time the device starts to see nearly 100% retry rates and then stops reporting anything other than ersu*. This coincides with a jump in heap high water mark of 159136K vs 147316K. Additionally the AP reports the RX rate of the device as 7.3 Mbps (MCS0 with 3.2 µs GI) from which it never recovers. A reset resolves the issue and the PHY rate goes back to normal 86 Mbps.

Additionally esp_wifi_get_rx_mu_statistics(&rx_mu_stats); stats report nothing, so can’t see details regarding MCS:
W (2026) wireless: No rx mimo statistics
W (2026) wireless: (mimo)dut rx:0
W (2026) wireless: (mimo)sigb, mcs0:0(nan%), mcs1:0(nan%), mcs2:0(nan%), mcs3:0(nan%), mcs4:0(nan%), mcs5:0(nan%)
W (2028) wireless: (mimo)users num2:0(nan%), num3:0(nan%), num4:0(nan%), num5:0(nan%), num6:0(nan%), num7:0(nan%), num8:0(nan%)
W (2029) wireless: No rx non mimo statistics
W (2030) wireless: (nonmimo)dut rx:0
W (2030) wireless: (nonmimo)ru_alloc_96_num_2046:0, ru_alloc_112_num_2046:0
W (2031) wireless: (nonmimo)sigb, mcs0:0(nan%), mcs1:0(nan%), mcs2:0(nan%), mcs3:0(nan%), mcs4:0(nan%), mcs5:0(nan%)
W (2033) wireless: (nonmimo)users, num1:0(nan%), num2:0(nan%), num3:0(nan%), num4:0(nan%), num5:0(nan%), num6:0(nan%), num7:0(nan%), num8:0(nan%), num9:0(nan%)
Finally, excessive (>50%) TX retry rates occur when the C6 is close to our AP, reducing the tx power down from 20db -> 16.5db mitigates.

I’m running another long duration test with TWT disabled to see if the same issues occur with the stuck PHY rate, if it does I’ll create a new bug report, else it’s probably best to keep all these teardown/setup issues here?

What hardware and setup are you using to capture wifi frames? Maybe running that here can facilitate analysing these problems.

Furthermore, we’re experiencing issues with several other aspects of HE wifi on the C6, these are some rx stats during longer testing: Hi, for esp_wifi_get_rx_mu_statistics(&rx_mu_stats), only when the STA receives an MU-PPDU, calling esp_wifi_get_rx_mu_statistics(&rx_mu_stats) will have data available. Please fell free to open a new bug to track this issues. We are using intel AX200 wifi card to capture wifi frame, you can fellow this guide: https://wifilogic.wordpress.com/2019/09/21/how-to-setup-wifi6-sniffer-in-ubuntu/

xuxiao111 on Apr 9, 2024

Hi @djangoa,

I have changed the service period to 118489088us (~118s), and the test log is twt_ping_example_2.log , and still works fine. The “E (25283) wifi:(itwt)twt id:0 is already exist, please change to another value”, is an internal error, we already found the root cause and will fix it ASAP. Thanks for reporting this issue. I (516434) itwt: <WIFI_EVENT_ITWT_TEARDOWN> flow_id 8(all twt) I (516485) wifi:Set ps type: 0, coexist: 0

E (516688) itwt: <PING_EVENT_TIMEOUT> From 192.168.50.1 icmp_seq=1 timeout E (517083) itwt: <PING_EVENT_TIMEOUT> From 192.168.50.1 icmp_seq=2 timeout I (517216) itwt: <PING_EVENT_SUCCESS> 56 bytes from 192.168.50.1 icmp_seq=3 ttl=64 time=132 ms I (517251) itwt: <PING_EVENT_SUCCESS> 56 bytes from 192.168.50.1 icmp_seq=4 ttl=64 time=13 ms E (517487) itwt: <PING_EVENT_END> 4 packets transmitted, 2 received, 50% packet loss, time 690mn W (517487) stats: Get tx statistics

(test)rx_trig:0, tx_bfrpt:2, tb_times:0, tb_qos_null:0, tb_qos_data:0, tb_cca_cancel:0, tb_sifs_abort:0, tb_pwr_outof_range:0 (test)aci:2, tb(suc:0, ack:0, err:0), count(suc:0, ack:0, err:0, tot:0, max_sent:0) (test)aci:2, enable:4, complete:4, tb_times:0, tb_last:0, edca:4, succ:4, fail(0,0,0, cts:0/0.00%, ack:0/0.00%, tot:0, 0.00%), edca(ack:0, ba:4), tb(hw-ba:0, sw-ba:0) (test)aci:2, txFrames:4, s-mpdu:0(0.00%), bitmap(max:1, min:1, tot:4, avg:1.00), retry(edca:0, tb:0, 0.00%), collision:0, timeout:0 (test)aci:2, seqno_rtt[321,77102], hw_rtt[321, 77102], muedca[enable:0, times:0, 0.00, 0.00, tot:0.00], avg:24.872 ms, tot:0.099 secs As for ping timeout, from this log, we can see, that enabled to transmit 4 data frames, and the success is also 4, the success means that the station successfully transmits the data frame and receives the ACK frame from AP. So seems like the reason why ping timeout is no ping replay received within 250 ms.

Also, I have done the ping test using iperf example under the same test env, We can see the ping delay between 4ms ~ 225ms, the main reason is that my environment is relatively noisy and there will be many wireless devices, which will interfere with each other. And I will do a long test to see if the same problem exists.

xuxiao111 on Apr 3, 2024