=~=~=~=~=~=~=~=~=~=~=~= PuTTY log 2020.07.02 17:20:00 =~=~=~=~=~=~=~=~=~=~=~= (Cisco Controller) >debug mac addr 7C:2A:31:1E:A4:42 70:7d:b9:56:91:7e (Cisco Controller) >debug capwap events enable (Cisco Controller) >debug capwap errors enable (Cisco Controller) >debug pm pki enable (Cisco Controller) >debug dtls all enable (Cisco Controller) >*sshpmLscTask: Jul 02 17:21:05.560: [SA] sshpmLscTask: LSC Task received a message 4 *spamApTask1: Jul 02 17:21:09.944: [SA] 00000000: 15 fe fd 00 01 00 00 00 00 02 6f 00 30 2c 20 19 ..........o.0,.. *spamApTask1: Jul 02 17:21:09.945: [SA] 7c:2a:31:1e:a4:42 Cleaning up state for STA 7c:2a:31:1e:a4:42 due to event for AP 00:5d:73:d2:ea:40(1) *spamApTask1: Jul 02 17:21:09.945: [SA] 7c:2a:31:1e:a4:42 Succesfully freed AID 120, slot 1 on AP 00:5d:73:d2:ea:40, #client on this slot 1 *apfReceiveTask: Jul 02 17:21:09.945: [SA] 7c:2a:31:1e:a4:42 apfSendDisAssocMsgDebug (apf_80211.c:3612) Changing state for mobile 7c:2a:31:1e:a4:42 on AP 00:00:00:00:00:00 from Associated to Disassociated *apfReceiveTask: Jul 02 17:21:09.945: [SA] 7c:2a:31:1e:a4:42 Not Sending Disassociate to flex ap auth client on AP 00:00:00:00:00:00-0 (reason 1, caller apf_ms.c:7662) *apfReceiveTask: Jul 02 17:21:09.945: [SA] 7c:2a:31:1e:a4:42 Scheduling deletion of Mobile Station: (callerId: 45) in 10 seconds *osapiBsnTimer: Jul 02 17:21:20.300: [SA] 7c:2a:31:1e:a4:42 apfMsExpireCallback (apf_ms.c:639) Expiring Mobile! *apfReceiveTask: Jul 02 17:21:20.300: [SA] 7c:2a:31:1e:a4:42 Client already in disassociated state, not sending disassociation *apfReceiveTask: Jul 02 17:21:20.300: [SA] 7c:2a:31:1e:a4:42 Not sending De-auth to flex ap auth client on AP 00:00:00:00:00:00-0 on BSSID 00:5d:73:d2:ea:42(reason 2, caller apf_ms.c:7780) *apfReceiveTask: Jul 02 17:21:20.300: [SA] 7c:2a:31:1e:a4:42 apfMsAssoStateDec *apfReceiveTask: Jul 02 17:21:20.300: [SA] 7c:2a:31:1e:a4:42 apfMsWepPskStateDec *apfReceiveTask: Jul 02 17:21:20.300: [SA] 7c:2a:31:1e:a4:42 apfMsExpireMobileStation (apf_ms.c:7821) Changing state for mobile 7c:2a:31:1e:a4:42 on AP 00:00:00:00:00:00 from Disassociated to Idle *apfReceiveTask: Jul 02 17:21:20.300: [SA] 7c:2a:31:1e:a4:42 Scheduling deletion of Mobile Station: (callerId: 47) in 10 seconds *spamApTask1: Jul 02 17:21:25.053: [SA] sshpmGetCID: called to evaluate *spamApTask1: Jul 02 17:21:25.053: [SA] sshpmGetCID: Found matching ID cert cscoSha2IdCert in row 3 *spamApTask1: Jul 02 17:21:25.053: [SA] Get Cert from CID: For CID 1a67cf95 certType 1 *spamApTask1: Jul 02 17:21:25.053: [SA] Get Cert from CID: Found match of ID Cert in row 3 *spamApTask1: Jul 02 17:21:25.053: [SA] sshpmGetCID: called to evaluate *spamApTask1: Jul 02 17:21:25.053: [SA] sshpmGetCID: Found matching ID cert cscoSha2IdCert in row 3 *spamApTask1: Jul 02 17:21:25.053: [SA] GetDERIDKey: Using SHA2 Id cert Private Keys on WLC *spamApTask1: Jul 02 17:21:25.053: [SA] GetPrivateKey: called to get key for CID 1a67cf95 *spamApTask1: Jul 02 17:21:25.053: [SA] Private Key found row 3 KeyBufLen 2048 Keylen 1191 PrivateKeyPtr 0x7f4e4da3cb70 *spamApTask1: Jul 02 17:21:25.054: [SA] 00000000: 16 fe ff 00 00 00 00 00 00 00 00 00 8f 01 00 00 ................ *spamApTask1: Jul 02 17:21:25.058: [SA] 00000000: 16 fe ff 00 00 00 00 00 00 00 01 00 af 01 00 00 ................ *spamApTask1: Jul 02 17:21:25.058: [SA] 00000000: 69 95 f9 15 55 92 3f 68 26 cc bb f0 38 80 05 32 i...U.?h&...8..2 *spamApTask1: Jul 02 17:21:25.058: [SA] 00000010: b9 40 4b d0 .@K. *spamApTask1: Jul 02 17:21:25.063: [SA] 00000000: 16 fe fd 00 00 00 00 00 00 00 02 02 13 0b 00 04 ................ *spamApTask1: Jul 02 17:21:25.063: [SA] 00000000: 16 fe fd 00 00 00 00 00 00 00 03 02 13 0b 00 04 ................ *spamApTask1: Jul 02 17:21:25.063: [SA] 00000000: 16 fe fd 00 00 00 00 00 00 00 04 00 77 0b 00 04 ............w... *spamApTask1: Jul 02 17:21:25.063: [SA] OpenSSL Get Issuer Handles: locking ca cert table *spamApTask1: Jul 02 17:21:25.063: [SA] OpenSSL Get Issuer Handles: x509 subject_name /C=US/ST=California/L=San Jose/O=Cisco Systems/CN=AP3G3-707DB956917E/emailAddress=support@cisco.com *spamApTask1: Jul 02 17:21:25.063: [SA] OpenSSL Get Issuer Handles: issuer_name /O=Cisco/CN=Cisco Manufacturing CA SHA2 *spamApTask1: Jul 02 17:21:25.063: [SA] OpenSSL Get Issuer Handles: CN AP3G3-707DB956917E *spamApTask1: Jul 02 17:21:25.063: [SA] OpenSSL Get Issuer Handles: issuerCertCN Cisco Manufacturing CA SHA2 *spamApTask1: Jul 02 17:21:25.063: [SA] GetMac: MAC: 707d.b956.917e *spamApTask1: Jul 02 17:21:25.063: [SA] OpenSSL Get Issuer Handles: openssl Mac Address in subject is 70:7d:b9:56:91:7e *spamApTask1: Jul 02 17:21:25.063: [SA] OpenSSL Get Issuer Handles: Cert Name in subject is AP3G3-707DB956917E *spamApTask1: Jul 02 17:21:25.063: [SA] OpenSSL Get Issuer Handles: Extracted cert issuer from subject name. *spamApTask1: Jul 02 17:21:25.063: [SA] NMSP:: Algo name matched SHA256 *spamApTask1: Jul 02 17:21:25.063: [SA] OpenSSL Get Issuer Handles: Cert is issued by Cisco Systems. *spamApTask1: Jul 02 17:21:25.063: [SA] Retrieving x509 cert for CertName cscoMfgSha2CaCert *spamApTask1: Jul 02 17:21:25.063: [SA] sshpmGetCID: called to evaluate *spamApTask1: Jul 02 17:21:25.063: [SA] sshpmGetCID: Found matching CA cert cscoMfgSha2CaCert in row 7 *spamApTask1: Jul 02 17:21:25.063: [SA] Found CID 21726e5d for certname cscoMfgSha2CaCert *spamApTask1: Jul 02 17:21:25.063: [SA] CACertTable: Found matching CID cscoMfgSha2CaCert in row 7 x509 0x7f4e4549d100 *spamApTask1: Jul 02 17:21:25.063: [SA] Retrieving x509 cert for CertName cscoRootSha2CaCert *spamApTask1: Jul 02 17:21:25.063: [SA] sshpmGetCID: called to evaluate *spamApTask1: Jul 02 17:21:25.063: [SA] sshpmGetCID: Found matching CA cert cscoRootSha2CaCert in row 6 *spamApTask1: Jul 02 17:21:25.063: [SA] Found CID 256e8878 for certname cscoRootSha2CaCert *spamApTask1: Jul 02 17:21:25.063: [SA] CACertTable: Found matching CID cscoRootSha2CaCert in row 6 x509 0x7f4e4549d3d0 *spamApTask1: Jul 02 17:21:25.063: [SA] Verify User Certificate: X509 Cert Verification return code: 1 *spamApTask1: Jul 02 17:21:25.063: [SA] Verify User Certificate: X509 Cert Verification result text: ok *spamApTask1: Jul 02 17:21:25.063: [SA] sshpmGetCID: called to evaluate *spamApTask1: Jul 02 17:21:25.063: [SA] sshpmGetCID: Found matching CA cert cscoMfgSha2CaCert in row 7 *spamApTask1: Jul 02 17:21:25.063: [SA] Verify User Certificate: OPENSSL X509_Verify: AP Cert Verfied Using >cscoMfgSha2CaCert< *spamApTask1: Jul 02 17:21:25.063: [SA] OpenSSL Get Issuer Handles: Check cert validity times (allow expired NO) *spamApTask1: Jul 02 17:21:25.063: [SA] sshpmGetCID: called to evaluate *spamApTask1: Jul 02 17:21:25.063: [SA] sshpmGetCID: Found matching ID cert cscoDefaultIdCert in row 2 *spamApTask1: Jul 02 17:21:25.063: [SA] sshpmFreePublicKeyHandle: called with 0x7f4e4775a140 *spamApTask1: Jul 02 17:21:25.063: [SA] sshpmFreePublicKeyHandle: freeing public key *spamApTask1: Jul 02 17:21:25.064: [SA] 00000000: 16 fe fd 00 00 00 00 00 00 00 05 01 0e 10 00 01 ................ *spamApTask1: Jul 02 17:21:25.085: [SA] 00000000: 16 fe fd 00 00 00 00 00 00 00 06 01 10 0f 00 01 ................ *spamApTask1: Jul 02 17:21:25.085: [SA] 00000000: 14 fe fd 00 00 00 00 00 00 00 07 00 01 01 16 fe ................ *spamApTask1: Jul 02 17:21:26.069: [SA] Flex Group Feature BITMAP 0 *spamApTask1: Jul 02 17:21:26.069: [SA] Queuing 13 PMK cache entries to send to AP 00:5d:73:d2:ea:40 *spamApTask1: Jul 02 17:21:26.069: [SA] No CCKM cache entries found to send to AP 00:5d:73:d2:ea:40 *spamReceiveTask: Jul 02 17:21:26.069: [SA] Received SPAM_UPLOAD_STATIC_BLACKLIST_TABLE *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 apfMsAssoStateInc *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 apfHreapFaultTolClientUpdate (apf_80211.c:16900) Changing state for mobile 7c:2a:31:1e:a4:42 on AP 00:5d:73:d2:ea:40 from Idle to Associated *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 Stopping deletion of Mobile Station: (callerId: 81) *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 override for default ap group, marking intgrp NULL *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 apfApplyWlanPolicy: Apply WLAN Policy over PMIPv6 Client Mobility Type, Tunnel User - 0 *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 Applying site-specific Local Bridging override for station 7c:2a:31:1e:a4:42 - vapId 4, site 'i919', interface 'guests' *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 Applying Local Bridging Interface Policy for station 7c:2a:31:1e:a4:42 - vlan 192, interface id 12, interface 'guests' *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 override from ap group, removing intf group from mscb *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 Applying site-specific override for station 7c:2a:31:1e:a4:42 - vapId 4, site 'i919', interface 'guests' *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 Applying Interface(guests) policy on Mobile, role Local. Ms NAC State 2 Quarantine Vlan 0 Access Vlan 192 *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 Not re-applying interface policy for local switching Client *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 192.168.166.68 RUN (20) Changing IPv4 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2922) *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 192.168.166.68 RUN (20) Changing Url ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2942) *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 192.168.166.68 RUN (20) Changing IPv6 ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:2963) *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 In setApfVapLocalSwitchFlag:16214 setting Central switched to FLASE *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 Set Clinet MSCB as Central Association Disabled *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 apfMsRunStateDec *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 192.168.166.68 RUN (20) Change state to DHCP_REQD (7) last state RUN (20) *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 apfMsRunStateInc *apfReceiveTask: Jul 02 17:21:26.273: [SA] 7c:2a:31:1e:a4:42 192.168.166.68 DHCP_REQD (7) Change state to RUN (20) last state DHCP_REQD (7) *apfReceiveTask: Jul 02 17:21:27.868: [SA] 7c:2a:31:1e:a4:42 (15850) Rx'ed HreapClientDelete state :1 with slotId :1 aid :0 wlanId :3 vlanId :192 BSSID:00:5d:73:d2:ea:4d *apfReceiveTask: Jul 02 17:21:27.868: [SA] 7c:2a:31:1e:a4:42 apfMsAssoStateDec *apfReceiveTask: Jul 02 17:21:27.868: [SA] 7c:2a:31:1e:a4:42 apfMsWepPskStateDec *apfReceiveTask: Jul 02 17:21:27.868: [SA] 7c:2a:31:1e:a4:42 apfHreapClientDelete (apf_80211.c:15883) Changing state for mobile 7c:2a:31:1e:a4:42 on AP 00:5d:73:d2:ea:40 from Associated to Idle *apfReceiveTask: Jul 02 17:21:27.868: [SA] 7c:2a:31:1e:a4:42 apfSendDeleteMobileMsgImmediate (apf_net.c:5786) Expiring Mobile! *apfReceiveTask: Jul 02 17:21:27.868: [SA] 7c:2a:31:1e:a4:42 pemApfDeleteMobileStation2: APF_MS_PEM_WAIT_L2_AUTH_COMPLETE = 0. *apfReceiveTask: Jul 02 17:21:27.868: [SA] 7c:2a:31:1e:a4:42 192.168.166.68 RUN (20) Deleted mobile LWAPP rule on AP [00:5d:73:d2:ea:40] *apfReceiveTask: Jul 02 17:21:27.868: [SA] 7c:2a:31:1e:a4:42 Succesfully freed AID 120, slot 1 on AP 00:5d:73:d2:ea:40, #client on this slot 1 *apfReceiveTask: Jul 02 17:21:27.868: [SA] 7c:2a:31:1e:a4:42 apfMsRunStateDec *apfReceiveTask: Jul 02 17:21:27.868: [SA] 7c:2a:31:1e:a4:42 apfMs1xStateDec *apfReceiveTask: Jul 02 17:21:27.868: [SA] 7c:2a:31:1e:a4:42 Deleting mobile on AP 00:5d:73:d2:ea:40(1) *spamApTask1: Jul 02 17:21:33.866: [SA] 7c:2a:31:1e:a4:42 Received DELETE mobile, reason MN_REASSOC_TIMEOUT, from AP 00:5d:73:d2:ea:40, slot 1 ...cleaning up mscb *sshpmLscTask: Jul 02 17:23:09.936: [SA] sshpmLscTask: LSC Task received a message 4 *spamApTask1: Jul 02 17:23:21.879: [SA] 7c:2a:31:1e:a4:42 Received DELETE mobile, reason MN_REASSOC_TIMEOUT, from AP 00:5d:73:d2:ea:40, slot 1 ...cleaning up mscb