WiFi scan while connected

Does the NCS stack + nRF7002 support scanning while connected? I would expect it could, to support handoff, but getting errors.

Using nRF7002-DK and NCS 2.8.0.

Compile the wifi/shell example for nrf7002dk/nrf5340/cpuapp, no other changes.

*** Booting nRF Connect SDK v2.8.0-a2386bfc8401 ***
*** Using Zephyr OS v3.7.99-0bc3393fb112 ***
Starting nrf7002dk with CPU frequency: 128 MHz
[00:00:00.532,226] <inf> wifi_supplicant: wpa_supplicant initialized


uart:~$ wifi connect -s Hizzulon <my AP credentials>
Connection requested
Connected
[00:00:19.725,433] <inf> wpa_supp: MBO: Disable MBO/OCE due to misbehaving AP not having enabled PMF
[00:00:19.726,226] <inf> wpa_supp: wlan0: SME: Trying to authenticate with fc:34:97:af:71:54 (SSID='Hizzulon' freq=5220 MHz)
[00:00:20.086,120] <inf> wpa_supp: wlan0: Trying to associate with fc:34:97:af:71:54 (SSID='Hizzulon' freq=5220 MHz)
[00:00:20.102,874] <inf> wpa_supp: wlan0: Associated with fc:34:97:af:71:54
[00:00:20.103,027] <inf> wpa_supp: MBO: Disable MBO/OCE due to misbehaving AP not having enabled PMF
[00:00:20.103,118] <inf> wpa_supp: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
[00:00:20.122,253] <inf> wpa_supp: wlan0: WPA: Key negotiation completed with fc:34:97:af:71:54 [PTK=CCMP GTK=CCMP]
[00:00:20.122,467] <inf> wpa_supp: wlan0: CTRL-EVENT-CONNECTED - Connection to fc:34:97:af:71:54 completed [id=0 id_str=]
[00:00:20.137,420] <inf> net_dhcpv4: Received: 192.168.1.203


uart:~$ wifi status
Status: successful
==================
State: COMPLETED
Interface Mode: STATION
Link Mode: WIFI 6 (802.11ax/HE)
SSID: Hizzulon
BSSID: FC:34:97:AF:71:54
Band: 5GHz
Channel: 44
Security: WPA2-PSK
MFP: Optional
RSSI: -34
Beacon Interval: 100
DTIM: 1
TWT: Supported
Current PHY rate : 26000


uart:~$ wifi scan
Scan requested

[wait ~30 seconds]


Scan request failed (-116)

[wait another ~30 seconds]


[00:01:33.363,311] <err> wifi_nrf: nrf_wifi_fmac_chg_vif_state: RPU is unresponsive for 10 sec
[00:01:33.363,342] <err> wifi_nrf: nrf_wifi_if_stop_zep: nrf_wifi_fmac_chg_vif_state failed
[00:01:33.364,013] <inf> wifi_supplicant: Network interface 1 (0x200013c0) down
[00:01:33.375,396] <inf> wpa_supp: wlan0: CTRL-EVENT-DSCP-POLICY clear_all
[00:01:33.375,854] <inf> wpa_supp: wlan0: CTRL-EVENT-DSCP-POLICY clear_all
[00:01:35.533,050] <inf> wifi_supplicant: Network interface 1 (0x200013c0) up
uart:~$ wifi status
Status: successful
==================
State: DISCONNECTED
uart:~$ 

So the scan fails, but later there's another error that looks like the low-level nRF7002 driver failing and recovering (CONFIG_NRF_WIFI_RPU_RECOVERY is enabled by default).

If scan while connected isn't a supported feature, I would expect it to error immediately, not get into a state where it drops the connection?

A probably related issue: if I issue "wifi connect" with invalid credentials, wifi status is "SCANNING" forever (certainly much longer than the 30 second scan timeout), and later connect requests fail with:

uart:~$ wifi connect <credentials>
Connection requested
[00:01:58.298,828] <inf> wpa_supp: wlan0: CTRL-EVENT-DSCP-POLICY clear_all
[00:01:58.302,124] <inf> wpa_supp: wlan0: Reject scan trigger since one is already pending
[00:01:58.302,246] <wrn> wpa_supp: wlan0: Failed to initiate AP scan
[00:01:58.304,992] <inf> wpa_supp: wlan0: Reject scan trigger since one is already pending
[00:01:58.305,114] <wrn> wpa_supp: wlan0: Failed to initiate AP scan

I need to explicitly do "wifi disconnect" before it will stop scanning and allow another connection. Normally, issuing a connect command while already connected disconnects automatically then initiates the new connection.

