Network not working when TWT is activated on nrf7002DK

[Seb-labs]

I have an nrf7002DK

using sdk-nrf v2.4.1.

I compiled wifi shell sample

The used ap is netgear WAX214 AX1800.

After connecting to it, I check the wifi status:

> wifi status
Status: successful
==================
State: COMPLETED
Interface Mode: STATION
Link Mode: WIFI 6 (802.11ax/HE)
SSID: MyWifi6                    
BSSID: **:**:**:**:**:**
Band: 5GHz
Channel: 44
Security: WPA3-SAE
MFP: Optional
RSSI: -38
Beacon Interval: 100
DTIM: 2
TWT: Supported

All communications are working correctly (ping from 7002DK, ping to 7002DK, tcp from 7002DK).

I activate twt:

>wifi twt setup 0 0 1 1 0 1 1 1 65000 524000
TWT operation TWT setup with dg: 1, flow_id: 1 requested
TWT response: TWT accept
TWT Dialog token: 1
TWT flow ID: 1
TWT negotiation type: TWT individual negotiation
TWT responder: true
TWT implicit: true
TWT announce: true
TWT trigger: true
TWT wake interval: 65024 us
TWT interval: 524000 us
========================
>wifi ps
PS status: Power save enabled
PS mode: Legacy power save
PS listen_interval: 10
PS wake up mode: DTIM
PS timeout: -1 ms
TWT Dialog token: 1
TWT flow ID: 1
TWT negotiation type: TWT individual negotiation
TWT responder: false
TWT implicit: true
TWT announce: true
TWT trigger: true
TWT wake interval: 65024 us
TWT interval: 524000 us
========================

And then no communication are working:

>net ping 192.168.0.1
PING 192.168.0.1
Ping timeout

