i have a problem with android phones obtaining IP address from the network

jawadawawdeh · ‎06-25-2016

i have a problem with android phones obtaining IP address from the network , i have standalone DHCP server , DHCP proxy is diable on the WLC , this is the logs from "debug client" attached files contain debug info about DHCP packet,message

(Cisco Controller) >debug client f4:09:d8:fc:24:dd

(Cisco Controller) >*Dot1x_NW_MsgTask_4: Jun 25 11:58:20.492: CCKM: Sending CCKM PMK (Version_2) information to mobility group
*Dot1x_NW_MsgTask_5: Jun 25 11:58:22.029: f4:09:d8:fc:24:dd f4:09:d8:fc:24:dd: Creating CCKM cache entry(version 2) on receiving message from mobility
*Dot1x_NW_MsgTask_5: Jun 25 11:58:22.030: f4:09:d8:fc:24:dd CCKM: Sending cache delete
*Dot1x_NW_MsgTask_5: Jun 25 11:58:22.030: f4:09:d8:fc:24:dd CCKM: Sending cache add
*Dot1x_NW_MsgTask_5: Jun 25 11:58:22.041: f4:09:d8:fc:24:dd Mobile Announce recvd from 172.16.31.6 Vlan List payload not found, ignoring ...

*Dot1x_NW_MsgTask_3: Jun 25 11:58:26.379: CCKM: Sending CCKM PMK (Version_2) information to mobility group
*Dot1x_NW_MsgTask_6: Jun 25 11:58:29.705: CCKM: Sending CCKM PMK (Version_2) information to mobility group
*apfMsConnTask_4: Jun 25 11:58:31.673: f4:09:d8:fc:24:dd CCKM: Received REASSOC REQ IE
*apfMsConnTask_4: Jun 25 11:58:31.673: f4:09:d8:fc:24:dd Processing assoc-req station:f4:09:d8:fc:24:dd AP:54:78:1a:d0:3a:20-00 thread:15147bd0
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd Adding mobile on LWAPP AP 54:78:1a:d0:3a:20(0)
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd Reassociation received from mobile on BSSID 54:78:1a:d0:3a:20 AP AP-ITC006
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd Global 200 Clients are allowed to AP radio

*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd Max Client Trap Threshold: 0 cur: 5

*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd Rf profile 600 Clients are allowed to AP wlan

*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd override for default ap group, marking intgrp NULL
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd Applying Interface policy on Mobile, role Unassociated. Ms NAC State 0 Quarantine Vlan 0 Access Vlan 0

*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd Re-applying interface policy for client

*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd 0.0.0.0 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2435)
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd 0.0.0.0 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2456)
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd Values before applying NASID - interfacetype:0, ovrd:0, mscb nasid:, interface nasid:
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd Check before Setting the NAS Id to WLAN specific Id ''
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd Applying site-specific Local Bridging override for station f4:09:d8:fc:24:dd - vapId 1, site 'default-group', interface 'management'
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd Applying Local Bridging Interface Policy for station f4:09:d8:fc:24:dd - vlan 0, interface id 0, interface 'management', nasId:''
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd processSsidIE statusCode is 0 and status is 0
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd processSsidIE ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd STA - rates (8): 130 132 139 150 36 48 72 108 0 0 0 0 0 0 0 0
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd suppRates statusCode is 0 and gotSuppRatesElement is 1
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd STA - rates (12): 130 132 139 150 36 48 72 108 12 18 24 96 0 0 0 0
*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1
*apfMsConnTask_4: Jun 25 11:58:31.674: RSNIE in Assoc. Req.: (20)

*apfMsConnTask_4: Jun 25 11:58:31.674: [0000] 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 40

*apfMsConnTask_4: Jun 25 11:58:31.674: [0016] 96 00 00 00

