=~=~=~=~=~=~=~=~=~=~=~= PuTTY log 2014.10.15 16:18:31 =~=~=~=~=~=~=~=~=~=~=~= *DHCP Socket Task: Oct 15 15:47:26.074: 3c:a9:f4:01:21:84 DHCP server id: 1.1.1.1 rcvd server id: 192.168.120.1 *apfReceiveTask: Oct 15 15:48:07.596: 3c:a9:f4:01:21:84 apfSendDisAssocMsgDebug (apf_80211.c:3158) Changing state for mobile 3c:a9:f4:01:21:84 on AP ec:c8:82:a4:5b:c0 from Associated to Disassociated *apfReceiveTask: Oct 15 15:48:07.596: 3c:a9:f4:01:21:84 Sent Disassociate to mobile on AP ec:c8:82:a4:5b:c0-1 (reason 1, caller apf_ms.c:6945) *apfReceiveTask: Oct 15 15:48:07.596: 3c:a9:f4:01:21:84 Sent Deauthenticate to mobile on BSSID ec:c8:82:a4:5b:c0 slot 1(caller apf_ms.c:7065) *apfReceiveTask: Oct 15 15:48:07.596: 3c:a9:f4:01:21:84 Resetting MSCB PMK Cache Entry 0 for station 3c:a9:f4:01:21:84 *apfReceiveTask: Oct 15 15:48:07.596: 3c:a9:f4:01:21:84 Removing BSSID ec:c8:82:a4:5b:cb from PMKID cache of station 3c:a9:f4:01:21:84 *apfReceiveTask: Oct 15 15:48:07.596: 3c:a9:f4:01:21:84 Setting active key cache index 0 ---> 8 *apfReceiveTask: Oct 15 15:48:07.597: 3c:a9:f4:01:21:84 Deleting the PMK cache when de-authenticating the client. *apfReceiveTask: Oct 15 15:48:07.597: 3c:a9:f4:01:21:84 Global PMK Cache deletion failed. *apfReceiveTask: Oct 15 15:48:07.597: 3c:a9:f4:01:21:84 apfMsAssoStateDec *apfReceiveTask: Oct 15 15:48:07.597: 3c:a9:f4:01:21:84 apfMsWepPskStateDec *apfReceiveTask: Oct 15 15:48:07.597: 3c:a9:f4:01:21:84 apfMsExpireMobileStation (apf_ms.c:7103) Changing state for mobile 3c:a9:f4:01:21:84 on AP ec:c8:82:a4:5b:c0 from Disassociated to Idle *apfReceiveTask: Oct 15 15:48:07.597: 3c:a9:f4:01:21:84 pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfReceiveTask: Oct 15 15:48:07.597: 3c:a9:f4:01:21:84 192.168.120.21 START (0) Deleted mobile LWAPP rule on AP [ec:c8:82:a4:5b:c0] *apfReceiveTask: Oct 15 15:48:07.597: 3c:a9:f4:01:21:84 Deleting mobile on AP ec:c8:82:a4:5b:c0(1) *apfReceiveTask: Oct 15 15:48:07.597: e8:2a:ea:77:e1:8d apfSendDisAssocMsgDebug (apf_80211.c:3158) Changing state for mobile e8:2a:ea:77:e1:8d on AP ec:c8:82:a4:5b:c0 from Associated to Disassociated *apfReceiveTask: Oct 15 15:48:07.597: e8:2a:ea:77:e1:8d Sent Disassociate to mobile on AP ec:c8:82:a4:5b:c0-0 (reason 1, caller apf_ms.c:6945) *apfReceiveTask: Oct 15 15:48:07.597: e8:2a:ea:77:e1:8d Sent Deauthenticate to mobile on BSSID ec:c8:82:a4:5b:c0 slot 0(caller apf_ms.c:7065) *apfReceiveTask: Oct 15 15:48:07.597: e8:2a:ea:77:e1:8d Resetting MSCB PMK Cache Entry 0 for station e8:2a:ea:77:e1:8d *apfReceiveTask: Oct 15 15:48:07.597: e8:2a:ea:77:e1:8d Removing BSSID ec:c8:82:a4:5b:c4 from PMKID cache of station e8:2a:ea:77:e1:8d *apfReceiveTask: Oct 15 15:48:07.598: e8:2a:ea:77:e1:8d Setting active key cache index 0 ---> 8 *apfReceiveTask: Oct 15 15:48:07.598: e8:2a:ea:77:e1:8d Deleting the PMK cache when de-authenticating the client. *apfReceiveTask: Oct 15 15:48:07.598: e8:2a:ea:77:e1:8d Global PMK Cache deletion failed. *apfReceiveTask: Oct 15 15:48:07.598: e8:2a:ea:77:e1:8d apfMsAssoStateDec *apfReceiveTask: Oct 15 15:48:07.598: e8:2a:ea:77:e1:8d apfMsWepPskStateDec *apfReceiveTask: Oct 15 15:48:07.598: e8:2a:ea:77:e1:8d apfMsExpireMobileStation (apf_ms.c:7103) Changing state for mobile e8:2a:ea:77:e1:8d on AP ec:c8:82:a4:5b:c0 from Disassociated to Idle *apfReceiveTask: Oct 15 15:48:07.598: e8:2a:ea:77:e1:8d pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfReceiveTask: Oct 15 15:48:07.598: e8:2a:ea:77:e1:8d 192.168.120.22 START (0) Deleted mobile LWAPP rule on AP [ec:c8:82:a4:5b:c0] *apfReceiveTask: Oct 15 15:48:07.598: e8:2a:ea:77:e1:8d Deleting mobile on AP ec:c8:82:a4:5b:c0(0) *pemReceiveTask: Oct 15 15:48:07.605: 3c:a9:f4:01:21:84 192.168.120.21 Removed NPU entry. *pemReceiveTask: Oct 15 15:48:07.606: e8:2a:ea:77:e1:8d 192.168.120.22 Removed NPU entry. *emWeb: Oct 15 15:48:13.311: RSNIE Data: (64) *emWeb: Oct 15 15:48:13.311: [0000] 30 14 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 *emWeb: Oct 15 15:48:13.311: [0016] 00 0f ac 02 29 00 96 00 28 00 00 00 00 00 00 00 *emWeb: Oct 15 15:48:13.311: [0032] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 *emWeb: Oct 15 15:48:13.311: [0048] 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 *emWeb: Oct 15 15:48:13.311: Created WARP Capabilities IE (length 12) for WLAN ptest *apfMsConnTask_1: Oct 15 15:48:13.747: 3c:a9:f4:01:21:84 Processing assoc-req station:3c:a9:f4:01:21:84 AP:ec:c8:82:a4:5b:c0-00 thread:150e3e20 *apfMsConnTask_1: Oct 15 15:48:13.747: 3c:a9:f4:01:21:84 Adding mobile on LWAPP AP ec:c8:82:a4:5b:c0(0) *apfMsConnTask_1: Oct 15 15:48:13.747: 3c:a9:f4:01:21:84 Association received from mobile on BSSID ec:c8:82:a4:5b:c4 AP VoiceAP_1042 *apfMsConnTask_1: Oct 15 15:48:13.747: 3c:a9:f4:01:21:84 Global 200 Clients are allowed to AP radio *apfMsConnTask_1: Oct 15 15:48:13.747: 3c:a9:f4:01:21:84 Max Client Trap Threshold: 0 cur: 0 *apfMsConnTask_1: Oct 15 15:48:13.747: 3c:a9:f4:01:21:84 Rf profile 600 Clients are allowed to AP wlan *apfMsConnTask_1: Oct 15 15:48:13.747: 3c:a9:f4:01:21:84 override for default ap group, marking intgrp NULL *apfMsConnTask_1: Oct 15 15:48:13.747: 3c:a9:f4:01:21:84 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 0 Quarantine Vlan 0 Access Vlan 0 *apfMsConnTask_1: Oct 15 15:48:13.747: 3c:a9:f4:01:21:84 Re-applying interface policy for client *apfMsConnTask_1: Oct 15 15:48:13.747: 3c:a9:f4:01:21:84 0.0.0.0 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2385) *apfMsConnTask_1: Oct 15 15:48:13.747: 3c:a9:f4:01:21:84 0.0.0.0 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2406) *apfMsConnTask_1: Oct 15 15:48:13.747: 3c:a9:f4:01:21:84 apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 In processSsidIE:5680 setting Central switched to TRUE *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 In processSsidIE:5683 apVapId = 5 and Split Acl Id = 65535 *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 Applying site-specific Local Bridging override for station 3c:a9:f4:01:21:84 - vapId 5, site 'default-group', interface 'test' *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 Applying Local Bridging Interface Policy for station 3c:a9:f4:01:21:84 - vlan 120, interface id 13, interface 'test' *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 STA - rates (8): 139 150 12 18 24 36 48 72 0 0 0 0 0 0 0 0 *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 STA - rates (10): 139 150 12 18 24 36 48 72 96 108 0 0 0 0 0 0 *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_1: Oct 15 15:48:13.748: RSNIE in Assoc. Req.: (22) *apfMsConnTask_1: Oct 15 15:48:13.748: [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f *apfMsConnTask_1: Oct 15 15:48:13.748: [0016] ac 02 3c 00 00 00 *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 Processing RSN IE type 48, length 22 for mobile 3c:a9:f4:01:21:84 *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 Received 802.11i PSK key management suite, enabling Authentication *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 RSN Capabilities: 60 *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 apfValidateDot11iCapabilities:1122 Received RSNIE with Capabilities with STA MFPC: 0, STA MFPR:0, & AP MFPC:0MFPR:0 *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 Marking Mobile as non-11w Capable *apfMsConnTask_1: Oct 15 15:48:13.748: 3c:a9:f4:01:21:84 apfValidateDot11wGroupMgmtCipher:1552, Received NULL 11w Group Mgmt Cipher Suite for STA, hence returning *apfMsConnTask_1: Oct 15 15:48:13.750: 3c:a9:f4:01:21:84 0.0.0.0 START (0) Initializing policy *apfMsConnTask_1: Oct 15 15:48:13.750: 3c:a9:f4:01:21:84 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state START (0) *apfMsConnTask_1: Oct 15 15:48:13.750: 3c:a9:f4:01:21:84 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2) *apfMsConnTask_1: Oct 15 15:48:13.750: 3c:a9:f4:01:21:84 Encryption policy is set to 0x80000001 *apfMsConnTask_1: Oct 15 15:48:13.750: 3c:a9:f4:01:21:84 Not Using WMM Compliance code qosCap 00 *apfMsConnTask_1: Oct 15 15:48:13.750: 3c:a9:f4:01:21:84 Sending 11w Flag 0 for Client 3C:A9:F4:01:21:84 *apfMsConnTask_1: Oct 15 15:48:13.750: 3c:a9:f4:01:21:84 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP ec:c8:82:a4:5b:c0 vapId 5 apVapId 5 flex-acl-name: *apfMsConnTask_1: Oct 15 15:48:13.750: 3c:a9:f4:01:21:84 apfMsAssoStateInc *apfMsConnTask_1: Oct 15 15:48:13.750: 3c:a9:f4:01:21:84 apfMsWepPskStateInc *apfMsConnTask_1: Oct 15 15:48:13.750: 3c:a9:f4:01:21:84 apfPemAddUser2 (apf_policy.c:352) Changing state for mobile 3c:a9:f4:01:21:84 on AP ec:c8:82:a4:5b:c0 from Idle to Associated *apfMsConnTask_1: Oct 15 15:48:13.750: 3c:a9:f4:01:21:84 apfPemAddUser2:session timeout forstation 3c:a9:f4:01:21:84 - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is 0 *apfMsConnTask_1: Oct 15 15:48:13.750: 3c:a9:f4:01:21:84 Stopping deletion of Mobile Station: (callerId: 48) *apfMsConnTask_1: Oct 15 15:48:13.750: 3c:a9:f4:01:21:84 Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0 *apfMsConnTask_1: Oct 15 15:48:13.750: 3c:a9:f4:01:21:84 Sending assoc-resp with status 0 station:3c:a9:f4:01:21:84 AP:ec:c8:82:a4:5b:c0-00 on apVapId 5 *apfMsConnTask_1: Oct 15 15:48:13.750: 3c:a9:f4:01:21:84 Sending Assoc Response to station on BSSID ec:c8:82:a4:5b:c4 (status 0) ApVapId 5 Slot 0 *apfMsConnTask_1: Oct 15 15:48:13.751: 3c:a9:f4:01:21:84 apfProcessAssocReq (apf_80211.c:9452) Changing state for mobile 3c:a9:f4:01:21:84 on AP ec:c8:82:a4:5b:c0 from Associated to Associated *spamApTask1: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 Sent 1x initiate message to multi thread task for mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 reauth_sm state transition 0 ---> 1 for mobile 3c:a9:f4:01:21:84 at 1x_reauth_sm.c:47 *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 Creating a PKC PMKID Cache entry for station 3c:a9:f4:01:21:84 (RSN 2) *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 Resetting MSCB PMK Cache Entry 0 for station 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 Setting active key cache index 8 ---> 8 *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 Setting active key cache index 8 ---> 0 *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 Adding BSSID ec:c8:82:a4:5b:c4 to PMKID cache at index 0 for station 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: New PMKID: (16) *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: [0000] f1 ac d9 ef 7e 6e 35 56 1f 93 cb 06 cb ec cf 6f *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 Initiating RSN PSK to mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 EAP-PARAM Debug - eap-params for Wlan-Id :5 is disabled - applying Global eap timers and retries *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 Disable re-auth, use PMK lifetime. *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 dot1x - moving mobile 3c:a9:f4:01:21:84 into Force Auth state *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 Skipping EAP-Success to mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 Found an cache entry for BSSID ec:c8:82:a4:5b:c4 in PMKID cache at index 0 of station 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 Found an cache entry for BSSID ec:c8:82:a4:5b:c4 in PMKID cache at index 0 of station 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: Including PMKID in M1 (16) *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: [0000] f1 ac d9 ef 7e 6e 35 56 1f 93 cb 06 cb ec cf 6f *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 Starting key exchange to mobile 3c:a9:f4:01:21:84, data packets will be dropped *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 Sending EAPOL-Key Message to mobile 3c:a9:f4:01:21:84 state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_4: Oct 15 15:48:13.755: 3c:a9:f4:01:21:84 Allocating EAP Pkt for retransmission to mobile 3c:a9:f4:01:21:84 *osapiBsnTimer: Oct 15 15:48:14.036: 3c:a9:f4:01:21:84 802.1x 'timeoutEvt' Timer expired for station 3c:a9:f4:01:21:84 and for message = M2 *dot1xMsgTask: Oct 15 15:48:14.037: 3c:a9:f4:01:21:84 Retransmit 1 of EAPOL-Key M1 (length 121) for mobile 3c:a9:f4:01:21:84 *osapiBsnTimer: Oct 15 15:48:14.436: 3c:a9:f4:01:21:84 802.1x 'timeoutEvt' Timer expired for station 3c:a9:f4:01:21:84 and for message = M2 *dot1xMsgTask: Oct 15 15:48:14.436: 3c:a9:f4:01:21:84 Retransmit 2 of EAPOL-Key M1 (length 121) for mobile 3c:a9:f4:01:21:84 *osapiBsnTimer: Oct 15 15:48:14.836: 3c:a9:f4:01:21:84 802.1x 'timeoutEvt' Timer expired for station 3c:a9:f4:01:21:84 and for message = M2 *dot1xMsgTask: Oct 15 15:48:14.837: 3c:a9:f4:01:21:84 Retransmit failure for EAPOL-Key M1 to mobile 3c:a9:f4:01:21:84, retransmit count 3, mscb deauth count 0 *dot1xMsgTask: Oct 15 15:48:14.837: 3c:a9:f4:01:21:84 Resetting MSCB PMK Cache Entry 0 for station 3c:a9:f4:01:21:84 *dot1xMsgTask: Oct 15 15:48:14.837: 3c:a9:f4:01:21:84 Removing BSSID ec:c8:82:a4:5b:c4 from PMKID cache of station 3c:a9:f4:01:21:84 *dot1xMsgTask: Oct 15 15:48:14.837: 3c:a9:f4:01:21:84 Setting active key cache index 0 ---> 8 *dot1xMsgTask: Oct 15 15:48:14.837: 3c:a9:f4:01:21:84 Sent Deauthenticate to mobile on BSSID ec:c8:82:a4:5b:c0 slot 0(caller 1x_ptsm.c:599) *dot1xMsgTask: Oct 15 15:48:14.837: 3c:a9:f4:01:21:84 Setting active key cache index 8 ---> 8 *dot1xMsgTask: Oct 15 15:48:14.837: 3c:a9:f4:01:21:84 Deleting the PMK cache when de-authenticating the client. *dot1xMsgTask: Oct 15 15:48:14.837: 3c:a9:f4:01:21:84 Global PMK Cache deletion failed. *dot1xMsgTask: Oct 15 15:48:14.837: 3c:a9:f4:01:21:84 Scheduling deletion of Mobile Station: (callerId: 57) in 10 seconds *dot1xMsgTask: Oct 15 15:48:14.837: 3c:a9:f4:01:21:84 Freeing EAP Retransmit Bufer for mobile 3c:a9:f4:01:21:84 *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d Processing assoc-req station:e8:2a:ea:77:e1:8d AP:ec:c8:82:a4:5b:c0-00 thread:150e3e20 *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d Adding mobile on LWAPP AP ec:c8:82:a4:5b:c0(0) *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d Association received from mobile on BSSID ec:c8:82:a4:5b:c4 AP VoiceAP_1042 *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d Global 200 Clients are allowed to AP radio *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d Max Client Trap Threshold: 0 cur: 1 *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d Rf profile 600 Clients are allowed to AP wlan *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d override for default ap group, marking intgrp NULL *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d Applying Interface policy on Mobile, role Unassociated. Ms NAC State 0 Quarantine Vlan 0 Access Vlan 0 *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d Re-applying interface policy for client *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d 0.0.0.0 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2385) *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d 0.0.0.0 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2406) *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d In processSsidIE:5680 setting Central switched to TRUE *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d In processSsidIE:5683 apVapId = 5 and Split Acl Id = 65535 *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d Applying site-specific Local Bridging override for station e8:2a:ea:77:e1:8d - vapId 5, site 'default-group', interface 'test' *apfMsConnTask_1: Oct 15 15:48:16.099: e8:2a:ea:77:e1:8d Applying Local Bridging Interface Policy for station e8:2a:ea:77:e1:8d - vlan 120, interface id 13, interface 'test' *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d STA - rates (8): 139 150 12 18 24 36 48 72 0 0 0 0 0 0 0 0 *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d STA - rates (10): 139 150 12 18 24 36 48 72 96 108 0 0 0 0 0 0 *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_1: Oct 15 15:48:16.100: RSNIE in Assoc. Req.: (22) *apfMsConnTask_1: Oct 15 15:48:16.100: [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f *apfMsConnTask_1: Oct 15 15:48:16.100: [0016] ac 02 3c 00 00 00 *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d Processing RSN IE type 48, length 22 for mobile e8:2a:ea:77:e1:8d *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d Received 802.11i PSK key management suite, enabling Authentication *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d RSN Capabilities: 60 *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d apfValidateDot11iCapabilities:1122 Received RSNIE with Capabilities with STA MFPC: 0, STA MFPR:0, & AP MFPC:0MFPR:0 *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d Marking Mobile as non-11w Capable *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d apfValidateDot11wGroupMgmtCipher:1552, Received NULL 11w Group Mgmt Cipher Suite for STA, hence returning *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d 0.0.0.0 START (0) Initializing policy *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state START (0) *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2) *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d Encryption policy is set to 0x80000001 *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d Not Using WMM Compliance code qosCap 2f *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d Sending 11w Flag 0 for Client E8:2A:EA:77:E1:8D *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP ec:c8:82:a4:5b:c0 vapId 5 apVapId 5 flex-acl-name: *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d apfMsAssoStateInc *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d apfMsWepPskStateInc *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d apfPemAddUser2 (apf_policy.c:352) Changing state for mobile e8:2a:ea:77:e1:8d on AP ec:c8:82:a4:5b:c0 from Idle to Associated *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d apfPemAddUser2:session timeout forstation e8:2a:ea:77:e1:8d - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is 0 *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d Stopping deletion of Mobile Station: (callerId: 48) *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0 *apfMsConnTask_1: Oct 15 15:48:16.100: e8:2a:ea:77:e1:8d Sending assoc-resp with status 0 station:e8:2a:ea:77:e1:8d AP:ec:c8:82:a4:5b:c0-00 on apVapId 5 *apfMsConnTask_1: Oct 15 15:48:16.101: e8:2a:ea:77:e1:8d Sending Assoc Response to station on BSSID ec:c8:82:a4:5b:c4 (status 0) ApVapId 5 Slot 0 *apfMsConnTask_1: Oct 15 15:48:16.101: e8:2a:ea:77:e1:8d apfProcessAssocReq (apf_80211.c:9452) Changing state for mobile e8:2a:ea:77:e1:8d on AP ec:c8:82:a4:5b:c0 from Associated to Associated *spamApTask1: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d Sent 1x initiate message to multi thread task for mobile e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d reauth_sm state transition 0 ---> 1 for mobile e8:2a:ea:77:e1:8d at 1x_reauth_sm.c:47 *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d Creating a PKC PMKID Cache entry for station e8:2a:ea:77:e1:8d (RSN 2) *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d Resetting MSCB PMK Cache Entry 0 for station e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d Setting active key cache index 8 ---> 8 *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d Setting active key cache index 8 ---> 0 *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d Adding BSSID ec:c8:82:a4:5b:c4 to PMKID cache at index 0 for station e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: New PMKID: (16) *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: [0000] d7 0a 04 d8 fa a5 e1 09 00 d4 5d d1 8b a5 ac f9 *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d Initiating RSN PSK to mobile e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d EAP-PARAM Debug - eap-params for Wlan-Id :5 is disabled - applying Global eap timers and retries *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d Disable re-auth, use PMK lifetime. *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d dot1x - moving mobile e8:2a:ea:77:e1:8d into Force Auth state *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d Skipping EAP-Success to mobile e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d Found an cache entry for BSSID ec:c8:82:a4:5b:c4 in PMKID cache at index 0 of station e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d Found an cache entry for BSSID ec:c8:82:a4:5b:c4 in PMKID cache at index 0 of station e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: Including PMKID in M1 (16) *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: [0000] d7 0a 04 d8 fa a5 e1 09 00 d4 5d d1 8b a5 ac f9 *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d Starting key exchange to mobile e8:2a:ea:77:e1:8d, data packets will be dropped *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.106: e8:2a:ea:77:e1:8d Sending EAPOL-Key Message to mobile e8:2a:ea:77:e1:8d state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.107: e8:2a:ea:77:e1:8d Allocating EAP Pkt for retransmission to mobile e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.112: e8:2a:ea:77:e1:8d Received EAPOL-Key from mobile e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.112: e8:2a:ea:77:e1:8d Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.112: e8:2a:ea:77:e1:8d Received EAPOL-key in PTK_START state (message 2) from mobile e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.112: e8:2a:ea:77:e1:8d Dumping RSNIE received in Association request: *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.112: 00000000: 30 16 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 0............... *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.112: 00000010: 00 0f ac 02 3c 00 00 00 ....<... *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.112: e8:2a:ea:77:e1:8d Dumping RSNIE received in EAPOL M2 : *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.112: 00000000: 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ................ *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.112: 00000010: ac 02 3c 00 00 00 ..<... *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.112: e8:2a:ea:77:e1:8d Stopping retransmission timer for mobile e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.112: e8:2a:ea:77:e1:8d Sending EAPOL-Key Message to mobile e8:2a:ea:77:e1:8d state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.112: e8:2a:ea:77:e1:8d Reusing allocated memory for EAP Pkt for retransmission to mobile e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.114: e8:2a:ea:77:e1:8d Received EAPOL-Key from mobile e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.114: e8:2a:ea:77:e1:8d Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.114: e8:2a:ea:77:e1:8d Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.114: e8:2a:ea:77:e1:8d Stopping retransmission timer for mobile e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.114: e8:2a:ea:77:e1:8d Freeing EAP Retransmit Bufer for mobile e8:2a:ea:77:e1:8d *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.114: e8:2a:ea:77:e1:8d apfMs1xStateInc *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.115: e8:2a:ea:77:e1:8d 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3) *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.115: e8:2a:ea:77:e1:8d Mobility query, PEM State: L2AUTHCOMPLETE *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.115: e8:2a:ea:77:e1:8d Building Mobile Announce : *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.115: e8:2a:ea:77:e1:8d Building Client Payload: *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.115: e8:2a:ea:77:e1:8d Client Ip: 0.0.0.0 *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.115: e8:2a:ea:77:e1:8d Client Vlan Ip: 192.168.120.2, Vlan mask : 255.255.255.0 *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.115: e8:2a:ea:77:e1:8d Client Vap Security: 1073758272 *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.115: e8:2a:ea:77:e1:8d Virtual Ip: 1.1.1.1 *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.116: e8:2a:ea:77:e1:8d ssid: ptest *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.116: e8:2a:ea:77:e1:8d Building VlanIpPayload. *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.116: e8:2a:ea:77:e1:8d Not Using WMM Compliance code qosCap 2f *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.116: e8:2a:ea:77:e1:8d Sending 11w Flag 0 for Client E8:2A:EA:77:E1:8D *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.116: e8:2a:ea:77:e1:8d 0.0.0.0 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP ec:c8:82:a4:5b:c0 vapId 5 apVapId 5 flex-acl-name: *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.117: e8:2a:ea:77:e1:8d 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state L2AUTHCOMPLETE (4) *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.117: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 6486, Adding TMP rule *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.117: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) Adding Fast Path rule type = Airespace AP - Learn IP address on AP ec:c8:82:a4:5b:c0, slot 0, interface = 1, QOS = 0 IPv4 ACL ID = 255, IPv *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.117: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 13 Local Bridging Vlan = 120, Local Bridging intf id = 13 *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.117: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.117: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.117: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *Dot1x_NW_MsgTask_5: Oct 15 15:48:16.118: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255) *apfReceiveTask: Oct 15 15:48:16.118: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) mobility role update request from Unassociated to Local Peer = 0.0.0.0, Old Anchor = 0.0.0.0, New Anchor = 10.201.234.165 *apfReceiveTask: Oct 15 15:48:16.118: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) State Update from Mobility-Incomplete to Mobility-Complete, mobility role=Local, client state=APF_MS_STATE_ASSOCIATED *apfReceiveTask: Oct 15 15:48:16.118: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 6102, Adding TMP rule *apfReceiveTask: Oct 15 15:48:16.118: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) Replacing Fast Path rule type = Airespace AP - Learn IP address on AP ec:c8:82:a4:5b:c0, slot 0, interface = 1, QOS = 0 IPv4 ACL ID = 255, *apfReceiveTask: Oct 15 15:48:16.118: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 13 Local Bridging Vlan = 120, Local Bridging intf id = 13 *apfReceiveTask: Oct 15 15:48:16.118: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *apfReceiveTask: Oct 15 15:48:16.118: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *apfReceiveTask: Oct 15 15:48:16.118: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *apfReceiveTask: Oct 15 15:48:16.118: e8:2a:ea:77:e1:8d 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255) *pemReceiveTask: Oct 15 15:48:16.119: e8:2a:ea:77:e1:8d 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0 *pemReceiveTask: Oct 15 15:48:16.119: e8:2a:ea:77:e1:8d 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0 *pemReceiveTask: Oct 15 15:48:16.119: e8:2a:ea:77:e1:8d Sent an XID frame *DHCP Socket Task: Oct 15 15:48:16.131: e8:2a:ea:77:e1:8d DHCP received op BOOTREQUEST (1) (len 334,vlan 0, port 1, encap 0xec03) *DHCP Socket Task: Oct 15 15:48:16.131: e8:2a:ea:77:e1:8d DHCP (encap type 0xec03) mstype 0ff:ff:ff:ff:ff:ff *DHCP Socket Task: Oct 15 15:48:16.131: e8:2a:ea:77:e1:8d DHCP selecting relay 1 - control block settings: dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0, dhcpGateway: 0.0.0.0, dhcpRelay: 0.0.0.0 VLAN: 0 *DHCP Socket Task: Oct 15 15:48:16.131: e8:2a:ea:77:e1:8d DHCP selected relay 1 - 192.168.120.1 (local address 192.168.120.2, gateway 192.168.120.1, VLAN 120, port 2) *DHCP Socket Task: Oct 15 15:48:16.131: e8:2a:ea:77:e1:8d DHCP transmitting DHCP REQUEST (3) *DHCP Socket Task: Oct 15 15:48:16.131: e8:2a:ea:77:e1:8d DHCP op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1 *DHCP Socket Task: Oct 15 15:48:16.131: e8:2a:ea:77:e1:8d DHCP xid: 0x341d404b (874332235), secs: 0, flags: 0 *DHCP Socket Task: Oct 15 15:48:16.131: e8:2a:ea:77:e1:8d DHCP chaddr: e8:2a:ea:77:e1:8d *DHCP Socket Task: Oct 15 15:48:16.131: e8:2a:ea:77:e1:8d DHCP ciaddr: 0.0.0.0, yiaddr: 0.0.0.0 *DHCP Socket Task: Oct 15 15:48:16.131: e8:2a:ea:77:e1:8d DHCP siaddr: 0.0.0.0, giaddr: 192.168.120.2 *DHCP Socket Task: Oct 15 15:48:16.131: e8:2a:ea:77:e1:8d DHCP requested ip: 192.168.120.22 *DHCP Socket Task: Oct 15 15:48:16.132: e8:2a:ea:77:e1:8d DHCP sending REQUEST to 192.168.120.1 (len 390, port 2, vlan 120) *DHCP Socket Task: Oct 15 15:48:16.132: e8:2a:ea:77:e1:8d DHCP selecting relay 2 - control block settings: dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0, dhcpGateway: 0.0.0.0, dhcpRelay: 192.168.120.2 VLAN: 120 *DHCP Socket Task: Oct 15 15:48:16.132: e8:2a:ea:77:e1:8d DHCP selected relay 2 - NONE (server address 0.0.0.0,local address 0.0.0.0, gateway 192.168.120.1, VLAN 120, port 2) *DHCP Socket Task: Oct 15 15:48:16.133: e8:2a:ea:77:e1:8d DHCP received op BOOTREPLY (2) (len 308,vlan 0, port 1, encap 0xec00) *DHCP Socket Task: Oct 15 15:48:16.133: e8:2a:ea:77:e1:8d DHCP setting server from ACK (mscb=0x40808380 ip=0xc0a87816)(server 192.168.120.1, yiaddr 192.168.120.22) *DHCP Socket Task: Oct 15 15:48:16.133: e8:2a:ea:77:e1:8d DHCP setting server from ACK (server 192.168.120.1, yiaddr 192.168.120.22) *DHCP Socket Task: Oct 15 15:48:16.133: e8:2a:ea:77:e1:8d apfMsRunStateInc *DHCP Socket Task: Oct 15 15:48:16.133: e8:2a:ea:77:e1:8d 192.168.120.22 DHCP_REQD (7) Change state to RUN (20) last state DHCP_REQD (7) *DHCP Socket Task: Oct 15 15:48:16.133: e8:2a:ea:77:e1:8d 192.168.120.22 RUN (20) Reached PLUMBFASTPATH: from line 7148 *DHCP Socket Task: Oct 15 15:48:16.133: e8:2a:ea:77:e1:8d 192.168.120.22 RUN (20) Replacing Fast Path rule type = Airespace AP Client on AP ec:c8:82:a4:5b:c0, slot 0, interface = 1, QOS = 0 IPv4 ACL ID = 255, IPv6 ACL I *DHCP Socket Task: Oct 15 15:48:16.133: e8:2a:ea:77:e1:8d 192.168.120.22 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 13 Local Bridging Vlan = 120, Local Bridging intf id = 13 *DHCP Socket Task: Oct 15 15:48:16.133: e8:2a:ea:77:e1:8d 192.168.120.22 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *DHCP Socket Task: Oct 15 15:48:16.134: e8:2a:ea:77:e1:8d 192.168.120.22 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *DHCP Socket Task: Oct 15 15:48:16.134: e8:2a:ea:77:e1:8d 192.168.120.22 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *DHCP Socket Task: Oct 15 15:48:16.134: e8:2a:ea:77:e1:8d 192.168.120.22 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255) *DHCP Socket Task: Oct 15 15:48:16.134: e8:2a:ea:77:e1:8d Assigning Address 192.168.120.22 to mobile *DHCP Socket Task: Oct 15 15:48:16.134: e8:2a:ea:77:e1:8d DHCP success event for client. Clearing dhcp failure count for interface test. *DHCP Socket Task: Oct 15 15:48:16.134: e8:2a:ea:77:e1:8d DHCP success event for client. Clearing dhcp failure count for interface test. *DHCP Socket Task: Oct 15 15:48:16.134: e8:2a:ea:77:e1:8d DHCP sending REPLY to STA (len 398, port 1, vlan 0) *DHCP Socket Task: Oct 15 15:48:16.134: e8:2a:ea:77:e1:8d DHCP transmitting DHCP ACK (5) *DHCP Socket Task: Oct 15 15:48:16.134: e8:2a:ea:77:e1:8d DHCP op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0 *DHCP Socket Task: Oct 15 15:48:16.134: e8:2a:ea:77:e1:8d DHCP xid: 0x341d404b (874332235), secs: 0, flags: 0 *DHCP Socket Task: Oct 15 15:48:16.134: e8:2a:ea:77:e1:8d DHCP chaddr: e8:2a:ea:77:e1:8d *DHCP Socket Task: Oct 15 15:48:16.134: e8:2a:ea:77:e1:8d DHCP ciaddr: 0.0.0.0, yiaddr: 192.168.120.22 *DHCP Socket Task: Oct 15 15:48:16.134: e8:2a:ea:77:e1:8d DHCP siaddr: 0.0.0.0, giaddr: 0.0.0.0 *DHCP Socket Task: Oct 15 15:48:16.134: e8:2a:ea:77:e1:8d DHCP server id: 1.1.1.1 rcvd server id: 192.168.120.1 *pemReceiveTask: Oct 15 15:48:16.137: e8:2a:ea:77:e1:8d 192.168.120.22 Added NPU entry of type 1, dtlFlags 0x0 *pemReceiveTask: Oct 15 15:48:16.138: e8:2a:ea:77:e1:8d Sending a gratuitous ARP for 192.168.120.22, VLAN Id 4216 *apfMsConnTask_1: Oct 15 15:48:17.642: 3c:a9:f4:01:21:84 Processing assoc-req station:3c:a9:f4:01:21:84 AP:ec:c8:82:a4:5b:c0-00 thread:150e3e20 *apfMsConnTask_1: Oct 15 15:48:17.642: 3c:a9:f4:01:21:84 Association received from mobile on BSSID ec:c8:82:a4:5b:c4 AP VoiceAP_1042 *apfMsConnTask_1: Oct 15 15:48:17.642: 3c:a9:f4:01:21:84 Global 200 Clients are allowed to AP radio *apfMsConnTask_1: Oct 15 15:48:17.642: 3c:a9:f4:01:21:84 Max Client Trap Threshold: 0 cur: 2 *apfMsConnTask_1: Oct 15 15:48:17.642: 3c:a9:f4:01:21:84 Rf profile 600 Clients are allowed to AP wlan *apfMsConnTask_1: Oct 15 15:48:17.642: 3c:a9:f4:01:21:84 override for default ap group, marking intgrp NULL *apfMsConnTask_1: Oct 15 15:48:17.642: 3c:a9:f4:01:21:84 Applying Interface policy on Mobile, role Unassociated. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 120 *apfMsConnTask_1: Oct 15 15:48:17.642: 3c:a9:f4:01:21:84 Re-applying interface policy for client *apfMsConnTask_1: Oct 15 15:48:17.642: 3c:a9:f4:01:21:84 0.0.0.0 START (0) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2385) *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 0.0.0.0 START (0) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2406) *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 In processSsidIE:5680 setting Central switched to TRUE *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 In processSsidIE:5683 apVapId = 5 and Split Acl Id = 65535 *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 Applying site-specific Local Bridging override for station 3c:a9:f4:01:21:84 - vapId 5, site 'default-group', interface 'test' *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 Applying Local Bridging Interface Policy for station 3c:a9:f4:01:21:84 - vlan 120, interface id 13, interface 'test' *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 processSsidIE statusCode is 0 and status is 0 *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 processSsidIE ssid_done_flag is 0 finish_flag is 0 *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 STA - rates (8): 139 150 12 18 24 36 48 72 96 108 0 0 0 0 0 0 *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 suppRates statusCode is 0 and gotSuppRatesElement is 1 *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 STA - rates (10): 139 150 12 18 24 36 48 72 96 108 0 0 0 0 0 0 *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 extSuppRates statusCode is 0 and gotExtSuppRatesElement is 1 *apfMsConnTask_1: Oct 15 15:48:17.643: RSNIE in Assoc. Req.: (22) *apfMsConnTask_1: Oct 15 15:48:17.643: [0000] 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f *apfMsConnTask_1: Oct 15 15:48:17.643: [0016] ac 02 3c 00 00 00 *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 Processing RSN IE type 48, length 22 for mobile 3c:a9:f4:01:21:84 *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 Received 802.11i PSK key management suite, enabling Authentication *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 RSN Capabilities: 60 *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 apfValidateDot11iCapabilities:1122 Received RSNIE with Capabilities with STA MFPC: 0, STA MFPR:0, & AP MFPC:0MFPR:0 *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 Marking Mobile as non-11w Capable *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 apfValidateDot11wGroupMgmtCipher:1552, Received NULL 11w Group Mgmt Cipher Suite for STA, hence returning *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 0.0.0.0 START (0) Initializing policy *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state START (0) *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state AUTHCHECK (2) *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 Encryption policy is set to 0x80000001 *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 Not Using WMM Compliance code qosCap 00 *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 Sending 11w Flag 0 for Client 3C:A9:F4:01:21:84 *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP ec:c8:82:a4:5b:c0 vapId 5 apVapId 5 flex-acl-name: *apfMsConnTask_1: Oct 15 15:48:17.643: 3c:a9:f4:01:21:84 apfPemAddUser2 (apf_policy.c:352) Changing state for mobile 3c:a9:f4:01:21:84 on AP ec:c8:82:a4:5b:c0 from Associated to Associated *apfMsConnTask_1: Oct 15 15:48:17.644: 3c:a9:f4:01:21:84 apfPemAddUser2:session timeout forstation 3c:a9:f4:01:21:84 - Session Tout 0, apfMsTimeOut '0' and sessionTimerRunning flag is 0 *apfMsConnTask_1: Oct 15 15:48:17.644: 3c:a9:f4:01:21:84 Stopping deletion of Mobile Station: (callerId: 48) *apfMsConnTask_1: Oct 15 15:48:17.644: 3c:a9:f4:01:21:84 Func: apfPemAddUser2, Ms Timeout = 0, Session Timeout = 0 *apfMsConnTask_1: Oct 15 15:48:17.644: 3c:a9:f4:01:21:84 Sending assoc-resp with status 0 station:3c:a9:f4:01:21:84 AP:ec:c8:82:a4:5b:c0-00 on apVapId 5 *apfMsConnTask_1: Oct 15 15:48:17.644: 3c:a9:f4:01:21:84 Sending Assoc Response to station on BSSID ec:c8:82:a4:5b:c4 (status 0) ApVapId 5 Slot 0 *apfMsConnTask_1: Oct 15 15:48:17.644: 3c:a9:f4:01:21:84 apfProcessAssocReq (apf_80211.c:9452) Changing state for mobile 3c:a9:f4:01:21:84 on AP ec:c8:82:a4:5b:c0 from Associated to Associated *spamApTask1: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 Sent 1x initiate message to multi thread task for mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 reauth_sm state transition 0 ---> 1 for mobile 3c:a9:f4:01:21:84 at 1x_reauth_sm.c:47 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 Creating a PKC PMKID Cache entry for station 3c:a9:f4:01:21:84 (RSN 2) *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 Resetting MSCB PMK Cache Entry 0 for station 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 Setting active key cache index 8 ---> 8 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 Setting active key cache index 8 ---> 0 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 Adding BSSID ec:c8:82:a4:5b:c4 to PMKID cache at index 0 for station 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: New PMKID: (16) *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: [0000] f1 ac d9 ef 7e 6e 35 56 1f 93 cb 06 cb ec cf 6f *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 Initiating RSN PSK to mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 EAP-PARAM Debug - eap-params for Wlan-Id :5 is disabled - applying Global eap timers and retries *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 Disable re-auth, use PMK lifetime. *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 dot1x - moving mobile 3c:a9:f4:01:21:84 into Force Auth state *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 Skipping EAP-Success to mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 Found an cache entry for BSSID ec:c8:82:a4:5b:c4 in PMKID cache at index 0 of station 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 Found an cache entry for BSSID ec:c8:82:a4:5b:c4 in PMKID cache at index 0 of station 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: Including PMKID in M1 (16) *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: [0000] f1 ac d9 ef 7e 6e 35 56 1f 93 cb 06 cb ec cf 6f *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 Starting key exchange to mobile 3c:a9:f4:01:21:84, data packets will be dropped *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 Sending EAPOL-Key Message to mobile 3c:a9:f4:01:21:84 state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.649: 3c:a9:f4:01:21:84 Allocating EAP Pkt for retransmission to mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.653: 3c:a9:f4:01:21:84 Received EAPOL-Key from mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.653: 3c:a9:f4:01:21:84 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.653: 3c:a9:f4:01:21:84 Received EAPOL-key in PTK_START state (message 2) from mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.653: 3c:a9:f4:01:21:84 Dumping RSNIE received in Association request: *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.653: 00000000: 30 16 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 0............... *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.653: 00000010: 00 0f ac 02 3c 00 00 00 ....<... *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.653: 3c:a9:f4:01:21:84 Dumping RSNIE received in EAPOL M2 : *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.653: 00000000: 01 00 00 0f ac 04 01 00 00 0f ac 04 01 00 00 0f ................ *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.653: 00000010: ac 02 3c 00 00 00 ..<... *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.653: 3c:a9:f4:01:21:84 Stopping retransmission timer for mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.653: 3c:a9:f4:01:21:84 Sending EAPOL-Key Message to mobile 3c:a9:f4:01:21:84 state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.653: 3c:a9:f4:01:21:84 Reusing allocated memory for EAP Pkt for retransmission to mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.655: 3c:a9:f4:01:21:84 Received EAPOL-Key from mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.655: 3c:a9:f4:01:21:84 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 Stopping retransmission timer for mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 Freeing EAP Retransmit Bufer for mobile 3c:a9:f4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 apfMs1xStateInc *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state 8021X_REQD (3) *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 Mobility query, PEM State: L2AUTHCOMPLETE *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 Building Mobile Announce : *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 Building Client Payload: *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 Client Ip: 0.0.0.0 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 Client Vlan Ip: 192.168.120.2, Vlan mask : 255.255.255.0 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 Client Vap Security: 1073758272 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 Virtual Ip: 1.1.1.1 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 ssid: ptest *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 Building VlanIpPayload. *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 Not Using WMM Compliance code qosCap 00 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 Sending 11w Flag 0 for Client 3C:A9:F4:01:21:84 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 0.0.0.0 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP ec:c8:82:a4:5b:c0 vapId 5 apVapId 5 flex-acl-name: *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state L2AUTHCOMPLETE (4) *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 6486, Adding TMP rule *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) Adding Fast Path rule type = Airespace AP - Learn IP address on AP ec:c8:82:a4:5b:c0, slot 0, interface = 1, QOS = 0 IPv4 ACL ID = 255, IPv *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 13 Local Bridging Vlan = 120, Local Bridging intf id = 13 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *Dot1x_NW_MsgTask_4: Oct 15 15:48:17.656: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255) *apfReceiveTask: Oct 15 15:48:17.658: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) mobility role update request from Unassociated to Local Peer = 0.0.0.0, Old Anchor = 0.0.0.0, New Anchor = 10.201.234.165 *apfReceiveTask: Oct 15 15:48:17.658: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) State Update from Mobility-Incomplete to Mobility-Complete, mobility role=Local, client state=APF_MS_STATE_ASSOCIATED *apfReceiveTask: Oct 15 15:48:17.658: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 6102, Adding TMP rule *apfReceiveTask: Oct 15 15:48:17.658: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) Replacing Fast Path rule type = Airespace AP - Learn IP address on AP ec:c8:82:a4:5b:c0, slot 0, interface = 1, QOS = 0 IPv4 ACL ID = 255, *apfReceiveTask: Oct 15 15:48:17.658: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 13 Local Bridging Vlan = 120, Local Bridging intf id = 13 *apfReceiveTask: Oct 15 15:48:17.658: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *apfReceiveTask: Oct 15 15:48:17.658: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *apfReceiveTask: Oct 15 15:48:17.658: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *apfReceiveTask: Oct 15 15:48:17.658: 3c:a9:f4:01:21:84 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255) *pemReceiveTask: Oct 15 15:48:17.659: 3c:a9:f4:01:21:84 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0 *pemReceiveTask: Oct 15 15:48:17.659: 3c:a9:f4:01:21:84 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0 *pemReceiveTask: Oct 15 15:48:17.659: 3c:a9:f4:01:21:84 Sent an XID frame *DHCP Socket Task: Oct 15 15:48:17.675: 3c:a9:f4:01:21:84 DHCP received op BOOTREQUEST (1) (len 334,vlan 0, port 1, encap 0xec03) *DHCP Socket Task: Oct 15 15:48:17.675: 3c:a9:f4:01:21:84 DHCP (encap type 0xec03) mstype 0ff:ff:ff:ff:ff:ff *DHCP Socket Task: Oct 15 15:48:17.675: 3c:a9:f4:01:21:84 DHCP selecting relay 1 - control block settings: dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0, dhcpGateway: 0.0.0.0, dhcpRelay: 0.0.0.0 VLAN: 0 *DHCP Socket Task: Oct 15 15:48:17.675: 3c:a9:f4:01:21:84 DHCP selected relay 1 - 192.168.120.1 (local address 192.168.120.2, gateway 192.168.120.1, VLAN 120, port 2) *DHCP Socket Task: Oct 15 15:48:17.675: 3c:a9:f4:01:21:84 DHCP transmitting DHCP REQUEST (3) *DHCP Socket Task: Oct 15 15:48:17.675: 3c:a9:f4:01:21:84 DHCP op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1 *DHCP Socket Task: Oct 15 15:48:17.675: 3c:a9:f4:01:21:84 DHCP xid: 0x85588d90 (2237173136), secs: 0, flags: 8000 *DHCP Socket Task: Oct 15 15:48:17.675: 3c:a9:f4:01:21:84 DHCP chaddr: 3c:a9:f4:01:21:84 *DHCP Socket Task: Oct 15 15:48:17.675: 3c:a9:f4:01:21:84 DHCP ciaddr: 0.0.0.0, yiaddr: 0.0.0.0 *DHCP Socket Task: Oct 15 15:48:17.676: 3c:a9:f4:01:21:84 DHCP siaddr: 0.0.0.0, giaddr: 192.168.120.2 *DHCP Socket Task: Oct 15 15:48:17.676: 3c:a9:f4:01:21:84 DHCP requested ip: 192.168.120.21 *DHCP Socket Task: Oct 15 15:48:17.676: 3c:a9:f4:01:21:84 DHCP sending REQUEST to 192.168.120.1 (len 390, port 2, vlan 120) *DHCP Socket Task: Oct 15 15:48:17.676: 3c:a9:f4:01:21:84 DHCP selecting relay 2 - control block settings: dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0, dhcpGateway: 0.0.0.0, dhcpRelay: 192.168.120.2 VLAN: 120 *DHCP Socket Task: Oct 15 15:48:17.676: 3c:a9:f4:01:21:84 DHCP selected relay 2 - NONE (server address 0.0.0.0,local address 0.0.0.0, gateway 192.168.120.1, VLAN 120, port 2) *DHCP Socket Task: Oct 15 15:48:17.677: 3c:a9:f4:01:21:84 DHCP received op BOOTREPLY (2) (len 308,vlan 0, port 1, encap 0xec00) *DHCP Socket Task: Oct 15 15:48:17.677: 3c:a9:f4:01:21:84 DHCP setting server from ACK (mscb=0x40806bb0 ip=0xc0a87815)(server 192.168.120.1, yiaddr 192.168.120.21) *DHCP Socket Task: Oct 15 15:48:17.677: 3c:a9:f4:01:21:84 DHCP setting server from ACK (server 192.168.120.1, yiaddr 192.168.120.21) *DHCP Socket Task: Oct 15 15:48:17.677: 3c:a9:f4:01:21:84 apfMsRunStateInc *DHCP Socket Task: Oct 15 15:48:17.677: 3c:a9:f4:01:21:84 192.168.120.21 DHCP_REQD (7) Change state to RUN (20) last state DHCP_REQD (7) *DHCP Socket Task: Oct 15 15:48:17.677: 3c:a9:f4:01:21:84 192.168.120.21 RUN (20) Reached PLUMBFASTPATH: from line 7148 *DHCP Socket Task: Oct 15 15:48:17.677: 3c:a9:f4:01:21:84 192.168.120.21 RUN (20) Replacing Fast Path rule type = Airespace AP Client on AP ec:c8:82:a4:5b:c0, slot 0, interface = 1, QOS = 0 IPv4 ACL ID = 255, IPv6 ACL I *DHCP Socket Task: Oct 15 15:48:17.677: 3c:a9:f4:01:21:84 192.168.120.21 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 15206, IntfId = 13 Local Bridging Vlan = 120, Local Bridging intf id = 13 *DHCP Socket Task: Oct 15 15:48:17.677: 3c:a9:f4:01:21:84 192.168.120.21 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *DHCP Socket Task: Oct 15 15:48:17.677: 3c:a9:f4:01:21:84 192.168.120.21 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *DHCP Socket Task: Oct 15 15:48:17.677: 3c:a9:f4:01:21:84 192.168.120.21 RUN (20) Fast Path rule (contd...) AVC Ratelimit: AppID = 0 ,AppAction = 0, AppToken = 15206 AverageRate = 0, BurstRate = 0 *DHCP Socket Task: Oct 15 15:48:17.678: 3c:a9:f4:01:21:84 192.168.120.21 RUN (20) Successfully plumbed mobile rule (IPv4 ACL ID 255, IPv6 ACL ID 255, L2 ACL ID 255) *DHCP Socket Task: Oct 15 15:48:17.678: 3c:a9:f4:01:21:84 Assigning Address 192.168.120.21 to mobile *DHCP Socket Task: Oct 15 15:48:17.678: 3c:a9:f4:01:21:84 DHCP success event for client. Clearing dhcp failure count for interface test. *DHCP Socket Task: Oct 15 15:48:17.678: 3c:a9:f4:01:21:84 DHCP success event for client. Clearing dhcp failure count for interface test. *DHCP Socket Task: Oct 15 15:48:17.678: 3c:a9:f4:01:21:84 DHCP sending REPLY to STA (len 398, port 1, vlan 0) *DHCP Socket Task: Oct 15 15:48:17.678: 3c:a9:f4:01:21:84 DHCP transmitting DHCP ACK (5) *DHCP Socket Task: Oct 15 15:48:17.678: 3c:a9:f4:01:21:84 DHCP op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0 *DHCP Socket Task: Oct 15 15:48:17.678: 3c:a9:f4:01:21:84 DHCP xid: 0x85588d90 (2237173136), secs: 0, flags: 8000 *DHCP Socket Task: Oct 15 15:48:17.678: 3c:a9:f4:01:21:84 DHCP chaddr: 3c:a9:f4:01:21:84 *DHCP Socket Task: Oct 15 15:48:17.678: 3c:a9:f4:01:21:84 DHCP ciaddr: 0.0.0.0, yiaddr: 192.168.120.21 *DHCP Socket Task: Oct 15 15:48:17.678: 3c:a9:f4:01:21:84 DHCP siaddr: 0.0.0.0, giaddr: 0.0.0.0 *DHCP Socket Task: Oct 15 15:48:17.678: 3c:a9:f4:01:21:84 DHCP server id: 1.1.1.1 rcvd server id: 192.168.120.1 *pemReceiveTask: Oct 15 15:48:17.682: 3c:a9:f4:01:21:84 192.168.120.21 Added NPU entry of type 1, dtlFlags 0x0 *pemReceiveTask: Oct 15 15:48:17.682: 3c:a9:f4:01:21:84 Sending a gratuitous ARP for 192.168.120.21, VLAN Id 4216 *DHCP Socket Task: Oct 15 15:48:19.207: e8:2a:ea:77:e1:8d DHCP received op BOOTREQUEST (1) (len 308,vlan 0, port 1, encap 0xec03) *DHCP Socket Task: Oct 15 15:48:19.207: e8:2a:ea:77:e1:8d DHCP (encap type 0xec03) mstype 0ff:ff:ff:ff:ff:ff *DHCP Socket Task: Oct 15 15:48:19.207: e8:2a:ea:77:e1:8d DHCP selecting relay 1 - control block settings: dhcpServer: 192.168.120.1, dhcpNetmask: 255.255.255.0, dhcpGateway: 192.168.120.1, dhcpRelay: 192.168.120.2 VLAN *DHCP Socket Task: Oct 15 15:48:19.207: e8:2a:ea:77:e1:8d DHCP mscbVapLocalAddr=192.168.120.2 mscbVapLocalNetMask= 255.255.255.0 mscbdhcpRelay=192.168.120.2 *DHCP Socket Task: Oct 15 15:48:19.207: e8:2a:ea:77:e1:8d DHCP selected relay 1 - 192.168.120.1 (local address 192.168.120.2, gateway 192.168.120.1, VLAN 120, port 2) *DHCP Socket Task: Oct 15 15:48:19.207: e8:2a:ea:77:e1:8d DHCP transmitting DHCP INFORM (8) *DHCP Socket Task: Oct 15 15:48:19.207: e8:2a:ea:77:e1:8d DHCP op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1 *DHCP Socket Task: Oct 15 15:48:19.207: e8:2a:ea:77:e1:8d DHCP xid: 0x941a7d86 (2484764038), secs: 0, flags: 0 *DHCP Socket Task: Oct 15 15:48:19.207: e8:2a:ea:77:e1:8d DHCP chaddr: e8:2a:ea:77:e1:8d *DHCP Socket Task: Oct 15 15:48:19.207: e8:2a:ea:77:e1:8d DHCP ciaddr: 192.168.120.22, yiaddr: 0.0.0.0 *DHCP Socket Task: Oct 15 15:48:19.207: e8:2a:ea:77:e1:8d DHCP siaddr: 0.0.0.0, giaddr: 192.168.120.2 *DHCP Socket Task: Oct 15 15:48:19.207: e8:2a:ea:77:e1:8d DHCP sending REQUEST to 192.168.120.1 (len 366, port 2, vlan 120) *DHCP Socket Task: Oct 15 15:48:19.207: e8:2a:ea:77:e1:8d DHCP selecting relay 2 - control block settings: dhcpServer: 192.168.120.1, dhcpNetmask: 255.255.255.0, dhcpGateway: 192.168.120.1, dhcpRelay: 192.168.120.2 VLAN *DHCP Socket Task: Oct 15 15:48:19.207: e8:2a:ea:77:e1:8d DHCP selected relay 2 - NONE *DHCP Socket Task: Oct 15 15:48:19.208: e8:2a:ea:77:e1:8d DHCP received op BOOTREPLY (2) (len 308,vlan 0, port 1, encap 0xec00) *DHCP Socket Task: Oct 15 15:48:19.208: e8:2a:ea:77:e1:8d DHCP setting server from ACK (mscb=0x40808380 ip=0x0)(server 192.168.120.1, yiaddr 0.0.0.0) *DHCP Socket Task: Oct 15 15:48:19.208: e8:2a:ea:77:e1:8d DHCP sending REPLY to STA (len 398, port 1, vlan 0) *DHCP Socket Task: Oct 15 15:48:19.208: e8:2a:ea:77:e1:8d DHCP transmitting DHCP ACK (5) *DHCP Socket Task: Oct 15 15:48:19.208: e8:2a:ea:77:e1:8d DHCP op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0 *DHCP Socket Task: Oct 15 15:48:19.209: e8:2a:ea:77:e1:8d DHCP xid: 0x941a7d86 (2484764038), secs: 0, flags: 0 *DHCP Socket Task: Oct 15 15:48:19.209: e8:2a:ea:77:e1:8d DHCP chaddr: e8:2a:ea:77:e1:8d *DHCP Socket Task: Oct 15 15:48:19.209: e8:2a:ea:77:e1:8d DHCP ciaddr: 192.168.120.22, yiaddr: 0.0.0.0 *DHCP Socket Task: Oct 15 15:48:19.209: e8:2a:ea:77:e1:8d DHCP siaddr: 0.0.0.0, giaddr: 0.0.0.0 *DHCP Socket Task: Oct 15 15:48:19.209: e8:2a:ea:77:e1:8d DHCP server id: 1.1.1.1 rcvd server id: 192.168.120.1 *DHCP Socket Task: Oct 15 15:48:21.073: 3c:a9:f4:01:21:84 DHCP received op BOOTREQUEST (1) (len 308,vlan 0, port 1, encap 0xec03) *DHCP Socket Task: Oct 15 15:48:21.074: 3c:a9:f4:01:21:84 DHCP (encap type 0xec03) mstype 0ff:ff:ff:ff:ff:ff *DHCP Socket Task: Oct 15 15:48:21.074: 3c:a9:f4:01:21:84 DHCP selecting relay 1 - control block settings: dhcpServer: 192.168.120.1, dhcpNetmask: 255.255.255.0, dhcpGateway: 192.168.120.1, dhcpRelay: 192.168.120.2 VLAN *DHCP Socket Task: Oct 15 15:48:21.074: 3c:a9:f4:01:21:84 DHCP mscbVapLocalAddr=192.168.120.2 mscbVapLocalNetMask= 255.255.255.0 mscbdhcpRelay=192.168.120.2 *DHCP Socket Task: Oct 15 15:48:21.074: 3c:a9:f4:01:21:84 DHCP selected relay 1 - 192.168.120.1 (local address 192.168.120.2, gateway 192.168.120.1, VLAN 120, port 2) *DHCP Socket Task: Oct 15 15:48:21.074: 3c:a9:f4:01:21:84 DHCP transmitting DHCP INFORM (8) *DHCP Socket Task: Oct 15 15:48:21.074: 3c:a9:f4:01:21:84 DHCP op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1 *DHCP Socket Task: Oct 15 15:48:21.074: 3c:a9:f4:01:21:84 DHCP xid: 0x95d46410 (2513724432), secs: 0, flags: 8000 *DHCP Socket Task: Oct 15 15:48:21.074: 3c:a9:f4:01:21:84 DHCP chaddr: 3c:a9:f4:01:21:84 *DHCP Socket Task: Oct 15 15:48:21.074: 3c:a9:f4:01:21:84 DHCP ciaddr: 192.168.120.21, yiaddr: 0.0.0.0 *DHCP Socket Task: Oct 15 15:48:21.074: 3c:a9:f4:01:21:84 DHCP siaddr: 0.0.0.0, giaddr: 192.168.120.2 *DHCP Socket Task: Oct 15 15:48:21.074: 3c:a9:f4:01:21:84 DHCP sending REQUEST to 192.168.120.1 (len 366, port 2, vlan 120) *DHCP Socket Task: Oct 15 15:48:21.074: 3c:a9:f4:01:21:84 DHCP selecting relay 2 - control block settings: dhcpServer: 192.168.120.1, dhcpNetmask: 255.255.255.0, dhcpGateway: 192.168.120.1, dhcpRelay: 192.168.120.2 VLAN *DHCP Socket Task: Oct 15 15:48:21.074: 3c:a9:f4:01:21:84 DHCP selected relay 2 - NONE *DHCP Socket Task: Oct 15 15:48:21.075: 3c:a9:f4:01:21:84 DHCP received op BOOTREPLY (2) (len 308,vlan 0, port 1, encap 0xec00) *DHCP Socket Task: Oct 15 15:48:21.075: 3c:a9:f4:01:21:84 DHCP setting server from ACK (mscb=0x40806bb0 ip=0x0)(server 192.168.120.1, yiaddr 0.0.0.0) *DHCP Socket Task: Oct 15 15:48:21.075: 3c:a9:f4:01:21:84 DHCP sending REPLY to STA (len 398, port 1, vlan 0) *DHCP Socket Task: Oct 15 15:48:21.075: 3c:a9:f4:01:21:84 DHCP transmitting DHCP ACK (5) *DHCP Socket Task: Oct 15 15:48:21.075: 3c:a9:f4:01:21:84 DHCP op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0 *DHCP Socket Task: Oct 15 15:48:21.075: 3c:a9:f4:01:21:84 DHCP xid: 0x95d46410 (2513724432), secs: 0, flags: 8000 *DHCP Socket Task: Oct 15 15:48:21.075: 3c:a9:f4:01:21:84 DHCP chaddr: 3c:a9:f4:01:21:84 *DHCP Socket Task: Oct 15 15:48:21.075: 3c:a9:f4:01:21:84 DHCP ciaddr: 192.168.120.21, yiaddr: 0.0.0.0 *DHCP Socket Task: Oct 15 15:48:21.075: 3c:a9:f4:01:21:84 DHCP siaddr: 0.0.0.0, giaddr: 0.0.0.0 (Cisco Controller) > (Cisco Controller) > (Cisco Controller) >debug di (Cisco Controller) >