Request log details for session: R000004ea-01-5c204978
Time	Message
2018-12-24 02:50:32,223	[Th 8 Req 1410 SessId R000004ea-01-5c204978] INFO RadiusServer.Radius - rlm_service: Starting Service Categorization - 132:159:00-00-06-00-00-07
2018-12-24 02:50:32,228	[RequestHandler-1-0x7fb6c97eb700 r=psauto-1545386720-2517 h=79 r=R000004ea-01-5c204978] INFO Core.ServiceReqHandler - Service classification result = Pica MAB
2018-12-24 02:50:32,229	[Th 8 Req 1410 SessId R000004ea-01-5c204978] INFO RadiusServer.Radius - Service Categorization time = 6 ms
2018-12-24 02:50:32,229	[Th 8 Req 1410 SessId R000004ea-01-5c204978] INFO RadiusServer.Radius - rlm_service: The request has been categorized into service "Pica MAB"
2018-12-24 02:50:32,229	[Th 8 Req 1410 SessId R000004ea-01-5c204978] INFO RadiusServer.Radius - rlm_sql: searching for user 00:00:06:00:00:07 in Local:localhost
2018-12-24 02:50:32,231	[Th 8 Req 1410 SessId R000004ea-01-5c204978] INFO RadiusServer.Radius - rlm_sql: found user 00:00:06:00:00:07 in Local:localhost
2018-12-24 02:50:32,231	[Th 8 Req 1410 SessId R000004ea-01-5c204978] INFO RadiusServer.Radius - SQL User lookup time = 2 ms
2018-12-24 02:50:32,231	[Th 8 Req 1410 SessId R000004ea-01-5c204978] INFO RadiusServer.Radius - rlm_policy: Starting Policy Evaluation.
2018-12-24 02:50:32,233	[RequestHandler-1-0x7fb6c97eb700 r=psauto-1545386720-2518 h=83 r=R000004ea-01-5c204978] INFO Common.EndpointTable - Returning EndpointSPtr for macAddr 000006000007
2018-12-24 02:50:32,234	[RequestHandler-1-0x7fb6c97eb700 r=psauto-1545386720-2518 h=83 r=R000004ea-01-5c204978] INFO Common.TagDefinitionCacheTable - No InstanceTagDefCacheMap found for instance id = 3001 entity id = 29
2018-12-24 02:50:32,234	[RequestHandler-1-0x7fb6c97eb700 r=psauto-1545386720-2518 h=83 r=R000004ea-01-5c204978] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for NAD instance=3001
2018-12-24 02:50:32,234	[RequestHandler-1-0x7fb6c97eb700 r=psauto-1545386720-2518 h=83 r=R000004ea-01-5c204978] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for NAD instanceId=3001|entityId=29
2018-12-24 02:50:32,234	[RequestHandler-1-0x7fb6c97eb700 r=psauto-1545386720-2518 h=83 r=R000004ea-01-5c204978] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=3001|entity=Device
2018-12-24 02:50:32,234	[RequestHandler-1-0x7fb6c97eb700 r=psauto-1545386720-2518 h=83 r=R000004ea-01-5c204978] INFO TAT.AluTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL AuthLocalUser)
2018-12-24 02:50:32,234	[RequestHandler-1-0x7fb6c97eb700 r=psauto-1545386720-2518 h=83 r=R000004ea-01-5c204978] INFO TAT.GuTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL GuestUser)
2018-12-24 02:50:32,234	[RequestHandler-1-0x7fb6c97eb700 r=psauto-1545386720-2518 h=83 r=R000004ea-01-5c204978] INFO Common.TagDefinitionCacheTable - No TagDefCacheMap could be found for instance id = 3014 entity id = 72
2018-12-24 02:50:32,234	[RequestHandler-1-0x7fb6c97eb700 r=psauto-1545386720-2518 h=83 r=R000004ea-01-5c204978] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for Endpoint instance=3014
2018-12-24 02:50:32,234	[RequestHandler-1-0x7fb6c97eb700 r=psauto-1545386720-2518 h=83 r=R000004ea-01-5c204978] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for instanceId=3014|entityId=72|entityName=Endpoint
2018-12-24 02:50:32,234	[RequestHandler-1-0x7fb6c97eb700 r=psauto-1545386720-2518 h=83 r=R000004ea-01-5c204978] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=3014|entity=Endpoint
2018-12-24 02:50:32,234	[RequestHandler-1-0x7fb6c97eb700 r=psauto-1545386720-2518 h=83 r=R000004ea-01-5c204978] INFO TAT.OnboardTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Onboard Device User)
2018-12-24 02:50:32,234	[RequestHandler-1-0x7fb6c97eb700 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Started ***
2018-12-24 02:50:32,234	[RequestHandler-1-0x7fb6c97eb700 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskAudit **
2018-12-24 02:50:32,234	[RequestHandler-1-0x7fb6c97eb700 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskAuthSourceRestriction **
2018-12-24 02:50:32,235	[RequestHandler-1-0x7fb6c97eb700 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskRoleMapping **
2018-12-24 02:50:32,235	[RequestHandler-1-0x7fb6c97eb700 h=26710 c=R000004ea-01-5c204978] WARN REC.EvaluatorCtx - Prerequisites set is empty, not populating the Request Map
2018-12-24 02:50:32,236	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskAuthSourceRestriction **
2018-12-24 02:50:32,237	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26711 c=R000004ea-01-5c204978] INFO Core.PETaskRoleMapping - Roles: Pica8-Employees, User Authenticated]
2018-12-24 02:50:32,237	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskRoleMapping **
2018-12-24 02:50:32,242	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26709 c=R000004ea-01-5c204978] INFO Core.PETaskAudit - populateResCollectorAndTerminate: auditStatus=AUDIT_INPROGRESS spt=15 timeout=180 message=
2018-12-24 02:50:32,242	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26709 c=R000004ea-01-5c204978] INFO Core.PolicyResCollector - updateSpt: SPT set to: TRANSITION force=0
2018-12-24 02:50:32,242	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26709 c=R000004ea-01-5c204978] INFO Core.PolicyResCollector - updateAuditApt: AuditAPT set to TRANSITION
2018-12-24 02:50:32,243	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskAudit **
2018-12-24 02:50:32,243	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskPolicyResult **
2018-12-24 02:50:32,243	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskPolicyResult **
2018-12-24 02:50:32,243	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskEnforcement **
2018-12-24 02:50:32,244	[RequestHandler-1-0x7fb6c97eb700 h=26715 c=R000004ea-01-5c204978] INFO Core.PETaskEnforcement - EnfProfiles: VLAN 999
2018-12-24 02:50:32,244	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskEnforcement **
2018-12-24 02:50:32,244	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskRadiusEnfProfileBuilder **
2018-12-24 02:50:32,244	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskRadiusCoAEnfProfileBuilder **
2018-12-24 02:50:32,244	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskAppEnfProfileBuilder **
2018-12-24 02:50:32,244	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskAgentEnfProfileBuilder **
2018-12-24 02:50:32,245	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskPostAuthEnfProfileBuilder **
2018-12-24 02:50:32,245	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskGenericEnfProfileBuilder **
2018-12-24 02:50:32,245	[RequestHandler-1-0x7fb6c97eb700 h=26721 c=R000004ea-01-5c204978] INFO Core.PETaskGenericEnfProfileBuilder - getApplicableProfiles: No App enforcement (Generic) profiles applicable for this device
2018-12-24 02:50:32,245	[RequestHandler-1-0x7fb6c97eb700 h=26716 c=R000004ea-01-5c204978] INFO Core.PETaskRadiusEnfProfileBuilder - EnfProfileAction=ACCEPT
2018-12-24 02:50:32,245	[RequestHandler-1-0x7fb6c97eb700 h=26716 c=R000004ea-01-5c204978] INFO Core.PETaskRadiusEnfProfileBuilder - Radius enfProfiles used: VLAN 999
2018-12-24 02:50:32,245	[RequestHandler-1-0x7fb6c97eb700 h=26716 c=R000004ea-01-5c204978] INFO Core.EnfProfileComputer - getFinalSessionTimeout: sessionTimeout = 180
2018-12-24 02:50:32,246	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskGenericEnfProfileBuilder **
2018-12-24 02:50:32,246	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskAgentEnfProfileBuilder **
2018-12-24 02:50:32,246	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskAppEnfProfileBuilder **
2018-12-24 02:50:32,246	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskCliEnforcement **
2018-12-24 02:50:32,247	[RequestHandler-1-0x7fb6c97eb700 h=26722 c=R000004ea-01-5c204978] INFO Core.PETaskCliEnforcement - startHandler: No commands for CLI enforcement
2018-12-24 02:50:32,247	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskRadiusEnfProfileBuilder **
2018-12-24 02:50:32,247	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskCliEnforcement **
2018-12-24 02:50:32,247	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26720 c=R000004ea-01-5c204978] INFO Core.PETaskPostAuthEnfProfileBuilder - getApplicableProfiles: No Post auth enforcement profiles applicable for this device
2018-12-24 02:50:32,248	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26717 c=R000004ea-01-5c204978] INFO Core.PETaskRadiusCoAEnfProfileBuilder - getApplicableProfiles: No radius_coa enforcement profiles applicable for this device
2018-12-24 02:50:32,248	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskPostAuthEnfProfileBuilder **
2018-12-24 02:50:32,248	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskRadiusCoAEnfProfileBuilder **
2018-12-24 02:50:32,248	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskAuthStatusInfo **
2018-12-24 02:50:32,248	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskMacAuthResetHandler **
2018-12-24 02:50:32,248	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskOutputPolicyRes **
2018-12-24 02:50:32,249	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Starting PETaskSessionLog **
2018-12-24 02:50:32,253	[RequestHandler-1-0x7fb6c97eb700 h=26725 c=R000004ea-01-5c204978] INFO Core.XpipPolicyResHandler - populateResponseTlv: PETaskPostureOutput does not exist. Skip sending posture VAFs
2018-12-24 02:50:32,253	[RequestHandler-1-0x7fb6c97eb700 h=26725 c=R000004ea-01-5c204978] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2018-12-24 02:50:32,254	[RequestHandler-1-0x7fb6c97eb700 h=26723 c=R000004ea-01-5c204978] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2018-12-24 02:50:32,254	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskSessionLog **
2018-12-24 02:50:32,254	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskOutputPolicyRes **
2018-12-24 02:50:32,254	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskAuthStatusInfo **
2018-12-24 02:50:32,255	[Th 8 Req 1410 SessId R000004ea-01-5c204978] INFO RadiusServer.Radius - Policy Evaluation time = 24 ms
2018-12-24 02:50:32,255	[Th 8 Req 1410 SessId R000004ea-01-5c204978] INFO RadiusServer.Radius - rlm_policy: Received Accept Enforcement Profile
2018-12-24 02:50:32,255	[Th 8 Req 1410 SessId R000004ea-01-5c204978] INFO RadiusServer.Radius - rlm_policy: Added Class attribute with value Class = 0xe9ec367f262947c78d461b9fa8ec183abb0b0000000000005230303030303465612d30312d35633230343937380000000000000000000000
2018-12-24 02:50:32,255	[Th 8 Req 1410 SessId R000004ea-01-5c204978] INFO RadiusServer.Radius - rlm_policy: Policy Server reply does not contain Posture-Validation-Response
2018-12-24 02:50:32,255	[Th 8 Req 1410 SessId R000004ea-01-5c204978] INFO RadiusServer.Radius - Request processing time = 32 ms
2018-12-24 02:50:32,256	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - ** Completed PETaskMacAuthResetHandler **
2018-12-24 02:50:32,256	[RequestHandler-1-0x7fb6c97eb700 r=R000004ea-01-5c204978 h=26708 c=R000004ea-01-5c204978] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Completed ***