*apfMsConnTask_4: Jun 25 11:58:31.674: f4:09:d8:fc:24:dd Processing RSN IE type 48, length 20 for mobile f4:09:d8:fc:24:dd
*apfMsConnTask_4: Jun 25 11:58:31.675: f4:09:d8:fc:24:dd CCKM: Mobile is using CCKM
*apfMsConnTask_4: Jun 25 11:58:31.675: f4:09:d8:fc:24:dd RSN Capabilities: 0
*apfMsConnTask_4: Jun 25 11:58:31.675: f4:09:d8:fc:24:dd Marking Mobile as non-11w Capable
*apfMsConnTask_4: Jun 25 11:58:31.675: f4:09:d8:fc:24:dd Received RSN IE with 0 PMKIDs from mobile f4:09:d8:fc:24:dd
*apfMsConnTask_4: Jun 25 11:58:31.675: f4:09:d8:fc:24:dd Setting active key cache index 8 ---> 8
*apfMsConnTask_4: Jun 25 11:58:31.675: f4:09:d8:fc:24:dd unsetting PmkIdValidatedByAp
*apfMsConnTask_4: Jun 25 11:58:31.675: f4:09:d8:fc:24:dd CCKM: Processing REASSOC REQ IE
*apfMsConnTask_4: Jun 25 11:58:31.675: f4:09:d8:fc:24:dd CCKM: Received RSN/WPA IE length (22) validation failed with the cached RSN/WPA IE length (24) entry
*apfMsConnTask_4: Jun 25 11:58:31.675: f4:09:d8:fc:24:dd CCKM: Failed to validate REASSOC REQ IE
*apfMsConnTask_4: Jun 25 11:58:31.675: f4:09:d8:fc:24:dd Sending assoc-resp with status 1 station:f4:09:d8:fc:24:dd AP:54:78:1a:d0:3a:20-00 on apVapId 1
*apfMsConnTask_4: Jun 25 11:58:31.675: f4:09:d8:fc:24:dd Sending Assoc Response to station on BSSID 54:78:1a:d0:3a:20 (status unspecified failure) ApVapId 1 Slot 0
*apfMsConnTask_4: Jun 25 11:58:31.675: f4:09:d8:fc:24:dd Scheduling deletion of Mobile Station: (callerId: 22) in 3 seconds
*Dot1x_NW_MsgTask_6: Jun 25 11:58:32.206: CCKM: Sending CCKM PMK (Version_2) information to mobility group
*osapiBsnTimer: Jun 25 11:58:34.515: f4:09:d8:fc:24:dd apfMsExpireCallback (apf_ms.c:637) Expiring Mobile!
*apfReceiveTask: Jun 25 11:58:34.515: f4:09:d8:fc:24:dd pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfReceiveTask: Jun 25 11:58:34.515: f4:09:d8:fc:24:dd 0.0.0.0 START (0) Deleted mobile LWAPP rule on AP [54:78:1a:d0:3a:20]
*apfReceiveTask: Jun 25 11:58:34.515: f4:09:d8:fc:24:dd Deleting mobile on AP 54:78:1a:d0:3a:20(0)
*Apf Guest: Jun 25 11:58:38.315: Wired client head is NULL, no clients in the list. Number of clients = 0

*apfMsConnTask_4: Jun 25 11:58:39.490: f4:09:d8:fc:24:dd Processing assoc-req station:f4:09:d8:fc:24:dd AP:54:78:1a:d0:3a:20-00 thread:15147bd0
*apfMsConnTask_4: Jun 25 11:58:39.490: f4:09:d8:fc:24:dd Adding mobile on LWAPP AP 54:78:1a:d0:3a:20(0)
*apfMsConnTask_4: Jun 25 11:58:39.490: f4:09:d8:fc:24:dd Association received from mobile on BSSID 54:78:1a:d0:3a:20 AP AP-ITC006
*apfMsConnTask_4: Jun 25 11:58:39.490: f4:09:d8:fc:24:dd Global 200 Clients are allowed to AP radio

*apfMsConnTask_4: Jun 25 11:58:39.490: f4:09:d8:fc:24:dd Max Client Trap Threshold: 0 cur: 5

*apfMsConnTask_4: Jun 25 11:58:39.490: f4:09:d8:fc:24:dd Rf profile 600 Clients are allowed to AP wlan

*apfMsConnTask_4: Jun 25 11:58:39.490: f4:09:d8:fc:24:dd override for default ap group, marking intgrp NULL
*apfMsConnTask_4: Jun 25 11:58:39.490: f4:09:d8:fc:24:dd Applying Interface policy on Mobile, role Unassociated. Ms NAC State 0 Quarantine Vlan 0 Access Vlan 0

*apfMsConnTask_4: Jun 25 11:58:39.490: f4:09:d8:fc:24:dd Re-applying interface policy for client