>net tcp connect 192.168.0.1 80
Connecting from 192.168.1.39:0 to 192.168.0.1:80
TCP connection failed (-116)
[00:08:47.829,925] <err> os: ***** USAGE FAULT *****
[00:08:47.829,956] <err> os:   Illegal use of the EPSR
[00:08:47.829,956] <err> os: r0/a1:  0x20000e18  r1/a2:  0x0008ea08  r2/a3:  0x20007e40
[00:08:47.829,956] <err> os: r3/a4:  0x0008ecf8 r12/ip:  0x20038c20 r14/lr:  0x0000c60f
[00:08:47.829,956] <err> os:  xpsr:  0x60000000
[00:08:47.829,986] <err> os: Faulting instruction address (r15/pc): 0x0008ecf8
[00:08:47.829,986] <err> os: >>> ZEPHYR FATAL ERROR 35: Unknown error on CPU 0
[00:08:47.830,017] <err> os: Current thread: 0x20002868 (tcp_work)
[00:08:47.887,664] <err> coredump: #CD:BEGIN#
[00:08:47.893,432] <err> coredump: #CD:5a4501000300050023000000
[00:08:47.900,726] <err> coredump: #CD:4102004400
[00:08:47.906,829] <err> coredump: #CD:180e002008ea0800407e0020f8ec0800208c03200fc60000f8ec080000000060
[00:08:47.917,633] <err> coredump: #CD:28d0002000000000000000000000000000000000000000000000000000000000
[00:08:47.928,405] <err> coredump: #CD:00000000
[00:08:47.934,326] <err> coredump: #CD:4d01006828002030290020
[00:08:47.941,467] <err> coredump: #CD:e0200020607e0020000000000080f00000000000000000000000000000000000
[00:08:47.952,270] <err> coredump: #CD:000000000000000000000000000000000000000000000000ffffffffffffffff
[00:08:47.963,073] <err> coredump: #CD:00000000000000000000000000000000f0cf002000000000c0280020c0280020
[00:08:47.973,876] <err> coredump: #CD:0001000009910500682800200000000000000000d03200207463705f776f726b
[00:08:47.984,649] <err> coredump: #CD:00000000000000000000000000000000000000000000000000000000a0cc0020
[00:08:47.995,452] <err> coredump: #CD:0004000000000000ec1300200000000000000000000000000000000000000000
[00:08:48.006,256] <err> coredump: #CD:0000000000000000
[00:08:48.012,878] <err> coredump: #CD:4d0100a0cc0020a0d00020
[00:08:48.020,019] <err> coredump: #CD:f0f0f0f0aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[00:08:48.030,822] <err> coredump: #CD:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[00:08:48.041,595] <err> coredump: #CD:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[00:08:48.052,398] <err> coredump: #CD:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[00:08:48.063,201] <err> coredump: #CD:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[00:08:48.074,005] <err> coredump: #CD:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[00:08:48.084,808] <err> coredump: #CD:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[00:08:48.095,581] <err> coredump: #CD:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[00:08:48.106,384] <err> coredump: #CD:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[00:08:48.117,187] <err> coredump: #CD:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[00:08:48.127,990] <err> coredump: #CD:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[00:08:48.138,793] <err> coredump: #CD:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[00:08:48.149,597] <err> coredump: #CD:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[00:08:48.160,400] <err> coredump: #CD:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[00:08:48.171,203] <err> coredump: #CD:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa
[00:08:48.182,006] <err> coredump: #CD:aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaab032002020310020
[00:08:48.192,779] <err> coredump: #CD:00000000d99305002031002001000000607e0020f19405006828002068280020
[00:08:48.203,582] <err> coredump: #CD:44100020d79605006828002017a208000000000000ed00e0407e002000000000
[00:08:48.214,385] <err> coredump: #CD:c1000000640c09000200000000000000ffffffff208c0320640c090044cf0020
[00:08:48.225,189] <err> coredump: #CD:02000000e0350020640c0900e1fc060044cf0020020000001c00000025fd0600
[00:08:48.235,992] <err> coredump: #CD:44cf0020020000001c00000080ef080003fd0600c43500200f4809008f0a0700
[00:08:48.246,795] <err> coredump: #CD:0200000002000000140c09000a0000001d05070000000000ffffffffb50a0700
[00:08:48.257,598] <err> coredump: #CD:af0a070015050700140c09005b050700becf00201c000000140c090047590000
[00:08:48.268,402] <err> coredump: #CD:becf0020c0cf00200d48090048d0002074000000000000008000016400000000
[00:08:48.279,174] <err> coredump: #CD:000000000000000000000000010000009294070119950700b032002020310020
[00:08:48.289,978] <err> coredump: #CD:00000000d99305002031002001000000607e0020f19405006828002068280020
[00:08:48.300,781] <err> coredump: #CD:68440020d79605006828002017a208000000000000ed00e0407e002000000000
[00:08:48.311,584] <err> coredump: #CD:208c032023970500e4c400000000006168440020c38d05006844002000000000
[00:08:48.322,357] <err> coredump: #CD:68440020878e0500180e002008ea0800407e0020f8ec0800208c03200fc60000
[00:08:48.333,160] <err> coredump: #CD:f8ec08000000006000000000197007008cffffff0000000064ae032001000000
[00:08:48.343,963] <err> coredump: #CD:3cae032095700700ccae0320682800200000000093910500ffffffffffffffff
[00:08:48.354,736] <err> coredump: #CD:0000000068280020099105000000000000000000f7bc060000000000aaaaaaaa
[00:08:48.365,539] <err> coredump: #CD:END#
[00:08:48.371,093] <err> fatal_error: Resetting system

The last valid stack trace is https://github.com/nrfconnect/sdk-zephyr/blob/28a3fca7da5cfb3b72f1a874b3b7fa62f713ab3d/subsys/net/ip/tcp.c#L503.

After some minutes of twt activated, the 7002DK disappear from connected device in the AP webui. If I desactivate twt, the 7002DK realise it is disconnected, and reconnect:

>wifi twt teardown_all
TWT operation TWT teardown all flows
Disconnected
[00:18:21.978,485] <inf> wpa_supp: wlan0: CTRL-EVENT-DISCONNECTED bssid=**:**:**:**:**:** reason=2 locally_generated=1
[00:18:22.004,547] <inf> wpa_supp: wlan0: CTRL-EVENT-DSCP-POLICY clear_all
Connected
[00:18:27.160,644] <inf> wpa_supp: wlan0: SME: Trying to authenticate with **:**:**:**:**:** (SSID='MyWifi6' freq=5220 MHz)
[00:18:27.171,997] <inf> wifi_nrf: wifi_nrf_wpa_supp_authenticate:Authentication request sent successfully

