88W8997 module disconnect issue (interface PCIE+UART, Host: iMX8MQ), Q2, 24 BSP version + patch

[yao_feng]

Q2, 24 i.mx BSP version + patch
WiFi/BT based version: PCIE-WLAN-UART-BT-8997-LNX_6_6_23-IMX8-16.92.21.p119.3-16.92.21.p119.3-MM6X16437.P21-GPL
reproduce scenario WiFi 2.4G STA connect to a AP and BT playing audio in the meantime.

@Christine_Li 
@ArthurC please help to share logs with us.

[ArthurC]

Hello @Christine_Li ,

The current logs about test are as attached.

There are disconnection occured. 

And we do AP re-connection will cause FW re-loading.

[Christine_Li]

Hi, @ArthurC 

Share today's updates as below:
1. From given logs, I saw the disconnection issue is always occurred after uap0 scan. Because in your project you also need 88W8997 works in AP mode, so it is better we find a way to stop uap0 scanning together. uAP0 scan is not automatically initiated by driver, should received some commands or actions from above layer such as wpa_supplicant or nmcli, so let's try together to find whether have this kind of command to stop uap0 scanning.

2. About the FW reload, you are correct, normally, FW should not do reset without crash.

But in the given logs, it shows that FW reset because of authentication cnt =5. I will check this point internally.

3.I will also check internally about whether we enable uap0 scanning during our local iperf test. If no, I will request our internal team or do it by myself to see whether can reproduce this disconnection issue locally. It will need some time.

Best regards,

Christine.

[Christine_Li]

Hi， @ArthurC 

I found below info for your reference to set uap0 interface unmanaged.

To do so, you could either:

• run nmcli dev set uap0 managed no
• create a conf file in /etc/NetworkManager/conf.d/11-unmanaged-devices.conf containing:

[keyfile]unmanaged-devices=interface-name:uap0

The first option works only while the system is still powered on while the second will make it the standard-setting.

1.Can you please try on you side and let me know whether it works?

2.Have you tried with drv_mode=1 (only load Wi-Fi driver in STA mode) and no load Wi-Fi in AP mode to see whether uap0 has influence on this disconnection issue?

3.Have you tried with wpa_supplicant instead of nmcli to see whether it still have disconnect issue?

Best regards,

Christine.

[Christine_Li]

Hi, @ArthurC 

Sorry, for this issue, we are still under discussion with our internal team.

I just post my questions and findings in your provided logs like below. Now is pending our internal team's feedback.

===========

• For before unmanaged uap0 logs, I have below question:

1.Except for the New activation causing the disconnection, I also see below disconnection, is it normal? Why it has this kind of disconnections?

==========

Line 5538: Jul 31 13:35:47 tbox100 NetworkManager[580]: <info> [1722432947.9881] device (wlan0): state change: activated -> deactivating (reason 'connection-removed', sys-iface-state: 'managed')//Christine

Line 5545: Jul 31 13:35:48 tbox100 wpa_supplicant[801]: wlan0: Request to deauthenticate - bssid=bc:a5:11:ad:03:1a pending_bssid=00:00:00:00:00:00 reason=3 (DEAUTH_LEAVING) state=COMPLETED //Christine

Line 5547: Jul 31 13:35:48 tbox100 wpa_supplicant[801]: wpa_driver_nl80211_deauthenticate(addr=bc:a5:11:ad:03:1a reason_code=3)//Christine

Line 5548: Jul 31 13:35:48 tbox100 kernel: wlan: Received disassociation request on wlan0, reason: 3 //Christine

Line 5550: Jul 31 13:35:48 tbox100 wpa_supplicant[801]: wlan0: Event DEAUTH (11) received //Christine

Line 5551: Jul 31 13:35:48 tbox100 wpa_supplicant[801]: wlan0: Deauthentication notification //Christine

Line 5554: Jul 31 13:35:48 tbox100 wpa_supplicant[801]: wlan0: CTRL-EVENT-DISCONNECTED bssid=bc:a5:11:ad:03:1a reason=3 locally_generated=1 //Christine

• Line 5571: Jul 31 13:35:48 tbox100 wpa_supplicant[801]: wlan0: State: COMPLETED -> DISCONNECTED //Christine

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

Line 33765: Jul 31 14:04:00 tbox100 NetworkManager[580]: <info> [1722434640.9160] device (wlan0): state change: activated -> deactivating (reason 'connection-removed', sys-iface-state: 'managed') //Christine

