Re: Cisco Mobility Express Apple devices take long time to connect and QoS

Gray_FoX · ‎10-07-2020

Hellow to everyone,

I have a smal WLAN network , a couple of Cisco AIR-AP1832I-E-9, one is configured as WLC, the others as CAP-WAP ( AP)

there are no more then 10 devices. The Problem I have is " When I conne't to the WLAN SSID the IOS devices ( Iphones and Ipads) the conection time is more then 50 seconds, all other Devices ( Android, Windwos laptops) connect much much faster(3 seconds). I checked all IOS Best Practices ( Exept QoS... can't find why it stays unchecked).

Hase anyone encountered this kind of problems? I updated the Software to Version 8.10.130.0 (newest update) Fast transition is on, problem remains the same.

Can someone Hellp me? I spend lots of time googling but havent find any solution.

* How to Fix connection delay on all IOS devices
* What option should be checked so that ALL IOS best Practices checkboxes are checked (QoS) ?

Thank you all for the time in advance.

Rasika Nayanajith · ‎10-07-2020

The easiest way is to compare the client association process of two different clients. If you can get below debug output from those two different clients (ios client and a laptop), we can check where things get slow.

"debug client <mac_addr>"

HTH

Rasika

*** Pls rate all useful responses ***

Gray_FoX · ‎10-12-2020

10x for the tip, ill try it tommorow at work, what should i lock for ( i tested it at home, have 1 for testing) there are much info that is shown...
ill write the result tomorrow.

Gray_FoX · ‎10-13-2020

Today I tryed to read the Syslog, but couldn't finde how to activate the terminal monitor int the cli.

Is there something similar in MobilityExpress? How can i see the whole Logging msg when using SSH & CLI ???

10x in advance

patoberli · ‎10-14-2020

I don't know of one, because wireless causes a lot of logs. You will see that if you once enter the show logging.

But the debug commands are your best friend here.

Gray_FoX · ‎10-17-2020

.

Gray_FoX · ‎10-18-2020

Hello to everyone, sorry it took so long, was some bissy week...

Hire the Logs from the Apple device:

01(Cisco Controller) >*apfReceiveTask: Oct 13 21:38:19.246: dc:86:d8:01:7b:0d Received management frame ASSOCIATION REQUEST  on BSSID 5c:e1:76:7d:16:6f destination addr 5c:e1:76:7d:16:6f slotid 1
*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Updating 11r vendor IE

*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Updating the client capabiility as 2
*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Processing assoc-req station:dc:86:d8:01:7b:0d AP:5c:e1:76:7d:16:60-01 ssid : Medientechnik thread:32e83730
*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Station:  DC:86:D8:01:7B:0D  trying to join WLAN with RSSI -54. Checking for XOR roam conditions on AP:  5C:E1:76:7D:16:60  Slot: 1
*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Station:  DC:86:D8:01:7B:0D  is associating to AP  5C:E1:76:7D:16:60  which is not XOR roam capable
*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Updating location for mobile on same AP 5c:e1:76:7d:16:60-1
*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Client AVC Roaming context transfer needed? YES
*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Setting RTTS enabled to 0
*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Association received from mobile on BSSID 5c:e1:76:7d:16:6f AP AP5CE1-767C-30F0
*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Station:  DC:86:D8:01:7B:0D  trying to join WLAN with RSSI -54. Checking for XOR roam conditions on AP:  5C:E1:76:7D:16:60  Slot: 1
*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Station:  DC:86:D8:01:7B:0D  is associating to AP  5C:E1:76:7D:16:60  which is not XOR roam capable
*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Global 200 Clients are allowed to AP radio

*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Max Client Trap Threshold: 0  cur: 2

*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Rf profile 600 Clients are allowed to AP wlan

