Enable 802.11kv causes memory leak and unexpected impact with wifi scan (IDFGH-5703)

[AxelLin]

Environment

Module or chip used: ESP32-WROOM-32E
IDF version: v4.3-356-g48ae2309fd9c
Build System: idf.py
Compiler version: xtensa-esp32-elf-gcc (crosstool-NG esp-2021r1) 8.4.0
Operating System: Linux
Power Supply: USB

Problem Description

While testing wifi roaming, I notice my application keeps receiving WIFI_EVENT_SCAN_DONE event.
I register even hander for WIFI_EVENT_SCAN_DONE event because when user issues wifi scan
command, my application code will collect received scan result.
But now my application code keeps get called because the scan is issued internally when 802.11kv is enabled.
I'm not sure if there is a proper way to differentiate the scan caused by 802.11kv or
the scan because user explicitly set command to scan. If not, this seems a bug.

BTW, the device issues scan so frequently when 802.11kv is enabled (see the timestamp below).
Is this normal?

I (726679) wpa: action frame sent
I (732690) wpa: scan issued at time=1956986705404
I (732695) wpa: BSS: Add new id 326 BSSID ac:84:c6:32:14:77 SSID 'TEST-MESH' chan 9
I (732709) wpa: BSS: Add new id 327 BSSID d8:47:32:7c:34:ba SSID 'TEST-MESH' chan 9
I (732738) wpa: BSS: Add new id 328 BSSID ac:84:c6:32:35:b5 SSID 'TEST-MESH' chan 9
I (732741) app: Got WIFI_EVENT, event_id 1
I (732742) wpa: scan done received
I (732748) wpa: action frame sent
I (738756) wpa: scan issued at time=1956992771567
I (738761) wpa: BSS: Add new id 329 BSSID ac:84:c6:32:14:77 SSID 'TEST-MESH' chan 9
I (738773) wpa: BSS: Add new id 330 BSSID ac:84:c6:32:1a:26 SSID 'TEST-MESH' chan 9
I (738808) app: Got WIFI_EVENT, event_id 1
I (738808) wpa: scan done received
I (738810) wpa: action frame sent
I (744816) wpa: scan issued at time=1956998831566
I (744822) wpa: BSS: Add new id 331 BSSID ac:84:c6:32:14:77 SSID 'TEST-MESH' chan 9
I (744828) wpa: BSS: Add new id 332 BSSID ac:84:c6:32:1a:26 SSID 'TEST-MESH' chan 9
I (744856) wpa: BSS: Add new id 333 BSSID d8:47:32:7c:34:ba SSID 'TEST-MESH' chan 9
I (744868) app: Got WIFI_EVENT, event_id 1
I (744869) wpa: scan done received
I (744871) wpa: action frame sent
I (750879) wpa: scan issued at time=1957004894061
I (750894) wpa: BSS: Add new id 334 BSSID ac:84:c6:32:14:77 SSID 'TEST-MESH' chan 9
I (750903) wpa: BSS: Add new id 335 BSSID ac:84:c6:32:1a:26 SSID 'TEST-MESH' chan 9
I (750931) app: Got WIFI_EVENT, event_id 1
I (750931) wpa: scan done received
I (750933) wpa: action frame sent
I (757037) wpa: scan issued at time=1957011052506
I (757043) wpa: BSS: Add new id 336 BSSID ac:84:c6:32:14:77 SSID 'TEST-MESH' chan 9
I (757046) wpa: BSS: Add new id 337 BSSID ac:84:c6:32:1a:26 SSID 'TEST-MESH' chan 9
I (757089) app: Got WIFI_EVENT, event_id 1
I (757089) wpa: scan done received
I (757091) wpa: action frame sent
I (763102) wpa: scan issued at time=1957017117584
I (763107) wpa: BSS: Add new id 338 BSSID ac:84:c6:32:1a:26 SSID 'TEST-MESH' chan 9
I (763115) wpa: BSS: Add new id 339 BSSID ac:84:c6:32:14:77 SSID 'TEST-MESH' chan 9
I (763130) wpa: BSS: Add new id 340 BSSID d8:47:32:7c:34:ba SSID 'TEST-MESH' chan 9
I (763151) wpa: BSS: Add new id 341 BSSID ac:84:c6:32:35:b5 SSID 'TEST-MESH' chan 9
I (763154) app: Got WIFI_EVENT, event_id 1
I (763156) wpa: scan done received

