WiFi scan while connected

[Remi.G]

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.

[Simonr]

Hi

From the logs and since we can't reproduce this using your configurations in the lab, the problem looks to be due to the environment and not AP configuration. Can you try out this .hex file as well and get the log from it? We've added a few more debug flags to get a better idea of what's going on.

 zephyr_logs_v2.hex

Best regards,

Simon

[Remi.G]

Here are the logs from zephyr_logs_v2.hex

Fullscreen zephyr_logs_v2_log.txt Download

uart:~$
--- 5 messages dropped ---
Starting nrf7002dk with CPU frequency: 128 MHz
[00:00:00.523,864] <dbg> wpa_supp: wpa_printf_impl: wpa_supplicant v2.11-devel
--- 11 messages dropped ---
[00:00:00.524,414] <inf> wifi_supplicant: wpa_supplicant initialized
[00:00:00.525,024] <dbg> wifi_supplicant: add_interface: Adding interface wlan0 [1] (0x200013c0)
[00:00:00.525,085] <dbg> wpa_supp: wpa_printf_impl: Calling wpa_cli: interface_add, argc: 5
[00:00:00.525,146] <dbg> wpa_supp: wpa_printf_impl: argv[0]: interface_add
[00:00:00.525,177] <dbg> wpa_supp: wpa_printf_impl: argv[1]: wlan0
[00:00:00.525,207] <dbg> wpa_supp: wpa_printf_impl: argv[2]: zephyr
[00:00:00.525,238] <dbg> wpa_supp: wpa_printf_impl: argv[3]: zephyr
[00:00:00.525,299] <dbg> wpa_supp: wpa_printf_impl: argv[4]: zephyr
[00:00:00.536,834] <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.539,825] <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.541,473] <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.543,090] <dbg> wpa_supp: wpa_printf_impl: wlan0: RSN: flushing PMKID list in the driver
[00:00:00.543,182] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: DISCONNECTED -> INACTIVE
[00:00:00.543,792] <dbg> wpa_supp: wpa_printf_impl: MBO: Update non-preferred channels, non_pref_chan=N/A
[00:00:00.543,975] <dbg> wpa_supp: wpa_printf_impl: wlan0: Added interface wlan0
[00:00:00.544,067] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: INACTIVE -> DISCONNECTED

uart:~$ wifi scan
Scan requested
uart:~$ debug event 1122  0000  0000
debug event 1127  0001  0000
debug event 1127  0002  0000
debug event 1127  0003  0000
debug event 1127  0004  0000
debug event 1127  0005  0000
debug event 1127  0006  0000
debug event 1127  0007  0000
debug event 1127  0008  0000
debug event 1127  0009  0000
debug event 1127  000a  0000
debug event 1127  000b  0000
debug event 1127  000c  0000
debug event 1127  000d  0000
debug event 1127  000e  0000
debug event 1124  0000  0000
debug event 113000  0000  0000
debug event 113001  0000  0000
debug event 1122  0000  0000
debug event 1127  0024  0000
debug event 1127  0028  0000
debug event 1127  002c  0000
debug event 1127  0030  0000
debug event 1127  0034  0000
debug event 1127  0038  0000
debug event 1127  003c  0000
debug event 1127  0040  0000
debug event 1127  0064  0000
debug event 1127  0068  0000
debug event 1127  006c  0000
debug event 1127  0070  0000
debug event 1127  0074  0000
debug event 1127  0078  0000
debug event 1127  007c  0000
debug event 1127  0080  0000
debug event 1127  0084  0000
debug event 1127  0088  0000
debug event 1127  008c  0000
debug event 1127  0090  0000
debug event 1127  0095  0000
debug event 1127  0099  0000
debug event 1127  009d  0000
debug event 1127  00a1  0000
debug event 1127  00a5  0000
debug event 1127  00a9  0000
debug event 1127  00ad  0000
debug event 1127  00b1  0000
debug event 1124  0000  0000
debug event 113000  0000  0000
debug event 113001  0000  0000

