GEORGE STEFANICK - CWSP JOURNEY, (CHAPTER 5 – debugs#6)- 10/03/2010
If you have gear to play with you can run various commands and see the (802.1X) process at work. I will highlight a few commands quick for brief overview with a Cisco WLC and Cisco autonomous access point. Debug is your friend and I encourage playing with the debug function.
EXAMPLE #1 - Session Timeout
If you are familiar with the Cisco WLCs . You may have noticed a check box called “Enable Session Timeout”. This feature can be found under WLAN-> (pick your wlan)->ADVANCED -> Session Timeout (check box). Session Timeout is feature set per WLAN setting.
This feature allows you to add a reauthenication timer (or shall we say a rekeying event). Lets say for example you keep the 1800 second timeout value. This means every 1800 seconds from the time your client authenticated to the wireless network the WLC will send a deauthentication frame to the client. Thus causing the client to reauthenticate (or shall we say rekey).
You can also see the clients PMK record in the WLC. Drop into the CLI of the WLC >show pmk-cache. Under the lifetime value you will see a timer and it counts down. Once it hits zero your client will rekey. This is directly related to the “enable session timeout”
** CAUTION** Some Enterprise environments disable or increase the timeout value to equal 24 hours. Some sensitive applications can be disrupted by frequent re- authentication.
Below is an example:
(Cisco_2006_WLC) >show pmk-cache all
Type Station Lifetime VLAN Override IP Override
------ -------------- -------- ------------------ ---------------
RSN 00:21:6a:11:a8:02 1775 0.0.0.0
(Cisco_2006_WLC) >show pmk-cache all
Type Station Lifetime VLAN Override IP Override
----- -------------- -------- ------------------ ---------------
RSN 00:21:6a:11:a8:02 1750 0.0.0.0
Example #2 - Manually Update the GTK on a autonomous access point
Drop into the CLI of the Cisco autonomous access point and issue the following command:
dot11 dot11Radio 0 update-group-key
ap#dot11 dot11Radio 0 update-group-key
*Mar 2 21:28:05.767: dot11_dot1x_new_key: mcst encrypt mode 0x10 gtk len 32
*Mar 2 21:28:05.767: dot11_dot1x_distribute_bkey: Updating Group Key: vlan=0, index=2, len=32
*Mar 2 21:28:05.767: dot11_dot1x_hex_dump: GTK: 5A CA 2D 68 1C 0E FD A2 DF 6E 8C A4 E6 CE D3 FB 71 F5 6C 84 8C BF EB 35 4C C0 80 CB 3E D1 48 B0
*Mar 2 21:28:05.768: dot11_dot1x_send_ssn_gtk: Sending GTK Message 1 to 0021.6a11.a802
*Mar 2 21:28:05.768: dot11_dot1x_distribute_bkey: Multicast key distributed to 1 clients
Example # 3 - Debug on the Cisco WLC
There is a host of 802.1x / AAA commands. I deployed dot1x states/event enabled.
(Cisco_2006_WLC) >debug dot1x states enable
(Cisco_2006_WLC) >debug dot1x events enable
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Processing RSN IE type 48, length 20 for mobile d8:30:62:80:61:a1
!! States 0 PMKIDs. This means this is a new device on the WLC and there is no PMKIDs in que
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Received RSN IE with 0 PMKIDs from mobile d8:30:62:80:61:a1
!! The WLC moves the client into the connecting state.
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 dot1x - moving mobile d8:30:62:80:61:a1 into Connecting state
!! The WLC is sending the EAP-Request/Identity
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Sending EAP-Request/Identity to mobile d8:30:62:80:61:a1 (EAP Id 1)
!! The WLC received an EAP packet from the supplicant
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Received EAPOL EAPPKT from mobile d8:30:62:80:61:a1
!! The supplicant responded to the Identity Response
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Received Identity Response (count=1) from mobile d8:30:62:80:61:a1
!! The next state after connecting is authenticating
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 EAP State update from Connecting to Authenticating for mobile d8:30:62:80:61:a1
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 dot1x - moving mobile d8:30:62:80:61:a1 into Authenticating state
!! This I understand means the WLC is sending the response to the AAA server
!! “Entering Backend Auth Response state for mobile”
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Entering Backend Auth Response state for mobile d8:30:62:80:61:a1
!! EAP PROCESS
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Processing Access-Challenge for mobile d8:30:62:80:61:a1
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Entering Backend Auth Req state (id=112) for mobile d8:30:62:80:61:a1
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 WARNING: updated EAP-Identifer 1 ===> 112 for STA d8:30:62:80:61:a1
!! The authentication server (AAA) is sending the EAP request through the WLC
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Sending EAP Request from AAA to mobile d8:30:62:80:61:a1 (EAP Id 112)
!! Response from supplicant
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Received EAPOL EAPPKT from mobile d8:30:62:80:61:a1
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Received EAP Response from mobile d8:30:62:80:61:a1 (EAP Id 112, EAP Type 17)
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Entering Backend Auth Response state for mobile d8:30:62:80:61:a1
!! EAP PROCESS
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Processing Access-Challenge for mobile d8:30:62:80:61:a1
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Entering Backend Auth Req state (id=112) for mobile d8:30:62:80:61:a1
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 WARNING: updated EAP-Identifer 112 ===> 112 for STA d8:30:62:80:61:a1
!! AAA request from server to supplicant
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Sending EAP Request from AAA to mobile d8:30:62:80:61:a1 (EAP Id 112)
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Received EAPOL EAPPKT from mobile d8:30:62:80:61:a1
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Received LEAP EAP Request (type=17, ver=1) from mobile d8:30:62:80:61:a1
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Entering Backend Auth Response state for mobile d8:30:62:80:61:a1
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Processing Access-Accept for mobile d8:30:62:80:61:a1
!! Here is the enable session we talked about. It is set @ 1800 seconds
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Setting re-auth timeout to 1800 seconds, got from WLAN config.
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Station d8:30:62:80:61:a1 setting dot1x reauth timeout = 1800
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Creating a PKC PMKID Cache entry for station d8:30:62:80:61:a1 (RSN 2)
!! Access point adds PMKID cache for supplicant
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Adding BSSID 00:1c:b0:06:d2:d5 to PMKID cache for station d8:30:62:80:61:a1
!! This is the PMK that was derived
Sun Oct 3 11:56:44 2010: New PMKID: (16)
Sun Oct 3 11:56:44 2010: [0000] 02 4a 48 af f6 d6 32 8f 2b 1f ee cc 5a 0a 58 12
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Disabling re-auth since PMK lifetime can take care of same.
Sun Oct 3 11:56:44 2010: Including PMKID in M1 (16)
Sun Oct 3 11:56:44 2010: [0000] 02 4a 48 af f6 d6 32 8f 2b 1f ee cc 5a 0a 58 12
!! Message 1 – This is our first exchange in the 4 way handshake. This is where the authenticator sends the ANonce and mac address.
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Sending EAPOL-Key Message to mobile d8:30:62:80:61:a1
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Entering Backend Auth Success state (id=112) for mobile d8:30:62:80:61:a1
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 Received Auth Success while in Authenticating state for mobile d8:30:62:80:61:a1
Sun Oct 3 11:56:44 2010: d8:30:62:80:61:a1 dot1x - moving mobile d8:30:62:80:61:a1 into Authenticated state
Sun Oct 3 11:56:45 2010: d8:30:62:80:61:a1 802.1x 'timeoutEvt' Timer expired for station d8:30:62:80:61:a1
!! Message received from the supplicant
Sun Oct 3 11:56:45 2010: d8:30:62:80:61:a1 Received EAPOL-Key from mobile d8:30:62:80:61:a1
!! Message 2 – This is our second exchange in the 4 way handshake. This client is send the SNonce and the supplicant mac address.
Sun Oct 3 11:56:45 2010: d8:30:62:80:61:a1 Received EAPOL-key in PKT_START state (message 2) from mobile d8:30:62:80:61:a1
Sun Oct 3 11:56:45 2010: d8:30:62:80:61:a1 Stopping retransmission timer for mobile d8:30:62:80:61:a1
!! Message 3 – This is our third exchange in the 4 way handshake. This is where the GTK is being derived and sent back at the supplicant.
Sun Oct 3 11:56:45 2010: d8:30:62:80:61:a1 Sending EAPOL-Key Message to mobile d8:30:62:80:61:a1
state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.02
Sun Oct 3 11:56:45 2010: d8:30:62:80:61:a1 Received EAPOL-Key from mobile d8:30:62:80:61:a1
!! Message 4 – This is our fourth exchange in the 4 way handshake. This is confirmation the keys were installed.
Sun Oct 3 11:56:45 2010: d8:30:62:80:61:a1 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile d8:30:62:80:61:a1
Sun Oct 3 11:56:45 2010: d8:30:62:80:61:a1 Stopping retransmission timer for mobile d8:30:62:80:61:a1
Sun Oct 3 11:57:40 2010: d8:30:62:80:61:a1 Sending EAPOL-Key Message to mobile d8:30:62:80:61:a1
state PTKINITDONE (message 5 - group), replay counter 00.00.00.00.00.00.00.03
!! Message 5 – Is our group key update
!! You can see here it states updated broadcast key and it was sent to the supplicant
Sun Oct 3 11:57:40 2010: d8:30:62:80:61:a1 Updated broadcast key sent to mobile D8:30:62:80:61:A1
!! Group key timer is set @ 3653 seconds. At which point the group key will be re-keyed.
Sun Oct 3 11:57:40 2010: 00:1c:b0:06:d2:d0 Resetting the group key timer for 3653 seconds on AP 00:1c:b0:06:d2:d0(0)
Sun Oct 3 11:57:40 2010: d8:30:62:80:61:a1 Received EAPOL-Key from mobile d8:30:62:80:61:a1
!! Message 6 – This is confirmation the from the supplicant
Sun Oct 3 11:57:40 2010: d8:30:62:80:61:a1 Received EAPOL-key in REKEYNEGOTIATING state (message 6) from mobile d8:30:62:80:61:a1
Sun Oct 3 11:57:40 2010: d8:30:62:80:61:a1 Stopping retransmission timer for mobile d8:30:62:80:61:a1
Play with the debugs ... ENJOY!