Request log details for session: R000000cb-01-58c994c7 Time Message 2017-03-15 16:23:51,253 [Th 40 Req 1385 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_service: Starting Service Categorization - 22:225:D4-F4-6F-A1-E9-7C 2017-03-15 16:23:51,258 [RequestHandler-1-0x7f25439fc700 r=psauto-1489533848-468 h=223 r=R000000cb-01-58c994c7] INFO Core.ServiceReqHandler - Service classification result = LAB 802.1X Wireless with AD 2017-03-15 16:23:51,259 [Th 40 Req 1385 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - Service Categorization time = 6 ms 2017-03-15 16:23:51,259 [Th 40 Req 1385 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_service: The request has been categorized into service "LAB 802.1X Wireless with AD" 2017-03-15 16:23:51,260 [Th 40 Req 1385 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_eap_peap: Initiate 2017-03-15 16:23:51,260 [Th 40 Req 1385 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 22:88:D4-F4-6F-A1-E9-7C:AEUACQAyAMhpBQAAMPsN0tZ+ZUnsdbC9uazcPw== 2017-03-15 16:23:51,363 [Th 36 Req 1386 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "LAB 802.1X Wireless with AD" - 23:378:D4-F4-6F-A1-E9-7C 2017-03-15 16:23:51,366 [Th 36 Req 1386 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read client key exchange A 2017-03-15 16:23:51,366 [Th 36 Req 1386 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read client key exchange A 2017-03-15 16:23:51,366 [Th 36 Req 1386 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 23:1124:D4-F4-6F-A1-E9-7C:AEoAUgAHAJZqBQAAejdCDeqipEzmPFKFq7aoow== 2017-03-15 16:23:51,471 [Th 38 Req 1387 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "LAB 802.1X Wireless with AD" - 24:257:D4-F4-6F-A1-E9-7C 2017-03-15 16:23:51,471 [Th 38 Req 1387 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 24:339:D4-F4-6F-A1-E9-7C:AG8AIAA0AD9rBQAADq3vFyCuq7B8szdxkN1A7w== 2017-03-15 16:23:51,611 [Th 39 Req 1388 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "LAB 802.1X Wireless with AD" - 25:395:D4-F4-6F-A1-E9-7C 2017-03-15 16:23:51,612 [Th 39 Req 1388 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 25:151:D4-F4-6F-A1-E9-7C:AOgA7gDJAH1sBQAAAPQGVulgNK4jJeBje2J44w== 2017-03-15 16:23:51,710 [Th 37 Req 1389 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "LAB 802.1X Wireless with AD" - 26:257:D4-F4-6F-A1-E9-7C 2017-03-15 16:23:51,710 [Th 37 Req 1389 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_eap_peap: Session established. 2017-03-15 16:23:51,710 [Th 37 Req 1389 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 26:125:D4-F4-6F-A1-E9-7C:AAsAQgAAACdtBQAA6Jq3pnpMpJkqsW2FGqoz1w== 2017-03-15 16:23:51,786 [Th 40 Req 1390 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "LAB 802.1X Wireless with AD" - 27:310:D4-F4-6F-A1-E9-7C 2017-03-15 16:23:51,786 [Th 40 Req 1390 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_ldap: searching for user liveconsult in AD:SRV-DC01.lab.local 2017-03-15 16:23:51,800 [Th 40 Req 1390 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_ldap: found user liveconsult in AD:SRV-DC01.lab.local 2017-03-15 16:23:51,800 [Th 40 Req 1390 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - LDAP/AD User lookup time = 14 ms 2017-03-15 16:23:51,800 [Th 40 Req 1390 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_eap_mschapv2: Issuing Challenge 2017-03-15 16:23:51,801 [Th 40 Req 1390 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 27:157:D4-F4-6F-A1-E9-7C:AJcA9gA7AHBuBQAAUbnwzW6ijXWFr+zluamCWQ== 2017-03-15 16:23:51,877 [Th 36 Req 1391 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "LAB 802.1X Wireless with AD" - 28:358:D4-F4-6F-A1-E9-7C 2017-03-15 16:23:51,878 [Th 36 Req 1391 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "LAB 802.1X Wireless with AD" - 111:0:D4-F4-6F-A1-E9-7C 2017-03-15 16:23:51,878 [Th 36 Req 1391 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_eap_mschapv2: Received MSCHAPv2 Response from client 2017-03-15 16:23:51,878 [Th 36 Req 1391 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_mschap: MSCHAPv2 username used for challenge computation liveconsult 2017-03-15 16:23:51,878 [Th 36 Req 1391 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_mschap: Using domain LAB from objectSid attribute 2017-03-15 16:23:51,878 [Th 36 Req 1391 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_mschap: authenticating user liveconsult, domain LAB 2017-03-15 16:23:51,889 [Th 36 Req 1391 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_mschap: user liveconsult authenticated successfully 2017-03-15 16:23:51,889 [Th 36 Req 1391 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - MS-Chap User Authentication time = 11 ms 2017-03-15 16:23:51,889 [Th 36 Req 1391 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_eap_mschapv2: Sending MSCHAPv2 Success reply 2017-03-15 16:23:51,890 [Th 36 Req 1391 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 28:173:D4-F4-6F-A1-E9-7C:AFgA9wCiAJJvBQAA+mrxM/3yfIakdQ0WRl2TWg== 2017-03-15 16:23:52,019 [Th 38 Req 1392 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "LAB 802.1X Wireless with AD" - 29:294:D4-F4-6F-A1-E9-7C 2017-03-15 16:23:52,019 [Th 38 Req 1392 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "LAB 802.1X Wireless with AD" - 112:0:D4-F4-6F-A1-E9-7C 2017-03-15 16:23:52,019 [Th 38 Req 1392 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_eap_mschapv2: Received MSCHAPv2 Success from client 2017-03-15 16:23:52,019 [Th 38 Req 1392 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_policy: Starting Policy Evaluation. 2017-03-15 16:23:52,023 [RequestHandler-1-0x7f25439fc700 r=psauto-1489533848-469 h=239 r=R000000cb-01-58c994c7] INFO Common.EndpointTable - Returning EndpointSPtr for macAddr d4f46fa1e97c 2017-03-15 16:23:52,023 [RequestHandler-1-0x7f25439fc700 r=psauto-1489533848-469 h=239 r=R000000cb-01-58c994c7] INFO Common.TagDefinitionCacheTable - No InstanceTagDefCacheMap found for instance id = 3003 entity id = 29 2017-03-15 16:23:52,023 [RequestHandler-1-0x7f25439fc700 r=psauto-1489533848-469 h=239 r=R000000cb-01-58c994c7] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for NAD instance=3003 2017-03-15 16:23:52,023 [RequestHandler-1-0x7f25439fc700 r=psauto-1489533848-469 h=239 r=R000000cb-01-58c994c7] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for NAD instanceId=3003|entityId=29 2017-03-15 16:23:52,023 [RequestHandler-1-0x7f25439fc700 r=psauto-1489533848-469 h=239 r=R000000cb-01-58c994c7] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=3003|entity=Device 2017-03-15 16:23:52,023 [RequestHandler-1-0x7f25439fc700 r=psauto-1489533848-469 h=239 r=R000000cb-01-58c994c7] INFO TAT.AluTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL AuthLocalUser) 2017-03-15 16:23:52,023 [RequestHandler-1-0x7f25439fc700 r=psauto-1489533848-469 h=239 r=R000000cb-01-58c994c7] INFO TAT.GuTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL GuestUser) 2017-03-15 16:23:52,023 [RequestHandler-1-0x7f25439fc700 r=psauto-1489533848-469 h=239 r=R000000cb-01-58c994c7] INFO TAT.OnboardTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Onboard Device User) 2017-03-15 16:23:52,023 [RequestHandler-1-0x7f25439fc700 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Started *** 2017-03-15 16:23:52,023 [RequestHandler-1-0x7f25439fc700 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Starting PETaskAuthSourceRestriction ** 2017-03-15 16:23:52,023 [RequestHandler-1-0x7f25439fc700 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Starting PETaskRoleMapping ** 2017-03-15 16:23:52,024 [RequestHandler-1-0x7f25439fc700 h=4265 c=R000000cb-01-58c994c7] WARN REC.EvaluatorCtx - Prerequisites set is empty, not populating the Request Map 2017-03-15 16:23:52,024 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Completed PETaskAuthSourceRestriction ** 2017-03-15 16:23:52,026 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4266 c=R000000cb-01-58c994c7] INFO Core.PETaskRoleMapping - Roles: User Authenticated] 2017-03-15 16:23:52,026 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Completed PETaskRoleMapping ** 2017-03-15 16:23:52,026 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Starting PETaskPolicyResult ** 2017-03-15 16:23:52,027 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Completed PETaskPolicyResult ** 2017-03-15 16:23:52,027 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Starting PETaskEnforcement ** 2017-03-15 16:23:52,027 [RequestHandler-1-0x7f25439fc700 h=4269 c=R000000cb-01-58c994c7] INFO Core.PETaskEnforcement - EnfProfiles: Allow Access Profile] 2017-03-15 16:23:52,028 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Completed PETaskEnforcement ** 2017-03-15 16:23:52,028 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Starting PETaskRadiusEnfProfileBuilder ** 2017-03-15 16:23:52,028 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Starting PETaskRadiusCoAEnfProfileBuilder ** 2017-03-15 16:23:52,028 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Starting PETaskAppEnfProfileBuilder ** 2017-03-15 16:23:52,028 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Starting PETaskPostAuthEnfProfileBuilder ** 2017-03-15 16:23:52,028 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Starting PETaskGenericEnfProfileBuilder ** 2017-03-15 16:23:52,028 [RequestHandler-1-0x7f25439fc700 h=4274 c=R000000cb-01-58c994c7] INFO Core.PETaskGenericEnfProfileBuilder - getApplicableProfiles: No App enforcement (Generic) profiles applicable for this device 2017-03-15 16:23:52,029 [RequestHandler-1-0x7f25439fc700 h=4270 c=R000000cb-01-58c994c7] INFO Core.PETaskRadiusEnfProfileBuilder - EnfProfileAction=ACCEPT 2017-03-15 16:23:52,029 [RequestHandler-1-0x7f25439fc700 h=4270 c=R000000cb-01-58c994c7] INFO Core.PETaskRadiusEnfProfileBuilder - Radius enfProfiles used: Allow Access Profile] 2017-03-15 16:23:52,029 [RequestHandler-1-0x7f25439fc700 h=4270 c=R000000cb-01-58c994c7] INFO Core.EnfProfileComputer - getFinalSessionTimeout: sessionTimeout = 0 2017-03-15 16:23:52,030 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Completed PETaskGenericEnfProfileBuilder ** 2017-03-15 16:23:52,030 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Completed PETaskAppEnfProfileBuilder ** 2017-03-15 16:23:52,030 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Starting PETaskCliEnforcement ** 2017-03-15 16:23:52,030 [RequestHandler-1-0x7f25439fc700 h=4275 c=R000000cb-01-58c994c7] INFO Core.PETaskCliEnforcement - startHandler: No commands for CLI enforcement 2017-03-15 16:23:52,030 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4271 c=R000000cb-01-58c994c7] INFO Core.PETaskRadiusCoAEnfProfileBuilder - getApplicableProfiles: No radius_coa enforcement profiles applicable for this device 2017-03-15 16:23:52,030 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4273 c=R000000cb-01-58c994c7] INFO Core.PETaskPostAuthEnfProfileBuilder - getApplicableProfiles: No Post auth enforcement profiles applicable for this device 2017-03-15 16:23:52,030 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Completed PETaskRadiusEnfProfileBuilder ** 2017-03-15 16:23:52,030 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Completed PETaskCliEnforcement ** 2017-03-15 16:23:52,031 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Completed PETaskRadiusCoAEnfProfileBuilder ** 2017-03-15 16:23:52,031 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Completed PETaskPostAuthEnfProfileBuilder ** 2017-03-15 16:23:52,031 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Starting PETaskAuthStatusInfo ** 2017-03-15 16:23:52,031 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Starting PETaskOutputPolicyRes ** 2017-03-15 16:23:52,031 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Starting PETaskSessionLog ** 2017-03-15 16:23:52,034 [RequestHandler-1-0x7f25439fc700 h=4277 c=R000000cb-01-58c994c7] INFO Core.XpipPolicyResHandler - populateResponseTlv: PETaskPostureOutput does not exist. Skip sending posture VAFs 2017-03-15 16:23:52,034 [RequestHandler-1-0x7f25439fc700 h=4277 c=R000000cb-01-58c994c7] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr 2017-03-15 16:23:52,034 [RequestHandler-1-0x7f25439fc700 h=4276 c=R000000cb-01-58c994c7] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr 2017-03-15 16:23:52,035 [Th 38 Req 1392 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - Policy Evaluation time = 15 ms 2017-03-15 16:23:52,035 [Th 38 Req 1392 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_policy: Received Accept Enforcement Profile 2017-03-15 16:23:52,035 [Th 38 Req 1392 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_policy: Policy Server reply does not contain Posture-Validation-Response 2017-03-15 16:23:52,035 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Completed PETaskSessionLog ** 2017-03-15 16:23:52,035 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Completed PETaskOutputPolicyRes ** 2017-03-15 16:23:52,035 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - ** Completed PETaskAuthStatusInfo ** 2017-03-15 16:23:52,035 [RequestHandler-1-0x7f25439fc700 r=R000000cb-01-58c994c7 h=4264 c=R000000cb-01-58c994c7] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Completed *** 2017-03-15 16:23:52,036 [Th 38 Req 1392 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 29:125:D4-F4-6F-A1-E9-7C:AEgADwBaAFlwBQAARd34a/OY1fgjP/VPEU1aCg== 2017-03-15 16:23:52,117 [Th 39 Req 1393 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "LAB 802.1X Wireless with AD" - 30:294:D4-F4-6F-A1-E9-7C 2017-03-15 16:23:52,118 [Th 39 Req 1393 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_policy: Bypassing Policy Evaluation. 2017-03-15 16:23:52,118 [Th 39 Req 1393 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - rlm_policy: Added Class attribute with value Class = 0xbcaed1cf74344082beef187eda46c4c8b90b0000000000005230303030303063622d30312d35386339393463370000000000000000000000 2017-03-15 16:23:52,118 [Th 39 Req 1393 SessId R000000cb-01-58c994c7] INFO RadiusServer.Radius - Request processing time = 866 ms