*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Updated local bridging VLAN to 0 while applying WLAN policy
*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d Updated session timeout to 0 and Sleep timeout to 720 while applying WLAN policy
*apfMsConnTask_0: Oct 13 21:38:19.247: dc:86:d8:01:7b:0d override for default ap group, marking intgrp NULL
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type, Tunnel User - 0
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d Check before Setting the NAS Id to WLAN specific Id ''
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d In processSsidIE:7640 setting Central switched to FALSE
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d Disabling flexconnect central association for the client
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d Applying site-specific Local Bridging override for station dc:86:d8:01:7b:0d - vapId 1, site 'default-group', interface 'management'
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d Applying Local Bridging Interface Policy for station dc:86:d8:01:7b:0d - vlan 0, interface id 0, interface 'management', nasId:''
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d Set Client Non AP specific WLAN apfMsAccessVlan = 427
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d This apfMsAccessVlan may be changed later from AAA after L2 Auth
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d Cleared localSwitchingVlan, may be assigned later based on AAA override
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d processSsidIE  statusCode is 0 and status is 0
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d processSsidIE  ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d STA - rates (6): 152 36 48 72 96 108 0 0 0 0 0 0 0 0 0 0
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d suppRates  statusCode is 0 and gotSuppRatesElement is 1
*apfMsConnTask_0: Oct 13 21:38:19.248: RSNIE in Assoc. Req.: (20)

