WPA Supplicant causes timeouts

Fri Nov 4 14:57:38 PDT 2016

Hey guys,

Can someone please get back to me (see below)?
This is really disruptive to have timeouts, after
timeouts, after timeouts.  I would like to know if my
question is trivial.  Or perhaps it's being looked into,
but no resolution had been found.

After I posted the original question, I disabled the 5 GHz
band, and the behavior changed.  Now, I've only gotten
2-3 timeouts for the last 5 days.  But this is obviously a
temporary fix.

Thx again.

On Sun, Oct 30, 2016 at 8:01 PM, Nickolai Dobrynin <ndobrynin at gmail.com> wrote:
> 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