Intermittent tacacs failure between AAA client and ACS 4.2, no network changes, path verified. Everything works fine when ACS connection established. I can only see tacacs socket opens and closes when its failing. No changes are made to the network or device configurations it works fine for a time then fails for a time then works for a time.....etc. Have tried increasing tacacs server timeout unsuccessfully.
suspected causes: -
1 - ACS 4.2 intermittently fails to respond to the client for initail handshake. Bug on ACS possibly relating to services,
or could be a timer conflict? (I can see no packet increments in sh tacacs only sockets opens and closes increment).
2 - Switch or ACS intermittently sends key in wrong format server does not respond so client timesout?
ACS presents 'Authen session timed out: Challenge not provided by client' in failed attempts log.
Also debug shows When failing the client delcares 'timed out', 'time out clean up' and 'processing the reply packet'
(suggests ACS sends a packet - but no packet increment in sh tacacs)
3 - Version comaptibilty issue
Device details: -
SWITCH
WS-C3750-24TS 12.2(55)SE4 C3750-IPSERVICESK9-M
ACS
Cisco Secure ACS 4.2.0.124
Appliance Management Software 4.2.0.124
Appliance Base Image 4.2.0.107
Debugs below caputured when tacacs connection fails and when a connection is established. When failing the client delcares 'timed out', 'time out clean up' and 'processing the reply packet' , but when successfull a 'socket event 2' can be seen.
FAILED - FALLS BACK TO LOCAL AUTH - DEBUG TACACS events/packets/authentication
13:51:12: TPLUS: Queuing AAA Authentication request 42 for processing
13:51:12: TPLUS: processing authentication start request id 42
13:51:12: TPLUS: Authentication start packet created for 42()
13:51:12: TPLUS: Using server 10.16.11.31
13:51:12: TPLUS(0000002A)/0/NB_WAIT/597CA5C: Started 5 sec timeout
13:51:17: TPLUS(0000002A)/0/NB_WAIT/597CA5C: timed out
13:51:17: TPLUS(0000002A)/0/NB_WAIT/597CA5C: timed out, clean up
13:51:17: TPLUS(0000002A)/0/597CA5C: Processing the reply packet
13:51:25: TAC+: Opening TCP/IP to 10.16.11.31/49 timeout=5
13:51:30: TAC+: TCP/IP open to 10.16.11.31/49 failed -- Connection timed out; re
mote host not responding
13:51:52: TAC+: Opening TCP/IP to 10.16.11.31/49 timeout=5
13:51:57: TAC+: TCP/IP open to 10.16.11.31/49 failed -- Connection timed out; re
mote host not responding
PASSED - TACACS and all AAA service work - DEBUG TACACS events/packets
14:04:36: T+: Version 192 (0xC0), type 1, seq 1, encryption 1
14:04:36: T+: session_id 1269367001 (0x4BA900D9), dlen 26 (0x1A)
14:04:36: T+: type:AUTHEN/START, priv_lvl:1 action:LOGIN ascii
14:04:36: T+: svc:LOGIN user_len:0 port_len:4 (0x4) raddr_len:14 (0xE) data_len:
0
14:04:36: T+: user:
14:04:36: T+: port: tty2
14:04:36: T+: rem_addr: 10.120.240.138
14:04:36: T+: data:
14:04:36: T+: End Packet
14:04:36: T+: Version 192 (0xC0), type 1, seq 2, encryption 1
14:04:36: T+: session_id 1269367001 (0x4BA900D9), dlen 16 (0x10)
14:04:36: T+: AUTHEN/REPLY status:4 flags:0x0 msg_len:10, data_len:0
14:04:36: T+: msg: Username:
14:04:36: T+: data:
14:04:36: T+: End Packet
14:04:41: TAC+: Opening TCP/IP to 10.16.11.31/49 timeout=5
14:04:41: TAC+: Opened TCP/IP handle 0x6100374 to 10.16.11.31/49 using source 10
.106.21.243
14:04:41: TAC+: periodic timer started
14:04:41: TAC+: 10.16.11.31 req=5EA6548 Qd id=2285506582 ver=192 handle=0x610037
4 expire=5 AUTHOR/START queued
14:04:41: TAC+: 10.16.11.31 id=2285506582 wrote 96 of 96 bytes
14:04:41: TAC+: 10.16.11.31 req=5EA6548 Qd id=2285506582 ver=192 handle=0x610037
4 expire=4 AUTHOR/START sent
14:04:41: TAC+: 10.16.11.31 read=12 wanted=12 alloc=12 got=12
14:04:41: TAC+: 10.16.11.31 read=18 wanted=18 alloc=18 got=6
14:04:41: TAC+: 10.16.11.31 received 18 byte reply for 5EA6548
14:04:41: TAC+: req=5EA6548 Tx id=2285506582 ver=192 handle=0x6100374 expire=4 A
UTHOR/START processed
14:04:41: TAC+: periodic timer stopped (queue empty)
14:04:41: TAC+: Closing TCP/IP 0x6100374 connection to 10.16.11.31/49
Switch#
PASSED - TACACS and all AAA service work - DEBUG TACACS events/packets/authentication
:12:06: TPLUS: Queuing AAA Authentication request 55 for processing
14:12:06: TPLUS: processing authentication start request id 55
14:12:06: TPLUS: Authentication start packet created for 55()
14:12:06: TPLUS: Using server 10.16.11.31
14:12:06: TPLUS(00000037)/0/NB_WAIT/6107BE0: Started 5 sec timeout
14:12:06: TPLUS(00000037)/0/NB_WAIT: socket event 2
14:12:06: T+: Version 192 (0xC0), type 1, seq 1, encryption 1
14:12:06: T+: session_id 4249683755 (0xFD4D072B), dlen 26 (0x1A)
14:12:06: T+: type:AUTHEN/START, priv_lvl:1 action:LOGIN ascii
14:12:06: T+: svc:LOGIN user_len:0 port_len:4 (0x4) raddr_len:14 (0xE) data_len:
0
14:12:06: T+: user:
14:12:06: T+: port: tty2
14:12:06: T+: rem_addr: 10.120.240.138
14:12:06: T+: data:
14:12:06: T+: End Packet
14:12:06: TPLUS(00000037)/0/NB_WAIT: wrote entire 38 bytes request
14:12:06: TPLUS(00000037)/0/READ: socket event 1
14:12:06: TPLUS(00000037)/0/READ: Would block while reading
14:12:06: TPLUS(00000037)/0/READ: socket event 1
14:12:06: TPLUS(00000037)/0/READ: read entire 12 header bytes (expect 16 bytes d
ata)
14:12:06: TPLUS(00000037)/0/READ: socket event 1
14:12:06: TPLUS(00000037)/0/READ: read entire 28 bytes response
14:12:06: T+: Version 192 (0xC0), type 1, seq 2, encryption 1
14:12:06: T+: session_id 4249683755 (0xFD4D072B), dlen 16 (0x10)
14:12:06: T+: AUTHEN/REPLY status:4 flags:0x0 msg_len:10, data_len:0
14:12:06: T+: msg: Username:
14:12:06: T+: data:
14:12:06: T+: End Packet
14:12:06: TPLUS(00000037)/0/6107BE0: Processing the reply packet
14:12:06: TPLUS: Received authen response status GET_USER (7)
14:12:07: TAC+: Opening TCP/IP to 10.16.11.31/49 timeout=5
14:12:08: TAC+: Opened TCP/IP handle 0x5F526DC to 10.16.11.31/49 using source 10
.106.21.243
14:12:08: TAC+: periodic timer started
14:12:08: TAC+: 10.16.11.31 req=5F52B98 Qd id=3787871813 ver=192 handle=0x5F526D
C expire=5 AUTHOR/START queued
14:12:08: TAC+: 10.16.11.31 id=3787871813 wrote 96 of 96 bytes
14:12:08: TAC+: 10.16.11.31 req=5F52B98 Qd id=3787871813 ver=192 handle=0x5F526D
C expire=4 AUTHOR/START sent
14:12:08: TAC+: 10.16.11.31 read=12 wanted=12 alloc=12 got=12
14:12:08: TAC+: 10.16.11.31 read=18 wanted=18 alloc=18 got=6
14:12:08: TAC+: 10.16.11.31 received 18 byte reply for 5F52B98
14:12:08: TAC+: req=5F52B98 Tx id=3787871813 ver=192 handle=0x5F526DC expire=4 A
UTHOR/START processed
14:12:08: TAC+: periodic timer stopped (queue empty)
14:12:08: TAC+: Closing TCP/IP 0x5F526DC connection to 10.16.11.31/49
14:13:05: TAC+: Opening TCP/IP to 10.16.11.31/49 timeout=5
14:13:05: TAC+: Opened TCP/IP handle 0x6106380 to 10.16.11.31/49 using source 10
.106.21.243
14:13:05: TAC+: periodic timer started
14:13:05: TAC+: 10.16.11.31 req=5F52B98 Qd id=2567533126 ver=192 handle=0x610638
0 expire=5 AUTHOR/START queued
14:13:06: TAC+: 10.16.11.31 id=2567533126 wrote 102 of 102 bytes
14:13:06: TAC+: 10.16.11.31 req=5F52B98 Qd id=2567533126 ver=192 handle=0x610638
0 expire=4 AUTHOR/START sent
14:13:06: TAC+: 10.16.11.31 read=12 wanted=12 alloc=12 got=12
14:13:06: TAC+: 10.16.11.31 read=18 wanted=18 alloc=18 got=6
14:13:06: TAC+: 10.16.11.31 received 18 byte reply for 5F52B98
14:13:06: TAC+: req=5F52B98 Tx id=2567533126 ver=192 handle=0x6106380 expire=4 A
UTHOR/START processed
14:13:06: TAC+: periodic timer stopped (queue empty)
14:13:06: TAC+: Closing TCP/IP 0x6106380 connection to 10.16.11.31/49
14:13:18: %SYS-5-CONFIG_I: Configured from console by ddaley on vty0 (10.120.240
.138)
14:13:23: TAC+: Opening TCP/IP to 10.16.11.31/49 timeout=5
14:13:23: TAC+: Opened TCP/IP handle 0x5F526DC to 10.16.11.31/49 using source 10
.106.21.243
14:13:23: TAC+: periodic timer started
14:13:23: TAC+: 10.16.11.31 req=610683C Qd id=483402383 ver=192 handle=0x5F526DC
expire=5 AUTHOR/START queued
14:13:23: TAC+: 10.16.11.31 id=483402383 wrote 96 of 96 bytes
14:13:23: TAC+: 10.16.11.31 req=610683C Qd id=483402383 ver=192 handle=0x5F526DC
expire=4 AUTHOR/START sent
14:13:23: TAC+: 10.16.11.31 read=12 wanted=12 alloc=12 got=12
14:13:23: TAC+: 10.16.11.31 read=18 wanted=18 alloc=18 got=6
14:13:23: TAC+: 10.16.11.31 received 18 byte reply for 610683C
Switch#