*apfMsConnTask_4: Jun 25 11:58:39.490: f4:09:d8:fc:24:dd 0.0.0.0 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2435)
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd 0.0.0.0 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2456)
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd Values before applying NASID - interfacetype:0, ovrd:0, mscb nasid:, interface nasid:
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd Check before Setting the NAS Id to WLAN specific Id ''
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd Applying site-specific Local Bridging override for station f4:09:d8:fc:24:dd - vapId 1, site 'default-group', interface 'management'
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd Applying Local Bridging Interface Policy for station f4:09:d8:fc:24:dd - vlan 0, interface id 0, interface 'management', nasId:''
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd processSsidIE statusCode is 0 and status is 0
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd processSsidIE ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd STA - rates (8): 130 132 139 150 36 48 72 108 0 0 0 0 0 0 0 0
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd suppRates statusCode is 0 and gotSuppRatesElement is 1
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd STA - rates (12): 130 132 139 150 36 48 72 108 12 18 24 96 0 0 0 0
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1
*apfMsConnTask_4: Jun 25 11:58:39.491: RSNIE in Assoc. Req.: (38)

*apfMsConnTask_4: Jun 25 11:58:39.491: [0000] 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 40

*apfMsConnTask_4: Jun 25 11:58:39.491: [0016] 96 00 00 00 01 00 91 ee 45 92 90 04 67 cd cf ec

*apfMsConnTask_4: Jun 25 11:58:39.491: [0032] 07 c6 15 9d f7 ff

*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd Processing RSN IE type 48, length 38 for mobile f4:09:d8:fc:24:dd
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd CCKM: Mobile is using CCKM
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd RSN Capabilities: 0
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd Marking Mobile as non-11w Capable
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd Received RSN IE with 1 PMKIDs from mobile f4:09:d8:fc:24:dd
*apfMsConnTask_4: Jun 25 11:58:39.491: Received PMKID: (16)

*apfMsConnTask_4: Jun 25 11:58:39.491: [0000] 91 ee 45 92 90 04 67 cd cf ec 07 c6 15 9d f7 ff

*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd Searching for PMKID in MSCB PMKID cache for mobile f4:09:d8:fc:24:dd
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd No valid PMKID found in the MSCB PMKID cache for mobile f4:09:d8:fc:24:dd
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd Trying to compute a PMKID from MSCB PMK cache for mobile f4:09:d8:fc:24:dd
*apfMsConnTask_4: Jun 25 11:58:39.491: CCKM: Find PMK in cache: BSSID = (6)

*apfMsConnTask_4: Jun 25 11:58:39.491: [0000] 54 78 1a d0 3a 20

*apfMsConnTask_4: Jun 25 11:58:39.491: CCKM: Find PMK in cache: realAA = (6)

*apfMsConnTask_4: Jun 25 11:58:39.491: [0000] 54 78 1a d0 3a 20

*apfMsConnTask_4: Jun 25 11:58:39.491: CCKM: Find PMK in cache: PMKID = (16)

*apfMsConnTask_4: Jun 25 11:58:39.491: [0000] 91 ee 45 92 90 04 67 cd cf ec 07 c6 15 9d f7 ff

*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd Unable to compute a valid PMKID from MSCB PMK cache for mobile f4:09:d8:fc:24:dd
*apfMsConnTask_4: Jun 25 11:58:39.491: f4:09:d8:fc:24:dd Searching for PMK in global PMK cache for mobile f4:09:d8:fc:24:dd
*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd Found an entry in the global PMK cache for station f4:09:d8:fc:24:dd
*apfMsConnTask_4: Jun 25 11:58:39.492: CCKM: AA (6)

*apfMsConnTask_4: Jun 25 11:58:39.492: [0000] 54 78 1a d0 3a 20

*apfMsConnTask_4: Jun 25 11:58:39.492: CCKM: SPA (6)

*apfMsConnTask_4: Jun 25 11:58:39.492: [0000] f4 09 d8 fc 24 dd