Parents
  • Hi Remi

    Today I got hex files from the devs, that has a potential fix to the scan issues at least. Please test them for both the scan and connection issues on your end and report back what you're seeing.

    zephyr (1).hexzephyr_with_logs_enabled.hex

    There should be logging enabled on one of them that might give us an idea of what's wrong if this doesn't fix the problem(s).

    Best regards,

    Simon

  • For the new "zephyr (1).hex" file, same behavior as before, fails scan on channel 165.

    Not including full log here, just the Zephyr header so you can confirm I'm running the expected image, and the command I'm executing:

    *** Booting nRF Connect SDK v2.8.0-caf9929fbaeb ***
    *** Using Zephyr OS v3.7.99-6c5454b22eea ***
    Starting nrf7002dk with CPU frequency: 128 MHz
    [00:00:00.499,359] <inf> wifi_supplicant: wpa_supplicant initialized

    uart:~$ wifi connect -s Hizzulon <credentials>

    ... connects successfully to a 5GHz AP

    uart:~$ wifi scan -b 5 -c 5:44

    ... successful scan

    uart:~$ wifi scan -b 5 -c 5:165

    ... fails scan

    For "zephyr_with_logs_enabled.hex", also same behavior. Here are the logs - there are some dropped messages (including the Zephyr boot banner), though no drops around the scanning. I waited between commands for some of the background periodic wpa_supp messages to appear.

    uart:~$
    --- 5 messages dropped ---
    Starting nrf7002dk with CPU frequency: 128 MHz
    [00:00:00.512,847] <dbg> wpa_supp: wpa_printf_impl: wpa_supplicant v2.11-devel
    --- 11 messages dropped ---
    [00:00:00.513,397] <inf> wifi_supplicant: wpa_supplicant initialized
    [00:00:00.514,007] <dbg> wifi_supplicant: add_interface: Adding interface wlan0 [1] (0x200013c0)
    [00:00:00.514,068] <dbg> wpa_supp: wpa_printf_impl: Calling wpa_cli: interface_add, argc: 5
    [00:00:00.514,099] <dbg> wpa_supp: wpa_printf_impl: argv[0]: interface_add
    [00:00:00.514,160] <dbg> wpa_supp: wpa_printf_impl: argv[1]: wlan0
    [00:00:00.514,190] <dbg> wpa_supp: wpa_printf_impl: argv[2]: zephyr
    [00:00:00.514,221] <dbg> wpa_supp: wpa_printf_impl: argv[3]: zephyr
    [00:00:00.514,251] <dbg> wpa_supp: wpa_printf_impl: argv[4]: zephyr
    [00:00:00.525,848] <dbg> wpa_supp: wpa_printf_impl: _wpa_drv_zep_set_key: priv:0x20002f08 alg 0 addr 0 key_idx 3 set_tx 0 seq 0 seq_len 0 key 0 key_len 0 key_flag 10
    [00:00:00.528,900] <dbg> wpa_supp: wpa_printf_impl: _wpa_drv_zep_set_key: priv:0x20002f08 alg 0 addr 0 key_idx 4 set_tx 0 seq 0 seq_len 0 key 0 key_len 0 key_flag 10
    [00:00:00.530,548] <dbg> wpa_supp: wpa_printf_impl: _wpa_drv_zep_set_key: priv:0x20002f08 alg 0 addr 0 key_idx 5 set_tx 0 seq 0 seq_len 0 key 0 key_len 0 key_flag 10
    [00:00:00.532,196] <dbg> wpa_supp: wpa_printf_impl: wlan0: RSN: flushing PMKID list in the driver
    [00:00:00.532,287] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: DISCONNECTED -> INACTIVE
    [00:00:00.532,897] <dbg> wpa_supp: wpa_printf_impl: MBO: Update non-preferred channels, non_pref_chan=N/A
    [00:00:00.533,081] <dbg> wpa_supp: wpa_printf_impl: wlan0: Added interface wlan0
    [00:00:00.533,172] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: INACTIVE -> DISCONNECTED

    uart:~$ wifi connect -s Hizzulon <credentials>
    Connection requested
    --- 87 messages dropped ---
    [00:00:09.294,036] <dbg> wpa_supp: wpa_printf_impl: CTRL_IFACE: ENABLE_NETWORK id=0
    --- 4 messages dropped ---
    [00:00:09.294,128] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 0.000000 sec
    [00:00:09.294,342] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: DISCONNECTED -> SCANNING
    [00:00:09.294,433] <dbg> wpa_supp: wpa_printf_impl: Scan SSID - hexdump_ascii(len=8):
    [00:00:09.294,464] <dbg> wpa_supp: _wpa_hexdump_ascii:
    48 69 7a 7a 75 6c 6f 6e |Hizzulon
    [00:00:09.294,525] <dbg> wpa_supp: wpa_printf_impl: wlan0: Include wildcard SSID in the scan request
    [00:00:09.294,738] <dbg> wpa_supp: wpa_printf_impl: wlan0: Add radio work 'scan'@0x200329a0
    [00:00:09.295,776] <dbg> wpa_supp: wpa_printf_impl: argv[1]: 0
    [00:00:09.304,046] <dbg> wpa_supp: wpa_printf_impl: wpa_drv_zep_scan2: Scan requested - scan timeout 35 seconds
    [00:00:09.305,175] <dbg> wpa_supp: wpa_printf_impl: wlan0: Control interface command 'SELECT_NETWORK 0'
    [00:00:09.305,236] <dbg> wpa_supp: wpa_printf_impl: CTRL_IFACE: SELECT_NETWORK id=0
    [00:00:09.305,328] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 0.000000 sec
    [00:00:09.305,541] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:09.305,633] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:09.305,847] <dbg> wifi_supplicant: event_socket_handler: Passing message 47 to wpa_supplicant
    [00:00:09.305,938] <dbg> wpa_supp: wpa_printf_impl: wlan0: Event SCAN_STARTED (47) received
    [00:00:09.306,060] <dbg> wpa_supp: wpa_printf_impl: wlan0: Own scan request started a scan in 0.001801 seconds
    [00:00:09.306,304] <dbg> wpa_supp: wpa_printf_impl: Received len: 24, msg_len:24 - CTRL-EVENT-SCAN-STARTED ->END
    [00:00:10.305,847] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:10.305,969] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:11.306,213] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:11.306,304] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:12.306,518] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:12.306,640] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    --- 44 messages dropped ---
    [00:00:13.929,321] <dbg> wpa_supp: wpa_printf_impl: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 80 00
    [00:00:13.929,412] <dbg> wpa_supp: wpa_printf_impl: RSN: Set own RSNXE default - hexdump(len=0):��
    [00:00:13.929,473] <dbg> wpa_supp: wpa_printf_impl: PSK (set in config) - hexdump(len=32): [REMOVED]
    [00:00:13.929,534] <dbg> wpa_supp: wpa_printf_impl: WPA: Set PMK based on external data - hexdump(len=32): [REMOVED]
    [00:00:13.929,595] <dbg> wpa_supp: wpa_printf_impl: RRM: Determining whether RRM can be used - device support: 0x50
    [00:00:13.929,656] <dbg> wpa_supp: wpa_printf_impl: RRM: Adding RRM IE to Association Request
    [00:00:13.930,206] <dbg> wpa_supp: wpa_printf_impl: Added supported operating classes IE - hexdump(len=10): 3b 08 80 51 52 73 76 79 7c 7d
    [00:00:13.930,328] <dbg> wpa_supp: wpa_printf_impl: wlan0: Cancelling scan request
    [00:00:13.930,511] <inf> wpa_supp: wlan0: SME: Trying to authenticate with fc:34:97:af:71:34 (SSID='Hizzulon' freq=5220 MHz)
    [00:00:13.930,633] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: SCANNING -> AUTHENTICATING
    [00:00:13.934,783] <dbg> wpa_supp: wpa_printf_impl: Received len: 40, msg_len:40 - CTRL-EVENT-BSS-ADDED 0 fc:34:97:af:71:34->END
    [00:00:13.934,936] <dbg> wpa_supp: wpa_printf_impl: Received len: 24, msg_len:24 - CTRL-EVENT-SCAN-RESULTS ->END
    [00:00:13.935,119] <dbg> wpa_supp: wpa_printf_impl: Received len: 82, msg_len:82 - SME: Trying to authenticate with fc:34:97:af:71:34 (SSID='Hizzulon' freq=5220 MHz)->END
    --- 2 messages dropped ---
    [00:00:14.291,900] <dbg> wpa_supp: wpa_printf_impl: wlan0: SME: Authentication response: peer=fc:34:97:af:71:34 auth_type=0 auth_transaction=2 status_code=0
    --- 90 messages dropped ---
    [00:00:14.292,083] <dbg> wpa_supp: wpa_printf_impl: SME: Authentication response IEs - hexdump(len=11): dd 09 00 10 18 02 07 00 9c 00 00
    --- 11 messages dropped ---
    [00:00:14.292,510] <dbg> wpa_supp: wpa_printf_impl: SME: Association Request IEs - hexdump(len=52): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 80 00 7f 0b 00 00 0a 02 00 40 40 00 00 00 20 46 05 70 00 00 00 00 3b 08 80 51 52 73 76 79 7c 7d
    [00:00:14.292,694] <inf> wpa_supp: wlan0: Trying to associate with fc:34:97:af:71:34 (SSID='Hizzulon' freq=5220 MHz)
    [00:00:14.337,249] <dbg> wpa_supp: wpa_printf_impl: WPA: KCK - hexdump(len=16): [REMOVED]
    [00:00:14.346,069] <dbg> wpa_supp: wpa_printf_impl: wlan0: Cancelling authentication timeout
    [00:00:14.346,191] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: GROUP_HANDSHAKE -> COMPLETED
    [00:00:14.346,343] <dbg> wpa_supp: wpa_printf_impl: wlan0: Radio work 'sme-connect'@0x200329a0 done in 0.419311 seconds
    [00:00:14.346,496] <dbg> wpa_supp: wpa_printf_impl: wlan0: radio_work_free('sme-connect'@0x200329a0): num_active_works --> 0
    [00:00:14.346,710] <inf> wpa_supp: wlan0: CTRL-EVENT-CONNECTED - Connection to fc:34:97:af:71:34 completed [id=0 id_str=]
    [00:00:14.349,853] <dbg> wpa_supp: wpa_printf_impl: Received len: 73, msg_len:73 - WPA: Key negotiation completed with fc:34:97:af:71:34 [PTK=CCMP GTK=CCMP]->END
    [00:00:14.350,006] <dbg> wpa_supp: wpa_printf_impl: Received len: 79, msg_len:79 - CTRL-EVENT-CONNECTED - Connection to fc:34:97:af:71:34 completed [id=0 id_str=]->END
    [00:00:14.357,330] <inf> net_dhcpv4: Received: 192.168.1.203
    Connected


    uart:~$ wifi status
    Status: successful
    ==================
    State: COMPLETED
    Interface Mode: STATION
    Link Mode: WIFI 6 (802.11ax/HE)
    SSID: Hizzulon
    BSSID: FC:34:97:AF:71:34
    Band: 5GHz
    Channel: 44
    Security: WPA2-PSK
    MFP: Optional
    RSSI: -55
    Beacon Interval: 100
    DTIM: 1
    TWT: Supported
    Current PHY rate : 34400


    [00:00:25.801,727] <dbg> wpa_supp: wpa_printf_impl: wlan0: Control interface command 'SIGNAL_POLL'
    [00:00:26.446,777] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Frame event
    [00:00:26.446,929] <dbg> wifi_supplicant: event_socket_handler: Passing message 18 to wpa_supplicant
    [00:00:26.446,990] <dbg> wpa_supp: wpa_printf_impl: wlan0: Event RX_MGMT (18) received
    [00:00:26.447,204] <dbg> wpa_supp: wpa_printf_impl: wlan0: Received Action frame: SA=fc:34:97:af:71:34 Category=5 DataLen=40 freq=5220 MHz
    [00:00:26.447,265] <dbg> wpa_supp: wpa_printf_impl: Measurement request type 5 token 144
    [00:00:26.447,326] <dbg> wpa_supp: wpa_printf_impl: Beacon request: invalid operating class 0
    [00:00:26.447,357] <dbg> wpa_supp: wpa_printf_impl: Beacon request: No valid channels
    [00:00:26.447,479] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Send Action frame (freq=5220 MHz wait=0 ms no_cck=0)
    [00:00:26.450,073] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Frame TX status event
    [00:00:26.450,225] <dbg> wifi_supplicant: event_socket_handler: Passing message 16 to wpa_supplicant


    uart:~$ wifi scan -b 5 -c 5:44
    Scan requested

    Num | SSID (len) | Chan (Band) | RSSI | Security | BSSID | MFP
    1 | Hizzulon 8 | 44 (5GHz ) | -56 | WPA2-PSK | FC:34:97:AF:71:34 | Disable
    Scan request done


    [00:00:26.450,317] <dbg> wpa_supp: wpa_printf_impl: wlan0: Event TX_STATUS (16) received
    [00:00:26.450,469] <dbg> wpa_supp: wpa_printf_impl: wlan0: EVENT_TX_STATUS dst=fc:34:97:af:71:34 type=0 stype=13
    [00:00:53.480,773] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Frame event
    [00:00:53.480,926] <dbg> wifi_supplicant: event_socket_handler: Passing message 18 to wpa_supplicant
    [00:00:53.481,018] <dbg> wpa_supp: wpa_printf_impl: wlan0: Event RX_MGMT (18) received
    [00:00:53.481,201] <dbg> wpa_supp: wpa_printf_impl: wlan0: Received Action frame: SA=fc:34:97:af:71:34 Category=5 DataLen=40 freq=5220 MHz
    [00:00:53.481,262] <dbg> wpa_supp: wpa_printf_impl: Measurement request type 5 token 150
    [00:00:53.481,323] <dbg> wpa_supp: wpa_printf_impl: Beacon request: invalid operating class 0
    [00:00:53.481,384] <dbg> wpa_supp: wpa_printf_impl: Beacon request: No valid channels
    [00:00:53.481,475] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Send Action frame (freq=5220 MHz wait=0 ms no_cck=0)
    [00:00:53.484,069] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Frame TX status event
    [00:00:53.484,222] <dbg> wifi_supplicant: event_socket_handler: Passing message 16 to wpa_supplicant
    [00:00:53.484,313] <dbg> wpa_supp: wpa_printf_impl: wlan0: Event TX_STATUS (16) received
    [00:00:53.484,466] <dbg> wpa_supp: wpa_printf_impl: wlan0: EVENT_TX_STATUS dst=fc:34:97:af:71:34 type=0 stype=13
    [00:01:09.455,535] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Frame event
    [00:01:09.455,688] <dbg> wifi_supplicant: event_socket_handler: Passing message 18 to wpa_supplicant
    [00:01:09.455,749] <dbg> wpa_supp: wpa_printf_impl: wlan0: Event RX_MGMT (18) received
    [00:01:09.455,963] <dbg> wpa_supp: wpa_printf_impl: wlan0: Received Action frame: SA=fc:34:97:af:71:34 Category=5 DataLen=40 freq=5220 MHz
    [00:01:09.456,024] <dbg> wpa_supp: wpa_printf_impl: Measurement request type 5 token 154
    [00:01:09.456,085] <dbg> wpa_supp: wpa_printf_impl: Beacon request: invalid operating class 0
    [00:01:09.456,115] <dbg> wpa_supp: wpa_printf_impl: Beacon request: No valid channels
    [00:01:09.456,207] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Send Action frame (freq=5220 MHz wait=0 ms no_cck=0)
    [00:01:09.458,831] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Frame TX status event
    [00:01:09.458,984] <dbg> wifi_supplicant: event_socket_handler: Passing message 16 to wpa_supplicant
    [00:01:09.459,075] <dbg> wpa_supp: wpa_printf_impl: wlan0: Event TX_STATUS (16) received
    [00:01:09.459,228] <dbg> wpa_supp: wpa_printf_impl: wlan0: EVENT_TX_STATUS dst=fc:34:97:af:71:34 type=0 stype=13

    uart:~$ wifi scan -b 5 -c 5:165
    Scan requested
    Scan request failed (-116)

    --- 15 messages dropped ---
    [00:02:15.691,192] <dbg> wpa_supp: wpa_printf_impl: wlan0: Removing interface wlan0
    [00:02:15.691,436] <dbg> wpa_supp: wpa_printf_impl: wlan0: Request to deauthenticate - bssid=00:00:00:00:00:00 pending_bssid=00:00:00:00:00:00 reason=3 (DEAUTH_LEAVING) state=INTERFACE_DISABLED
    [00:02:15.691,528] <dbg> wpa_supp: wpa_printf_impl: QM: Clear all active DSCP policies
    [00:02:15.691,589] <inf> wpa_supp: wlan0: CTRL-EVENT-DSCP-POLICY clear_all
    [00:02:15.691,741] <dbg> wpa_supp: wpa_printf_impl: wlan0: WPA: Clear old PMK and PTK
    [00:02:15.691,955] <dbg> wpa_supp: wpa_printf_impl: wlan0: BSS: Remove id 0 BSSID fc:34:97:af:71:34 SSID 'Hizzulon' due to wpa_bss_flush
    [00:02:15.692,138] <dbg> wpa_supp: wpa_printf_impl: wlan0: Cancelling scan request
    [00:02:15.692,230] <dbg> wpa_supp: wpa_printf_impl: wlan0: Cancelling authentication timeout
    [00:02:15.692,382] <dbg> wpa_supp: wpa_printf_impl: QM: Clear all active DSCP policies
    [00:02:15.692,443] <inf> wpa_supp: wlan0: CTRL-EVENT-DSCP-POLICY clear_all
    [00:02:15.692,504] <dbg> wpa_supp: wpa_printf_impl: Remove interface wlan0 from radio
    [00:02:15.692,535] <dbg> wpa_supp: wpa_printf_impl: Remove radio
    [00:02:17.848,602] <inf> wifi_supplicant: Network interface 1 (0x200013c0) up
    --- 4 messages dropped ---
    [00:02:17.848,632] <dbg> wifi_supplicant: add_interface: Adding interface wlan0 [1] (0x200013c0)
    [00:02:17.848,693] <dbg> wpa_supp: wpa_printf_impl: Calling wpa_cli: interface_add, argc: 5
    --- 5 messages dropped ---
    [00:02:17.848,724] <dbg> wpa_supp: wpa_printf_impl: argv[0]: interface_add
    [00:02:17.848,785] <dbg> wpa_supp: wpa_printf_impl: argv[1]: wlan0
    [00:02:17.848,815] <dbg> wpa_supp: wpa_printf_impl: argv[2]: zephyr
    [00:02:17.848,846] <dbg> wpa_supp: wpa_printf_impl: argv[3]: zephyr
    [00:02:17.848,876] <dbg> wpa_supp: wpa_printf_impl: argv[4]: zephyr
    [00:02:17.851,959] <dbg> wpa_supp: wpa_printf_impl: RX global ctrl_iface - hexdump_ascii(len=71):
    [00:02:17.857,635] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Added 802.11b mode based on 802.11g information
    [00:02:17.863,098] <dbg> wpa_supp: wpa_printf_impl: _wpa_drv_zep_set_key: priv:0x20002f08 alg 0 addr 0 key_idx 3 set_tx 0 seq 0 seq_len 0 key 0 key_len 0 key_flag 10
    [00:02:17.866,058] <dbg> wpa_supp: wpa_printf_impl: _wpa_drv_zep_set_key: priv:0x20002f08 alg 0 addr 0 key_idx 4 set_tx 0 seq 0 seq_len 0 key 0 key_len 0 key_flag 10
    [00:02:17.867,706] <dbg> wpa_supp: wpa_printf_impl: _wpa_drv_zep_set_key: priv:0x20002f08 alg 0 addr 0 key_idx 5 set_tx 0 seq 0 seq_len 0 key 0 key_len 0 key_flag 10
    [00:02:17.869,323] <dbg> wpa_supp: wpa_printf_impl: wlan0: RSN: flushing PMKID list in the driver
    [00:02:17.869,415] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: DISCONNECTED -> INACTIVE
    [00:02:17.870,025] <dbg> wpa_supp: wpa_printf_impl: MBO: Update non-preferred channels, non_pref_chan=N/A
    [00:02:17.870,208] <dbg> wpa_supp: wpa_printf_impl: wlan0: Added interface wlan0
    [00:02:17.870,300] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: INACTIVE -> DISCONNECTED
    uart:~$

    For the 2.4GHz connection failure, here are the logs, in case they help:

    uart:~$ wifi connect -s Hizzulon2 -p H1zzul0n -k 1
    Connection requested
    --- 87 messages dropped ---
    [00:00:08.492,462] <dbg> wpa_supp: wpa_printf_impl: CTRL_IFACE: ENABLE_NETWORK id=0
    --- 4 messages dropped ---
    [00:00:08.492,553] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 0.000000 sec
    [00:00:08.492,797] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: DISCONNECTED -> SCANNING
    [00:00:08.492,858] <dbg> wpa_supp: wpa_printf_impl: Scan SSID - hexdump_ascii(len=9):
    [00:00:08.492,889] <dbg> wpa_supp: _wpa_hexdump_ascii:
    48 69 7a 7a 75 6c 6f 6e 32 |Hizzulon 2
    [00:00:08.492,980] <dbg> wpa_supp: wpa_printf_impl: wlan0: Include wildcard SSID in the scan request
    [00:00:08.493,194] <dbg> wpa_supp: wpa_printf_impl: wlan0: Add radio work 'scan'@0x200329a0
    [00:00:08.494,232] <dbg> wpa_supp: wpa_printf_impl: argv[1]: 0
    [00:00:08.503,051] <dbg> wpa_supp: wpa_printf_impl: wpa_drv_zep_scan2: Scan requested - scan timeout 35 seconds
    [00:00:08.504,150] <dbg> wpa_supp: wpa_printf_impl: wlan0: Control interface command 'SELECT_NETWORK 0'
    [00:00:08.504,241] <dbg> wpa_supp: wpa_printf_impl: CTRL_IFACE: SELECT_NETWORK id=0
    [00:00:08.504,333] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 0.000000 sec
    [00:00:08.504,547] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:08.504,638] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:08.504,852] <dbg> wifi_supplicant: event_socket_handler: Passing message 47 to wpa_supplicant
    [00:00:08.504,943] <dbg> wpa_supp: wpa_printf_impl: wlan0: Event SCAN_STARTED (47) received
    [00:00:08.505,065] <dbg> wpa_supp: wpa_printf_impl: wlan0: Own scan request started a scan in 0.001801 seconds
    [00:00:08.505,310] <dbg> wpa_supp: wpa_printf_impl: Received len: 24, msg_len:24 - CTRL-EVENT-SCAN-STARTED ->END
    [00:00:09.504,882] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:09.505,004] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:10.505,218] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:10.505,340] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:11.505,523] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:11.505,645] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:12.505,859] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:12.505,981] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:13.506,164] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:13.506,286] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:14.506,500] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:14.506,622] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:15.506,805] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:15.506,927] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:16.507,141] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:16.507,263] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:17.507,446] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:17.507,568] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:18.507,751] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:18.507,873] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:19.508,056] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:19.508,178] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:20.508,392] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:20.508,514] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:21.508,697] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:21.508,819] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:22.509,033] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:22.509,155] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:23.509,338] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:23.509,460] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:24.509,643] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:24.509,765] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:25.510,009] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:25.510,101] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:26.510,284] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:26.510,406] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:27.510,650] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:27.510,772] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:28.510,986] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:28.511,108] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:29.511,291] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:29.511,413] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:30.511,627] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:30.511,749] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:31.511,932] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:31.512,054] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:32.512,237] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:32.512,359] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:33.512,603] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:33.512,695] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:34.512,878] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:34.513,000] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:35.513,244] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:35.513,366] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    [00:00:36.513,580] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
    [00:00:36.513,702] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
    --- 43 messages dropped ---
    [00:00:38.514,984] <dbg> wpa_supp: wpa_printf_impl: WPA: Set own WPA IE default - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 80 00
    [00:00:38.515,075] <dbg> wpa_supp: wpa_printf_impl: RSN: Set own RSNXE default - hexdump(len=0):(ďż˝
    [00:00:38.515,136] <dbg> wpa_supp: wpa_printf_impl: PSK (set in config) - hexdump(len=32): [REMOVED]
    [00:00:38.515,197] <dbg> wpa_supp: wpa_printf_impl: WPA: Set PMK based on external data - hexdump(len=32): [REMOVED]
    [00:00:38.515,258] <dbg> wpa_supp: wpa_printf_impl: RRM: Determining whether RRM can be used - device support: 0x50
    [00:00:38.515,319] <dbg> wpa_supp: wpa_printf_impl: RRM: Adding RRM IE to Association Request
    [00:00:38.515,838] <dbg> wpa_supp: wpa_printf_impl: Added supported operating classes IE - hexdump(len=10): 3b 08 51 51 52 73 76 79 7c 7d
    [00:00:38.515,960] <dbg> wpa_supp: wpa_printf_impl: wlan0: Cancelling scan request
    [00:00:38.516,174] <inf> wpa_supp: wlan0: SME: Trying to authenticate with fc:34:97:af:71:30 (SSID='Hizzulon2' freq=2442 MHz)
    [00:00:38.516,296] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: SCANNING -> AUTHENTICATING
    [00:00:38.520,446] <dbg> wpa_supp: wpa_printf_impl: Received len: 40, msg_len:40 - CTRL-EVENT-BSS-ADDED 0 fc:34:97:af:71:30->END
    [00:00:38.520,599] <dbg> wpa_supp: wpa_printf_impl: Received len: 24, msg_len:24 - CTRL-EVENT-SCAN-RESULTS ->END
    [00:00:38.520,751] <dbg> wpa_supp: wpa_printf_impl: Received len: 83, msg_len:83 - SME: Trying to authenticate with fc:34:97:af:71:30 (SSID='Hizzulon2' freq=2442 MHz)->END
    --- 2 messages dropped ---
    [00:00:43.522,491] <dbg> wpa_supp: wpa_printf_impl: wlan0: radio_work_free('sme-connect'@0x200329a0): num_active_works --> 0
    [00:00:43.522,583] <dbg> wpa_supp: wpa_printf_impl: Added BSSID fc:34:97:af:71:30 into ignore list, ignoring for 10 seconds
    [00:00:43.522,705] <dbg> wpa_supp: wpa_printf_impl: wlan0: Consecutive connection failures: 1 --> request scan in 100 ms
    [00:00:43.522,827] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 0.100000 sec
    [00:00:43.522,949] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: AUTHENTICATING -> DISCONNECTED
    [00:00:43.623,016] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: DISCONNECTED -> SCANNING
    [00:00:43.623,107] <dbg> wpa_supp: wpa_printf_impl: wlan0: Starting AP scan for wildcard SSID
    [00:00:43.623,321] <dbg> wpa_supp: wpa_printf_impl: wlan0: Add radio work 'scan'@0x20032348
    [00:00:43.623,474] <dbg> wpa_supp: wpa_printf_impl: wlan0: First radio work item in the queue - schedule start immediately
    [00:00:43.623,718] <dbg> wpa_supp: wpa_printf_impl: wlan0: Starting radio work 'scan'@0x20032348 after 0.000214 second wait
    [00:00:43.626,159] <dbg> wpa_supp: wpa_printf_impl: wpa_drv_zep_scan2: Scan requested - scan timeout 35 seconds
    [00:00:46.530,639] <dbg> wifi_supplicant: event_socket_handler: Passing message 11 to wpa_supplicant
    [00:00:46.530,731] <dbg> wpa_supp: wpa_printf_impl: wlan0: Event DEAUTH (11) received
    [00:00:46.530,822] <dbg> wpa_supp: wpa_printf_impl: wlan0: Deauthentication notification
    [00:00:46.530,914] <dbg> wpa_supp: wpa_printf_impl: wlan0: * reason 3 (DEAUTH_LEAVING)
    [00:00:46.531,036] <dbg> wpa_supp: wpa_printf_impl: wlan0: * address f4:ce:36:00:23:2c
    [00:00:46.531,097] <dbg> wpa_supp: wpa_printf_impl: Deauthentication frame IE(s) - hexdump(len=0): [NULL]
    [00:00:46.531,219] <dbg> wpa_supp: wpa_printf_impl: wlan0: Auto connect enabled: try to reconnect (wps=0/0 wpa_state=3)
    [00:00:46.531,311] <dbg> wpa_supp: wpa_printf_impl: wlan0: Do not request new immediate scan
    [00:00:46.531,402] <dbg> wpa_supp: wpa_printf_impl: wlan0: WPA: Clear old PMK and PTK
    [00:00:46.531,524] <dbg> wpa_supp: wpa_printf_impl: wlan0: Disconnect event - remove keys
    [00:00:46.531,646] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: SCANNING -> DISCONNECTED
    --- 3 messages dropped ---
    [00:01:13.628,845] <dbg> wpa_supp: wpa_printf_impl: 00:00:00:00:00:00 freq=0 qual=0 noise=-89 level=0 flags=0x7 age=0 est=0
    [00:01:13.628,906] <dbg> wpa_supp: wpa_printf_impl: wlan0: BSS: Start scan result update 2
    [00:01:13.629,058] <dbg> wpa_supp: wpa_printf_impl: wlan0: BSS: No SSID IE included for 00:00:00:00:00:00
    [00:01:13.629,119] <dbg> wpa_supp: wpa_printf_impl: BSS: last_scan_res_used=0/32
    [00:01:13.629,211] <dbg> wpa_supp: wpa_printf_impl: wlan0: New scan results available (own=0 ext=0)
    [00:01:13.629,425] <dbg> wpa_supp: wpa_printf_impl: wlan0: Radio work 'scan'@0x20032348 done in 30.005706 seconds
    [00:01:13.629,577] <dbg> wpa_supp: wpa_printf_impl: wlan0: radio_work_free('scan'@0x20032348): num_active_works --> 0
    [00:01:13.629,669] <dbg> wpa_supp: wpa_printf_impl: wlan0: No suitable network found
    [00:01:13.629,760] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 5.000000 sec
    [00:01:13.630,035] <dbg> wpa_supp: wpa_printf_impl: Received len: 24, msg_len:24 - CTRL-EVENT-SCAN-RESULTS ->END
    [00:01:13.630,187] <dbg> wpa_supp: wpa_printf_impl: Received len: 29, msg_len:29 - CTRL-EVENT-NETWORK-NOT-FOUND ->END
    [00:01:18.629,974] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: DISCONNECTED -> SCANNING
    [00:01:18.630,065] <dbg> wpa_supp: wpa_printf_impl: Scan SSID - hexdump_ascii(len=9):
    [00:01:18.630,065] <dbg> wpa_supp: _wpa_hexdump_ascii:
    48 69 7a 7a 75 6c 6f 6e 32 |Hizzulon 2
    [00:01:18.630,157] <dbg> wpa_supp: wpa_printf_impl: wlan0: Include wildcard SSID in the scan request
    [00:01:18.630,371] <dbg> wpa_supp: wpa_printf_impl: wlan0: Add radio work 'scan'@0x20032c88
    [00:01:18.630,493] <dbg> wpa_supp: wpa_printf_impl: wlan0: First radio work item in the queue - schedule start immediately
    [00:01:18.630,737] <dbg> wpa_supp: wpa_printf_impl: wlan0: Starting radio work 'scan'@0x20032c88 after 0.000214 second wait
    [00:01:18.633,605] <dbg> wpa_supp: wpa_printf_impl: wpa_drv_zep_scan2: Scan requested - scan timeout 35 seconds
    uart:~$

  • It sounds like you have not been able to reproduce this locally. I'm attaching an exported configuration from my Asus ZenMax WiFi XT8 (AX6600) (running current latest firmware 3.0.0.4.388_24688-gf94212b) in case that helps. 

    I haven't tried loading an external config, but if you connect to the web interface, Administration, Restore/Save/Upload Setting tab, there is a button to upload a configuration.

    If it works, there will be a 2.4GHz network "Hizzulon2" and a 5GHz network "Hizzulon". I didn't export the passwords so you will probably have to set those.

    There are also some mesh configs, but it should be fine if there's no mesh to connect to.

    Settings_ZenWiFi AX.CFG

Reply
  • It sounds like you have not been able to reproduce this locally. I'm attaching an exported configuration from my Asus ZenMax WiFi XT8 (AX6600) (running current latest firmware 3.0.0.4.388_24688-gf94212b) in case that helps. 

    I haven't tried loading an external config, but if you connect to the web interface, Administration, Restore/Save/Upload Setting tab, there is a button to upload a configuration.

    If it works, there will be a 2.4GHz network "Hizzulon2" and a 5GHz network "Hizzulon". I didn't export the passwords so you will probably have to set those.

    There are also some mesh configs, but it should be fine if there's no mesh to connect to.

    Settings_ZenWiFi AX.CFG

Children
No Data
Related