wpa_supplicant的log中四次握手分析

06-04 16:23:30.248 I/wpa_supplicant( 1465): wlan0: Associated with d8:63:75:3e:0f:f3   //关联
06-04 16:23:30.248 D/wpa_supplicant( 1465): wlan0: WPA: Association event - clear replay counter
06-04 16:23:30.248 D/wpa_supplicant( 1465): wlan0: WPA: Clear old PTK  //清除Authorized原来的PTK，每次连接的PTK都是不一样的。
06-04 16:23:30.248 D/wpa_supplicant( 1465): TDLS: Remove peers on association
06-04 16:23:30.248 D/wpa_supplicant( 1465): EAPOL: External notification - portEnabled=0
06-04 16:23:30.248 D/wpa_supplicant( 1465): EAPOL: External notification - portValid=0
06-04 16:23:30.248 D/wpa_supplicant( 1465): EAPOL: External notification - EAP success=0
06-04 16:23:30.248 D/wpa_supplicant( 1465): EAPOL: External notification - portEnabled=1
06-04 16:23:30.248 D/wpa_supplicant( 1465): EAPOL: SUPP_PAE entering state CONNECTING
06-04 16:23:30.248 D/wpa_supplicant( 1465): EAPOL: enable timer tick
06-04 16:23:30.248 D/wpa_supplicant( 1465): EAPOL: SUPP_BE entering state IDLE
06-04 16:23:30.248 D/wpa_supplicant( 1465): wlan0: Setting authentication timeout: 10 sec 0 usec  //设置认证超时时间10s，也就是说四次握手的超时时间是10秒，如果四次握手出错，将会有10秒时间继续握手
// 这10秒内数据连接是有问题的。10s过后才会重新认证，关联
06-04 16:23:30.248 D/wpa_supplicant( 1465): wlan0: Cancelling scan request
06-04 16:23:30.248 D/wpa_supplicant( 1465): WMM AC: AC mandatory: AC_BE=0 AC_BK=0 AC_VI=0 AC_VO=0
06-04 16:23:30.248 D/wpa_supplicant( 1465): WMM AC: U-APSD queues=0x0
06-04 16:23:30.248 D/wpa_supplicant( 1465): WMM AC: Valid WMM association, WMM AC is enabled
06-04 16:23:30.248 I/wpa_supplicant( 1465): wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0
第一次握手，EAPOL-Key包含AP生成的Nonce(ANonce) 
06-04 16:23:30.334 D/wpa_supplicant( 1465): l2_packet_receive: src=d8:63:75:3e:0f:f3 len=99
06-04 16:23:30.335 D/wpa_supplicant( 1465): wlan0: RX EAPOL from d8:63:75:3e:0f:f3   //第一次握手，收到EAPOL包
06-04 16:23:30.335 D/wpa_supplicant( 1465): RX EAPOL - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 01 ee ff 60 66 b2 1c b9 0d ee dd 59 51 ab e4 3a ...
06-04 16:23:30.335 D/wpa_supplicant( 1465): wlan0: Setting authentication timeout: 10 sec 0 usec
06-04 16:23:30.335 D/wpa_supplicant( 1465): wlan0: IEEE 802.1X RX: version=2 type=3 length=95
06-04 16:23:30.335 D/wpa_supplicant( 1465): WPA: RX EAPOL-Key - hexdump(len=99): 02 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 01 ee ff 60 66 b2 1c b9 0d ee dd 59 51 ab e4 3a ...
06-04 16:23:30.335 D/wpa_supplicant( 1465): wlan0:   EAPOL-Key type=2
06-04 16:23:30.335 D/wpa_supplicant( 1465): wlan0:   key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
06-04 16:23:30.335 D/wpa_supplicant( 1465): wlan0:   key_length=16 key_data_length=0
06-04 16:23:30.335 D/wpa_supplicant( 1465):   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 01
06-04 16:23:30.335 D/wpa_supplicant( 1465):   key_nonce - hexdump(len=32): ee ff 60 66 b2 1c b9 0d ee dd 59 51 ab e4 3a c9 01 9b 4d fb c7 70 88 8a be c6 d6 a8 7a 82 33 9e
06-04 16:23:30.335 D/wpa_supplicant( 1465):   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
06-04 16:23:30.335 D/wpa_supplicant( 1465):   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
06-04 16:23:30.335 D/wpa_supplicant( 1465):   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
06-04 16:23:30.335 D/wpa_supplicant( 1465):   key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
06-04 16:23:30.335 D/wpa_supplicant( 1465): wlan0: State: ASSOCIATED -> 4WAY_HANDSHAKE
06-04 16:23:30.335 D/wpa_supplicant( 1465): Notifying state change event to hidl control: 7
06-04 16:23:30.335 D/wpa_supplicant( 1465): wlan0: Determining shared radio frequencies (max len 2)
06-04 16:23:30.335 D/wpa_supplicant( 1465): wlan0: Shared frequencies (len=1): completed iteration
06-04 16:23:30.335 D/wpa_supplicant( 1465): wlan0: freq[0]: 2422, flags=0x1
06-04 16:23:30.336 I/wpa_supplicant( 1465): wlan0: WPA: RX message 1 of 4-Way Handshake from d8:63:75:3e:0f:f3 (ver=2)   //提示四次握手的第一个包
06-04 16:23:30.336 D/wpa_supplicant( 1465): RSN: msg 1/4 key data - hexdump(len=0):
//第二次握手
Supplicant生成SNonce
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: Renewed SNonce - hexdump(len=32): c6 1c 24 87 3c d1 60 d3 b6 12 9b 82 44 d4 b6 c8 a4 f8 5b d4 5d 30 96 c7 c8 95 7e cf 0a 7f 96 58
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: PTK derivation using PRF(SHA1)
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: PTK derivation - A1=40:45:da:ff:3c:bd A2=d8:63:75:3e:0f:f3
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: Nonce1 - hexdump(len=32): c6 1c 24 87 3c d1 60 d3 b6 12 9b 82 44 d4 b6 c8 a4 f8 5b d4 5d 30 96 c7 c8 95 7e cf 0a 7f 96 58
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: Nonce2 - hexdump(len=32): ee ff 60 66 b2 1c b9 0d ee dd 59 51 ab e4 3a c9 01 9b 4d fb c7 70 88 8a be c6 d6 a8 7a 82 33 9e
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: PMK - hexdump(len=32): 98 0b 9c 55 85 14 72 db 2b 50 2a 3a 5c e1 c2 d6 e0 70 1b 34 d6 5a 23 44 be a0 2a 38 3b d2 72 43
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: PTK - hexdump(len=48): ce 5f c9 36 e4 06 8d 40 f7 4d a8 3e 2c ed 24 c6 49 39 08 08 cb 63 1d 73 96 5f 5d 33 e7 6f c6 21 ...
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: KCK - hexdump(len=16): ce 5f c9 36 e4 06 8d 40 f7 4d a8 3e 2c ed 24 c6
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: KEK - hexdump(len=16): 49 39 08 08 cb 63 1d 73 96 5f 5d 33 e7 6f c6 21
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: TK - hexdump(len=16): 44 61 6d 7d 4c ea ca 00 cc e1 cd 94 cd 1f b9 15
06-04 16:23:30.336 D/wpa_supplicant( 1465): 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 00 00
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 01
06-04 16:23:30.336 I/wpa_supplicant( 1465): wlan0: WPA: Sending EAPOL-Key 2/4
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: Send EAPOL-Key frame to d8:63:75:3e:0f:f3 ver=2 mic_len=16 key_mgmt=0x2
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: EAPOL-Key MIC using HMAC-SHA1
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: KCK - hexdump(len=16): ce 5f c9 36 e4 06 8d 40 f7 4d a8 3e 2c ed 24 c6
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: Derived Key MIC - hexdump(len=16): 78 a6 2e 51 72 57 24 02 4f ff be 15 6e a5 ec fe
06-04 16:23:30.336 D/wpa_supplicant( 1465): WPA: TX EAPOL-Key - hexdump(len=121): 01 03 00 75 02 01 0a 00 00 00 00 00 00 00 00 00 01 c6 1c 24 87 3c d1 60 d3 b6 12 9b 82 44 d4 b6 ...
06-04 16:23:30.583 W/SettingsLib.AccessPoint( 1161): Received abnormal flag string: [WPA2-FT/PSK-CCMP][ESS]
06-04 16:23:30.584 D/wpa_supplicant( 1465): nl80211: Event message available
06-04 16:23:30.584 D/wpa_supplicant( 1465): nl80211: Ignored event (cmd=33) for foreign interface (ifindex 15 wdev 0x0)
06-04 16:23:30.584 D/wpa_supplicant( 1465): nl80211: Drv Event 33 (NL80211_CMD_TRIGGER_SCAN) received for wlan0
06-04 16:23:30.584 D/wpa_supplicant( 1465): wlan0: nl80211: Scan trigger
06-04 16:23:30.585 D/wpa_supplicant( 1465): wlan0: Event SCAN_STARTED (46) received
06-04 16:23:30.585 D/wpa_supplicant( 1465): wlan0: External program started a scan
06-04 16:23:30.607 D/wpa_supplicant( 1465): l2_packet_receive: src=d8:63:75:3e:0f:f3 len=155
//第三次握手， AP派生密钥，发送supplicant
06-04 16:23:30.607 D/wpa_supplicant( 1465): wlan0: RX EAPOL from d8:63:75:3e:0f:f3  //第三次握手，收到AP发过来的EAPOL包
06-04 16:23:30.608 D/wpa_supplicant( 1465): RX EAPOL - hexdump(len=155): 02 03 00 97 02 13 ca 00 10 00 00 00 00 00 00 00 02 ee ff 60 66 b2 1c b9 0d ee dd 59 51 ab e4 3a ...
06-04 16:23:30.608 D/wpa_supplicant( 1465): wlan0: IEEE 802.1X RX: version=2 type=3 length=151
06-04 16:23:30.608 D/wpa_supplicant( 1465): WPA: RX EAPOL-Key - hexdump(len=155): 02 03 00 97 02 13 ca 00 10 00 00 00 00 00 00 00 02 ee ff 60 66 b2 1c b9 0d ee dd 59 51 ab e4 3a ...
06-04 16:23:30.608 D/wpa_supplicant( 1465): wlan0:   EAPOL-Key type=2
06-04 16:23:30.608 D/wpa_supplicant( 1465): wlan0:   key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
06-04 16:23:30.608 D/wpa_supplicant( 1465): wlan0:   key_length=16 key_data_length=56
06-04 16:23:30.608 D/wpa_supplicant( 1465):   replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 02
06-04 16:23:30.608 D/wpa_supplicant( 1465):   key_nonce - hexdump(len=32): ee ff 60 66 b2 1c b9 0d ee dd 59 51 ab e4 3a c9 01 9b 4d fb c7 70 88 8a be c6 d6 a8 7a 82 33 9e
06-04 16:23:30.608 D/wpa_supplicant( 1465):   key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
06-04 16:23:30.608 D/wpa_supplicant( 1465):   key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
06-04 16:23:30.609 D/wpa_supplicant( 1465):   key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
06-04 16:23:30.609 D/wpa_supplicant( 1465):   key_mic - hexdump(len=16): e7 3d b5 52 43 5e 42 16 74 8f d3 ef ab 86 12 3f
06-04 16:23:30.609 D/wpa_supplicant( 1465): WPA: EAPOL-Key MIC using HMAC-SHA1
06-04 16:23:30.609 D/wpa_supplicant( 1465): RSN: encrypted key data - hexdump(len=56): a1 33 bf 0c ef aa 16 5d 67 45 80 9e 71 37 cc a6 51 16 05 71 db 21 bc 5b 6c 2d 85 83 c0 fd d8 c1 ...
06-04 16:23:30.609 D/wpa_supplicant( 1465): WPA: Decrypt Key Data using AES-UNWRAP (KEK length 16)
06-04 16:23:30.609 D/wpa_supplicant( 1465): WPA: decrypted EAPOL-Key key data - hexdump(len=48): 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ac 02 0c 00 dd 16 00 0f ac 01 01 00 71 21 ...
06-04 16:23:30.609 D/wpa_supplicant( 1465): wlan0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
06-04 16:23:30.609 I/wpa_supplicant( 1465): wlan0: WPA: RX message 3 of 4-Way Handshake from d8:63:75:3e:0f:f3 (ver=2)  //四次握手第三个包
06-04 16:23:30.609 D/wpa_supplicant( 1465): 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 0c 00 dd 16 00 0f ac 01 01 00 71 21 ...
06-04 16:23:30.609 D/wpa_supplicant( 1465): 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 0c 00
06-04 16:23:30.609 D/wpa_supplicant( 1465): WPA: GTK in EAPOL-Key - hexdump(len=24): dd 16 00 0f ac 01 01 00 71 21 9e a9 cb cd 47 a4 c4 a1 23 05 3d a7 ce 34
//第四次握手
06-04 16:23:30.609 I/wpa_supplicant( 1465): wlan0: WPA: Sending EAPOL-Key 4/4 // 发送EAPOL包
06-04 16:23:30.609 D/wpa_supplicant( 1465): WPA: Send EAPOL-Key frame to d8:63:75:3e:0f:f3 ver=2 mic_len=16 key_mgmt=0x2
06-04 16:23:30.609 D/wpa_supplicant( 1465): WPA: EAPOL-Key MIC using HMAC-SHA1
06-04 16:23:30.609 D/wpa_supplicant( 1465): WPA: KCK - hexdump(len=16): ce 5f c9 36 e4 06 8d 40 f7 4d a8 3e 2c ed 24 c6
06-04 16:23:30.609 D/wpa_supplicant( 1465): WPA: Derived Key MIC - hexdump(len=16): bc 00 62 c8 8a da 44 28 b5 69 bb d9 1a 30 7b de
06-04 16:23:30.609 D/wpa_supplicant( 1465): WPA: TX EAPOL-Key - hexdump(len=99): 01 03 00 5f 02 03 0a 00 00 00 00 00 00 00 00 00 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ...
06-04 16:23:30.609 D/wpa_supplicant( 1465): wlan0: WPA: Installing PTK to the driver
06-04 16:23:30.609 D/wpa_supplicant( 1465): wpa_driver_nl80211_set_key: ifindex=15 (wlan0) alg=3 addr=0x77bb283368 key_idx=0 set_tx=1 seq_len=6 key_len=16
06-04 16:23:30.610 D/wpa_supplicant( 1465): nl80211: KEY_DATA - hexdump(len=16): 44 61 6d 7d 4c ea ca 00 cc e1 cd 94 cd 1f b9 15
06-04 16:23:30.610 D/wpa_supplicant( 1465): nl80211: KEY_SEQ - hexdump(len=6): 00 00 00 00 00 00
06-04 16:23:30.610 D/wpa_supplicant( 1465):    addr=d8:63:75:3e:0f:f3
06-04 16:23:30.962 D/wpa_supplicant( 1465): EAPOL: External notification - portValid=1
06-04 16:23:30.962 D/wpa_supplicant( 1465): wlan0: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
06-04 16:23:30.962 D/wpa_supplicant( 1465): Notifying state change event to hidl control: 8
06-04 16:23:30.962 D/wpa_supplicant( 1465): wlan0: Determining shared radio frequencies (max len 2)
06-04 16:23:30.962 D/wpa_supplicant( 1465): wlan0: Shared frequencies (len=1): completed iteration
06-04 16:23:30.962 D/wpa_supplicant( 1465): wlan0: freq[0]: 2422, flags=0x1
06-04 16:23:30.964 D/wpa_supplicant( 1465): RSN: received GTK in pairwise handshake - hexdump(len=18): 01 00 71 21 9e a9 cb cd 47 a4 c4 a1 23 05 3d a7 ce 34
06-04 16:23:30.964 D/wpa_supplicant( 1465): WPA: Group Key - hexdump(len=16): 71 21 9e a9 cb cd 47 a4 c4 a1 23 05 3d a7 ce 34
06-04 16:23:30.964 D/wpa_supplicant( 1465): wlan0: WPA: Installing GTK to the driver (keyidx=1 tx=0 len=16)
06-04 16:23:30.964 D/wpa_supplicant( 1465): WPA: RSC - hexdump(len=6): 00 00 00 00 00 00
06-04 16:23:30.966 D/wpa_supplicant( 1465): wpa_driver_nl80211_set_key: ifindex=15 (wlan0) alg=3 addr=0x57885f22b1 key_idx=1 set_tx=0 seq_len=6 key_len=16
06-04 16:23:30.966 D/wpa_supplicant( 1465): nl80211: KEY_DATA - hexdump(len=16): 71 21 9e a9 cb cd 47 a4 c4 a1 23 05 3d a7 ce 34
06-04 16:23:30.966 D/wpa_supplicant( 1465): nl80211: KEY_SEQ - hexdump(len=6): 00 00 00 00 00 00
06-04 16:23:30.966 D/wpa_supplicant( 1465):    broadcast key
06-04 16:23:31.026 I/wpa_supplicant( 1465): wlan0: WPA: Key negotiation completed with d8:63:75:3e:0f:f3 [PTK=CCMP GTK=CCMP]
06-04 16:23:31.026 D/wpa_supplicant( 1465): wlan0: Cancelling authentication timeout
06-04 16:23:31.026 D/wpa_supplicant( 1465): wlan0: State: GROUP_HANDSHAKE -> COMPLETED