Solved: WLAN User Idle Timeout and WPA2-PSK authentication

rick505d3 · ‎02-03-2015

Hi,

There is a WLAN for Guest users with Session Timeout of 65535 sec and User Idle Timeout of 28800 sec. The WLAN uses PSK as Layer-2 authentication and Web Auth as Layer-3 authentication. Authentication source is locally created users on the controllers (LocalEAP) - can be RADIUS through ISE as well.

(Cisco Controller) show>sysinfo

Manufacturer's Name.............................. Cisco Systems Inc.
Product Name..................................... Cisco Controller
Product Version.................................. 7.6.130.0
RTOS Version..................................... 7.6.130.0
Bootloader Version............................... 7.6.130.0
Emergency Image Version.......................... 7.6.130.0

Build Type....................................... DATA + WPS

System Name...................................... vwlc-1
System Location.................................. Matrix
System Contact................................... IT HelpDesk Matrix
System ObjectID.................................. 1.3.6.1.4.1.9.1.1631
IP Address....................................... 10.10.10.50
System Up Time................................... 6 days 17 hrs 30 mins 26 secs
System Timezone Location......................... (GMT+10:00) Sydney, Melbourne, Canberra
System Stats Realtime Interval................... 5
System Stats Normal Interval..................... 180

Configured Country............................... AU  - Australia

--More-- or (q)uit
State of 802.11b Network......................... Enabled
State of 802.11a Network......................... Enabled
Number of WLANs.................................. 2
Number of Active Clients......................... 0

Burned-in MAC Address............................ 00:0C:29:74:15:2F
Maximum number of APs supported.................. 200



(Cisco Controller) show> wlan 2

WLAN Identifier.................................. 2
Profile Name..................................... Matrix-LocalEAP
Network Name (SSID).............................. Matrix-LocalEAP
Status........................................... Enabled
MAC Filtering.................................... Disabled
Broadcast SSID................................... Enabled
AAA Policy Override.............................. Disabled
Network Admission Control
Client Profiling Status
    Radius Profiling ............................ Disabled
     DHCP ....................................... Disabled
     HTTP ....................................... Disabled
    Local Profiling ............................. Disabled
     DHCP ....................................... Disabled
     HTTP ....................................... Disabled
  Radius-NAC State............................... Disabled
  SNMP-NAC State................................. Disabled
  Quarantine VLAN................................ 0
Maximum number of Associated Clients............. 0
Maximum number of Clients per AP Radio........... 200

Number of Active Clients......................... 0
Exclusionlist Timeout............................ 60 seconds
Session Timeout.................................. 65535 seconds
User Idle Timeout................................ 28800 seconds
Sleep Client..................................... disable
Sleep Client Timeout............................. 12 hours
User Idle Threshold.............................. 0 Bytes
NAS-identifier................................... vwlc-1
CHD per WLAN..................................... Enabled
Webauth DHCP exclusion........................... Disabled
Interface........................................ management
Multicast Interface.............................. Not Configured
WLAN IPv4 ACL.................................... unconfigured
WLAN IPv6 ACL.................................... unconfigured
WLAN Layer2 ACL.................................. unconfigured
mDNS Status...................................... Disabled
mDNS Profile Name................................ unconfigured
DHCP Server...................................... Default
DHCP Address Assignment Required................. Enabled
Static IP client tunneling....................... Disabled
Quality of Service............................... Silver
Per-SSID Rate Limits............................. Upstream      Downstream
Average Data Rate................................   0             0

Average Realtime Data Rate.......................   0             0
Burst Data Rate..................................   0             0
Burst Realtime Data Rate.........................   0             0
Per-Client Rate Limits........................... Upstream      Downstream
Average Data Rate................................   0             0
Average Realtime Data Rate.......................   0             0
Burst Data Rate..................................   0             0
Burst Realtime Data Rate.........................   0             0
Scan Defer Priority.............................. 4,5,6
Scan Defer Time.................................. 100 milliseconds
WMM.............................................. Allowed
WMM UAPSD Compliant Client Support............... Disabled
Media Stream Multicast-direct.................... Disabled
CCX - AironetIe Support.......................... Enabled
CCX - Gratuitous ProbeResponse (GPR)............. Disabled
CCX - Diagnostics Channel Capability............. Disabled
Dot11-Phone Mode (7920).......................... Disabled
Wired Protocol................................... 802.1P (Tag=2)
Passive Client Feature........................... Disabled
Peer-to-Peer Blocking Action..................... Disabled
Radio Policy..................................... All
DTIM period for 802.11a radio.................... 1
DTIM period for 802.11b radio.................... 1

Radius Servers
   Authentication................................ 10.10.10.70 1812
   Accounting.................................... 10.10.10.70 1813
      Interim Update............................. Disabled
      Framed IPv6 Acct AVP ...................... Prefix
   Dynamic Interface............................. Disabled
   Dynamic Interface Priority.................... wlan
