TACACS authentication fails with error: Connection closed by remote end [edited]

By API User posted Jan 20, 2021 08:02 PM

  
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.

0 comments
0 views