[88W9098] DFS cannot change frequency twice?

[martinetd]

Hello,

I'm using the driver from PCIE-WLAN-UART-BT-9098-U16-X86-17.68.1.p136.13-17.26.1.p136.13-MXM5X17366_P3_V0V1-MGPL: wlan: version = PCIE9098--17.68.1.p136.13-MXM5X17366.p3-GPL-(FP68) on the imx8mp-evk running the 5.10.72 kernel release lf-5.10.72-2.2.2

I'm loading the moal driver with ps_mode=2 auto_ds=2, because of another bug on the client side.

Here is my hostapd config:

interface=uap0
hw_mode=a
channel=52
country_code=JP
ssid=NXP_Demo
auth_algs=1
ieee80211n=1
ieee80211d=1
ieee80211h=1
wpa=2
wpa_key_mgmt=WPA-PSK
rsn_pairwise=CCMP
wpa_passphrase=123456789

With this config, I can successfully start hostapd in a DFS-required channel.

I've noticed two problems:

 - when using networkmanager and leaving other interfaces e.g. mlan0 unconfigured, networkmanager will issue regular scans, which cause the DFS mechanism to detect radar occasionally. I was able to reproduce this without NetworkManager on the evk by running this loop `ip link set mlan0 up; while sleep 10; do iw mlan0 scan; done` (in practice the scans done by networkmanager are roughly every 300s, but timing here does not seem to matter)

 - The first detection works successfully and hostapd switches to another frequency, but subsequent detections seem to fail according to logs. The problem is likely that the frequency selected as fallback is not a frequency that requires DFS, so the mechanism does not make sense with it? (I seem to recall it used a dfs-enabled frequency as fallback when I tried earlier with a previous version, but I could not reproduce now)

Here's an excerpt from dmesg+hostapd logs:

root@imx8mpevk:~# hostapd hostapd-dfs.conf 
Configuration file: hostapd-dfs.conf
rfkill: Cannot open RFKILL control device
uap0: interface state UNINITIALIZED->COUNTRY_UPDATE
uap0: interface state COUNTRY_UPDATE->DFS
uap0: DFS-CAC-START freq=5260 chan=52 sec_chan=0, width=0, seg0=0, seg1=0, cac_time=60s
[78872.172930] 11h: issuing DFS Radar check for channel=52.  Please wait for response...
[78872.181029] 11h: Ret ChanRptReq.  Set dfs_check_pending and wait for EVENT_CHANNEL_REPORT.
[78875.183087] CAC check is on going... Blocking Command
[78875.188168] woal_do_scan fails!
[78885.198264] CAC check is on going... Blocking Command
[78885.203350] woal_do_scan fails!
[78895.213527] CAC check is on going... Blocking Command
[78895.218607] woal_do_scan fails!
[78905.228548] CAC check is on going... Blocking Command
[78905.233654] woal_do_scan fails!
[78915.243848] CAC check is on going... Blocking Command
[78915.248941] woal_do_scan fails!
[78925.259262] CAC check is on going... Blocking Command
[78925.264347] woal_do_scan fails!
uap0: DFS-CAC-COMPLETED success=1 freq=5260 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5260 cf2=0
Using interface uap0 with hwaddr 36:6f:24:c0:d0:9f and ssid "NXP_Demo"
[78932.204236] wlan: Starting AP
[78932.210981] wlan: AP started
[78932.213919] IPv6: ADDRCONF(NETDEV_CHANGE): uap0: link becomes ready
[78932.221646] Set AC=3, txop=47 cwmin=3, cwmax=7 aifs=1
[78932.227002] Set AC=2, txop=94 cwmin=7, cwmax=15 aifs=1
[78932.232489] Set AC=0, txop=0 cwmin=15, cwmax=63 aifs=3
[78932.237875] Set AC=1, txop=0 cwmin=15, cwmax=1023 aifs=7
uap0: interface state DFS->ENABLED
uap0: AP-ENABLED 
[78935.274917] wlan: mlan0 START SCAN
[78938.795720] wlan: SCAN COMPLETED: scanned AP count=13
[78948.810888] wlan: mlan0 START SCAN
[78952.330912] wlan: SCAN COMPLETED: scanned AP count=12
[78962.346232] wlan: mlan0 START SCAN
uap0: DFS-RADAR-DETECTED freq=5260 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5260 cf2=0
uap0: DFS-NEW-CHANNEL freq=5240 chan=48 sec_chan=0
[78965.868243] wlan: SCAN COMPLETED: scanned AP count=12
uap0: IEEE 802.11 driver had channel switch: freq=5240, ht=1, vht_ch=0x0, offset=0, width=1 (20 MHz), cf1=5240, cf2=0
uap0: CTRL-EVENT-CHANNEL-SWITCH freq=5240 ht_enabled=1 ch_offset=0 ch_width=20 MHz cf1=5240 cf2=0 dfs=0
uap0: AP-CSA-FINISHED freq=5240 dfs=0
[78965.882337] CSA/ECSA: Switch to new channel 48 complete!
[78975.884349] wlan: mlan0 START SCAN
[78979.405786] wlan: SCAN COMPLETED: scanned AP count=13
[78989.421162] wlan: mlan0 START SCAN
[78992.946316] wlan: SCAN COMPLETED: scanned AP count=11
[79002.961632] wlan: mlan0 START SCAN
uap0: DFS-RADAR-DETECTED freq=5240 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5240 cf2=0
Can't set DFS state for freq 5240 MHz
uap0: DFS-RADAR-DETECTED freq=5240 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5240 cf2=0
Can't set DFS state for freq 5240 MHz
uap0: DFS-RADAR-DETECTED freq=5240 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5240 cf2=0
Can't set DFS state for freq 5240 MHz
uap0: DFS-RADAR-DETECTED freq=5240 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5240 cf2=0
Can't set DFS state for freq 5240 MHz
uap0: DFS-RADAR-DETECTED freq=5240 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5240 cf2=0
Can't set DFS state for freq 5240 MHz
uap0: DFS-RADAR-DETECTED freq=5240 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5240 cf2=0
Can't set DFS state for freq 5240 MHz
[79006.486908] wlan: SCAN COMPLETED: scanned AP count=11
[79016.501871] wlan: mlan0 START SCAN
uap0: DFS-RADAR-DETECTED freq=5240 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5240 cf2=0
Can't set DFS state for freq 5240 MHz
uap0: DFS-RADAR-DETECTED freq=5240 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5240 cf2=0
Can't set DFS state for freq 5240 MHz
uap0: DFS-RADAR-DETECTED freq=5240 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5240 cf2=0
Can't set DFS state for freq 5240 MHz
uap0: DFS-RADAR-DETECTED freq=5240 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5240 cf2=0
Can't set DFS state for freq 5240 MHz
uap0: DFS-RADAR-DETECTED freq=5240 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5240 cf2=0
Can't set DFS state for freq 5240 MHz
[79020.025322] wlan: SCAN COMPLETED: scanned AP count=11
[79030.040347] wlan: mlan0 START SCAN
[79033.561811] wlan: SCAN COMPLETED: scanned AP count=13

