Request log details for session: R001ccd9e-01-5e4c0b61
Time	Message
2020-02-18 16:05:53,713	[Th 189 Req 17876372 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_service: Starting Service Categorization - 73:369:11-22-33-44-55-66
2020-02-18 16:05:53,718	[RequestHandler-1-0x7f5f28be5700 r=psauto-1570860243-2374529 h=223 r=R001ccd9e-01-5e4c0b61] INFO Core.ServiceReqHandler - Service classification result = CUSTOMER Wired Access 802.1X Wired
2020-02-18 16:05:53,719	[Th 189 Req 17876372 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - Service Categorization time = 5 ms
2020-02-18 16:05:53,719	[Th 189 Req 17876372 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_service: The request has been categorized into service "CUSTOMER Wired Access 802.1X Wired"
2020-02-18 16:05:53,719	[Th 189 Req 17876372 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_ldap: searching for user CP-8831-SEPAC44F212B816 in AD:1.1.1.1
2020-02-18 16:05:53,720	[Th 189 Req 17876372 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_ldap: searching for user CP-8831-SEPAC44F212B816 in AD:1.1.1.2
2020-02-18 16:05:53,728	[Th 189 Req 17876372 SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - rlm_ldap: could not start TLS Connect error
2020-02-18 16:05:53,728	[Th 189 Req 17876372 SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - rlm_ldap: (re)connection attempt failed
2020-02-18 16:05:53,728	[Th 189 Req 17876372 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_ldap: searching for user CP-8831-SEPAC44F212B816 in AD:1.1.1.3
2020-02-18 16:05:53,737	[Th 189 Req 17876372 SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - rlm_ldap: could not start TLS Connect error
2020-02-18 16:05:53,737	[Th 189 Req 17876372 SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - rlm_ldap: (re)connection attempt failed
2020-02-18 16:05:53,737	[Th 189 Req 17876372 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_eap_peap: Initiate
2020-02-18 16:05:53,737	[Th 189 Req 17876372 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 73:88:11-22-33-44-55-66:AIcAdgA/AEeUxRABVsE+JHR5X5u8qiBXn7iddw==
2020-02-18 16:05:53,739	[Th 194 Req 17876373 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "CUSTOMER Wired Access 802.1X Wired" - 74:390:11-22-33-44-55-66
2020-02-18 16:05:53,739	[Th 194 Req 17876373 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_ldap: searching for user CP-8831-SEPAC44F212B816 in AD:1.1.1.1
2020-02-18 16:05:53,740	[Th 194 Req 17876373 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_ldap: searching for user CP-8831-SEPAC44F212B816 in AD:1.1.1.2
2020-02-18 16:05:53,748	[Th 194 Req 17876373 SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - rlm_ldap: could not start TLS Connect error
2020-02-18 16:05:53,748	[Th 194 Req 17876373 SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - rlm_ldap: (re)connection attempt failed
2020-02-18 16:05:53,748	[Th 194 Req 17876373 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_ldap: searching for user CP-8831-SEPAC44F212B816 in AD:1.1.1.3
2020-02-18 16:05:53,756	[Th 194 Req 17876373 SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - rlm_ldap: could not start TLS Connect error
2020-02-18 16:05:53,756	[Th 194 Req 17876373 SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - rlm_ldap: (re)connection attempt failed
2020-02-18 16:05:53,756	[Th 194 Req 17876373 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_eap_fast: Initiate
2020-02-18 16:05:53,756	[Th 194 Req 17876373 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 74:108:11-22-33-44-55-66:AAoA9wDhAISVxRABBZiU71OhAPAeXfBkZa8IhQ==
2020-02-18 16:05:53,893	[Th 192 Req 17876374 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "CUSTOMER Wired Access 802.1X Wired" - 75:454:11-22-33-44-55-66
2020-02-18 16:05:53,893	[Th 192 Req 17876374 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_ldap: searching for user CP-8831-SEPAC44F212B816 in AD:1.1.1.1
2020-02-18 16:05:53,894	[Th 192 Req 17876374 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_ldap: searching for user CP-8831-SEPAC44F212B816 in AD:1.1.1.2
2020-02-18 16:05:53,901	[Th 192 Req 17876374 SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - rlm_ldap: could not start TLS Connect error
2020-02-18 16:05:53,901	[Th 192 Req 17876374 SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - rlm_ldap: (re)connection attempt failed
2020-02-18 16:05:53,901	[Th 192 Req 17876374 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_ldap: searching for user CP-8831-SEPAC44F212B816 in AD:1.1.1.3
2020-02-18 16:05:53,909	[Th 192 Req 17876374 SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - rlm_ldap: could not start TLS Connect error
2020-02-18 16:05:53,910	[Th 192 Req 17876374 SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - rlm_ldap: (re)connection attempt failed
2020-02-18 16:05:53,910	[Th 192 Req 17876374 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read client key exchange A
2020-02-18 16:05:53,910	[Th 192 Req 17876374 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read client key exchange A
2020-02-18 16:05:53,910	[Th 192 Req 17876374 SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 75:1124:11-22-33-44-55-66:ADkAbwCvAOGWxRABXa/cWhiAwiDkIvPbyXgLZw==
2020-02-18 16:06:41,994	[main SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - reqst_clean_list: Deleting request sessid - R001ccd9e-01-5e4c0b61, state - ADkAbwCvAOGWxRABXa/cWhiAwiDkIvPbyXgLZw=
2020-02-18 16:06:41,994	[main SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - reqst_clean_list: Packet 73:369:88:11-22-33-44-55-66 recv 1582041953.713679 - resp 1582041953.737456
2020-02-18 16:06:41,994	[main SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - reqst_clean_list: Packet 74:390:108:11-22-33-44-55-66 recv 1582041953.739496 - resp 1582041953.756682
2020-02-18 16:06:41,994	[main SessId R001ccd9e-01-5e4c0b61] ERROR RadiusServer.Radius - reqst_clean_list: Packet 75:454:1124:11-22-33-44-55-66 recv 1582041953.893191 - resp 1582041953.910605
2020-02-18 16:06:41,995	[main SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_policy: Starting Policy Evaluation.
2020-02-18 16:06:41,998	[RequestHandler-1-0x7f5f28be5700 r=psauto-1570860243-2374563 h=239 r=R001ccd9e-01-5e4c0b61] INFO Common.EndpointTable - Returning NULL (EndpointPtr) for macAddr ac44f212b816
2020-02-18 16:06:41,998	[RequestHandler-1-0x7f5f28be5700 r=psauto-1570860243-2374563 h=239 r=R001ccd9e-01-5e4c0b61] INFO Common.TagDefinitionCacheTable - No InstanceTagDefCacheMap found for instance id = 3004 entity id = 29
2020-02-18 16:06:41,998	[RequestHandler-1-0x7f5f28be5700 r=psauto-1570860243-2374563 h=239 r=R001ccd9e-01-5e4c0b61] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for NAD instance=3004
2020-02-18 16:06:41,998	[RequestHandler-1-0x7f5f28be5700 r=psauto-1570860243-2374563 h=239 r=R001ccd9e-01-5e4c0b61] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for NAD instanceId=3004|entityId=29
2020-02-18 16:06:41,998	[RequestHandler-1-0x7f5f28be5700 r=psauto-1570860243-2374563 h=239 r=R001ccd9e-01-5e4c0b61] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=3004|entity=Device
2020-02-18 16:06:41,998	[RequestHandler-1-0x7f5f28be5700 r=psauto-1570860243-2374563 h=239 r=R001ccd9e-01-5e4c0b61] INFO TAT.AluTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL AuthLocalUser)
2020-02-18 16:06:41,998	[RequestHandler-1-0x7f5f28be5700 r=psauto-1570860243-2374563 h=239 r=R001ccd9e-01-5e4c0b61] INFO TAT.GuTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL GuestUser)
2020-02-18 16:06:41,998	[RequestHandler-1-0x7f5f28be5700 r=psauto-1570860243-2374563 h=239 r=R001ccd9e-01-5e4c0b61] INFO TAT.EndpointTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Endpoint)
2020-02-18 16:06:41,998	[RequestHandler-1-0x7f5f28be5700 r=psauto-1570860243-2374563 h=239 r=R001ccd9e-01-5e4c0b61] INFO TAT.OnboardTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Onboard Device User)
2020-02-18 16:06:41,999	[RequestHandler-1-0x7f5f28be5700 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Started ***
2020-02-18 16:06:41,999	[RequestHandler-1-0x7f5f28be5700 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Starting PETaskAuthSourceRestriction **
2020-02-18 16:06:41,999	[RequestHandler-1-0x7f5f28be5700 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Starting PETaskRoleMapping **
2020-02-18 16:06:41,999	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Completed PETaskAuthSourceRestriction **
2020-02-18 16:06:41,999	[RequestHandler-1-0x7f5f28be5700 h=21342067 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskRoleMapping - Roles:
2020-02-18 16:06:41,999	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Completed PETaskRoleMapping **
2020-02-18 16:06:42,000	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Starting PETaskPolicyResult **
2020-02-18 16:06:42,000	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Completed PETaskPolicyResult **
2020-02-18 16:06:42,000	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Starting PETaskEnforcement **
2020-02-18 16:06:42,003	[RequestHandler-1-0x7f5f28be5700 h=21342070 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskEnforcement - EnfProfiles: CUSTOMER Wired Access 802.1X Wired Default Profile
2020-02-18 16:06:42,003	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Completed PETaskEnforcement **
2020-02-18 16:06:42,003	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Starting PETaskRadiusEnfProfileBuilder **
2020-02-18 16:06:42,003	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Starting PETaskRadiusCoAEnfProfileBuilder **
2020-02-18 16:06:42,003	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Starting PETaskAppEnfProfileBuilder **
2020-02-18 16:06:42,003	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Starting PETaskAgentEnfProfileBuilder **
2020-02-18 16:06:42,003	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Starting PETaskPostAuthEnfProfileBuilder **
2020-02-18 16:06:42,003	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Starting PETaskGenericEnfProfileBuilder **
2020-02-18 16:06:42,004	[RequestHandler-1-0x7f5f28be5700 h=21342077 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskGenericEnfProfileBuilder - getApplicableProfiles: No App enforcement (Generic) profiles applicable for this device
2020-02-18 16:06:42,004	[RequestHandler-1-0x7f5f28be5700 h=21342072 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskRadiusEnfProfileBuilder - EnfProfileAction=ACCEPT
2020-02-18 16:06:42,004	[RequestHandler-1-0x7f5f28be5700 h=21342072 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskRadiusEnfProfileBuilder - Radius enfProfiles used: CUSTOMER Wired Access 802.1X Wired Default Profile
2020-02-18 16:06:42,004	[RequestHandler-1-0x7f5f28be5700 h=21342072 c=R001ccd9e-01-5e4c0b61] INFO Core.EnfProfileComputer - getFinalSessionTimeout: sessionTimeout = 0
2020-02-18 16:06:42,004	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Completed PETaskGenericEnfProfileBuilder **
2020-02-18 16:06:42,004	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Completed PETaskAgentEnfProfileBuilder **
2020-02-18 16:06:42,004	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Completed PETaskAppEnfProfileBuilder **
2020-02-18 16:06:42,005	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Starting PETaskCliEnforcement **
2020-02-18 16:06:42,005	[RequestHandler-1-0x7f5f28be5700 h=21342078 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskCliEnforcement - startHandler: No commands for CLI enforcement
2020-02-18 16:06:42,005	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Completed PETaskRadiusEnfProfileBuilder **
2020-02-18 16:06:42,005	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Completed PETaskCliEnforcement **
2020-02-18 16:06:42,006	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342073 c=R001ccd9e-01-5e4c0b61] WARN Core.PETaskRadiusCoAEnfProfileBuilder - handleHttpResponseEv: Fetching Radius attributes from battery failed, errMsg=
2020-02-18 16:06:42,006	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Completed PETaskRadiusCoAEnfProfileBuilder **
2020-02-18 16:06:42,006	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342076 c=R001ccd9e-01-5e4c0b61] WARN Core.PETaskPostAuthEnfProfileBuilder - handleHttpResponseEv: Fetching Radius attributes from battery failed, errMsg=
2020-02-18 16:06:42,006	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342076 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskPostAuthEnfProfileBuilder - getApplicableProfiles: No Post auth enforcement profiles applicable for this device
2020-02-18 16:06:42,006	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Completed PETaskPostAuthEnfProfileBuilder **
2020-02-18 16:06:42,006	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Starting PETaskAuthStatusInfo **
2020-02-18 16:06:42,006	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Starting PETaskOutputPolicyRes **
2020-02-18 16:06:42,006	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Starting PETaskSessionLog **
2020-02-18 16:06:42,011	[RequestHandler-1-0x7f5f28be5700 h=21342080 c=R001ccd9e-01-5e4c0b61] INFO Core.XpipPolicyResHandler - populateResponseTlv: PETaskPostureOutput does not exist. Skip sending posture VAFs
2020-02-18 16:06:42,012	[main SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - Policy Evaluation time = 17 ms
2020-02-18 16:06:42,012	[main SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_policy: Received Accept Enforcement Profile
2020-02-18 16:06:42,012	[main SessId R001ccd9e-01-5e4c0b61] INFO RadiusServer.Radius - rlm_policy: Policy Server reply does not contain Posture-Validation-Response
2020-02-18 16:06:42,012	[RequestHandler-1-0x7f5f28be5700 h=21342080 c=R001ccd9e-01-5e4c0b61] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2020-02-18 16:06:42,012	[RequestHandler-1-0x7f5f28be5700 h=21342079 c=R001ccd9e-01-5e4c0b61] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2020-02-18 16:06:42,012	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Completed PETaskSessionLog **
2020-02-18 16:06:42,012	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Completed PETaskOutputPolicyRes **
2020-02-18 16:06:42,012	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - ** Completed PETaskAuthStatusInfo **
2020-02-18 16:06:42,012	[RequestHandler-1-0x7f5f28be5700 r=R001ccd9e-01-5e4c0b61 h=21342065 c=R001ccd9e-01-5e4c0b61] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Completed ***