Num  | SSID                             (len) | Chan (Band)   | RSSI | Security        | BSSID             | MFP
1    |                                  0     | 161  (5GHz  ) | -57  | WPA2-PSK        | BA:34:97:AF:71:3D | Disable
2    |                                  0     | 161  (5GHz  ) | -57  | WPA2-PSK        | FC:34:97:AF:71:38 | Disable
3    | Hizzulon                         8     | 44   (5GHz  ) | -57  | WPA2-PSK        | FC:34:97:AF:71:34 | Disable
4    | Hizzulon2                        9     | 7    (2.4GHz) | -62  | WPA2-PSK        | FC:34:97:AF:71:30 | Disable
5    |                                  0     | 44   (5GHz  ) | -76  | WPA2-PSK        | 22:EF:BD:34:5E:DF | Disable
6    | Padres19                         8     | 10   (2.4GHz) | -80  | WPA2-PSK        | BC:9A:8E:33:9A:74 | Optional
7    | ATT5ffDcTA                       10    | 2    (2.4GHz) | -81  | WPA2-PSK        | 74:8A:0D:86:7F:D0 | Optional
8    | Cycle                            5     | 5    (2.4GHz) | -89  | WPA2-PSK        | F0:2F:74:C5:75:F8 | Disable
9    | ATTkuv7HS2_Guest                 16    | 1    (2.4GHz) | -90  | WPA2-PSK        | 5A:60:D8:7C:DD:31 | Optional
10   |                                  0     | 10   (2.4GHz) | -91  | WPA2-PSK        | 3C:A3:08:9E:D7:11 | Disable
Scan request done

uart:~$ wifi connect -s Hizzulon <credentials>
debug event 1122  0000  0000
debug event 1127  0001  0000
Connection requested
--- 87 messages dropped ---
[00:00:22.130,767] <dbg> wpa_supp: wpa_printf_impl: CTRL_IFACE: ENABLE_NETWORK id=0
--- 4 messages dropped ---
[00:00:22.130,889] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 0.000000 sec
[00:00:22.131,103] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: DISCONNECTED -> SCANNING
[00:00:22.131,164] <dbg> wpa_supp: wpa_printf_impl: Scan SSID - hexdump_ascii(len=8):
[00:00:22.131,195] <dbg> wpa_supp: _wpa_hexdump_ascii:
                                   48 69 7a 7a 75 6c 6f 6e                          |Hizzulon
