On Wed, 2019-05-15 at 21:54 +0200, Wiktor Drewniak wrote:
> Can you provide your wpa_supplicant config? Or way how you configure
> it?
Looks like the problem is likely on the NetworkManager side. Note that
a Network object is registered via D-Bus and then unregistered after
the association timeout. NM reads the scan results from the supplicant
and when it matches an SSID from its configuration to one from the scan
results, will create a Network object (representing a 'network' block
in the supplicant config) and ask the supplicant to use it. When NM
thinks it shouldn't be connected anymore, it will remove that network
object.
So you'd want to enable NetworkManager debug info to figure out why NM
is deciding not to connect to the SSID:
nmcli g log level debug
<try again>
journalctl -b -u NetworkManager (or if not using the systemd journal,
wherever your syslog config puts NetworkManager output)
Dan
> 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
>
>
_______________________________________________
Hostap mailing list
Hostap@xxxxxxxxxxxxxxxxxxx
http://lists.infradead.org/mailman/listinfo/hostap
