Hello,
I am seeing a consistent failure of wpa_supplicant v2.7 to attempt association with secondary BSSes after association with the selected BSS times out. I expect wpa_supplicant to blacklist the failed BSS, and attempt a connection to each other BSSs in the same ESS, but this doesn't seem to be happening.
This is the v2.7 wpa_supplicant release, built by buildroot 2019.02.1.
Full debug log at the end, but here are the significant events as I see them:
1) wpa_s sees multiple BSS for selected ESS:
wlan0: Scan results matching the currently selected network
wlan0: 1: f2:9f:c2:3a:da:1c freq=2437 level=-45 snr=44 est_throughput=65000
wlan0: 3: f2:9f:c2:71:f4:4c freq=2412 level=-50 snr=39 est_throughput=65000
wlan0: 11: f2:9f:c2:34:b2:f0 freq=2462 level=-66 snr=23 est_throughput=58500
2) wpa_s chooses a BSS:
wlan0: Considering connect request: reassociate: 1 selected: f2:9f:c2:3a:da:1c bssid: 00:00:00:00:00:00 pending: 00:00:00:00:00:00 wpa_state: INACTIVE ssid=0x9fd08 current_ssid=0x9fd08
wlan0: Request association with f2:9f:c2:3a:da:1c
3) authentication succeeds:
wlan0: SME: Trying to authenticate with f2:9f:c2:3a:da:1c (SSID='Sense' freq=2437 MHz)
[...]
wlan0: State: INACTIVE -> AUTHENTICATING
[...]
wlan0: Event AUTH (10) received
wlan0: SME: Authentication response: peer=f2:9f:c2:3a:da:1c auth_type=0 auth_transaction=2 status_code=0
SME: Association Request IEs - hexdump(len=39): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00 7f 08 04 00 00 00 00 00 00 40 3b 05 51 51 52 53 54
wlan0: Trying to associate with f2:9f:c2:3a:da:1c (SSID='Sense' freq=2437 MHz)
wlan0: State: AUTHENTICATING -> ASSOCIATING
4) association times out:
nl80211: Association request send successfully
dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0
nl80211: Drv Event 20 (NL80211_CMD_DEL_STATION) received for wlan0
nl80211: Delete station f2:9f:c2:3a:da:1c
nl80211: Drv Event 38 (NL80211_CMD_ASSOCIATE) received for wlan0
nl80211: MLME event 38; timeout with f2:9f:c2:3a:da:1c
wlan0: Event ASSOC_TIMED_OUT (14) received
5) wpa_s blacklists BSS, and talks about associating with other BSS in the same ESS:
Added BSSID f2:9f:c2:3a:da:1c into blacklist
wlan0: Another BSS in this ESS has been seen; try it next
BSSID f2:9f:c2:3a:da:1c blacklist count incremented to 2
... however no further association attempts are made. A scan request is made, but no action is taken on the results.
Full wpa_supplicant -d log follows. Any help would be much appreciated.
Best,
Jonah
Dec 21 18:53:44 wpa_supplicant v2.7
Dec 21 18:53:44 random: Trying to read entropy from /dev/random
Dec 21 18:53:44 dbus: Register D-Bus object '/fi/w1/wpa_supplicant1'
Dec 21 18:53:44 Providing DBus service 'fi.w1.wpa_supplicant1'.
Dec 21 18:53:44 Successfully initialized wpa_supplicant
Dec 21 18:53:44 random: Got 20/20 bytes from /dev/random
Dec 21 18:53:45 RTM_NEWLINK: ifi_index=3 ifname=wlan0 operstate=0 linkmode=0 ifi_family=0 ifi_flags=0x9043 ([UP][RUNNING])
Dec 21 18:53:45 RTM_NEWLINK: ifi_index=3 ifname=wlan0 operstate=2 linkmode=0 ifi_family=0 ifi_flags=0x9003 ([UP])
Dec 21 18:53:45 Initializing interface 'wlan0' conf 'N/A' driver 'nl80211,wext' ctrl_interface 'N/A' bridge 'N/A'
Dec 21 18:53:45 nl80211: Supported cipher 00-0f-ac:1
Dec 21 18:53:45 nl80211: Supported cipher 00-0f-ac:5
Dec 21 18:53:45 nl80211: Supported cipher 00-0f-ac:2
Dec 21 18:53:45 nl80211: Supported cipher 00-0f-ac:4
Dec 21 18:53:45 nl80211: Supported cipher 00-14-72:1
Dec 21 18:53:45 nl80211: Supports Probe Response offload in AP mode
Dec 21 18:53:45 nl80211: Using driver-based off-channel TX
Dec 21 18:53:45 nl80211: Driver-advertised extended capabilities (default) - hexdump(len=8): 04 00 00 00 00 00 00 40
Dec 21 18:53:45 nl80211: Driver-advertised extended capabilities mask (default) - hexdump(len=8): 04 00 00 00 00 00 00 40
Dec 21 18:53:45 nl80211: Supported vendor command: vendor_id=0x80028 subcmd=0
Dec 21 18:53:45 nl80211: Supported vendor command: vendor_id=0x80028 subcmd=1
Dec 21 18:53:45 nl80211: Supported vendor command: vendor_id=0x80028 subcmd=2
Dec 21 18:53:45 nl80211: Supported vendor event: vendor_id=0x80028 subcmd=0
Dec 21 18:53:45 nl80211: Supported vendor event: vendor_id=0x80028 subcmd=1
Dec 21 18:53:45 nl80211: Use separate P2P group interface (driver advertised support)
Dec 21 18:53:45 nl80211: Enable multi-channel concurrent (driver advertised support)
Dec 21 18:53:45 nl80211: use P2P_DEVICE support
Dec 21 18:53:45 nl80211: interface wlan0 in phy phy0
Dec 21 18:53:45 nl80211: Set mode ifindex 3 iftype 2 (STATION)
Dec 21 18:53:45 nl80211: Subscribe to mgmt frames with non-AP handle 0x94e98
Dec 21 18:53:45 nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x94e98 match=06
Dec 21 18:53:45 nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x94e98 match=0a07
Dec 21 18:53:45 nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x94e98 match=0a11
Dec 21 18:53:45 nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x94e98 match=1101
Dec 21 18:53:45 nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x94e98 match=1102
Dec 21 18:53:45 nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x94e98 match=0505
Dec 21 18:53:45 nl80211: Register frame type=0xd0 (WLAN_FC_STYPE_ACTION) nl_handle=0x94e98 match=0500
Dec 21 18:53:45 rfkill: Cannot open RFKILL control device
Dec 21 18:53:45 nl80211: RFKILL status not available
Dec 21 18:53:45 netlink: Operstate: ifindex=3 linkmode=1 (userspace-control), operstate=5 (IF_OPER_DORMANT)
Dec 21 18:53:45 Add interface wlan0 to a new radio phy0
Dec 21 18:53:45 nl80211: Regulatory information - country=00
Dec 21 18:53:45 nl80211: 2402-2472 @ 40 MHz 20 mBm
Dec 21 18:53:45 nl80211: 2457-2482 @ 20 MHz 20 mBm (no IR)
Dec 21 18:53:45 nl80211: 2474-2494 @ 20 MHz 20 mBm (no OFDM) (no IR)
Dec 21 18:53:45 nl80211: 5170-5250 @ 80 MHz 20 mBm (no IR)
Dec 21 18:53:45 nl80211: 5250-5330 @ 80 MHz 20 mBm (DFS) (no IR)
Dec 21 18:53:45 nl80211: 5490-5730 @ 160 MHz 20 mBm (DFS) (no IR)
Dec 21 18:53:45 nl80211: 5735-5835 @ 80 MHz 20 mBm (no IR)
Dec 21 18:53:45 nl80211: 57240-63720 @ 2160 MHz 0 mBm
Dec 21 18:53:45 nl80211: Added 802.11b mode based on 802.11g information
Dec 21 18:53:45 wlan0: Own MAC address: 98:7b:f3:c6:82:55
Dec 21 18:53:45 wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=(nil) key_idx=0 set_tx=0 seq_len=0 key_len=0
Dec 21 18:53:45 wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=(nil) key_idx=1 set_tx=0 seq_len=0 key_len=0
Dec 21 18:53:45 wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=(nil) key_idx=2 set_tx=0 seq_len=0 key_len=0
Dec 21 18:53:45 wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=(nil) key_idx=3 set_tx=0 seq_len=0 key_len=0
Dec 21 18:53:45 wlan0: RSN: flushing PMKID list in the driver
Dec 21 18:53:45 nl80211: Flush PMKIDs
Dec 21 18:53:45 wlan0: State: DISCONNECTED -> INACTIVE
Dec 21 18:53:45 EAPOL: SUPP_PAE entering state DISCONNECTED
Dec 21 18:53:45 EAPOL: Supplicant port status: Unauthorized
Dec 21 18:53:45 nl80211: Skip set_supp_port(unauthorized) while not associated
Dec 21 18:53:45 EAPOL: KEY_RX entering state NO_KEY_RECEIVE
Dec 21 18:53:45 EAPOL: SUPP_BE entering state INITIALIZE
Dec 21 18:53:45 EAP: EAP entering state DISABLED
Dec 21 18:53:45 dbus: Register interface object '/fi/w1/wpa_supplicant1/Interfaces/0'
Dec 21 18:53:45 wlan0: Added interface wlan0
Dec 21 18:53:45 wlan0: State: INACTIVE -> DISCONNECTED
Dec 21 18:53:45 nl80211: Set wlan0 operstate 0->0 (DORMANT)
Dec 21 18:53:45 netlink: Operstate: ifindex=3 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
Dec 21 18:53:45 RTM_NEWLINK: ifi_index=3 ifname=wlan0 operstate=2 linkmode=1 ifi_family=0 ifi_flags=0x9003 ([UP])
Dec 21 18:53:45 wlan0: Setting scan request: 0.000000 sec
Dec 21 18:53:45 no property handler for fi.w1.wpa_supplicant1.Interface.P2PDevice.P2PDeviceConfig on /fi/w1/wpa_supplicant1/Interfaces/0
Dec 21 18:53:45 wlan0: State: DISCONNECTED -> SCANNING
Dec 21 18:53:45 wlan0: Starting AP scan for wildcard SSID
Dec 21 18:53:45 wlan0: Add radio work 'scan'@0x91dd0
Dec 21 18:53:45 wlan0: First radio work item in the queue - schedule start immediately
Dec 21 18:53:45 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0
Dec 21 18:53:45 wlan0: Starting radio work 'scan'@0x91dd0 after 0.004327 second wait
Dec 21 18:53:45 wlan0: nl80211: scan request
Dec 21 18:53:45 Scan requested (ret=0) - scan timeout 10 seconds
Dec 21 18:53:45 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0
Dec 21 18:53:45 nl80211: Drv Event 33 (NL80211_CMD_TRIGGER_SCAN) received for wlan0
Dec 21 18:53:45 wlan0: nl80211: Scan trigger
Dec 21 18:53:45 wlan0: Event SCAN_STARTED (46) received
Dec 21 18:53:45 wlan0: Own scan request started a scan in 0.015061 seconds
Dec 21 18:53:46 nl80211: Drv Event 34 (NL80211_CMD_NEW_SCAN_RESULTS) received for wlan0
Dec 21 18:53:46 wlan0: nl80211: New scan results available
Dec 21 18:53:46 nl80211: Scan probed for SSID ''
Dec 21 18:53:46 nl80211: Scan included frequencies: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467 2472 2484
Dec 21 18:53:46 wlan0: Event SCAN_RESULTS (3) received
Dec 21 18:53:46 wlan0: Scan completed in 0.681293 seconds
Dec 21 18:53:46 nl80211: Received scan results (14 BSSes)
Dec 21 18:53:46 wlan0: BSS: Start scan result update 1
Dec 21 18:53:46 wlan0: BSS: Add new id 0 BSSID f0:9f:c2:3a:da:1c SSID 'Sense Guest' freq 2437
Dec 21 18:53:46 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/0'
Dec 21 18:53:46 wlan0: BSS: Add new id 1 BSSID f2:9f:c2:3a:da:1c SSID 'Sense' freq 2437
Dec 21 18:53:46 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/1'
Dec 21 18:53:46 wlan0: BSS: Add new id 2 BSSID f0:9f:c2:71:f4:4c SSID 'Sense Guest' freq 2412
Dec 21 18:53:46 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/2'
Dec 21 18:53:46 wlan0: BSS: Add new id 3 BSSID f2:9f:c2:71:f4:4c SSID 'Sense' freq 2412
Dec 21 18:53:46 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/3'
Dec 21 18:53:46 wlan0: BSS: Add new id 4 BSSID 82:15:44:ab:7f:35 SSID 'DO Staff' freq 2462
Dec 21 18:53:46 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/4'
Dec 21 18:53:46 wlan0: BSS: Add new id 5 BSSID 8e:15:44:ab:7f:35 SSID 'DigitalOcean Guest' freq 2462
Dec 21 18:53:46 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/5'
Dec 21 18:53:46 wlan0: BSS: Add new id 6 BSSID 8e:15:44:ab:7f:35 SSID '' freq 2462
Dec 21 18:53:46 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/6'
Dec 21 18:53:46 wlan0: BSS: Add new id 7 BSSID 82:15:44:ab:7f:17 SSID '' freq 2462
Dec 21 18:53:46 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/7'
Dec 21 18:53:46 wlan0: BSS: Add new id 8 BSSID 8e:15:44:ab:7f:17 SSID 'DigitalOcean Guest' freq 2462
Dec 21 18:53:46 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/8'
Dec 21 18:53:46 wlan0: BSS: Add new id 9 BSSID 82:15:44:ab:7f:17 SSID 'DO Staff' freq 2462
Dec 21 18:53:46 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/9'
Dec 21 18:53:46 wlan0: BSS: Add new id 10 BSSID f0:9f:c2:34:b2:f0 SSID 'Sense Guest' freq 2462
Dec 21 18:53:46 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/10'
Dec 21 18:53:46 wlan0: BSS: Add new id 11 BSSID f2:9f:c2:34:b2:f0 SSID 'Sense' freq 2462
Dec 21 18:53:46 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/11'
Dec 21 18:53:46 wlan0: BSS: Add new id 12 BSSID 14:dd:a9:75:f4:08 SSID 'SenseTest' freq 2437
Dec 21 18:53:46 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/12'
Dec 21 18:53:46 wlan0: BSS: Add new id 13 BSSID 8e:15:44:ab:7f:36 SSID 'DigitalOcean Guest' freq 2412
Dec 21 18:53:46 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/13'
Dec 21 18:53:46 BSS: last_scan_res_used=14/32
Dec 21 18:53:46 wlan0: New scan results available (own=1 ext=0)
Dec 21 18:53:46 wlan0: Radio work 'scan'@0x91dd0 done in 0.819459 seconds
Dec 21 18:53:46 wlan0: radio_work_free('scan'@0x91dd0): num_active_works --> 0
Dec 21 18:53:46 wlan0: No suitable network found
Dec 21 18:53:46 wlan0: Use normal scan instead of sched_scan for initial scans (normal_scans=1)
Dec 21 18:53:46 wlan0: Short-circuit new scan request since there are no enabled networks
Dec 21 18:53:46 wlan0: State: SCANNING -> INACTIVE
Dec 21 18:53:46 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0
Dec 21 18:53:46 dbus: Register network object '/fi/w1/wpa_supplicant1/Interfaces/0/Networks/0'
Dec 21 18:53:46 wlan0: Scan results matching the currently selected network
Dec 21 18:53:46 wlan0: 1: f2:9f:c2:3a:da:1c freq=2437 level=-45 snr=44 est_throughput=65000
Dec 21 18:53:46 wlan0: 3: f2:9f:c2:71:f4:4c freq=2412 level=-50 snr=39 est_throughput=65000
Dec 21 18:53:46 wlan0: 11: f2:9f:c2:34:b2:f0 freq=2462 level=-66 snr=23 est_throughput=58500
Dec 21 18:53:46 wlan0: Selecting BSS from priority group 0
Dec 21 18:53:46 wlan0: 0: f0:9f:c2:3a:da:1c ssid='Sense Guest' wpa_ie_len=0 rsn_ie_len=20 caps=0x431 level=-43 freq=2437
Dec 21 18:53:46 wlan0: skip - SSID mismatch
Dec 21 18:53:46 wlan0: 1: f2:9f:c2:3a:da:1c ssid='Sense' wpa_ie_len=0 rsn_ie_len=20 caps=0x431 level=-45 freq=2437
Dec 21 18:53:46 wlan0: selected based on RSN IE
Dec 21 18:53:46 wlan0: selected BSS f2:9f:c2:3a:da:1c ssid='Sense'
Dec 21 18:53:46 wlan0: Considering connect request: reassociate: 1 selected: f2:9f:c2:3a:da:1c bssid: 00:00:00:00:00:00 pending: 00:00:00:00:00:00 wpa_state: INACTIVE ssid=0x9fd08 current_ssid=0x9fd08
Dec 21 18:53:46 wlan0: Request association with f2:9f:c2:3a:da:1c
Dec 21 18:53:46 wlan0: No ongoing scan/p2p-scan found to abort
Dec 21 18:53:46 wlan0: Add radio work 'sme-connect'@0xa0110
Dec 21 18:53:46 wlan0: First radio work item in the queue - schedule start immediately
Dec 21 18:53:46 wlan0: Starting radio work 'sme-connect'@0xa0110 after 0.004232 second wait
Dec 21 18:53:46 wlan0: WPA: clearing own WPA/RSN IE
Dec 21 18:53:46 wlan0: Automatic auth_alg selection: 0x1
Dec 21 18:53:46 RSN: PMKSA cache search - network_ctx=0x9fd08 try_opportunistic=0 akmp=0x0
Dec 21 18:53:46 RSN: Search for BSSID f2:9f:c2:3a:da:1c
Dec 21 18:53:46 RSN: No PMKSA cache entry found
Dec 21 18:53:46 wlan0: RSN: using IEEE 802.11i/D9.0
Dec 21 18:53:46 wlan0: WPA: Selected cipher suites: group 16 pairwise 16 key_mgmt 2 proto 2
Dec 21 18:53:46 wlan0: WPA: clearing AP WPA IE
Dec 21 18:53:46 WPA: set AP RSN IE - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
Dec 21 18:53:46 wlan0: WPA: using GTK CCMP
Dec 21 18:53:46 wlan0: WPA: using PTK CCMP
Dec 21 18:53:46 wlan0: WPA: using KEY_MGMT WPA-PSK
Dec 21 18:53:46 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 00 00
Dec 21 18:53:46 WPA: Set PMK based on external data - hexdump(len=32): [REMOVED]
Dec 21 18:53:46 FT: Stored MDIE and FTIE from (Re)Association Response - hexdump(len=0):
Dec 21 18:53:46 RRM: Determining whether RRM can be used - device support: 0x10
Dec 21 18:53:46 RRM: No RRM in network
Dec 21 18:53:46 Added supported operating classes IE - hexdump(len=7): 3b 05 51 51 52 53 54
Dec 21 18:53:46 EAPOL: External notification - EAP success=0
Dec 21 18:53:46 EAPOL: External notification - EAP fail=0
Dec 21 18:53:46 EAPOL: External notification - portControl=Auto
Dec 21 18:53:46 wlan0: Cancelling scan request
Dec 21 18:53:46 wlan0: SME: Trying to authenticate with f2:9f:c2:3a:da:1c (SSID='Sense' freq=2437 MHz)
Dec 21 18:53:46 EAPOL: External notification - portValid=0
Dec 21 18:53:46 wlan0: State: INACTIVE -> AUTHENTICATING
Dec 21 18:53:46 nl80211: Authenticate (ifindex=3)
Dec 21 18:53:46 * bssid=f2:9f:c2:3a:da:1c
Dec 21 18:53:46 * freq=2437
Dec 21 18:53:46 * SSID - hexdump_ascii(len=5):
Dec 21 18:53:46 53 65 6e 73 65 Sense
Dec 21 18:53:46 * IEs - hexdump(len=0): [NULL]
Dec 21 18:53:46 * Auth Type 0
Dec 21 18:53:46 nl80211: Authentication request send successfully
Dec 21 18:53:46 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0
Dec 21 18:53:46 nl80211: Drv Event 19 (NL80211_CMD_NEW_STATION) received for wlan0
Dec 21 18:53:46 nl80211: New station f2:9f:c2:3a:da:1c
Dec 21 18:53:46 EAPOL: disable timer tick
Dec 21 18:53:48 nl80211: Drv Event 37 (NL80211_CMD_AUTHENTICATE) received for wlan0
Dec 21 18:53:48 nl80211: Authenticate event
Dec 21 18:53:48 wlan0: Event AUTH (10) received
Dec 21 18:53:48 wlan0: SME: Authentication response: peer=f2:9f:c2:3a:da:1c auth_type=0 auth_transaction=2 status_code=0
Dec 21 18:53:48 SME: Association Request IEs - hexdump(len=39): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00 7f 08 04 00 00 00 00 00 00 40 3b 05 51 51 52 53 54
Dec 21 18:53:48 wlan0: Trying to associate with f2:9f:c2:3a:da:1c (SSID='Sense' freq=2437 MHz)
Dec 21 18:53:48 wlan0: State: AUTHENTICATING -> ASSOCIATING
Dec 21 18:53:48 nl80211: Set wlan0 operstate 0->0 (DORMANT)
Dec 21 18:53:48 netlink: Operstate: ifindex=3 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
Dec 21 18:53:48 WPA: set own WPA/RSN IE - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
Dec 21 18:53:48 nl80211: Associate (ifindex=3)
Dec 21 18:53:48 * bssid=f2:9f:c2:3a:da:1c
Dec 21 18:53:48 * freq=2437
Dec 21 18:53:48 * SSID - hexdump_ascii(len=5):
Dec 21 18:53:48 53 65 6e 73 65 Sense
Dec 21 18:53:48 * IEs - hexdump(len=39): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00 7f 08 04 00 00 00 00 00 00 40 3b 05 51 51 52 53 54
Dec 21 18:53:48 * WPA Versions 0x2
Dec 21 18:53:48 * pairwise=0xfac04
Dec 21 18:53:48 * group=0xfac04
Dec 21 18:53:48 * akm=0xfac02
Dec 21 18:53:48 nl80211: Association request send successfully
Dec 21 18:53:48 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0
Dec 21 18:53:50 nl80211: Drv Event 20 (NL80211_CMD_DEL_STATION) received for wlan0
Dec 21 18:53:50 nl80211: Delete station f2:9f:c2:3a:da:1c
Dec 21 18:53:51 nl80211: Drv Event 38 (NL80211_CMD_ASSOCIATE) received for wlan0
Dec 21 18:53:51 nl80211: MLME event 38; timeout with f2:9f:c2:3a:da:1c
Dec 21 18:53:51 wlan0: Event ASSOC_TIMED_OUT (14) received
Dec 21 18:53:51 wlan0: SME: Association timed out
Dec 21 18:53:51 wlan0: Radio work 'sme-connect'@0xa0110 done in 4.482622 seconds
Dec 21 18:53:51 wlan0: radio_work_free('sme-connect'@0xa0110): num_active_works --> 0
Dec 21 18:53:51 Added BSSID f2:9f:c2:3a:da:1c into blacklist
Dec 21 18:53:51 wlan0: Another BSS in this ESS has been seen; try it next
Dec 21 18:53:51 BSSID f2:9f:c2:3a:da:1c blacklist count incremented to 2
Dec 21 18:53:51 wlan0: Blacklist count 1 --> request scan in 100 ms
Dec 21 18:53:51 wlan0: Setting scan request: 0.100000 sec
Dec 21 18:53:51 wlan0: State: ASSOCIATING -> DISCONNECTED
Dec 21 18:53:51 nl80211: Set wlan0 operstate 0->0 (DORMANT)
Dec 21 18:53:51 netlink: Operstate: ifindex=3 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
Dec 21 18:53:51 EAPOL: External notification - portEnabled=0
Dec 21 18:53:51 EAPOL: External notification - portValid=0
Dec 21 18:53:51 EAPOL: External notification - EAP success=0
Dec 21 18:53:51 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0
Dec 21 18:53:51 wlan0: State: DISCONNECTED -> SCANNING
Dec 21 18:53:51 Scan SSID - hexdump_ascii(len=5):
Dec 21 18:53:51 53 65 6e 73 65 Sense
Dec 21 18:53:51 wlan0: Starting AP scan for wildcard SSID (Interleave with specific)
Dec 21 18:53:51 wlan0: Optimize scan based on previously generated frequency list
Dec 21 18:53:51 wlan0: Add radio work 'scan'@0xa04b0
Dec 21 18:53:51 wlan0: First radio work item in the queue - schedule start immediately
Dec 21 18:53:51 wlan0: Starting radio work 'scan'@0xa04b0 after 0.000053 second wait
Dec 21 18:53:51 wlan0: nl80211: scan request
Dec 21 18:53:51 Scan requested (ret=0) - scan timeout 30 seconds
Dec 21 18:53:51 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0
Dec 21 18:53:51 nl80211: Drv Event 33 (NL80211_CMD_TRIGGER_SCAN) received for wlan0
Dec 21 18:53:51 wlan0: nl80211: Scan trigger
Dec 21 18:53:51 wlan0: Event SCAN_STARTED (46) received
Dec 21 18:53:51 wlan0: Own scan request started a scan in 0.001574 seconds
Dec 21 18:53:51 dbus: Unregister network object '/fi/w1/wpa_supplicant1/Interfaces/0/Networks/0'
Dec 21 18:53:51 nl80211: Drv Event 34 (NL80211_CMD_NEW_SCAN_RESULTS) received for wlan0
Dec 21 18:53:51 wlan0: nl80211: New scan results available
Dec 21 18:53:51 nl80211: Scan probed for SSID ''
Dec 21 18:53:51 nl80211: Scan included frequencies: 2412 2462
Dec 21 18:53:51 wlan0: Event SCAN_RESULTS (3) received
Dec 21 18:53:51 wlan0: Scan completed in 0.088583 seconds
Dec 21 18:53:51 nl80211: Received scan results (17 BSSes)
Dec 21 18:53:51 wlan0: BSS: Start scan result update 2
Dec 21 18:53:51 wlan0: BSS: Add new id 14 BSSID 02:9f:c2:71:f4:4c SSID '' freq 2412
Dec 21 18:53:51 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/14'
Dec 21 18:53:51 wlan0: BSS: Add new id 15 BSSID 82:15:44:ab:7f:35 SSID '' freq 2462
Dec 21 18:53:51 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/15'
Dec 21 18:53:51 wlan0: BSS: Add new id 16 BSSID 8e:15:44:ab:7f:17 SSID '' freq 2462
Dec 21 18:53:51 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/16'
Dec 21 18:53:51 wlan0: BSS: Add new id 17 BSSID 00:19:77:9f:43:94 SSID 'Central SQ. 1 World WiFi' freq 2462
Dec 21 18:53:51 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/17'
Dec 21 18:53:51 BSS: last_scan_res_used=17/32
Dec 21 18:53:51 wlan0: New scan results available (own=1 ext=0)
Dec 21 18:53:51 wlan0: Radio work 'scan'@0xa04b0 done in 0.143483 seconds
Dec 21 18:53:51 wlan0: radio_work_free('scan'@0xa04b0): num_active_works --> 0
Dec 21 18:53:51 wlan0: No APs found - clear blacklist and try again
Dec 21 18:53:51 Removed BSSID f2:9f:c2:3a:da:1c from blacklist (clear)
Dec 21 18:53:51 wlan0: No suitable network found
Dec 21 18:53:51 wlan0: Use normal scan instead of sched_scan for initial scans (normal_scans=2)
Dec 21 18:53:51 wlan0: Short-circuit new scan request since there are no enabled networks
Dec 21 18:53:51 wlan0: State: SCANNING -> INACTIVE
Dec 21 18:53:51 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0
Dec 21 18:53:54 wlan0: Setting scan request: 0.000000 sec
Dec 21 18:53:54 wlan0: State: INACTIVE -> SCANNING
Dec 21 18:53:54 wlan0: Starting AP scan for wildcard SSID
Dec 21 18:53:54 wlan0: Add radio work 'scan'@0xa8d58
Dec 21 18:53:54 wlan0: First radio work item in the queue - schedule start immediately
Dec 21 18:53:54 wlan0: Starting radio work 'scan'@0xa8d58 after 0.000043 second wait
Dec 21 18:53:54 wlan0: nl80211: scan request
Dec 21 18:53:55 Scan requested (ret=0) - scan timeout 30 seconds
Dec 21 18:53:55 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0
Dec 21 18:53:55 nl80211: Drv Event 33 (NL80211_CMD_TRIGGER_SCAN) received for wlan0
Dec 21 18:53:55 wlan0: nl80211: Scan trigger
Dec 21 18:53:55 wlan0: Event SCAN_STARTED (46) received
Dec 21 18:53:55 wlan0: Own scan request started a scan in 0.000603 seconds
Dec 21 18:53:55 nl80211: Drv Event 34 (NL80211_CMD_NEW_SCAN_RESULTS) received for wlan0
Dec 21 18:53:55 wlan0: nl80211: New scan results available
Dec 21 18:53:55 nl80211: Scan probed for SSID ''
Dec 21 18:53:55 nl80211: Scan included frequencies: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467 2472 2484
Dec 21 18:53:55 wlan0: Event SCAN_RESULTS (3) received
Dec 21 18:53:55 wlan0: Scan completed in 0.713011 seconds
Dec 21 18:53:55 nl80211: Received scan results (19 BSSes)
Dec 21 18:53:55 wlan0: BSS: Start scan result update 3
Dec 21 18:53:55 wlan0: BSS: Add new id 18 BSSID aa:6b:ad:a0:78:36 SSID 'DIRECT-13356_QL-820NWB' freq 2412
Dec 21 18:53:55 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/18'
Dec 21 18:53:55 BSS: last_scan_res_used=19/32
Dec 21 18:53:55 wlan0: New scan results available (own=1 ext=0)
Dec 21 18:53:55 wlan0: Radio work 'scan'@0xa8d58 done in 0.748037 seconds
Dec 21 18:53:55 wlan0: radio_work_free('scan'@0xa8d58): num_active_works --> 0
Dec 21 18:53:55 wlan0: No suitable network found
Dec 21 18:53:55 wlan0: Beginning of SSID list
Dec 21 18:53:55 wlan0: Starting sched scan after 0 seconds (no timeout)
Dec 21 18:53:55 wlan0: nl80211: sched_scan request
Dec 21 18:53:55 nl80211: Passive scan requested
Dec 21 18:53:55 nl80211: Sched scan requested (ret=0)
Dec 21 18:53:55 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0
Dec 21 18:53:55 nl80211: Drv Event 75 (NL80211_CMD_START_SCHED_SCAN) received for wlan0
Dec 21 18:53:55 wlan0: nl80211: Sched scan started
Dec 21 18:53:57 nl80211: Drv Event 77 (NL80211_CMD_SCHED_SCAN_RESULTS) received for wlan0
Dec 21 18:53:57 wlan0: nl80211: New sched scan results available
Dec 21 18:53:57 wlan0: Event SCAN_RESULTS (3) received
Dec 21 18:53:57 nl80211: Received scan results (22 BSSes)
Dec 21 18:53:57 wlan0: BSS: Start scan result update 4
Dec 21 18:53:57 wlan0: BSS: Add new id 19 BSSID 02:9f:c2:3a:da:1c SSID '' freq 2437
Dec 21 18:53:57 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/19'
Dec 21 18:53:57 wlan0: BSS: Add new id 20 BSSID 8e:15:44:ab:7f:e1 SSID '' freq 2437
Dec 21 18:53:57 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/20'
Dec 21 18:53:57 wlan0: BSS: Add new id 21 BSSID 8a:8a:20:d7:37:bb SSID '' freq 2412
Dec 21 18:53:57 dbus: Register BSS object '/fi/w1/wpa_supplicant1/Interfaces/0/BSSs/21'
Dec 21 18:53:57 BSS: last_scan_res_used=22/32
Dec 21 18:53:57 wlan0: New scan results available (own=0 ext=0)
Dec 21 18:53:57 wlan0: No suitable network found
Dec 21 18:53:57 wlan0: Already sched scanning
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/0
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/1
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/2
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/3
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/14
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/6
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/15
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/4
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/5
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/7
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/8
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/9
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/16
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/18
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/10
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/11
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/12
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/13
Dec 21 18:53:57 dbus: flush_object_timeout_handler: Timeout - sending changed properties of object /fi/w1/wpa_supplicant1/Interfaces/0/BSSs/17
Dec 21 18:54:04 wpas_dbus_handler_scan[dbus]: Stop ongoing sched_scan to allow requested scan to proceed
Dec 21 18:54:04 wlan0: Cancelling sched scan
_______________________________________________
Hostap mailing list
Hostap@xxxxxxxxxxxxxxxxxxx
http://lists.infradead.org/mailman/listinfo/hostap
