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) >

Rasika Nayanajith · ‎06-27-2016

*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_BLACKLISTE

As per above client get excluded (may be due to too many unsuccessful attempts).

*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

Have you enabled CCKM ? I would suggest to disable it & test

Also make sure dynamic interface is configured with DHCP server IP address and "ip helper address" is configured on SVI on that vlan if DHCP server is not on the same vlan.

HTH

Rasika

*** Pls rate all useful responses ***

jawadawawdeh · ‎06-28-2016

found this and it works :

https://supportforums.cisco.com/discussion/12267001/galaxy-s4-faills-connect-wifi

an upgrade to the firmware and the software is recommended
Wi-Fi Direct Clients Policy (original: disable), change it to (allow)

could be related to the bug :

https://bst.cloudapps.cisco.com/bugsearch/bug/CSCuc79613

jawadawawdeh · ‎12-12-2016

it seems that the problem still present , here is a link to the problem in details with all the logs

https://supportforums.cisco.com/discussion/13181761/csctz41993-buffer-dhcp-request-during-mobility-handshake-1