Request log details for session: R00000345-01-58409598

Time Message
2016-12-01 16:26:48,849 [Th 38 Req 7416 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_service: Starting Service Categorization - 218:199:b01041ca594b
2016-12-01 16:26:48,855 [RequestHandler-1-0x7f28fd3e9700 r=psauto-1480111576-2298 h=223 r=R00000345-01-58409598] INFO Core.ServiceReqHandler - Service classification result = Copy_of_AYNI-Cert Onboard Provisioning
2016-12-01 16:26:48,856 [Th 38 Req 7416 SessId R00000345-01-58409598] INFO RadiusServer.Radius - Service Categorization time = 7 ms
2016-12-01 16:26:48,856 [Th 38 Req 7416 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_service: The request has been categorized into service "Copy_of_AYNI-Cert Onboard Provisioning"
2016-12-01 16:26:48,856 [Th 38 Req 7416 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_ldap: searching for user usrWL.test in AD:DCSIS11.sunat.peru
2016-12-01 16:26:48,936 [Th 38 Req 7416 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_ldap: found user usrWL.test in AD:DCSIS11.sunat.peru
2016-12-01 16:26:48,937 [Th 38 Req 7416 SessId R00000345-01-58409598] INFO RadiusServer.Radius - LDAP/AD User lookup time = 80 ms
2016-12-01 16:26:48,937 [Th 38 Req 7416 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_eap_tls: Initiate
2016-12-01 16:26:48,937 [Th 38 Req 7416 SessId R00000345-01-58409598] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 218:88:b01041ca594b:AJoACACqAGv4HAAADHOPZyrrxP8hicGRpzCyaQ==
2016-12-01 16:26:48,988 [Th 40 Req 7417 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "Copy_of_AYNI-Cert Onboard Provisioning" - 219:408:b01041ca594b
2016-12-01 16:26:48,994 [Th 40 Req 7417 SessId R00000345-01-58409598] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read client certificate A
2016-12-01 16:26:48,994 [Th 40 Req 7417 SessId R00000345-01-58409598] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read client certificate A
2016-12-01 16:26:48,995 [Th 40 Req 7417 SessId R00000345-01-58409598] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 219:1124:b01041ca594b:AI8AwAABAA/5HAAAexorHofzNp+02Gmdn6DY4g==
2016-12-01 16:26:49,058 [Th 33 Req 7418 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "Copy_of_AYNI-Cert Onboard Provisioning" - 220:232:b01041ca594b
2016-12-01 16:26:49,058 [Th 33 Req 7418 SessId R00000345-01-58409598] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 220:1120:b01041ca594b:ALkA0QDhALz6HAAA+2in1mOiHOcX9Y0FLYHqNg==
2016-12-01 16:26:49,105 [Th 34 Req 7419 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "Copy_of_AYNI-Cert Onboard Provisioning" - 221:232:b01041ca594b
2016-12-01 16:26:49,105 [Th 34 Req 7419 SessId R00000345-01-58409598] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 221:1120:b01041ca594b:AHIAfgByALH7HAAAcUAEIg6jEZYYMbXiwnvQzA==
2016-12-01 16:26:49,159 [Th 35 Req 7420 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "Copy_of_AYNI-Cert Onboard Provisioning" - 222:232:b01041ca594b
2016-12-01 16:26:49,160 [Th 35 Req 7420 SessId R00000345-01-58409598] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 222:1120:b01041ca594b:ABAAUwC0ALH8HAAAELqjl4wFHgJqTR+H5hlpRw==
2016-12-01 16:26:49,204 [Th 36 Req 7421 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "Copy_of_AYNI-Cert Onboard Provisioning" - 223:232:b01041ca594b
2016-12-01 16:26:49,205 [Th 36 Req 7421 SessId R00000345-01-58409598] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 223:1120:b01041ca594b:AJwACgBrAIf9HAAA89WQRYd2tX67Y9CRBLuqqA==
2016-12-01 16:26:49,254 [Th 37 Req 7422 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "Copy_of_AYNI-Cert Onboard Provisioning" - 224:232:b01041ca594b
2016-12-01 16:26:49,254 [Th 37 Req 7422 SessId R00000345-01-58409598] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 224:1120:b01041ca594b:AHAAOQBSAJX+HAAA3dmrF8tEhMnqBNnLFRNy4Q==
2016-12-01 16:26:49,301 [Th 39 Req 7423 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "Copy_of_AYNI-Cert Onboard Provisioning" - 225:232:b01041ca594b
2016-12-01 16:26:49,302 [Th 39 Req 7423 SessId R00000345-01-58409598] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 225:1120:b01041ca594b:AGcA2QC+AKn/HAAAM5fuja8x6hnJXthOi9thRQ==
2016-12-01 16:26:49,355 [Th 38 Req 7424 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "Copy_of_AYNI-Cert Onboard Provisioning" - 226:232:b01041ca594b
2016-12-01 16:26:49,355 [Th 38 Req 7424 SessId R00000345-01-58409598] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 226:538:b01041ca594b:AG4AcgAwAMMAHQAA+OBT5mMvToQVXq1U1eRhpg==
2016-12-01 16:26:49,480 [Th 40 Req 7425 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "Copy_of_AYNI-Cert Onboard Provisioning" - 227:1728:b01041ca594b
2016-12-01 16:26:49,480 [Th 40 Req 7425 SessId R00000345-01-58409598] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 227:88:b01041ca594b:ANkA2gCuAEMBHQAAI8zio3B26DJ3514lP3aDHA==
2016-12-01 16:26:49,519 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "Copy_of_AYNI-Cert Onboard Provisioning" - 228:1430:b01041ca594b
2016-12-01 16:26:49,520 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - chain-depth=2,
2016-12-01 16:26:49,520 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - error=0
2016-12-01 16:26:49,520 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - --> User-Name = usrWL.test
2016-12-01 16:26:49,520 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - --> subject = /C=PE/ST=LIMA/L=LIMA/O=SUNAT/CN=SUNAT ClearPass Onboard Local Certificate Authority/emailAddress=sunat@sunat.gob.pe
2016-12-01 16:26:49,520 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - --> issuer = /C=PE/ST=LIMA/L=LIMA/O=SUNAT/CN=SUNAT ClearPass Onboard Local Certificate Authority/emailAddress=sunat@sunat.gob.pe
2016-12-01 16:26:49,520 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - --> verify return:1
2016-12-01 16:26:49,520 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - chain-depth=1,
2016-12-01 16:26:49,520 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - error=0
2016-12-01 16:26:49,520 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - --> User-Name = usrWL.test
2016-12-01 16:26:49,520 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - --> subject = /C=PE/ST=LIMA/L=LIMA/O=SUNAT/CN=SUNAT ClearPass Onboard Local Certificate Authority (Signing)/emailAddress=sunat@sunat.gob.pe
2016-12-01 16:26:49,520 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - --> issuer = /C=PE/ST=LIMA/L=LIMA/O=SUNAT/CN=SUNAT ClearPass Onboard Local Certificate Authority/emailAddress=sunat@sunat.gob.pe
2016-12-01 16:26:49,520 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - --> verify return:1
2016-12-01 16:26:49,521 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_eap_tls {User-Name} xlated usrWL.test
2016-12-01 16:26:49,521 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_eap_tls {Stripped-User-Name} is usrWL.test
2016-12-01 16:26:49,521 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_eap_tls: Found matching CN
2016-12-01 16:26:49,521 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - chain-depth=0,
2016-12-01 16:26:49,521 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - error=0
2016-12-01 16:26:49,521 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - --> User-Name = usrWL.test
2016-12-01 16:26:49,521 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - --> subject = /C=PE/ST=LIMA/L=LIMA/O=SUNAT/CN=usrWL.test/emailAddress=usrWL.test@sunat.gob.pe
2016-12-01 16:26:49,521 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - --> issuer = /C=PE/ST=LIMA/L=LIMA/O=SUNAT/CN=SUNAT ClearPass Onboard Local Certificate Authority (Signing)/emailAddress=sunat@sunat.gob.pe
2016-12-01 16:26:49,521 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - --> verify return:1
2016-12-01 16:26:49,523 [Th 33 Req 7426 SessId R00000345-01-58409598] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 228:143:b01041ca594b:AAQAOAAjADMCHQAA7/ciLBb1X126r5dvYyKFpA==
2016-12-01 16:26:49,552 [Th 34 Req 7427 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "Copy_of_AYNI-Cert Onboard Provisioning" - 229:232:b01041ca594b
2016-12-01 16:26:49,552 [Th 34 Req 7427 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_eap_tls: Session established.
2016-12-01 16:26:49,553 [Th 34 Req 7427 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_policy: Starting Policy Evaluation.
2016-12-01 16:26:49,559 [RequestHandler-1-0x7f28fd3e9700 r=psauto-1480111576-2299 h=239 r=R00000345-01-58409598] INFO Common.EndpointTable - Returning EndpointSPtr for macAddr b01041ca594b
2016-12-01 16:26:49,559 [RequestHandler-1-0x7f28fd3e9700 r=psauto-1480111576-2299 h=239 r=R00000345-01-58409598] INFO Common.TagDefinitionCacheTable - No InstanceTagDefCacheMap found for instance id = 3002 entity id = 29
2016-12-01 16:26:49,559 [RequestHandler-1-0x7f28fd3e9700 r=psauto-1480111576-2299 h=239 r=R00000345-01-58409598] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for NAD instance=3002
2016-12-01 16:26:49,559 [RequestHandler-1-0x7f28fd3e9700 r=psauto-1480111576-2299 h=239 r=R00000345-01-58409598] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for NAD instanceId=3002|entityId=29
2016-12-01 16:26:49,559 [RequestHandler-1-0x7f28fd3e9700 r=psauto-1480111576-2299 h=239 r=R00000345-01-58409598] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=3002|entity=Device
2016-12-01 16:26:49,559 [RequestHandler-1-0x7f28fd3e9700 r=psauto-1480111576-2299 h=239 r=R00000345-01-58409598] INFO TAT.AluTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL AuthLocalUser)
2016-12-01 16:26:49,559 [RequestHandler-1-0x7f28fd3e9700 r=psauto-1480111576-2299 h=239 r=R00000345-01-58409598] INFO TAT.GuTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL GuestUser)
2016-12-01 16:26:49,559 [RequestHandler-1-0x7f28fd3e9700 r=psauto-1480111576-2299 h=239 r=R00000345-01-58409598] INFO TAT.OnboardTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Onboard Device User)
2016-12-01 16:26:49,560 [RequestHandler-1-0x7f28fd3e9700 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Started ***
2016-12-01 16:26:49,560 [RequestHandler-1-0x7f28fd3e9700 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Starting PETaskAuthSourceRestriction **
2016-12-01 16:26:49,560 [RequestHandler-1-0x7f28fd3e9700 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Starting PETaskRoleMapping **
2016-12-01 16:26:49,561 [RequestHandler-1-0x7f28fd3e9700 h=17444 c=R00000345-01-58409598] WARN REC.EvaluatorCtx - Prerequisites set is empty, not populating the Request Map
2016-12-01 16:26:49,561 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Completed PETaskAuthSourceRestriction **
2016-12-01 16:26:49,562 [AuthReqThreadPool-18-0x7f29e7dfe700 r=R00000345-01-58409598 h=59] WARN Util.ParameterizedString - getReplacedStrings: Failed to replace parameString =(&(sAMAccountName=%{Host:Name}$)(objectClass=computer)), error=No values for param=Host:Name
2016-12-01 16:26:49,562 [AuthReqThreadPool-18-0x7f29e7dfe700 r=R00000345-01-58409598 h=59] WARN Ldap.LdapQuery - execute: Failed to construct filter=(&(sAMAccountName=%{Host:Name}$)(objectClass=computer))
2016-12-01 16:26:49,562 [AuthReqThreadPool-18-0x7f29e7dfe700 r=R00000345-01-58409598 h=59] WARN Ldap.LdapQuery - Failed to get value for attributes=ComputerStatus, Department, HostName, OSServicePack, OperatingSystem]
2016-12-01 16:26:49,563 [RequestHandler-1-0x7f28fd3e9700 h=17445 c=R00000345-01-58409598] INFO Core.PETaskRoleMapping - Roles: User Authenticated]
2016-12-01 16:26:49,563 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Completed PETaskRoleMapping **
2016-12-01 16:26:49,563 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Starting PETaskPolicyResult **
2016-12-01 16:26:49,564 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Completed PETaskPolicyResult **
2016-12-01 16:26:49,564 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Starting PETaskEnforcement **
2016-12-01 16:26:49,565 [RequestHandler-1-0x7f28fd3e9700 h=17448 c=R00000345-01-58409598] INFO Core.PETaskEnforcement - EnfProfiles: Allow Access Profile], AYNI-Cert Onboard Post-Provisioning
2016-12-01 16:26:49,565 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Completed PETaskEnforcement **
2016-12-01 16:26:49,565 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Starting PETaskRadiusEnfProfileBuilder **
2016-12-01 16:26:49,565 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Starting PETaskRadiusCoAEnfProfileBuilder **
2016-12-01 16:26:49,565 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Starting PETaskAppEnfProfileBuilder **
2016-12-01 16:26:49,565 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Starting PETaskPostAuthEnfProfileBuilder **
2016-12-01 16:26:49,565 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Starting PETaskGenericEnfProfileBuilder **
2016-12-01 16:26:49,565 [RequestHandler-1-0x7f28fd3e9700 h=17453 c=R00000345-01-58409598] INFO Core.PETaskGenericEnfProfileBuilder - getApplicableProfiles: No App enforcement (Generic) profiles applicable for this device
2016-12-01 16:26:49,566 [RequestHandler-1-0x7f28fd3e9700 h=17449 c=R00000345-01-58409598] INFO Core.PETaskRadiusEnfProfileBuilder - EnfProfileAction=ACCEPT
2016-12-01 16:26:49,566 [RequestHandler-1-0x7f28fd3e9700 h=17449 c=R00000345-01-58409598] INFO Core.PETaskRadiusEnfProfileBuilder - Radius enfProfiles used: Allow Access Profile], AYNI-Cert Onboard Post-Provisioning
2016-12-01 16:26:49,567 [RequestHandler-1-0x7f28fd3e9700 h=17449 c=R00000345-01-58409598] INFO Core.EnfProfileComputer - getFinalSessionTimeout: sessionTimeout = 0
2016-12-01 16:26:49,567 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Completed PETaskGenericEnfProfileBuilder **
2016-12-01 16:26:49,567 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Completed PETaskAppEnfProfileBuilder **
2016-12-01 16:26:49,567 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Starting PETaskCliEnforcement **
2016-12-01 16:26:49,567 [RequestHandler-1-0x7f28fd3e9700 h=17454 c=R00000345-01-58409598] INFO Core.PETaskCliEnforcement - startHandler: No commands for CLI enforcement
2016-12-01 16:26:49,567 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Completed PETaskRadiusEnfProfileBuilder **
2016-12-01 16:26:49,568 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17450 c=R00000345-01-58409598] INFO Core.PETaskRadiusCoAEnfProfileBuilder - getApplicableProfiles: No radius_coa enforcement profiles applicable for this device
2016-12-01 16:26:49,568 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Completed PETaskCliEnforcement **
2016-12-01 16:26:49,568 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17452 c=R00000345-01-58409598] INFO Core.PETaskPostAuthEnfProfileBuilder - getApplicableProfiles: No Post auth enforcement profiles applicable for this device
2016-12-01 16:26:49,568 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Completed PETaskRadiusCoAEnfProfileBuilder **
2016-12-01 16:26:49,568 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Completed PETaskPostAuthEnfProfileBuilder **
2016-12-01 16:26:49,568 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Starting PETaskAuthStatusInfo **
2016-12-01 16:26:49,569 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Starting PETaskOutputPolicyRes **
2016-12-01 16:26:49,569 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Starting PETaskSessionLog **
2016-12-01 16:26:49,576 [RequestHandler-1-0x7f28fd3e9700 h=17456 c=R00000345-01-58409598] INFO Core.XpipPolicyResHandler - populateResponseTlv: PETaskPostureOutput does not exist. Skip sending posture VAFs
2016-12-01 16:26:49,576 [RequestHandler-1-0x7f28fd3e9700 h=17456 c=R00000345-01-58409598] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2016-12-01 16:26:49,576 [RequestHandler-1-0x7f28fd3e9700 h=17455 c=R00000345-01-58409598] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2016-12-01 16:26:49,577 [Th 34 Req 7427 SessId R00000345-01-58409598] INFO RadiusServer.Radius - Policy Evaluation time = 23 ms
2016-12-01 16:26:49,577 [Th 34 Req 7427 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_policy: Received Accept Enforcement Profile
2016-12-01 16:26:49,577 [Th 34 Req 7427 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_policy: Added Class attribute with value Class = 0xe057349257894bc9afae9bca6bb3762ac70b0000000000005230303030303334352d30312d35383430393539380000000000000000000000
2016-12-01 16:26:49,577 [Th 34 Req 7427 SessId R00000345-01-58409598] INFO RadiusServer.Radius - rlm_policy: Policy Server reply does not contain Posture-Validation-Response
2016-12-01 16:26:49,577 [Th 34 Req 7427 SessId R00000345-01-58409598] INFO RadiusServer.Radius - Request processing time = 729 ms
2016-12-01 16:26:49,577 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Completed PETaskSessionLog **
2016-12-01 16:26:49,577 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Completed PETaskOutputPolicyRes **
2016-12-01 16:26:49,577 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - ** Completed PETaskAuthStatusInfo **
2016-12-01 16:26:49,577 [RequestHandler-1-0x7f28fd3e9700 r=R00000345-01-58409598 h=17443 c=R00000345-01-58409598] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Completed ***