Expected Behavior

I'm not sure if there is a proper way to differentiate the scan caused by 802.11kv or
the scan because user explicitly set command to scan.
If yes, please document how do differentiate the scan caused by 802.11kv or not.
If not, this seems a bug.

Actual Behavior

see above log

Steps to reproduce

Just set below config and enable rm_enabled and btm_enabled in wifi config.
CONFIG_WPA_DEBUG_PRINT=y
CONFIG_WPA_11KV_SUPPORT=y

[AxelLin]

@kapilkedawat

I figure out the reason why my device run to OOM if CONFIG_WPA_11KV_SUPPORT=y
#3671 (comment)

My code flow is: (when user start wifi scan, I will collect the scan result and display for user)

1. The caller to start wifi scan
2. Collect scan result when got WIFI_EVENT_SCAN_DONE
3. Pass the scan result to the caller and the caller will free the memory for saving scan result

This works fine when CONFIG_WPA_11KV_SUPPORT=n.

However, when CONFIG_WPA_11KV_SUPPORT=y the device will scan in the backgroud.
So I got many WIFI_EVENT_SCAN_DONE and my code will allocate memory to collect scan result.
Since the scan is not trigger my application code, the the memory for saving scan result is never released so it run to OOM.

This leads to this issue:

1. I cannot differentiate if the WIFI_EVENT_SCAN_DONE is caused by 802.11kv in backgroud or scan by the user.
2. For the scan by 802.11kv in backgroud case, what should I suppose to do when got WIFI_EVENT_SCAN_DONE?
   I'm not familiar the 802.11kv scan case, I observed many scan but the device seems never roaming no matter if I move the
   device away from the origianl AP. Did I miss something?

[kapilkedawat]

Hi @AxelLin ,

Scan triggered by supplicant are cleaned in esp_supp_scan_done_cleanup() routine. We tried to reproduce this issue inhouse but couldn't.

If the issue is easy enough to reproduce in your environment , Can you please collect supplicant logs and sniffer captures and attach here?

[AxelLin]

@kapilkedawat

The problem is not esp_supp_scan_done_cleanup().
In components/wpa_supplicant/src/esp_supplicant/esp_scan.c it calls esp_wifi_scan_start().

My code (register event handler for WIFI_EVENT, ESP_EVENT_ANY_ID) to collect scan result will allocate memory to collect scan result,
In my application code the caller will free the memory when scan is done.

The point is it will post WIFI_EVENT_SCAN_DONE event, and I cannot tell
if the WIFI_EVENT_SCAN_DONE should be ignored (by triggered by supplicant).

[AxelLin]

@kapilkedawat

Let me explain this way:

My code flow is: (when user start wifi scan, I will collect the scan result and display for user)

1. The caller to start wifi scan (blocking=true)
2. Collect scan result when got WIFI_EVENT_SCAN_DONE
3. Pass the scan result to the caller and the caller will free the memory for saving scan result

This works fine when CONFIG_WPA_11KV_SUPPORT=n.

See above code flow.
The question is when CONFIG_WPA_11KV_SUPPORT=y the
"2. Collect scan result when got WIFI_EVENT_SCAN_DONE" will be called many times. (will allocate memory to save scan result)"
However the "3. Pass the scan result to the caller and the caller will free the memory for saving scan result" is never called
because the scan is not triggered by user but triggered by supplicant.

This is nothing to do with environment.

[kapilkedawat]

