Hoog CPU-gebruik door alarmloggerproces op routers met IOS-XR

Inleiding

tacacs is een IOS XR proces dat is geassocieerd met Tacacs AAA service. Dit document bespreekt een softwarebug en zijn symptomen die ervoor kunnen zorgen dat routers met IOS XR versie 4.2.X of lager een constant hoog CPU-gebruik kunnen waarnemen.

Voorwaarden

Er zijn geen specifieke vereisten van toepassing op dit document.

Gebruikte componenten

Het probleem dat in dit document wordt besproken, is van toepassing op Cisco GSR, ASR 9000, CRS en andere routers met IOS XR. De hieronder gebruikte uitgangen zijn genomen van een laboratoriumrouter die IOS XR versie lager dan 4.2.X in werking stelt. 

Probleem

Routers met IOS XR versie 4.2.X of lager kunnen een constant hoog CPU-gebruik waarnemen vanwege een alarmregistratieproces vanwege een bekende software bug. Toon proces cpu output zou tonen alarmlogboek proces verbruikend maximumhoeveelheid CPU gebruik.

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 de logboekbuffer kan u aanhoudende logbestanden te zien gelijkend op:

tacacsd[XXXX]: %SECURITY-TACACSD-7-GENERIC_ERROR: Aanvraag voor: toets -XXXXX/XXXX/XXXX sessie XXXXX mislukt

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

 details van alarmloggers en tacsd-processen kunnen als volgt worden samengevat.

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>

Hoge CPU wordt veroorzaakt door vloed van syslog berichten waardoor alarm-logger buffer om volledig te krijgen. Daarom blijft het alarmloggerproces druk bezig om het bericht te behandelen en tegelijk tegenover buffer volledige voorwaarde te staan.  In dit geval is het TACACS-proces een overweldigende alarmlogger. Omdat alarmlogger een slachtoffer is, zal het opnieuw starten van alarmlogger proces niet helpen als gedeelde geheugenbuffer blijft vasthouden na het opnieuw opstarten van het proces.

Oplossing

Dit probleem is aangepakt en opgelost via software bug CSCuh98484 - Tacacsd "Fout bij ophalen verzoek om sleutel" fout veroorzaakt hoge CPU. Bug details zijn hier aanwezig

Houd er rekening mee dat het opnieuw starten van het tacsd-proces een tijdelijke oplossing is die de logbestanden moet stoppen en dat het CPU-gebruik moet terugkeren naar het normale niveau. Het herstarten van tacsd-proces zal geen invloed hebben op enige functionaliteit of gegevenspakketdoorsturen, het zal het proces in zijn initiële status.

Deze bug is opgelost in de volgende IOS XR versies.