Can you provide your wpa_supplicant config? Or way how you configure it?
pt., 19 kwi 2019 o 18:14 Jonah Petri <jonah@xxxxxxxxx> napisał(a):
>
> 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
--
Wiktor Drewniak
tel. +48 609 314 098
_______________________________________________
Hostap mailing list
Hostap@xxxxxxxxxxxxxxxxxxx
http://lists.infradead.org/mailman/listinfo/hostap