Local EAP Authentication......................... Enabled (Profile 'local-eap-matrix')
Security

   802.11 Authentication:........................ Open System
   FT Support.................................... Disabled
   Static WEP Keys............................... Disabled
   802.1X........................................ Disabled
   Wi-Fi Protected Access (WPA/WPA2)............. Enabled
      WPA (SSN IE)............................... Disabled
      WPA2 (RSN IE).............................. Enabled
         TKIP Cipher............................. Disabled
         AES Cipher.............................. Enabled
                                                               Auth Key Management
         802.1x.................................. Disabled
         PSK..................................... Enabled
         CCKM.................................... Disabled

         FT-1X(802.11r).......................... Disabled
         FT-PSK(802.11r)......................... Disabled
         PMF-1X(802.11w)......................... Disabled
         PMF-PSK(802.11w)........................ Disabled
      FT Reassociation Timeout................... 20
      FT Over-The-DS mode........................ Disabled
      GTK Randomization.......................... Disabled
      SKC Cache Support.......................... Disabled
      CCKM TSF Tolerance......................... 1000
   WAPI.......................................... Disabled
   Wi-Fi Direct policy configured................ Disabled
   EAP-Passthrough............................... Disabled
   CKIP ......................................... Disabled
   Web Based Authentication...................... Enabled
        IPv4 ACL........................................ Unconfigured
        IPv6 ACL........................................ Unconfigured
        Web-Auth Flex ACL............................... Unconfigured
        Web Authentication server precedence:
        1............................................... local
        2............................................... radius
        3............................................... ldap
   Web-Passthrough............................... Disabled
   Conditional Web Redirect...................... Disabled

   Splash-Page Web Redirect...................... Disabled
   Auto Anchor................................... Disabled
   FlexConnect Local Switching................... Enabled
   flexconnect Central Dhcp Flag................. Disabled
   flexconnect nat-pat Flag...................... Disabled
   flexconnect Dns Override Flag................. Disabled
   flexconnect PPPoE pass-through................ Disabled
   flexconnect local-switching IP-source-guar.... Disabled
   FlexConnect Vlan based Central Switching ..... Disabled
   FlexConnect Local Authentication.............. Disabled
   FlexConnect Learn IP Address.................. Enabled
   Client MFP.................................... Optional
   PMF........................................... Disabled
   PMF Association Comeback Time................. 1
   PMF SA Query RetryTimeout..................... 200
   Tkip MIC Countermeasure Hold-down Timer....... 60
   Eap-params.................................... Disabled
AVC Visibilty.................................... Disabled
AVC Profile Name................................. None
Flow Monitor Name................................ None
Split Tunnel (Printers).......................... Disabled
Call Snooping.................................... Disabled
Roamed Call Re-Anchor Policy..................... Disabled

SIP CAC Fail Send-486-Busy Policy................ Enabled
SIP CAC Fail Send Dis-Association Policy......... Disabled
KTS based CAC Policy............................. Disabled
Assisted Roaming Prediction Optimization......... Disabled
802.11k Neighbor List............................ Disabled
802.11k Neighbor List Dual Band.................. Disabled
Band Select...................................... Disabled
Load Balancing................................... Disabled
Multicast Buffer................................. Disabled

 Mobility Anchor List
 WLAN ID     IP Address            Status
 -------     ---------------       ------

802.11u........................................ Disabled

MSAP Services.................................. Disabled

Local Policy
----------------
Priority  Policy Name
--------  ---------------

The wireless user on joining the WLAN enters the PSK and than gets redirected to WLC Web Auth portal for authentication. On successful login, the user is granted access. The issue is that despite Idle Timeout being 28800 sec (8 hours), the WLC removes the client entry before 8 hours if the device goes to sleep - mostly within the first hour. Tested this on Windows 7 notebook multiple times. When the PC is put to sleep, the WLC loses its record after some time. When PC wakes up, it has to undergo Web Auth again. Debugging the client MAC generates these logs - from initial association to final clearing.


(Cisco Controller) >*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 Association received from mobile on BSSID 00:26:cb:4c:89:d1
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 Global 200 Clients are allowed to AP radio

*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 Max Client Trap Threshold: 0  cur: 1

*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 Rf profile 600 Clients are allowed to AP wlan

*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 override for default ap group, marking intgrp NULL
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 Applying Interface policy on Mobile, role Local. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 10

*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 Re-applying interface policy for client

*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 10.10.1.130 WEBAUTH_REQD (8) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2219)
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 10.10.1.130 WEBAUTH_REQD (8) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2240)
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 In processSsidIE:4850 setting Central switched to FALSE
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 Applying site-specific Local Bridging override for station 3c:a9:f4:0b:91:70 - vapId 2, site 'default-group', interface 'management'
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 Applying Local Bridging Interface Policy for station 3c:a9:f4:0b:91:70 - vlan 10, interface id 0, interface 'management'
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 processSsidIE  statusCode is 0 and status is 0
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 processSsidIE  ssid_done_flag is 0 finish_flag is 0
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 STA - rates (6): 152 36 176 72 96 108 0 0 0 0 0 0 0 0 0 0
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 suppRates  statusCode is 0 and gotSuppRatesElement is 1
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 Processing RSN IE type 48, length 22 for mobile 3c:a9:f4:0b:91:70
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 AID 1 in Assoc Req from flex AP 00:26:cb:4c:89:d0 is same as in mscb 3c:a9:f4:0b:91:70
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 apfMs1xStateDec
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 10.10.1.130 WEBAUTH_REQD (8) Change state to START (0) last state WEBAUTH_REQD (8)

*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 10.10.1.130 START (0) Initializing policy
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 10.10.1.130 START (0) Change state to AUTHCHECK (2) last state START (0)

*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 10.10.1.130 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2)

*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 Encryption policy is set to 0x80000001
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 Central switch is FALSE
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 Sending Local Switch flag = 1
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 10.10.1.130 8021X_REQD (3) DHCP Not required on AP 00:26:cb:4c:89:d0 vapId 2 apVapId 2for this client
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 Not Using WMM Compliance code qosCap 00
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 10.10.1.130 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 00:26:cb:4c:89:d0 vapId 2 apVapId 2 flex-acl-name:
*apfMsConnTask_0: Feb 04 07:48:10.562: 3c:a9:f4:0b:91:70 apfPemAddUser2 (apf_policy.c:333) Changing state for mobile 3c:a9:f4:0b:91:70 on AP 00:26:cb:4c:89:d0 from Associated to Associated