*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd computed a valid PMKID from global PMK cache for mobile f4:09:d8:fc:24:dd
*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd Username entry (s1410982) created for mobile, length = 253
*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd Username entry (s1410982) created in mscb for mobile, length = 253
*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd Setting active key cache index 8 ---> 8
*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd Setting active key cache index 8 ---> 0
*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd Creating a PKC PMKID Cache entry for station f4:09:d8:fc:24:dd (RSN 0) on BSSID 54:78:1a:d0:3a:20
*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd Adding BSSID 54:78:1a:d0:3a:20 to PMKID cache at index 0 for station f4:09:d8:fc:24:dd
*apfMsConnTask_4: Jun 25 11:58:39.492: New PMKID: (16)

*apfMsConnTask_4: Jun 25 11:58:39.492: [0000] 91 ee 45 92 90 04 67 cd cf ec 07 c6 15 9d f7 ff

*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd 0.0.0.0 START (0) Initializing policy
*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state START (0)

*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd Encryption policy is set to 0x80000001
*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd Not Using WMM Compliance code qosCap 00
*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 54:78:1a:d0:3a:20 vapId 1 apVapId 1 flex-acl-name:
*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd apfMsAssoStateInc
*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd apfPemAddUser2 (apf_policy.c:353) Changing state for mobile f4:09:d8:fc:24:dd on AP 54:78:1a:d0:3a:20 from Idle to Associated

*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd apfPemAddUser2:session timeout forstation f4:09:d8:fc:24:dd - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is 0
*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_4: Jun 25 11:58:39.492: f4:09:d8:fc:24:dd Sending assoc-resp with status 0 station:f4:09:d8:fc:24:dd AP:54:78:1a:d0:3a:20-00 on apVapId 1
*apfMsConnTask_4: Jun 25 11:58:39.493: f4:09:d8:fc:24:dd Sending Assoc Response to station on BSSID 54:78:1a:d0:3a:20 (status 0) ApVapId 1 Slot 0
*apfMsConnTask_4: Jun 25 11:58:39.493: f4:09:d8:fc:24:dd apfProcessAssocReq (apf_80211.c:9582) Changing state for mobile f4:09:d8:fc:24:dd on AP 54:78:1a:d0:3a:20 from Associated to Associated

*spamApTask5: Jun 25 11:58:39.498: f4:09:d8:fc:24:dd Sent 1x initiate message to multi thread task for mobile f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.498: f4:09:d8:fc:24:dd reauth_sm state transition 0 ---> 1 for mobile f4:09:d8:fc:24:dd at 1x_reauth_sm.c:47
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.498: f4:09:d8:fc:24:dd Initiating RSN with existing PMK to mobile f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.498: f4:09:d8:fc:24:dd EAP-PARAM Debug - eap-params for Wlan-Id :1 is disabled - applying Global eap timers and retries
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.498: f4:09:d8:fc:24:dd Disable re-auth, use PMK lifetime.
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.498: f4:09:d8:fc:24:dd Station f4:09:d8:fc:24:dd setting dot1x reauth timeout = 1800
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.498: f4:09:d8:fc:24:dd dot1x - moving mobile f4:09:d8:fc:24:dd into Force Auth state
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.498: f4:09:d8:fc:24:dd Skipping EAP-Success to mobile f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.498: f4:09:d8:fc:24:dd Username entry (s1410982) already exists in name table, length = 253
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.498: f4:09:d8:fc:24:dd Username entry (s1410982) created in mscb for mobile, length = 253
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.499: f4:09:d8:fc:24:dd Found an cache entry for BSSID 54:78:1a:d0:3a:20 in PMKID cache at index 0 of station f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.499: f4:09:d8:fc:24:dd Found an cache entry for BSSID 54:78:1a:d0:3a:20 in PMKID cache at index 0 of station f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.499: Including PMKID in M1 (16)

*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.499: [0000] 91 ee 45 92 90 04 67 cd cf ec 07 c6 15 9d f7 ff