Line 33766: Jul 31 14:04:00 tbox100 NetworkManager[580]: <info> [1722434640.9211] manager: NetworkManager state is now CONNECTED_LOCAL //Christine

Line 33772: Jul 31 14:04:00 tbox100 wpa_supplicant[801]: wlan0: Request to deauthenticate - bssid=bc:a5:11:ad:03:1a pending_bssid=00:00:00:00:00:00 reason=3 (DEAUTH_LEAVING) state=COMPLETED //Christine

Line 33774: Jul 31 14:04:00 tbox100 wpa_supplicant[801]: wpa_driver_nl80211_deauthenticate(addr=bc:a5:11:ad:03:1a reason_code=3) //Christine

Line 33775: Jul 31 14:04:00 tbox100 kernel: wlan: Received disassociation request on wlan0, reason: 3 //Christine

Line 33776: Jul 31 14:04:00 tbox100 kernel: wlan: REASON: (Deauth) Sending STA is leaving (or has left) IBSS or ESS //Christine

Line 33778: Jul 31 14:04:00 tbox100 wpa_supplicant[801]: wlan0: Deauthentication notification //Christine

Line 33798: Jul 31 14:04:01 tbox100 wpa_supplicant[801]: wlan0: State: COMPLETED -> DISCONNECTED//Christine

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

2.We have Wi-Fi In-band reset because of auth timeout cnt 5, is it normal?

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

Line 16203: Jul 31 13:37:13 tbox100 kernel: WiFi Reset diff 619651202//Christine

Line 16204: Jul 31 13:37:13 tbox100 kernel: WiFi Reset due to auth timeout cnt 5 //Christine

Line 16276: Jul 31 13:37:13 tbox100 kernel: Start to process hanging//Christine

Line 16277: Jul 31 13:37:13 tbox100 kernel: Cancel all pending cmd and txrx queue//Christine

Line 16278: Jul 31 13:37:13 tbox100 kernel: WIFI auto_fw_reload: fw_reload=6 //Christine

Line 16350: Jul 31 13:37:13 tbox100 kernel: ========START IN-BAND RESET=========== //Christine

Line 16351: Jul 31 13:37:13 tbox100 kernel: woal_reset_intf: get bss info failed //Christine

Line 16352: Jul 31 13:37:13 tbox100 kernel: Cancel all pending cmd and txrx queue//Christine

Line 16353: Jul 31 13:37:13 tbox100 kernel: IOCTL failed: 00000000cc3e22ce id=0x80000, sub_id=0x80001 action=2, status_code=0x80000007//Christine

Line 16529: Jul 31 13:37:13 tbox100 wpa_supplicant[801]: wlan0: Request association with bc:a5:11:ad:03:1a//Christine

Line 16924: Jul 31 13:37:13 tbox100 wpa_supplicant[801]: wlan0: SME: Trying to authenticate with bc:a5:11:ad:03:1a (SSID='NETGEAR45' freq=2427 MHz)//Christine

Line 16960: Jul 31 13:37:13 tbox100 wpa_supplicant[801]: nl80211: Authentication request send successfully //Christine

Line 17017: Jul 31 13:37:13 tbox100 wpa_supplicant[801]: nl80211: Drv Event 103 (NL80211_CMD_VENDOR) received for wlan0//Christine

Line 17165: Jul 31 13:37:13 tbox100 wpa_supplicant[801]: nl80211: Interface down (/wlan0)//Christine

Line 17167: Jul 31 13:37:13 tbox100 wpa_supplicant[801]: wlan0: Interface was disabled//Christine

Line 17168: Jul 31 13:37:13 tbox100 wpa_supplicant[801]: wlan0: CTRL-EVENT-DISCONNECTED bssid=bc:a5:11:ad:03:1a reason=3 locally_generated=1//Christine

Line 17174: Jul 31 13:37:13 tbox100 wpa_supplicant[801]: wlan0: State: AUTHENTICATING -> DISCONNECTED//Christine

Line 17205: Jul 31 13:37:13 tbox100 wpa_supplicant[801]: wlan0: State: DISCONNECTED -> INTERFACE_DISABLED //Christine

Line 17318: Jul 31 13:37:13 tbox100 wpa_supplicant[801]: Remove interface wlan0 from radio mwiphy0//Christine