*apfMsConnTask_0: Oct 13 21:38:19.248:      [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f

*apfMsConnTask_0: Oct 13 21:38:19.248:      [0016] ac 02 0c 00

*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d Processing RSN IE type 48, length 20 for mobile dc:86:d8:01:7b:0d
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d Selected Unicast cipher CCMP128 for client device
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d Received 802.11i PSK key management suite, enabling Authentication
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d RSN Capabilities:  12
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d non-11w Capable mobile
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d Received RSN IE(AKM:2) with 0 PMKIDs
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d Assigning flex webauth IPv4-ACL ID :65535, IPv6-ACL ID:65535 for AP WLAN ID : 1
*apfMsConnTask_0: Oct 13 21:38:19.248: dc:86:d8:01:7b:0d Assigned flex post-auth IPv4-ACL ID :65535, IPv6-ACL ID:65535 for AP WLAN ID : 1
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d AID 2 in Assoc Req from flex AP 5c:e1:76:7d:16:60 is same as in mscb dc:86:d8:01:7b:0d
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d Assoc Req BSSID 5c:e1:76:7d:16:6f AP(AP5CE1-767C-30F0) slot 1 ssid (Internet) Tmstmp 2106 AID 2 stCode 0/0 apChngd 0 oldAp 5C:E1:76:7D:16:60
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d apfMsRunStateDec
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d apfMs1xStateDec
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d 19:82:21:202 RUN (20) Change state to START (0) last state RUN (20)

*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d the value of url acl preserve flag is 0 for mobile dc:86:d8:01:7b:0d (caller pem_api.c:3816)
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d 19:82:21:202 START (0) Initializing policy
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d 19:82:21:202 START (0) Change state to AUTHCHECK (2) last state START (0)

*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d  apfVapSecurity=0x40004000 L2=16384 SkipWeb=0
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d  AuthenticationRequired = 1
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d 19:82:21:202 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d Encryption policy is set to 0x80000001
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d Flex Central Auth Client
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d Setting the action to initiate 1x 4 way handshake upon Add_Mobile_Ack for station with encrypt policy:[80000001]
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d 19:82:21:202 8021X_REQD (3) Client already has IP 19:82:21:202 DHCP Not required on AP 5c:e1:76:7d:16:60 vapId 1 apVapId 1
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d Not Using WMM Compliance code qosCap 00
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d flex webauth acl id to be sent :65535 name : client acl id :65535 name :
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d flex webauth ipv6 acl id to be sent :65535 name : client acl id :65535 name :
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d Vlan while overriding the policy = -1
*apfMsConnTask_0: Oct 13 21:38:19.249: dc:86:d8:01:7b:0d sending to spamAddMobile vlanId -1 aclName = , flexAclId 65535

*apfMsConnTask_0: Oct 13 21:38:19.251: dc:86:d8:01:7b:0d 19:82:21:202 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 5c:e1:76:7d:16:60 vapId 1 apVapId 1 flex acl-name: v6acl-name
*apfMsConnTask_0: Oct 13 21:38:19.251: dc:86:d8:01:7b:0d apfPemAddUser2 (apf_policy.c:465) Changing state for mobile dc:86:d8:01:7b:0d on AP 5c:e1:76:7d:16:60 from Associated to Associated

*apfMsConnTask_0: Oct 13 21:38:19.251: dc:86:d8:01:7b:0d apfPemAddUser2:session timeout forstation dc:86:d8:01:7b:0d - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is  0
*apfMsConnTask_0: Oct 13 21:38:19.251: dc:86:d8:01:7b:0d Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_0: Oct 13 21:38:19.251: dc:86:d8:01:7b:0d Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0

*apfMsConnTask_0: Oct 13 21:38:19.251: dc:86:d8:01:7b:0d Sending assoc-resp with status 0 station:dc:86:d8:01:7b:0d AP:5c:e1:76:7d:16:60-01 on apVapId 1
*apfMsConnTask_0: Oct 13 21:38:19.251: dc:86:d8:01:7b:0d Sending Assoc Response (status: '0') to station on AP AP5CE1-767C-30F0 on BSSID 5c:e1:76:7d:16:6f ApVapId 1 Slot 1, mobility role 1
*apfMsConnTask_0: Oct 13 21:38:19.251: dc:86:d8:01:7b:0d apfProcessAssocReq (apf_80211.c:12920) Changing state for mobile dc:86:d8:01:7b:0d on AP 5c:e1:76:7d:16:60 from Associated to Associated

*spamApTask0: Oct 13 21:38:19.252: dc:86:d8:01:7b:0d Add SGT:0 to AP 5c:e1:76:7d:16:60
*spamApTask0: Oct 13 21:38:19.252: dc:86:d8:01:7b:0d Add CTS mobile SGT - Encoded the capwap payload for the mobile with SGT 0
*spamApTask0: Oct 13 21:38:19.252: IP context - srcApMac:  5C:E1:76:7D:16:60  msMac:  DC:86:D8:01:7B:0D  msIpAddr: 19:82:21:202 msIpv6Cnt: 1
*spamApTask0: Oct 13 21:38:19.252: msIpv6Addr[1] : fe80:0000:0000:0000:0815:049e:9dfe:d6f7
*spamApTask0: Oct 13 21:38:19.252: dc:86:d8:01:7b:0d Sending client IP( 19:82:21:202) context in AddMobile
*spamApTask0: Oct 13 21:38:19.252: dc:86:d8:01:7b:0d Flex Ipv6 pre-auth acl is not present, not Encoding Flex Ipv6 acl for add mobile Payload
*spamApTask0: Oct 13 21:38:19.252: dc:86:d8:01:7b:0d Flex Ipv6 post auth acl is not present, not updating add mobile Payload
*spamApTask0: Oct 13 21:38:19.252: dc:86:d8:01:7b:0d Successful transmission of LWAPP Add-Mobile to AP 5c:e1:76:7d:16:60 slotId 1 idx@44
*spamApTask0: Oct 13 21:38:19.252: dc:86:d8:01:7b:0d Setting ADD_MOBILE (idx 44, seqno 45, action 1, count 45, last count 45) ack state for STA on AP 5c:e1:76:7d:16:60
*spamApTask0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d Received add/del ack packet with sequence number: got 45 expected 45 action = 1
*spamApTask0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d Received ADD_MOBILE ack - Initiating 1x to STA dc:86:d8:01:7b:0d (idx 44)
*spamApTask0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d APF Initiating 1x to STA dc:86:d8:01:7b:0d
*spamApTask0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d Sent dot1x auth initiate message for mobile dc:86:d8:01:7b:0d
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d dot1xProcessInitiate1XtoMobile to mobile station dc:86:d8:01:7b:0d (mscb 2, msg 2)
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d reauth_sm state transition 1 ---> 0 for mobile dc:86:d8:01:7b:0d at 1x_reauth_sm.c:53
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d Normal psk client, full auth
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d Creating a PKC PMKID Cache entry for station dc:86:d8:01:7b:0d (RSN 2)
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d Resetting MSCB PMK Cache Entry @index 0 for station dc:86:d8:01:7b:0d
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d Removing BSSID 5c:e1:76:7d:16:6f from PMKID cache of station dc:86:d8:01:7b:0d
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d Setting active key cache index 0 ---> 8
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d Setting active key cache index 8 ---> 0
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d Created PMKID PMK Cache for BSSID 5c:e1:76:7d:16:6f  at index 0 for station dc:86:d8:01:7b:0d
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291: New PMKID: (16)

*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291:      [0000] 6e aa 40 43 b0 d9 5f 0f 28 16 04 b9 05 b7 45 72

*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d sendPmkIdinM1 0
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d Initiating RSN PSK to mobile dc:86:d8:01:7b:0dkeyMgmtType : 0
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d unsetting PmkIdValidatedByAp
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d Not WPA3 OWE client, no creation of OWE pmkcache entry
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.291: dc:86:d8:01:7b:0d EAP-PARAM Debug - eap-params for Wlan-Id :1 is disabled - applying Global eap timers and retries
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.292: dc:86:d8:01:7b:0d Disable re-auth, use PMK lifetime.
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.292: dc:86:d8:01:7b:0d dot1x - moving mobile dc:86:d8:01:7b:0d into Force Auth state
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.292: dc:86:d8:01:7b:0d Skipping EAP-Success to mobile dc:86:d8:01:7b:0d (encryptBit:0)
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.292: dc:86:d8:01:7b:0d key Desc Version FT - 0

*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.292: dc:86:d8:01:7b:0d skipping PMKID inclusion in M1.
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.292: dc:86:d8:01:7b:0d Starting key exchange to mobile dc:86:d8:01:7b:0d, data packets will be dropped
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.292: dc:86:d8:01:7b:0d Sending EAPOL-Key Message to mobile dc:86:d8:01:7b:0d
   state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.292: dc:86:d8:01:7b:0d Allocating EAP Pkt for retransmission to mobile dc:86:d8:01:7b:0d
*CAPWAP DATA: Oct 13 21:38:19.294: dc:86:d8:01:7b:0d validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: dc:86:d8:01:7b:0d Received EAPOL-Key from mobile dc:86:d8:01:7b:0d
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: dc:86:d8:01:7b:0d key Desc Version FT - 0

*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: dc:86:d8:01:7b:0d Received EAPOL-key in PTK_START state (message 2) from mobile dc:86:d8:01:7b:0d
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: dc:86:d8:01:7b:0d Encryption Policy: 4, PTK Key Length: 48
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: dc:86:d8:01:7b:0d Successfully computed PTK from PMK!!!
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: dc:86:d8:01:7b:0d Received valid MIC in EAPOL Key Message M2!!!!!
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: dc:86:d8:01:7b:0d Compare RSN IE in association and EAPOL-M2 frame(rsnie_len :20, and grpMgmtCipherLen:0)
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: dc:86:d8:01:7b:0d rsnieCapabilty = c rsnie_len =20
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: dc:86:d8:01:7b:0d Dumping RSNIE received in Association request(len = 22):
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: 00000000: 30 14 01 00 00 0f ac 04  01 00 00 0f ac 04 01 00  0...............
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: 00000010: 00 0f ac 02 0c 00                                 ......
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: dc:86:d8:01:7b:0d Dumping RSNIE received in EAPOL M2 (len = 20):
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: 00000000: 01 00 00 0f ac 04 01 00  00 0f ac 04 01 00 00 0f  ................
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: 00000010: ac 02 0c 00                                       ....
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: dc:86:d8:01:7b:0d Stopping retransmission timer for mobile dc:86:d8:01:7b:0d
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: dc:86:d8:01:7b:0d key Desc Version FT - 0

*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: dc:86:d8:01:7b:0d key Desc Version FT - 0

*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: dc:86:d8:01:7b:0d Sending EAPOL-Key Message to mobile dc:86:d8:01:7b:0d
   state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.295: dc:86:d8:01:7b:0d Reusing allocated memory for  EAP Pkt for retransmission to mobile dc:86:d8:01:7b:0d
*CAPWAP DATA: Oct 13 21:38:19.301: dc:86:d8:01:7b:0d validating eapol pkt: key version = 2
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.301: dc:86:d8:01:7b:0d Received EAPOL-Key from mobile dc:86:d8:01:7b:0d
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.301: dc:86:d8:01:7b:0d key Desc Version FT - 0

*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.301: dc:86:d8:01:7b:0d Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile dc:86:d8:01:7b:0d
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.301: dc:86:d8:01:7b:0d Stopping retransmission timer for mobile dc:86:d8:01:7b:0d
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.301: dc:86:d8:01:7b:0d Freeing EAP Retransmit Bufer for mobile dc:86:d8:01:7b:0d
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.301: dc:86:d8:01:7b:0d apfMs1xStateInc
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.301: dc:86:d8:01:7b:0d 19:82:21:202 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3)