*apfMsConnTask_0: Feb 04 07:48:10.563: 3c:a9:f4:0b:91:70 apfPemAddUser2:session timeout forstation 3c:a9:f4:0b:91:70 - Session Tout 65535, apfMsTimeOut '65535' and sessionTimerRunning flag is  0
*apfMsConnTask_0: Feb 04 07:48:10.563: 3c:a9:f4:0b:91:70 Scheduling deletion of Mobile Station:  (callerId: 49) in 65535 seconds
*apfMsConnTask_0: Feb 04 07:48:10.563: 3c:a9:f4:0b:91:70 Func: apfPemAddUser2, Ms Timeout = 65535, Session Timeout = 65535

*apfMsConnTask_0: Feb 04 07:48:10.563: 3c:a9:f4:0b:91:70 Sending Assoc Response to station on BSSID 00:26:cb:4c:89:d1 (status 0) ApVapId 2 Slot 0
*apfMsConnTask_0: Feb 04 07:48:10.563: 3c:a9:f4:0b:91:70 apfProcessAssocReq (apf_80211.c:8294) Changing state for mobile 3c:a9:f4:0b:91:70 on AP 00:26:cb:4c:89:d0 from Associated to Associated

*pemReceiveTask: Feb 04 07:48:10.563: 3c:a9:f4:0b:91:70 10.10.1.130 Removed NPU entry.
*spamApTask7: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 Sent 1x initiate message to multi thread task for mobile 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 Creating a PKC PMKID Cache entry for station 3c:a9:f4:0b:91:70 (RSN 2)
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 Resetting MSCB PMK Cache Entry 0 for station 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 Removing BSSID 00:26:cb:4c:89:d1 from PMKID cache of station 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 Setting active key cache index 0 ---> 8
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 Setting active key cache index 8 ---> 0
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 Adding BSSID 00:26:cb:4c:89:d1 to PMKID cache at index 0 for station 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: New PMKID: (16)

*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566:      [0000] 67 67 8f 7d 2a 8d 78 f9 6d 29 c7 74 d2 fd 6a 25

*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 Initiating RSN PSK to mobile 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 EAP-PARAM Debug - eap-params for Wlan-Id :2 is disabled - applying Global eap timers and retries
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 dot1x - moving mobile 3c:a9:f4:0b:91:70 into Force Auth state
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 Skipping EAP-Success to mobile 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 EAPOL Header:
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 00000000: 02 03 5f 00                                       .._.
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 Found an cache entry for BSSID 00:26:cb:4c:89:d1 in PMKID cache at index 0 of station 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 Found an cache entry for BSSID 00:26:cb:4c:89:d1 in PMKID cache at index 0 of station 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: Including PMKID in M1  (16)

*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566:      [0000] 67 67 8f 7d 2a 8d 78 f9 6d 29 c7 74 d2 fd 6a 25

*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 Starting key exchange to mobile 3c:a9:f4:0b:91:70, data packets will be dropped
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 Sending EAPOL-Key Message to mobile 3c:a9:f4:0b:91:70
                                                                                                                    state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 Sending EAPOL-Key Message to mobile 3c:a9:f4:0b:91:70
                                                                                                                    state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 Allocating EAP Pkt for retransmission to mobile 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70 mscb->apfMsLwappLradNhMac = 00:0c:29:e4:e9:6a mscb->apfMsLradSlotId = 0 mscb->apfMsLradJumbo = 0 mscb->apfMsintIfNum = 1
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70  mscb->apfMsBssid = 00:26:cb:4c:89:d0 mscb->apfMsAddress = 3c:a9:f4:0b:91:70 mscb->apfMsApVapId = 2
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70  dot1xcb->snapOrg = 00 00 00 dot1xcb->eapolWepBit = 0 mscb->apfMsLwappLradVlanId = 10 mscb->apfMsLwappMwarInet.ipv4.addr = 168430130
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.566: 3c:a9:f4:0b:91:70  mscb->apfMsLwappMwarPort = 5246 mscb->apfMsLwappLradInet.ipv4.addr = 168427904 mscb->apfMsLwappLradPort = 41879
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.567: 3c:a9:f4:0b:91:70 Received EAPOL-Key from mobile 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.568: 3c:a9:f4:0b:91:70 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.568: 3c:a9:f4:0b:91:70 Received EAPOL-key in PTK_START state (message 2) from mobile 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.568: 3c:a9:f4:0b:91:70 Stopping retransmission timer for mobile 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.568: 3c:a9:f4:0b:91:70 EAPOL Header:
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.568: 00000000: 02 03 5f 00                                       .._.
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.568: 3c:a9:f4:0b:91:70 Sending EAPOL-Key Message to mobile 3c:a9:f4:0b:91:70
                                                                                                                    state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.568: 3c:a9:f4:0b:91:70 Sending EAPOL-Key Message to mobile 3c:a9:f4:0b:91:70
                                                                                                                    state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.568: 3c:a9:f4:0b:91:70 Reusing allocated memory for  EAP Pkt for retransmission to mobile 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.568: 3c:a9:f4:0b:91:70 mscb->apfMsLwappLradNhMac = 00:0c:29:e4:e9:6a mscb->apfMsLradSlotId = 0 mscb->apfMsLradJumbo = 0 mscb->apfMsintIfNum = 1
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.568: 3c:a9:f4:0b:91:70  mscb->apfMsBssid = 00:26:cb:4c:89:d0 mscb->apfMsAddress = 3c:a9:f4:0b:91:70 mscb->apfMsApVapId = 2
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.568: 3c:a9:f4:0b:91:70  dot1xcb->snapOrg = 00 00 00 dot1xcb->eapolWepBit = 0 mscb->apfMsLwappLradVlanId = 10 mscb->apfMsLwappMwarInet.ipv4.addr = 168430130
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.568: 3c:a9:f4:0b:91:70  mscb->apfMsLwappMwarPort = 5246 mscb->apfMsLwappLradInet.ipv4.addr = 168427904 mscb->apfMsLwappLradPort = 41879
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 Received EAPOL-Key from mobile 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 Stopping retransmission timer for mobile 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 Freeing EAP Retransmit Bufer for mobile 3c:a9:f4:0b:91:70
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 apfMs1xStateInc
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 10.10.1.130 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3)

