Problem:
TACACS authentication fails with error: Connection closed by remote end
Diagnostics:
Below is a TACACS request that failed with the error:Connection closed by remote end
Request Details Summary -
Session ID: T00017aa9-15-5e417444
Date and Time: Feb 10, 2020 15:18:30 UTC
Username: 43******
Status: UnknownAuthenStatus[0]
Request Type: TACACS_AUTHENTICATION
Authorizations: 0
Client IP Address/Port: x.x.131.78:unknown
Remote IP Address: unknown
Policies Used -
Service: CLEARPASS-TACACS-AUTH
Authentication Source:
Roles:
Enforcement Profiles:
Authentication Request Messages -
Error Category: Internal error
Error Code: Internal error in performing authentication
Alerts for this Request -
Tacacs server: Connection closed by remote end
To identify the issue, you need to have "Tacacs server" service in DEBUG. Navigate to Administartion->Server Manager->Log Configuration. From the drop down, select the service as Tacacs server and place the default log level to "DEBUG" and save the config.
Replicate the issue by connecting to NAD and export the access tracker log (Monitoring->Access Tracker). Click on the request and click "Export" or you can click on "Show Logs" to view the logs
After the access tracker log is exported, navigate to Administration->Server Manager->Log Configuration. From the drop down, select the service as Tacacs server and place the default log level as shown below and save the config:
From the access tracker log exported, we can see that the response from token server(x.x.24.12) was received in Clearpass at 15:18:32 as (highlighted below in green) in the access tracker log and the TACACS session was closed by NAD(x.x.131.78) prior at 15:18:30(highlighted in red)
2020-02-10 15:18:28,989 [AAAModuleThread-0x7f73b4f7e700 h=415337 c=T00017aa9-15-5e417444] DEBUG AAA.AAASession - startAuthentication: AuthenticationRequest={requestId=369469-3706296546-1581347908-514643, username=43*****, service=CLEARPASS-TACACS-AUTH)}
2020-02-10 15:18:28,989 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643] DEBUG EF.HandlerThread - processEvent: [Event::Type=160 Name=HttpRequestEv RequestId=369469-3706296546-1581347908-514643 SourceHandlerAddr=EventHandlerAddr:<HandlerId=415337, Queue=AAAModuleQ> TargetHandlerAddr=EventHandlerAddr:<HandlerId=0, Queue=HttpModuleQ> Priority=2] Http server Id=1 context=AuthenService Method=1 Path=
2020-02-10 15:18:28,989 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643] DEBUG EF.HandlerThread - processEvent: [Event::Type=160 Name=HttpRequestEv RequestId=369469-3706296546-1581347908-514643 SourceHandlerAddr=EventHandlerAddr:<HandlerId=415337, Queue=AAAModuleQ> TargetHandlerAddr=EventHandlerAddr:<HandlerId=0, Queue=HttpModuleQ> Priority=2] Http server Id=1 context=AuthenService Method=1 Path=
2020-02-10 15:18:28,989 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643] DEBUG EF.HandlerThread - Event type=160 name=HttpRequestEv Handled by handler: {name=HttpEventHandler id=203}
2020-02-10 15:18:28,989 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643 h=203] DEBUG EF.BasicEventHandler - Handling event: [Event::Type=160 Name=HttpRequestEv RequestId=369469-3706296546-1581347908-514643 SourceHandlerAddr=EventHandlerAddr:<HandlerId=415337, Queue=AAAModuleQ> TargetHandlerAddr=EventHandlerAddr:<HandlerId=0, Queue=HttpModuleQ> Priority=2] Http server Id=1 context=AuthenService Method=1 Path=
2020-02-10 15:18:28,989 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643 h=203] DEBUG EF.BasicEventHandler - Handling event: [Event::Type=160 Name=HttpRequestEv RequestId=369469-3706296546-1581347908-514643 SourceHandlerAddr=EventHandlerAddr:<HandlerId=415337, Queue=AAAModuleQ> TargetHandlerAddr=EventHandlerAddr:<HandlerId=0, Queue=HttpModuleQ> Priority=2] Http server Id=1 context=AuthenService Method=1 Path=
2020-02-10 15:18:28,989 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643 h=203] DEBUG EF.BasicEventHandler - Found registered handler for event name=HttpRequestEv
2020-02-10 15:18:28,989 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643 h=203] DEBUG BaseExtSvr.DefaultFailOverPolicy - HostList: http://127.0.0.1:8080/networkservices/webauthservice/BasicAuthentication
2020-02-10 15:18:28,989 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643 h=203] DEBUG BaseExtSvr.ExtSvrSession - Got host list for manager=AuthenService. Number of hosts=1
2020-02-10 15:18:28,990 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643 h=203] DEBUG BaseExtSvr.ExtSvrSession - Hosts=: http://127.0.0.1:8080/networkservices/webauthservice/BasicAuthentication
2020-02-10 15:18:28,990 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643 h=203] DEBUG BaseExtSvr.ExtSvrSession - checkRetryCurrentHandle: Null manager or current hostId. Skip retry.
2020-02-10 15:18:28,990 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643 h=203] DEBUG BaseExtSvr.ExtSvrSession - getNextHandle: Getting handle to hostId=http://127.0.0.1:8080/networkservices/webauthservice/BasicAuthentication
2020-02-10 15:18:28,990 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643 h=203] DEBUG BaseExtSvr.ExtSvrManager - getHandle: Manager=AuthenService Host Id=http://127.0.0.1:8080/networkservices/webauthservice/BasicAuthentication
2020-02-10 15:18:28,990 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643 h=203] DEBUG BaseExtSvr.ExtSvrManager - Returning handle from pool for SvrManager=AuthenService HostId=http://127.0.0.1:8080/networkservices/webauthservice/BasicAuthentication
2020-02-10 15:18:28,990 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643 h=203] DEBUG BaseExtSvr.ExtSvrSession - getNextHandle: Got a handle to hostId=http://127.0.0.1:8080/networkservices/webauthservice/BasicAuthentication
2020-02-10 15:18:30,887 [AAAModuleThread-0x7f73b4f7e700 h=415337 c=T00017aa9-15-5e417444] DEBUG EF.BasicEventHandler - Handling event: [Event::Type=604 Name=TacacsStopSessionEv RequestId= SourceHandlerAddr=EventHandlerAddr:<HandlerId=0, Queue=<None>> TargetHandlerAddr=EventHandlerAddr:<HandlerId=415337, Queue=AAAModuleQ> Priority=2]
2020-02-10 15:18:30,887 [AAAModuleThread-0x7f73b4f7e700 h=415337 c=T00017aa9-15-5e417444] DEBUG EF.BasicEventHandler - No registered handler. Looking in common handlermap for event name=TacacsStopSessionEv. Got handler=1
2020-02-10 15:18:30,887 [AAAModuleThread-0x7f73b4f7e700 h=415337 c=T00017aa9-15-5e417444] DEBUG AAA.AuthenSession - handleTacacsStopSessionEv: TacacsId::<369469-3706296546>
2020-02-10 15:18:30,888 [AAAModuleThread-0x7f73b4f7e700 h=415337 c=T00017aa9-15-5e417444] DEBUG AAA.AuthenHandler - removeSession: TacacsId::<369469-3706296546>
2020-02-10 15:18:30,888 [AAAModuleThread-0x7f73b4f7e700 h=415337 c=T00017aa9-15-5e417444] DEBUG EF.HandlerThread - Queueing event handler for remove to thread=AAAModuleThread with id=415337
2020-02-10 15:18:32,942 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643 h=203] DEBUG BaseExtSvr.ExtSvrManager - putHandle: Manager=AuthenService. Returning handle for host=http://127.0.0.1:8080/networkservices/webauthservice/BasicAuthentication to pool
2020-02-10 15:18:32,942 [HttpModule-ThreadPool-52-0x7f73bb3f9700 r=369469-3706296546-1581347908-514643 h=203] DEBUG EF.SignalableQ - Enqueueing event with name=HttpResponseEv Queue=AAAModuleQ
2020-02-10 15:18:32,943 [AAAModuleThread-0x7f73b4f7e700 r=369469-3706296546-1581347908-514643] DEBUG EF.HandlerThread - processEvent: [Event::Type=161 Name=HttpResponseEv RequestId=369469-3706296546-1581347908-514643 SourceHandlerAddr=EventHandlerAddr:<HandlerId=203, Queue=HttpModuleQ> TargetHandlerAddr=EventHandlerAddr:<HandlerId=415337, Queue=AAAModuleQ> Priority=2] context=AuthenService Status code=200 Data=<?xml version="1.0" encoding="UTF-8" standalone="yes"?><AuthenticationResponse xmlns="http://www.avendasys.com"><RequestId>369469-3706296546-1581347908-514643</RequestId><Status>202</Status><StatusMessage>Request rejected for user='43******' by token-server=AUTH-SOURCE-CLEARPASS-TACACS Token Server(x.x.24.12)</StatusMessage><AuthSource>AUTH-SOURCE-CLEARPASS-TACACS Token Server</AuthSource></AuthenticationResponse> Alerts=
From pcap, we can see that session was closed by NAD IP:x.x.131.78 at 15:18:30 (frame no:861)
From pcap, we can see that Clearpass received the response from token server(x.x.24.12) at 15:18:32 (which is seen in tacacs log as highlighted above as well). As the session was closed by NAD device:x.x.131.78 by 15:18:30, in access tracker we see the error: Connection closed by remote end.
Solution
Fix is to ensure if the session timeout can be increased in NAD device. In above example, from 2sec to 5sec so that the NAD device does not close the connection with Clearpass before auth response is received from token server (OR) check why there is a delay in response from token server for authentication and if taken server can respond for auth request from Clearpass sooner than 2 sec in above example.