WPA Supplicant causes timeouts

Sun Oct 30 12:01:19 PDT 2016

Hi all,

Last February, the distro I was using - Gentoo - switched
from WPA Supplicant v. 2.4 to v. 2.5, and recently to 2.6.

After the upgrade, I started having frequent (every 2-4 mins)
transient timeouts in all of my web browsers.  I looked at the
logs and found this:

Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Associated on 5500 MHz
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Associated on 2462 MHz

Why would it associate and instantly reassociate with the same AP on a different
frequency?  I am sending the relevant log snippet.  Is there any way to stop
these timeouts from happening?

Many thanks,
Nickolai Dobrynin

Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Event message available
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Drv Event 34
(NL80211_CMD_NEW_SCAN_RESULTS) received for wlp3s0
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: nl80211: New scan results available
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Scan probed for SSID ''
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Scan probed for SSID '***'
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Scan included
frequencies: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462
2467 2472 5180 5200 5220 5240 5260 5280 5300 5320 5500 5520 5540 5560
5580 5600 5620 5640 5660 5680 5700 5745 5765 5785 5805 5825
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Event SCAN_RESULTS (3) received
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Scan completed in 4.223758 seconds
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Associated on 5500 MHz
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Associated with ***
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Received scan results (9 BSSes)
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Scan results indicate
BSS status with *** as associated
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: BSS: Start scan result update 11
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: BSS: Add new id 41 BSSID
*** SSID 'Vodafone Hotspot' freq 2462
Oct 30 03:08:17 wpa_supplicant[335]: dbus: Register BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/41'
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: BSS: Remove id 32 BSSID
*** SSID 'KD-WLAN-A1E4' due to no match in scan
Oct 30 03:08:17 wpa_supplicant[335]: dbus: Unregister BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/32'
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: BSS: Remove id 34 BSSID
*** SSID 'Vodafone Hotspot' due to no match in scan
Oct 30 03:08:17 wpa_supplicant[335]: dbus: Unregister BSS object
'/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/34'
Oct 30 03:08:17 wpa_supplicant[335]: BSS: last_scan_res_used=9/32
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: New scan results
available (own=1 ext=0)
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Radio work
'scan'@0x17ac210 done in 4.224317 seconds
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0:
radio_work_free('scan'@0x17ac210: num_active_works --> 0
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Selecting BSS from priority group 0
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: 0: *** ssid='***'
wpa_ie_len=0 rsn_ie_len=20 caps=0x411 level=-57 freq=2462  wps
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0:    selected based on RSN IE
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0:    selected BSS *** ssid='***'
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Considering within-ESS
reassociation
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Current BSS: ***
level=-68 snr=24 est_throughput=390001
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Selected BSS: ***
level=-57 snr=32 est_throughput=65000
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Considering connect
request: reassociate: 0  selected: ***  bssid: ***  pending:
00:00:00:00:00:00  wpa_state: COMPLETED  ssid=0x17cc4b0
current_ssid=0x17cc4b0
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Request association with ***
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Re-association to the same ESS
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Add radio work
'sme-connect'@0x17ac210
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: First radio work item in
the queue - schedule start immediately
Oct 30 03:08:17 wpa_supplicant[335]: RSN: Ignored PMKID candidate
without preauth flag
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Starting radio work
'sme-connect'@0x17ac210 after 0.000010 second wait
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Automatic auth_alg selection: 0x1
Oct 30 03:08:17 wpa_supplicant[335]: RSN: PMKSA cache search -
network_ctx=0x17cc4b0 try_opportunistic=0
Oct 30 03:08:17 wpa_supplicant[335]: RSN: Search for BSSID ***
Oct 30 03:08:17 wpa_supplicant[335]: RSN: No PMKSA cache entry found
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: RSN: using IEEE 802.11i/D9.0
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: Selected cipher
suites: group 16 pairwise 16 key_mgmt 2 proto 2
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: Selected mgmt group cipher 32
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: clearing AP WPA IE
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: using GTK CCMP
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: using PTK CCMP
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: using KEY_MGMT WPA-PSK
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: not using MGMT group cipher
Oct 30 03:08:17 wpa_supplicant[335]: FT: Stored MDIE and FTIE from
(Re)Association Response - hexdump(len=0):
Oct 30 03:08:17 wpa_supplicant[335]: RRM: Determining whether RRM can
be used - device support: 0x0
Oct 30 03:08:17 wpa_supplicant[335]: RRM: No RRM in network
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Cancelling scan request
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: SME: Trying to
authenticate with *** (SSID='***' freq=2462 MHz)
Oct 30 03:08:17 wpa_supplicant[335]: wpa_driver_nl80211_set_key:
ifindex=3 (wlp3s0) alg=0 addr=(nil) key_idx=0 set_tx=0 seq_len=0
key_len=0
Oct 30 03:08:17 wpa_supplicant[335]: wpa_driver_nl80211_set_key:
ifindex=3 (wlp3s0) alg=0 addr=(nil) key_idx=1 set_tx=0 seq_len=0
key_len=0
Oct 30 03:08:17 wpa_supplicant[335]: wpa_driver_nl80211_set_key:
ifindex=3 (wlp3s0) alg=0 addr=0x17d09e0 key_idx=0 set_tx=0 seq_len=0
key_len=0
Oct 30 03:08:17 wpa_supplicant[335]: addr=***
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: State: COMPLETED -> AUTHENTICATING
Oct 30 03:08:17 wpa_supplicant[335]: WMM AC: WMM AC is disabled
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: External notification -
EAP success=0
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: External notification - EAP fail=0
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: External notification -
portControl=Auto
Oct 30 03:08:17 wpa_supplicant[335]: Not configuring frame filtering -
BSS 00:00:00:00:00:00 is not a Hotspot 2.0 network
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Authenticate (ifindex=3)
Oct 30 03:08:17 wpa_supplicant[335]: * bssid=***
Oct 30 03:08:17 wpa_supplicant[335]: * freq=2462
Oct 30 03:08:17 wpa_supplicant[335]: * SSID - hexdump_ascii(len=11):
Oct 30 03:08:17 wpa_supplicant[335]: 57 4c 41 4e 2d 37 44 4d 50 45 33
                ***
Oct 30 03:08:17 wpa_supplicant[335]: * IEs - hexdump(len=0): [NULL]
Oct 30 03:08:17 wpa_supplicant[335]: * Auth Type 0
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Authentication request
send successfully
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Event message available
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Drv Event 20
(NL80211_CMD_DEL_STATION) received for wlp3s0
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Delete station ***
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Event message available
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Drv Event 39
(NL80211_CMD_DEAUTHENTICATE) received for wlp3s0
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: MLME event 39
(NL80211_CMD_DEAUTHENTICATE) on wlp3s0(***) A1=*** A2=***
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Deauthenticate event
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Received a locally
generated deauth event. Clear ignore_next_local_deauth flag
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Event message available
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Drv Event 48
(NL80211_CMD_DISCONNECT) received for wlp3s0
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Ignore disconnect event
when using userspace SME
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Event message available
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Drv Event 19
(NL80211_CMD_NEW_STATION) received for wlp3s0
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: New station ***
Oct 30 03:08:17 wpa_supplicant[335]: RTM_NEWLINK: ifi_index=3
ifname=wlp3s0 operstate=2 linkmode=1 ifi_family=0 ifi_flags=0x1003
([UP])
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Event message available
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Drv Event 37
(NL80211_CMD_AUTHENTICATE) received for wlp3s0
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: MLME event 37
(NL80211_CMD_AUTHENTICATE) on wlp3s0(***) A1=*** A2=***
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Authenticate event
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Event AUTH (11) received
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: SME: Authentication
response: peer=*** auth_type=0 auth_transaction=2 status_code=0
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Trying to associate with
*** (SSID='***' freq=2462 MHz)
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: State: AUTHENTICATING ->
ASSOCIATING
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Set wlp3s0 operstate
1->0 (DORMANT)
Oct 30 03:08:17 wpa_supplicant[335]: netlink: Operstate: ifindex=3
linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Associate (ifindex=3)
Oct 30 03:08:17 wpa_supplicant[335]: * bssid=***
Oct 30 03:08:17 wpa_supplicant[335]: * freq=2462
Oct 30 03:08:17 wpa_supplicant[335]: * SSID - hexdump_ascii(len=11):
Oct 30 03:08:17 wpa_supplicant[335]: 57 4c 41 4e 2d 37 44 4d 50 45 33
                ***
Oct 30 03:08:17 wpa_supplicant[335]: * WPA Versions 0x2
Oct 30 03:08:17 wpa_supplicant[335]: * pairwise=0xfac04
Oct 30 03:08:17 wpa_supplicant[335]: * group=0xfac04
Oct 30 03:08:17 wpa_supplicant[335]: * akm=0xfac02
Oct 30 03:08:17 wpa_supplicant[335]: * prev_bssid=***
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Association request send
successfully
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/11
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/10
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/12
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/13
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/33
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/28
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/27
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/40
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
org.freedesktop.DBus.Properties.GetAll
(/fi/w1/wpa_supplicant1/Interfaces/1/BSSs/41) [s]
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Event message available
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Drv Event 36
(NL80211_CMD_REG_CHANGE) received for wlp3s0
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Regulatory domain change
Oct 30 03:08:17 wpa_supplicant[335]: * initiator=0
Oct 30 03:08:17 wpa_supplicant[335]: * type=1
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Event
CHANNEL_LIST_CHANGED (28) received
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: CTRL-EVENT-REGDOM-CHANGE
init=CORE type=WORLD
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Updating hw mode
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Regulatory information -
country=00
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: 2402-2472 @ 40 MHz 20 mBm
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: 2457-2482 @ 20 MHz 20 mBm (no IR)
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: 2474-2494 @ 20 MHz 20
mBm (no OFDM) (no IR)
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: 5170-5250 @ 80 MHz 20 mBm (no IR)
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: 5250-5330 @ 80 MHz 20
mBm (DFS) (no IR)
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: 5490-5730 @ 160 MHz 20
mBm (DFS) (no IR)
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: 5735-5835 @ 80 MHz 20 mBm (no IR)
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: 57240-63720 @ 2160 MHz 0 mBm
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Added 802.11b mode based
on 802.11g information
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Event message available
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Drv Event 38
(NL80211_CMD_ASSOCIATE) received for wlp3s0
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: MLME event 38
(NL80211_CMD_ASSOCIATE) on wlp3s0(***) A1=*** A2=***
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Associate event
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Event ASSOC (0) received
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Association info event
Oct 30 03:08:17 wpa_supplicant[335]: IEEE 802.11 element parse ignored
unknown element (id=74 elen=14)
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: freq=2462 MHz
Oct 30 03:08:17 wpa_supplicant[335]: FT: Stored MDIE and FTIE from
(Re)Association Response - hexdump(len=0):
Oct 30 03:08:17 wpa_supplicant[335]: Operating frequency changed from
5500 to 2462 MHz
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Associated on 2462 MHz
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Associated with ***
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Received scan results (9 BSSes)
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Scan results indicate
BSS status with *** as associated
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: BSS: Start scan result update 12
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: State: ASSOCIATING -> ASSOCIATED
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Set wlp3s0 operstate
0->0 (DORMANT)
Oct 30 03:08:17 wpa_supplicant[335]: netlink: Operstate: ifindex=3
linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Associated to a new BSS: BSSID=***
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Associated with ***
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: Association event -
clear replay counter
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: Clear old PTK
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: External notification -
portEnabled=0
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: SUPP_PAE entering state DISCONNECTED
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: Supplicant port status: Unauthorized
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Set supplicant port
unauthorized for ***
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: SUPP_BE entering state INITIALIZE
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: External notification - portValid=0
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: External notification -
EAP success=0
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: External notification -
portEnabled=1
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: SUPP_PAE entering state CONNECTING
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: enable timer tick
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: SUPP_BE entering state IDLE
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Setting authentication
timeout: 10 sec 0 usec
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Cancelling scan request
Oct 30 03:08:17 wpa_supplicant[335]: IEEE 802.11 element parse ignored
unknown element (id=74 elen=14)
Oct 30 03:08:17 wpa_supplicant[335]: WMM AC: AC mandatory: AC_BE=0
AC_BK=0 AC_VI=0 AC_VO=0
Oct 30 03:08:17 wpa_supplicant[335]: WMM AC: U-APSD queues=0x0
Oct 30 03:08:17 wpa_supplicant[335]: WMM AC: Valid WMM association,
WMM AC is enabled
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0:
CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
Oct 30 03:08:17 wpa_supplicant[335]: RTM_NEWLINK: ifi_index=3
ifname=wlp3s0 operstate=5 linkmode=1 ifi_family=0 ifi_flags=0x11003
([UP][LOWER_UP])
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Event message available
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Drv Event 46
(NL80211_CMD_CONNECT) received for wlp3s0
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Ignore connect event
(cmd=46) when using userspace SME
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/11
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/10
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/12
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/13
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/33
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/28
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/27
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/40
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1/BSSs/41
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1
Oct 30 03:08:17 wpa_supplicant[335]: l2_packet_receive: src=*** len=121
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: RX EAPOL from ***
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Setting authentication
timeout: 10 sec 0 usec
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: IEEE 802.1X RX: version=2
type=3 length=117
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0:   EAPOL-Key type=2
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0:   key_info 0x8a (ver=2
keyidx=0 rsvd=0 Pairwise Ack)
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0:   key_length=16 key_data_length=22
Oct 30 03:08:17 wpa_supplicant[335]: key_iv - hexdump(len=16): 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00
Oct 30 03:08:17 wpa_supplicant[335]: key_rsc - hexdump(len=8): 00 00
00 00 00 00 00 00
Oct 30 03:08:17 wpa_supplicant[335]: key_id (reserved) -
hexdump(len=8): 00 00 00 00 00 00 00 00
Oct 30 03:08:17 wpa_supplicant[335]: key_mic - hexdump(len=16): 00 00
00 00 00 00 00 00 00 00 00 00 00 00 00 00
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: State: ASSOCIATED -> 4WAY_HANDSHAKE
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: RX message 1 of
4-Way Handshake from *** (ver=2)
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: RSN: no matching PMKID found
Oct 30 03:08:17 wpa_supplicant[335]: Get randomness: len=32 entropy=71
Oct 30 03:08:17 wpa_supplicant[335]: WPA: PTK derivation - A1=*** A2=***
Oct 30 03:08:17 wpa_supplicant[335]: WPA: PMK - hexdump(len=32): [REMOVED]
Oct 30 03:08:17 wpa_supplicant[335]: WPA: PTK - hexdump(len=48): [REMOVED]
Oct 30 03:08:17 wpa_supplicant[335]: WPA: KCK - hexdump(len=16): [REMOVED]
Oct 30 03:08:17 wpa_supplicant[335]: WPA: KEK - hexdump(len=16): [REMOVED]
Oct 30 03:08:17 wpa_supplicant[335]: WPA: TK - hexdump(len=16): [REMOVED]
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: Sending EAPOL-Key 2/4
Oct 30 03:08:17 wpa_supplicant[335]: WPA: KCK - hexdump(len=16): [REMOVED]
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1
Oct 30 03:08:17 wpa_supplicant[335]: l2_packet_receive: src=*** len=155
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: RX EAPOL from ***
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: IEEE 802.1X RX: version=2
type=3 length=151
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0:   EAPOL-Key type=2
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0:   key_info 0x13ca (ver=2
keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0:   key_length=16 key_data_length=56
Oct 30 03:08:17 wpa_supplicant[335]: WPA: decrypted EAPOL-Key key data
- hexdump(len=48): [REMOVED]
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: State: 4WAY_HANDSHAKE ->
4WAY_HANDSHAKE
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: RX message 3 of
4-Way Handshake from *** (ver=2)
Oct 30 03:08:17 wpa_supplicant[335]: WPA: GTK in EAPOL-Key -
hexdump(len=24): [REMOVED]
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: Sending EAPOL-Key 4/4
Oct 30 03:08:17 wpa_supplicant[335]: WPA: KCK - hexdump(len=16): [REMOVED]
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: Installing PTK to the driver
Oct 30 03:08:17 wpa_supplicant[335]: wpa_driver_nl80211_set_key:
ifindex=3 (wlp3s0) alg=3 addr=0x17ae528 key_idx=0 set_tx=1 seq_len=6
key_len=16
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: KEY_DATA -
hexdump(len=16): [REMOVED]
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: KEY_SEQ -
hexdump(len=6): 00 00 00 00 00 00
Oct 30 03:08:17 wpa_supplicant[335]: addr=***
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: External notification - portValid=1
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: State: 4WAY_HANDSHAKE ->
GROUP_HANDSHAKE
Oct 30 03:08:17 wpa_supplicant[335]: RSN: received GTK in pairwise
handshake - hexdump(len=18): [REMOVED]
Oct 30 03:08:17 wpa_supplicant[335]: WPA: Group Key - hexdump(len=16): [REMOVED]
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: Installing GTK to
the driver (keyidx=1 tx=0 len=16)
Oct 30 03:08:17 wpa_supplicant[335]: wpa_driver_nl80211_set_key:
ifindex=3 (wlp3s0) alg=3 addr=0x4a5d40 key_idx=1 set_tx=0 seq_len=6
key_len=16
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: KEY_DATA -
hexdump(len=16): [REMOVED]
Oct 30 03:08:17 wpa_supplicant[335]: broadcast key
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: WPA: Key negotiation
completed with *** [PTK=CCMP GTK=CCMP]
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Cancelling authentication timeout
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: State: GROUP_HANDSHAKE -> COMPLETED
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: Radio work
'sme-connect'@0x17ac210 done in 0.049596 seconds
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0:
radio_work_free('sme-connect'@0x17ac210: num_active_works --> 0
Oct 30 03:08:17 wpa_supplicant[335]: wlp3s0: CTRL-EVENT-CONNECTED -
Connection to *** completed [id=0 id_str=]
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Set wlp3s0 operstate 0->1 (UP)
Oct 30 03:08:17 wpa_supplicant[335]: netlink: Operstate: ifindex=3
linkmode=-1 (no change), operstate=6 (IF_OPER_UP)
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: External notification - portValid=1
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: External notification -
EAP success=1
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: SUPP_PAE entering state
AUTHENTICATING
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: SUPP_BE entering state SUCCESS
Oct 30 03:08:17 wpa_supplicant[335]: EAP: EAP entering state DISABLED
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: SUPP_PAE entering state
AUTHENTICATED
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: Supplicant port status: Authorized
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Set supplicant port
authorized for ***
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL: SUPP_BE entering state IDLE
Oct 30 03:08:17 wpa_supplicant[335]: EAPOL authentication completed -
result=SUCCESS
Oct 30 03:08:17 wpa_supplicant[335]: nl80211: Set rekey offload
Oct 30 03:08:17 wpa_supplicant[335]: RTM_NEWLINK: ifi_index=3
ifname=wlp3s0 operstate=6 linkmode=1 ifi_family=0 ifi_flags=0x11043
([UP][RUNNING][LOWER_UP])
Oct 30 03:08:17 wpa_supplicant[335]: dbus:
flush_object_timeout_handler: Timeout - sending changed properties of
object /fi/w1/wpa_supplicant1/Interfaces/1