| Time | Message |
|---|---|
| 2016-10-28 11:23:45,451 | [Th 38 Req 7364 SessId R0000016d-01-58136d81] INFO RadiusServer.Radius - rlm_service: Starting Service Categorization - 53:187:14a364afb691 |
| 2016-10-28 11:23:45,460 | [RequestHandler-1-0x7fecf8fe7700 r=psauto-1472046227-858 h=223 r=R0000016d-01-58136d81] INFO Core.ServiceReqHandler - Service classification result = dot1x IAP |
| 2016-10-28 11:23:45,462 | [Th 38 Req 7364 SessId R0000016d-01-58136d81] INFO RadiusServer.Radius - Service Categorization time = 11 ms |
| 2016-10-28 11:23:45,462 | [Th 38 Req 7364 SessId R0000016d-01-58136d81] INFO RadiusServer.Radius - rlm_service: The request has been categorized into service "dot1x IAP" |
| 2016-10-28 11:23:45,463 | [Th 38 Req 7364 SessId R0000016d-01-58136d81] INFO RadiusServer.Radius - rlm_ldap: searching for user dspencer in AD:esai-dc1.soo.algoma.com |
| 2016-10-28 11:23:45,466 | [Th 38 Req 7364 SessId R0000016d-01-58136d81] INFO RadiusServer.Radius - rlm_ldap: found user dspencer in AD:esai-dc1.soo.algoma.com |
| 2016-10-28 11:23:45,467 | [Th 38 Req 7364 SessId R0000016d-01-58136d81] INFO RadiusServer.Radius - LDAP/AD User lookup time = 4 ms |
| 2016-10-28 11:23:45,467 | [Th 38 Req 7364 SessId R0000016d-01-58136d81] INFO RadiusServer.Radius - rlm_eap_tls: Initiate |
| 2016-10-28 11:23:45,468 | [Th 38 Req 7364 SessId R0000016d-01-58136d81] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 53:88:14a364afb691:AJ0AJwBbABDEHAAA8C9xF8NvS2LNZ/Q0gWdXqw== |
| 2016-10-28 11:23:45,480 | [Th 34 Req 7365 SessId R0000016d-01-58136d81] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "dot1x IAP" - 54:222:14a364afb691 |
| 2016-10-28 11:23:45,481 | [Th 34 Req 7365 SessId R0000016d-01-58136d81] ERROR RadiusServer.Radius - rlm_eap: Client doesn't support any method that we require. Rejecting client. |
| 2016-10-28 11:23:45,481 | [Th 34 Req 7365 SessId R0000016d-01-58136d81] INFO RadiusServer.Radius - rlm_policy: Starting Policy Evaluation. |
| 2016-10-28 11:23:45,488 | [RequestHandler-1-0x7fecf8fe7700 r=psauto-1472046227-859 h=239 r=R0000016d-01-58136d81] INFO Common.EndpointTable - Returning EndpointSPtr for macAddr 14a364afb691 |
| 2016-10-28 11:23:45,488 | [RequestHandler-1-0x7fecf8fe7700 r=psauto-1472046227-859 h=239 r=R0000016d-01-58136d81] INFO Common.TagDefinitionCacheTable - No InstanceTagDefCacheMap found for instance id = 3002 entity id = 29 |
| 2016-10-28 11:23:45,488 | [RequestHandler-1-0x7fecf8fe7700 r=psauto-1472046227-859 h=239 r=R0000016d-01-58136d81] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for NAD instance=3002 |
| 2016-10-28 11:23:45,488 | [RequestHandler-1-0x7fecf8fe7700 r=psauto-1472046227-859 h=239 r=R0000016d-01-58136d81] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for NAD instanceId=3002|entityId=29 |
| 2016-10-28 11:23:45,488 | [RequestHandler-1-0x7fecf8fe7700 r=psauto-1472046227-859 h=239 r=R0000016d-01-58136d81] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=3002|entity=Device |
| 2016-10-28 11:23:45,488 | [RequestHandler-1-0x7fecf8fe7700 r=psauto-1472046227-859 h=239 r=R0000016d-01-58136d81] INFO TAT.AluTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL AuthLocalUser) |
| 2016-10-28 11:23:45,488 | [RequestHandler-1-0x7fecf8fe7700 r=psauto-1472046227-859 h=239 r=R0000016d-01-58136d81] INFO TAT.GuTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL GuestUser) |
| 2016-10-28 11:23:45,489 | [RequestHandler-1-0x7fecf8fe7700 r=psauto-1472046227-859 h=239 r=R0000016d-01-58136d81] INFO TAT.OnboardTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Onboard Device User) |
| 2016-10-28 11:23:45,489 | [RequestHandler-1-0x7fecf8fe7700 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Started *** |
| 2016-10-28 11:23:45,489 | [RequestHandler-1-0x7fecf8fe7700 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Starting PETaskAuthSourceRestriction ** |
| 2016-10-28 11:23:45,489 | [RequestHandler-1-0x7fecf8fe7700 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Starting PETaskRoleMapping ** |
| 2016-10-28 11:23:45,491 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Completed PETaskAuthSourceRestriction ** |
| 2016-10-28 11:23:45,493 | [RequestHandler-1-0x7fecf8fe7700 h=7094 c=R0000016d-01-58136d81] INFO Core.PETaskRoleMapping - Roles: |
| 2016-10-28 11:23:45,494 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Completed PETaskRoleMapping ** |
| 2016-10-28 11:23:45,494 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Starting PETaskPolicyResult ** |
| 2016-10-28 11:23:45,495 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Completed PETaskPolicyResult ** |
| 2016-10-28 11:23:45,495 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Starting PETaskEnforcement ** |
| 2016-10-28 11:23:45,501 | [RequestHandler-1-0x7fecf8fe7700 h=7097 c=R0000016d-01-58136d81] INFO Core.PETaskEnforcement - EnfProfiles: Allow Access Profile] |
| 2016-10-28 11:23:45,501 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Completed PETaskEnforcement ** |
| 2016-10-28 11:23:45,502 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Starting PETaskRadiusEnfProfileBuilder ** |
| 2016-10-28 11:23:45,502 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Starting PETaskRadiusCoAEnfProfileBuilder ** |
| 2016-10-28 11:23:45,502 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Starting PETaskAppEnfProfileBuilder ** |
| 2016-10-28 11:23:45,502 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Starting PETaskPostAuthEnfProfileBuilder ** |
| 2016-10-28 11:23:45,502 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Starting PETaskGenericEnfProfileBuilder ** |
| 2016-10-28 11:23:45,503 | [RequestHandler-1-0x7fecf8fe7700 h=7103 c=R0000016d-01-58136d81] INFO Core.PETaskGenericEnfProfileBuilder - getApplicableProfiles: No App enforcement (Generic) profiles applicable for this device |
| 2016-10-28 11:23:45,504 | [RequestHandler-1-0x7fecf8fe7700 h=7099 c=R0000016d-01-58136d81] INFO Core.PETaskRadiusEnfProfileBuilder - EnfProfileAction=ACCEPT |
| 2016-10-28 11:23:45,504 | [RequestHandler-1-0x7fecf8fe7700 h=7099 c=R0000016d-01-58136d81] INFO Core.PETaskRadiusEnfProfileBuilder - Radius enfProfiles used: Allow Access Profile] |
| 2016-10-28 11:23:45,504 | [RequestHandler-1-0x7fecf8fe7700 h=7099 c=R0000016d-01-58136d81] INFO Core.EnfProfileComputer - getFinalSessionTimeout: sessionTimeout = 0 |
| 2016-10-28 11:23:45,505 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Completed PETaskGenericEnfProfileBuilder ** |
| 2016-10-28 11:23:45,505 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Completed PETaskAppEnfProfileBuilder ** |
| 2016-10-28 11:23:45,505 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Starting PETaskCliEnforcement ** |
| 2016-10-28 11:23:45,505 | [RequestHandler-1-0x7fecf8fe7700 h=7104 c=R0000016d-01-58136d81] INFO Core.PETaskCliEnforcement - startHandler: No commands for CLI enforcement |
| 2016-10-28 11:23:45,505 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Completed PETaskRadiusEnfProfileBuilder ** |
| 2016-10-28 11:23:45,506 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Completed PETaskCliEnforcement ** |
| 2016-10-28 11:23:45,506 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7100 c=R0000016d-01-58136d81] INFO Core.PETaskRadiusCoAEnfProfileBuilder - getApplicableProfiles: No radius_coa enforcement profiles applicable for this device |
| 2016-10-28 11:23:45,506 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Completed PETaskRadiusCoAEnfProfileBuilder ** |
| 2016-10-28 11:23:45,507 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7102 c=R0000016d-01-58136d81] INFO Core.PETaskPostAuthEnfProfileBuilder - getApplicableProfiles: No Post auth enforcement profiles applicable for this device |
| 2016-10-28 11:23:45,507 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Completed PETaskPostAuthEnfProfileBuilder ** |
| 2016-10-28 11:23:45,507 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Starting PETaskAuthStatusInfo ** |
| 2016-10-28 11:23:45,507 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Starting PETaskOutputPolicyRes ** |
| 2016-10-28 11:23:45,508 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Starting PETaskSessionLog ** |
| 2016-10-28 11:23:45,517 | [RequestHandler-1-0x7fecf8fe7700 h=7106 c=R0000016d-01-58136d81] INFO Core.XpipPolicyResHandler - populateResponseTlv: PETaskPostureOutput does not exist. Skip sending posture VAFs |
| 2016-10-28 11:23:45,518 | [RequestHandler-1-0x7fecf8fe7700 h=7106 c=R0000016d-01-58136d81] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr |
| 2016-10-28 11:23:45,518 | [RequestHandler-1-0x7fecf8fe7700 h=7105 c=R0000016d-01-58136d81] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr |
| 2016-10-28 11:23:45,519 | [Th 34 Req 7365 SessId R0000016d-01-58136d81] INFO RadiusServer.Radius - Policy Evaluation time = 37 ms |
| 2016-10-28 11:23:45,519 | [Th 34 Req 7365 SessId R0000016d-01-58136d81] INFO RadiusServer.Radius - rlm_policy: Received Accept Enforcement Profile |
| 2016-10-28 11:23:45,519 | [Th 34 Req 7365 SessId R0000016d-01-58136d81] INFO RadiusServer.Radius - rlm_policy: Policy Server reply does not contain Posture-Validation-Response |
| 2016-10-28 11:23:45,519 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Completed PETaskSessionLog ** |
| 2016-10-28 11:23:45,519 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Completed PETaskOutputPolicyRes ** |
| 2016-10-28 11:23:45,520 | [Th 34 Req 7365 SessId R0000016d-01-58136d81] INFO RadiusServer.Radius - Request processing time = 68 ms |
| 2016-10-28 11:23:45,520 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - ** Completed PETaskAuthStatusInfo ** |
| 2016-10-28 11:23:45,520 | [RequestHandler-1-0x7fecf8fe7700 r=R0000016d-01-58136d81 h=7092 c=R0000016d-01-58136d81] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Completed *** |