Hi @AxelLin ,
WIFI_EVENT_SCAN_DONE is a generic event and can be registered by a number of applications, however the cleanup should be done by the application which issued the scan. Please see the flow where supplicant only cleans the scan if it issued that(wpa_s->scanning) . I would suggest to keep reference in application to check whether scan was issued by application.

@kapilkedawat

Let me explain this way:

My code flow is: (when user start wifi scan, I will collect the scan result and display for user)

1. The caller to start wifi scan (blocking=true)
2. Collect scan result when got WIFI_EVENT_SCAN_DONE
3. Pass the scan result to the caller and the caller will free the memory for saving scan result

This works fine when CONFIG_WPA_11KV_SUPPORT=n.

See above code flow.
The question is when CONFIG_WPA_11KV_SUPPORT=y the
"2. Collect scan result when got WIFI_EVENT_SCAN_DONE" will be called many times. (will allocate memory to save scan result)"
However the "3. Pass the scan result to the caller and the caller will free the memory for saving scan result" is never called
because the scan is not triggered by user but triggered by supplicant.

that's what my original comment #7423 (comment) mean, whenever scan is issued by supplicant, cleanup is also called by supplicant(application need not to call anything). And the supplicant scan cleanup function only being called when that scan is issued by supplicant.

May be the issue is more related to your application and how it is handling the scan_done event, Can you paste your scan issue and handler code so that we can take a look?

This is nothing to do with environment.

[AxelLin]

@kapilkedawat