Line 17407: Jul 31 13:37:13 tbox100 kernel: PCIE Trigger FW In-band Reset success.//Christine

Line 17435: Jul 31 13:37:15 tbox100 kernel: wlan: version = PCIE8997--16.92.21.p119.2-MM6X16437.p21-(FP92) //Christine

Line 17436: Jul 31 13:37:15 tbox100 kernel: ========END IN-BAND RESET===========//Christine

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

Line 40460: Jul 31 14:04:43 tbox100 kernel: WiFi Reset due to auth timeout cnt 5//Christine

Line 40461: Jul 31 14:04:43 tbox100 kernel: Start to process hanging//Christine

Line 40462: Jul 31 14:04:43 tbox100 kernel: Cancel all pending cmd and txrx queue//Christine

Line 40533: Jul 31 14:04:43 tbox100 kernel: WIFI auto_fw_reload: fw_reload=6//Christine

Line 40534: Jul 31 14:04:43 tbox100 kernel: ========START IN-BAND RESET===========//Christine

Line 40535: Jul 31 14:04:43 tbox100 kernel: woal_reset_intf: get bss info failed //Christine

Line 40706: Jul 31 14:04:43 tbox100 wpa_supplicant[801]: wlan0: SME: Trying to authenticate with bc:a5:11:ad:03:1a (SSID='NETGEAR45' freq=2427 MHz)//Christine

Line 40741: Jul 31 14:04:43 tbox100 wpa_supplicant[801]: nl80211: Authentication request send successfully//Christine

Line 40771: Jul 31 14:04:43 tbox100 wpa_supplicant[801]: nl80211: Interface down (/wlan0)//Christine

Line 40774: Jul 31 14:04:43 tbox100 wpa_supplicant[801]: wlan0: CTRL-EVENT-DISCONNECTED bssid=bc:a5:11:ad:03:1a reason=3 locally_generated=1//Christine

Line 40780: Jul 31 14:04:43 tbox100 wpa_supplicant[801]: wlan0: State: AUTHENTICATING -> DISCONNECTED//Christine

Line 41024: Jul 31 14:04:43 tbox100 kernel: PCIE Trigger FW In-band Reset success. //Christine

Line 41054: Jul 31 14:04:45 tbox100 kernel: ========END IN-BAND RESET=========== //Christine

• For after unmanaged uap0's logs:
  

There is no wlan0 disconnection shown in "after unmanaged uap0 logs", but customer feedback the iperf shows throughput is 0. And also with "ping" command, it could not ping successfully. It is so strange. What kind of issue should cause this kind of phenomenon?

Best regards,

Christine.

[Christine_Li]

Hi, @ArthurC 

Today I got a chance to discuss with our internal AE team. Please find the below MOM for our today's discussion:

• From the detailed log analysis we could identify the disconnection is initiated from the NetworkManager and not from the NXP driver/fw side. (Attached our elaborate log analysis justifying this behavior in previous comment). 
• To further debug why the NetworkManager is triggering the disconnection and confirm the identified suspect, we need the logs with the "drv_mode=1" driver load parameter to conclude the issue.
• From your shared "after unmanaged uap0" case logs though mentioned you have unmanaged uap0 interface but from the logs we could observe there are activities on-going on the uap0 interface. So please help to use drv_mode=1 to disable the uap0 interface and validate the behavior to confirm if uap0 is impacting the performance of NetworkManager.

And also for your information, we are still actively on this case, we never give up locating why to move forward on the mentioned issue.

Best regards,

Christine.

[Christine_Li]

Hi, @ArthurC 

Just update yesterday's status.

Thanks for corporation to provide us the logs after loading Wi-Fi driver with drv_mod=1.

I paste your provided logs in the attachment and also I have forwarded the latest logs to our internal team. We will analyze it and let you know our analysis ASAP.

Best regards,

Christine.

[Christine_Li]

Hi, @ArthurC 

We had a chance to look into the shared logs and could not observe the disconnection, please find our analysis below:

• Could observe only 1 Connection established
  • Aug 26 09:49:40 tbox100 kernel: wlan: HostMlme wlan0 Connected to bssid bc:XX:XX:XX:03:1a successfully 4-way HS completed and connected with AP 
  • Aug 26 09:49:40 tbox100 wpa_supplicant[809]: wlan0: CTRL-EVENT-CONNECTED - Connection to bc:a5:11:ad:03:1a completed [id=0 id_str=]
