Android WiFi 日志记录(四次握手)

你的名字 2021-05-02 14:27 519阅读 0赞

记录一下四次握手的log。

PMK：
    PMK（Pairwise Master Key，成对主密钥
    
    
STA和AP得到PMK后，将进行密匙派生以得到PTK。最后，PTK被设置到硬件中，
用于数据的加解密。
·由于AP和STA都需要使用PTK，所以二者需要利用EAPOL Key帧进行信息交换。
这就是4-Way Handshake的作用。

由于STA每次关联都需要重新派生这些
Key，所以它们称为PTK（Pairwise Transient Key，成对临时Key），
    
    09-04 16:01:00.393  5955  5955 I wpa_supplicant: wlan0: Associated with 70:3d:15:1a:31:38           // 关联
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: wlan0: WPA: Association event - clear replay counter
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: wlan0: WPA: Clear old PTK                                    // 清楚原来的PTK，每次连接的PTK都是不一样的。
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: TDLS: Remove peers on association
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: EAPOL: External notification - portEnabled=0
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: EAPOL: SUPP_PAE entering state DISCONNECTED
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: EAPOL: Supplicant port status: Unauthorized                // 此时的端口状态，EAPOL状态unauthorized
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: nl80211: Set supplicant port unauthorized for 70:3d:15:1a:31:38
    09-04 16:01:00.393   960   960 E wificond: Failed to get NL80211_STA_INFO_TX_PACKETS
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: EAPOL: SUPP_BE entering state INITIALIZE
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: EAPOL: External notification - portValid=0
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: EAPOL: External notification - EAP success=0
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: EAPOL: External notification - portEnabled=1
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: EAPOL: SUPP_PAE entering state CONNECTING
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: EAPOL: enable timer tick
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: EAPOL: SUPP_BE entering state IDLE
    // 设置认证超时时间10s，也就是说四次握手的超时时间是10秒，如果四次握手出错，将会有10秒时间继续握手
    // 这10秒内数据连接是有问题的。10s过后才会重新认证，关联。
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: wlan0: Setting authentication timeout: 10 sec 0 usec           
    09-04 16:01:00.393  1398  1629 E WificondControl: Invalid signal poll result from wificond
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: wlan0: Cancelling scan request
    09-04 16:01:00.393  5955  5955 D wpa_supplicant: WMM AC: Missing U-APSD configuration
    09-04 16:01:00.393  5955  5955 I wpa_supplicant: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
    // 第一次握手，EAPOL-Key包含AP生成的Nonce(ANonce)
    09-04 16:01:00.394  5955  5955 D wpa_supplicant: l2_packet_receive: l2=0x721d027400, wpa_s->l2_wapi=0x721d027380
    09-04 16:01:00.394  5955  5955 D wpa_supplicant: l2_packet_receive: src=70:3d:15:1a:31:38 len=121
    09-04 16:01:00.394  5955  5955 D wpa_supplicant: wlan0: RX EAPOL from 70:3d:15:1a:31:38             // 第一次握手，收到EAPOL包
    09-04 16:01:00.394  5955  5955 D wpa_supplicant: wlan0: Setting authentication timeout: 10 sec 0 usec
    09-04 16:01:00.394  5955  5955 D wpa_supplicant: wlan0: IEEE 802.1X RX: version=1 type=3 length=117
    09-04 16:01:00.394  5955  5955 D wpa_supplicant: wlan0:   EAPOL-Key type=2
    09-04 16:01:00.394  5955  5955 D wpa_supplicant: wlan0:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
    09-04 16:01:00.394  5955  5955 D wpa_supplicant: wlan0:   key_length=16 key_data_length=22
    09-04 16:01:00.396  2013  2080 I QCNEJ/CndHalConnector: -> SND notifyRatConnectionStatusChanged(rat = 1, CONNECTED)
    09-04 16:01:00.397  5955  5955 D wpa_supplicant:   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 00
    09-04 16:01:00.397  5955  5955 D wpa_supplicant:   key_nonce - hexdump(len=32): 82 19 37 88 e2 a9 51 62 f8 ce e3 98 73 ce 52 e6 32 b8 6a d6 03 9a 48 de df b3 63 51 1a 3a 9c 1e
    09-04 16:01:00.397  5955  5955 D wpa_supplicant:   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
    09-04 16:01:00.397  5955  5955 D wpa_supplicant:   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
    09-04 16:01:00.397  5955  5955 D wpa_supplicant:   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
    09-04 16:01:00.397  5955  5955 D wpa_supplicant:   key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
    09-04 16:01:00.397  5955  5955 D wpa_supplicant: wlan0: State: ASSOCIATED -> 4WAY_HANDSHAKE
    09-04 16:01:00.397  5955  5955 D wpa_supplicant: Notifying state change event to hidl control: 4WAY_HANDSHAKE
    09-04 16:01:00.399  1398  2072 I WifiService: getWifiApEnabledState uid=1000
    09-04 16:01:00.399   994   994 E Parcel  : Reading a NULL string not supported here.
    09-04 16:01:00.399  5955  5955 D wpa_supplicant: wlan0: Determining shared radio frequencies (max len 2)
    09-04 16:01:00.399   994   994 E Parcel  : Reading a NULL string not supported here.
    09-04 16:01:00.400  5955  5955 D wpa_supplicant: wlan0: Shared frequencies (len=1): completed iteration
    09-04 16:01:00.400  5955  5955 D wpa_supplicant: wlan0: freq[0]: 2462, flags=0x1
    ......
    09-04 16:01:00.400  5955  5955 D wpa_supplicant: wlan0: WPA: RX message 1 of 4-Way Handshake from 70:3d:15:1a:31:38 (ver=2)            // 提示四次握手的第一个包
    09-04 16:01:00.400  5955  5955 D wpa_supplicant: RSN: msg 1/4 key data - hexdump(len=22): dd 14 00 0f ac 04 00 84 a5 48 43 26 dc c2 9e 6c 92 df 8f 28 5d f5
    09-04 16:01:00.400  5955  5955 D wpa_supplicant: WPA: PMKID in EAPOL-Key - hexdump(len=22): dd 14 00 0f ac 04 00 84 a5 48 43 26 dc c2 9e 6c 92 df 8f 28 5d f5
    09-04 16:01:00.400  5955  5955 D wpa_supplicant: RSN: PMKID from Authenticator - hexdump(len=16): 00 84 a5 48 43 26 dc c2 9e 6c 92 df 8f 28 5d f5
    09-04 16:01:00.400  5955  5955 D wpa_supplicant: wlan0: RSN: no matching PMKID found
    // 第二次握手
    // Supplicant生成SNonce
    09-04 16:01:00.401  5955  5955 D wpa_supplicant: WPA: Renewed SNonce - hexdump(len=32): 35 fa 6e 62 22 f8 1a a2 73 e5 00 18 5f 1d 56 93 79 73 f0 3f 55 c6 e3 35 e2 06 82 5d e4 ff 19 ee
    09-04 16:01:00.401  5955  5955 D wpa_supplicant: WPA: PTK derivation using PRF(SHA1)
    09-04 16:01:00.401  5955  5955 D wpa_supplicant: WPA: PTK derivation - A1=00:0a:f5:32:b1:50 A2=70:3d:15:1a:31:38
    09-04 16:01:00.401  5955  5955 D wpa_supplicant: WPA: Nonce1 - hexdump(len=32): 35 fa 6e 62 22 f8 1a a2 73 e5 00 18 5f 1d 56 93 79 73 f0 3f 55 c6 e3 35 e2 06 82 5d e4 ff 19 ee
    09-04 16:01:00.401  5955  5955 D wpa_supplicant: WPA: Nonce2 - hexdump(len=32): 82 19 37 88 e2 a9 51 62 f8 ce e3 98 73 ce 52 e6 32 b8 6a d6 03 9a 48 de df b3 63 51 1a 3a 9c 1e
    09-04 16:01:00.402  5955  5955 D wpa_supplicant: WPA: PMK - hexdump(len=32): [REMOVED]
    09-04 16:01:00.402  5955  5955 D wpa_supplicant: WPA: PTK - hexdump(len=48): [REMOVED]
    09-04 16:01:00.402  5955  5955 D wpa_supplicant: WPA: KCK - hexdump(len=16): [REMOVED]
    09-04 16:01:00.402  5955  5955 D wpa_supplicant: WPA: KEK - hexdump(len=16): [REMOVED]
    09-04 16:01:00.402  5955  5955 D wpa_supplicant: WPA: TK - hexdump(len=16): [REMOVED]
    09-04 16:01:00.402  5955  5955 D wpa_supplicant: WPA: WPA IE for msg 2/4 - hexdump(len=22): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 80 00
    09-04 16:01:00.402  5955  5955 D wpa_supplicant: WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 00
    09-04 16:01:00.402  5955  5955 D wpa_supplicant: wlan0: WPA: Sending EAPOL-Key 2/4              // 第二次握手，发送EAPOL
    09-04 16:01:00.402  5955  5955 D wpa_supplicant: WPA: Send EAPOL-Key frame to 70:3d:15:1a:31:38 ver=2 mic_len=16 key_mgmt=0x2
    09-04 16:01:00.402  5955  5955 D wpa_supplicant: WPA: EAPOL-Key MIC using HMAC-SHA1
    09-04 16:01:00.402  5955  5955 D wpa_supplicant: WPA: KCK - hexdump(len=16): [REMOVED]
    09-04 16:01:00.402  5955  5955 D wpa_supplicant: WPA: Derived Key MIC - hexdump(len=16): 98 1f 71 89 58 08 ee 9e e6 96 f2 a9 0f f6 4f f0
    09-04 16:01:00.402  5955  5955 D wpa_supplicant: RTM_NEWLINK: ifi_index=22 ifname=wlan0 operstate=5 linkmode=1 ifi_family=0 ifi_flags=0x11003 ([UP][LOWER_UP])
    09-04 16:01:00.403  1398  1629 D WifiStateMachine:  ConnectedState !SUPPLICANT_STATE_CHANGE_EVENT rt=19506385/19506385 0 0 SSID: eda51_roam_test BSSID: 70:3d:15:1a:31:38 nid: 0 state: FOUR_WAY_HANDSHAKE
    09-04 16:01:00.403  1398  1629 D WifiStateMachine:  L2ConnectedState !SUPPLICANT_STATE_CHANGE_EVENT rt=19506386/19506386 0 0 SSID: eda51_roam_test BSSID: 70:3d:15:1a:31:38 nid: 0 state: FOUR_WAY_HANDSHAKE
    09-04 16:01:00.403  1398  1629 D WifiStateMachine:  ConnectModeState !SUPPLICANT_STATE_CHANGE_EVENT rt=19506386/19506386 0 0 SSID: eda51_roam_test BSSID: 70:3d:15:1a:31:38 nid: 0 state: FOUR_WAY_HANDSHAKE
    09-04 16:01:00.404  1398  1629 D SupplicantStateTracker: CompletedState{ when=0 what=147462 obj= SSID: eda51_roam_test BSSID: 70:3d:15:1a:31:38 nid: 0 state: FOUR_WAY_HANDSHAKE target=com.android.internal.util.StateMachine$SmHandler }
    
    09-04 16:01:00.412  5955  5955 D wpa_supplicant: l2_packet_receive: l2=0x721d027400, wpa_s->l2_wapi=0x721d027380
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: l2_packet_receive: src=70:3d:15:1a:31:38 len=155
    // 第三次握手， AP派生密钥，发送supplicant,
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: wlan0: RX EAPOL from 70:3d:15:1a:31:38             // 第三次握手，收到AP发过来的EAPOL包
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: wlan0: IEEE 802.1X RX: version=1 type=3 length=151
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: wlan0:   EAPOL-Key type=2
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: wlan0:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: wlan0:   key_length=16 key_data_length=56
    09-04 16:01:00.413  5955  5955 D wpa_supplicant:   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 01
    09-04 16:01:00.413  5955  5955 D wpa_supplicant:   key_nonce - hexdump(len=32): 82 19 37 88 e2 a9 51 62 f8 ce e3 98 73 ce 52 e6 32 b8 6a d6 03 9a 48 de df b3 63 51 1a 3a 9c 1e
    09-04 16:01:00.413  5955  5955 D wpa_supplicant:   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
    09-04 16:01:00.413  5955  5955 D wpa_supplicant:   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
    09-04 16:01:00.413  5955  5955 D wpa_supplicant:   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
    09-04 16:01:00.413  5955  5955 D wpa_supplicant:   key_mic - hexdump(len=16): 76 32 3f 2e f5 8d a2 93 d4 48 a3 04 97 31 e9 e9
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: WPA: EAPOL-Key MIC using HMAC-SHA1
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: RSN: encrypted key data - hexdump(len=56): e4 42 21 3a 98 9f 97 3e bd 07 38 71 17 4f cb 96 78 dd d0 d3 a0 3f 22 02 4a 7b dd 1c d6 95 93 a4 ...
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: WPA: Decrypt Key Data using AES-UNWRAP (KEK length 16)
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: WPA: decrypted EAPOL-Key key data - hexdump(len=48): [REMOVED]
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: wlan0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: wlan0: WPA: RX message 3 of 4-Way Handshake from 70:3d:15:1a:31:38 (ver=2)            // 四次握手第三个包
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: WPA: IE KeyData - hexdump(len=48): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00 dd 16 00 0f ac 01 01 00 ae 9e ...
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: WPA: RSN IE in EAPOL-Key - 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
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: WPA: GTK in EAPOL-Key - hexdump(len=24): [REMOVED]
    // 第四次握手
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: wlan0: WPA: Sending EAPOL-Key 4/4                  // 发送EAPOL包
    09-04 16:01:00.413  5955  5955 D wpa_supplicant: WPA: Send EAPOL-Key frame to 70:3d:15:1a:31:38 ver=2 mic_len=16 key_mgmt=0x2
    09-04 16:01:00.414  5955  5955 D wpa_supplicant: WPA: EAPOL-Key MIC using HMAC-SHA1
    09-04 16:01:00.414  5955  5955 D wpa_supplicant: WPA: KCK - hexdump(len=16): [REMOVED]
    09-04 16:01:00.414  5955  5955 D wpa_supplicant: WPA: Derived Key MIC - hexdump(len=16): 42 6f 06 c0 ef b2 ff 4c cd 8e 52 ff 8f 70 a4 c0
    09-04 16:01:00.414  5955  5955 D wpa_supplicant: wlan0: WPA: Installing PTK to the driver
    09-04 16:01:00.414  5955  5955 D wpa_supplicant: wpa_driver_nl80211_set_key: ifindex=22 (wlan0) alg=3 addr=0x721d0c5a68 key_idx=0 set_tx=1 seq_len=6 key_len=16
    09-04 16:01:00.414  5955  5955 D wpa_supplicant: nl80211: KEY_DATA - hexdump(len=16): [REMOVED]
    09-04 16:01:00.414  5955  5955 D wpa_supplicant: nl80211: KEY_SEQ - hexdump(len=6): 00 00 00 00 00 00
    09-04 16:01:00.414  5955  5955 D wpa_supplicant:    addr=70:3d:15:1a:31:38
    09-04 16:01:00.415  5955  5955 D wpa_supplicant: EAPOL: External notification - portValid=1
    09-04 16:01:00.415  5955  5955 D wpa_supplicant: wlan0: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
    09-04 16:01:00.416  5955  5955 D wpa_supplicant: Notifying state change event to hidl control: GROUP_HANDSHAKE
    ......
    09-04 16:01:00.418  5955  5955 D wpa_supplicant: RSN: received GTK in pairwise handshake - hexdump(len=18): [REMOVED]
    09-04 16:01:00.418  5955  5955 D wpa_supplicant: WPA: Group Key - hexdump(len=16): [REMOVED]
    09-04 16:01:00.418  5955  5955 D wpa_supplicant: wlan0: WPA: Installing GTK to the driver (keyidx=1 tx=0 len=16)
    09-04 16:01:00.418  5955  5955 D wpa_supplicant: WPA: RSC - hexdump(len=6): 00 00 00 00 00 00
    09-04 16:01:00.418  1398  1629 D WifiStateMachine:  L2ConnectedState !SUPPLICANT_STATE_CHANGE_EVENT rt=19506401/19506401 0 0 SSID: eda51_roam_test BSSID: 70:3d:15:1a:31:38 nid: 0 state: GROUP_HANDSHAKE
    09-04 16:01:00.419  5955  5955 D wpa_supplicant: wpa_driver_nl80211_set_key: ifindex=22 (wlan0) alg=3 addr=0x6075bec231 key_idx=1 set_tx=0 seq_len=6 key_len=16
    09-04 16:01:00.419  5955  5955 D wpa_supplicant: nl80211: KEY_DATA - hexdump(len=16): [REMOVED]
    09-04 16:01:00.419  5955  5955 D wpa_supplicant: nl80211: KEY_SEQ - hexdump(len=6): 00 00 00 00 00 00
    09-04 16:01:00.419  1398  1629 D WifiStateMachine:  ConnectModeState !SUPPLICANT_STATE_CHANGE_EVENT rt=19506401/19506401 0 0 SSID: eda51_roam_test BSSID: 70:3d:15:1a:31:38 nid: 0 state: GROUP_HANDSHAKE
    09-04 16:01:00.419  5955  5955 D wpa_supplicant:    broadcast key
    09-04 16:01:00.419  1398  1629 D SupplicantStateTracker: CompletedState{ when=0 what=147462 obj= SSID: eda51_roam_test BSSID: 70:3d:15:1a:31:38 nid: 0 state: GROUP_HANDSHAKE target=com.android.internal.util.StateMachine$SmHandler }
    09-04 16:01:00.420  5955  5955 I wpa_supplicant: wlan0: WPA: Key negotiation completed with 70:3d:15:1a:31:38 [PTK=CCMP GTK=CCMP]
    09-04 16:01:00.420  5955  5955 D wpa_supplicant: wlan0: Cancelling authentication timeout
    09-04 16:01:00.421  5955  5955 D wpa_supplicant: wlan0: State: GROUP_HANDSHAKE -> COMPLETED
    
    
    四次握手：kernel
    16:01:00.398896  [16:01:00.383270] [00000057392A15C3] [VosRX] wlan: [I :TL ] This is RX UC frame
    16:01:00.399110  [16:01:00.383275] [00000057392A1622] [VosRX] wlan: [IM:TL ] ****Received rate Index = 0 type=2 subtype=8****
    16:01:00.399288  [16:01:00.383284] [00000057392A16D3] [VosRX] wlan: [I :TL ] WLAN TL:RX Frame  EAPOL EtherType 34958 - processing
    16:01:00.399467  [16:01:00.383435] [00000057392A2229] [VosRX] wlan: [I :HDD] wlan_hdd_log_eapol: 3222: RX: M1 packet                // 第一次握手
    16:01:00.399688  [16:01:00.383440] [00000057392A228E] [VosRX] wlan: [I :HDD] STA RX EAPOL                                                            // 接收
    16:01:00.399910  [16:01:00.383496] [00000057392A26BD] [VosRX] wlan: [I :VOS] VPKT [1428]: [0000000000000000] Packet returned, type 3[RX_RAW]
    16:01:00.400117  [16:01:00.383748] [00000057392A39B8] [VosMC] wlan: [IM:HDD] ULA auth StaId= 3. Changing TL state to CONNECTEDat Join time
    16:01:00.400301  [16:01:00.383759] [00000057392A3A7F] [VosMC] wlan: [IL:HDD] hdd_wmm_assoc: Entered
    16:01:00.400472  [16:01:00.383764] [00000057392A3ADA] [VosMC] wlan: [IL:HDD] hdd_wmm_assoc: U-APSD mask is 0x00
    16:01:00.400642  [16:01:00.383774] [00000057392A3B96] [VosMC] wlan: [I :SME] sme_UpdateDSCPtoUPMapping: QOS Mapping IE not present
    16:01:00.400816  [16:01:00.383778] [00000057392A3BEA] [VosMC] wlan: [IL:HDD] hdd_wmm_init: Entered
    16:01:00.400991  [16:01:00.383782] [00000057392A3C2F] [VosMC] wlan: [IL:HDD] hdd_wmm_assoc: Exiting
    16:01:00.401157  [16:01:00.383787] [00000057392A3C89] [VosMC] wlan: [I :HDD] hdd_AssociationCompletionHandler: 2617: Enabling queues
    16:01:00.401310  [16:01:00.383836] [00000057392A4042] [VosMC] wlan: [I :HDD] wlan_hdd_sta_tdls_init: 1086: TDLS INIT DONE set to 1, no point in re-init
    16:01:00.401459  [16:01:00.383841] [00000057392A40A6] [VosMC] wlan: [I :HDD] wlan_hdd_tdls_connection_callback, update 2000 discover 20000
    16:01:00.401606  [16:01:00.384127] [00000057392A5621] [VosMC] wlan: [W :SME] csrRoamCompletion: 11405:   indicates association completion. roamResult = 0
    16:01:00.401751  [16:01:00.384140] [00000057392A5713] [VosMC] wlan: [IH:HDD] CSR Callback: status= 5 result= 0 roamID=0
    16:01:00.401902  [16:01:00.384154] [00000057392A5812] [VosMC] wlan: [I :SME] csrRoamProcessResults: 6022: Set full_power_till_set_key to make sure we wait until keys are set before going to BMPS
    16:01:00.402059  [16:01:00.384160] [00000057392A588A] [VosMC] wlan: [I :PMC] pmcStartTrafficTimer: 886: Enter. Timer duration is 8000
    16:01:00.402213  [16:01:00.384167] [00000057392A5914] [VosMC] wlan: [IH:VOS] Timer Addr inside voss_start : 0x0000000000000000 
    16:01:00.402369  [16:01:00.384185] [00000057392A5A6A] [VosMC] wlan: [IH:VOS] vos_timer_stop: Timer Addr inside voss_stop : 0x0000000000000000
    16:01:00.402524  [16:01:00.384262] [00000057392A602F] [VosMC] wlan: [I :VOS] VosMCThread: Servicing the VOS SYS MC Message queue
    16:01:00.402688  [16:01:00.384274] [00000057392A6110] [VosMC] wlan: [IH:VOS] Timer Addr inside voss_start : 0x0000000000000000 
    16:01:00.402842  [16:01:00.384281] [00000057392A619E] [VosMC] wlan: [I :VOS] VosMCThread: Servicing the VOS WDA MC Message queue
    16:01:00.403013  [16:01:00.384287] [00000057392A6213] [VosMC] wlan: [IL:WDA] =========> WDA_McProcessMsg msgType: 1130 
    16:01:00.403194  [16:01:00.384340] [00000057392A6608] [VosMC] wlan: [IH:VOS] vos_list_remove_front: list empty
    16:01:00.403384  [16:01:00.384347] [00000057392A668C] [VosMC] wlan: [I :VOS] VosMCThread: Servicing the VOS PE MC Message queue
    16:01:00.403569  [16:01:00.384359] [00000057392A6770] [VosMC] wlan: [I :SYS] tx_timer_deactivate() called for timer Heartbeat TIMEOUT
    16:01:00.403892  [16:01:00.384363] [00000057392A67C4] [VosMC] wlan: [IH:VOS] vos_timer_stop: Timer Addr inside voss_stop : 0x0000000000000000
    16:01:00.404048  [16:01:00.384368] [00000057392A6820] [VosMC] wlan: [IH:VOS] vos_timer_stop: Cannot stop timer in state = 19
    16:01:00.404207  [16:01:00.384374] [00000057392A6898] [VosMC] wlan: [W :PE ] limDeactivateAndChangeTimer: 1498: Deactivated heartbeat link monitoring
    16:01:00.406261  [16:01:00.384381] [00000057392A691A] [VosMC] wlan: [W :PE ] limDeactivateAndChangeTimer: 1530: HeartBeat timer value is changed = 0
    16:01:00.406427  [16:01:00.384408] [00000057392A6B2A] [VosMC] wlan: [I :PMC] pmmSendPowerSaveCfg: 799: pmmBmps: Sending WDA_PWR_SAVE_CFG to HAL
    16:01:00.406567  [16:01:00.384418] [00000057392A6BE3] [VosMC] wlan: [I :VOS] VosMCThread: Servicing the VOS WDA MC Message queue
    16:01:00.406704  [16:01:00.384423] [00000057392A6C45] [VosMC] wlan: [IL:WDA] =========> WDA_McProcessMsg msgType: 105e 
    16:01:00.406841  [16:01:00.384429] [00000057392A6CB1] [VosMC] wlan: [I :WDA] ------> WDA_ProcessSetPwrSaveCfgReq 
    16:01:00.406975  [16:01:00.384474] [00000057392A7010] [VosMC] wlan: [IH:VOS] Timer Addr inside voss_start : 0x0000000000000000 
    16:01:00.407110  [16:01:00.385179] [00000057392AA519] [wpa_s] wlan: [I :HDD] Enter:__wlan_hdd_cfg80211_dump_survey
    16:01:00.407304  [16:01:00.385448] [00000057392AB934] [cnss_] wlan: [I :HDD] __wlan_hdd_cfg80211_get_wifi_info: 6759: Rcvd req for FW version FW version is CNSS-PR-4-0-509-158621-1
    16:01:00.407450  [16:01:00.386824] [00000057392B2076] [VosMC] wlan: [IH:VOS] vos_timer_stop: Timer Addr inside voss_stop : 0x0000000000000000
    16:01:00.407595  [16:01:00.386840] [00000057392B2191] [VosMC] wlan: [I :WDA] <------ WDA_SetPwrSaveCfgReqCallback 
    16:01:00.407732  [16:01:00.386875] [00000057392B242F] [VosMC] wlan: [IH:VOS] vos_list_remove_front: list empty
    16:01:00.407877  [16:01:00.387576] [00000057392B58DB] [cnss_] wlan: [I :HDD] __wlan_hdd_cfg80211_get_wifi_info: 6759: Rcvd req for FW version FW version is CNSS-PR-4-0-509-158621-1
    16:01:00.408018  [16:01:00.392035] [00000057392CA743] [wpa_s] wlan: [I :HDD] Exit:__wlan_hdd_cfg80211_del_key
    16:01:00.408163  [16:01:00.392320] [00000057392CBC9F] [wpa_s] wlan: [I :HDD] Exit:__wlan_hdd_cfg80211_del_key
    16:01:00.408310  [16:01:00.392899] [00000057392CE814] [wpa_s] wlan: [I :HDD] Exit:__wlan_hdd_cfg80211_del_key
    16:01:00.408449  [16:01:00.393270] [00000057392D03E1] [wific] wlan: [I :HDD] Enter:__wlan_hdd_cfg80211_get_station
    16:01:00.408675  [16:01:00.393280] [00000057392D0498] [wific] wlan: [I :HDD] __wlan_hdd_cfg80211_get_station: Roaming in progress, so unable to proceed this request
    16:01:00.408813  [16:01:00.393448] [00000057392D113A] [wpa_s] wlan: [I :HDD] Enter:__wlan_hdd_change_station
    16:01:00.408960  [16:01:00.393458] [00000057392D11E5] [wpa_s] wlan: [I :HDD] Exit:__wlan_hdd_change_station
    16:01:00.409098  [16:01:00.394157] [00000057392D4667] [cnss_] wlan: [I :HDD] __wlan_hdd_cfg80211_get_wifi_info: 6759: Rcvd req for FW version FW version is CNSS-PR-4-0-509-158621-1
    16:01:00.409312  [16:01:00.394741] [00000057392D7246] [cnss_] wlan: [I :HDD] __wlan_hdd_cfg80211_get_wifi_info: 6759: Rcvd req for FW version FW version is CNSS-PR-4-0-509-158621-1
    16:01:00.409470  [16:01:00.395345] [00000057392D9F98] [cnss_] wlan: [I :HDD] __wlan_hdd_cfg80211_get_wifi_info: 6759: Rcvd req for FW version FW version is CNSS-PR-4-0-509-158621-1
    16:01:00.409630  [16:01:00.395958] [00000057392DCD82] [cnss_] wlan: [I :HDD] __wlan_hdd_cfg80211_get_wifi_info: 6759: Rcvd req for FW version FW version is CNSS-PR-4-0-509-158621-1
    16:01:00.409839  [16:01:00.396674] [00000057392E0331] [cnss_] wlan: [I :HDD] __wlan_hdd_cfg80211_get_wifi_info: 6759: Rcvd req for FW version FW version is CNSS-PR-4-0-509-158621-1
    16:01:00.410002  [16:01:00.402372] [00000057392FAE93] [wpa_s] wlan: [IL:HDD] hdd_wmm_select_queue: up=6 QIndex:4
    16:01:00.410166  [16:01:00.402385] [00000057392FAF68] [wpa_s] wlan: [IL:HDD] hdd_wmm_select_queue: up=6 QIndex:4
    16:01:00.410313  [16:01:00.402415] [00000057392FB1AD] [wpa_s] wlan: [I :HDD] __hdd_hard_start_xmit It must be a Eapol/Wapi/DHCP packet device_mode:0
    16:01:00.410526  [16:01:00.402424] [00000057392FB250] [wpa_s] wlan: [I :TL ] WLAN TL:Packet pending indication for STA: 3 AC: 4
    16:01:00.410674  [16:01:00.402431] [00000057392FB2E4] [wpa_s] wlan: [IH:TL ] WLAN TL:Packet pending indication for STA: 3 AC: 4 State: 1
    16:01:00.410842  [16:01:00.402436] [00000057392FB33B] [wpa_s] wlan: [IH:TL ] Serializing WDA TX Start Xmit event
    16:01:00.410996  [16:01:00.402786] [00000057392FCD92] [VosTX] wlan: [I :VOS] VosTXThread: Servicing the VOS TL TX Message queue
    16:01:00.411224  [16:01:00.402806] [00000057392FCEFF] [VosTX] wlan: [I :TL ] WLAN TL: WLANTL_STATxConn fetching packet from HDD for AC: 4 AC Mask: 0 Pkt Pending: 0
    16:01:00.411384  [16:01:00.402817] [00000057392FCFCB] [VosTX] wlan: [I :VOS] VPKT [963]: [0000000000000000] Packet allocated, type TX_802_3_DATA
    
    16:01:00.416780  [16:01:00.403016] [00000057392FDECE] [VosTX] wlan: [I :HDD] wlan_hdd_log_eapol: 3227: TX: M2 packet        // 第二个包
    16:01:00.416951  [16:01:00.403042] [00000057392FE0BC] [VosTX] wlan: [I :HDD] STA TX EAPOL                                                    // 发送
    16:01:00.417105  [16:01:00.403047] [00000057392FE114] [VosTX] wlan: [I :HDD] hdd_tx_fetch_packet_cbk :STA TX ARP Received in TL 
    16:01:00.417602  [16:01:00.403072] [00000057392FE2F1] [VosTX] wlan: [IL:TL ] WLAN TL: Dump TX meta info: txFlags:4, qosEnabled:1, ac:6, isEapol:1, fdisableFrmXlt:1, frmType:2
    16:01:00.417816  [16:01:00.403078] [00000057392FE367] [VosTX] wlan: [IH:TL ] WLAN TL:GetFrames STA: 3 EAPOLPktPending 0
    16:01:00.418066  [16:01:00.403084] [00000057392FE3DE] [VosTX] wlan: [I :TL ] WLAN TL: WLANTL_STATxConn fetching packet from HDD for AC: 4 AC Mask: 0 Pkt Pending: 0
    16:01:00.418268  [16:01:00.403090] [00000057392FE448] [VosTX] wlan: [I :TL ] WLAN TL:No more data at HDD status 16
    16:01:00.418439  [16:01:00.403094] [00000057392FE49A] [VosTX] wlan: [I :TL ] WLAN TL: WLANTL_STATxConn no more packets in HDD for AC: 4 AC Mask: 0
    16:01:00.418615  [16:01:00.403123] [00000057392FE6C0] [VosTX] wlan: [I :HDD] WDTS_TxPacket :Transmitting ARP packet
    16:01:00.418793  [16:01:00.403174] [00000057392FEA93] [VosTX] wlan: [IH:TL ] WLAN TL:No station registered with TL at this point
    16:01:00.418970  [16:01:00.403188] [00000057392FEB9D] [VosTX] wlan: [I :WDI] WDTS_TxPacketComplete: Management frame Tx complete status: 0
    16:01:00.419159  [16:01:00.403211] [00000057392FED62] [VosTX] wlan: [I :VOS] VPKT [1428]: [0000000000000000] Packet returned, type 2[TX_802_3_DATA]
    16:01:00.419345  [16:01:00.404711] [0000005739305DF2] [cnss_] wlan: [I :HDD] __wlan_hdd_cfg80211_get_wifi_info: 6759: Rcvd req for FW version FW version is CNSS-PR-4-0-509-158621-1
    16:01:00.419551  [16:01:00.405222] [000000573930844A] [cnss_] wlan: [I :HDD] __wlan_hdd_cfg80211_get_wifi_info: 6759: Rcvd req for FW version FW version is CNSS-PR-4-0-509-158621-1
    16:01:00.419756  [16:01:00.405772] [000000573930AD8D] [cnss_] wlan: [I :HDD] __wlan_hdd_cfg80211_get_wifi_info: 6759: Rcvd req for FW version FW version is CNSS-PR-4-0-509-158621-1
    16:01:00.419958  [16:01:00.411968] [0000005739327E42] [VosRX] wlan: [I :VOS] VPKT [779]: [0000000000000000] Packet allocated, type 3[RX_RAW]
    16:01:00.420156  [16:01:00.412004] [00000057393280D7] [VosRX] wlan: [I :VOS] VPKT [779]: [0000000000000000] Packet allocated, type 3[RX_RAW]
    16:01:00.420325  [16:01:00.412035] [0000005739328324] [VosRX] wlan: [I :TL ] Management Frame, not need to handle with Stat
    16:01:00.420702  [16:01:00.412080] [0000005739328694] [VosRX] wlan: [I :TL ] This is RX UC frame
    16:01:00.421034  [16:01:00.412085] [00000057393286F5] [VosRX] wlan: [IM:TL ] ****Received rate Index = 0 type=2 subtype=8****
    16:01:00.421304  [16:01:00.412092] [0000005739328769] [VosRX] wlan: [I :TL ] Current new Data RSSI is -44, averaged Data RSSI is -53
    16:01:00.421561  [16:01:00.412100] [0000005739328809] [VosRX] wlan: [I :TL ] WLAN TL:RX Frame  EAPOL EtherType 34958 - processing
    
    16:01:00.421831  [16:01:00.412276] [000000573932953B] [VosRX] wlan: [I :HDD] wlan_hdd_log_eapol: 3234: RX: M3 packet            // 第三个包
    16:01:00.422151  [16:01:00.412281] [000000573932959F] [VosRX] wlan: [I :HDD] STA RX EAPOL                                                    // 发送
    16:01:00.422352  [16:01:00.412291] [0000005739329662] [VosMC] wlan: [I :VOS] VosMCThread: Servicing the VOS PE MC Message queue
    16:01:00.422529  [16:01:00.412314] [0000005739329811] [VosMC] wlan: [I :VOS] vos_list_peek_next: list empty
    16:01:00.422812  [16:01:00.412346] [0000005739329A7C] [VosRX] wlan: [I :VOS] VPKT [1428]: [0000000000000000] Packet returned, type 3[RX_RAW]
    16:01:00.423016  [16:01:00.412454] [000000573932A29A] [VosMC] wlan: [I :PE ] limEncTypeMatched: 1815: Beacon/Probe:: Privacy :1 WPA Present:1 RSN Present: 1
    16:01:00.423216  [16:01:00.412460] [000000573932A315] [VosMC] wlan: [I :PE ] limEncTypeMatched: 1819: pSession:: Privacy :1 EncyptionType: 4 WPS 0 OSEN 0
    16:01:00.423552  [16:01:00.412497] [000000573932A5CE] [VosMC] wlan: [I :VOS] VPKT [1428]: [0000000000000000] Packet returned, type 3[RX_RAW]
    16:01:00.423805  [16:01:00.413233] [000000573932DD0D] [cnss_] wlan: [I :HDD] __wlan_hdd_cfg80211_get_wifi_info: 6759: Rcvd req for FW version FW version is CNSS-PR-4-0-509-158621-1
    16:01:00.424046  [16:01:00.413661] [000000573932FD28] [cnss_] wlan: [I :HDD] __wlan_hdd_cfg80211_get_wifi_info: 6759: Rcvd req for FW version FW version is CNSS-PR-4-0-509-158621-1
    16:01:00.424261  [16:01:00.414148] [00000057393321A7] [wpa_s] wlan: [IL:HDD] hdd_wmm_select_queue: up=6 QIndex:4
    16:01:00.424521  [16:01:00.414156] [0000005739332240] [wpa_s] wlan: [IL:HDD] hdd_wmm_select_queue: up=6 QIndex:4
    16:01:00.428462  [16:01:00.414185] [0000005739332466] [wpa_s] wlan: [I :HDD] __hdd_hard_start_xmit It must be a Eapol/Wapi/DHCP packet device_mode:0
    16:01:00.428803  [16:01:00.414212] [000000573933266B] [wpa_s] wlan: [I :TL ] WLAN TL:Packet pending indication for STA: 3 AC: 4
    16:01:00.429820  [16:01:00.414218] [00000057393326EA] [wpa_s] wlan: [IH:TL ] WLAN TL:Packet pending indication for STA: 3 AC: 4 State: 1
    16:01:00.430116  [16:01:00.414223] [000000573933274C] [wpa_s] wlan: [IH:TL ] Serializing WDA TX Start Xmit event
    16:01:00.430331  [16:01:00.414518] [0000005739333D62] [VosTX] wlan: [I :VOS] VosTXThread: Servicing the VOS TL TX Message queue
    16:01:00.430528  [16:01:00.414533] [0000005739333E89] [VosTX] wlan: [I :TL ] WLAN TL: WLANTL_STATxConn fetching packet from HDD for AC: 4 AC Mask: 0 Pkt Pending: 0
    16:01:00.430708  [16:01:00.414543] [0000005739333F49] [VosTX] wlan: [I :VOS] VPKT [963]: [0000000000000000] Packet allocated, type TX_802_3_DATA
    16:01:00.430870  [16:01:00.414602] [00000057393343AE] [wpa_s] wlan: [I :HDD] Enter:__wlan_hdd_cfg80211_add_key
    16:01:00.431038  [16:01:00.414610] [000000573933444F] [wpa_s] wlan: [I :HDD] __wlan_hdd_cfg80211_add_key: device_mode = WLAN_HDD_INFRA_STATION (0)
    16:01:00.431194  [16:01:00.414616] [00000057393344C1] [wpa_s] wlan: [I :HDD] __wlan_hdd_cfg80211_add_key: called with key index = 0 & key length 16 & seq length 6
    16:01:00.431350  [16:01:00.414621] [0000005739334516] [wpa_s] wlan: [IM:HDD] __wlan_hdd_cfg80211_add_key: encryption type 6
    16:01:00.431504  [16:01:00.414626] [0000005739334580] [wpa_s] wlan: [I :HDD] __wlan_hdd_cfg80211_add_key- 13077: setting pairwise key
    16:01:00.431664  [16:01:00.414634] [0000005739334610] [wpa_s] wlan: [IM:HDD] __wlan_hdd_cfg80211_add_key: set key for peerMac 70:3d:15:1a:31:38, direction 2
    16:01:00.431829  [16:01:00.414640] [0000005739334690] [wpa_s] wlan: [IH:TL ] Serializing WDA_DS_FinishULA event
    
    16:01:00.432003  [16:01:00.414710] [0000005739334BCD] [VosTX] wlan: [I :HDD] wlan_hdd_log_eapol: 3240: TX: M4 packet            // 第四个包
    16:01:00.432188  [16:01:00.414716] [0000005739334C46] [VosTX] wlan: [I :HDD] STA TX EAPOL
    16:01:00.432380  [16:01:00.414721] [0000005739334C98] [VosTX] wlan: [I :HDD] hdd_tx_fetch_packet_cbk :STA TX ARP Received in TL 
    16:01:00.432583  [16:01:00.414738] [0000005739334DE5] [VosTX] wlan: [IL:TL ] WLAN TL: Dump TX meta info: txFlags:4, qosEnabled:1, ac:6, isEapol:1, fdisableFrmXlt:1, frmType:2
    16:01:00.432768  [16:01:00.414745] [0000005739334E65] [VosTX] wlan: [IH:TL ] WLAN TL:GetFrames STA: 3 EAPOLPktPending 0
    16:01:00.432942  [16:01:00.414752] [0000005739334EF7] [VosTX] wlan: [I :TL ] WLAN TL: WLANTL_STATxConn fetching packet from HDD for AC: 4 AC Mask: 0 Pkt Pending: 0
    16:01:00.433113  [16:01:00.414757] [0000005739334F49] [VosTX] wlan: [I :TL ] WLAN TL:No more data at HDD status 16
    16:01:00.433278  [16:01:00.414761] [0000005739334FA3] [VosTX] wlan: [I :TL ] WLAN TL: WLANTL_STATxConn no more packets in HDD for AC: 4 AC Mask: 0
    16:01:00.433440  [16:01:00.414797] [000000573933525C] [VosTX] wlan: [I :HDD] WDTS_TxPacket :Transmitting ARP packet
    16:01:00.433602  [16:01:00.414860] [0000005739335708] [VosTX] wlan: [IH:TL ] WLAN TL:No station registered with TL at this point
    16:01:00.433765  [16:01:00.414882] [00000057393358AA] [VosTX] wlan: [I :WDI] WDTS_TxPacketComplete: Management frame Tx complete status: 0