[00:18:27.739,959] <inf> wpa_supp: wlan0: SME: Trying to authenticate with **:**:**:**:**:** (SSID='MyWifi6' freq=5220 MHz)
[00:18:27.747,985] <inf> wifi_nrf: wifi_nrf_wpa_supp_authenticate:Authentication request sent successfully

[00:18:27.754,455] <inf> wpa_supp: wlan0: Trying to associate with **:**:**:**:**:** (SSID='MyWifi6' freq=5220 MHz)
[00:18:27.760,681] <inf> wifi_nrf: wifi_nrf_wpa_supp_associate: Association request sent successfully

[00:18:27.773,681] <inf> wpa_supp: wlan0: Associated with **:**:**:**:**:**
[00:18:27.773,773] <inf> wpa_supp: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
[00:18:27.799,011] <inf> wpa_supp: wlan0: WPA: Key negotiation completed with **:**:**:**:**:** [PTK=CCMP GTK=CCMP]
[00:18:27.799,133] <inf> wpa_supp: wlan0: CTRL-EVENT-CONNECTED - Connection to **:**:**:**:**:** completed [id=0 id_str=]
[00:18:27.835,144] <inf> net_dhcpv4: Received: 192.168.1.39

Do you have an idea of what is happening? I have nothing to capture wifi communications.

[Seb-labs]

I disabled GTK/Group rekeying on the ap.

Tried with wifi_shell you provided to me with this parameters:

wifi twt setup 0 0 1 1 0 0 1 1 65000 600000000

Not working: device is disconnected.

Here is the capture I have done:

wifi6-twt2.pcapng

Regards.

[Simonr]

Hi

From the sniffer trace this looks to be an AP issue for the following reasons:

1. The TWT session is initiated with 600 seconds of sleep.
2. The DK wakes up at the 600th second and schedule the uplink "QOS null" as per protocol.
3. For some reason the AP seems to send a deauthentication message to the DK. 

The AP is trying to send frames after ~300 seconds even though a DK is in TWT power save, which the DK isn't able to receive. If we look at frames 6781-6938 we can see a "TIM" for the DK in all beacons. You can add the following filter to capture these frames:

(wlan.addr == f4:ce:36:00:20:d2) || (wlan.tim.partial_virtual_bitmap != 00)

So it seems like an interoperability issue with this specific AP to us. Can you try another AP for your application (we would recommend an ASUS AP, as we've had a good success rate with them) to see if that works better.

Best regards,

Simon

[Seb-labs]

Can you advice me an exact asus ap reference?

[Simonr]

Hi again

So, this will be an issue with multiple APs, since most APs will give a deauth if you don't send traffic after setting up the TWT. The AP is listening up to the inactivity timeout and if there's no traffic from the station during the inactivity time period. By setting the interval to 600 seconds (10 minutes), almost all APs will time out and trig a deauth before the device wakes up the first time, so we would strongly recommend the sleep interval to be much lower (60 seconds for example) and for the nRF7002 to do some data transfers every now and then to not be deauthenticated by the AP.

With the .hex we provided, did you try doing Pings/TCP connects with this, and did you still see the same issues? In general, with lower intervals TWT will work as expected, but since most APs don't support very high sleep intervals, there will likely be issues with multiple minutes of sleep intervals. 

Unfortunately I'm not aware of any APs that supports as much as 600 seconds of sleep intervals, so on that end you're on your own. But at a 1 minute interval your application should be able to work as expected both on the AP you're using and I.E. an ASUS RT-AX3000 AP.

Best regards,

Simon

[Seb-labs]

Our device will be on battery. Even 600 s is not enough for the consumption goal. We will need at least 1h.

Is there a way to disconnect the wifi (and power off the 7200), and connect to wifi only when needed but without the scan part at connection (like a fast connect)?

I tried with wifi shell sample, and when I enter wifi connect (giving the exact channel), There is a long (7s) delay at 60 mA the first time. If I disconnect and connect again, it is faster.