RADIUS EAP-TLS TIMEOUT issue. No issues with PEAP or MS-CHAP

Sam Na 46 Reputation points
2022-02-07T17:15:32.23+00:00

For some reason, when we use EAP-TLS, we get the TIMEOUT error. Just wondering the best method to figure out if either server or client certificates missing some data or have some issues so that the validations fail or take longer than usual.

Both PEAP and MS-CHAP are working OK with no issues, only EAP-TLS fails(certificate authentication):

Time Message
2022-02-07 09:07:31,516 [Th 15 Req 3915 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - rlm_service: Starting Service Categorization - 203:259:c0b6f9fc8be5
2022-02-07 09:07:31,520 [Th 15 Req 3915 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - Service Categorization time = 4 ms
2022-02-07 09:07:31,520 [Th 15 Req 3915 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - rlm_service: The request has been categorized into service "ws_ArubaInstant_Wireless802.1"
2022-02-07 09:07:31,520 [RequestHandler-1-0x7fd7c6bf5700 r=psauto-1643762453-1330 h=127 r=R00000295-01-620151d3] INFO Core.ServiceReqHandler - Service classification result = ws_ArubaInstant_Wireless802.1
2022-02-07 09:07:31,521 [Th 15 Req 3915 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - rlm_ldap: searching for user host/xxxPC-OnZF4eVnF.contoso.com in AD:capsw022.enterprise.lan
2022-02-07 09:07:32,230 [Th 15 Req 3915 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - rlm_ldap: found user XXXPC-OnZF4eVnF$ in AD:xxxx022.contoso.com
2022-02-07 09:07:32,230 [Th 15 Req 3915 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - LDAP/AD User lookup time = 709 ms
2022-02-07 09:07:32,230 [Th 15 Req 3915 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - rlm_eap_tls: Initiate
2022-02-07 09:07:32,230 [Th 15 Req 3915 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 203:88:c0b6f9fc8be5:AH8AlgCYAENLDwAAFQsw1I+js+EPsT43bwD6Zg==
2022-02-07 09:07:32,255 [Th 17 Req 3916 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "ws_ArubaInstant_Wireless802.1" - 204:427:c0b6f9fc8be5
2022-02-07 09:07:32,256 [Th 17 Req 3916 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read client certificate A
2022-02-07 09:07:32,256 [Th 17 Req 3916 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - TLS_accept:error in SSLv3 read client certificate A
2022-02-07 09:07:32,257 [Th 17 Req 3916 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 204:1124:c0b6f9fc8be5:AIsAuQBmAIBMDwAAnvw2FJecdjHcOL9fFLmgxg==
2022-02-07 09:07:32,278 [Th 20 Req 3917 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "ws_ArubaInstant_Wireless802.1" - 205:267:c0b6f9fc8be5
2022-02-07 09:07:32,278 [Th 20 Req 3917 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 205:1120:c0b6f9fc8be5:AGEA4ABMAI1NDwAAPuXWOQchHwTEenFGpvB1qg==
2022-02-07 09:07:32,304 [Th 14 Req 3918 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "ws_ArubaInstant_Wireless802.1" - 206:267:c0b6f9fc8be5
2022-02-07 09:07:32,305 [Th 14 Req 3918 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 206:1120:c0b6f9fc8be5:ALwAKQCcAEVODwAA7suBqn7UuHLFWpj7fva3Gw==
2022-02-07 09:07:32,328 [Th 19 Req 3919 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "ws_ArubaInstant_Wireless802.1" - 207:267:c0b6f9fc8be5
2022-02-07 09:07:32,329 [Th 19 Req 3919 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 207:1120:c0b6f9fc8be5:APoAXwDlAHxPDwAASn3FLjaggE41cBAxqnXkxg==
2022-02-07 09:07:32,352 [Th 16 Req 3920 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - rlm_service: The request was categorized into service "ws_ArubaInstant_Wireless802.1" - 209:267:c0b6f9fc8be5
2022-02-07 09:07:32,352 [Th 16 Req 3920 SessId R00000295-01-620151d3] INFO RadiusServer.Radius - reqst_update_state: Access-Challenge 209:942:c0b6f9fc8be5:ABEAwADqAGdQDwAAyXB6p3ll3N2o2wXXB1oQbA==
2022-02-07 09:08:29,139 [main SessId R00000295-01-620151d3] ERROR RadiusServer.Radius - reqst_clean_list: Deleting request sessid - R00000295-01-620151d3, state - ABEAwADqAGdQDwAAyXB6p3ll3N2o2wXXB1oQbA=
2022-02-07 09:08:29,139 [main SessId R00000295-01-620151d3] ERROR RadiusServer.Radius - reqst_clean_list: Packet 203:259:88:c0b6f9fc8be5 recv 1644253651.516644 - resp 1644253652.230784
2022-02-07 09:08:29,139 [main SessId R00000295-01-620151d3] ERROR RadiusServer.Radius - reqst_clean_list: Packet 204:427:1124:c0b6f9fc8be5 recv 1644253652.254819 - resp 1644253652.257420
2022-02-07 09:08:29,139 [main SessId R00000295-01-620151d3] ERROR RadiusServer.Radius - reqst_clean_list: Packet 205:267:1120:c0b6f9fc8be5 recv 1644253652.277683 - resp 1644253652.278936
2022-02-07 09:08:29,139 [main SessId R00000295-01-620151d3] ERROR RadiusServer.Radius - reqst_clean_list: Packet 206:267:1120:c0b6f9fc8be5 recv 1644253652.304406 - resp 1644253652.305060
2022-02-07 09:08:29,139 [main SessId R00000295-01-620151d3] ERROR RadiusServer.Radius - reqst_clean_list: Packet 207:267:1120:c0b6f9fc8be5 recv 1644253652.328143 - resp 1644253652.329253
2022-02-07 09:08:29,139 [main SessId R00000295-01-620151d3] ERROR RadiusServer.Radius - reqst_clean_list: Packet 209:267:942:c0b6f9fc8be5 recv 1644253652.351683 - resp 1644253652.352699
2022-02-07 09:08:29,139 [main SessId R00000295-01-620151d3] INFO RadiusServer.Radius - rlm_policy: Starting Policy Evaluation.
2022-02-07 09:08:29,142 [RequestHandler-1-0x7fd7c6bf5700 r=psauto-1643762453-1345 h=135 r=R00000295-01-620151d3] INFO Common.EndpointTable - Returning EndpointSPtr for macAddr c0b6f9fc8be5
2022-02-07 09:08:29,142 [RequestHandler-1-0x7fd7c6bf5700 r=psauto-1643762453-1345 h=135 r=R00000295-01-620151d3] INFO Common.TagDefinitionCacheTable - No InstanceTagDefCacheMap found for instance id = 3001 entity id = 29
2022-02-07 09:08:29,142 [RequestHandler-1-0x7fd7c6bf5700 r=psauto-1643762453-1345 h=135 r=R00000295-01-620151d3] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for NAD instance=3001
2022-02-07 09:08:29,142 [RequestHandler-1-0x7fd7c6bf5700 r=psauto-1643762453-1345 h=135 r=R00000295-01-620151d3] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for NAD instanceId=3001|entityId=29
2022-02-07 09:08:29,142 [RequestHandler-1-0x7fd7c6bf5700 r=psauto-1643762453-1345 h=135 r=R00000295-01-620151d3] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=3001|entity=Device
2022-02-07 09:08:29,142 [RequestHandler-1-0x7fd7c6bf5700 r=psauto-1643762453-1345 h=135 r=R00000295-01-620151d3] INFO TAT.AluTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL AuthLocalUser)
2022-02-07 09:08:29,142 [RequestHandler-1-0x7fd7c6bf5700 r=psauto-1643762453-1345 h=135 r=R00000295-01-620151d3] INFO TAT.GuTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL GuestUser)
2022-02-07 09:08:29,142 [RequestHandler-1-0x7fd7c6bf5700 r=psauto-1643762453-1345 h=135 r=R00000295-01-620151d3] INFO Common.TagDefinitionCacheTable - No InstanceTagDefCacheMap found for instance id = 3004 entity id = 72
2022-02-07 09:08:29,142 [RequestHandler-1-0x7fd7c6bf5700 r=psauto-1643762453-1345 h=135 r=R00000295-01-620151d3] INFO Common.TagDefinitionCacheTable - Building the TagDefMapTable for Endpoint instance=3004
2022-02-07 09:08:29,142 [RequestHandler-1-0x7fd7c6bf5700 r=psauto-1643762453-1345 h=135 r=R00000295-01-620151d3] INFO Common.TagDefinitionCacheTable - Built 0 tag(s) for instanceId=3004|entityId=72|entityName=Endpoint
2022-02-07 09:08:29,142 [RequestHandler-1-0x7fd7c6bf5700 r=psauto-1643762453-1345 h=135 r=R00000295-01-620151d3] INFO TAT.TagAttrHolderBuilder - No tags built for instanceId=3004|entity=Endpoint
2022-02-07 09:08:29,142 [RequestHandler-1-0x7fd7c6bf5700 r=psauto-1643762453-1345 h=135 r=R00000295-01-620151d3] INFO TAT.OnboardTagAttrHolderBuilder - buildAttrHolder: Tags cannot be built for instanceId=0 (NULL Onboard Device User)
2022-02-07 09:08:29,143 [RequestHandler-1-0x7fd7c6bf5700 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - * PE_TASK_SCHEDULE_RADIUS Started *
2022-02-07 09:08:29,143 [RequestHandler-1-0x7fd7c6bf5700 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Starting PETaskAuthSourceRestriction **
2022-02-07 09:08:29,143 [RequestHandler-1-0x7fd7c6bf5700 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Starting PETaskRoleMapping **
2022-02-07 09:08:29,143 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Completed PETaskAuthSourceRestriction **
2022-02-07 09:08:29,143 [RequestHandler-1-0x7fd7c6bf5700 h=11903 c=R00000295-01-620151d3] INFO Core.PETaskRoleMapping - Roles:
2022-02-07 09:08:29,143 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Completed PETaskRoleMapping **
2022-02-07 09:08:29,143 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Starting PETaskPolicyResult **
2022-02-07 09:08:29,144 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Completed PETaskPolicyResult **
2022-02-07 09:08:29,144 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Starting PETaskEnforcement **
2022-02-07 09:08:29,144 [RequestHandler-1-0x7fd7c6bf5700 h=11906 c=R00000295-01-620151d3] INFO Core.PETaskEnforcement - EnfProfiles: Allow Access Profile]
2022-02-07 09:08:29,144 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Completed PETaskEnforcement **
2022-02-07 09:08:29,144 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Starting PETaskRadiusEnfProfileBuilder **
2022-02-07 09:08:29,145 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Starting PETaskRadiusCoAEnfProfileBuilder **
2022-02-07 09:08:29,145 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Starting PETaskAppEnfProfileBuilder **
2022-02-07 09:08:29,145 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Starting PETaskAgentEnfProfileBuilder **
2022-02-07 09:08:29,145 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Starting PETaskPostAuthEnfProfileBuilder **
2022-02-07 09:08:29,145 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Starting PETaskGenericEnfProfileBuilder **
2022-02-07 09:08:29,145 [RequestHandler-1-0x7fd7c6bf5700 h=11912 c=R00000295-01-620151d3] INFO Core.PETaskGenericEnfProfileBuilder - getApplicableProfiles: No App enforcement (Generic) profiles applicable for this device
2022-02-07 09:08:29,145 [RequestHandler-1-0x7fd7c6bf5700 h=11907 c=R00000295-01-620151d3] INFO Core.PETaskRadiusEnfProfileBuilder - EnfProfileAction=ACCEPT
2022-02-07 09:08:29,145 [RequestHandler-1-0x7fd7c6bf5700 h=11907 c=R00000295-01-620151d3] INFO Core.PETaskRadiusEnfProfileBuilder - Radius enfProfiles used: Allow Access Profile]
2022-02-07 09:08:29,145 [RequestHandler-1-0x7fd7c6bf5700 h=11907 c=R00000295-01-620151d3] INFO Core.EnfProfileComputer - getFinalSessionTimeout: sessionTimeout = 0
2022-02-07 09:08:29,145 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Completed PETaskGenericEnfProfileBuilder **
2022-02-07 09:08:29,146 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Completed PETaskAgentEnfProfileBuilder **
2022-02-07 09:08:29,146 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Completed PETaskAppEnfProfileBuilder **
2022-02-07 09:08:29,146 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Starting PETaskCliEnforcement **
2022-02-07 09:08:29,146 [RequestHandler-1-0x7fd7c6bf5700 h=11913 c=R00000295-01-620151d3] INFO Core.PETaskCliEnforcement - startHandler: No commands for CLI enforcement
2022-02-07 09:08:29,146 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Completed PETaskRadiusEnfProfileBuilder **
2022-02-07 09:08:29,146 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11908 c=R00000295-01-620151d3] WARN Core.PETaskRadiusCoAEnfProfileBuilder - handleHttpResponseEv: Fetching Radius attributes from battery failed, errMsg=
2022-02-07 09:08:29,146 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Completed PETaskCliEnforcement **
2022-02-07 09:08:29,146 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Completed PETaskRadiusCoAEnfProfileBuilder **
2022-02-07 09:08:29,150 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11911 c=R00000295-01-620151d3] WARN Core.PETaskPostAuthEnfProfileBuilder - handleHttpResponseEv: Fetching Radius attributes from battery failed, errMsg=
2022-02-07 09:08:29,150 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11911 c=R00000295-01-620151d3] INFO Core.PETaskPostAuthEnfProfileBuilder - getApplicableProfiles: No Post auth enforcement profiles applicable for this device
2022-02-07 09:08:29,150 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Completed PETaskPostAuthEnfProfileBuilder **
2022-02-07 09:08:29,150 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Starting PETaskAuthStatusInfo **
2022-02-07 09:08:29,150 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Starting PETaskOutputPolicyRes **
2022-02-07 09:08:29,151 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Starting PETaskSessionLog **
2022-02-07 09:08:29,154 [main SessId R00000295-01-620151d3] INFO RadiusServer.Radius - Policy Evaluation time = 14 ms
2022-02-07 09:08:29,154 [main SessId R00000295-01-620151d3] INFO RadiusServer.Radius - rlm_policy: Received Accept Enforcement Profile
2022-02-07 09:08:29,154 [main SessId R00000295-01-620151d3] INFO RadiusServer.Radius - rlm_policy: Policy Server reply does not contain Posture-Validation-Response
2022-02-07 09:08:29,154 [RequestHandler-1-0x7fd7c6bf5700 h=11915 c=R00000295-01-620151d3] INFO Core.XpipPolicyResHandler - populateResponseTlv: PETaskPostureOutput does not exist. Skip sending posture VAFs
2022-02-07 09:08:29,154 [RequestHandler-1-0x7fd7c6bf5700 h=11915 c=R00000295-01-620151d3] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2022-02-07 09:08:29,154 [RequestHandler-1-0x7fd7c6bf5700 h=11914 c=R00000295-01-620151d3] INFO Core.PolicyResCollector - getSohr: Failed to generate Sohr
2022-02-07 09:08:29,154 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Completed PETaskSessionLog **
2022-02-07 09:08:29,154 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Completed PETaskOutputPolicyRes **
2022-02-07 09:08:29,154 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - ** Completed PETaskAuthStatusInfo **
2022-02-07 09:08:29,154 [RequestHandler-1-0x7fd7c6bf5700 r=R00000295-01-620151d3 h=11901 c=R00000295-01-620151d3] INFO Core.PETaskScheduler - * PE_TASK_SCHEDULE_RADIUS Completed *

Windows 10 Security
Windows 10 Security
Windows 10: A Microsoft operating system that runs on personal computers and tablets.Security: The precautions taken to guard against crime, attack, sabotage, espionage, or another threat.
2,754 questions
Windows Server Security
Windows Server Security
Windows Server: A family of Microsoft server operating systems that support enterprise-level management, data storage, applications, and communications.Security: The precautions taken to guard against crime, attack, sabotage, espionage, or another threat.
1,720 questions
0 comments