Contents

Introduction

Prerequisites

Components Used

Problem

Solution

Introduction

tacacsd is an IOS XR process which is associated with Tacacs AAA service. This document discusses a software bug and its symptoms which can cause routers running IOS XR version 4.2.X or lower to observe constant high CPU utilization.

Prerequisites

There are no specific requirements for this document.

Components Used

Problem addressed in this document applies to Cisco GSR, ASR9000, CRS and other routers running IOS XR. The outputs used below have been taken from a lab router running IOS XR version lower than 4.2.X.

Problem

Routers running IOS XR version 4.2.X or lower may observe constant high CPU utilization due to alarm-logger process due to a known software bug. Show process cpu output would show alarm-logger process consuming maximum amount of CPU utilization.

show proc cpu | ex "0% 0% 0%"

CPU utilization for one minute: 100%; five minutes: 100%; fifteen minutes: 100%

PID 1Min 5Min 15Min Process

<snip>

53281 2% 2% 2% syslogd_helper

57379 1% 1% 1% fabricq_prp_driver

69636 1% 1% 1% correlatord

69677 6% 6% 6% syslogd

118842 1% 1% 1% sysdb_svr_local

122962 3% 3% 3% gsp

229604 2% 2% 2% eem_ed_syslog

262456 1% 1% 1% tacacsd

452726918 67% 71% 72% alarm-logger

463302887 1% 1% 1% exec

<snip>

In logging buffer you may see continous logs similar to:

tacacsd[XXXX]: %SECURITY-TACACSD-7-GENERIC_ERROR : Failed to get request for: key -XXXXX/XXXX/XXXX/XXXX session XXXXX

show log

<snip>

RP/0/7/CPU0:Dec 26 04:02:03.149 : tacacsd[1110]: %SECURITY-TACACSD-6-SERVER_UP :

TACACS+ server 32.95.X.X/XXXX is UP

RP/0/7/CPU0:Dec 26 04:02:05.956 : tacacsd[1110]: %SECURITY-TACACSD-6-SERVER_DOWN :

TACACS+ server 32.95.X.X/XXXX is DOWN - Socket 43: Connection timed out

RP/0/7/CPU0:Dec 26 04:02:09.468 : tacacsd[1110]: %SECURITY-TACACSD-6-SERVER_DOWN :

TACACS+ server 199.37.X.X/XXXX is DOWN - Socket 43: Connection timed out

RP/0/7/CPU0:Dec 26 04:02:09.647 : tacacsd[1110]: %SECURITY-TACACSD-6-TIMEOUT_IGNORED :

A time out event has been ignored for context key -953829129/1073/60000000/6486405

(session 6486405)

RP/0/7/CPU0:Dec 26 04:02:11.647 : tacacsd[1110]: %SECURITY-TACACSD-7-GENERIC_ERROR :

Failed to get request for: key -953829129/1073/60000000/6486405 session 105407493

RP/0/0/CPU0:last message repeated 520 times

RP/0/7/CPU0:Dec 26 04:02:34.064 : tacacsd[1110]: %SECURITY-TACACSD-6-SERVER_UP :

TACACS+ server 32.95.X.X/XXXX is UP

RP/0/7/CPU0:Dec 26 04:02:34.064 : tacacsd[1110]: %SECURITY-TACACSD-7-GENERIC_ERROR :

Failed to get request for: key -953829129/1073/60000000/6486405 session 105407493

alarm-logger and tacacsd processes details can be seen as below.

show processes alarm-logger

<snip>

Job Id: 114

PID: 135303

Executable path: /c12k-os-4.2.4/sbin/alarm-logger

Instance #: 1

Version ID: 00.00.0000

Respawn: ON

Respawn count: 1

Max. spawns per minute: 12

Last started: Tue Aug 13 02:17:23 2013

Process state: Run

Package state: Normal

core: MAINMEM

Max. core: 0

Level: 91

Placement: None

startup_path: /pkg/startup/alarm-logger.startup

Ready: 0.672s

Process cpu time: 1401.018 user, 49.774 kernel, 1450.792 total

JID TID Stack pri state TimeInState HR:MM:SS:MSEC NAME

114 1 88K 10 Receive 0:00:02:0071 0:00:40:0919 alarm-logger

114 2 88K 10 Receive 3242:46:17:0308 0:00:00:0000 alarm-logger

114 3 88K 10 Reply 0:00:00:0000 0:23:08:0029 alarm-logger

114 4 88K 10 Mutex 0:00:00:0000 0:00:21:0957 alarm-logger

-------------------------------------------------------------------------------

<snip>

show processes tacacsd

<snip>

Job Id: 1110

PID: 266551

Executable path: /disk0/iosxr-infra-4.2.4/bin/tacacsd

Instance #: 1

Version ID: 00.00.0000

Respawn: ON

Respawn count: 1

Max. spawns per minute: 12

Last started: Tue Aug 13 02:23:47 2013

Process state: Run

Package state: Normal

Started on config: cfg/gl/aaa/tacacs/

Process group: central-services

core: MAINMEM

Max. core: 0

Placement: Placeable

startup_path: /pkg/startup/tacacsd.startup

Ready: 3.954s

Process cpu time: 1010.118 user, 185.932 kernel, 1196.050 total

JID TID Stack pri state TimeInState HR:MM:SS:MSEC NAME

1110 1 108K 16 Sigwaitinfo 3242:46:40:0742 0:00:00:0116 tacacsd

1110 2 108K 10 Nanosleep 0:01:03:0835 0:00:00:0019 tacacsd

1110 3 108K 10 Receive 3242:46:41:0593 0:00:00:0002 tacacsd

1110 4 108K 10 Reply 0:00:00:0000 0:08:55:0970 tacacsd

1110 5 108K 16 Receive 3242:46:40:0771 0:00:00:0000 tacacsd

1110 6 108K 10 Receive 0:07:07:0403 0:04:03:0462 tacacsd

1110 7 108K 10 Receive 0:00:01:0389 0:03:28:0939 tacacsd

1110 8 108K 10 Receive 0:00:01:0332 0:03:03:0622 tacacsd

-------------------------------------------------------------------------------

<snip>

High CPU is caused due to flood of syslog messages causing alarm-logger buffer to get full. Hence alarm-logger process remains busy trying to handle the message and facing buffer full condition at the same time.  In this case, TACACS process is overwhelming alarm-logger. As alarm-logger is a victim, restarting alarm-logger process will not help as shared memory buffer remains persistent after process restart.

Solution

This issue has been addressed and fixed via software bug CSCuh98484 - Tacacsd "Failed to get request for key" error causes high CPU. Bug details are present here

Please note that restarting tacacsd process is a workaround which should stop the logs and CPU utilization should return to normal level. Restarting tacacsd process will not affect any functionality or data packet forwarding, it will put the process in its initial state.

This bug has been fixed in following IOS XR versions.

4.3.2.SP2

4.3.2.SP3

4.3.2.SP5

4.3.2.SP6

4.3.2.SP7

4.3.2.SP8