2018-05-23 05:33:12,724	[Th 37 Req 1110 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: Starting Service Categorization - 61:216:107b44e80744
2018-05-23 05:33:12,733	[RequestHandler-1-0x7fcc08be5700 r=psauto-1526650985-345 h=223 r=R000000aa-01-5b04d2e8] INFO Core.ServiceReqHandler - Service classification result = PL_homeIAP_8021x_wireless
2018-05-23 05:33:12,735	[Th 37 Req 1110 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - Service Categorization time = 9 ms
2018-05-23 05:33:12,735	[Th 37 Req 1110 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: The request has been categorized into service "PL_homeIAP_8021x_wireless"
2018-05-23 05:33:12,735	[Th 37 Req 1110 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_ldap: searching for user oauser1 in AD:oa-dc.oasis.local
2018-05-23 05:33:12,741	[Th 37 Req 1110 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_ldap: found user oauser1 in AD:oa-dc.oasis.local
2018-05-23 05:33:12,742	[Th 37 Req 1110 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - LDAP/AD User lookup time = 6 ms
2018-05-23 05:33:12,742	[Th 37 Req 1110 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_eap_peap: Initiate
2018-05-23 05:33:12,742	[Th 37 Req 1110 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 61:88:107b44e80744:AIkATwAdALRWBAAAozgEsgY6OJ+iKqxCJcBSTQ==
2018-05-23 05:33:12,765	[Th 38 Req 1111 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "PL_homeIAP_8021x_wireless" - 62:391:107b44e80744
2018-05-23 05:33:12,774	[Th 38 Req 1111 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read client key exchange A
2018-05-23 05:33:12,774	[Th 38 Req 1111 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read client key exchange A
2018-05-23 05:33:12,775	[Th 38 Req 1111 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 62:1124:107b44e80744:AFcArAClAGpXBAAAF0qaq9h/V4++BRpDZVTOjg==
2018-05-23 05:33:12,801	[Th 39 Req 1112 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "PL_homeIAP_8021x_wireless" - 63:252:107b44e80744
2018-05-23 05:33:12,801	[Th 39 Req 1112 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 63:1120:107b44e80744:AEAADgByAA1YBAAAMeA8D3NwsTSJdu1jrWB19A==
2018-05-23 05:33:12,828	[Th 40 Req 1113 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "PL_homeIAP_8021x_wireless" - 64:252:107b44e80744
2018-05-23 05:33:12,828	[Th 40 Req 1113 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 64:1120:107b44e80744:AMkA+gALAGZZBAAAZsyL4ong0i6Kbc7pPDDaAQ==
2018-05-23 05:33:12,859	[Th 37 Req 1114 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "PL_homeIAP_8021x_wireless" - 65:252:107b44e80744
2018-05-23 05:33:12,860	[Th 37 Req 1114 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 65:1120:107b44e80744:AN4AggCgAJ9aBAAAJJIqRYFsqgCGkEhHfMfnvQ==
2018-05-23 05:33:12,893	[Th 38 Req 1115 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "PL_homeIAP_8021x_wireless" - 66:252:107b44e80744
2018-05-23 05:33:12,893	[Th 38 Req 1115 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 66:978:107b44e80744:ABgARwCYAFRbBAAAfaTsyLD1Y7bjxvhGseqqPA==
2018-05-23 05:33:12,926	[Th 39 Req 1116 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "PL_homeIAP_8021x_wireless" - 67:390:107b44e80744
2018-05-23 05:33:12,928	[Th 39 Req 1116 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 67:147:107b44e80744:AMsAtgDfAMtcBAAAoy6GGf3bwoMuQUsfidYi4w==
2018-05-23 05:33:12,949	[Th 40 Req 1117 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "PL_homeIAP_8021x_wireless" - 68:252:107b44e80744
2018-05-23 05:33:12,949	[Th 40 Req 1117 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_eap_peap: Session established.
2018-05-23 05:33:12,949	[Th 40 Req 1117 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 68:125:107b44e80744:AJwAnwCPAKVdBAAAKfAQOgoJJsGW6KWHLzEmsQ==
2018-05-23 05:33:12,969	[Th 37 Req 1118 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "PL_homeIAP_8021x_wireless" - 69:289:107b44e80744
2018-05-23 05:33:12,970	[Th 37 Req 1118 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_eap_mschapv2: Issuing Challenge
2018-05-23 05:33:12,971	[Th 37 Req 1118 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 69:157:107b44e80744:AHUAnwDEAKxeBAAAN/AC89CtOvf0FxXJ/pcCRA==
2018-05-23 05:33:12,996	[Th 38 Req 1119 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "PL_homeIAP_8021x_wireless" - 70:353:107b44e80744
2018-05-23 05:33:12,997	[Th 38 Req 1119 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "PL_homeIAP_8021x_wireless" - 95:0:107b44e80744
2018-05-23 05:33:12,997	[Th 38 Req 1119 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_eap_mschapv2: Received MSCHAPv2 Response from client
2018-05-23 05:33:12,997	[Th 38 Req 1119 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_mschap: MSCHAPv2 username used for challenge computation oauser1
2018-05-23 05:33:12,997	[Th 38 Req 1119 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_mschap: Using domain OASIS from objectSid attribute
2018-05-23 05:33:12,997	[Th 38 Req 1119 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_mschap: authenticating user OAUser1, domain OASIS
2018-05-23 05:33:13,064	[Th 38 Req 1119 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_mschap: user OAUser1 authenticated successfully
2018-05-23 05:33:13,064	[Th 38 Req 1119 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - MS-Chap User Authentication time = 67 ms
2018-05-23 05:33:13,064	[Th 38 Req 1119 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_eap_mschapv2: Sending MSCHAPv2 Success reply
2018-05-23 05:33:13,065	[Th 38 Req 1119 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 70:173:107b44e80744:ANkA7QDXAC5fBAAADyVFHE5GFc62rsoTfjlmgg==
2018-05-23 05:33:13,094	[Th 39 Req 1120 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "PL_homeIAP_8021x_wireless" - 71:289:107b44e80744
2018-05-23 05:33:13,095	[Th 39 Req 1120 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "PL_homeIAP_8021x_wireless" - 96:0:107b44e80744
2018-05-23 05:33:13,095	[Th 39 Req 1120 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_eap_mschapv2: Received MSCHAPv2 Success from client
2018-05-23 05:33:13,095	[Th 39 Req 1120 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_policy: Starting Policy Evaluation.
2018-05-23 05:33:13,101	[RequestHandler-1-0x7fcc08be5700 r=psauto-1526650985-346 h=239 r=R000000aa-01-5b04d2e8] INFO Common.EndpointTable - Returning NULL (EndpointPtr) for macAddr 107b44e80744
2018-05-23 05:33:13,102	[RequestHandler-1-0x7fcc08be5700 r=psauto-1526650985-346 h=239 r=R000000aa-01-5b04d2e8] INFO Common.TagDefinitionCacheTable - No InstanceTagDefCacheMap found for instance id = 3001 entity id = 29
2018-05-23 05:33:13,102	[RequestHandler-1-0x7fcc08be5700 r=psauto-1526650985-346 h=239 r=R000000aa-01-5b04d2e8] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for NAD instance=3001
2018-05-23 05:33:13,102	[RequestHandler-1-0x7fcc08be5700 r=psauto-1526650985-346 h=239 r=R000000aa-01-5b04d2e8] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for NAD instanceId=3001|entityId=29
2018-05-23 05:33:13,102	[RequestHandler-1-0x7fcc08be5700 r=psauto-1526650985-346 h=239 r=R000000aa-01-5b04d2e8] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=3001|entity=Device
2018-05-23 05:33:13,102	[RequestHandler-1-0x7fcc08be5700 r=psauto-1526650985-346 h=239 r=R000000aa-01-5b04d2e8] INFO TAT.AluTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL AuthLocalUser)
2018-05-23 05:33:13,102	[RequestHandler-1-0x7fcc08be5700 r=psauto-1526650985-346 h=239 r=R000000aa-01-5b04d2e8] INFO TAT.GuTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL GuestUser)
2018-05-23 05:33:13,102	[RequestHandler-1-0x7fcc08be5700 r=psauto-1526650985-346 h=239 r=R000000aa-01-5b04d2e8] INFO TAT.EndpointTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Endpoint)
2018-05-23 05:33:13,102	[RequestHandler-1-0x7fcc08be5700 r=psauto-1526650985-346 h=239 r=R000000aa-01-5b04d2e8] INFO TAT.OnboardTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Onboard Device User)
2018-05-23 05:33:13,103	[RequestHandler-1-0x7fcc08be5700 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Started ***
2018-05-23 05:33:13,103	[RequestHandler-1-0x7fcc08be5700 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Starting PETaskAuthSourceRestriction **
2018-05-23 05:33:13,103	[RequestHandler-1-0x7fcc08be5700 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Starting PETaskRoleMapping **
2018-05-23 05:33:13,104	[RequestHandler-1-0x7fcc08be5700 h=2426 c=R000000aa-01-5b04d2e8] WARN REC.EvaluatorCtx - Prerequisites set is empty, not populating the Request Map
2018-05-23 05:33:13,105	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Completed PETaskAuthSourceRestriction **
2018-05-23 05:33:13,111	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2427 c=R000000aa-01-5b04d2e8] INFO Core.PETaskRoleMapping - Roles: User Authenticated], pl_test
2018-05-23 05:33:13,111	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Completed PETaskRoleMapping **
2018-05-23 05:33:13,112	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Starting PETaskPolicyResult **
2018-05-23 05:33:13,112	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Completed PETaskPolicyResult **
2018-05-23 05:33:13,112	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Starting PETaskEnforcement **
2018-05-23 05:33:13,113	[RequestHandler-1-0x7fcc08be5700 h=2430 c=R000000aa-01-5b04d2e8] INFO Core.PETaskEnforcement - EnfProfiles: pl_onIAP_denyping
2018-05-23 05:33:13,114	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Completed PETaskEnforcement **
2018-05-23 05:33:13,114	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Starting PETaskRadiusEnfProfileBuilder **
2018-05-23 05:33:13,114	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Starting PETaskAppEnfProfileBuilder **
2018-05-23 05:33:13,115	[RequestHandler-1-0x7fcc08be5700 h=2431 c=R000000aa-01-5b04d2e8] INFO Core.PETaskRadiusEnfProfileBuilder - EnfProfileAction=ACCEPT
2018-05-23 05:33:13,115	[RequestHandler-1-0x7fcc08be5700 h=2431 c=R000000aa-01-5b04d2e8] INFO Core.PETaskRadiusEnfProfileBuilder - Radius enfProfiles used: pl_onIAP_denyping
2018-05-23 05:33:13,116	[RequestHandler-1-0x7fcc08be5700 h=2431 c=R000000aa-01-5b04d2e8] INFO Core.EnfProfileComputer - getFinalSessionTimeout: sessionTimeout = 0
2018-05-23 05:33:13,117	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Completed PETaskAppEnfProfileBuilder **
2018-05-23 05:33:13,117	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Completed PETaskRadiusEnfProfileBuilder **
2018-05-23 05:33:13,117	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Starting PETaskAuthStatusInfo **
2018-05-23 05:33:13,118	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Starting PETaskOutputPolicyRes **
2018-05-23 05:33:13,118	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Starting PETaskSessionLog **
2018-05-23 05:33:13,124	[RequestHandler-1-0x7fcc08be5700 h=2434 c=R000000aa-01-5b04d2e8] INFO Core.XpipPolicyResHandler - populateResponseTlv: PETaskPostureOutput does not exist. Skip sending posture VAFs
2018-05-23 05:33:13,124	[RequestHandler-1-0x7fcc08be5700 h=2434 c=R000000aa-01-5b04d2e8] INFO Core.XpipPolicyResHandler - populateRadiusTlv: In monitor mode - skip all Radius attributes
2018-05-23 05:33:13,124	[RequestHandler-1-0x7fcc08be5700 h=2434 c=R000000aa-01-5b04d2e8] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2018-05-23 05:33:13,125	[RequestHandler-1-0x7fcc08be5700 h=2433 c=R000000aa-01-5b04d2e8] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2018-05-23 05:33:13,125	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Completed PETaskSessionLog **
2018-05-23 05:33:13,125	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Completed PETaskOutputPolicyRes **
2018-05-23 05:33:13,126	[Th 39 Req 1120 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - Policy Evaluation time = 30 ms
2018-05-23 05:33:13,126	[Th 39 Req 1120 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_policy: Policy Server reply does not contain Posture-Validation-Response
2018-05-23 05:33:13,126	[Th 39 Req 1120 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: Service "PL_homeIAP_8021x_wireless" is in monitor mode
2018-05-23 05:33:13,126	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - ** Completed PETaskAuthStatusInfo **
2018-05-23 05:33:13,126	[RequestHandler-1-0x7fcc08be5700 r=R000000aa-01-5b04d2e8 h=2425 c=R000000aa-01-5b04d2e8] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Completed ***
2018-05-23 05:33:13,127	[Th 39 Req 1120 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 71:125:107b44e80744:AGMAhADMALpgBAAA7wvinMDO+CiA8KeJNfIJEg==
2018-05-23 05:33:13,149	[Th 40 Req 1121 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "PL_homeIAP_8021x_wireless" - 72:289:107b44e80744
2018-05-23 05:33:13,150	[Th 40 Req 1121 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_policy: Bypassing Policy Evaluation.
2018-05-23 05:33:13,150	[Th 40 Req 1121 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_policy: Added Class attribute with value Class = 0xedff5eaf717d46399708c0d1d8ac5931ba0b0000000000005230303030303061612d30312d35623034643265380000000000000000000000
2018-05-23 05:33:13,150	[Th 40 Req 1121 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - rlm_service: Service "PL_homeIAP_8021x_wireless" is in monitor mode
2018-05-23 05:33:13,150	[Th 40 Req 1121 SessId R000000aa-01-5b04d2e8] INFO RadiusServer.Radius - Request processing time = 427 ms