GEORGE STEFANICK - CWSP JOURNEY, (CHAPTER 5 – DEBUGS POST#6)- 10/03/2010

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!

Comments

[Sean]

George, thank you for the debugs. I struggle understand something that i can't see. The debugs you mentioned are great and will help with my studies. Thanks again! Keep up the great work!

[Jason C. Miller]

Great post! This will come in handy when I start my CWSP study!

[Andrew]

George,
Great post, being able to debug client authentication and roaming is a vital skill for engineers to have. One command frequently used is "debug client". Being able to identify if the client performed a full authentication, PMK/OKC/CCKM roam, or attempted DHCP renewal or discovery are vital to diagnosing problems with roaming, especially with mobile clients in use in many retail and transportation industries.

In addition, here is what a CCKM roam looks like.

Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 Reassociation received from mobile on AP 00:22:be:90:86:40
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 STA - rates (4): 2 4 11 22 12 18 24 36 48 72 96 108 0 0 0 0
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 STA - rates (12): 2 4 11 22 12 18 24 36 48 72 96 108 0 0 0 0
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 Processing WPA IE type 221, length 22 for mobile 00:15:70:f0:9a:a3
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 10.37.120.62 RUN (20) Deleted mobile LWAPP rule on AP [00:00:00:00:00:00]
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 Updated location for station old AP 00:00:00:00:00:00-0, new AP 00:22:be:90:86:40-0
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 10.37.120.62 RUN (20) Change state to START (0) last state RUN (20)
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 10.37.120.62 START (0) Initializing policy
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 10.37.120.62 START (0) Change state to AUTHCHECK (2) last state RUN (20)
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 10.37.120.62 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20)
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 10.37.120.62 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:22:be:90:86:40
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 apfPemAddUser2 (apf_policy.c:212) Changing state for mobile 00:15:70:f0:9a:a3 on AP 00:22:be:90:86:40 from Associated to Associated
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 Stopping deletion of Mobile Station: (callerId: 48)
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 Creating a PKC PMKID Cache entry for station 00:15:70:f0:9a:a3 (RSN 0) on BSSID 00:22:be:90:86:43
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 Including CCKM Response IE (length 62) in Assoc Resp to mobile
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 Sending Assoc Response to station on BSSID 00:22:be:90:86:40 (status 0)
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 apfProcessAssocReq (apf_80211.c:3888) Changing state for mobile 00:15:70:f0:9a:a3 on AP 00:22:be:90:86:40 from Associated to Associated
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 Initiating WARP/CCKM to mobile 00:15:70:f0:9a:a3
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 dot1x - moving mobile 00:15:70:f0:9a:a3 into Force Auth state
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 Skipping EAP-Success to mobile 00:15:70:f0:9a:a3
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 10.37.120.62 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20)
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 10.37.120.62 L2AUTHCOMPLETE (4) State Update from Mobility-Complete to Mobility-Incomplete
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 10.37.120.62 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 00:22:be:90:86:40
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 10.37.120.62 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20)
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 10.37.120.62 RUN (20) Reached PLUMBFASTPATH: from line 4373
Thu May 27 14:33:06 2010: 00:15:70:f0:9a:a3 10.37.120.62 RUN (20) Change state to RUN (20) last state RUN (20)

Andrew (@revolutionwifi)