Request log details for session: R00012d58-01-5a8d9f32
Time 	Message
2018-02-21 11:32:50,284 	[Th 96709 Req 834033 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - rlm_service: Starting Service Categorization - 240:196:00907A1212E0
2018-02-21 11:32:50,287 	[Th 96709 Req 834033 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - Service Categorization time = 3 ms
2018-02-21 11:32:50,287 	[Th 96709 Req 834033 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - rlm_service: The request has been categorized into service "GBIN-Secure 802.1X"
2018-02-21 11:32:50,287 	[Th 96709 Req 834033 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - rlm_ldap: searching for user jrobson in AD:ldap.gbin.local
2018-02-21 11:32:50,287 	[RequestHandler-1-0x7f3446551700 r=psauto-1518445815-159617 h=223 r=R00012d58-01-5a8d9f32] INFO Core.ServiceReqHandler - Service classification result = GBIN-Secure 802.1X
2018-02-21 11:32:50,288 	[Th 96709 Req 834033 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - rlm_ldap: found user jrobson in AD:ldap.gbin.local
2018-02-21 11:32:50,288 	[Th 96709 Req 834033 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - LDAP/AD User lookup time = 1 ms
2018-02-21 11:32:50,288 	[Th 96709 Req 834033 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - rlm_eap_peap: Initiate
2018-02-21 11:32:50,288 	[Th 96709 Req 834033 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 240:88:00907A1212E0:AOMAwgAbAB/xuQwAB0lTIRyvaWnY7B5qE+I0zg==
2018-02-21 11:32:50,307 	[Th 96700 Req 834034 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "GBIN-Secure 802.1X" - 230:286:00907A1212E0
2018-02-21 11:32:50,308 	[Th 96700 Req 834034 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read client key exchange A
2018-02-21 11:32:50,308 	[Th 96700 Req 834034 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read client key exchange A
2018-02-21 11:32:50,308 	[Th 96700 Req 834034 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 230:1124:00907A1212E0:AO0AFgDEAJfyuQwA1osiMvC4g9kgjds1xAK2qQ==
2018-02-21 11:32:50,330 	[Th 96708 Req 834035 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "GBIN-Secure 802.1X" - 198:232:00907A1212E0
2018-02-21 11:32:50,330 	[Th 96708 Req 834035 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 198:1120:00907A1212E0:AEwAXQDYAPrzuQwAvmSzkrB1KX50OXmiqnznlA==
2018-02-21 11:32:50,353 	[Th 96703 Req 834036 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "GBIN-Secure 802.1X" - 50:232:00907A1212E0
2018-02-21 11:32:50,353 	[Th 96703 Req 834036 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 50:1120:00907A1212E0:AGgAhwBZAN/0uQwAAhvRaDYrfsc8kP0jFGBxfQ==
2018-02-21 11:32:50,375 	[Th 96704 Req 834037 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "GBIN-Secure 802.1X" - 130:232:00907A1212E0
2018-02-21 11:32:50,375 	[Th 96704 Req 834037 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 130:1120:00907A1212E0:AGkAnACoADr1uQwA0xX7UzLaYbUQVz62cDDt2g==
2018-02-21 11:32:50,398 	[Th 96701 Req 834038 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "GBIN-Secure 802.1X" - 203:232:00907A1212E0
2018-02-21 11:32:50,398 	[Th 96701 Req 834038 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 203:160:00907A1212E0:AD4ADgAHABX2uQwApLuiYhjfKdEhT7kPDFcoIA==
2018-02-21 11:32:50,490 	[Th 96699 Req 834039 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "GBIN-Secure 802.1X" - 105:239:00907A1212E0
2018-02-21 11:32:50,490 	[Th 96699 Req 834039 SessId R00012d58-01-5a8d9f32] ERROR RadiusServer.Radius - TLS Alert read:fatal:unknown CA
2018-02-21 11:32:50,490 	[Th 96699 Req 834039 SessId R00012d58-01-5a8d9f32] ERROR RadiusServer.Radius - TLS_accept:failed in SSLv3 read client key exchange A
2018-02-21 11:32:50,490 	[Th 96699 Req 834039 SessId R00012d58-01-5a8d9f32] ERROR RadiusServer.Radius - rlm_eap_tls: SSL_read failed inside of TLS (-1), TLS session fails. error:14094418:SSL routines:ssl3_read_bytes:tlsv1 alert unknown ca
2018-02-21 11:32:50,490 	[Th 96699 Req 834039 SessId R00012d58-01-5a8d9f32] ERROR RadiusServer.Radius - rlm_eap_tls: TLS Handshake failed
2018-02-21 11:32:50,490 	[Th 96699 Req 834039 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - rlm_policy: Starting Policy Evaluation.
2018-02-21 11:32:50,492 	[RequestHandler-1-0x7f3446551700 r=psauto-1518445815-159618 h=239 r=R00012d58-01-5a8d9f32] INFO Common.EndpointTable - Returning EndpointSPtr for macAddr 00907a1212e0
2018-02-21 11:32:50,492 	[RequestHandler-1-0x7f3446551700 r=psauto-1518445815-159618 h=239 r=R00012d58-01-5a8d9f32] INFO Common.TagDefinitionCacheTable - No InstanceTagDefCacheMap found for instance id = 3004 entity id = 29
2018-02-21 11:32:50,492 	[RequestHandler-1-0x7f3446551700 r=psauto-1518445815-159618 h=239 r=R00012d58-01-5a8d9f32] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for NAD instance=3004
2018-02-21 11:32:50,492 	[RequestHandler-1-0x7f3446551700 r=psauto-1518445815-159618 h=239 r=R00012d58-01-5a8d9f32] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for NAD instanceId=3004|entityId=29
2018-02-21 11:32:50,492 	[RequestHandler-1-0x7f3446551700 r=psauto-1518445815-159618 h=239 r=R00012d58-01-5a8d9f32] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=3004|entity=Device
2018-02-21 11:32:50,492 	[RequestHandler-1-0x7f3446551700 r=psauto-1518445815-159618 h=239 r=R00012d58-01-5a8d9f32] INFO TAT.AluTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL AuthLocalUser)
2018-02-21 11:32:50,492 	[RequestHandler-1-0x7f3446551700 r=psauto-1518445815-159618 h=239 r=R00012d58-01-5a8d9f32] INFO TAT.GuTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL GuestUser)
2018-02-21 11:32:50,492 	[RequestHandler-1-0x7f3446551700 r=psauto-1518445815-159618 h=239 r=R00012d58-01-5a8d9f32] INFO Common.TagDefinitionCacheTable - No TagDefCacheMap could be found for instance id = 55873 entity id = 72
2018-02-21 11:32:50,492 	[RequestHandler-1-0x7f3446551700 r=psauto-1518445815-159618 h=239 r=R00012d58-01-5a8d9f32] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for Endpoint instance=55873
2018-02-21 11:32:50,492 	[RequestHandler-1-0x7f3446551700 r=psauto-1518445815-159618 h=239 r=R00012d58-01-5a8d9f32] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for instanceId=55873|entityId=72|entityName=Endpoint
2018-02-21 11:32:50,492 	[RequestHandler-1-0x7f3446551700 r=psauto-1518445815-159618 h=239 r=R00012d58-01-5a8d9f32] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=55873|entity=Endpoint
2018-02-21 11:32:50,492 	[RequestHandler-1-0x7f3446551700 r=psauto-1518445815-159618 h=239 r=R00012d58-01-5a8d9f32] INFO TAT.OnboardTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Onboard Device User)
2018-02-21 11:32:50,492 	[RequestHandler-1-0x7f3446551700 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Started ***
2018-02-21 11:32:50,492 	[RequestHandler-1-0x7f3446551700 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Starting PETaskAuthSourceRestriction **
2018-02-21 11:32:50,492 	[RequestHandler-1-0x7f3446551700 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Starting PETaskRoleMapping **
2018-02-21 11:32:50,493 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Completed PETaskAuthSourceRestriction **
2018-02-21 11:32:50,493 	[AuthReqThreadPool-30-0x7f347f5fa700 r=R00012d58-01-5a8d9f32 h=71] WARN Util.ParameterizedString - getReplacedStrings: Failed to replace parameString =(&(sAMAccountName=%{Host:Name}$)(objectClass=computer)), error=No values for param=Host:Name
2018-02-21 11:32:50,493 	[AuthReqThreadPool-30-0x7f347f5fa700 r=R00012d58-01-5a8d9f32 h=71] WARN Ldap.LdapQuery - execute: Failed to construct filter=(&(sAMAccountName=%{Host:Name}$)(objectClass=computer))
2018-02-21 11:32:50,493 	[AuthReqThreadPool-30-0x7f347f5fa700 r=R00012d58-01-5a8d9f32 h=71] WARN Util.ParameterizedString - getReplacedStrings: Failed to replace parameString =(&(sAMAccountName=%{Onboard:Owner})(objectClass=user)), error=No values for param=Onboard:Owner
2018-02-21 11:32:50,493 	[AuthReqThreadPool-30-0x7f347f5fa700 r=R00012d58-01-5a8d9f32 h=71] WARN Ldap.LdapQuery - execute: Failed to construct filter=(&(sAMAccountName=%{Onboard:Owner})(objectClass=user))
2018-02-21 11:32:50,493 	[AuthReqThreadPool-30-0x7f347f5fa700 r=R00012d58-01-5a8d9f32 h=71] WARN Util.ParameterizedString - getReplacedStrings: Failed to replace parameString =(distinguishedName=%{Onboard memberOf}), error=No values for param=Onboard memberOf
2018-02-21 11:32:50,493 	[AuthReqThreadPool-30-0x7f347f5fa700 r=R00012d58-01-5a8d9f32 h=71] WARN Ldap.LdapQuery - execute: Failed to construct filter=(distinguishedName=%{Onboard memberOf})
2018-02-21 11:32:50,493 	[AuthReqThreadPool-30-0x7f347f5fa700 r=R00012d58-01-5a8d9f32 h=71] WARN Ldap.LdapQuery - Failed to get value for attributes=HostName, OSServicePack, Onboard Groups, OperatingSystem, Phone]
2018-02-21 11:32:50,494 	[RequestHandler-1-0x7f3446551700 h=1490060 c=R00012d58-01-5a8d9f32] INFO Core.PETaskRoleMapping - Roles: Other]
2018-02-21 11:32:50,495 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Completed PETaskRoleMapping **
2018-02-21 11:32:50,495 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Starting PETaskPolicyResult **
2018-02-21 11:32:50,495 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Completed PETaskPolicyResult **
2018-02-21 11:32:50,495 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Starting PETaskEnforcement **
2018-02-21 11:32:50,495 	[RequestHandler-1-0x7f3446551700 h=1490063 c=R00012d58-01-5a8d9f32] INFO Core.PETaskEnforcement - EnfProfiles: Deny Access Profile]
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Completed PETaskEnforcement **
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Starting PETaskRadiusEnfProfileBuilder **
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Starting PETaskRadiusCoAEnfProfileBuilder **
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Starting PETaskAppEnfProfileBuilder **
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Starting PETaskAgentEnfProfileBuilder **
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Starting PETaskPostAuthEnfProfileBuilder **
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Starting PETaskGenericEnfProfileBuilder **
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 h=1490069 c=R00012d58-01-5a8d9f32] INFO Core.PETaskGenericEnfProfileBuilder - getApplicableProfiles: No App enforcement (Generic) profiles applicable for this device
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 h=1490064 c=R00012d58-01-5a8d9f32] INFO Core.PETaskRadiusEnfProfileBuilder - EnfProfileAction=DENY
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 h=1490064 c=R00012d58-01-5a8d9f32] INFO Core.PETaskRadiusEnfProfileBuilder - Radius enfProfiles used: Deny Access Profile]
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 h=1490064 c=R00012d58-01-5a8d9f32] INFO Core.EnfProfileComputer - getFinalSessionTimeout: sessionTimeout = 0
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Completed PETaskGenericEnfProfileBuilder **
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Completed PETaskAgentEnfProfileBuilder **
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Completed PETaskAppEnfProfileBuilder **
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Starting PETaskCliEnforcement **
2018-02-21 11:32:50,496 	[RequestHandler-1-0x7f3446551700 h=1490070 c=R00012d58-01-5a8d9f32] INFO Core.PETaskCliEnforcement - startHandler: Request rejected. Skip CLI enforcement
2018-02-21 11:32:50,497 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Completed PETaskRadiusEnfProfileBuilder **
2018-02-21 11:32:50,497 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Completed PETaskCliEnforcement **
2018-02-21 11:32:50,497 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490065 c=R00012d58-01-5a8d9f32] WARN Core.PETaskRadiusCoAEnfProfileBuilder - handleHttpResponseEv: Fetching Radius attributes from battery failed, errMsg=
2018-02-21 11:32:50,497 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Completed PETaskRadiusCoAEnfProfileBuilder **
2018-02-21 11:32:50,497 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490068 c=R00012d58-01-5a8d9f32] WARN Core.PETaskPostAuthEnfProfileBuilder - handleHttpResponseEv: Fetching Radius attributes from battery failed, errMsg=
2018-02-21 11:32:50,497 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490068 c=R00012d58-01-5a8d9f32] INFO Core.PETaskPostAuthEnfProfileBuilder - getApplicableProfiles: No Post auth enforcement profiles applicable for this device
2018-02-21 11:32:50,497 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Completed PETaskPostAuthEnfProfileBuilder **
2018-02-21 11:32:50,497 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Starting PETaskAuthStatusInfo **
2018-02-21 11:32:50,497 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Starting PETaskOutputPolicyRes **
2018-02-21 11:32:50,497 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Starting PETaskSessionLog **
2018-02-21 11:32:50,500 	[RequestHandler-1-0x7f3446551700 h=1490072 c=R00012d58-01-5a8d9f32] INFO Core.XpipPolicyResHandler - populateResponseTlv: PETaskPostureOutput does not exist. Skip sending posture VAFs
2018-02-21 11:32:50,500 	[RequestHandler-1-0x7f3446551700 h=1490072 c=R00012d58-01-5a8d9f32] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2018-02-21 11:32:50,500 	[RequestHandler-1-0x7f3446551700 h=1490071 c=R00012d58-01-5a8d9f32] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2018-02-21 11:32:50,500 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Completed PETaskSessionLog **
2018-02-21 11:32:50,501 	[Th 96699 Req 834039 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - Policy Evaluation time = 10 ms
2018-02-21 11:32:50,501 	[Th 96699 Req 834039 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - rlm_policy: Received Deny Enforcement Profile
2018-02-21 11:32:50,501 	[Th 96699 Req 834039 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - rlm_policy: Policy Server reply does not contain Posture-Validation-Response
2018-02-21 11:32:50,501 	[Th 96699 Req 834039 SessId R00012d58-01-5a8d9f32] INFO RadiusServer.Radius - Request processing time = 216 ms
2018-02-21 11:32:50,501 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Completed PETaskOutputPolicyRes **
2018-02-21 11:32:50,501 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - ** Completed PETaskAuthStatusInfo **
2018-02-21 11:32:50,501 	[RequestHandler-1-0x7f3446551700 r=R00012d58-01-5a8d9f32 h=1490058 c=R00012d58-01-5a8d9f32] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Completed ***