[00:00:22.131,286] <dbg> wpa_supp: wpa_printf_impl: wlan0: Include wildcard SSID in the scan request
[00:00:22.131,500] <dbg> wpa_supp: wpa_printf_impl: wlan0: Add radio work 'scan'@0x20032158
[00:00:22.132,537] <dbg> wpa_supp: wpa_printf_impl: argv[1]: 0
[00:00:22.141,052] <dbg> wpa_supp: wpa_printf_impl: wpa_drv_zep_scan2: Scan requested - scan timeout 35 seconds
[00:00:22.142,730] <dbg> wpa_supp: wpa_printf_impl: wlan0: Control interface command 'SELECT_NETWORK 0'
[00:00:22.142,822] <dbg> wpa_supp: wpa_printf_impl: CTRL_IFACE: SELECT_NETWORK id=0
[00:00:22.142,913] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 0.000000 sec
[00:00:22.143,127] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
[00:00:22.143,218] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
[00:00:22.148,773] <dbg> wifi_supplicant: event_socket_handler: Passing message 47 to wpa_supplicant
[00:00:22.148,864] <dbg> wpa_supp: wpa_printf_impl: wlan0: Event SCAN_STARTED (47) received
[00:00:22.148,986] <dbg> wpa_supp: wpa_printf_impl: wlan0: Own scan request started a scan in 0.007691 seconds
[00:00:22.149,230] <dbg> wpa_supp: wpa_printf_impl: Received len: 24, msg_len:24 - CTRL-EVENT-SCAN-STARTED ->END
uart:~$ debug event 1127  0002  0000
debug event 1127  0003  0000
debug event 1127  0004  0000
debug event 1127  0005  0000
debug event 1127  0006  0000
debug event 1127  0007  0000
debug event 1127  0008  0000
debug event 1127  0009  0000
debug event 1127  000a  0000
debug event 1127  000b  0000
debug event 1127  000c  0000
debug event 1127  000d  0000
debug event 1127  000e  0000
debug event 1124  0000  0000
debug event 113000  0000  0000
debug event 113001  0000  0000
debug event 1122  0000  0000
debug event 1127  0024  0000
debug event 1127  0028  0000
debug event 1127  002c  0000
debug event 1127  0030  0000
debug event 1127  0034  0000
debug event 1127  0038  0000
debug event 1127  003c  0000
debug event 1127  0040  0000
debug event 1127  0064  0000
[00:00:23.143,402] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
[00:00:23.143,524] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
uart:~$ debug event 1127  0068  0000
debug event 1127  006c  0000
debug event 1127  0070  0000
debug event 1127  0074  0000
debug event 1127  0078  0000
debug event 1127  007c  0000
debug event 1127  0080  0000
debug event 1127  0084  0000
[00:00:24.143,768] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
[00:00:24.143,890] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
uart:~$ debug event 1127  0088  0000
debug event 1127  008c  0000
debug event 1127  0090  0000
debug event 1127  0095  0000
debug event 1127  0099  0000
debug event 1127  009d  0000
debug event 1127  00a1  0000
debug event 1127  00a5  0000
[00:00:25.144,073] <dbg> wpa_supp: wpa_printf_impl: wlan0: Already scanning - Reschedule the incoming scan req
[00:00:25.144,195] <dbg> wpa_supp: wpa_printf_impl: wlan0: Setting scan request: 1.000000 sec
uart:~$ debug event 1127  00a9  0000
debug event 1127  00ad  0000
debug event 1127  00b1  0000
debug event 1124  0000  0000
debug event 113000  0000  0000
debug event 113001  0000  0000
--- 44 messages dropped ---
[00:00:26.618,164] <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:26.618,225] <dbg> wpa_supp: wpa_printf_impl: RSN: Set own RSNXE default - hexdump(len=0):  
[00:00:26.618,286] <dbg> wpa_supp: wpa_printf_impl: PSK (set in config) - hexdump(len=32): [REMOVED]
[00:00:26.618,377] <dbg> wpa_supp: wpa_printf_impl: WPA: Set PMK based on external data - hexdump(len=32): [REMOVED]
[00:00:26.618,438] <dbg> wpa_supp: wpa_printf_impl: RRM: Determining whether RRM can be used - device support: 0x50
[00:00:26.618,499] <dbg> wpa_supp: wpa_printf_impl: RRM: Adding RRM IE to Association Request
[00:00:26.619,018] <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:26.619,171] <dbg> wpa_supp: wpa_printf_impl: wlan0: Cancelling scan request
[00:00:26.619,354] <inf> wpa_supp: wlan0: SME: Trying to authenticate with fc:34:97:af:71:34 (SSID='Hizzulon' freq=5220 MHz)
[00:00:26.619,476] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: SCANNING -> AUTHENTICATING
[00:00:26.623,596] <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:26.623,779] <dbg> wpa_supp: wpa_printf_impl: Received len: 24, msg_len:24 - CTRL-EVENT-SCAN-RESULTS ->END
[00:00:26.623,931] <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:26.980,926] <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:26.981,079] <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:26.981,567] <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:26.981,750] <inf> wpa_supp: wlan0: Trying to associate with fc:34:97:af:71:34 (SSID='Hizzulon' freq=5220 MHz)
[00:00:27.026,245] <dbg> wpa_supp: wpa_printf_impl: WPA: KCK - hexdump(len=16): [REMOVED]
[00:00:27.035,064] <dbg> wpa_supp: wpa_printf_impl: wlan0: Cancelling authentication timeout
[00:00:27.035,186] <dbg> wpa_supp: wpa_printf_impl: wlan0: State: GROUP_HANDSHAKE -> COMPLETED
[00:00:27.035,339] <dbg> wpa_supp: wpa_printf_impl: wlan0: Radio work 'sme-connect'@0x20032ca8 done in 0.419464 seconds
[00:00:27.035,491] <dbg> wpa_supp: wpa_printf_impl: wlan0: radio_work_free('sme-connect'@0x20032ca8): num_active_works --> 0
[00:00:27.035,675] <inf> wpa_supp: wlan0: CTRL-EVENT-CONNECTED - Connection to fc:34:97:af:71:34 completed [id=0 id_str=]
[00:00:27.038,818] <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:27.038,970] <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:27.045,471] <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: -57
Beacon Interval: 100
DTIM: 1
TWT: Supported
Current PHY rate : 26000
uart:~$ debug event 214000  0008  0004
[00:00:31.353,851] <dbg> wpa_supp: wpa_printf_impl: wlan0: Control interface command 'SIGNAL_POLL'
[00:00:38.840,667] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Frame event
[00:00:38.840,820] <dbg> wifi_supplicant: event_socket_handler: Passing message 18 to wpa_supplicant
[00:00:38.840,881] <dbg> wpa_supp: wpa_printf_impl: wlan0: Event RX_MGMT (18) received
[00:00:38.841,064] <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:38.841,156] <dbg> wpa_supp: wpa_printf_impl: Measurement request type 5 token 208
[00:00:38.841,217] <dbg> wpa_supp: wpa_printf_impl: Beacon request: invalid operating class 0
[00:00:38.841,247] <dbg> wpa_supp: wpa_printf_impl: Beacon request: No valid channels
[00:00:38.841,339] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Send Action frame (freq=5220 MHz wait=0 ms no_cck=0)
[00:00:38.843,902] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Frame TX status event
[00:00:38.844,055] <dbg> wifi_supplicant: event_socket_handler: Passing message 16 to wpa_supplicant
[00:00:38.844,146] <dbg> wpa_supp: wpa_printf_impl: wlan0: Event TX_STATUS (16) received
[00:00:38.844,299] <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:44
Scan requested
uart:~$ debug event 1122  0000  0000
debug event 112500  0000  0000
debug event 112501  0000  0000
debug event 112502  0000  0000
debug event 1124  0000  0000
debug event 113000  0000  0000
debug event 113001  0000  0000

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

