Thank you! I changed some values in the section of the RF (the threshold for voice I have set at -50 dB), and paragraph roaming client I have that the minimum is -57. coverage has been increased, and even the handover seems to work better. Sometimes the following happens: The NEC phone is associated with an Access Point, I walk, I stand in front of another access point and takes time to turn blue, or not turn blue until I make a call. Another question about AP, model LAP1041N: How does the AP work? How does the AP broadcast?. Is It a circle and the AP is the center? Does the AP broadcast more front than back? Have any blind spot? I put logs. First log (Cisco Controller) >*pemReceiveTask: Jun 27 11:45:46.177: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 *apfMsConnTask_1: Jun 28 10:39:17.850: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP c8:f9:f9:5b:12:10 *apfMsConnTask_1: Jun 28 10:39:17.850: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_1: Jun 28 10:39:17.850: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_1: Jun 28 10:39:17.850: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_1: Jun 28 10:39:17.850: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_1: Jun 28 10:39:17.850: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_1: Jun 28 10:39:17.850: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_1: Jun 28 10:39:17.850: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_1: Jun 28 10:39:17.850: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_1: Jun 28 10:39:17.850: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_1: Jun 28 10:39:17.851: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_1: Jun 28 10:39:17.851: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_1: Jun 28 10:39:17.851: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_1: Jun 28 10:39:17.851: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [3c:ce:73:f8:e1:00] *pemReceiveTask: Jun 28 10:39:17.851: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *apfMsConnTask_1: Jun 28 10:39:17.851: 00:60:b9:0d:ec:1f Updated location for station old AP 3c:ce:73:f8:e1:00-0, new AP c8:f9:f9:5b:12:10-0 *apfMsConnTask_1: Jun 28 10:39:17.851: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_1: Jun 28 10:39:17.851: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_1: Jun 28 10:39:17.851: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_1: Jun 28 10:39:17.852: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_1: Jun 28 10:39:17.852: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_1: Jun 28 10:39:17.852: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_1: Jun 28 10:39:17.852: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_1: Jun 28 10:39:17.852: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP c8:f9:f9:5b:12:10 vapId 2 apVapId 2for this client *apfMsConnTask_1: Jun 28 10:39:17.852: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_1: Jun 28 10:39:17.852: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP c8:f9:f9:5b:12:10 vapId 2 apVapId 2 *apfMsConnTask_1: Jun 28 10:39:17.852: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP c8:f9:f9:5b:12:10 from Associated to Associated *apfMsConnTask_1: Jun 28 10:39:17.852: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_1: Jun 28 10:39:17.853: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID c8:f9:f9:5b:12:10 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_1: Jun 28 10:39:17.853: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP c8:f9:f9:5b:12:10 from Associated to Associated *dot1xMsgTask: Jun 28 10:39:17.854: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 10:39:17.854: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:39:17.854: 00:60:b9:0d:ec:1f Removing BSSID 3c:ce:73:f8:e1:01 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:39:17.854: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 10:39:17.854: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 10:39:17.855: 00:60:b9:0d:ec:1f Adding BSSID c8:f9:f9:5b:12:11 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:39:17.855: New PMKID: (16) *dot1xMsgTask: Jun 28 10:39:17.855: [0000] bb 36 2c 2a e6 49 d5 39 af 0e 23 7b 64 9b ae 5b *dot1xMsgTask: Jun 28 10:39:17.855: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:39:17.855: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 10:39:17.855: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:39:17.855: 00:60:b9:0d:ec:1f Found an cache entry for BSSID c8:f9:f9:5b:12:11 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:39:17.855: 00:60:b9:0d:ec:1f Found an cache entry for BSSID c8:f9:f9:5b:12:11 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:39:17.855: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 10:39:17.855: [0000] bb 36 2c 2a e6 49 d5 39 af 0e 23 7b 64 9b ae 5b *dot1xMsgTask: Jun 28 10:39:17.855: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 10:39:17.855: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.911: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.911: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.912: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.912: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.912: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.915: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.915: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.915: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.915: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.915: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP c8:f9:f9:5b:12:10 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.916: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.916: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP c8:f9:f9:5b:12:10 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.916: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.916: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.916: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 10:39:17.916: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP c8:f9:f9:5b:12:10, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.916: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.916: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 10:39:17.916: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *pemReceiveTask: Jun 28 10:39:17.916: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 *apfMsConnTask_2: Jun 28 10:39:29.027: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP c8:f9:f9:5a:80:80 *apfMsConnTask_2: Jun 28 10:39:29.027: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_2: Jun 28 10:39:29.027: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_2: Jun 28 10:39:29.027: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_2: Jun 28 10:39:29.027: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_2: Jun 28 10:39:29.027: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_2: Jun 28 10:39:29.027: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_2: Jun 28 10:39:29.027: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_2: Jun 28 10:39:29.027: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_2: Jun 28 10:39:29.027: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_2: Jun 28 10:39:29.027: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_2: Jun 28 10:39:29.027: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_2: Jun 28 10:39:29.027: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [c8:f9:f9:5b:12:10] *pemReceiveTask: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f Updated location for station old AP c8:f9:f9:5b:12:10-0, new AP c8:f9:f9:5a:80:80-0 *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP c8:f9:f9:5a:80:80 vapId 2 apVapId 2for this client *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP c8:f9:f9:5a:80:80 vapId 2 apVapId 2 *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP c8:f9:f9:5a:80:80 from Associated to Associated *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID c8:f9:f9:5a:80:80 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_2: Jun 28 10:39:29.028: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP c8:f9:f9:5a:80:80 from Associated to Associated *dot1xMsgTask: Jun 28 10:39:29.030: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 10:39:29.030: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:39:29.030: 00:60:b9:0d:ec:1f Removing BSSID c8:f9:f9:5b:12:11 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:39:29.030: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 10:39:29.030: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 10:39:29.030: 00:60:b9:0d:ec:1f Adding BSSID c8:f9:f9:5a:80:81 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:39:29.030: New PMKID: (16) *dot1xMsgTask: Jun 28 10:39:29.030: [0000] e4 40 26 0e d5 70 ea 0f 0d 45 09 72 4f bc 00 71 *dot1xMsgTask: Jun 28 10:39:29.030: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:39:29.030: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 10:39:29.030: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:39:29.030: 00:60:b9:0d:ec:1f Found an cache entry for BSSID c8:f9:f9:5a:80:81 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:39:29.030: 00:60:b9:0d:ec:1f Found an cache entry for BSSID c8:f9:f9:5a:80:81 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:39:29.030: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 10:39:29.030: [0000] e4 40 26 0e d5 70 ea 0f 0d 45 09 72 4f bc 00 71 *dot1xMsgTask: Jun 28 10:39:29.031: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 10:39:29.031: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.070: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.070: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.070: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.070: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.071: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.075: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.076: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.076: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.076: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.076: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP c8:f9:f9:5a:80:80 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.076: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.076: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP c8:f9:f9:5a:80:80 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.076: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.076: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.076: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 10:39:29.076: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP c8:f9:f9:5a:80:80, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.076: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.076: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 10:39:29.076: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *pemReceiveTask: Jun 28 10:39:29.076: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 *apfMsConnTask_4: Jun 28 10:41:06.675: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP 3c:ce:73:f7:62:10 *apfMsConnTask_4: Jun 28 10:41:06.675: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_4: Jun 28 10:41:06.675: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_4: Jun 28 10:41:06.675: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [c8:f9:f9:5a:80:80] *pemReceiveTask: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f Updated location for station old AP c8:f9:f9:5a:80:80-0, new AP 3c:ce:73:f7:62:10-0 *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP 3c:ce:73:f7:62:10 vapId 2 apVapId 2for this client *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 3c:ce:73:f7:62:10 vapId 2 apVapId 2 *apfMsConnTask_4: Jun 28 10:41:06.676: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f7:62:10 from Associated to Associated *apfMsConnTask_4: Jun 28 10:41:06.677: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_4: Jun 28 10:41:06.677: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID 3c:ce:73:f7:62:10 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_4: Jun 28 10:41:06.677: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f7:62:10 from Associated to Associated *dot1xMsgTask: Jun 28 10:41:06.678: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 10:41:06.678: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:41:06.679: 00:60:b9:0d:ec:1f Removing BSSID c8:f9:f9:5a:80:81 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:41:06.679: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 10:41:06.679: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 10:41:06.679: 00:60:b9:0d:ec:1f Adding BSSID 3c:ce:73:f7:62:11 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:41:06.679: New PMKID: (16) *dot1xMsgTask: Jun 28 10:41:06.679: [0000] 03 12 c0 c5 10 08 ab 14 77 76 f5 62 92 95 82 5a *dot1xMsgTask: Jun 28 10:41:06.679: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:41:06.679: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 10:41:06.679: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:41:06.679: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f7:62:11 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:41:06.679: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f7:62:11 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:41:06.679: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 10:41:06.679: [0000] 03 12 c0 c5 10 08 ab 14 77 76 f5 62 92 95 82 5a *dot1xMsgTask: Jun 28 10:41:06.679: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 10:41:06.679: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.737: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.737: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.738: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.738: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.738: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.741: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.741: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.742: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.742: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.742: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP 3c:ce:73:f7:62:10 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.742: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.742: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 3c:ce:73:f7:62:10 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.742: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.742: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.742: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 10:41:06.742: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP 3c:ce:73:f7:62:10, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.742: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.742: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 10:41:06.742: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *pemReceiveTask: Jun 28 10:41:06.742: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 *apfMsConnTask_5: Jun 28 10:41:44.174: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP c8:f9:f9:5b:0e:e0 *apfMsConnTask_5: Jun 28 10:41:44.174: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [3c:ce:73:f7:62:10] *pemReceiveTask: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f Updated location for station old AP 3c:ce:73:f7:62:10-0, new AP c8:f9:f9:5b:0e:e0-0 *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP c8:f9:f9:5b:0e:e0 vapId 2 apVapId 2for this client *apfMsConnTask_5: Jun 28 10:41:44.175: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_5: Jun 28 10:41:44.176: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP c8:f9:f9:5b:0e:e0 vapId 2 apVapId 2 *apfMsConnTask_5: Jun 28 10:41:44.176: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP c8:f9:f9:5b:0e:e0 from Associated to Associated *apfMsConnTask_5: Jun 28 10:41:44.176: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_5: Jun 28 10:41:44.176: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID c8:f9:f9:5b:0e:e0 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_5: Jun 28 10:41:44.176: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP c8:f9:f9:5b:0e:e0 from Associated to Associated *dot1xMsgTask: Jun 28 10:41:44.177: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 10:41:44.177: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:41:44.178: 00:60:b9:0d:ec:1f Removing BSSID 3c:ce:73:f7:62:11 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:41:44.178: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 10:41:44.178: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 10:41:44.178: 00:60:b9:0d:ec:1f Adding BSSID c8:f9:f9:5b:0e:e1 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:41:44.178: New PMKID: (16) *dot1xMsgTask: Jun 28 10:41:44.178: [0000] 09 1d 27 25 44 d4 32 7b 4a dc d8 46 6d 8a d4 92 *dot1xMsgTask: Jun 28 10:41:44.178: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:41:44.178: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 10:41:44.178: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:41:44.178: 00:60:b9:0d:ec:1f Found an cache entry for BSSID c8:f9:f9:5b:0e:e1 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:41:44.178: 00:60:b9:0d:ec:1f Found an cache entry for BSSID c8:f9:f9:5b:0e:e1 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 10:41:44.178: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 10:41:44.178: [0000] 09 1d 27 25 44 d4 32 7b 4a dc d8 46 6d 8a d4 92 *dot1xMsgTask: Jun 28 10:41:44.178: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 10:41:44.178: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *osapiBsnTimer: Jun 28 10:41:45.219: 00:60:b9:0d:ec:1f 802.1x 'timeoutEvt' Timer expired for station 00:60:b9:0d:ec:1f and for message = M2 *dot1xMsgTask: Jun 28 10:41:45.219: 00:60:b9:0d:ec:1f Retransmit 1 of EAPOL-Key M1 (length 121) for mobile 00:60:b9:0d:ec:1f *osapiBsnTimer: Jun 28 10:41:46.219: 00:60:b9:0d:ec:1f 802.1x 'timeoutEvt' Timer expired for station 00:60:b9:0d:ec:1f and for message = M2 *dot1xMsgTask: Jun 28 10:41:46.219: 00:60:b9:0d:ec:1f Retransmit 2 of EAPOL-Key M1 (length 121) for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.226: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.226: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.226: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.226: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.226: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.03 *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.230: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.230: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.230: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.230: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.230: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP c8:f9:f9:5b:0e:e0 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.230: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.230: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP c8:f9:f9:5b:0e:e0 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.230: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.230: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.230: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 10:41:46.230: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP c8:f9:f9:5b:0e:e0, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.230: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.230: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 10:41:46.230: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f (Cisco Controller) User: admin1 Password:********* (Cisco Controller) > (Cisco Controller) User: logout Password:* User:admin Password:********* User:admin1 Password:********* (Cisco Controller) > ------------------------------------------------------------------------------------------------------------------------------------------------------------------ Second log debug client 00:60:B9:0D:EC:1F (Cisco Controller) >debug client 00:60:B9:0D:EC:1F (Cisco Controller) >*apfMsConnTask_6: Jun 28 11:57:06.181: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP 3c:ce:73:f9:2e:c0 *apfMsConnTask_6: Jun 28 11:57:06.181: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_6: Jun 28 11:57:06.181: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_6: Jun 28 11:57:06.181: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_6: Jun 28 11:57:06.181: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [c8:f9:f9:5b:0f:70] *pemReceiveTask: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f Updated location for station old AP c8:f9:f9:5b:0f:70-0, new AP 3c:ce:73:f9:2e:c0-0 *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP 3c:ce:73:f9:2e:c0 vapId 2 apVapId 2for this client *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 3c:ce:73:f9:2e:c0 vapId 2 apVapId 2 *apfMsConnTask_6: Jun 28 11:57:06.182: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f9:2e:c0 from Associated to Associated *apfMsConnTask_6: Jun 28 11:57:06.183: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_6: Jun 28 11:57:06.183: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID 3c:ce:73:f9:2e:c0 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_6: Jun 28 11:57:06.183: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f9:2e:c0 from Associated to Associated *dot1xMsgTask: Jun 28 11:57:06.184: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 11:57:06.184: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:57:06.185: 00:60:b9:0d:ec:1f Removing BSSID c8:f9:f9:5b:0f:71 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:57:06.185: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 11:57:06.185: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 11:57:06.185: 00:60:b9:0d:ec:1f Adding BSSID 3c:ce:73:f9:2e:c1 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:57:06.185: New PMKID: (16) *dot1xMsgTask: Jun 28 11:57:06.185: [0000] 74 1f ee 29 2e 8d fc df 33 97 9a 33 d6 57 d8 be *dot1xMsgTask: Jun 28 11:57:06.185: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:57:06.185: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 11:57:06.185: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:57:06.185: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f9:2e:c1 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:57:06.185: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f9:2e:c1 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:57:06.185: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 11:57:06.185: [0000] 74 1f ee 29 2e 8d fc df 33 97 9a 33 d6 57 d8 be *dot1xMsgTask: Jun 28 11:57:06.185: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 11:57:06.185: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.236: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.236: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.236: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.237: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.237: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.241: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.241: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.241: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.241: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.241: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP 3c:ce:73:f9:2e:c0 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.241: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.241: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 3c:ce:73:f9:2e:c0 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.241: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.241: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.241: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 11:57:06.241: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP 3c:ce:73:f9:2e:c0, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.241: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.241: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 11:57:06.241: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *pemReceiveTask: Jun 28 11:57:06.242: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 *apfMsConnTask_6: Jun 28 11:58:05.342: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP 3c:ce:73:f9:06:50 *apfMsConnTask_6: Jun 28 11:58:05.342: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_6: Jun 28 11:58:05.342: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_6: Jun 28 11:58:05.342: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_6: Jun 28 11:58:05.342: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_6: Jun 28 11:58:05.342: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_6: Jun 28 11:58:05.342: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_6: Jun 28 11:58:05.342: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_6: Jun 28 11:58:05.342: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_6: Jun 28 11:58:05.342: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_6: Jun 28 11:58:05.342: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [3c:ce:73:f9:2e:c0] *pemReceiveTask: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f Updated location for station old AP 3c:ce:73:f9:2e:c0-0, new AP 3c:ce:73:f9:06:50-0 *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP 3c:ce:73:f9:06:50 vapId 2 apVapId 2for this client *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 3c:ce:73:f9:06:50 vapId 2 apVapId 2 *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f9:06:50 from Associated to Associated *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID 3c:ce:73:f9:06:50 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_6: Jun 28 11:58:05.343: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f9:06:50 from Associated to Associated *dot1xMsgTask: Jun 28 11:58:05.346: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 11:58:05.346: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:58:05.346: 00:60:b9:0d:ec:1f Removing BSSID 3c:ce:73:f9:2e:c1 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:58:05.346: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 11:58:05.346: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 11:58:05.346: 00:60:b9:0d:ec:1f Adding BSSID 3c:ce:73:f9:06:51 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:58:05.346: New PMKID: (16) *dot1xMsgTask: Jun 28 11:58:05.346: [0000] 2c de dd 37 b5 fb 3c 2d 0e a4 47 e2 fd 62 19 fe *dot1xMsgTask: Jun 28 11:58:05.346: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:58:05.346: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 11:58:05.346: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:58:05.346: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f9:06:51 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:58:05.346: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f9:06:51 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:58:05.346: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 11:58:05.346: [0000] 2c de dd 37 b5 fb 3c 2d 0e a4 47 e2 fd 62 19 fe *dot1xMsgTask: Jun 28 11:58:05.346: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 11:58:05.346: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.404: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.404: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.404: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.404: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.405: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.412: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.413: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.413: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.413: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.413: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP 3c:ce:73:f9:06:50 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.413: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.413: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 3c:ce:73:f9:06:50 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.413: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.413: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.413: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 11:58:05.413: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP 3c:ce:73:f9:06:50, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.413: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.413: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 11:58:05.413: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *pemReceiveTask: Jun 28 11:58:05.413: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 *apfMsConnTask_4: Jun 28 11:58:16.473: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP 3c:ce:73:f7:62:10 *apfMsConnTask_4: Jun 28 11:58:16.473: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_4: Jun 28 11:58:16.473: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_4: Jun 28 11:58:16.473: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_4: Jun 28 11:58:16.473: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_4: Jun 28 11:58:16.473: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_4: Jun 28 11:58:16.473: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_4: Jun 28 11:58:16.473: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [3c:ce:73:f9:06:50] *pemReceiveTask: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f Updated location for station old AP 3c:ce:73:f9:06:50-0, new AP 3c:ce:73:f7:62:10-0 *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP 3c:ce:73:f7:62:10 vapId 2 apVapId 2for this client *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 3c:ce:73:f7:62:10 vapId 2 apVapId 2 *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f7:62:10 from Associated to Associated *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_4: Jun 28 11:58:16.474: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID 3c:ce:73:f7:62:10 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_4: Jun 28 11:58:16.475: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f7:62:10 from Associated to Associated *dot1xMsgTask: Jun 28 11:58:16.476: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 11:58:16.476: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:58:16.476: 00:60:b9:0d:ec:1f Removing BSSID 3c:ce:73:f9:06:51 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:58:16.476: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 11:58:16.476: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 11:58:16.476: 00:60:b9:0d:ec:1f Adding BSSID 3c:ce:73:f7:62:11 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:58:16.476: New PMKID: (16) *dot1xMsgTask: Jun 28 11:58:16.476: [0000] 03 12 c0 c5 10 08 ab 14 77 76 f5 62 92 95 82 5a *dot1xMsgTask: Jun 28 11:58:16.476: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:58:16.476: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 11:58:16.477: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:58:16.477: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f7:62:11 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:58:16.477: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f7:62:11 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 11:58:16.477: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 11:58:16.477: [0000] 03 12 c0 c5 10 08 ab 14 77 76 f5 62 92 95 82 5a *dot1xMsgTask: Jun 28 11:58:16.477: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 11:58:16.477: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.532: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.532: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.532: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.532: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.532: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.537: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.537: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.537: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.537: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.537: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP 3c:ce:73:f7:62:10 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.537: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.537: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 3c:ce:73:f7:62:10 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.537: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.537: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.537: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 11:58:16.537: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP 3c:ce:73:f7:62:10, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.537: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.538: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 11:58:16.538: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f ---------------------------------------------------------------------------------------------------------------------------------------------- Third log: debug client 00:60:B9:0D:EC:!F 1F (Cisco Controller) >*pemReceiveTask: Jun 28 11:58:16.538: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 *apfMsConnTask_6: Jun 28 12:08:12.696: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP 3c:ce:73:f9:2e:c0 *apfMsConnTask_6: Jun 28 12:08:12.696: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_6: Jun 28 12:08:12.696: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_6: Jun 28 12:08:12.696: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_6: Jun 28 12:08:12.696: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_6: Jun 28 12:08:12.696: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_6: Jun 28 12:08:12.696: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_6: Jun 28 12:08:12.696: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_6: Jun 28 12:08:12.696: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_6: Jun 28 12:08:12.696: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_6: Jun 28 12:08:12.696: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_6: Jun 28 12:08:12.696: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_6: Jun 28 12:08:12.696: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [3c:ce:73:f8:e1:00] *pemReceiveTask: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f Updated location for station old AP 3c:ce:73:f8:e1:00-0, new AP 3c:ce:73:f9:2e:c0-0 *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP 3c:ce:73:f9:2e:c0 vapId 2 apVapId 2for this client *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 3c:ce:73:f9:2e:c0 vapId 2 apVapId 2 *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f9:2e:c0 from Associated to Associated *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID 3c:ce:73:f9:2e:c0 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_6: Jun 28 12:08:12.697: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f9:2e:c0 from Associated to Associated *dot1xMsgTask: Jun 28 12:08:12.699: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 12:08:12.700: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:08:12.700: 00:60:b9:0d:ec:1f Removing BSSID 3c:ce:73:f8:e1:01 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:08:12.700: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 12:08:12.700: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 12:08:12.700: 00:60:b9:0d:ec:1f Adding BSSID 3c:ce:73:f9:2e:c1 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:08:12.700: New PMKID: (16) *dot1xMsgTask: Jun 28 12:08:12.700: [0000] 74 1f ee 29 2e 8d fc df 33 97 9a 33 d6 57 d8 be *dot1xMsgTask: Jun 28 12:08:12.700: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:08:12.700: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 12:08:12.700: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:08:12.700: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f9:2e:c1 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:08:12.700: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f9:2e:c1 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:08:12.700: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 12:08:12.700: [0000] 74 1f ee 29 2e 8d fc df 33 97 9a 33 d6 57 d8 be *dot1xMsgTask: Jun 28 12:08:12.700: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 12:08:12.700: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.728: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.728: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.729: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.729: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.729: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.734: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.734: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.734: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.734: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.734: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP 3c:ce:73:f9:2e:c0 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.734: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.734: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 3c:ce:73:f9:2e:c0 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.734: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.734: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.734: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 12:08:12.734: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP 3c:ce:73:f9:2e:c0, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.734: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.734: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 12:08:12.734: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *pemReceiveTask: Jun 28 12:08:12.735: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP 3c:ce:73:f7:62:10 *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [3c:ce:73:f9:2e:c0] *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f Updated location for station old AP 3c:ce:73:f9:2e:c0-0, new AP 3c:ce:73:f7:62:10-0 *apfMsConnTask_4: Jun 28 12:08:39.132: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_4: Jun 28 12:08:39.133: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_4: Jun 28 12:08:39.133: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_4: Jun 28 12:08:39.133: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_4: Jun 28 12:08:39.133: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_4: Jun 28 12:08:39.133: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_4: Jun 28 12:08:39.133: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_4: Jun 28 12:08:39.133: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP 3c:ce:73:f7:62:10 vapId 2 apVapId 2for this client *apfMsConnTask_4: Jun 28 12:08:39.133: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_4: Jun 28 12:08:39.133: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 3c:ce:73:f7:62:10 vapId 2 apVapId 2 *apfMsConnTask_4: Jun 28 12:08:39.133: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f7:62:10 from Associated to Associated *apfMsConnTask_4: Jun 28 12:08:39.133: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_4: Jun 28 12:08:39.133: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID 3c:ce:73:f7:62:10 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_4: Jun 28 12:08:39.133: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f7:62:10 from Associated to Associated *pemReceiveTask: Jun 28 12:08:39.133: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *dot1xMsgTask: Jun 28 12:08:39.135: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 12:08:39.135: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:08:39.135: 00:60:b9:0d:ec:1f Removing BSSID 3c:ce:73:f9:2e:c1 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:08:39.135: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 12:08:39.135: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 12:08:39.135: 00:60:b9:0d:ec:1f Adding BSSID 3c:ce:73:f7:62:11 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:08:39.135: New PMKID: (16) *dot1xMsgTask: Jun 28 12:08:39.135: [0000] 03 12 c0 c5 10 08 ab 14 77 76 f5 62 92 95 82 5a *dot1xMsgTask: Jun 28 12:08:39.135: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:08:39.135: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 12:08:39.135: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:08:39.136: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f7:62:11 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:08:39.136: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f7:62:11 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:08:39.136: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 12:08:39.136: [0000] 03 12 c0 c5 10 08 ab 14 77 76 f5 62 92 95 82 5a *dot1xMsgTask: Jun 28 12:08:39.136: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 12:08:39.136: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.213: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.213: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.213: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.213: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.213: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.220: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.220: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.220: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.220: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.220: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP 3c:ce:73:f7:62:10 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.220: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.220: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 3c:ce:73:f7:62:10 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.220: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.220: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.220: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 12:08:39.220: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP 3c:ce:73:f7:62:10, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.220: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.220: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 12:08:39.220: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *pemReceiveTask: Jun 28 12:08:39.221: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP c8:f9:f9:2b:42:d0 *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [3c:ce:73:f7:62:10] *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f Updated location for station old AP 3c:ce:73:f7:62:10-0, new AP c8:f9:f9:2b:42:d0-0 *apfMsConnTask_1: Jun 28 12:10:07.011: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_1: Jun 28 12:10:07.012: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_1: Jun 28 12:10:07.012: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_1: Jun 28 12:10:07.012: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_1: Jun 28 12:10:07.012: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_1: Jun 28 12:10:07.012: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_1: Jun 28 12:10:07.012: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_1: Jun 28 12:10:07.012: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP c8:f9:f9:2b:42:d0 vapId 2 apVapId 2for this client *apfMsConnTask_1: Jun 28 12:10:07.012: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_1: Jun 28 12:10:07.012: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP c8:f9:f9:2b:42:d0 vapId 2 apVapId 2 *apfMsConnTask_1: Jun 28 12:10:07.012: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP c8:f9:f9:2b:42:d0 from Associated to Associated *pemReceiveTask: Jun 28 12:10:07.012: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *apfMsConnTask_1: Jun 28 12:10:07.012: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_1: Jun 28 12:10:07.012: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID c8:f9:f9:2b:42:d0 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_1: Jun 28 12:10:07.012: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP c8:f9:f9:2b:42:d0 from Associated to Associated *dot1xMsgTask: Jun 28 12:10:07.014: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 12:10:07.014: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:10:07.014: 00:60:b9:0d:ec:1f Removing BSSID 3c:ce:73:f7:62:11 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:10:07.014: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 12:10:07.014: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 12:10:07.014: 00:60:b9:0d:ec:1f Adding BSSID c8:f9:f9:2b:42:d1 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:10:07.014: New PMKID: (16) *dot1xMsgTask: Jun 28 12:10:07.014: [0000] bf 62 c5 bb 99 b4 f0 33 cf 37 03 18 3b 1c 80 6a *dot1xMsgTask: Jun 28 12:10:07.014: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:10:07.014: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 12:10:07.014: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:10:07.014: 00:60:b9:0d:ec:1f Found an cache entry for BSSID c8:f9:f9:2b:42:d1 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:10:07.014: 00:60:b9:0d:ec:1f Found an cache entry for BSSID c8:f9:f9:2b:42:d1 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:10:07.014: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 12:10:07.014: [0000] bf 62 c5 bb 99 b4 f0 33 cf 37 03 18 3b 1c 80 6a *dot1xMsgTask: Jun 28 12:10:07.014: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 12:10:07.014: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.076: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.076: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.076: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.076: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.076: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.081: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.081: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.081: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.081: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.081: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP c8:f9:f9:2b:42:d0 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.081: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.081: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP c8:f9:f9:2b:42:d0 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.081: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.082: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.082: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 12:10:07.082: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP c8:f9:f9:2b:42:d0, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.082: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.082: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 12:10:07.082: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *pemReceiveTask: Jun 28 12:10:07.082: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP c8:f9:f9:5b:20:f0 *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [c8:f9:f9:2b:42:d0] *pemReceiveTask: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f Updated location for station old AP c8:f9:f9:2b:42:d0-0, new AP c8:f9:f9:5b:20:f0-0 *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_3: Jun 28 12:10:32.555: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_3: Jun 28 12:10:32.556: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP c8:f9:f9:5b:20:f0 vapId 2 apVapId 2for this client *apfMsConnTask_3: Jun 28 12:10:32.556: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_3: Jun 28 12:10:32.556: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP c8:f9:f9:5b:20:f0 vapId 2 apVapId 2 *apfMsConnTask_3: Jun 28 12:10:32.556: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP c8:f9:f9:5b:20:f0 from Associated to Associated *apfMsConnTask_3: Jun 28 12:10:32.556: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_3: Jun 28 12:10:32.556: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID c8:f9:f9:5b:20:f0 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_3: Jun 28 12:10:32.556: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP c8:f9:f9:5b:20:f0 from Associated to Associated *dot1xMsgTask: Jun 28 12:10:32.557: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 12:10:32.558: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:10:32.558: 00:60:b9:0d:ec:1f Removing BSSID c8:f9:f9:2b:42:d1 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:10:32.558: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 12:10:32.558: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 12:10:32.558: 00:60:b9:0d:ec:1f Adding BSSID c8:f9:f9:5b:20:f1 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:10:32.558: New PMKID: (16) *dot1xMsgTask: Jun 28 12:10:32.558: [0000] 4d 80 29 c7 23 1c cb 26 9f 77 8d 66 63 bc 7b b9 *dot1xMsgTask: Jun 28 12:10:32.558: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:10:32.558: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 12:10:32.558: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:10:32.558: 00:60:b9:0d:ec:1f Found an cache entry for BSSID c8:f9:f9:5b:20:f1 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:10:32.558: 00:60:b9:0d:ec:1f Found an cache entry for BSSID c8:f9:f9:5b:20:f1 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:10:32.558: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 12:10:32.558: [0000] 4d 80 29 c7 23 1c cb 26 9f 77 8d 66 63 bc 7b b9 *dot1xMsgTask: Jun 28 12:10:32.558: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 12:10:32.558: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.604: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.604: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.604: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.604: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.604: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.610: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.610: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.610: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.610: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.610: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP c8:f9:f9:5b:20:f0 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.610: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.610: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP c8:f9:f9:5b:20:f0 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.610: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.611: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.611: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 12:10:32.611: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP c8:f9:f9:5b:20:f0, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.611: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.611: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 12:10:32.611: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *pemReceiveTask: Jun 28 12:10:32.611: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 *apfMsConnTask_6: Jun 28 12:11:48.799: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP 3c:ce:73:f9:06:50 *apfMsConnTask_6: Jun 28 12:11:48.799: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [c8:f9:f9:5b:20:f0] *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f Updated location for station old AP c8:f9:f9:5b:20:f0-0, new AP 3c:ce:73:f9:06:50-0 *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP 3c:ce:73:f9:06:50 vapId 2 apVapId 2for this client *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_6: Jun 28 12:11:48.800: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 3c:ce:73:f9:06:50 vapId 2 apVapId 2 *apfMsConnTask_6: Jun 28 12:11:48.801: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f9:06:50 from Associated to Associated *apfMsConnTask_6: Jun 28 12:11:48.801: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_6: Jun 28 12:11:48.801: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID 3c:ce:73:f9:06:50 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_6: Jun 28 12:11:48.801: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f9:06:50 from Associated to Associated *pemReceiveTask: Jun 28 12:11:48.801: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *dot1xMsgTask: Jun 28 12:11:48.803: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 12:11:48.803: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:11:48.803: 00:60:b9:0d:ec:1f Removing BSSID c8:f9:f9:5b:20:f1 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:11:48.803: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 12:11:48.803: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 12:11:48.803: 00:60:b9:0d:ec:1f Adding BSSID 3c:ce:73:f9:06:51 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:11:48.803: New PMKID: (16) *dot1xMsgTask: Jun 28 12:11:48.803: [0000] 2c de dd 37 b5 fb 3c 2d 0e a4 47 e2 fd 62 19 fe *dot1xMsgTask: Jun 28 12:11:48.803: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:11:48.803: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 12:11:48.803: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:11:48.803: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f9:06:51 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:11:48.803: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f9:06:51 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:11:48.803: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 12:11:48.803: [0000] 2c de dd 37 b5 fb 3c 2d 0e a4 47 e2 fd 62 19 fe *dot1xMsgTask: Jun 28 12:11:48.803: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 12:11:48.803: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.845: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.845: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.845: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.845: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.845: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.850: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.850: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.850: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.850: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.850: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP 3c:ce:73:f9:06:50 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.850: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.850: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 3c:ce:73:f9:06:50 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.850: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.850: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.850: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 12:11:48.850: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP 3c:ce:73:f9:06:50, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.850: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.850: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 12:11:48.850: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *pemReceiveTask: Jun 28 12:11:48.850: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 (Cisco Controller) User: (Cisco Controller) User: (Cisco Controller) User: (Cisco Controller) User: (Cisco Controller) User: (Cisco Controller) User: adn min1 Password:********* (Cisco Controller) >debug client show (Cisco Controller) show>exit (Cisco Controller) >debug client 3C 00:60:B9:0D:EC:1F (Cisco Controller) >*apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP 3c:ce:73:f9:2e:c0 *apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [3c:ce:73:f8:e1:00] *pemReceiveTask: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f Updated location for station old AP 3c:ce:73:f8:e1:00-0, new AP 3c:ce:73:f9:2e:c0-0 *apfMsConnTask_6: Jun 28 12:17:10.281: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_6: Jun 28 12:17:10.282: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_6: Jun 28 12:17:10.282: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_6: Jun 28 12:17:10.282: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_6: Jun 28 12:17:10.282: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_6: Jun 28 12:17:10.282: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_6: Jun 28 12:17:10.282: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_6: Jun 28 12:17:10.282: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP 3c:ce:73:f9:2e:c0 vapId 2 apVapId 2for this client *apfMsConnTask_6: Jun 28 12:17:10.282: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_6: Jun 28 12:17:10.282: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 3c:ce:73:f9:2e:c0 vapId 2 apVapId 2 *apfMsConnTask_6: Jun 28 12:17:10.282: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f9:2e:c0 from Associated to Associated *apfMsConnTask_6: Jun 28 12:17:10.282: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_6: Jun 28 12:17:10.282: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID 3c:ce:73:f9:2e:c0 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_6: Jun 28 12:17:10.282: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f9:2e:c0 from Associated to Associated *dot1xMsgTask: Jun 28 12:17:10.286: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 12:17:10.286: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:17:10.286: 00:60:b9:0d:ec:1f Removing BSSID 3c:ce:73:f8:e1:01 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:17:10.286: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 12:17:10.286: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 12:17:10.286: 00:60:b9:0d:ec:1f Adding BSSID 3c:ce:73:f9:2e:c1 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:17:10.286: New PMKID: (16) *dot1xMsgTask: Jun 28 12:17:10.286: [0000] 74 1f ee 29 2e 8d fc df 33 97 9a 33 d6 57 d8 be *dot1xMsgTask: Jun 28 12:17:10.286: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:17:10.286: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 12:17:10.286: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:17:10.286: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f9:2e:c1 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:17:10.286: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f9:2e:c1 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:17:10.286: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 12:17:10.286: [0000] 74 1f ee 29 2e 8d fc df 33 97 9a 33 d6 57 d8 be *dot1xMsgTask: Jun 28 12:17:10.286: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 12:17:10.286: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.336: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.336: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.336: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.336: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.336: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.341: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.341: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.341: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.341: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.341: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP 3c:ce:73:f9:2e:c0 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.341: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.341: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 3c:ce:73:f9:2e:c0 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.341: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.341: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.341: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 12:17:10.341: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP 3c:ce:73:f9:2e:c0, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.341: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.341: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 12:17:10.341: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *pemReceiveTask: Jun 28 12:17:10.342: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 *apfMsConnTask_4: Jun 28 12:17:47.887: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP c8:f9:f9:5b:0f:70 *apfMsConnTask_4: Jun 28 12:17:47.887: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_4: Jun 28 12:17:47.887: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_4: Jun 28 12:17:47.887: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_4: Jun 28 12:17:47.887: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_4: Jun 28 12:17:47.887: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_4: Jun 28 12:17:47.887: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_4: Jun 28 12:17:47.887: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [3c:ce:73:f9:2e:c0] *pemReceiveTask: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f Updated location for station old AP 3c:ce:73:f9:2e:c0-0, new AP c8:f9:f9:5b:0f:70-0 *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP c8:f9:f9:5b:0f:70 vapId 2 apVapId 2for this client *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP c8:f9:f9:5b:0f:70 vapId 2 apVapId 2 *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP c8:f9:f9:5b:0f:70 from Associated to Associated *apfMsConnTask_4: Jun 28 12:17:47.888: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_4: Jun 28 12:17:47.889: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID c8:f9:f9:5b:0f:70 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_4: Jun 28 12:17:47.889: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP c8:f9:f9:5b:0f:70 from Associated to Associated *dot1xMsgTask: Jun 28 12:17:47.890: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 12:17:47.890: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:17:47.890: 00:60:b9:0d:ec:1f Removing BSSID 3c:ce:73:f9:2e:c1 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:17:47.890: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 12:17:47.890: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 12:17:47.890: 00:60:b9:0d:ec:1f Adding BSSID c8:f9:f9:5b:0f:71 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:17:47.890: New PMKID: (16) *dot1xMsgTask: Jun 28 12:17:47.890: [0000] 4a ed 4a f8 37 9c f3 ab ac 44 4a 01 f9 7c 4e 46 *dot1xMsgTask: Jun 28 12:17:47.890: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:17:47.890: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 12:17:47.890: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:17:47.891: 00:60:b9:0d:ec:1f Found an cache entry for BSSID c8:f9:f9:5b:0f:71 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:17:47.891: 00:60:b9:0d:ec:1f Found an cache entry for BSSID c8:f9:f9:5b:0f:71 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:17:47.891: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 12:17:47.891: [0000] 4a ed 4a f8 37 9c f3 ab ac 44 4a 01 f9 7c 4e 46 *dot1xMsgTask: Jun 28 12:17:47.891: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 12:17:47.891: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.947: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.947: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.947: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.947: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.947: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.952: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.952: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.952: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.952: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.952: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP c8:f9:f9:5b:0f:70 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.952: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.952: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP c8:f9:f9:5b:0f:70 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.952: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.952: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.952: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 12:17:47.952: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP c8:f9:f9:5b:0f:70, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.952: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.952: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 12:17:47.953: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *pemReceiveTask: Jun 28 12:17:47.953: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 *apfMsConnTask_3: Jun 28 12:18:15.346: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP 3c:ce:73:f9:13:e0 *apfMsConnTask_3: Jun 28 12:18:15.346: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_3: Jun 28 12:18:15.346: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_3: Jun 28 12:18:15.346: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_3: Jun 28 12:18:15.346: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_3: Jun 28 12:18:15.346: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_3: Jun 28 12:18:15.346: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [c8:f9:f9:5b:0f:70] *pemReceiveTask: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f Updated location for station old AP c8:f9:f9:5b:0f:70-0, new AP 3c:ce:73:f9:13:e0-0 *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP 3c:ce:73:f9:13:e0 vapId 2 apVapId 2for this client *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 3c:ce:73:f9:13:e0 vapId 2 apVapId 2 *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f9:13:e0 from Associated to Associated *apfMsConnTask_3: Jun 28 12:18:15.347: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_3: Jun 28 12:18:15.348: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID 3c:ce:73:f9:13:e0 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_3: Jun 28 12:18:15.348: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f9:13:e0 from Associated to Associated *dot1xMsgTask: Jun 28 12:18:15.349: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 12:18:15.349: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:18:15.349: 00:60:b9:0d:ec:1f Removing BSSID c8:f9:f9:5b:0f:71 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:18:15.349: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 12:18:15.349: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 12:18:15.349: 00:60:b9:0d:ec:1f Adding BSSID 3c:ce:73:f9:13:e1 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:18:15.349: New PMKID: (16) *dot1xMsgTask: Jun 28 12:18:15.349: [0000] 8e d8 80 65 d2 75 1e 24 a7 a1 ab 8b 7e 72 e1 6a *dot1xMsgTask: Jun 28 12:18:15.350: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:18:15.350: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 12:18:15.350: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:18:15.350: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f9:13:e1 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:18:15.350: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f9:13:e1 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:18:15.350: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 12:18:15.350: [0000] 8e d8 80 65 d2 75 1e 24 a7 a1 ab 8b 7e 72 e1 6a *dot1xMsgTask: Jun 28 12:18:15.350: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 12:18:15.350: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.411: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.411: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.411: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.411: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.411: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.416: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.416: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.416: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.416: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.416: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP 3c:ce:73:f9:13:e0 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.416: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.417: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 3c:ce:73:f9:13:e0 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.417: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.417: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.417: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 12:18:15.417: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP 3c:ce:73:f9:13:e0, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.417: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.417: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 12:18:15.417: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *pemReceiveTask: Jun 28 12:18:15.417: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f Association received from mobile on AP c8:f9:f9:5b:0f:70 *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [3c:ce:73:f9:13:e0] *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f Updated location for station old AP 3c:ce:73:f9:13:e0-0, new AP c8:f9:f9:5b:0f:70-0 *apfMsConnTask_4: Jun 28 12:19:06.181: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_4: Jun 28 12:19:06.182: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_4: Jun 28 12:19:06.182: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_4: Jun 28 12:19:06.182: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_4: Jun 28 12:19:06.182: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_4: Jun 28 12:19:06.182: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_4: Jun 28 12:19:06.182: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_4: Jun 28 12:19:06.182: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP c8:f9:f9:5b:0f:70 vapId 2 apVapId 2for this client *apfMsConnTask_4: Jun 28 12:19:06.182: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_4: Jun 28 12:19:06.182: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP c8:f9:f9:5b:0f:70 vapId 2 apVapId 2 *apfMsConnTask_4: Jun 28 12:19:06.182: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP c8:f9:f9:5b:0f:70 from Associated to Associated *apfMsConnTask_4: Jun 28 12:19:06.182: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_4: Jun 28 12:19:06.182: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID c8:f9:f9:5b:0f:70 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_4: Jun 28 12:19:06.182: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP c8:f9:f9:5b:0f:70 from Associated to Associated *pemReceiveTask: Jun 28 12:19:06.184: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *dot1xMsgTask: Jun 28 12:19:06.186: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 12:19:06.186: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:19:06.186: 00:60:b9:0d:ec:1f Removing BSSID 3c:ce:73:f9:13:e1 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:19:06.186: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 12:19:06.186: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 12:19:06.186: 00:60:b9:0d:ec:1f Adding BSSID c8:f9:f9:5b:0f:71 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:19:06.186: New PMKID: (16) *dot1xMsgTask: Jun 28 12:19:06.186: [0000] 4a ed 4a f8 37 9c f3 ab ac 44 4a 01 f9 7c 4e 46 *dot1xMsgTask: Jun 28 12:19:06.186: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:19:06.186: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 12:19:06.186: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:19:06.186: 00:60:b9:0d:ec:1f Found an cache entry for BSSID c8:f9:f9:5b:0f:71 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:19:06.186: 00:60:b9:0d:ec:1f Found an cache entry for BSSID c8:f9:f9:5b:0f:71 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:19:06.186: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 12:19:06.186: [0000] 4a ed 4a f8 37 9c f3 ab ac 44 4a 01 f9 7c 4e 46 *dot1xMsgTask: Jun 28 12:19:06.186: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 12:19:06.186: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.205: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.205: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.205: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.205: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.205: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.209: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.209: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.209: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.209: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.209: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP c8:f9:f9:5b:0f:70 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.209: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.209: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP c8:f9:f9:5b:0f:70 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.209: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.209: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.209: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 12:19:06.209: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP c8:f9:f9:5b:0f:70, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.210: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.210: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 12:19:06.210: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *pemReceiveTask: Jun 28 12:19:06.210: 00:60:b9:0d:ec:1f 10.160.91.51 Added NPU entry of type 1, dtlFlags 0x0 *apfMsConnTask_0: Jun 28 12:19:38.015: 00:60:b9:0d:ec:1f Reassociation received from mobile on AP 3c:ce:73:f8:e1:00 *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1697) *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1864) *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f Applying site-specific Local Bridging override for station 00:60:b9:0d:ec:1f - vapId 2, site 'default-group', interface 'pvoz' *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f Applying Local Bridging Interface Policy for station 00:60:b9:0d:ec:1f - vlan 106, interface id 12, interface 'pvoz' *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f STA - rates (8): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f STA - rates (10): 139 22 24 36 48 72 96 108 12 18 0 0 0 0 0 0 *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f Processing RSN IE type 48, length 20 for mobile 00:60:b9:0d:ec:1f *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Deleted mobile LWAPP rule on AP [c8:f9:f9:5b:0f:70] *pemReceiveTask: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f 10.160.91.51 Removed NPU entry. *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f Updated location for station old AP c8:f9:f9:5b:0f:70-0, new AP 3c:ce:73:f8:e1:00-0 *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f apfMsRunStateDec *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f apfMs1xStateDec *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Change state to START (0) last state RUN (20) *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f pemApfAddMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Initializing policy *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f 10.160.91.51 START (0) Change state to AUTHCHECK (2) last state RUN (20) *apfMsConnTask_0: Jun 28 12:19:38.016: 00:60:b9:0d:ec:1f 10.160.91.51 AUTHCHECK (2) Change state to 8021X_REQD (3) last state RUN (20) *apfMsConnTask_0: Jun 28 12:19:38.017: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) DHCP required on AP 3c:ce:73:f8:e1:00 vapId 2 apVapId 2for this client *apfMsConnTask_0: Jun 28 12:19:38.017: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *apfMsConnTask_0: Jun 28 12:19:38.017: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 3c:ce:73:f8:e1:00 vapId 2 apVapId 2 *apfMsConnTask_0: Jun 28 12:19:38.017: 00:60:b9:0d:ec:1f apfPemAddUser2 (apf_policy.c:268) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f8:e1:00 from Associated to Associated *apfMsConnTask_0: Jun 28 12:19:38.017: 00:60:b9:0d:ec:1f Scheduling deletion of Mobile Station: (callerId: 49) in 1800 seconds *apfMsConnTask_0: Jun 28 12:19:38.017: 00:60:b9:0d:ec:1f Sending Assoc Response to station on BSSID 3c:ce:73:f8:e1:00 (status 0) ApVapId 2 Slot 0 *apfMsConnTask_0: Jun 28 12:19:38.017: 00:60:b9:0d:ec:1f apfProcessAssocReq (apf_80211.c:6290) Changing state for mobile 00:60:b9:0d:ec:1f on AP 3c:ce:73:f8:e1:00 from Associated to Associated *dot1xMsgTask: Jun 28 12:19:38.019: 00:60:b9:0d:ec:1f Creating a PKC PMKID Cache entry for station 00:60:b9:0d:ec:1f (RSN 2) *dot1xMsgTask: Jun 28 12:19:38.019: 00:60:b9:0d:ec:1f Resetting MSCB PMK Cache Entry 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:19:38.019: 00:60:b9:0d:ec:1f Removing BSSID c8:f9:f9:5b:0f:71 from PMKID cache of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:19:38.019: 00:60:b9:0d:ec:1f Setting active key cache index 0 ---> 8 *dot1xMsgTask: Jun 28 12:19:38.019: 00:60:b9:0d:ec:1f Setting active key cache index 8 ---> 0 *dot1xMsgTask: Jun 28 12:19:38.019: 00:60:b9:0d:ec:1f Adding BSSID 3c:ce:73:f8:e1:01 to PMKID cache at index 0 for station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:19:38.019: New PMKID: (16) *dot1xMsgTask: Jun 28 12:19:38.019: [0000] 45 62 00 8d ff f9 49 d4 7c bd 6e cd c2 16 8f de *dot1xMsgTask: Jun 28 12:19:38.019: 00:60:b9:0d:ec:1f Initiating RSN PSK to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:19:38.019: 00:60:b9:0d:ec:1f dot1x - moving mobile 00:60:b9:0d:ec:1f into Force Auth state *dot1xMsgTask: Jun 28 12:19:38.019: 00:60:b9:0d:ec:1f Skipping EAP-Success to mobile 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:19:38.019: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f8:e1:01 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:19:38.019: 00:60:b9:0d:ec:1f Found an cache entry for BSSID 3c:ce:73:f8:e1:01 in PMKID cache at index 0 of station 00:60:b9:0d:ec:1f *dot1xMsgTask: Jun 28 12:19:38.019: Including PMKID in M1 (16) *dot1xMsgTask: Jun 28 12:19:38.019: [0000] 45 62 00 8d ff f9 49 d4 7c bd 6e cd c2 16 8f de *dot1xMsgTask: Jun 28 12:19:38.019: 00:60:b9:0d:ec:1f Starting key exchange to mobile 00:60:b9:0d:ec:1f, data packets will be dropped *dot1xMsgTask: Jun 28 12:19:38.019: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.056: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.056: 00:60:b9:0d:ec:1f Received EAPOL-key in PTK_START state (message 2) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.056: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.056: 00:60:b9:0d:ec:1f Sending the random GTK in M3 for WPA2 client 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.056: 00:60:b9:0d:ec:1f Sending EAPOL-Key Message to mobile 00:60:b9:0d:ec:1f state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.062: 00:60:b9:0d:ec:1f Received EAPOL-Key from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.062: 00:60:b9:0d:ec:1f Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:60:b9:0d:ec:1f *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.062: 00:60:b9:0d:ec:1f apfMs1xStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.062: 00:60:b9:0d:ec:1f 10.160.91.51 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.062: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) DHCP required on AP 3c:ce:73:f8:e1:00 vapId 2 apVapId 2for this client *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.062: 00:60:b9:0d:ec:1f Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.062: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 3c:ce:73:f8:e1:00 vapId 2 apVapId 2 *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.062: 00:60:b9:0d:ec:1f apfMsRunStateInc *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.062: 00:60:b9:0d:ec:1f 10.160.91.51 L2AUTHCOMPLETE (4) Change state to RUN (20) last state RUN (20) *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.062: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Reached PLUMBFASTPATH: from line 5362 *Dot1x_: Jun 28 12:19:38.062: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Adding Fast Path rule type = Airespace AP Client on AP 3c:ce:73:f8:e1:00, slot 0, interface = 13, QOS = 2 IPv4 ACL ID = 255, IPv6 ACL ID = *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.062: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006 Local Bridging Vlan = 106, Local Bridging intf id = 12 *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.062: 00:60:b9:0d:ec:1f 10.160.91.51 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255) *Dot1x_NW_MsgTask_7: Jun 28 12:19:38.062: 00:60:b9:0d:ec:1f Stopping retransmission timer for mobile 00:60:b9:0d:ec:1f j ----------------------------------------------------------------------------------------------------
... View more