I'm aware the application should clean up memory allocated by the application.
That is why I keep asking how to differentiate if a scan is triggered by supplicant.
I want to avoid my WIFI_EVENT_SCAN_DONE event handler to allocate memory if it's triggered by supplicant.
(No matter it's triggered by supplicant of application, I got the same WIFI_EVENT_SCAN_DONE event.)

I'm not sure what you mean by "keep reference in application to check whether scan was issued by application".

My application does simple scan as below:

1. esp_wifi_scan_start() // with blocking=true
2. esp_wifi_scan_stop();
3. process the scan_result and free the memory once processing in application is done.

When got WIFI_EVENT_SCAN_DONE event:
I did

1. call esp_wifi_scan_get_ap_num and allocate required memory for storing the memory
2. call esp_wifi_scan_get_ap_records and save the scan result
   (I need to allocate memory for saving the scan result because it's needed for further operations in application).

[kapilkedawat]

A simple code example to handle this.

1. scan_issued_by_application = true;
2. esp_wifi_scan_start() // with blocking=true
3. process the scan_result and free the memory once processing in application is done.

When you get WIFI_EVENT_SCAN_DONE event:

if (scan_issued_by_application == false)
return; // issued by other applications

/* do scan processing */

1. scan_issued_by_application = false; //cleanup
2. call esp_wifi_scan_get_ap_num and allocate required memory for storing the memory.
3. call esp_wifi_scan_get_ap_records and save the scan result.

[AxelLin]

@kapilkedawat

It's racy with your suggestion.

You expect:

scan_issued_by_application = true;
esp_wifi_scan_start() // with blocking=true
scan_issued_by_application = false;

But in practice the supplicant is running in different task, it could be:

scan_issued_by_application = true;
esp_wifi_scan_start() // trigger by supplicant
esp_wifi_scan_start() // with blocking=true
scan_issued_by_application = false;

or

esp_wifi_scan_start() // trigger by supplicant
scan_issued_by_application = true;
esp_wifi_scan_start() // with blocking=true
scan_issued_by_application = false;

or

scan_issued_by_application = true;
esp_wifi_scan_start() // with blocking=true
esp_wifi_scan_start() // trigger by supplicant
scan_issued_by_application = false;

In additonal, I notice sometimes the esp_wifi_scan_start() trigger by application returns -1 if scan was trigger by supplicant.

[AxelLin]

@kapilkedawat

I also notice something unusal when application calls scan (scan all channels).
(I'm not sure if this is a bug or not. just FYI)

esp_issue_scan() will scan specific scan_params.
i.e. when supplicant triggerd scan, I observed:
I (304332) wpa: BSS: Add new id 185 BSSID ac:84:c6:32:14:77 SSID 'TEST-MESH' chan 9
I (304335) wpa: BSS: Add new id 186 BSSID ac:84:c6:32:1a:26 SSID 'TEST-MESH' chan 9
I (304353) wpa: BSS: Add new id 187 BSSID ac:84:c6:32:35:b5 SSID 'TEST-MESH' chan 9
I (304358) wpa: BSS: Add new id 188 BSSID d8:47:32:7c:34:ba SSID 'TEST-MESH' chan 9

i.e. It only adds new id for the same SSID / channel.

However, when my application trigger all channel scan, I observe below:
It adds new id for various SSIDs. (So this has impacted supplicant?)

I (376316) wpa: BSS: Add new id 206 BSSID ac:84:c6:32:1a:26 SSID 'TEST-MESG' chan 9
I (376394) wpa: BSS: Add new id 207 BSSID d8:47:32:7c:34:ba SSID 'TEST-MESG' chan 9
I (376468) wpa: BSS: Add new id 208 BSSID 00:d0:41:df:8e:31 SSID 'LAB-SA' chan 1
I (376477) wpa: BSS: Add new id 209 BSSID 9c:65:ee:b9:27:2f SSID 'tel26824949' chan 1
I (376540) wpa: BSS: Add new id 210 BSSID f8:1d:0f:0c:5a:68 SSID 'haha' chan 1
I (376744) wpa: BSS: Add new id 211 BSSID ac:84:c6:32:14:77 SSID 'TEST-MESG' chan 9
I (376918) wpa: BSS: Add new id 212 BSSID 1c:49:7b:b4:42:4a SSID 'AP-b44248' chan 4
I (377314) wpa: BSS: Add new id 213 BSSID ba:55:10:cf:aa:df SSID 'LAB-GUEST' chan 6
I (377315) wpa: BSS: Add new id 214 BSSID ba:55:10:cf:aa:d0 SSID 'LAB-WPA2-ENT' chan 6
I (377320) wpa: BSS: Add new id 215 BSSID b8:55:10:cf:aa:de SSID 'LAB' chan 6

[AxelLin]

Hi @kapilkedawat

Once 802.11kv is enabled on ESP32, the device keeps scan so frequently.
(see below log, it seems issue scan in very short interval.)

I (70455720) wpa: scan issued at time=2507736990988
I (70464832) wpa: scan issued at time=2507746103155
I (70480809) wpa: scan issued at time=2507762080506
I (70508864) wpa: scan issued at time=2507790135166
I (70517876) wpa: scan issued at time=2507799146489
I (70576961) wpa: scan issued at time=2507858231224
I (70576965) wpa: scan issued at time=2507858233826
I (70588327) wpa: scan issued at time=2507869597651
I (70613006) wpa: scan issued at time=2507894276012
I (70673115) wpa: scan issued at time=2507954385203
I (70697179) wpa: scan issued at time=2507978449124
I (70706190) wpa: scan issued at time=2507987459908
I (70733224) wpa: scan issued at time=2508014493581
I (70757288) wpa: scan issued at time=2508038557617
I (70792309) wpa: scan issued at time=2508073578463
I (70816374) wpa: scan issued at time=2508097642595
I (70856412) wpa: scan issued at time=2508137681139
I (70876483) wpa: scan issued at time=2508157751303
I (70892457) wpa: scan issued at time=2508173725552
I (70904540) wpa: scan issued at time=2508185808689
I (70944579) wpa: scan issued at time=2508225847448
I (70964662) wpa: scan issued at time=2508245930536
I (70992605) wpa: scan issued at time=2508273872958
I (71056708) wpa: scan issued at time=2508337975636
I (71100844) wpa: scan issued at time=2508382111318
I (71112823) wpa: scan issued at time=2508394090510
I (71136889) wpa: scan issued at time=2508418155586
I (71176926) wpa: scan issued at time=2508458192910
I (71193003) wpa: scan issued at time=2508474269564
I (71202014) wpa: scan issued at time=2508483280732
I (71237035) wpa: scan issued at time=2508518301561

I'm testing with Tplink Deco X60.
There is only one setting regarding roaming on the AP, to enable "Fast roaming" or not. (It's enabled on the AP)
Even though the ESP32 keeps scan, it seems the roaming never happen at all.

1. Is the above frequently scan a normal behavior?
2. How to recognize if roaming trigger by AP has happened? (Will device got some event so I can know roaming is done?)

[AshUK]

+1 have seen this issue, we ended up just disabling 802.11k and forcing a wifi disconnect before a scan however we would have a preferred a way to differentiate a from an intended scan. We tie a lot of onboarding user logic (including LED states) to wifi events. All of our wifi scans use the non-blocking mechanism esp_wifi_scan_start(&scan_config, false).

[kapilkedawat]

Hi @AxelLin , are you enabling client initiated roaming?
Can you please share sniffer captures when this happened?

[AxelLin]

Hi @AxelLin , are you enabling client initiated roaming?

No, that will cause other issues so I didn't call esp_wifi_set_rssi_threshold() in this test.
And I didn't handle WIFI_EVENT_STA_BSS_RSSI_LOW event.
Just want to test the roaming trigger by AP.

I just set below config and enable rm_enabled and btm_enabled in wifi config.
CONFIG_WPA_DEBUG_PRINT=y
CONFIG_WPA_11KV_SUPPORT=y

Can you please share sniffer captures when this happened?

I'm not sure if I can do it the sniffer may include some confidential data that I cannot share.
BTW, it just keeps happens. I observe the frequently scan since I begin testing roaming.

[AxelLin]

+1 have seen this issue, we ended up just disabling 802.11k and forcing a wifi disconnect before a scan however we would

+1, I don't have confidence to enable CONFIG_WPA_11KV_SUPPORT for production code at the moment.
However, without roaming support it has a different bug.
e.g. If the strongest signal AP reboot, the ESP32 (STA mode) may disconnect and re-connect to
a weak singal AP. Then it will has bad wifi performance.

[kapilkedawat]

Hi @AxelLin, in that case, scan is issued by AP, you can check whether AP is sending beacon measurement request.

[sagb2015]

@AxelLin @AshUK We have discussed the SCAN_DONE event implication for the applications. For internal 11kv scan, we will have additional event added, so that applications can distinguish clearly. Also, for scanning frequency, we will check with different routers with roaming enabled and see the "beacon measurement request" frequency from the AP.

[AxelLin]

@sagb2015

I have confirmed the frequently scan is because reciving "beacon measurement request" from AP.
I cannot judge if such behavior is correct or not.
However, we cannot control which AP model will be used by users.
I think it needs to allow programmer to run-time disable wifi roaming in case if the device hits unexpected behaviour.
(Currently it's compile time determinated by CONFIG_WPA_11KV_SUPPORT=y).

[sagb2015]

Hi @AxelLin, we have btm_enabled & rm_enabled flags in wifi_sta_config_t to control these 11kv behaviours. We may do some optimisation to deal with APs sending continuous measurement requests.

[AxelLin]

Hi @AxelLin, we have btm_enabled & rm_enabled flags in wifi_sta_config_t to control these 11kv behaviours. We may do some optimisation to deal with APs sending continuous measurement requests.

Thanks for the confirm.

Actually I had asked it before: #3671 (comment)
I just didn't fully understand @kapilkedawat's reply so I'm not sure if it's correct to just set rm_enabled = 0 && btm_enabled = 0.

Maybe needs some document update to make it clear about the way to run-time disable wifi roaming.

[AxelLin]

@AxelLin @AshUK We have discussed the SCAN_DONE event implication for the applications. For internal 11kv scan, we will have additional event added, so that applications can distinguish clearly.

In my current test, I just bypass the SCAN_DONE even if it is triggered by internal 11kv scan.
Just curious what do you expect the application developer to do with the new SCAN_DONE event?
Any thing needs to be taken care by application side when got the new SCAN_DONE event?

[sagb2015]

@AxelLin - Yes the documentation is WIP. Will have it ready soon.

[IbrahimMuala]

Hello,

I have bought a Deco M4 V2 (3-pack). I used one as a router and the second and third one as access points. I successfully made the ESP32 connected to it. but I found that ESP32 connected to the closest deco and it stayed connected to it, even if I walked and went to another deco.

Is there any way to make the esp32 connect to another repeater without disconnect?

is this related to this issue?

[sagb2015]

@IbrahimMuala - The issue is not related. Moving from one AP to another without disconnection can be done with 802.11r roaming. The support for the same is not added yet. However, with 11kv features you can register to get notified when signal strength from an AP drops to level below certain threshold. The application can ten get list of nearby APs and trigger re-connection with the best candidate if desired.

[AxelLin]

However, with 11kv features you can register to get notified when signal strength from an AP drops to level below certain threshold. The application can ten get list of nearby APs and trigger re-connection with the best candidate if desired.

@sagb2015
If the logic is just to trigger re-connection when reach low rssi threshold,
it even does not need to enable 11kv.
Is there any difference the application needs to take care with or without 11kv support?

[AxelLin]

@AxelLin @AshUK We have discussed the SCAN_DONE event implication for the applications. For internal 11kv scan, we will have additional event added, so that applications can distinguish clearly. Also, for scanning frequency, we will check with different routers with roaming enabled and see the "beacon measurement request" frequency from the AP.

@sagb2015 @kapilkedawat
I'm still waiting for this bug fix for v4.3 (to fix memory leak caused by internal 11kv scan).
Without this fix, it's not possible to enable wifi roaming feature.

[AxelLin]

@sagb2015 @kapilkedawat

If application issues a all channel scan, the wpa supplicant will also receive SIG_SUPPLICANT_SCAN_DONE event.
This side-effect also looks wrong to me.

[AxelLin]

Hi @AxelLin, in that case, scan is issued by AP, you can check whether AP is sending beacon measurement request.

Attached verbose log of frequently scan for reference
wpa.log
.

[AxelLin]

@sagb2015 @kapilkedawat

If application issues a all channel scan, the wpa supplicant will also receive SIG_SUPPLICANT_SCAN_DONE event. This side-effect also looks wrong to me.

I'm also wondering if the app's esp_wifi_scan_stop call will stop the esp_wifi_scan_start called by supplicant if it was scanning in progress.
yet another side-effect?

e.g.
app: to call esp_wifi_scan_start
supplicant: to call esp_wifi_scan_start
app: to call esp_wifi_scan_stop

[AxelLin]

with 11kv features you can register to get notified when signal strength from an AP drops to level below certain threshold. The application can ten get list of nearby APs and trigger re-connection with the best candidate if desired.

@sagb2015 @kapilkedawat
When I got WIFI_EVENT_STA_BSS_RSSI_LOW, I'll try to join an AP with strongest RSSI.
Is there any API to know if other AP with stronger RSSI is available or not (assume 802.11kv is enabled)?
Or I need to do wifi scan again for checking if other AP with stronger RSSI is available?

There is a CONFIG_WPA_SCAN_CACHE setting.
My question is if my application can access the cached scan result to
avoid additional scan when got low RSSI.

The help text for WPA_SCAN_CACHE does not tell what this config is for.
Will scan more quickly if WPA_SCAN_CACHE is set?
What is the user visble difference with and without WPA_SCAN_CACHE set?
What is the benefit of enable WPA_SCAN_CACHE?

[kapilkedawat]

Hi @AxelLin , When station is getting WIFI_EVENT_STA_BSS_RSSI_LOW, most likely scenario is that station has moved from it's previous location. In that case, cached results won't help and preferably you should go for a new scan.

WPA_SCAN_CACHE enables supplicant to store scan result and adds support for scan table. It's more advantageous for AP side when they want to manage the network and can get the saved results from station to move the station accordingly.