uart:~$ wifi scan -b 5 -c 5:165
Scan requested
uart:~$ debug event 1122  0000  0000
debug event 112500  0000  0000
debug event 112501  0000  0000
debug event 112502  0000  0000
debug event 1124  0000  0000
debug event 113000  0000  0000
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0004
debug event 214000  0008  0002
debug event 214000  0008  0002
debug event 214000  0008  0002
debug event 214000  0008  0002
debug event 214000  0008  0002
debug event 113001  0000  0000
Scan request done
[00:01:09.765,838] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Frame event
[00:01:09.766,021] <dbg> wifi_supplicant: event_socket_handler: Passing message 18 to wpa_supplicant
[00:01:09.766,082] <dbg> wpa_supp: wpa_printf_impl: wlan0: Event RX_MGMT (18) received
[00:01:09.766,296] <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.766,357] <dbg> wpa_supp: wpa_printf_impl: Measurement request type 5 token 212
[00:01:09.766,418] <dbg> wpa_supp: wpa_printf_impl: Beacon request: invalid operating class 0
[00:01:09.766,448] <dbg> wpa_supp: wpa_printf_impl: Beacon request: No valid channels
[00:01:09.766,540] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Send Action frame (freq=5220 MHz wait=0 ms no_cck=0)
[00:01:09.769,104] <dbg> wpa_supp: wpa_printf_impl: wpa_supp: Frame TX status event
[00:01:09.769,256] <dbg> wifi_supplicant: event_socket_handler: Passing message 16 to wpa_supplicant
[00:01:09.769,348] <dbg> wpa_supp: wpa_printf_impl: wlan0: Event TX_STATUS (16) received
[00:01:09.769,500] <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
uart:~$ debug event 1122  0000  0000
debug event 112500  0000  0000
debug event 112501  0000  0000
debug event 112502  0000  0000
debug event 1124  0000  0000
debug event 113000  0000  0000
debug event 214000  0008  0004
debug event 214000  0008  0004
... last line repeats forever

It fails the same as before on channel 165.

One new behavior, which is probably just random chance rather than a difference in this image, is that the first scan on channel 165 in this log completed. But when I scanned the same channel immediately afterwards, it didn't finish. I did multiple runs and could never get it to complete again, so seems a small chance.