client side, use wpa_supplicant, while AP side hostapd.
wifi client connect to AP, from logs, client take longer time to connect.
from AP side, hostapd log, the connection time takes around 30ms.
04:28:03.418248 hostapd[186000]: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: authenticated
04:28:03.419116 hostapd[186000]: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated (aid 1)
04:28:03.449556 hostapd[186000]: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: 4-Way handshake completed
however, from client side, wpa_supplicant log, it take around 66ms. It seems wpa_supplicant takes time to prepare/check something before Authentication.
or take time to wait Authentication response from AP.
Question: wpa_supplicant need to configure something to improve this connection time , for example, disable some parameters ?
04:28:03.417454 wpa_supplicant[657177]: wlan0: Add radio work 'sme-connect'@0x556086060400
04:28:03.417454 wpa_supplicant[657177]: wlan0: First radio work item in the queue - schedule start immediately
04:28:03.423134 wpa_supplicant[657177]: wlan0: Starting radio work 'sme-connect'@0x556086060400 after 0.000041 second wait
04:28:03.423134 wpa_supplicant[657177]: wlan0: WPA: clearing own WPA/RSN IE
04:28:03.423134 wpa_supplicant[657177]: wlan0: RSN: clearing own RSNXE
04:28:03.423134 wpa_supplicant[657177]: wlan0: Automatic auth_alg selection: 0x1
04:28:03.423134 wpa_supplicant[657177]: RSN: PMKSA cache search - network_ctx=0x556085fd0da0 try_opportunistic=0 akmp=0x0
04:28:03.423134 wpa_supplicant[657177]: RSN: Search for BSSID xx:xx:xx:xx:xx:xx
04:28:03.423134 wpa_supplicant[657177]: RSN: No PMKSA cache entry found
04:28:03.423134 wpa_supplicant[657177]: wlan0: RSN: using IEEE 802.11i/D9.0
04:28:03.423134 wpa_supplicant[657177]: wlan0: WPA: Selected cipher suites: group 8 pairwise 8 key_mgmt 2 proto 2
04:28:03.423134 wpa_supplicant[657177]: wlan0: WPA: Selected mgmt group cipher 32
04:28:03.423134 wpa_supplicant[657177]: wlan0: WPA: clearing AP WPA IE
04:28:03.423134 wpa_supplicant[657177]: WPA: set AP RSN IE - hexdump(len=22):
04:28:03.423134 wpa_supplicant[657177]: wlan0: WPA: clearing AP RSNXE
04:28:03.423134 wpa_supplicant[657177]: wlan0: WPA: AP group 0x8 network profile group 0x18; available group 0x8
04:28:03.423134 wpa_supplicant[657177]: wlan0: WPA: using GTK TKIP
04:28:03.423134 wpa_supplicant[657177]: wlan0: WPA: AP pairwise 0x8 network profile pairwise 0x18; available pairwise 0x8
04:28:03.423134 wpa_supplicant[657177]: wlan0: WPA: using PTK TKIP
04:28:03.423134 wpa_supplicant[657177]: wlan0: WPA: AP key_mgmt 0x2 network profile key_mgmt 0x2; available key_mgmt 0x2
04:28:03.423134 wpa_supplicant[657177]: wlan0: WPA: using KEY_MGMT WPA-PSK
04:28:03.423134 wpa_supplicant[657177]: wlan0: WPA: AP mgmt_group_cipher 0x20 network profile mgmt_group_cipher 0x0; available mgmt_group_cipher 0x0
04:28:03.423134 wpa_supplicant[657177]: wlan0: WPA: not using MGMT group cipher
04:28:03.423134 wpa_supplicant[657177]: WPA: Set own WPA IE default - hexdump(len=22):
04:28:03.423134 wpa_supplicant[657177]: RSN: Set own RSNXE default - hexdump(len=0):
04:28:03.423134 wpa_supplicant[657177]: PSK (set in config) - hexdump(len=32): [REMOVED]
04:28:03.423134 wpa_supplicant[657177]: WPA: Set PMK based on external data - hexdump(len=32): [REMOVED]
04:28:03.423134 wpa_supplicant[657177]: RRM: Determining whether RRM can be used - device support: 0x30
04:28:03.423134 wpa_supplicant[657177]: RRM: No RRM in network
04:28:03.423134 wpa_supplicant[657177]: Added supported operating classes IE - hexdump(len=18):
04:28:03.423134 wpa_supplicant[657177]: EAPOL: External notification - EAP success=0
04:28:03.423134 wpa_supplicant[657177]: EAPOL: External notification - EAP fail=0
04:28:03.423134 wpa_supplicant[657177]: EAPOL: External notification - portControl=Auto
04:28:03.423134 wpa_supplicant[657177]: wlan0: Cancelling scan request
04:28:03.423134 wpa_supplicant[657177]: wlan0: SME: Trying to authenticate with xx:xx:xx:xx:xx:xx (SSID='myssid' freq=5180 MHz)
04:28:03.423134 wpa_supplicant[657177]: EAPOL: External notification - portValid=0
04:28:03.423134 wpa_supplicant[657177]: EAPOL: SUPP_PAE entering state DISCONNECTED
04:28:03.423134 wpa_supplicant[657177]: EAPOL: Supplicant port status: Unauthorized
04:28:03.423134 wpa_supplicant[657177]: nl80211: Set supplicant port unauthorized for yy:yy:yy:yy:yy:yy
04:28:03.429567 wpa_supplicant[657177]: EAPOL: SUPP_BE entering state INITIALIZE
04:28:03.429567 wpa_supplicant[657177]: EAPOL: SUPP_PAE entering state CONNECTING
04:28:03.429567 wpa_supplicant[657177]: EAPOL: enable timer tick
04:28:03.429567 wpa_supplicant[657177]: EAPOL: SUPP_BE entering state IDLE
04:28:03.429567 wpa_supplicant[657177]: wpa_driver_nl80211_set_key: ifindex=6 (wlan0) alg=0 addr=(nil) key_idx=0 set_tx=0 seq_len=0 key_len=0 key_flag=0x10
04:28:03.429567 wpa_supplicant[657177]: nl80211: DEL_KEY
04:28:03.429567 wpa_supplicant[657177]: broadcast key
04:28:03.429567 wpa_supplicant[657177]: wpa_driver_nl80211_set_key: ifindex=6 (wlan0) alg=0 addr=(nil) key_idx=2 set_tx=0 seq_len=0 key_len=0 key_flag=0x10
04:28:03.429567 wpa_supplicant[657177]: nl80211: DEL_KEY
04:28:03.429567 wpa_supplicant[657177]: broadcast key
04:28:03.432116 wpa_supplicant[657177]: wpa_driver_nl80211_set_key: ifindex=6 (wlan0) alg=0 addr=0x5560860434b0 key_idx=0 set_tx=0 seq_len=0 key_len=0 key_flag=0x20
04:28:03.432116 wpa_supplicant[657177]: nl80211: DEL_KEY
04:28:03.432116 wpa_supplicant[657177]: addr=xx:xx:xx:xx:xx:xx
04:28:03.432116 wpa_supplicant[657177]: pairwise key
04:28:03.432116 wpa_supplicant[657177]: wlan0: State: COMPLETED -> AUTHENTICATING
04:28:03.432116 wpa_supplicant[657177]: bgscan: Deinitializing module 'simple'
04:28:03.432116 wpa_supplicant[657177]: nl80211: Signal monitor threshold=0 hysteresis=0
04:28:03.435765 wpa_supplicant[657177]: WMM AC: WMM AC is disabled
04:28:03.435765 wpa_supplicant[657177]: Not configuring frame filtering - BSS 00:00:00:00:00:00 is not a Hotspot 2.0 network
04:28:03.435765 wpa_supplicant[657177]: wlan0: Determining shared radio frequencies (max len 1)
04:28:03.435765 wpa_supplicant[657177]: wlan0: Shared frequencies (len=1): completed iteration
04:28:03.435765 wpa_supplicant[657177]: wlan0: freq[0]: 5180, flags=0x1
04:28:03.435765 wpa_supplicant[657177]: nl80211: Authenticate (ifindex=6)
04:28:03.435765 wpa_supplicant[657177]: * bssid=xx:xx:xx:xx:xx:xx
04:28:03.435765 wpa_supplicant[657177]: * freq=5180
04:28:03.435765 wpa_supplicant[657177]: * SSID=myssid
04:28:03.435765 wpa_supplicant[657177]: * IEs - hexdump(len=0): [NULL]
04:28:03.435765 wpa_supplicant[657177]: * Auth Type 0
04:28:03.451592 wpa_supplicant[657177]: nl80211: Authentication request send successfully
04:28:03.451592 wpa_supplicant[657177]: RTM_NEWLINK: ifi_index=6 ifname=wlan0 operstate=2 linkmode=1 ifi_family=0 ifi_flags=0x1003 ([UP])
04:28:03.452275 wpa_supplicant[657177]: RTM_NEWLINK: ifi_index=6 ifname=wlan0 wext ifi_family=0 ifi_flags=0x1003 ([UP])
04:28:03.452275 wpa_supplicant[657177]: nl80211: Event message available
04:28:03.452275 wpa_supplicant[657177]: nl80211: Drv Event 20 (NL80211_CMD_DEL_STATION) received for wlan0
04:28:03.452275 wpa_supplicant[657177]: nl80211: Delete station yy:yy:yy:yy:yy:yy
04:28:03.452275 wpa_supplicant[657177]: nl80211: Event message available
04:28:03.452275 wpa_supplicant[657177]: nl80211: Drv Event 39 (NL80211_CMD_DEAUTHENTICATE) received for wlan0
04:28:03.452275 wpa_supplicant[657177]: nl80211: MLME event 39 (NL80211_CMD_DEAUTHENTICATE) on wlan0(zz:zz:zz:zz:zz:zz) A1=yy:yy:yy:yy:yy:yy A2=zz:zz:zz:zz:zz:zz
04:28:03.452275 wpa_supplicant[657177]: nl80211: MLME event frame - hexdump(len=26):
04:28:03.452275 wpa_supplicant[657177]: nl80211: Deauthenticate event
04:28:03.452275 wpa_supplicant[657177]: nl80211: Received a locally generated deauth event. Clear ignore_next_local_deauth flag
04:28:03.452275 wpa_supplicant[657177]: nl80211: Event message available
04:28:03.452275 wpa_supplicant[657177]: nl80211: Drv Event 48 (NL80211_CMD_DISCONNECT) received for wlan0
04:28:03.452275 wpa_supplicant[657177]: nl80211: Ignore disconnect event when using userspace SME
04:28:03.452275 wpa_supplicant[657177]: nl80211: Event message available
04:28:03.452275 wpa_supplicant[657177]: nl80211: Drv Event 19 (NL80211_CMD_NEW_STATION) received for wlan0
04:28:03.452275 wpa_supplicant[657177]: nl80211: New station xx:xx:xx:xx:xx:xx
04:28:03.452275 wpa_supplicant[657177]: nl80211: Event message available
04:28:03.452275 wpa_supplicant[657177]: nl80211: Drv Event 36 (NL80211_CMD_REG_CHANGE) received for wlan0
04:28:03.452275 wpa_supplicant[657177]: nl80211: Regulatory domain change
04:28:03.452275 wpa_supplicant[657177]: * initiator=0
04:28:03.452275 wpa_supplicant[657177]: * type=1
04:28:03.452275 wpa_supplicant[657177]: wlan0: Event CHANNEL_LIST_CHANGED (27) received
04:28:03.452275 wpa_supplicant[657177]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
04:28:03.452275 wpa_supplicant[657177]: wlan0: Updating hw mode
04:28:03.456478 wpa_supplicant[657177]: nl80211: Regulatory information - country=00
04:28:03.456478 wpa_supplicant[657177]: nl80211: 2402-2472 @ 40 MHz 20 mBm
04:28:03.456478 wpa_supplicant[657177]: nl80211: 2457-2482 @ 20 MHz 20 mBm (no IR)
04:28:03.456478 wpa_supplicant[657177]: nl80211: 2474-2494 @ 20 MHz 20 mBm (no OFDM) (no IR)
04:28:03.456478 wpa_supplicant[657177]: nl80211: 5170-5250 @ 80 MHz 20 mBm (no IR)
04:28:03.456478 wpa_supplicant[657177]: nl80211: 5250-5330 @ 80 MHz 20 mBm (DFS) (no IR)
04:28:03.456478 wpa_supplicant[657177]: nl80211: 5490-5730 @ 160 MHz 20 mBm (DFS) (no IR)
04:28:03.456478 wpa_supplicant[657177]: nl80211: 5735-5835 @ 80 MHz 20 mBm (no IR)
04:28:03.456478 wpa_supplicant[657177]: nl80211: 57240-63720 @ 2160 MHz 0 mBm
04:28:03.456478 wpa_supplicant[657177]: nl80211: Added 802.11b mode based on 802.11g information
04:28:03.456478 wpa_supplicant[657177]: nl80211: Mode IEEE 802.11g: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467[DISABLED] 2472[DISABLED] 2484[DISABLED]
04:28:03.456478 wpa_supplicant[657177]: nl80211: Mode IEEE 802.11a: 5180[NO_IR] 5200[NO_IR] 5220[NO_IR] 5240[NO_IR] 5260[NO_IR][RADAR] 5280[NO_IR][RADAR] 5300[NO_IR][RADAR] 5320[NO_IR][RADAR] 5500[DISABLED] 5520[DISABLED] 5540[DISABLED] 5560[DISABLED] 5580[DISABLED]
04:28:03.456478 wpa_supplicant[657177]: nl80211: Mode IEEE 802.11b: 2412 2417 2422 2427 2432 2437 2442 2447 2452 2457 2462 2467[DISABLED] 2472[DISABLED] 2484[DISABLED]
04:28:03.472154 wpa_supplicant[657177]: nl80211: Event message available
04:28:03.472154 wpa_supplicant[657177]: nl80211: Drv Event 37 (NL80211_CMD_AUTHENTICATE) received for wlan0
04:28:03.472154 wpa_supplicant[657177]: nl80211: MLME event 37 (NL80211_CMD_AUTHENTICATE) on wlan0(zz:zz:zz:zz:zz:zz) A1=zz:zz:zz:zz:zz:zz A2=xx:xx:xx:xx:xx:xx
04:28:03.472154 wpa_supplicant[657177]: nl80211: MLME event frame - hexdump(len=30):
04:28:03.472154 wpa_supplicant[657177]: nl80211: Authenticate event
04:28:03.472154 wpa_supplicant[657177]: wlan0: Event AUTH (10) received
04:28:03.472154 wpa_supplicant[657177]: wlan0: SME: Authentication response: peer=xx:xx:xx:xx:xx:xx auth_type=0 auth_transaction=2 status_code=0
04:28:03.472154 wpa_supplicant[657177]: SME: Authentication response IEs - hexdump(len=0): [NULL]
04:28:03.472154 wpa_supplicant[657177]: SME: Association Request IEs - hexdump(len=53):
04:28:03.472154 wpa_supplicant[657177]: wlan0: Trying to associate with xx:xx:xx:xx:xx:xx (SSID='myssid' freq=5180 MHz)
04:28:03.472154 wpa_supplicant[657177]: wlan0: State: AUTHENTICATING -> ASSOCIATING
04:28:03.472154 wpa_supplicant[657177]: nl80211: Set wlan0 operstate 1->0 (DORMANT)
04:28:03.472154 wpa_supplicant[657177]: netlink: Operstate: ifindex=6 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
04:28:03.478260 wpa_supplicant[657177]: WPA: set own WPA/RSN IE - hexdump(len=22):
04:28:03.478260 wpa_supplicant[657177]: wlan0: RSN: clearing own RSNXE
04:28:03.478260 wpa_supplicant[657177]: nl80211: Associate (ifindex=6)
04:28:03.478260 wpa_supplicant[657177]: * bssid=xx:xx:xx:xx:xx:xx
04:28:03.478260 wpa_supplicant[657177]: * freq=5180
04:28:03.478260 wpa_supplicant[657177]: * SSID=myssid
04:28:03.478260 wpa_supplicant[657177]: * IEs - hexdump(len=53):
04:28:03.478260 wpa_supplicant[657177]: * WPA Versions 0x2
04:28:03.478260 wpa_supplicant[657177]: * pairwise=0xfac02
04:28:03.478260 wpa_supplicant[657177]: * group=0xfac02
04:28:03.478260 wpa_supplicant[657177]: * akm=0xfac02
04:28:03.478260 wpa_supplicant[657177]: * prev_bssid=yy:yy:yy:yy:yy:yy
04:28:03.478260 wpa_supplicant[657177]: nl80211: Association request send successfully
04:28:03.478260 wpa_supplicant[657177]: nl80211: Event message available
04:28:03.478260 wpa_supplicant[657177]: nl80211: BSS Event 129 (NL80211_CMD_CONTROL_PORT_FRAME) received for wlan0
04:28:03.478260 wpa_supplicant[657177]: wlan0: Event EAPOL_RX (23) received
04:28:03.478260 wpa_supplicant[657177]: wlan0: RX EAPOL from xx:xx:xx:xx:xx:xx
04:28:03.478260 wpa_supplicant[657177]: RX EAPOL - hexdump(len=99):
04:28:03.478260 wpa_supplicant[657177]: wlan0: Not associated - Delay processing of received EAPOL frame (state=ASSOCIATING bssid=00:00:00:00:00:00)
04:28:03.478260 wpa_supplicant[657177]: RTM_NEWLINK: ifi_index=6 ifname=wlan0 wext ifi_family=0 ifi_flags=0x11003 ([UP][LOWER_UP])
04:28:03.478260 wpa_supplicant[657177]: RTM_NEWLINK: ifi_index=6 ifname=wlan0 wext ifi_family=0 ifi_flags=0x11003 ([UP][LOWER_UP])
04:28:03.478260 wpa_supplicant[657177]: RTM_NEWLINK: ifi_index=6 ifname=wlan0 wext ifi_family=0 ifi_flags=0x11003 ([UP][LOWER_UP])
04:28:03.478260 wpa_supplicant[657177]: RTM_NEWLINK: ifi_index=6 ifname=wlan0 operstate=5 linkmode=1 ifi_family=0 ifi_flags=0x11003 ([UP][LOWER_UP])
04:28:03.478260 wpa_supplicant[657177]: nl80211: Event message available
04:28:03.478260 wpa_supplicant[657177]: nl80211: Drv Event 38 (NL80211_CMD_ASSOCIATE) received for wlan0
04:28:03.478260 wpa_supplicant[657177]: nl80211: MLME event 38 (NL80211_CMD_ASSOCIATE) on wlan0(zz:zz:zz:zz:zz:zz) A1=zz:zz:zz:zz:zz:zz A2=xx:xx:xx:xx:xx:xx
04:28:03.483327 wpa_supplicant[657177]: nl80211: MLME event frame - hexdump(len=76):
04:28:03.483327 wpa_supplicant[657177]: nl80211: Associate event
04:28:03.483327 wpa_supplicant[657177]: nl80211: Associated on 5180 MHz
04:28:03.483327 wpa_supplicant[657177]: nl80211: Associated with xx:xx:xx:xx:xx:xx
04:28:03.483327 wpa_supplicant[657177]: nl80211: Set drv->ssid based on scan res info to 'myssid'
04:28:03.483327 wpa_supplicant[657177]: wlan0: Event ASSOC (0) received
04:28:03.483327 wpa_supplicant[657177]: wlan0: Association info event
04:28:03.483327 wpa_supplicant[657177]: req_ies - hexdump(len=80):
04:28:03.483327 wpa_supplicant[657177]: resp_ies - hexdump(len=46):
04:28:03.483327 wpa_supplicant[657177]: wlan0: freq=5180 MHz
04:28:03.483327 wpa_supplicant[657177]: WPA: set own WPA/RSN IE - hexdump(len=22):
04:28:03.483327 wpa_supplicant[657177]: wlan0: RSN: clearing own RSNXE
04:28:03.483327 wpa_supplicant[657177]: wlan0: State: ASSOCIATING -> ASSOCIATED
04:28:03.483327 wpa_supplicant[657177]: nl80211: Set wlan0 operstate 0->0 (DORMANT)
04:28:03.483327 wpa_supplicant[657177]: netlink: Operstate: ifindex=6 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT)
04:28:03.483327 wpa_supplicant[657177]: wlan0: Associated to a new BSS: BSSID=xx:xx:xx:xx:xx:xx
04:28:03.483327 wpa_supplicant[657177]: wlan0: Associated with xx:xx:xx:xx:xx:xx
04:28:03.483327 wpa_supplicant[657177]: wlan0: WPA: Association event - clear replay counter
04:28:03.483327 wpa_supplicant[657177]: wlan0: WPA: Clear old PTK
04:28:03.483327 wpa_supplicant[657177]: EAPOL: External notification - portEnabled=0
04:28:03.483327 wpa_supplicant[657177]: EAPOL: SUPP_PAE entering state DISCONNECTED
04:28:03.483327 wpa_supplicant[657177]: EAPOL: Supplicant port status: Unauthorized
04:28:03.483327 wpa_supplicant[657177]: nl80211: Set supplicant port unauthorized for xx:xx:xx:xx:xx:xx
04:28:03.483327 wpa_supplicant[657177]: EAPOL: SUPP_BE entering state INITIALIZE
04:28:03.483327 wpa_supplicant[657177]: EAPOL: External notification - portValid=0
04:28:03.483327 wpa_supplicant[657177]: EAPOL: External notification - EAP success=0
04:28:03.483327 wpa_supplicant[657177]: EAPOL: External notification - portEnabled=1
04:28:03.483327 wpa_supplicant[657177]: EAPOL: SUPP_PAE entering state CONNECTING
04:28:03.483327 wpa_supplicant[657177]: EAPOL: SUPP_BE entering state IDLE
04:28:03.483327 wpa_supplicant[657177]: wlan0: Setting authentication timeout: 10 sec 0 usec
04:28:03.483327 wpa_supplicant[657177]: wlan0: Cancelling scan request
04:28:03.483327 wpa_supplicant[657177]: wlan0: Process pending EAPOL frame that was received just before association notification
04:28:03.488903 wpa_supplicant[657177]: wlan0: RX EAPOL from xx:xx:xx:xx:xx:xx
04:28:03.488903 wpa_supplicant[657177]: RX EAPOL - hexdump(len=99):
04:28:03.488903 wpa_supplicant[657177]: wlan0: Setting authentication timeout: 10 sec 0 usec
04:28:03.488903 wpa_supplicant[657177]: wlan0: IEEE 802.1X RX: version=2 type=3 length=95
04:28:03.488903 wpa_supplicant[657177]: WPA: RX EAPOL-Key - hexdump(len=99):
04:28:03.488903 wpa_supplicant[657177]: wlan0: EAPOL-Key type=2
04:28:03.488903 wpa_supplicant[657177]: wlan0: key_info 0x89 (ver=1 keyidx=0 rsvd=0 Pairwise Ack)
04:28:03.488903 wpa_supplicant[657177]: wlan0: key_length=32 key_data_length=0
04:28:03.488903 wpa_supplicant[657177]: replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 01
04:28:03.488903 wpa_supplicant[657177]: key_nonce - hexdump(len=32):
04:28:03.488903 wpa_supplicant[657177]: key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
04:28:03.488903 wpa_supplicant[657177]: key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
04:28:03.488903 wpa_supplicant[657177]: key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
04:28:03.488903 wpa_supplicant[657177]: key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
04:28:03.488903 wpa_supplicant[657177]: wlan0: State: ASSOCIATED -> 4WAY_HANDSHAKE
04:28:03.488903 wpa_supplicant[657177]: wlan0: WPA: RX message 1 of 4-Way Handshake from xx:xx:xx:xx:xx:xx (ver=1)
04:28:03.488903 wpa_supplicant[657177]: RSN: msg 1/4 key data - hexdump(len=0):
04:28:03.488903 wpa_supplicant[657177]: Get randomness: len=32 entropy=5
04:28:03.488903 wpa_supplicant[657177]: WPA: Renewed SNonce - hexdump(len=32):
04:28:03.488903 wpa_supplicant[657177]: WPA: PTK derivation using PRF(SHA1)
04:28:03.488903 wpa_supplicant[657177]: WPA: PTK derivation - A1=zz:zz:zz:zz:zz:zz A2=xx:xx:xx:xx:xx:xx
04:28:03.488903 wpa_supplicant[657177]: WPA: Nonce1 - hexdump(len=32):
04:28:03.493021 wpa_supplicant[657177]: WPA: Nonce2 - hexdump(len=32):
04:28:03.493021 wpa_supplicant[657177]: WPA: PMK - hexdump(len=32): [REMOVED]
04:28:03.493021 wpa_supplicant[657177]: WPA: PTK - hexdump(len=64): [REMOVED]
04:28:03.493021 wpa_supplicant[657177]: WPA: KCK - hexdump(len=16): [REMOVED]
04:28:03.493021 wpa_supplicant[657177]: WPA: KEK - hexdump(len=16): [REMOVED]
04:28:03.493021 wpa_supplicant[657177]: WPA: TK - hexdump(len=32): [REMOVED]
04:28:03.493021 wpa_supplicant[657177]: WPA: WPA IE for msg 2/4 - hexdump(len=22):
04:28:03.493021 wpa_supplicant[657177]: WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 01
04:28:03.493021 wpa_supplicant[657177]: wlan0: WPA: Sending EAPOL-Key 2/4
04:28:03.493021 wpa_supplicant[657177]: WPA: Send EAPOL-Key frame to xx:xx:xx:xx:xx:xx ver=1 mic_len=16 key_mgmt=0x2
04:28:03.493021 wpa_supplicant[657177]: WPA: EAPOL-Key MIC using HMAC-MD5
04:28:03.493021 wpa_supplicant[657177]: WPA: KCK - hexdump(len=16): [REMOVED]
04:28:03.493021 wpa_supplicant[657177]: WPA: Derived Key MIC - hexdump(len=16): a5 11 9a f5 fb c9 07 a1 b0 60 db 09 c8 ec a7 bd
04:28:03.493021 wpa_supplicant[657177]: WPA: TX EAPOL-Key - hexdump(len=121):
04:28:03.493021 wpa_supplicant[657177]: nl80211: Send over control port dest=xx:xx:xx:xx:xx:xx proto=0x888e len=121 no_encrypt=1
04:28:03.493021 wpa_supplicant[657177]: nl80211: tx_control_port cookie=0x75
04:28:03.493021 wpa_supplicant[657177]: WMM AC: AC mandatory: AC_BE=0 AC_BK=0 AC_VI=0 AC_VO=0
04:28:03.493021 wpa_supplicant[657177]: WMM AC: U-APSD queues=0x0
04:28:03.493021 wpa_supplicant[657177]: WMM AC: Valid WMM association, WMM AC is enabled
04:28:03.493021 wpa_supplicant[657177]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
04:28:03.493021 wpa_supplicant[657177]: nl80211: Event message available
04:28:03.493021 wpa_supplicant[657177]: nl80211: Drv Event 46 (NL80211_CMD_CONNECT) received for wlan0
04:28:03.493021 wpa_supplicant[657177]: nl80211: Ignore connect event (cmd=46) when using userspace SME
04:28:03.493021 wpa_supplicant[657177]: nl80211: Event message available
04:28:03.493021 wpa_supplicant[657177]: nl80211: Drv Event 139 (NL80211_CMD_CONTROL_PORT_FRAME_TX_STATUS) received for wlan0
04:28:03.493021 wpa_supplicant[657177]: nl80211: Control port TX status (ack=1), cookie=117
04:28:03.493021 wpa_supplicant[657177]: wlan0: Event EAPOL_TX_STATUS (37) received
04:28:03.493021 wpa_supplicant[657177]: nl80211: Event message available
04:28:03.493021 wpa_supplicant[657177]: nl80211: BSS Event 129 (NL80211_CMD_CONTROL_PORT_FRAME) received for wlan0
04:28:03.493021 wpa_supplicant[657177]: wlan0: Event EAPOL_RX (23) received
04:28:03.493021 wpa_supplicant[657177]: wlan0: RX EAPOL from xx:xx:xx:xx:xx:xx
04:28:03.498341 wpa_supplicant[657177]: RX EAPOL - hexdump(len=161):
04:28:03.498341 wpa_supplicant[657177]: wlan0: IEEE 802.1X RX: version=2 type=3 length=157
04:28:03.498341 wpa_supplicant[657177]: WPA: RX EAPOL-Key - hexdump(len=161):
04:28:03.498341 wpa_supplicant[657177]: wlan0: EAPOL-Key type=2
04:28:03.498341 wpa_supplicant[657177]: wlan0: key_info 0x13c9 (ver=1 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
04:28:03.498341 wpa_supplicant[657177]: wlan0: key_length=32 key_data_length=62
04:28:03.498341 wpa_supplicant[657177]: replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 02
04:28:03.498341 wpa_supplicant[657177]: key_nonce - hexdump(len=32):
04:28:03.498341 wpa_supplicant[657177]: key_iv - hexdump(len=16):
04:28:03.498341 wpa_supplicant[657177]: key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
04:28:03.498341 wpa_supplicant[657177]: key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
04:28:03.498341 wpa_supplicant[657177]: key_mic - hexdump(len=16):
04:28:03.498341 wpa_supplicant[657177]: WPA: EAPOL-Key MIC using HMAC-MD5
04:28:03.498341 wpa_supplicant[657177]: RSN: encrypted key data - hexdump(len=62):
04:28:03.498341 wpa_supplicant[657177]: WPA: Decrypt Key Data using RC4
04:28:03.498341 wpa_supplicant[657177]: WPA: decrypted EAPOL-Key key data - hexdump(len=62): [REMOVED]
04:28:03.501410 wpa_supplicant[657177]: wlan0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
04:28:03.501410 wpa_supplicant[657177]: wlan0: WPA: RX message 3 of 4-Way Handshake from xx:xx:xx:xx:xx:xx (ver=1)
04:28:03.501410 wpa_supplicant[657177]: WPA: IE KeyData - hexdump(len=62):
04:28:03.501410 wpa_supplicant[657177]: WPA: RSN IE in EAPOL-Key - hexdump(len=22):
04:28:03.501410 wpa_supplicant[657177]: WPA: GTK in EAPOL-Key - hexdump(len=40): [REMOVED]
04:28:03.501410 wpa_supplicant[657177]: wlan0: WPA: Sending EAPOL-Key 4/4
04:28:03.501410 wpa_supplicant[657177]: WPA: Send EAPOL-Key frame to xx:xx:xx:xx:xx:xx ver=1 mic_len=16 key_mgmt=0x2
04:28:03.501410 wpa_supplicant[657177]: WPA: EAPOL-Key MIC using HMAC-MD5
04:28:03.501410 wpa_supplicant[657177]: WPA: KCK - hexdump(len=16): [REMOVED]
04:28:03.501410 wpa_supplicant[657177]: WPA: Derived Key MIC - hexdump(len=16):
04:28:03.501410 wpa_supplicant[657177]: WPA: TX EAPOL-Key - hexdump(len=99):
04:28:03.501410 wpa_supplicant[657177]: nl80211: Send over control port dest=xx:xx:xx:xx:xx:xx proto=0x888e len=99 no_encrypt=1
04:28:03.501410 wpa_supplicant[657177]: nl80211: tx_control_port cookie=0x76
04:28:03.501410 wpa_supplicant[657177]: wlan0: WPA: Installing PTK to the driver
04:28:03.501410 wpa_supplicant[657177]: wpa_driver_nl80211_set_key: ifindex=6 (wlan0) alg=2 addr=0x556085fd2cc0 key_idx=0 set_tx=1 seq_len=6 key_len=32 key_flag=0x2c
04:28:03.501410 wpa_supplicant[657177]: nl80211: NEW_KEY
04:28:03.501410 wpa_supplicant[657177]: nl80211: KEY_DATA - hexdump(len=32): [REMOVED]
04:28:03.501410 wpa_supplicant[657177]: nl80211: KEY_SEQ - hexdump(len=6): 00 00 00 00 00 00
04:28:03.501410 wpa_supplicant[657177]: addr=xx:xx:xx:xx:xx:xx
04:28:03.501410 wpa_supplicant[657177]: pairwise key
04:28:03.501410 wpa_supplicant[657177]: EAPOL: External notification - portValid=1
04:28:03.501410 wpa_supplicant[657177]: wlan0: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
04:28:03.501410 wpa_supplicant[657177]: RSN: received GTK in pairwise handshake - hexdump(len=34): [REMOVED]
04:28:03.501410 wpa_supplicant[657177]: WPA: Group Key - hexdump(len=32): [REMOVED]
04:28:03.501410 wpa_supplicant[657177]: wlan0: WPA: Installing GTK to the driver (keyidx=2 tx=0 len=32)
04:28:03.501410 wpa_supplicant[657177]: WPA: RSC - hexdump(len=6): 00 00 00 00 00 00
04:28:03.501410 wpa_supplicant[657177]: wpa_driver_nl80211_set_key: ifindex=6 (wlan0) alg=2 addr=0x556085f02d80 key_idx=2 set_tx=0 seq_len=6 key_len=32 key_flag=0x14
04:28:03.501410 wpa_supplicant[657177]: nl80211: NEW_KEY
04:28:03.506195 wpa_supplicant[657177]: nl80211: KEY_DATA - hexdump(len=32): [REMOVED]
04:28:03.506195 wpa_supplicant[657177]: nl80211: KEY_SEQ - hexdump(len=6): 00 00 00 00 00 00
04:28:03.506195 wpa_supplicant[657177]: broadcast key
04:28:03.506195 wpa_supplicant[657177]: wlan0: WPA: Key negotiation completed with xx:xx:xx:xx:xx:xx [PTK=TKIP GTK=TKIP]
04:28:03.506195 wpa_supplicant[657177]: wlan0: Cancelling authentication timeout
04:28:03.506195 wpa_supplicant[657177]: wlan0: State: GROUP_HANDSHAKE -> COMPLETED
04:28:03.506195 wpa_supplicant[657177]: wlan0: Radio work 'sme-connect'@0x556086060400 done in 0.065947 seconds
04:28:03.506195 wpa_supplicant[657177]: wlan0: radio_work_free('sme-connect'@0x556086060400): num_active_works --> 0
04:28:03.506195 wpa_supplicant[657177]: wlan0: CTRL-EVENT-CONNECTED - Connection to xx:xx:xx:xx:xx:xx completed [id=0 id_str=]
