Step 5: Device connects to a service
Due to a policy, shill specifies that the device automatically connects to service 0. If the user chooses to connect to a different Wi-Fi network, a different service number might be selected.
Logs
- wpa_supplicant prioritizes networks. If a network is more desirable, based on security policy, signal strength, and so on, you can increase its priority value. For Chrome, the priority group value doesn’t change. It's always priority group 0 in the logs.
localhost shill: [0815/104606:INFO:service.cc(255)] Auto-connecting to service 0
localhost shill: [0815/104606:INFO:service.cc(271)] Connect to service 0: AutoConnect
localhost wpa_supplicant[1111]: nl80211: Received scan results (100 BSSes)
localhost wpa_supplicant[1111]: wlan0: BSS: Start scan result update 65
localhost wpa_supplicant[1111]: wlan0: Selecting BSS from priority group 0
localhost wpa_supplicant[1111]: wlan0: 0: 74:44:01:71:cf:91 ssid='Network4' wpa_ie_len=0 rsn_ie_len=20 caps=0x11 level=-46
localhost wpa_supplicant[1111]: wlan0: skip - SSID mismatch
localhost wpa_supplicant[1111]: wlan0: 1: 00:24:6c:db:e4:d0 ssid='Network5' wpa_ie_len=0 rsn_ie_len=20 caps=0x511 level=-64
localhost wpa_supplicant[1111]: wlan0: skip - SSID mismatch
localhost wpa_supplicant[1111]: wlan0: 2: 00:24:6c:db:e4:d2 ssid='' wpa_ie_len=0 rsn_ie_len=20 caps=0x511 level=-64
localhost wpa_supplicant[1111]: wlan0: skip - SSID not known
localhost wpa_supplicant[1111]: wlan0: 3: 00:24:6c:60:f2:d2 ssid='' wpa_ie_len=0 rsn_ie_len=20 caps=0x511 level=-64
localhost wpa_supplicant[1111]: wlan0: skip - SSID not known
localhost wpa_supplicant[1111]: wlan0: 4: 00:24:6c:e2:c0:30 ssid='Network5' wpa_ie_len=0 rsn_ie_len=20 caps=0x511 level=-62
localhost wpa_supplicant[1111]: wlan0: skip - SSID mismatch
localhost wpa_supplicant[1111]: wlan0: 5: 00:24:6c:e2:c0:32 ssid='' wpa_ie_len=0 rsn_ie_len=20 caps=0x511 level=-61
localhost wpa_supplicant[1111]: wlan0: skip - SSID not known
localhost wpa_supplicant[1111]: wlan0: 6: 00:24:6c:db:c4:52 ssid='' wpa_ie_len=0 rsn_ie_len=20 caps=0x511 level=-65
localhost wpa_supplicant[1111]: wlan0: skip - SSID not known
localhost wpa_supplicant[1111]: wlan0: 7: 00:24:6c:60:f2:d0 ssid='Network5' wpa_ie_len=0 rsn_ie_len=20 caps=0x511 level=-65
localhost wpa_supplicant[1111]: wlan0: skip - SSID mismatch
localhost wpa_supplicant[1111]: wlan0: 8: 00:24:6c:db:cc:70 ssid='Network5' wpa_ie_len=0 rsn_ie_len=20 caps=0x511 level=-67
localhost wpa_supplicant[1111]: wlan0: skip - SSID mismatch
localhost wpa_supplicant[1111]: wlan0: 9: 00:24:6c:db:c4:50 ssid='Network5' wpa_ie_len=0 rsn_ie_len=20 caps=0x511 level=-66
localhost wpa_supplicant[1111]: wlan0: skip - SSID mismatch
localhost wpa_supplicant[1111]: wlan0: 10: 00:24:6c:db:cc:72 ssid='' wpa_ie_len=0 rsn_ie_len=20 caps=0x511 level=-68
localhost wpa_supplicant[1111]: wlan0: skip - SSID not known
localhost wpa_supplicant[1111]: wlan0: 11: 00:24:6c:60:e3:90 ssid='Network5' wpa_ie_len=0 rsn_ie_len=20 caps=0x511 level=-68
localhost wpa_supplicant[1111]: wlan0: skip - SSID mismatch
localhost wpa_supplicant[1111]: wlan0: 12: 00:24:6c:64:b1:b2 ssid='' wpa_ie_len=0 rsn_ie_len=20 caps=0x511 level=-68
localhost wpa_supplicant[1111]: wlan0: skip - SSID not known
localhost wpa_supplicant[1111]: wlan0: 13: b0:c7:45:6b:b1:97 ssid='Network1' wpa_ie_len=26 rsn_ie_len=24 caps=0x411 level=-37 wps
localhost wpa_supplicant[1111]: wlan0: selected based on RSN IE
localhost wpa_supplicant[1111]: wlan0: selected BSS b0:c7:45:6b:b1:97 ssid='Network1'
localhost wpa_supplicant[1111]: wlan0: Request association: reassociate: 1 selected: b0:c7:45:6b:b1:97 bssid: 00:00:00:00:00:00 pending: 00:00:00:00:00:00 wpa_state: INACTIVE
Step 6: Device performs authentication
wpa_supplicant starts the authentication phase on the device. Shill continues monitoring the state.
Logs
localhost wpa_supplicant[1111]: wlan0: SME: Trying to authenticate with b0:c7:45:6b:b1:97 (SSID='BUFFALO-6BB197' freq=2422 MHz)
localhost wpa_supplicant[1111]: wlan0: No keys have been configured - skip key clearing
localhost wpa_supplicant[1111]: wlan0: State: INACTIVE -> AUTHENTICATING
localhost wpa_supplicant[1111]: EAPOL: External notification - EAP success=0
localhost wpa_supplicant[1111]: EAPOL: Supplicant port status: Unauthorized
localhost wpa_supplicant[1111]: EAPOL: External notification - EAP fail=0
localhost wpa_supplicant[1111]: EAPOL: Supplicant port status: Unauthorized
localhost wpa_supplicant[1111]: EAPOL: External notification - portControl=Auto
localhost wpa_supplicant[1111]: EAPOL: Supplicant port status: Unauthorized
localhost wpa_supplicant[1111]: nl80211: Authenticate (ifindex=2)
localhost wpa_supplicant[1111]: * bssid=b0:c7:45:6b:b1:97
localhost wpa_supplicant[1111]: * freq=2422
localhost wpa_supplicant[1111]: * SSID - hexdump(len=14): 42 55 46 46 41 4c 4f 2d 36 42 42 31 39 37
localhost wpa_supplicant[1111]: * IEs - hexdump(len=0): [NULL]
localhost wpa_supplicant[1111]: * Auth Type 0
localhost wpa_supplicant[1111]: nl80211: Authentication request send successfully
localhost wpa_supplicant[1111]: wlan0: Fast associate: Connect initiated!
localhost shill: [0815/104606:VERBOSE2:wifi.cc(1758)] WiFi wlan0 setting pending service to 0
localhost wpa_supplicant[1111]: nl80211: Event message available
localhost wpa_supplicant[1111]: nl80211: New station b0:c7:45:6b:b1:97
localhost wpa_supplicant[1111]: nl80211: Event message available
localhost wpa_supplicant[1111]: nl80211: MLME event 37
localhost wpa_supplicant[1111]: nl80211: MLME event frame - hexdump(len=30): b0 00 3a 01 9c d2 1e 60 3b 71 b0 c7 45 6b b1 97 b0 c7 45 6b b1 97 40 76 00 00 02 00 00 00
localhost wpa_supplicant[1111]: wlan0: Event AUTH (11) received
localhost wpa_supplicant[1111]: wlan0: SME: Authentication response: peer=b0:c7:45:6b:b1:97 auth_type=0 status_code=0
Step 7: Device performs association
wpa_supplicant moves to the association phase. After successful association, the device can send 802.11 data frames.
Logs
localhost shill: [0815/104606:INFO:service.cc(343)] Service 0: state Idle -> Associating
localhost wpa_supplicant[1111]: wlan0: Trying to associate with b0:c7:45:6b:b1:97 (SSID='Network1' freq=2422 MHz)
localhost wpa_supplicant[1111]: wlan0: State: AUTHENTICATING -> ASSOCIATING
localhost wpa_supplicant[1111]: wpa_driver_nl80211_set_operstate: operstate 0->0 (DORMANT)
localhost wpa_supplicant[1111]: netlink: Operstate: linkmode=-1, operstate=5
localhost shill: [0815/104606:VERBOSE2:wifi_endpoint.cc(96)] PropertiesChanged
localhost wpa_supplicant[1111]: WPA: set own WPA/RSN IE - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
localhost wpa_supplicant[1111]: nl80211: Associate (ifindex=2)
localhost wpa_supplicant[1111]: * bssid=b0:c7:45:6b:b1:97
localhost wpa_supplicant[1111]: * freq=2422
localhost wpa_supplicant[1111]: * SSID - hexdump(len=14): 42 55 46 46 41 4c 4f 2d 36 42 42 31 39 37
localhost wpa_supplicant[1111]: * IEs - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
localhost wpa_supplicant[1111]: * pairwise=0xfac04
localhost wpa_supplicant[1111]: * group=0xfac02
localhost wpa_supplicant[1111]: * prev_bssid=b0:c7:45:6b:b1:97
localhost wpa_supplicant[1111]: nl80211: Association request send successfully
localhost shill: [0815/104607:INFO:service.cc(264)] Suppressed autoconnect to service 0 (connecting)
localhost shill: [0815/104607:INFO:wifi.cc(1404)] WiFi wlan0 StateChanged inactive -> authenticating
localhost shill: [0815/104607:INFO:wifi.cc(1404)] WiFi wlan0 StateChanged authenticating -> associating
localhost wpa_supplicant[1111]: nl80211: Event message available
localhost wpa_supplicant[1111]: nl80211: MLME event 38
localhost wpa_supplicant[1111]: nl80211: MLME event frame - hexdump(len=124): 30 00 3a 01 9c d2 1e 60 3b 71 b0 c7 45 6b b1 97 b0 c7 45 6b b1 97 50 76 11 04 00 00 01 c0 01 08 82 84 8b 96 0c 12 18 24 32 04 30 48 60 6c 2d 1a cc 11 1b ff ff 00 00 00 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 3d 16 03 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 dd 18 00 50 f2 02 01 01 00 00 03 a4 00 00 27 a4 00 00 42 43 5e 00 62 32 2f 00
localhost wpa_supplicant[1111]: wlan0: Event ASSOC (0) received
localhost wpa_supplicant[1111]: wlan0: Association info event
localhost wpa_supplicant[1111]: resp_ies - hexdump(len=94): 01 08 82 84 8b 96 0c 12 18 24 32 04 30 48 60 6c 2d 1a cc 11 1b ff ff 00 00 00 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00 3d 16 03 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 dd 18 00 50 f2 02 01 01 00 00 03 a4 00 00 27 a4 00 00 42 43 5e 00 62 32 2f 00
localhost wpa_supplicant[1111]: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=28): 2d 1a cc 11 1b ff ff 00 00 00 00 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 00
localhost wpa_supplicant[1111]: WPA: Unrecognized EAPOL-Key Key Data IE - hexdump(len=24): 3d 16 03 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
localhost wpa_supplicant[1111]: wlan0: freq=2422 MHz
localhost wpa_supplicant[1111]: wlan0: State: ASSOCIATING -> ASSOCIATED
localhost wpa_supplicant[1111]: wpa_driver_nl80211_set_operstate: operstate 0->0 (DORMANT)
localhost wpa_supplicant[1111]: netlink: Operstate: linkmode=-1, operstate=5
localhost wpa_supplicant[1111]: wlan0: Associated to a new BSS: BSSID=b0:c7:45:6b:b1:97
localhost wpa_supplicant[1111]: Add randomness: count=455 entropy=123
localhost wpa_supplicant[1111]: wlan0: No keys have been configured - skip key clearing
localhost wpa_supplicant[1111]: wlan0: Associated with b0:c7:45:6b:b1:97
localhost wpa_supplicant[1111]: wlan0: WPA: Association event - clear replay counter
localhost wpa_supplicant[1111]: wlan0: WPA: Clear old PTK
localhost wpa_supplicant[1111]: TDLS: Remove peers on association
localhost wpa_supplicant[1111]: nl80211: Disabling high bitrates
localhost wpa_supplicant[1111]: EAPOL: External notification - portEnabled=0
localhost wpa_supplicant[1111]: EAPOL: Supplicant port status: Unauthorized
localhost wpa_supplicant[1111]: EAPOL: External notification - portValid=0
localhost wpa_supplicant[1111]: EAPOL: Supplicant port status: Unauthorized
localhost wpa_supplicant[1111]: EAPOL: External notification - EAP success=0
localhost wpa_supplicant[1111]: EAPOL: Supplicant port status: Unauthorized
localhost wpa_supplicant[1111]: EAPOL: External notification - portEnabled=1
localhost wpa_supplicant[1111]: EAPOL: SUPP_PAE entering state CONNECTING
localhost wpa_supplicant[1111]: EAPOL: enable timer tick
localhost wpa_supplicant[1111]: EAPOL: SUPP_BE entering state IDLE
localhost wpa_supplicant[1111]: wlan0: Setting authentication timeout: 10 sec 0 usec
localhost wpa_supplicant[1111]: wlan0: Cancelling scan request
localhost wpa_supplicant[1111]: nl80211: Event message available
localhost wpa_supplicant[1111]: nl80211: Ignore connect event (cmd=46) when using userspace SME
localhost shill: [0815/104607:INFO:wifi.cc(1404)] WiFi wlan0 StateChanged associating -> associated
localhost wpa_supplicant[1111]: wlan0: Setting authentication timeout: 10 sec 0 usec
localhost wpa_supplicant[1111]: wlan0: IEEE 802.1X RX: version=1 type=3 length=95
localhost wpa_supplicant[1111]: wlan0: EAPOL-Key type=2
localhost wpa_supplicant[1111]: wlan0: key_info 0x8a (ver=2 keyidx=0 rsvd=0 Pairwise Ack)
localhost wpa_supplicant[1111]: wlan0: key_length=16 key_data_length=0
localhost wpa_supplicant[1111]: replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 02
localhost wpa_supplicant[1111]: key_nonce - hexdump(len=32): 6b b6 64 5d 77 ab 39 b9 56 dd a0 1d 8b 6d db df 63 87 f4 b7 c5 69 10 e9 44 18 56 5a d1 b0 18 8e
localhost wpa_supplicant[1111]: key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
localhost wpa_supplicant[1111]: key_rsc - hexdump(len=8): 00 00 00 00 00 00 00 00
localhost wpa_supplicant[1111]: key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
localhost wpa_supplicant[1111]: key_mic - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
localhost wpa_supplicant[1111]: WPA: RX EAPOL-Key - hexdump(len=99): 01 03 00 5f 02 00 8a 00 10 00 00 00 00 00 00 00 02 6b b6 64 5d 77 ab 39 b9 56 dd a0 1d 8b 6d db df 63 87 f4 b7 c5 69 10 e9 44 18 56 5a d1 b0 18 8e 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Step 8: Device and AP perform 4-way handshake
To create a data encryption key using the shared key (pairwise master key or PMK), wpa_supplicant performs the 4-way handshake between the device and the AP. If the device connects to an 802.1X Extensible Authentication Protocol (EAP) network, it needs to perform the EAP authentication process first.
Logs
localhost wpa_supplicant[1111]: wlan0: State: ASSOCIATED -> 4WAY_HANDSHAKE
localhost wpa_supplicant[1111]: wlan0: WPA: RX message 1 of 4-Way Handshake from b0:c7:45:6b:b1:97 (ver=2)
localhost wpa_supplicant[1111]: RSN: msg 1/4 key data - hexdump(len=0):
localhost wpa_supplicant[1111]: Get randomness: len=32 entropy=124
localhost wpa_supplicant[1111]: WPA: Renewed SNonce - hexdump(len=32): 43 c9 43 60 12 eb 50 b4 a3 0d 3b a8 1d 0b e4 ea 22 bf 9e 28 b6 54 a5 c4 e7 27 29 2e ce 32 d3 0d
localhost wpa_supplicant[1111]: WPA: PTK derivation - A1=9c:d2:1e:60:3b:71 A2=b0:c7:45:6b:b1:97
localhost wpa_supplicant[1111]: WPA: Nonce1 - hexdump(len=32): 43 c9 43 60 12 eb 50 b4 a3 0d 3b a8 1d 0b e4 ea 22 bf 9e 28 b6 54 a5 c4 e7 27 29 2e ce 32 d3 0d
localhost wpa_supplicant[1111]: WPA: Nonce2 - hexdump(len=32): 6b b6 64 5d 77 ab 39 b9 56 dd a0 1d 8b 6d db df 63 87 f4 b7 c5 69 10 e9 44 18 56 5a d1 b0 18 8e
localhost wpa_supplicant[1111]: WPA: PMK - hexdump(len=32): [REMOVED]
localhost wpa_supplicant[1111]: WPA: PTK - hexdump(len=48): [REMOVED]
localhost wpa_supplicant[1111]: WPA: WPA IE for msg 2/4 - hexdump(len=22): 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
localhost wpa_supplicant[1111]: WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 02
localhost wpa_supplicant[1111]: wlan0: WPA: Sending EAPOL-Key 2/4
localhost wpa_supplicant[1111]: WPA: KCK - hexdump(len=16): [REMOVED]
localhost wpa_supplicant[1111]: WPA: Derived Key MIC - hexdump(len=16): 05 11 6f 30 dd 6b 41 fa e8 eb 37 80 2c d0 96 81
localhost wpa_supplicant[1111]: WPA: TX EAPOL-Key - hexdump(len=121): 01 03 00 75 02 01 0a 00 00 00 00 00 00 00 00 00 02 43 c9 43 60 12 eb 50 b4 a3 0d 3b a8 1d 0b e4 ea 22 bf 9e 28 b6 54 a5 c4 e7 27 29 2e ce 32 d3 0d 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 11 6f 30 dd 6b 41 fa e8 eb 37 80 2c d0 96 81 00 16 30 14 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 0f ac 02 00 00
localhost wpa_supplicant[1111]: wlan0: RX EAPOL from b0:c7:45:6b:b1:97
localhost wpa_supplicant[1111]: RX EAPOL - hexdump(len=203): 01 03 00 c7 02 13 ca 00 10 00 00 00 00 00 00 00 03 6b b6 64 5d 77 ab 39 b9 56 dd a0 1d 8b 6d db df 63 87 f4 b7 c5 69 10 e9 44 18 56 5a d1 b0 18 8e 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 a1 b0 ec da ac 0b 94 d9 59 a5 7b f2 23 31 dc 17 00 68 3c 33 b7 ae 71 37 aa 4c c3 fa 56 ee 9b a4 e8 37 ae 09 30 b1 1c f4 e5 86 3b c3 0b 33 3d 62 00 d0 53 93 a8 56 9a 71 f1 de 5e e5 17 4d 61 86 f1 8d e9 ed 10 43 96 0f e3 a3 1f c4 aa 13 35 5f bb 7b ed b1 97 ea 54 3b 1f c9 40 8b 00 ed 81 67 54 c9 c3 da ec 70 84 c0 24 4d 7d 8d 09 2b cd 1b f9 39 5f d7 0d f5 c1 3c b8 b2
localhost wpa_supplicant[1111]: wlan0: IEEE 802.1X RX: version=1 type=3 length=199
localhost wpa_supplicant[1111]: wlan0: EAPOL-Key type=2
localhost wpa_supplicant[1111]: wlan0: key_info 0x13ca (ver=2 keyidx=0 rsvd=0 Pairwise Install Ack MIC Secure Encr)
localhost wpa_supplicant[1111]: wlan0: key_length=16 key_data_length=104
localhost wpa_supplicant[1111]: replay_counter - hexdump(len=8): 00 00 00 00 00 00 00 03
localhost wpa_supplicant[1111]: key_nonce - hexdump(len=32): 6b b6 64 5d 77 ab 39 b9 56 dd a0 1d 8b 6d db df 63 87 f4 b7 c5 69 10 e9 44 18 56 5a d1 b0 18 8e
localhost wpa_supplicant[1111]: key_iv - hexdump(len=16): 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
localhost wpa_supplicant[1111]: key_rsc - hexdump(len=8): 2f 00 00 00 00 00 00 00
localhost wpa_supplicant[1111]: key_id (reserved) - hexdump(len=8): 00 00 00 00 00 00 00 00
localhost wpa_supplicant[1111]: key_mic - hexdump(len=16): a1 b0 ec da ac 0b 94 d9 59 a5 7b f2 23 31 dc 17
localhost wpa_supplicant[1111]: WPA: RX EAPOL-Key - hexdump(len=203): 01 03 00 c7 02 13 ca 00 10 00 00 00 00 00 00 00 03 6b b6 64 5d 77 ab 39 b9 56 dd a0 1d 8b 6d db df 63 87 f4 b7 c5 69 10 e9 44 18 56 5a d1 b0 18 8e 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 a1 b0 ec da ac 0b 94 d9 59 a5 7b f2 23 31 dc 17 00 68 3c 33 b7 ae 71 37 aa 4c c3 fa 56 ee 9b a4 e8 37 ae 09 30 b1 1c f4 e5 86 3b c3 0b 33 3d 62 00 d0 53 93 a8 56 9a 71 f1 de 5e e5 17 4d 61 86 f1 8d e9 ed 10 43 96 0f e3 a3 1f c4 aa 13 35 5f bb 7b ed b1 97 ea 54 3b 1f c9 40 8b 00 ed 81 67 54 c9 c3 da ec 70 84 c0 24 4d 7d 8d 09 2b cd 1b f9 39 5f d7 0d f5 c1 3c b8 b2
localhost wpa_supplicant[1111]: RSN: encrypted key data - hexdump(len=104): 3c 33 b7 ae 71 37 aa 4c c3 fa 56 ee 9b a4 e8 37 ae 09 30 b1 1c f4 e5 86 3b c3 0b 33 3d 62 00 d0 53 93 a8 56 9a 71 f1 de 5e e5 17 4d 61 86 f1 8d e9 ed 10 43 96 0f e3 a3 1f c4 aa 13 35 5f bb 7b ed b1 97 ea 54 3b 1f c9 40 8b 00 ed 81 67 54 c9 c3 da ec 70 84 c0 24 4d 7d 8d 09 2b cd 1b f9 39 5f d7 0d f5 c1 3c b8 b2
localhost wpa_supplicant[1111]: WPA: decrypted EAPOL-Key key data - hexdump(len=96): [REMOVED]
localhost wpa_supplicant[1111]: wlan0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
localhost wpa_supplicant[1111]: wlan0: WPA: RX message 3 of 4-Way Handshake from b0:c7:45:6b:b1:97 (ver=2)
localhost wpa_supplicant[1111]: WPA: IE KeyData - hexdump(len=96): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00 dd 1a 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02 dd 26 00 0f ac 01 02 00 f0 ce 7d c3 13 cd 27 6c bc 51 a0 d0 f0 b4 6e 2d dc a2 b5 45 ab 51 ee 3c 34 88 a6 d4 7a a6 44 4c dd 00
localhost wpa_supplicant[1111]: WPA: RSN IE in EAPOL-Key - hexdump(len=26): 30 18 01 00 00 0f ac 02 02 00 00 0f ac 04 00 0f ac 02 01 00 00 0f ac 02 0c 00
localhost wpa_supplicant[1111]: WPA: WPA IE in EAPOL-Key - hexdump(len=28): dd 1a 00 50 f2 01 01 00 00 50 f2 02 02 00 00 50 f2 04 00 50 f2 02 01 00 00 50 f2 02
localhost wpa_supplicant[1111]: WPA: GTK in EAPOL-Key - hexdump(len=40): [REMOVED]
localhost wpa_supplicant[1111]: wlan0: WPA: Sending EAPOL-Key 4/4
localhost wpa_supplicant[1111]: WPA: KCK - hexdump(len=16): [REMOVED]
localhost wpa_supplicant[1111]: WPA: Derived Key MIC - hexdump(len=16): fc db eb 52 d9 af 39 a7 aa e5 81 29 02 7c 24 52
localhost wpa_supplicant[1111]: WPA: TX EAPOL-Key - hexdump(len=99): 01 03 00 5f 02 03 0a 00 00 00 00 00 00 00 00 00 03 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fc db eb 52 d9 af 39 a7 aa e5 81 29 02 7c 24 52 00 00
localhost wpa_supplicant[1111]: wlan0: WPA: Installing PTK to the driver
localhost wpa_supplicant[1111]: wpa_driver_nl80211_set_key: ifindex=2 alg=3 addr=0x7f50cb798e88 key_idx=0 set_tx=1 seq_len=6 key_len=16
localhost wpa_supplicant[1111]: addr=b0:c7:45:6b:b1:97
localhost wpa_supplicant[1111]: EAPOL: External notification - portValid=1
Step 9: Device and AP perform group key handshake
To allow the device to receive encrypted multicast and broadcast messages from the AP, wpa_supplicant performs the group key handshake between the device and the AP. The AP sends a groupwise transient key (GTK) to the device and the device acknowledges it.
Logs
localhost wpa_supplicant[1111]: wlan0: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
localhost wpa_supplicant[1111]: RSN: received GTK in pairwise handshake - hexdump(len=34): [REMOVED]
localhost wpa_supplicant[1111]: WPA: Group Key - hexdump(len=32): [REMOVED]
localhost wpa_supplicant[1111]: wlan0: WPA: Installing GTK to the driver (keyidx=2 tx=0 len=32)
localhost wpa_supplicant[1111]: WPA: RSC - hexdump(len=6): 2f 00 00 00 00 00
localhost wpa_supplicant[1111]: wpa_driver_nl80211_set_key: ifindex=2 alg=2 addr=0x7f50caf03c24 key_idx=2 set_tx=0 seq_len=6 key_len=32
localhost wpa_supplicant[1111]: broadcast key
localhost wpa_supplicant[1111]: wlan0: WPA: Key negotiation completed with b0:c7:45:6b:b1:97 [PTK=CCMP GTK=TKIP]
localhost wpa_supplicant[1111]: wlan0: Cancelling authentication timeout
localhost wpa_supplicant[1111]: wlan0: State: GROUP_HANDSHAKE -> COMPLETE
Step 10: Device configures DHCP
Next, DHCP configuration takes place. When the device first connects to a network, it broadcasts a DHCP DISCOVER message to its subnet. The DHCP server offers an IP address to the device. The device formally requests the IP address with the DHCP REQUEST message. This is acknowledged by the DHCP server with the DHCP ACKNOWLEDGE message. The device then updates its settings to use this IP information.
Logs
- The WiFi connection is completed. See the line with
CTRL-EVENT-CONNECTED. - The shill service needs to receive its IP information from the DHCP server. The shill Wi-Fi state changes to completed. The shill service state changes to configuring.
- DHCP service initializes using process id (pid) 14295.
- The logs indicate DHCP transaction ID (xid) 0x63526f44.
- As well as providing the IP address for the device, the DHCP server also provides additional information, such as the gateway IP address and Domain Name Server (DNS) details. You can see this additional information in the lines with
Processing Keys. - After the device receives the IP address, it records it as the default gateway in its IP-forwarding table. First, though, it needs to resolve the MAC address of the gateway from the IP address using the Address Resolution Protocol (ARP).
localhost wpa_supplicant[1111]: wlan0: State: GROUP_HANDSHAKE -> COMPLETED
localhost wpa_supplicant[1111]: wlan0: CTRL-EVENT-CONNECTED - Connection to b0:c7:45:6b:b1:97 completed (reauth) [id=0 id_str=]
localhost shill: [0815/104607:INFO:wifi.cc(1404)] WiFi wlan0 StateChanged associated -> completed
localhost shill: [0815/104607:INFO:service.cc(343)] Service 0: state Associating -> Configuring
localhost dhcpcd[14295]: dhcpcd is running with reduced privileges localhost dhcpcd[14295]: version 5.1.4 starting
localhost dhcpcd[14295]: status changed to Init localhost shill: [0815/104607:VERBOSE2:dhcpcd_proxy.cc(88)] sender(:1.170) pid(14295)
localhost shill: [0815/104607:VERBOSE2:dhcp_provider.cc(72)] GetConfig pid: 14295
localhost shill: [0815/104607:INFO:dhcp_config.cc(160)] Init DHCP Proxy: wlan0 at :1.170
localhost dhcpcd[14295]: wlan0: broadcasting for a lease
localhost dhcpcd[14295]: wlan0: sending DHCP_DISCOVER (xid 0x63526f44), next in 4.61 seconds
localhost shill: [0815/104607:VERBOSE2:dhcpcd_proxy.cc(102)] DHCPCDProxy(service=:1.170).
localhost dhcpcd[14295]: wlan0: received DHCP_OFFER with xid 0x63526f44
localhost dhcpcd[14295]: wlan0: offered 192.168.11.26 from 192.168.11.1
localhost dhcpcd[14295]: wlan0: requesting lease of 192.168.11.26
localhost dhcpcd[14295]: wlan0: sending DHCP_REQUEST (xid 0x63526f44), next in 3.68 seconds
localhost dhcpcd[14295]: wlan0: received DHCP_ACK with xid 0x63526f44
localhost dhcpcd[14295]: wlan0: acknowledged 192.168.11.26 from 192.168.11.1
localhost dhcpcd[14295]: wlan0: checking for 192.168.11.1
localhost dhcpcd[14295]: wlan0: gateway 192.168.11.1 found at b0:c7:45:6b:b1:97
localhost dhcpcd[14295]: wlan0: leased 192.168.11.26 for 86400 seconds
localhost dhcpcd[14295]: event BOUND on interface wlan0
localhost shill: [0815/104607:VERBOSE2:dhcpcd_proxy.cc(48)] sender(:1.170) pid(14295)
localhost shill: [0815/104607:VERBOSE2:dhcp_provider.cc(72)] GetConfig pid: 14295
localhost shill: [0815/104607:INFO:dhcp_config.cc(167)] Event reason: BOUND
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(399)] ParseConfiguration
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(408)] Processing key: BroadcastAddress
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(408)] Processing key: DHCPLeaseTime
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(408)] Processing key: DHCPMessageType
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(462)] Key ignored.
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(408)] Processing key: DHCPRebindingTime
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(462)] Key ignored. localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(408)] Processing key: DHCPRenewalTime
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(462)] Key ignored.
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(408)] Processing key: DHCPServerIdentifier
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(462)] Key ignored.
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(408)] Processing key: DomainName
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(408)] Processing key: DomainNameServers
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(408)] Processing key: IPAddress
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(408)] Processing key: NetworkNumber
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(462)] Key ignored.
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(408)] Processing key: Routers
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(408)] Processing key: SubnetCIDR
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(408)] Processing key: SubnetMask
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(462)] Key ignored.
localhost shill: [0815/104607:VERBOSE2:dhcp_config.cc(537)] StartExpirationTimeout: wlan0: Lease timeout is 86400 seconds.
localhost shill: [0815/104607:VERBOSE2:device.cc(539)] OnIPConfigUpdated
localhost shill: [0815/104607:VERBOSE2:device.cc(652)] CreateConnection
localhost shill: [0815/104607:INFO:connection.cc(168)] UpdateFromIPConfig: Installing with parameters: local=192.168.11.26 broadcast=192.168.11.255 peer= gateway=192.168.11.1
localhost shill: [0815/104607:INFO:service.cc(343)] Service 0: state Configuring -> Connected