*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.301: dc:86:d8:01:7b:0d Flex Central Auth Client
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.301: dc:86:d8:01:7b:0d 19:82:21:202 L2AUTHCOMPLETE (4) Client already has IP 19:82:21:202, DHCP Not required on AP 5c:e1:76:7d:16:60 vapId 1 apVapId 1
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.301: dc:86:d8:01:7b:0d Not Using WMM Compliance code qosCap 00
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.301: dc:86:d8:01:7b:0d flex webauth acl id to be sent :65535 name : client acl id :65535 name :
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.301: dc:86:d8:01:7b:0d flex webauth ipv6 acl id to be sent :65535 name : client acl id :65535 name :
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.302: dc:86:d8:01:7b:0d Vlan while overriding the policy = -1
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.302: dc:86:d8:01:7b:0d sending to spamAddMobile vlanId -1 aclName = , flexAclId 65535

*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.302: dc:86:d8:01:7b:0d 19:82:21:202 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 5c:e1:76:7d:16:60 vapId 1 apVapId 1 flex acl-name: v6acl-name
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.302: dc:86:d8:01:7b:0d apfMsRunStateInc
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.302: dc:86:d8:01:7b:0d 19:82:21:202 L2AUTHCOMPLETE (4) Change state to RUN (20) last state L2AUTHCOMPLETE (4)