*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 Central switch is FALSE
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 Sending the Central Auth Info
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 Central Auth Info Allocated PMKLen = 32

*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: EapolReplayCounter: 00 00 00 00 00 00 00 01
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: EapolReplayCounter: 00 00 00 00 00 00 00 01
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 PMK: pmkActiveIndex = 0
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 EapolReplayCounter: 00 00 00 00 00 00 00 01
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 msAssocTypeFlagsMsb = 0 msAssocTypeFlagsLsb = 2
                                                                                                           apfMsEntryType = 0 apfMsEapType = 0
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 Sending Local Switch flag = 1
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 10.10.1.130 L2AUTHCOMPLETE (4) DHCP Not required on AP 00:26:cb:4c:89:d0 vapId 2 apVapId 2for this client
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 Not Using WMM Compliance code qosCap 00
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 10.10.1.130 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 00:26:cb:4c:89:d0 vapId 2 apVapId 2 flex-acl-name:
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 10.10.1.130 L2AUTHCOMPLETE (4) Change state to WEBAUTH_REQD (8) last state L2AUTHCOMPLETE (4)

*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 10.10.1.130 WEBAUTH_REQD (8) pemAdvanceState2 6236, Adding TMP rule
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 10.10.1.130 WEBAUTH_REQD (8) Adding Fast Path rule
  type = Airespace AP Client - ACL passthru
  on AP 00:26:cb:4c:89:d0, slot 0, interface = 1, QOS = 0
  IPv4 ACL ID
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 10.10.1.130 WEBAUTH_REQD (8) Fast Path rule (contd...) 802.1P = 2, DSCP = 0, TokenID = 64206  Local Bridging Vlan = 10, Local Bridging intf id = 0
*Dot1x_NW_MsgTask_0: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 10.10.1.130 WEBAUTH_REQD (8) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255)
*spamApTask7: Feb 04 07:48:10.569: 3c:a9:f4:0b:91:70 spamEncodeCentralAuthInoMsPayload: msAssocTypeFlagsMsb = 0 msAssocTypeFlagsLsb = 2
   apfMsEntryType = 0 pmkLen = 32
*pemReceiveTask: Feb 04 07:48:10.570: 3c:a9:f4:0b:91:70 10.10.1.130 Added NPU entry of type 2, dtlFlags 0x0
*pemReceiveTask: Feb 04 07:48:10.570: 3c:a9:f4:0b:91:70 Pushing IPv6: fe80:0000:0000:0000:c915:4a8e:6d1a:e20d , and MAC: 3C:A9:F4:0B:91:70 , Binding to Data Plane. SUCCESS !!
*DHCP Socket Task: Feb 04 07:48:10.589: 3c:a9:f4:0b:91:70 DHCP received op BOOTREPLY (2) (len 308,vlan 10, port 1, encap 0xec03)
*DHCP Socket Task: Feb 04 07:48:10.589: 3c:a9:f4:0b:91:70 DHCP processing DHCP ACK (5)
*DHCP Socket Task: Feb 04 07:48:10.589: 3c:a9:f4:0b:91:70 DHCP   op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0
*DHCP Socket Task: Feb 04 07:48:10.589: 3c:a9:f4:0b:91:70 DHCP   xid: 0xcce207f6 (3437365238), secs: 0, flags: 0
*DHCP Socket Task: Feb 04 07:48:10.589: 3c:a9:f4:0b:91:70 DHCP   chaddr: 3c:a9:f4:0b:91:70
*DHCP Socket Task: Feb 04 07:48:10.589: 3c:a9:f4:0b:91:70 DHCP   ciaddr: 0.0.0.0,  yiaddr: 10.10.1.130
*DHCP Socket Task: Feb 04 07:48:10.589: 3c:a9:f4:0b:91:70 DHCP   siaddr: 0.0.0.0,  giaddr: 0.0.0.0
*DHCP Socket Task: Feb 04 07:48:10.589: 3c:a9:f4:0b:91:70 DHCP   server id: 10.10.1.20  rcvd server id: 10.10.1.20
*SNMPTask: Feb 04 07:48:16.594: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*SNMPTask: Feb 04 07:48:16.594: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*SNMPTask: Feb 04 07:48:16.595: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*SNMPTask: Feb 04 07:48:16.595: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*ewmwebWebauth1: Feb 04 07:48:31.129: 3c:a9:f4:0b:91:70 Username entry (local1) created for mobile, length = 6
*ewmwebWebauth1: Feb 04 07:48:31.130: 3c:a9:f4:0b:91:70 Username entry (local1) created in mscb for mobile, length = 6
*ewmwebWebauth1: Feb 04 07:48:31.130: 3c:a9:f4:0b:91:70 10.10.1.130 WEBAUTH_REQD (8) Change state to WEBAUTH_NOL3SEC (14) last state WEBAUTH_REQD (8)

*ewmwebWebauth1: Feb 04 07:48:31.130: 3c:a9:f4:0b:91:70 apfMsRunStateInc
*ewmwebWebauth1: Feb 04 07:48:31.130: 3c:a9:f4:0b:91:70 10.10.1.130 WEBAUTH_NOL3SEC (14) Change state to RUN (20) last state WEBAUTH_NOL3SEC (14)