*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.499: f4:09:d8:fc:24:dd Starting key exchange to mobile f4:09:d8:fc:24:dd, data packets will be dropped
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.499: f4:09:d8:fc:24:dd Sending EAPOL-Key Message to mobile f4:09:d8:fc:24:dd
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.499: f4:09:d8:fc:24:dd Allocating EAP Pkt for retransmission to mobile f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.515: f4:09:d8:fc:24:dd Received EAPOL-Key from mobile f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.515: f4:09:d8:fc:24:dd Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.515: f4:09:d8:fc:24:dd Received EAPOL-key in PTK_START state (message 2) from mobile f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.515: f4:09:d8:fc:24:dd Dumping RSNIE received in Association request:
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.516: 00000000: 30 26 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 0&..............
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.516: 00000010: 00 40 96 00 00 00 01 00 91 ee 45 92 90 04 67 cd .@........E...g.
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.516: 00000020: cf ec 07 c6 15 9d f7 ff ........
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.516: f4:09:d8:fc:24:dd Dumping RSNIE received in EAPOL M2 :
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.516: 00000000: 01 00 00 0f ac 02 01 00 00 0f ac 04 01 00 00 40 ...............@
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.516: 00000010: 96 00 00 00 01 00 91 ee 45 92 90 04 67 cd cf ec ........E...g...
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.516: 00000020: 07 c6 15 9d f7 ff ......
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.516: f4:09:d8:fc:24:dd Not Flex client. Do not distribute CCKM Key cache.
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.516: CCKM: Sending CCKM PMK (Version_2) information to mobility group
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.516: f4:09:d8:fc:24:dd 5 PMK-update groupcast messages sent
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.516: f4:09:d8:fc:24:dd Stopping retransmission timer for mobile f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.517: f4:09:d8:fc:24:dd Sending EAPOL-Key Message to mobile f4:09:d8:fc:24:dd
state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.517: f4:09:d8:fc:24:dd Reusing allocated memory for EAP Pkt for retransmission to mobile f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.528: f4:09:d8:fc:24:dd Received EAPOL-Key from mobile f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.528: f4:09:d8:fc:24:dd Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd Stopping retransmission timer for mobile f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd Freeing EAP Retransmit Bufer for mobile f4:09:d8:fc:24:dd
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd apfMs1xStateInc
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3)

*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd Mobility query, PEM State: L2AUTHCOMPLETE

*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd Building Mobile Announce :

*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd Building Client Payload:

*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd Client Ip: 0.0.0.0

*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd Client Vlan Ip: 172.16.31.5, Vlan mask : 255.255.0.0

*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd Client Vap Security: 16384

*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd Virtual Ip: 1.1.1.1

*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd ssid: AL-QUDS-WLAN

*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd Building VlanIpPayload.

*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd Mobile Announce sent to 1 members of the local group.
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd Not Using WMM Compliance code qosCap 00
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd 0.0.0.0 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 54:78:1a:d0:3a:20 vapId 1 apVapId 1 flex-acl-name:
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state L2AUTHCOMPLETE (4)

*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 6575, Adding TMP rule
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd 0.0.0.0 DHCP_REQD (7) Adding Fast Path rule
type = Airespace AP - Learn IP address
on AP 54:78:1a:d0:3a:20, slot 0, interface = 1, QOS = 0
IPv4 ACL ID = 255, IPv
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.529: f4:09:d8:fc:24:dd 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 0 Local Bridging Vlan = 0, Local Bridging intf id = 0
*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.530: f4:09:d8:fc:24:dd 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0

*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.530: f4:09:d8:fc:24:dd 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0

*Dot1x_NW_MsgTask_5: Jun 25 11:58:39.530: f4:09:d8:fc:24:dd 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255)
*pemReceiveTask: Jun 25 11:58:39.530: f4:09:d8:fc:24:dd 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0
*apfReceiveTask: Jun 25 11:58:39.530: f4:09:d8:fc:24:dd apfBlacklistMobileStationEntry2 (apf_ms.c:6268) Changing state for mobile f4:09:d8:fc:24:dd on AP 54:78:1a:d0:3a:20 from Associated to Exclusion-list (1)

*apfReceiveTask: Jun 25 11:58:39.531: f4:09:d8:fc:24:dd Scheduling deletion of Mobile Station: (callerId: 44) in 10 seconds
*apfReceiveTask: Jun 25 11:58:39.531: f4:09:d8:fc:24:dd HandOff denied as Client is Blacklisted at Peer 0.0.0.0. Adding mobile to exclusion-list due to mobility reporting
*IPv6_Msg_Task: Jun 25 11:58:44.464: f4:09:d8:fc:24:dd Not Advancing pem state, mscb in apfMsMmQueryRequested mobility state and client state APF_MS_STATE_BLACKLISTED
*osapiBsnTimer: Jun 25 11:58:49.515: f4:09:d8:fc:24:dd apfMsExpireCallback (apf_ms.c:637) Expiring Mobile!
*apfReceiveTask: Jun 25 11:58:49.515: f4:09:d8:fc:24:dd Scheduling deletion of Mobile Station: (callerId: 46) in 60 seconds
*apfReceiveTask: Jun 25 11:58:49.515: f4:09:d8:fc:24:dd apfMsExpireMobileStation (apf_ms.c:7193) Changing state for mobile f4:09:d8:fc:24:dd on AP 54:78:1a:d0:3a:20 from Exclusion-list (1) to Exclusion-list (2)