*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.302: dc:86:d8:01:7b:0d 19:82:21:2022 RUN (20) Reached PLUMBFASTPATH: from line 7506, null
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.302: dc:86:d8:01:7b:0d 19:82:21:202 RUN (20) Not adding NPU. L3-auth not required on this local switching local DHCP client.
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.302: dc:86:d8:01:7b:0d Initiating Accounting request(1) update for mobile
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.302: dc:86:d8:01:7b:0d PemLocationConfigured [1]Adding VSA with NAS update and Role[1] with state[0]
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.302: dc:86:d8:01:7b:0d 19:82:21:202 RUN (20) No 11v BTM
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.302: dc:86:d8:01:7b:0d 19:82:21:202 RUN (20) NO release MSCB
*Dot1x_NW_MsgTask_0: Oct 13 21:38:19.302: dc:86:d8:01:7b:0d Successfully Plumbed PTK session Keysfor mobile dc:86:d8:01:7b:0d
*spamApTask0: Oct 13 21:38:19.303: dc:86:d8:01:7b:0d Add SGT:0 to AP 5c:e1:76:7d:16:60
*spamApTask0: Oct 13 21:38:19.303: dc:86:d8:01:7b:0d Add CTS mobile SGT - Encoded the capwap payload for the mobile with SGT 0
*spamApTask0: Oct 13 21:38:19.303: IP context - srcApMac:  5C:E1:76:7D:16:60  msMac:  DC:86:D8:01:7B:0D  msIpAddr:  19:82:21:202 msIpv6Cnt: 1
*spamApTask0: Oct 13 21:38:19.303: msIpv6Addr[1] : fe80:0000:0000:0000:0815:049e:9dfe:d6f7
*spamApTask0: Oct 13 21:38:19.303: dc:86:d8:01:7b:0d Sending client IP( 19:82:21:202) context in AddMobile
*spamApTask0: Oct 13 21:38:19.303: dc:86:d8:01:7b:0d Flex Ipv6 pre-auth acl is not present, not Encoding Flex Ipv6 acl for add mobile Payload
*spamApTask0: Oct 13 21:38:19.303: dc:86:d8:01:7b:0d Flex Ipv6 post auth acl is not present, not updating add mobile Payload
*spamApTask0: Oct 13 21:38:19.303: dc:86:d8:01:7b:0d Successful transmission of LWAPP Add-Mobile to AP 5c:e1:76:7d:16:60 slotId 1 idx@45
*spamApTask0: Oct 13 21:38:19.303: dc:86:d8:01:7b:0d Setting ADD_MOBILE (idx 46,  action 0, last count 45) ack state for STA on AP 5c:e1:76:7d:16:60
*apfReceiveTask: Oct 13 21:38:20.707: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 1, add_or_delete 1
*apfReceiveTask: Oct 13 21:38:20.707: dc:86:d8:01:7b:0d IPv4 Addr: 0:0:0:0