Note that for our product we instructed our users to not use the client functionality at the same time as AP, so we will disable the scans issued by networkmanager, but with that in mind:

 - are scans known to trigger DFS radar detection false positive?

 - is it safe to ignore the error shown on further detections? I do not have the hardware to trigger actual radar pulses for testing, so this behavior might actually not be the same with real detections...

Thank you,

--

Dominique Martinet

[weidong_sun]

Dear @martinetd ,

Sorry! I didn't get your points about DFS question before.

So I have to summarize and confirm your questions of DFS again! 

Would you like to confirm it?

===================================================

1. If not starting mlan0 scanning (STA) of 9098

Hostapd can normally perform Radar detection( I know you don't use actual Radar), and it can switch channel to next one, then continue to next detection....

Under the situation, we can assume it is working normally, right?

2. If starting mlan0(STA) scanning at the same time.

From the driver + hostapd logs, at freq=5260 , detection is normal, but when switching to freq=5240, detection can't be continued.

So for hostapd, only the first time is successful. after switching frequency, It seems that subsequent detection failed. 

so you want to know if the log can affect real DFS detection. right?

uap0: DFS-RADAR-DETECTED freq=5240 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5240 cf2=0
Can't set DFS state for freq 5240 MHz

3. your analysis about above question(No.2)

The problem is likely that the frequency selected as fallback is not a frequency that requires DFS, so the mechanism does not make sense with it? (I seem to recall it used a dfs-enabled frequency as fallback when I tried earlier with a previous version, but I could not reproduce now)

Right?

If yes, I will confirm it with internal team.

=================================================

Many thanks!

Regards,

weidong

[martinetd]

Hi @weidong_sun 

Thank you for new attempt, replying one by one:

=====

1. If not starting mlan0 scanning (STA) of 9098

I have not confirmed any detection in this setup yet. I started it just yesterday and the board is indoor so it is likely there is just nothing to detect, so I have nothing to ask about this right now. I will leave it running close to a window later but it is not a priority at this point.

2. If starting mlan0(STA) scanning at the same time.

> so you want to know if the log can affect real DFS detection. right?

Yes. I would not say detection is "normal", but I would like to confirm if this log is safe.

3. your analysis about above question(No.2)

That is just an idea, but yes; perhaps that warning is OK because the frequency is outside of DFS regulated ranges.

=====

On top of this I would like to add this if possible. If that does not look right, let's skip that for now and get feedback on the first three points only.

4. hostapd not returning to configured frequency

In the below log, hostapd correctly switches from 5320 to 5240 on DFS-RADAR-DETECTED event, but does not return to 5320 at the DFS-NOP-FINISHED event

uap0: DFS-RADAR-DETECTED freq=5320 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5320 cf2=0
uap0: DFS-NEW-CHANNEL freq=5240 chan=48 sec_chan=0
[94088.923176] wlan: SCAN COMPLETED: scanned AP count=13
uap0: IEEE 802.11 driver had channel switch: freq=5240, ht=1, vht_ch=0x0, offset=0, width=1 (20 MHz), cf1=5240, cf2=0
uap0: CTRL-EVENT-CHANNEL-SWITCH freq=5240 ht_enabled=1 ch_offset=0 ch_width=20 MHz cf1=5240 cf2=0 dfs=0
uap0: AP-CSA-FINISHED freq=5240 dfs=0
[94089.037532] CSA/ECSA: Switch to new channel 48 complete!
...
uap0: DFS-NOP-FINISHED freq=5320 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5320 cf2=0

Thank you,

Dominique

[weidong_sun]

Hello @martinetd ,

OK, understood!

I shared your feedback with internal team.

Let us wait for feedback.

Regards,

weidong

[weidong_sun]

Dear @martinetd ,

I got feedback from internal team, check it, please!

=======================================

No.1 Feedback
To answer to one of your query from your log -

First time channel was ch52 - which is DFS channel so expected to support DFS detection
fter detection, it moved to channel 48 which is NON DFS, so it is expected to not have any DFS activities.

This is seen in your log -

uap0: DFS-RADAR-DETECTED freq=5260 ht_enabled=1 chan_offset=0 chan_width=1 cf1=5260 cf2=0

uap0: DFS-NEW-CHANNEL freq=5240 chan=48 sec_chan=0

[78965.868243] wlan: SCAN COMPLETED: scanned AP count=12

uap0: IEEE 802.11 driver had channel switch: freq=5240, ht=1, vht_ch=0x0, offset=0, width=1 (20 MHz), cf1=5240, cf2=0

uap0: CTRL-EVENT-CHANNEL-SWITCH freq=5240 ht_enabled=1 ch_offset=0 ch_width=20 MHz cf1=5240 cf2=0 dfs=0

uap0: AP-CSA-FINISHED freq=5240 dfs=0

[78965.882337] CSA/ECSA: Switch to new channel 48 complete!

The second time radar detection when it already on the channel 48 is not expected and could be the corner case problem from sw.
We are looking into it to recreate the same behavior at our end. Please wait for the further updates on this.

No.2 Feedback
We have tried to check the customer behavior at our side, But we didn't see any issue with DFS.
Can you please check how quick customer can see this problem? and occurrence rate?
Please note, we did the same thing that customer tested with scan in looping, so please highlight if we are missing something here.

====================================

Regards,

weidong

[martinetd]

hi @weidong_sun 

Thank you for the feedback!

To answer the questions:

 - I'm not running anything else on the imx8mp-evk at the time, just hostapd in a console and scan loop in another (connecting through ssh over ethernet)

 - These "false radar" usually happen within 10 minutes, although it can be anything from the first scan to about 30 minutes. It's been fairly reliable for me.

 - Running linux kernel lf-5.10.72-2.2.2 with wifi driver/firmware from PCIE-WLAN-UART-BT-9098-U16-X86-17.68.1.p136.13-17.26.1.p136.13-MXM5X17366_P3_V0V1-MGPL ; BSP userspace (hostapd version) also is 5.10.72-2.2.2 from the LF_v5.10.72-2.2.2_images_IMX8MPEVK archive.

Thanks!

[weidong_sun]

Dear @martinetd ,

I got feedback from internal team, they reproduced the issue you reported. see below, please!

==============================

We did more test today and we can see this issue multiple times. This is exact what customer has reported.

We are working internally to get it resolve and will keep you posted further.

==============================

Regards,

weidong

[weidong_sun]

Hello @martinetd ,

I got feedback from internal team, check it, please!

========================================

As per discussion with the internal team, to debug the issue further we need one set of logs from the customer end including the dmesg log with drvdbg=0x2037, hostapd log with debug log enabled, and sniffer capture.

So can you please help to get Logs from the customer?

========================================

Regards,

weidong

[martinetd]

hi @weidong_sun 

I thought they were able to reproduce, could you clarify which part of the issue they want me to trace with logs?

Also, I am not sure what a sniffer capture means in this context, I don't think something like tcpdump would be enough, would it? airodump from another computer? I do not have access to any specific hardware for wireless capture.

Thank you,

Dominique

[weidong_sun]

Hello @martinetd ,

They need 3 logs:

1.  drvdbg=0x2037 log

the parameter should be added when loading drivers, then you will get logs on linux command line.

2. hostapd logs

need to run hostapd with -ddd arguments

3. sniffer logs

you use wireshark software tool to capture Air signals & logs.

Regards,

weidong

[martinetd]

hi @weidong_sun 

I'm sorry but I still do not understand what I should do.

Could you clarify:

1. What part of the problem should I reproduce with logs. The first "scan causes radar" issue?

2. Where should the packet capture be run, on the evk?

Thank you,

Dominique

[weidong_sun]

Hello @martinetd ,

1. how to get debug logs

add drvdbg=0x2037 parameter list when you load wifi driver.

insmod mlan.ko

insmod moal.ko  '...drvdbg=0x2037'

When loading driver is done, copy logs to a file, then send it to me, please!

2. How to get hostapd logs

when you start hostapd service, use the command:

#hostapd -ddd /etc/hostapd.conf

Then copy logs to a file, and send it to me.

3. Sniffer logs

(1)Running wireshark on your PC , and set PC wifi to be monitor mode

(2) Starting your board(probably EVK) with NXP wifi, and connect it to AP

wireshark can capture Air signals between EVK and AP,  then send it to me.

If you are not farmiliar with wireshark software, you can get more information from internet, research it firstly , then use it.

Regards,

weidong

[weidong_sun]

Dear @martinetd ,

See my advice, please! for you reference.

==========================================

I noticed 'woal_do_scan fails!' in logs.

It seems that more than 1 process sends scan command to wifi.

For example:

if wpa_supplicant is running and automatic scan is configured in wpa_supplicant.conf(ap_scan=1 / scan_ssid=1), wpa_supplicant will scan AP with a certain time interval.

if we run 'iw mlan0 scan' at the same time,  2 different scanning requirment source will be sent to wifi driver/firmware, which may cause us to receive scan fails prompts.

================================

Regards,

weidong

[martinetd]

By the way I did get an event after some time without scans/new events (didn't log timestamps):

uap0: DFS-NOP-FINISHED freq=5320 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5320 cf2=0

but hostapd did not move back to the original frequency, is that also expected?

thank you.

[weidong_sun]

Dear @martinetd ,

For the question , the AP will behave as below .

====================

When DFS channel is detected, these actions will be done:

• Stops transmission of data frames on that channel
• Broadcasts an 802.11h channel-switch announcement.
• Disassociates clients
• Selects a different channel from the DCA (Dynamic Channel Assignment) list If the selected
  channel is not DFS then AP enables beacons and accepts client associationsIf the AP selects
  a DFS-required channel, it scans the new channel for radar signals for 60 seconds. If there
  are no radar signals on the new channel, the AP enables beacons and accepts client
  associations. If a radar signal is detected, the AP selects a different channel

======================================

I feel that bove operations of AP can explain your findings.

Hope it is helpful for you.

Regads,

weidong

[martinetd]

hi @weidong_sun 

I am aware of how DFS works; channel switching on first radar event is correct, and I have confirmed it works for us.

However:

 - radar detection due to scan on other interface (another board with the same driver running next to the first one does not detect anything for long periods of time, there has been no radar burst)

 - further detection causing errors

 - not returning to original channel after DFS period is over

all are not expected to me, and not explained in the text you quoted.

Thank you.

[weidong_sun]

Hello @martinetd ,

Can I understand situation on your side like below?

==================

No.1 board for DFS operation is no problem.

No.2 board next to No.1 for DFS operation failed

Right?

==================

Regards,

weidong

[martinetd]

No. I have not confirmed DFS operation working "normally" (through actual radar detection).

- Board 1 not doing scan, no event happening over a few days, hostapd stays on DFS-enabled channel

- Board 2 running the same setup with networkmanager (reproduced with `iw mlan0 scan`), switches to non-DFS channel successfully but there should be no event; then further events error, and does not come back to configured channel after scans are stopped (and no more events) despite "uap0: DFS-NOP-FINISHED freq=5320 ht_enabled=0 chan_offset=0 chan_width=0 cf1=5320 cf2=0" message listing the frequency back (hostapd did not switch to 5320)

There are three problems there:

 - scans generating events

 - further events causing errors

 - hostapd not switching back

Thank you.