*apfReceiveTask: Jun 25 11:58:49.515: f4:09:d8:fc:24:dd pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfReceiveTask: Jun 25 11:58:49.515: f4:09:d8:fc:24:dd 0.0.0.0 DHCP_REQD (7) Deleted mobile LWAPP rule on AP [54:78:1a:d0:3a:20]
*pemReceiveTask: Jun 25 11:58:49.516: f4:09:d8:fc:24:dd 0.0.0.0 Removed NPU entry.
*apfMsConnTask_4: Jun 25 11:58:49.624: f4:09:d8:fc:24:dd Processing assoc-req station:f4:09:d8:fc:24:dd AP:54:78:1a:d0:3a:20-00 thread:15147bd0
*apfMsConnTask_4: Jun 25 11:58:49.624: f4:09:d8:fc:24:dd Ignoring assoc request due to mobile in exclusion list or marked for deletion
*apfMsConnTask_4: Jun 25 11:58:49.941: f4:09:d8:fc:24:dd Processing assoc-req station:f4:09:d8:fc:24:dd AP:54:78:1a:d0:3a:20-00 thread:15147bd0
*apfMsConnTask_4: Jun 25 11:58:49.941: f4:09:d8:fc:24:dd Ignoring assoc request due to mobile in exclusion list or marked for deletion
*apfMsConnTask_4: Jun 25 11:58:50.258: f4:09:d8:fc:24:dd Processing assoc-req station:f4:09:d8:fc:24:dd AP:54:78:1a:d0:3a:20-00 thread:15147bd0
*apfMsConnTask_4: Jun 25 11:58:50.258: f4:09:d8:fc:24:dd Ignoring assoc request due to mobile in exclusion list or marked for deletion
*apfMsConnTask_4: Jun 25 11:58:50.574: f4:09:d8:fc:24:dd Processing assoc-req station:f4:09:d8:fc:24:dd AP:54:78:1a:d0:3a:20-00 thread:15147bd0
*apfMsConnTask_4: Jun 25 11:58:50.574: f4:09:d8:fc:24:dd Ignoring assoc request due to mobile in exclusion list or marked for deletion
*apfMsConnTask_4: Jun 25 11:58:50.891: f4:09:d8:fc:24:dd Processing assoc-req station:f4:09:d8:fc:24:dd AP:54:78:1a:d0:3a:20-00 thread:15147bd0
*apfMsConnTask_4: Jun 25 11:58:50.891: f4:09:d8:fc:24:dd Ignoring assoc request due to mobile in exclusion list or marked for deletion
*apfMsConnTask_4: Jun 25 11:58:51.208: f4:09:d8:fc:24:dd Processing assoc-req station:f4:09:d8:fc:24:dd AP:54:78:1a:d0:3a:20-00 thread:15147bd0
*apfMsConnTask_4: Jun 25 11:58:51.208: f4:09:d8:fc:24:dd Ignoring assoc request due to mobile in exclusion list or marked for deletion
*apfMsConnTask_4: Jun 25 11:58:51.531: f4:09:d8:fc:24:dd Processing assoc-req station:f4:09:d8:fc:24:dd AP:54:78:1a:d0:3a:20-00 thread:15147bd0
*apfMsConnTask_4: Jun 25 11:58:51.531: f4:09:d8:fc:24:dd Ignoring assoc request due to mobile in exclusion list or marked for deletion

(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >diab*apfMsConnTask_6: Jun 25 11:59:01.384: Group Mgmt Cipher Suite: (4)

*apfMsConnTask_6: Jun 25 11:59:01.384: [0000] 01 00 ad 52

Incorrect usage. Use the '?' or <TAB> key to list commands.

(Cisco Controller) >debug disable-all

(Cisco Controller) >
(Cisco Controller) >