*CAPWAP DATA: Oct 13 21:38:20.708: dc:86:d8:01:7b:0d IAPP-IP-UPDATE(0):891 Bytes received for client
*apfReceiveTask: Oct 13 21:38:20.708: dc:86:d8:01:7b:0d Recieved MS IPv4 Addr= 19:82:21:202
*apfReceiveTask: Oct 13 21:38:20.708: dc:86:d8:01:7b:0d Recieved IPv6 addresses count: 1
*apfReceiveTask: Oct 13 21:38:20.708: dc:86:d8:01:7b:0d Updating MS IPv6[1] Addr=   fe80:0000:0000:0000:0815:049e:9dfe:d6f7
*apfReceiveTask: Oct 13 21:38:20.708: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 1, add_or_delete 1
*apfReceiveTask: Oct 13 21:38:20.708: dc:86:d8:01:7b:0d IPv4 Addr: 19:82:21:202

*apfReceiveTask: Oct 13 21:38:20.708: dc:86:d8:01:7b:0d DHCP success event for client. Clearing dhcp failure count for interface management.
*apfReceiveTask: Oct 13 21:38:20.708: dc:86:d8:01:7b:0d DHCP success event for client. Clearing dhcp failure count for interface management.
*apfReceiveTask: Oct 13 21:38:21.805: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 2, add_or_delete 1
*apfReceiveTask: Oct 13 21:38:21.805: dc:86:d8:01:7b:0d IPv4 Addr: 19:82:21:202

*apfReceiveTask: Oct 13 21:38:21.806: dc:86:d8:01:7b:0d Static IP client associated to interface management which cannot support client subnet.
*apfReceiveTask: Oct 13 21:38:22.009: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 2, add_or_delete 1
*apfReceiveTask: Oct 13 21:38:22.009: dc:86:d8:01:7b:0d IPv4 Addr: 19:82:21:202

*apfReceiveTask: Oct 13 21:38:22.009: dc:86:d8:01:7b:0d Static IP client associated to interface management which cannot support client subnet.
*apfReceiveTask: Oct 13 21:38:22.367: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 2, add_or_delete 1
*apfReceiveTask: Oct 13 21:38:22.367: dc:86:d8:01:7b:0d IPv4 Addr: 19:82:21:202

*apfReceiveTask: Oct 13 21:38:22.367: dc:86:d8:01:7b:0d Static IP client associated to interface management which cannot support client subnet.
*apfReceiveTask: Oct 13 21:39:23.203: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 2, add_or_delete 1
*apfReceiveTask: Oct 13 21:39:23.203: dc:86:d8:01:7b:0d IPv4 Addr: 19:82:21:202

*apfReceiveTask: Oct 13 21:39:23.203: dc:86:d8:01:7b:0d Static IP client associated to interface management which cannot support client subnet.
*apfReceiveTask: Oct 13 21:39:23.739: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 2, add_or_delete 1
*apfReceiveTask: Oct 13 21:39:23.739: dc:86:d8:01:7b:0d IPv4 Addr: 19:82:21:202

*apfReceiveTask: Oct 13 21:39:23.739: dc:86:d8:01:7b:0d Static IP client associated to interface management which cannot support client subnet.
*apfReceiveTask: Oct 13 21:39:24.100: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 2, add_or_delete 1
*apfReceiveTask: Oct 13 21:39:24.100: dc:86:d8:01:7b:0d IPv4 Addr: 19:82:21:202

*apfReceiveTask: Oct 13 21:39:24.100: dc:86:d8:01:7b:0d Static IP client associated to interface management which cannot support client subnet.
*apfReceiveTask: Oct 13 21:39:24.585: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 2, add_or_delete 1
*apfReceiveTask: Oct 13 21:39:24.585: dc:86:d8:01:7b:0d IPv4 Addr: 19:82:21:202

*apfReceiveTask: Oct 13 21:39:24.586: dc:86:d8:01:7b:0d Static IP client associated to interface management which cannot support client subnet.
*apfReceiveTask: Oct 13 21:39:25.075: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 2, add_or_delete 1
*apfReceiveTask: Oct 13 21:39:25.075: dc:86:d8:01:7b:0d IPv4 Addr: 19:82:21:202