*ewmwebWebauth1: Feb 04 07:48:31.130: 3c:a9:f4:0b:91:70 Session Timeout is 65535 - starting session timer for the mobile
*ewmwebWebauth1: Feb 04 07:48:31.130: 3c:a9:f4:0b:91:70 10.10.1.130 RUN (20) Reached PLUMBFASTPATH: from line 6571
*ewmwebWebauth1: Feb 04 07:48:31.131: 3c:a9:f4:0b:91:70 10.10.1.130 RUN (20) Replacing Fast Path rule
  type = Airespace AP Client
  on AP 00:26:cb:4c:89:d0, slot 0, interface = 1, QOS = 0
  IPv4 ACL ID = 255, IPv6 ACL ID =
*ewmwebWebauth1: Feb 04 07:48:31.131: 3c:a9:f4:0b:91:70 10.10.1.130 RUN (20) Fast Path rule (contd...) 802.1P = 2, DSCP = 0, TokenID = 64206  Local Bridging Vlan = 10, Local Bridging intf id = 0
*ewmwebWebauth1: Feb 04 07:48:31.131: 3c:a9:f4:0b:91:70 10.10.1.130 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255)
*pemReceiveTask: Feb 04 07:48:31.132: 3c:a9:f4:0b:91:70 10.10.1.130 Added NPU entry of type 1, dtlFlags 0x0

