Request log details for session: R000015f2-01-5e53e064
Time Message
2020-02-24 07:40:36,699 [Th 45 Req 171359 SessId R000015f2-01-5e53e064] INFO RadiusServer.Radius - rlm_service: Starting Service Categorization - 248:356:18-66-da-16-91-ea
2020-02-24 07:40:36,707 [RequestHandler-1-0x7f57a33f9700 r=psauto-1581650706-12348 h=223 r=R000015f2-01-5e53e064] INFO Core.ServiceReqHandler - Service classification result = fh_ArubaOS-Switch-MAC
2020-02-24 07:40:36,708 [Th 45 Req 171359 SessId R000015f2-01-5e53e064] INFO RadiusServer.Radius - Service Categorization time = 9 ms
2020-02-24 07:40:36,708 [Th 45 Req 171359 SessId R000015f2-01-5e53e064] INFO RadiusServer.Radius - rlm_service: The request has been categorized into service "fh_ArubaOS-Switch-MAC"
2020-02-24 07:40:36,708 [Th 45 Req 171359 SessId R000015f2-01-5e53e064] INFO RadiusServer.Radius - rlm_sql: searching for user 1866da1691ea in Local:localhost
2020-02-24 07:40:36,710 [Th 45 Req 171359 SessId R000015f2-01-5e53e064] INFO RadiusServer.Radius - rlm_sql: found user 1866da1691ea in Local:localhost
2020-02-24 07:40:36,710 [Th 45 Req 171359 SessId R000015f2-01-5e53e064] INFO RadiusServer.Radius - SQL User lookup time = 2 ms
2020-02-24 07:40:36,710 [Th 45 Req 171359 SessId R000015f2-01-5e53e064] INFO RadiusServer.Radius - rlm_policy: Starting Policy Evaluation.
2020-02-24 07:40:36,715 [RequestHandler-1-0x7f57a33f9700 r=psauto-1581650706-12349 h=239 r=R000015f2-01-5e53e064] INFO Common.EndpointTable - Returning EndpointSPtr for macAddr 1866da1691ea
2020-02-24 07:40:36,715 [RequestHandler-1-0x7f57a33f9700 r=psauto-1581650706-12349 h=239 r=R000015f2-01-5e53e064] INFO Common.TagDefinitionCacheTable - No InstanceTagDefCacheMap found for instance id = 3027 entity id = 29
2020-02-24 07:40:36,715 [RequestHandler-1-0x7f57a33f9700 r=psauto-1581650706-12349 h=239 r=R000015f2-01-5e53e064] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for NAD instance=3027
2020-02-24 07:40:36,715 [RequestHandler-1-0x7f57a33f9700 r=psauto-1581650706-12349 h=239 r=R000015f2-01-5e53e064] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for NAD instanceId=3027|entityId=29
2020-02-24 07:40:36,715 [RequestHandler-1-0x7f57a33f9700 r=psauto-1581650706-12349 h=239 r=R000015f2-01-5e53e064] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=3027|entity=Device
2020-02-24 07:40:36,715 [RequestHandler-1-0x7f57a33f9700 r=psauto-1581650706-12349 h=239 r=R000015f2-01-5e53e064] INFO TAT.AluTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL AuthLocalUser)
2020-02-24 07:40:36,715 [RequestHandler-1-0x7f57a33f9700 r=psauto-1581650706-12349 h=239 r=R000015f2-01-5e53e064] INFO TAT.GuTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL GuestUser)
2020-02-24 07:40:36,715 [RequestHandler-1-0x7f57a33f9700 r=psauto-1581650706-12349 h=239 r=R000015f2-01-5e53e064] INFO Common.TagDefinitionCacheTable - No InstanceTagDefCacheMap found for instance id = 4509 entity id = 72
2020-02-24 07:40:36,715 [RequestHandler-1-0x7f57a33f9700 r=psauto-1581650706-12349 h=239 r=R000015f2-01-5e53e064] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for Endpoint instance=4509
2020-02-24 07:40:36,715 [RequestHandler-1-0x7f57a33f9700 r=psauto-1581650706-12349 h=239 r=R000015f2-01-5e53e064] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for instanceId=4509|entityId=72|entityName=Endpoint
2020-02-24 07:40:36,715 [RequestHandler-1-0x7f57a33f9700 r=psauto-1581650706-12349 h=239 r=R000015f2-01-5e53e064] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=4509|entity=Endpoint
2020-02-24 07:40:36,715 [RequestHandler-1-0x7f57a33f9700 r=psauto-1581650706-12349 h=239 r=R000015f2-01-5e53e064] INFO TAT.OnboardTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Onboard Device User)
2020-02-24 07:40:36,716 [RequestHandler-1-0x7f57a33f9700 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Started ***
2020-02-24 07:40:36,716 [RequestHandler-1-0x7f57a33f9700 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Starting PETaskAuthSourceRestriction **
2020-02-24 07:40:36,716 [RequestHandler-1-0x7f57a33f9700 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Starting PETaskRoleMapping **
2020-02-24 07:40:36,716 [RequestHandler-1-0x7f57a33f9700 h=118961 c=R000015f2-01-5e53e064] WARN REC.EvaluatorCtx - Prerequisites set is empty, not populating the Request Map
2020-02-24 07:40:36,716 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Completed PETaskAuthSourceRestriction **
2020-02-24 07:40:36,718 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118962 c=R000015f2-01-5e53e064] INFO Core.PETaskRoleMapping - Roles: User Authenticated]
2020-02-24 07:40:36,718 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Completed PETaskRoleMapping **
2020-02-24 07:40:36,718 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Starting PETaskPolicyResult **
2020-02-24 07:40:36,718 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Completed PETaskPolicyResult **
2020-02-24 07:40:36,718 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Starting PETaskEnforcement **
2020-02-24 07:40:36,723 [RequestHandler-1-0x7f57a33f9700 h=118965 c=R000015f2-01-5e53e064] INFO Core.PETaskEnforcement - EnfProfiles: fh_vlan113_untrusted
2020-02-24 07:40:36,723 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Completed PETaskEnforcement **
2020-02-24 07:40:36,723 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Starting PETaskRadiusEnfProfileBuilder **
2020-02-24 07:40:36,723 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Starting PETaskRadiusCoAEnfProfileBuilder **
2020-02-24 07:40:36,723 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Starting PETaskAppEnfProfileBuilder **
2020-02-24 07:40:36,723 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Starting PETaskAgentEnfProfileBuilder **
2020-02-24 07:40:36,723 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Starting PETaskPostAuthEnfProfileBuilder **
2020-02-24 07:40:36,723 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Starting PETaskGenericEnfProfileBuilder **
2020-02-24 07:40:36,723 [RequestHandler-1-0x7f57a33f9700 h=118972 c=R000015f2-01-5e53e064] INFO Core.PETaskGenericEnfProfileBuilder - getApplicableProfiles: No App enforcement (Generic) profiles applicable for this device
2020-02-24 07:40:36,724 [RequestHandler-1-0x7f57a33f9700 h=118967 c=R000015f2-01-5e53e064] INFO Core.PETaskRadiusEnfProfileBuilder - EnfProfileAction=ACCEPT
2020-02-24 07:40:36,724 [RequestHandler-1-0x7f57a33f9700 h=118967 c=R000015f2-01-5e53e064] INFO Core.PETaskRadiusEnfProfileBuilder - Radius enfProfiles used: fh_vlan113_untrusted
2020-02-24 07:40:36,724 [RequestHandler-1-0x7f57a33f9700 h=118967 c=R000015f2-01-5e53e064] INFO Core.EnfProfileComputer - getFinalSessionTimeout: sessionTimeout = 10800
2020-02-24 07:40:36,725 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Completed PETaskGenericEnfProfileBuilder **
2020-02-24 07:40:36,725 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Completed PETaskAgentEnfProfileBuilder **
2020-02-24 07:40:36,725 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Completed PETaskAppEnfProfileBuilder **
2020-02-24 07:40:36,725 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Starting PETaskCliEnforcement **
2020-02-24 07:40:36,725 [RequestHandler-1-0x7f57a33f9700 h=118973 c=R000015f2-01-5e53e064] INFO Core.PETaskCliEnforcement - startHandler: No commands for CLI enforcement
2020-02-24 07:40:36,725 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Completed PETaskRadiusEnfProfileBuilder **
2020-02-24 07:40:36,725 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Completed PETaskCliEnforcement **
2020-02-24 07:40:36,726 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118968 c=R000015f2-01-5e53e064] INFO Core.PETaskRadiusCoAEnfProfileBuilder - getApplicableProfiles: No radius_coa enforcement profiles applicable for this device
2020-02-24 07:40:36,727 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118971 c=R000015f2-01-5e53e064] INFO Core.PETaskPostAuthEnfProfileBuilder - getApplicableProfiles: No Post auth enforcement profiles applicable for this device
2020-02-24 07:40:36,727 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Completed PETaskRadiusCoAEnfProfileBuilder **
2020-02-24 07:40:36,727 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Completed PETaskPostAuthEnfProfileBuilder **
2020-02-24 07:40:36,727 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Starting PETaskAuthStatusInfo **
2020-02-24 07:40:36,728 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Starting PETaskMacAuthResetHandler **
2020-02-24 07:40:36,728 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Starting PETaskOutputPolicyRes **
2020-02-24 07:40:36,728 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Starting PETaskSessionLog **
2020-02-24 07:40:36,737 [RequestHandler-1-0x7f57a33f9700 h=118976 c=R000015f2-01-5e53e064] INFO Core.XpipPolicyResHandler - populateResponseTlv: PETaskPostureOutput does not exist. Skip sending posture VAFs
2020-02-24 07:40:36,737 [RequestHandler-1-0x7f57a33f9700 h=118976 c=R000015f2-01-5e53e064] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2020-02-24 07:40:36,737 [RequestHandler-1-0x7f57a33f9700 h=118974 c=R000015f2-01-5e53e064] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2020-02-24 07:40:36,737 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Completed PETaskSessionLog **
2020-02-24 07:40:36,738 [Th 45 Req 171359 SessId R000015f2-01-5e53e064] INFO RadiusServer.Radius - Policy Evaluation time = 28 ms
2020-02-24 07:40:36,738 [Th 45 Req 171359 SessId R000015f2-01-5e53e064] INFO RadiusServer.Radius - rlm_policy: Received Accept Enforcement Profile
2020-02-24 07:40:36,738 [Th 45 Req 171359 SessId R000015f2-01-5e53e064] INFO RadiusServer.Radius - rlm_policy: Added Class attribute with value Class = 0xf7002019f7fb433487225787181757a1c10b0000000000005230303030313566322d30312d35653533653036340000000000000000000000
2020-02-24 07:40:36,738 [Th 45 Req 171359 SessId R000015f2-01-5e53e064] INFO RadiusServer.Radius - rlm_policy: Policy Server reply does not contain Posture-Validation-Response
2020-02-24 07:40:36,738 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Completed PETaskOutputPolicyRes **
2020-02-24 07:40:36,738 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Completed PETaskAuthStatusInfo **
2020-02-24 07:40:36,739 [Th 45 Req 171359 SessId R000015f2-01-5e53e064] INFO RadiusServer.Radius - Request processing time = 40 ms
2020-02-24 07:40:36,739 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118978] ERROR Core.MacAuthSessionQueryEventHandler - Failed to get MacAuth session info for 1866da1691ea
2020-02-24 07:40:36,739 [RequestHandler-1-0x7f57a33f9700 h=118975 c=R000015f2-01-5e53e064] WARN Core.PETaskMacAuthResetHandler - handleMacAuthSessionResponseEv: Error reading MacAuth session info. Error=Failed to get MacAuth session info for 1866da1691ea
2020-02-24 07:40:36,739 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - ** Completed PETaskMacAuthResetHandler **
2020-02-24 07:40:36,739 [RequestHandler-1-0x7f57a33f9700 r=R000015f2-01-5e53e064 h=118960 c=R000015f2-01-5e53e064] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Completed ***
2020-02-24 07:40:51,459 [RequestHandler-1-0x7f57a33f9700 r=R000015f1-01-5e53e064 h=118990 c=R000015f1-01-5e53e064] INFO Core.PETaskPostAuthEnfProfileBuilder - sendPostAuthHTTPRequest: Sending PostAuthEnfRequest {"content":{"auth_source_id":3001,"mac_address":"1866da1691ea","nas_ip":"10.101.5.29","post_auth_actions":{"enf_profile_name":"Update Endpoint Known]","enf_profile_type":"EntityUpdate","params":null}],"user_id":"[removed]"},"id":"R000015f2-01-5e53e064","name":"pactrl_enf_request"}
2020-02-24 07:40:51,497 [RequestHandler-1-0x7f57a33f9700 h=118997] INFO Core.SessionStopReqHandler - handleMacAuthSessionResponseEv: Found valid MAC auth session to remove: MacAuthSessionInfo::<SessionId=R000015f2-01-5e53e064 LocationId=10.101.5.29:33 VLAN=113 Timestamp=1582555236>]