*apfReceiveTask: Oct 13 21:39:25.075: dc:86:d8:01:7b:0d Static IP client associated to interface management which cannot support client subnet.
*apfReceiveTask: Oct 13 21:39:25.563: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 2, add_or_delete 1
*apfReceiveTask: Oct 13 21:39:25.563: dc:86:d8:01:7b:0d IPv4 Addr: 19:82:21:202

*apfReceiveTask: Oct 13 21:39:25.563: dc:86:d8:01:7b:0d Static IP client associated to interface management which cannot support client subnet.
*apfReceiveTask: Oct 13 21:39:26.052: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 2, add_or_delete 1
*apfReceiveTask: Oct 13 21:39:26.052: dc:86:d8:01:7b:0d IPv4 Addr: 19:82:21:202

*apfReceiveTask: Oct 13 21:39:26.052: dc:86:d8:01:7b:0d Static IP client associated to interface management which cannot support client subnet.
*apfReceiveTask: Oct 13 21:39:26.540: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 2, add_or_delete 1
*apfReceiveTask: Oct 13 21:39:26.540: dc:86:d8:01:7b:0d IPv4 Addr: 19:82:21:202

*apfReceiveTask: Oct 13 21:39:26.540: dc:86:d8:01:7b:0d Static IP client associated to interface management which cannot support client subnet.
*apfReceiveTask: Oct 13 21:39:27.028: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 2, add_or_delete 1
*apfReceiveTask: Oct 13 21:39:27.028: dc:86:d8:01:7b:0d IPv4 Addr: 19:82:21:202

*apfReceiveTask: Oct 13 21:39:27.028: dc:86:d8:01:7b:0d Static IP client associated to interface management which cannot support client subnet.
*apfReceiveTask: Oct 13 21:39:27.516: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 2, add_or_delete 1
*apfReceiveTask: Oct 13 21:39:27.516: dc:86:d8:01:7b:0d IPv4 Addr: 19:82:21:202

*apfReceiveTask: Oct 13 21:39:27.516: dc:86:d8:01:7b:0d Static IP client associated to interface management which cannot support client subnet.
*apfReceiveTask: Oct 13 21:39:28.004: dc:86:d8:01:7b:0d WcdbClientUpdate: IP Binding from WCDB ip_learn_type 2, add_or_delete 1
*apfReceiveTask: Oct 13 21:39:28.004: dc:86:d8:01:7b:0d IPv4 Addr: 19:82:21:202

The last 3 msg are repeating with no end.

any idea how to Fix it? 10x you all for the support.

patoberli · ‎10-19-2020

Here a useful tool: https://cway.cisco.com/wireless-debug-analyzer/

And the error message is this:

Static IP client associated to interface management which cannot support client subnet.

It seems this client has a static IP configured, which is not in the same VLAN/network as the assigned virtual interface of the WLC.

Gray_FoX · ‎10-21-2020

There is no Static IP on the Apple Clients, or do you mean the AP?

best regards

Gray_FoX · ‎10-21-2020

The ME is Configured with 2 networks each network hase its own VLAN and IP Scope

Example

Network 1 SSID: FreeNet
Network/Mask: 10.90.30.0 255.255.255.0 GW:10.90.30.1
StartIP: 10.98.30.130 EndIP 10.98.30.254
VlanID: 421

Network 2 SSID: Net2

Network/Mask 17.90.30.0 255.255.255.0 GW 17.90.30.0

StartIP: 17.90.30.130 EndIP 10.98.30.254
VlanID: 425

Native Vlan is 1

i want wo broadcast 2 networks , and with Android or Windwos PC i do not have pany problems.

just Apple devices take 50sec + to connect to the either network... Apple best practices are all OK

any idea where my mistake is ?

Im verry thankfull for your help and support.

Sorry im new to Cisco Mobility expres and i have much to learn! Tnx to all

Gray_FoX · ‎10-21-2020

Ok, sooo if i put the network in Vlan 1 then it is working like a charm, but i don't want that the network is in Vlan1.

I have Multiple SSID (2) each is in a separated Vlan.

In VLAN & Firelall Native VLAN ID = 1
Use VLAN Tagging = Yes

DHCP Scope = SSID of network VLAN ID* = 425
Enable Firewall = NO

Why is't it working properrly? any ideas?

Gray_FoX · ‎10-23-2020

i have found this bug, https://bst.cloudapps.cisco.com/bugsearch/bug/CSCvp90293/?rfs=iqvred does it mean that there is no solution?