(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >
(Cisco Controller) >*pemReceiveTask: Feb 04 07:48:31.132: 3c:a9:f4:0b:91:70 Pushing IPv6: fe80:0000:0000:0000:c915:4a8e:6d1a:e20d , and MAC: 3C:A9:F4:0B:91:70 , Binding to Data Plane. SUCCESS !!
*emWeb: Feb 04 07:49:14.120: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*emWeb: Feb 04 07:49:14.120: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*emWeb: Feb 04 07:49:14.120: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*SNMPTask: Feb 04 07:51:19.646: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*SNMPTask: Feb 04 07:51:19.646: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*SNMPTask: Feb 04 07:51:19.662: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*SNMPTask: Feb 04 07:51:19.662: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*SNMPTask: Feb 04 07:51:19.663: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*SNMPTask: Feb 04 07:51:19.663: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*IPv6_Msg_Task: Feb 04 07:53:35.661: 3c:a9:f4:0b:91:70 Link Local address fe80::c915:4a8e:6d1a:e20d updated to mscb. Not Advancing pem state.Current state: mscb in apfMsMmInitial mobility state and client state APF_MS_STATE_A
*dot1xMsgTask: Feb 04 07:54:26.664: GTK Rotation Kicked in for AP: 00:26:cb:4c:89:d0 SlotId = 1 - (0x47440ef0)
*dot1xMsgTask: Feb 04 07:54:26.665: Generated a new group key for AP 00:26:cb:4c:89:d0(1) - vap 1
*dot1xMsgTask: Feb 04 07:54:26.665: Sending of M5 for 00:26:cb:4c:89:d0 is Skipped, rc = 1
*dot1xMsgTask: Feb 04 07:54:26.665: Generated a new group key for AP 00:26:cb:4c:89:d0(1) - vap 2
*dot1xMsgTask: Feb 04 07:54:26.665: Sending of M5 for 00:26:cb:4c:89:d0 is Skipped, rc = 1
*SNMPTask: Feb 04 07:56:19.689: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*SNMPTask: Feb 04 07:56:19.689: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*SNMPTask: Feb 04 08:01:19.730: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*SNMPTask: Feb 04 08:01:19.730: 3c:a9:f4:0b:91:70 Central Switch = FALSE
*dot1xMsgTask: Feb 04 08:01:23.904: GTK Rotation Kicked in for AP: 00:26:cb:4c:89:d0 SlotId = 0 - (0x47440ef0)
*dot1xMsgTask: Feb 04 08:01:23.904: Generated a new group key for AP 00:26:cb:4c:89:d0(0) - vap 1
*dot1xMsgTask: Feb 04 08:01:23.905: Sending of M5 for 00:26:cb:4c:89:d0 is Skipped, rc = 1
*dot1xMsgTask: Feb 04 08:01:23.905: Generated a new group key for AP 00:26:cb:4c:89:d0(0) - vap 2
*dot1xMsgTask: Feb 04 08:01:23.905: GTK rotation for 3c:a9:f4:0b:91:70
*dot1xMsgTask: Feb 04 08:01:23.905: 3c:a9:f4:0b:91:70 EAPOL Header:
*dot1xMsgTask: Feb 04 08:01:23.905: 00000000: 02 03 5f 00                                       .._.
*dot1xMsgTask: Feb 04 08:01:23.905: 3c:a9:f4:0b:91:70 Key exchange done, data packets from mobile 3c:a9:f4:0b:91:70 should be forwarded shortly
*dot1xMsgTask: Feb 04 08:01:23.905: 3c:a9:f4:0b:91:70 Key exchange done, data packets from mobile 3c:a9:f4:0b:91:70 should be forwarded shortly
*dot1xMsgTask: Feb 04 08:01:23.906: Confirmation Key:  (16)

*dot1xMsgTask: Feb 04 08:01:23.906:      [0000] fa a3 68 28 46 1f 49 18 a0 60 7a 92 c4 f5 64 3d

*dot1xMsgTask: Feb 04 08:01:23.906: 3c:a9:f4:0b:91:70 Sending EAPOL-Key Message to mobile 3c:a9:f4:0b:91:70
                                                                                                              state PTKINITDONE (message 5 - group), replay counter 00.00.00.00.00.00.00.02
*dot1xMsgTask: Feb 04 08:01:23.906: 3c:a9:f4:0b:91:70 Sending EAPOL-Key Message to mobile 3c:a9:f4:0b:91:70
                                                                                                              state PTKINITDONE (message 5 - group), replay counter 00.00.00.00.00.00.00.02
*dot1xMsgTask: Feb 04 08:01:23.906: 3c:a9:f4:0b:91:70 Allocating EAP Pkt for retransmission to mobile 3c:a9:f4:0b:91:70
*dot1xMsgTask: Feb 04 08:01:23.906: 3c:a9:f4:0b:91:70 mscb->apfMsLwappLradNhMac = 00:0c:29:e4:e9:6a mscb->apfMsLradSlotId = 0 mscb->apfMsLradJumbo = 0 mscb->apfMsintIfNum = 1
*dot1xMsgTask: Feb 04 08:01:23.906: 3c:a9:f4:0b:91:70  mscb->apfMsBssid = 00:26:cb:4c:89:d0 mscb->apfMsAddress = 3c:a9:f4:0b:91:70 mscb->apfMsApVapId = 2
*dot1xMsgTask: Feb 04 08:01:23.907: 3c:a9:f4:0b:91:70  dot1xcb->snapOrg = 00 00 00 dot1xcb->eapolWepBit = 1 mscb->apfMsLwappLradVlanId = 10 mscb->apfMsLwappMwarInet.ipv4.addr = 168430130
*dot1xMsgTask: Feb 04 08:01:23.907: 3c:a9:f4:0b:91:70  mscb->apfMsLwappMwarPort = 5246 mscb->apfMsLwappLradInet.ipv4.addr = 168427904 mscb->apfMsLwappLradPort = 41879
*dot1xMsgTask: Feb 04 08:01:23.907: 3c:a9:f4:0b:91:70 Updated broadcast key sent to mobile 3C:A9:F4:0B:91:70
*dot1xMsgTask: Feb 04 08:01:23.907: 3c:a9:f4:0b:91:70 Updated broadcast key sent to mobile 3C:A9:F4:0B:91:70
*dot1xMsgTask: Feb 04 08:01:23.907: Sending of M5 for 00:26:cb:4c:89:d0 is Skipped, rc = 1
*osapiBsnTimer: Feb 04 08:01:25.104: 3c:a9:f4:0b:91:70 802.1x 'timeoutEvt' Timer expired for station 3c:a9:f4:0b:91:70 and for message = M5
*dot1xMsgTask: Feb 04 08:01:25.104: 3c:a9:f4:0b:91:70 Retransmit 1 of EAPOL-Key M5 (length 131) for mobile 3c:a9:f4:0b:91:70
*dot1xMsgTask: Feb 04 08:01:25.104: 3c:a9:f4:0b:91:70 mscb->apfMsLwappLradNhMac = 00:0c:29:e4:e9:6a mscb->apfMsLradSlotId = 0 mscb->apfMsLradJumbo = 0 mscb->apfMsintIfNum = 1
*dot1xMsgTask: Feb 04 08:01:25.104: 3c:a9:f4:0b:91:70  mscb->apfMsBssid = 00:26:cb:4c:89:d0 mscb->apfMsAddress = 3c:a9:f4:0b:91:70 mscb->apfMsApVapId = 2
*dot1xMsgTask: Feb 04 08:01:25.104: 3c:a9:f4:0b:91:70  dot1xcb->snapOrg = 00 00 00 dot1xcb->eapolWepBit = 1 mscb->apfMsLwappLradVlanId = 10 mscb->apfMsLwappMwarInet.ipv4.addr = 168430130
*dot1xMsgTask: Feb 04 08:01:25.104: 3c:a9:f4:0b:91:70  mscb->apfMsLwappMwarPort = 5246 mscb->apfMsLwappLradInet.ipv4.addr = 168427904 mscb->apfMsLwappLradPort = 41879
*osapiBsnTimer: Feb 04 08:01:26.104: 3c:a9:f4:0b:91:70 802.1x 'timeoutEvt' Timer expired for station 3c:a9:f4:0b:91:70 and for message = M5
*dot1xMsgTask: Feb 04 08:01:26.104: 3c:a9:f4:0b:91:70 Retransmit 2 of EAPOL-Key M5 (length 131) for mobile 3c:a9:f4:0b:91:70
*dot1xMsgTask: Feb 04 08:01:26.104: 3c:a9:f4:0b:91:70 mscb->apfMsLwappLradNhMac = 00:0c:29:e4:e9:6a mscb->apfMsLradSlotId = 0 mscb->apfMsLradJumbo = 0 mscb->apfMsintIfNum = 1
*dot1xMsgTask: Feb 04 08:01:26.104: 3c:a9:f4:0b:91:70  mscb->apfMsBssid = 00:26:cb:4c:89:d0 mscb->apfMsAddress = 3c:a9:f4:0b:91:70 mscb->apfMsApVapId = 2
*dot1xMsgTask: Feb 04 08:01:26.104: 3c:a9:f4:0b:91:70  dot1xcb->snapOrg = 00 00 00 dot1xcb->eapolWepBit = 1 mscb->apfMsLwappLradVlanId = 10 mscb->apfMsLwappMwarInet.ipv4.addr = 168430130
*dot1xMsgTask: Feb 04 08:01:26.104: 3c:a9:f4:0b:91:70  mscb->apfMsLwappMwarPort = 5246 mscb->apfMsLwappLradInet.ipv4.addr = 168427904 mscb->apfMsLwappLradPort = 41879
*osapiBsnTimer: Feb 04 08:01:27.104: 3c:a9:f4:0b:91:70 802.1x 'timeoutEvt' Timer expired for station 3c:a9:f4:0b:91:70 and for message = M5
*dot1xMsgTask: Feb 04 08:01:27.104: 3c:a9:f4:0b:91:70 Retransmit failure for EAPOL-Key M5 to mobile 3c:a9:f4:0b:91:70, retransmit count 3, mscb deauth count 0
*dot1xMsgTask: Feb 04 08:01:27.104: 3c:a9:f4:0b:91:70 Resetting MSCB PMK Cache Entry 0 for station 3c:a9:f4:0b:91:70
*dot1xMsgTask: Feb 04 08:01:27.105: 3c:a9:f4:0b:91:70 Removing BSSID 00:26:cb:4c:89:d1 from PMKID cache of station 3c:a9:f4:0b:91:70
*dot1xMsgTask: Feb 04 08:01:27.105: 3c:a9:f4:0b:91:70 Setting active key cache index 0 ---> 8
*dot1xMsgTask: Feb 04 08:01:27.105: 3c:a9:f4:0b:91:70 Sent Deauthenticate to mobile on BSSID 00:26:cb:4c:89:d0 slot 0(caller 1x_ptsm.c:598)
*dot1xMsgTask: Feb 04 08:01:27.105: 3c:a9:f4:0b:91:70 Setting active key cache index 8 ---> 8
*dot1xMsgTask: Feb 04 08:01:27.105: 3c:a9:f4:0b:91:70 Deleting the PMK cache when de-authenticating the client.
*dot1xMsgTask: Feb 04 08:01:27.105: 3c:a9:f4:0b:91:70 Global PMK Cache deletion failed.
*dot1xMsgTask: Feb 04 08:01:27.106: 3c:a9:f4:0b:91:70 Scheduling deletion of Mobile Station:  (callerId: 57) in 10 seconds
*dot1xMsgTask: Feb 04 08:01:27.106: 3c:a9:f4:0b:91:70 Freeing EAP Retransmit Bufer for mobile 3c:a9:f4:0b:91:70
*osapiBsnTimer: Feb 04 08:01:37.105: 3c:a9:f4:0b:91:70 apfMsExpireCallback (apf_ms.c:626) Expiring Mobile!
*apfReceiveTask: Feb 04 08:01:37.105: 3c:a9:f4:0b:91:70 apfMsExpireMobileStation (apf_ms.c:6655) Changing state for mobile 3c:a9:f4:0b:91:70 on AP 00:26:cb:4c:89:d0 from Associated to Disassociated

*apfReceiveTask: Feb 04 08:01:37.105: 3c:a9:f4:0b:91:70 Scheduling deletion of Mobile Station:  (callerId: 45) in 10 seconds
*osapiBsnTimer: Feb 04 08:01:47.105: 3c:a9:f4:0b:91:70 apfMsExpireCallback (apf_ms.c:626) Expiring Mobile!
*apfReceiveTask: Feb 04 08:01:47.106: 3c:a9:f4:0b:91:70 Sent Deauthenticate to mobile on BSSID 00:26:cb:4c:89:d0 slot 0(caller apf_ms.c:6749)
*apfReceiveTask: Feb 04 08:01:47.106: 3c:a9:f4:0b:91:70 Setting active key cache index 8 ---> 8
*apfReceiveTask: Feb 04 08:01:47.106: 3c:a9:f4:0b:91:70 Deleting the PMK cache when de-authenticating the client.
*apfReceiveTask: Feb 04 08:01:47.106: 3c:a9:f4:0b:91:70 Global PMK Cache deletion failed.
*apfReceiveTask: Feb 04 08:01:47.106: 3c:a9:f4:0b:91:70 apfMsAssoStateDec
*apfReceiveTask: Feb 04 08:01:47.106: 3c:a9:f4:0b:91:70 apfMsExpireMobileStation (apf_ms.c:6787) Changing state for mobile 3c:a9:f4:0b:91:70 on AP 00:26:cb:4c:89:d0 from Disassociated to Idle

*apfReceiveTask: Feb 04 08:01:47.106: 3c:a9:f4:0b:91:70 Scheduling deletion of Mobile Station:  (callerId: 47) in 10 seconds
*osapiBsnTimer: Feb 04 08:01:57.106: 3c:a9:f4:0b:91:70 apfMsExpireCallback (apf_ms.c:626) Expiring Mobile!
*apfReceiveTask: Feb 04 08:01:57.106: 3c:a9:f4:0b:91:70 pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0.
*apfReceiveTask: Feb 04 08:01:57.106: 3c:a9:f4:0b:91:70 10.10.1.130 START (0) Deleted mobile LWAPP rule on AP [00:26:cb:4c:89:d0]
*apfReceiveTask: Feb 04 08:01:57.106: 3c:a9:f4:0b:91:70 Username entry deleted for mobile
*apfReceiveTask: Feb 04 08:01:57.106: 3c:a9:f4:0b:91:70 Deleting mobile on AP 00:26:cb:4c:89:d0(0)

If Layer-2 Auth (PSK) is set to "none" and only Layer-3 Web Auth is kept, then there are no issues. PC can wake up before 8 hours and not prompted for Web Auth again. As a test, I setup the WLAN with Layer-2 PSK auth only with Layer-3 auth set to none. The WLC removed the client entry after 25 minutes. Not an issue for PSK based auth only as PC on wake up seamlessly gets associated to WLAN.

Is User Idle Timeout setting not valid when WPA2-PSK is used as the auth method ?

Thanks,

Rick.

George Stefanick · ‎02-04-2015

This is a good post .. After reading through and looking at your logs I would say you are correct. I will say your process of layer 3 and layer 2 is not the norm. But it doesn't work.

Rather than having 2 security methods in play why not just do 802.1X accounts ..

"Satisfaction does not come from knowing the solution, it comes from knowing why." - Rosalind Franklin
___________________________________________________________

View solution in original post

Scott Fella · ‎02-04-2015

I agree... You shouldn't use layer 2 and layer 3 and expect that they will not have to login the portal. If the device doesn't resond to the layer 2, well the controller deletes the entry and thus idle timer isn't a factor. Idle timer changes is only meant when using layer 3 only and keeping the client information alive. Sleeping client like George mentioned is a better way than adjusting the idle timer but strictly for layer 3 only. Of course your WLC has to be on the code that this feature is available on.

-Scott

-Scott
*** Please rate helpful posts ***

View solution in original post

Sandeep Choudhary · ‎02-03-2015

HI Rick,

I never faced this issue but did you also change the arp timeout value ?

If not then set the ARP timeout(same value as User idle timeout) and test it again.

https://rscciew.wordpress.com/2014/05/07/timeout-setting-on-wireless-lan-controller/

Regards

Dont forget to rate helpful posts

rick505d3 · ‎02-03-2015

Thanks Sandeep, the ARP timeout (under Controller -> General -> ARP Timeout) was set to 28800 sec in the above tests.

Around "08:01:25.104" in the log messages above, there is a Retransmit happening which after several failed attempts (as the PC is sound asleep) seems to make the WLC purge the client record. If L2 PSK auth is set to none (Only L3 Web Auth there), than these messages don't appear in the log through out the sleep duration and client wake up is all good.

It seems L2-PSK setting is overriding the Idle Timeout behaviour by expecting certain response from the client and on failure just clears the entry.

Rick.

Sandeep Choudhary · ‎02-03-2015

HI Ric,

I got ur concern.

"

*dot1xMsgTask: Feb 04 08:01:27.104: 3c:a9:f4:0b:91:70 Retransmit failure for EAPOL-Key M5 to mobile 3c:a9:f4:0b:91:70, retransmit count 3, mscb deauth count 0

"

Last solution is to increase the broadcast key time interval. I think this option is not available in the GUI with the code

Command Line Interface:

config advanced eap bcast-key-interval seconds (120 to 86400)

Regards

Dont forget to rate helpful posts

rick505d3 · ‎02-04-2015

It is set to 3600 sec. The client purge on WLC is happening much before that.

(Cisco Controller) >show advanced eap

EAP-Identity-Request Timeout (seconds)........... 30
EAP-Identity-Request Max Retries................. 2
EAP Key-Index for Dynamic WEP.................... 0
EAP Max-Login Ignore Identity Response........... enable
EAP-Request Timeout (seconds).................... 30
EAP-Request Max Retries.......................... 2
EAPOL-Key Timeout (milliseconds)................. 1000
EAPOL-Key Max Retries............................ 2
EAP-Broadcast Key Interval....................... 3600

Guess it is a limitation of this code release ?

Regards,

Rick.

Sandeep Choudhary · ‎02-04-2015

cant say about the limitation of code. I will now you should raise a TAC case may be they can you.

Regards

George Stefanick · ‎02-04-2015

You're playing with Fire when you start messing with all these timers.

While not directly your problem but I would look at sleeping client ..

this is way you don't have to mess with the idle timeout .. Know that this inflates yiur client count, also keeps higher cpu because the WLC needs to keep count of more clients ..

"Satisfaction does not come from knowing the solution, it comes from knowing why." - Rosalind Franklin
___________________________________________________________

George Stefanick · ‎02-04-2015

This is a good post .. After reading through and looking at your logs I would say you are correct. I will say your process of layer 3 and layer 2 is not the norm. But it doesn't work.

Rather than having 2 security methods in play why not just do 802.1X accounts ..

"Satisfaction does not come from knowing the solution, it comes from knowing why." - Rosalind Franklin
___________________________________________________________

Scott Fella · ‎02-04-2015

I agree... You shouldn't use layer 2 and layer 3 and expect that they will not have to login the portal. If the device doesn't resond to the layer 2, well the controller deletes the entry and thus idle timer isn't a factor. Idle timer changes is only meant when using layer 3 only and keeping the client information alive. Sleeping client like George mentioned is a better way than adjusting the idle timer but strictly for layer 3 only. Of course your WLC has to be on the code that this feature is available on.

-Scott

-Scott
*** Please rate helpful posts ***

rick505d3 · ‎02-04-2015

Thanks Scott, The code version is 7.6.130.0 which supports Sleeping Client feature. However, as per the docu "http://www.cisco.com/c/en/us/td/docs/wireless/controller/7-6/configuration-guide/b_cg76/b_cg76_chapter_010111.html#reference_7008E6F7D7094BA7AD39491D7361622D"

The authentication of sleeping clients feature is not supported with Layer 2 security and web authentication enabled.

and as you mentioned as well

...Sleeping client like George mentioned is a better way than adjusting the idle timer but strictly for layer 3 only...

Sleeping Client wasn't an option in my case. That is why I was hoping that Idle Timeout may do the trick here. This is an actual case where a client with an existing wireless network just wanted to enable sleeping client feature so that their guests don't need to re-auth if their device sleeps or they go out (break) and come back after some time. Layer-3 Web Auth alone should be enough I think. Keeping L2-PSK is probably their security team's decision, as they also use the same SSID for BYOD devices and don't want nearby people/buildings to see that there is an Open Wifi available and on joining would see the Web Auth portal and company disclaimer.

George, I agree with Dot1X method. It can be used for the BYOD devices (separate SSID) while we can keep the Guest WLAN as L3-WebAuth only on controller (or do CWA through ISE if available).

Thanks for all your help.

Rick.

Scott Fella · ‎02-05-2015

Rick,

The use of layer 3 is 99% of the time strictly for guest wireless access. Internal secured wireless should with use PSK or 802.1x if you have a radius server. The issue with PSK is if the shared secret gets passed around and again the same with login to the portal page. This isn't really secure. If your a Microsoft shop, you should look at brining up Microsoft radius and have that joined to the domain. It's easy to control access using AD credential or even machine authentication if they are in the domain. That's just my 2 cents:)

-Scott

-Scott
*** Please rate helpful posts ***