I am trying to troubleshoot why when I loose one of our AD controllers (DC1) authenications fail. We have primary (DC1), backup1 (DC2) and backup2 (DC3) setup. I see the user is looked up in AD against DC2. But then is says there are not logon servers. Any ideas? Here is the log:
Request log details for session: R0011d062-01-5a13ff1e
Time Message
2017-11-21 05:25:34,234 [Th 128971 Req 8576117 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_service: Starting Service Categorization - 237:207:247703BDF290
2017-11-21 05:25:34,237 [RequestHandler-1-0x7f536e3f1700 r=psauto-1507713661-2854317 h=127 r=R0011d062-01-5a13ff1e] INFO Core.ServiceReqHandler - Service classification result = secure wireless access service
2017-11-21 05:25:34,238 [Th 128971 Req 8576117 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - Service Categorization time = 4 ms
2017-11-21 05:25:34,238 [Th 128971 Req 8576117 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_service: The request has been categorized into service "secure wireless access service"
2017-11-21 05:25:34,238 [Th 128971 Req 8576117 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_ldap: searching for user jdoe in AD:dc2.domain.org
2017-11-21 05:25:34,239 [Th 128971 Req 8576117 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_ldap: found user jdoe in AD:dc2.domain.org
2017-11-21 05:25:34,239 [Th 128971 Req 8576117 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - LDAP/AD User lookup time = 1 ms
2017-11-21 05:25:34,240 [Th 128971 Req 8576117 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_eap_peap: Initiate
2017-11-21 05:25:34,240 [Th 128971 Req 8576117 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 237:88:247703BDF290:AKgAaAC9ACN13IIAh+R+3VRsrnEBYkxXjcXJ6g==
2017-11-21 05:25:34,245 [Th 128974 Req 8576118 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "secure wireless access service" - 134:448:247703BDF290
2017-11-21 05:25:34,246 [Th 128974 Req 8576118 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read finished A
2017-11-21 05:25:34,246 [Th 128974 Req 8576118 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read finished A
2017-11-21 05:25:34,246 [Th 128974 Req 8576118 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 134:228:247703BDF290:AOsA2QDRAI123IIALNitP2k6szd8/C8zgl9lKA==
2017-11-21 05:25:34,255 [Th 128976 Req 8576119 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "secure wireless access service" - 145:295:247703BDF290
2017-11-21 05:25:34,256 [Th 128976 Req 8576119 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_eap_peap: Session established.
2017-11-21 05:25:34,256 [Th 128976 Req 8576119 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 145:122:247703BDF290:AGkArwA4AAN33IIAlNQ4XouDyTZDmY0p7LefAw==
2017-11-21 05:25:34,261 [Th 128975 Req 8576120 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "secure wireless access service" - 203:280:247703BDF290
2017-11-21 05:25:34,262 [Th 128975 Req 8576120 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_eap_mschapv2: Issuing Challenge
2017-11-21 05:25:34,262 [Th 128975 Req 8576120 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 203:149:247703BDF290:AJMA0wBfACh43IIApzqVAaupKYMaYFWGO2LKDg==
2017-11-21 05:25:34,272 [Th 128977 Req 8576121 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "secure wireless access service" - 1:334:247703BDF290
2017-11-21 05:25:34,272 [Th 128977 Req 8576121 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "secure wireless access service" - 121:0:247703BDF290
2017-11-21 05:25:34,272 [Th 128977 Req 8576121 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_eap_mschapv2: Received MSCHAPv2 Response from client
2017-11-21 05:25:34,272 [Th 128977 Req 8576121 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_mschap: MSCHAPv2 username used for challenge computation jdoe
2017-11-21 05:25:34,272 [Th 128977 Req 8576121 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_mschap: Using domain DOMAIN from User-Name attribute
2017-11-21 05:25:34,272 [Th 128977 Req 8576121 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_mschap: authenticating user jdoe, domain DOMAIN
2017-11-21 05:25:34,273 [Th 128977 Req 8576121 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_mschap: user jdoe authentication failed
2017-11-21 05:25:34,273 [Th 128977 Req 8576121 SessId R0011d062-01-5a13ff1e] ERROR RadiusServer.Radius - rlm_mschap: AD status:No logon servers (0xc000005e)
2017-11-21 05:25:34,273 [Th 128977 Req 8576121 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - MS-Chap User Authentication time = 1 ms
2017-11-21 05:25:34,273 [Th 128977 Req 8576121 SessId R0011d062-01-5a13ff1e] ERROR RadiusServer.Radius - rlm_mschap: FAILED: MS-CHAP2-Response is incorrect
2017-11-21 05:25:34,273 [Th 128977 Req 8576121 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_policy: Starting Policy Evaluation.
2017-11-21 05:25:34,276 [RequestHandler-1-0x7f536e3f1700 r=psauto-1507713661-2854318 h=135 r=R0011d062-01-5a13ff1e] INFO Common.EndpointTable - Returning EndpointSPtr for macAddr 247703bdf290
2017-11-21 05:25:34,276 [RequestHandler-1-0x7f536e3f1700 r=psauto-1507713661-2854318 h=135 r=R0011d062-01-5a13ff1e] INFO Common.TagDefinitionCacheTable - No InstanceTagDefCacheMap found for instance id = 3019 entity id = 29
2017-11-21 05:25:34,276 [RequestHandler-1-0x7f536e3f1700 r=psauto-1507713661-2854318 h=135 r=R0011d062-01-5a13ff1e] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for NAD instance=3019
2017-11-21 05:25:34,276 [RequestHandler-1-0x7f536e3f1700 r=psauto-1507713661-2854318 h=135 r=R0011d062-01-5a13ff1e] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for NAD instanceId=3019|entityId=29
2017-11-21 05:25:34,276 [RequestHandler-1-0x7f536e3f1700 r=psauto-1507713661-2854318 h=135 r=R0011d062-01-5a13ff1e] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=3019|entity=Device
2017-11-21 05:25:34,276 [RequestHandler-1-0x7f536e3f1700 r=psauto-1507713661-2854318 h=135 r=R0011d062-01-5a13ff1e] INFO TAT.AluTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL AuthLocalUser)
2017-11-21 05:25:34,276 [RequestHandler-1-0x7f536e3f1700 r=psauto-1507713661-2854318 h=135 r=R0011d062-01-5a13ff1e] INFO TAT.GuTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL GuestUser)
2017-11-21 05:25:34,276 [RequestHandler-1-0x7f536e3f1700 r=psauto-1507713661-2854318 h=135 r=R0011d062-01-5a13ff1e] INFO TAT.OnboardTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Onboard Device User)
2017-11-21 05:25:34,276 [RequestHandler-1-0x7f536e3f1700 h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Started ***
2017-11-21 05:25:34,276 [RequestHandler-1-0x7f536e3f1700 h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Starting PETaskAuthSourceRestriction **
2017-11-21 05:25:34,277 [RequestHandler-1-0x7f536e3f1700 h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Starting PETaskRoleMapping **
2017-11-21 05:25:34,278 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Completed PETaskAuthSourceRestriction **
2017-11-21 05:25:34,280 [RequestHandler-1-0x7f536e3f1700 h=24163760 c=R0011d062-01-5a13ff1e] INFO Core.PETaskRoleMapping - Roles: Domain User
2017-11-21 05:25:34,280 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Completed PETaskRoleMapping **
2017-11-21 05:25:34,280 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Starting PETaskPolicyResult **
2017-11-21 05:25:34,282 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163762 c=R0011d062-01-5a13ff1e] ERROR Core.PETaskPolicyResult - handleHttpResponseEv: All policy result cache lookups failed
2017-11-21 05:25:34,282 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Completed PETaskPolicyResult **
2017-11-21 05:25:34,282 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Starting PETaskEnforcement **
2017-11-21 05:25:34,283 [RequestHandler-1-0x7f536e3f1700 h=24163763 c=R0011d062-01-5a13ff1e] INFO Core.PETaskEnforcement - EnfProfiles: admindc-fw user-id update, mobdc-fw user-id update, Aruba VLAN 200, secure-byod Aruba User Role
2017-11-21 05:25:34,283 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Completed PETaskEnforcement **
2017-11-21 05:25:34,283 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Starting PETaskRadiusEnfProfileBuilder **
2017-11-21 05:25:34,284 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Starting PETaskRadiusCoAEnfProfileBuilder **
2017-11-21 05:25:34,284 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Starting PETaskAppEnfProfileBuilder **
2017-11-21 05:25:34,284 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Starting PETaskAgentEnfProfileBuilder **
2017-11-21 05:25:34,284 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Starting PETaskPostAuthEnfProfileBuilder **
2017-11-21 05:25:34,284 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Starting PETaskGenericEnfProfileBuilder **
2017-11-21 05:25:34,284 [RequestHandler-1-0x7f536e3f1700 h=24163769 c=R0011d062-01-5a13ff1e] INFO Core.PETaskGenericEnfProfileBuilder - getApplicableProfiles: No App enforcement (Generic) profiles applicable for this device
2017-11-21 05:25:34,284 [RequestHandler-1-0x7f536e3f1700 h=24163766 c=R0011d062-01-5a13ff1e] WARN Common.AppEnfProfileTable - getAppType: Failed for id=3066
2017-11-21 05:25:34,284 [RequestHandler-1-0x7f536e3f1700 h=24163766 c=R0011d062-01-5a13ff1e] WARN Common.AppEnfProfileTable - getAppType: Failed for id=3073
2017-11-21 05:25:34,284 [RequestHandler-1-0x7f536e3f1700 h=24163764 c=R0011d062-01-5a13ff1e] INFO Core.PETaskRadiusEnfProfileBuilder - EnfProfileAction=ACCEPT
2017-11-21 05:25:34,284 [RequestHandler-1-0x7f536e3f1700 h=24163764 c=R0011d062-01-5a13ff1e] INFO Core.PETaskRadiusEnfProfileBuilder - Radius enfProfiles used: Aruba VLAN 200, secure-byod Aruba User Role
2017-11-21 05:25:34,284 [RequestHandler-1-0x7f536e3f1700 h=24163764 c=R0011d062-01-5a13ff1e] INFO Core.EnfProfileComputer - getFinalSessionTimeout: sessionTimeout = 0
2017-11-21 05:25:34,285 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Completed PETaskGenericEnfProfileBuilder **
2017-11-21 05:25:34,285 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Completed PETaskAgentEnfProfileBuilder **
2017-11-21 05:25:34,285 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Completed PETaskAppEnfProfileBuilder **
2017-11-21 05:25:34,285 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Starting PETaskCliEnforcement **
2017-11-21 05:25:34,285 [RequestHandler-1-0x7f536e3f1700 h=24163770 c=R0011d062-01-5a13ff1e] INFO Core.PETaskCliEnforcement - startHandler: No commands for CLI enforcement
2017-11-21 05:25:34,285 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Completed PETaskRadiusEnfProfileBuilder **
2017-11-21 05:25:34,285 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163768 c=R0011d062-01-5a13ff1e] INFO Core.PETaskPostAuthEnfProfileBuilder - Post auth enforcement profiles used: admindc-fw user-id update, mobdc-fw user-id update
2017-11-21 05:25:34,285 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163768 c=R0011d062-01-5a13ff1e] INFO Core.PETaskPostAuthEnfProfileBuilder - UnknownAutzParams to fetch for PostAuthEnfProfiles: :
2017-11-21 05:25:34,285 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163768 c=R0011d062-01-5a13ff1e] INFO Core.PETaskPostAuthEnfProfileBuilder - UnknownNAutzParams to fetch for PostAuthEnfProfiles: :
2017-11-21 05:25:34,286 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163765 c=R0011d062-01-5a13ff1e] INFO Core.PETaskRadiusCoAEnfProfileBuilder - getApplicableProfiles: No radius_coa enforcement profiles applicable for this device
2017-11-21 05:25:34,286 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Completed PETaskCliEnforcement **
2017-11-21 05:25:34,286 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Completed PETaskPostAuthEnfProfileBuilder **
2017-11-21 05:25:34,286 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Completed PETaskRadiusCoAEnfProfileBuilder **
2017-11-21 05:25:34,286 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Starting PETaskAuthStatusInfo **
2017-11-21 05:25:34,286 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Starting PETaskOutputPolicyRes **
2017-11-21 05:25:34,286 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Starting PETaskSessionLog **
2017-11-21 05:25:34,292 [RequestHandler-1-0x7f536e3f1700 h=24163772 c=R0011d062-01-5a13ff1e] INFO Core.XpipPolicyResHandler - populateResponseTlv: PETaskPostureOutput does not exist. Skip sending posture VAFs
2017-11-21 05:25:34,292 [RequestHandler-1-0x7f536e3f1700 h=24163772 c=R0011d062-01-5a13ff1e] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2017-11-21 05:25:34,292 [RequestHandler-1-0x7f536e3f1700 h=24163771 c=R0011d062-01-5a13ff1e] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2017-11-21 05:25:34,293 [Th 128977 Req 8576121 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - Policy Evaluation time = 19 ms
2017-11-21 05:25:34,293 [Th 128977 Req 8576121 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_policy: Received Accept Enforcement Profile
2017-11-21 05:25:34,293 [Th 128977 Req 8576121 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_policy: Policy Server reply does not contain Posture-Validation-Response
2017-11-21 05:25:34,293 [Th 128977 Req 8576121 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 1:128:247703BDF290:AKIAmwDwAKl53IIAdL06TG/kSHqYUoxL5xpBkA==
2017-11-21 05:25:34,293 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Completed PETaskSessionLog **
2017-11-21 05:25:34,293 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Completed PETaskOutputPolicyRes **
2017-11-21 05:25:34,293 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - ** Completed PETaskAuthStatusInfo **
2017-11-21 05:25:34,293 [RequestHandler-1-0x7f536e3f1700 r=R0011d062-01-5a13ff1e h=24163758 c=R0011d062-01-5a13ff1e] INFO Core.PETaskScheduler - *** PE_TASK_SCHEDULE_RADIUS Completed ***
2017-11-21 05:25:34,297 [Th 128978 Req 8576122 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "secure wireless access service" - 226:280:247703BDF290
2017-11-21 05:25:34,297 [Th 128978 Req 8576122 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_ldap: searching for user jdoe in AD:dc2.domain.org
2017-11-21 05:25:34,299 [Th 128978 Req 8576122 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_ldap: found user jdoe in AD:dc2.domain.org
2017-11-21 05:25:34,299 [Th 128978 Req 8576122 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - LDAP/AD User lookup time = 2 ms
2017-11-21 05:25:34,299 [Th 128978 Req 8576122 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - rlm_policy: Bypassing Policy Evaluation.
2017-11-21 05:25:34,299 [Th 128978 Req 8576122 SessId R0011d062-01-5a13ff1e] INFO RadiusServer.Radius - Request processing time = 65 ms