• After this Connection is established there is no disconnection in the logs.

So from the logs it looks the AP-STA connection is intact and no disconnection occurs with STA-only mode.

But from your given screenshot and your feedback, the iperf is disconnected and ping could not be successful, I suspect whether it might be causing by the auto deep sleep mode and power saving mode.

1.Can you please help to try with: drv_mode=1, auto_ds=2, ps_mode=2 when loading Wi-Fi driver? Logs request is same like before: dmesg logs and journal logs.

2.If above suggestion is still not working, can you please try with wpa_supplicant instead of network manager? The reason is network manager working above wpa_supplicant, from your previous "before unmanaged uap0", "after unmanaged uap0", and "disable uap0 with drv_mode=1" logs' comparisons, we can see network manager send some commands to wpa_supplicant, then through driver to FW side.

Please do not hesitate to let me know if you have any other concerns.

Best regards,

Christine.

[Christine_Li]

Hi, @ArthurC 

I discussed with our internal team about current status, please see below for our findings and suggestions:

For Before unamanged uap0

• From the logs with drv_mode=1, disconnection is not observed after disabling uap0
  • As per our analysis, the on-going scanning on both the uap0 & wlan0 interface causing the conflicts and impacting the behavior of Network-Manager. For uap0's  and wlan0's scan is from network manager. Please see below logs:
    
    

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

    Jul 31 13:30:13 tbox100 NetworkManager[580]: <info> [1722432613.3086] device (wlan0 set-hw-addr: set MAC address to 4E:CE:F1:5C:D0:35 (scanning)

    Jul 31 13:30:13 tbox100 NetworkManager[580]: <info> [1722432613.3460] device (uap0 set-hw-addr: set MAC address to DE:0C:9E:E9:E0:74 (scanning)

    Jul 31 13:30:13 tbox100 systemd[1]: Starting WPA supplicant...

    Jul 31 13:30:13 tbox100 wpa_supplicant[801]: wpa_supplicant v2.10

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

  • We recommending you to add some delay (more than 10sec) between the uap0 and wlan0 scan to avoid the conflicts on scan operation and unexpected behaviors from Network Manager. You can think about to add this delay in network manager or in wpa_supplicant code, because as per our understanding networkmanager will be using the wpa_supplicant in the back-end. The scan is initiated from the NetworkManager and the driver-fw is just executing the commands received from Application/Utility.

For drv_mode=1 ping issue

• The ping issue observed with disabling the uap0 interface is different from the disconnection issue(original reported).
• Can you please help create a separate case to debug the ping issue and avoid the discrepancy? At the same time, I will for sure to continue to discuss with our internal team about the iperf/ping failed issue after disabled uap0 interface with drv_mode=1. And also about the new logs showing "TX Ring full, can't send anymore packets to firmware" error.

Best regards,

Christine.

[Christine_Li]

Hi, @ArthurC @yao_feng 

As we discussed through Wechat, we will focus on the below scenario:

Disable uap0 with drv_mode=1.

And because after disabled uap0 with drv_mode=1, issue has been different with current case reported Wi-Fi disconnect. To avoid discrepancy, we will track further on the new case:

https://community.nxp.com/t5/Wireless-Connectivity/88W8997-module-iperf-disconnect-and-ping-failed-i...

Let me summarize current case status as below and then will close current case:

1.Before unamanged uap0

On-going scanning on both the uap0 & wlan0 interface causing the conflicts and impacting the behavior of Network-Manager. For uap0's  and wlan0's scan is from network manager. Working flow is like this:

Network manager->Wpa_supplicant->Kernel Driver->Wi-Fi FW.

So our Wi-Fi FW works as a executor. 

We recommending you to add some delay (more than 10sec) between the uap0 and wlan0 scan to avoid the conflicts on scan operation and unexpected behaviors from Network Manager.

2.For after unmanaged uap0 or disable uap0 with drv_mode=1, will track further on above new case. Including below 2 scenarios:

A. with drv_mode=1, auto_ds and ps_mode are default value:

• No disconnection in logs, only iperf disconnection and ping unsuccessfully.

 B. with drv_mode=1, auto_ds=2 ,ps_mode=2:

• Ping is working for the longer duration and after sometime observed "TX Ring full, can't send anymore packets to firmware".

Best regards,

Christine.