Hello,
I think I may have found some bad behaviour in supplicant's handling of dissassoc-imminent
messages. In this case, the AP sends the disassoc-imm message, and supplicant then scans,
finds some APs that match, but then chooses the existing one.
Maybe we should blacklist any AP that tells us disassoc-imm?
My supplicant logs:
1554848476.745848: nl80211: Event message available
1554848476.745903: nl80211: BSS Event 59 (NL80211_CMD_FRAME) received for sta0000
1554848476.745909: nl80211: MLME event 59 (NL80211_CMD_FRAME) on sta0000(04:f0:21:cc:ab:f3) A1=04:f0:21:cc:ab:f3 A2=04:f0:21:5b:ed:35
1554848476.745914: nl80211: MLME event frame - hexdump(len=31): d0 00 3c 00 04 f0 21 cc ab f3 04 f0 21 5b ed 35 04 f0 21 5b ed 35 a0 fd 0a 07 01 04 e8 03 00
1554848476.745920: nl80211: Frame event
1554848476.745923: nl80211: RX frame da=04:f0:21:cc:ab:f3 sa=04:f0:21:5b:ed:35 bssid=04:f0:21:5b:ed:35 freq=5500 ssi_signal=-27 fc=0xd0 seq_ctrl=0xfda0 stype=13
(WLAN_FC_STYPE_ACTION) len=31
1554848476.745931: sta0000: Event RX_MGMT (18) received
1554848476.745949: sta0000: Received Action frame: SA=04:f0:21:5b:ed:35 Category=10 DataLen=6 freq=5500 MHz
1554848476.745956: WNM: RX action 7 from 04:f0:21:5b:ed:35
1554848476.745959: WNM: BSS Transition Management Request: dialog_token=1 request_mode=0x4 disassoc_timer=1000 validity_interval=0
1554848476.745962: sta0000: WNM: Disassociation Imminent - Disassociation Timer 1000
1554848476.745966: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=0 send_len=56
1554848476.745987: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-1\x00
1554848476.745992: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=768 send_len=56
1554848476.746012: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-2\x00
1554848476.746016: Trying to find another BSS
1554848476.746020: sta0000: Setting scan request: 0.000000 sec
1554848476.746026: sta0000: WNM: BSS Transition Management Request did not include candidates
1554848476.746029: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=768 send_len=65
1554848476.746068: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-1\x00
1554848476.746087: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=768 send_len=65
1554848476.746106: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-2\x00
1554848476.746126: WNM: Send BSS Transition Management Response to 04:f0:21:5b:ed:35 dialog_token=1 status=1 reason=0 delay=0
1554848476.746148: nl80211: Send Action frame (ifindex=72, freq=5500 bss->freq=0 MHz wait=0 ms no_cck=0 offchanok=1)
1554848476.746157: nl80211: CMD_FRAME freq=5500 wait=0 no_cck=0 no_ack=0 offchanok=1
1554848476.746162: CMD_FRAME - hexdump(len=29): d0 00 00 00 04 f0 21 5b ed 35 04 f0 21 cc ab f3 04 f0 21 5b ed 35 00 00 0a 08 01 01 00
1554848476.746285: nl80211: Frame TX command accepted; cookie 0x5
1554848476.746319: sta0000: Starting AP scan for wildcard SSID
1554848476.746330: sta0000: Determining shared radio frequencies (max len 1)
1554848476.746336: sta0000: Shared frequencies (len=1): completed iteration
1554848476.746339: sta0000: freq[0]: 5500, flags=0x1
1554848476.746342: sta0000: Scan only the current operating channels since scan_cur_freq is enabled
1554848476.746375: sta0000: trigger-scan, freqs: 0x265ca40
1554848476.746381: sta0000: Add radio work 'scan'@0x26610c0
1554848476.746386: sta0000: First radio work item in the queue - schedule start immediately
1554848476.746403: sta0000: Starting radio work 'scan'@0x26610c0 after 0.000015 second wait
1554848476.746412: sta0000: nl80211: scan request
1554848476.746423: nl80211: Scan SSID
1554848476.746427: nl80211: Scan extra IEs - hexdump(len=12): 7f 08 04 00 0a 02 01 00 00 40 72 00
1554848476.746435: nl80211: Scan frequency 5500 MHz
1554848476.746688: Scan requested (ret=0) - scan timeout 30 seconds
1554848476.746710: sta0000: trigger-scan-cb, assign work: 0x26610c0
1554848476.746732: nl80211: Event message available
1554848476.746748: nl80211: Drv Event 60 (NL80211_CMD_FRAME_TX_STATUS) received for sta0000
1554848476.746759: nl80211: MLME event 60 (NL80211_CMD_FRAME_TX_STATUS) on sta0000(04:f0:21:cc:ab:f3) A1=04:f0:21:5b:ed:35 A2=04:f0:21:cc:ab:f3
1554848476.746768: nl80211: MLME event frame - hexdump(len=29): d0 00 00 00 04 f0 21 5b ed 35 04 f0 21 cc ab f3 04 f0 21 5b ed 35 00 00 0a 08 01 01 00
1554848476.746785: nl80211: Frame TX status event
1554848476.746791: nl80211: Action TX status: cookie=0x5 (match) (ack=1)
1554848476.746805: sta0000: Event TX_STATUS (16) received
1554848476.746830: sta0000: EVENT_TX_STATUS dst=04:f0:21:5b:ed:35 type=0 stype=13
1554848476.746838: Off-channel: Ignore Action TX status - no pending operation
1554848476.746859: nl80211: Event message available
1554848476.746880: nl80211: Drv Event 33 (NL80211_CMD_TRIGGER_SCAN) received for sta0000
1554848476.746896: sta0000: nl80211: Scan trigger
1554848476.746909: sta0000: Event SCAN_STARTED (46) received
1554848476.746916: sta0000: Own scan request started a scan in 0.000207 seconds
1554848476.746922: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=0 send_len=24
1554848476.746943: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-1\x00
1554848476.746946: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=768 send_len=24
1554848476.746952: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-2\x00
1554848477.004658: nl80211: Event message available
1554848477.004715: nl80211: Drv Event 34 (NL80211_CMD_NEW_SCAN_RESULTS) received for sta0000
1554848477.004721: sta0000: nl80211: New scan results available
1554848477.004733: nl80211: Scan probed for SSID ''
1554848477.004740: nl80211: Scan included frequencies: 5500
1554848477.004747: sta0000: Event SCAN_RESULTS (3) received
1554848477.004756: sta0000: Scan completed in 0.257840 seconds
1554848477.004830: nl80211: Received scan results (5 BSSes)
1554848477.004991: nl80211: Scan results indicate BSS status with 04:f0:21:5b:ed:35 as associated
1554848477.005009: sta0000: BSS: Start scan result update 11
1554848477.005024: sta0000: BSS: Add new id 34 BSSID 04:f0:21:e5:df:35 SSID 'routed-AP-11r' freq 5500
1554848477.005030: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=0 send_len=41
1554848477.005047: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-1\x00
1554848477.005050: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=768 send_len=41
1554848477.005056: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-2\x00
1554848477.005063: sta0000: BSS: Add new id 35 BSSID 04:f0:21:30:ea:35 SSID 'routed-AP-11r' freq 5500
1554848477.005069: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=1536 send_len=41
1554848477.005074: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-1\x00
1554848477.005077: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=1536 send_len=41
1554848477.005081: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-2\x00
1554848477.005086: sta0000: BSS: Add new id 36 BSSID 04:f0:21:e9:1a:35 SSID 'routed-AP-11r' freq 5500
1554848477.005090: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=0 send_len=41
1554848477.005094: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-1\x00
1554848477.005096: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=768 send_len=41
1554848477.005122: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-2\x00
1554848477.005126: sta0000: BSS: Add new id 37 BSSID 04:f0:21:ec:16:35 SSID 'routed-AP-11r' freq 5500
1554848477.005130: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=0 send_len=41
1554848477.005134: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-1\x00
1554848477.005136: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=768 send_len=41
1554848477.005138: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-2\x00
1554848477.005142: BSS: last_scan_res_used=5/32
1554848477.005145: sta0000: New scan results available (own=1 ext=0)
1554848477.005148: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=0 send_len=24
1554848477.005152: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-1\x00
1554848477.005154: CTRL-DEBUG: ctrl_sock-sendmsg: sock=5 sndbuf=212992 outq=768 send_len=24
1554848477.005156: CTRL_IFACE monitor sent successfully to /tmp/wpa_ctrl_6734-2\x00
1554848477.005163: sta0000: Remove scan work, work: 0x26610c0 dbg: scan-results
1554848477.005167: sta0000: Radio work 'scan'@0x26610c0 done in 0.258765 seconds
1554848477.005172: sta0000: radio_work_free('scan'@0x26610c0): num_active_works --> 0
1554848477.005176: sta0000: Scan results matching the currently selected network
1554848477.005188: sta0000: 0: 04:f0:21:5b:ed:35 freq=5500 level=-26 snr=77 est_throughput=390001
1554848477.005195: sta0000: 1: 04:f0:21:e5:df:35 freq=5500 level=-27 snr=76 est_throughput=390001
1554848477.005202: sta0000: 2: 04:f0:21:30:ea:35 freq=5500 level=-27 snr=76 est_throughput=390001
1554848477.005207: sta0000: 3: 04:f0:21:e9:1a:35 freq=5500 level=-27 snr=76 est_throughput=390001
1554848477.005212: sta0000: 4: 04:f0:21:ec:16:35 freq=5500 level=-28 snr=75 est_throughput=390001
1554848477.005214: sta0000: Selecting BSS from priority group 0
1554848477.005221: sta0000: 0: 04:f0:21:5b:ed:35 ssid='routed-AP-11r' wpa_ie_len=0 rsn_ie_len=20 caps=0x1111 level=-26 freq=5500
1554848477.005224: sta0000: selected based on RSN IE
1554848477.005227: sta0000: selected BSS 04:f0:21:5b:ed:35 ssid='routed-AP-11r'
Thanks,
Ben
--
Ben Greear <greearb@xxxxxxxxxxxxxxx>
Candela Technologies Inc http://www.candelatech.com
_______________________________________________
Hostap mailing list
Hostap@xxxxxxxxxxxxxxxxxxx
http://lists.infradead.org/mailman/listinfo/hostap
