Elevato utilizzo della CPU da parte del processo alarm-logger sui router con IOS-XR

Introduzione

tacacsd è un processo IOS XR associato al servizio Tacacs AAA. In questo documento viene descritto un bug software e i suoi sintomi che possono causare il costante e elevato utilizzo della CPU da parte dei router con IOS XR versione 4.2.X o precedenti.

Prerequisiti

Nessun requisito specifico previsto per questo documento.

Componenti usati

Il problema illustrato in questo documento si applica a Cisco GSR, ASR9000, CRS e altri router con IOS XR. Gli output usati di seguito sono stati presi da un router lab con IOS XR versione precedente alla 4.2.X. 

Problema

I router con IOS XR versione 4.2.X o inferiore possono rilevare un elevato utilizzo della CPU costante a causa del processo di registrazione degli allarmi dovuto a un bug noto del software. Mostra l'output della CPU del processo indica che il processo di registrazione degli allarmi utilizza la massima quantità di CPU.

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>

Nel buffer di registrazione è possibile visualizzare registri continui simili a:

tacacsd[XXXX]: %SECURITY-TACACSD-7-GENERIC_ERROR: impossibile ottenere la richiesta per: chiave -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

 i dettagli dei processi alarm-logger e tacacsd sono riportati di seguito.

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>

Un elevato livello di CPU è causato da un'ondata di messaggi syslog che causano il pieno utilizzo del buffer del registratore di allarmi. Quindi il processo di alarm-logger rimane occupato, cercando di gestire il messaggio e affrontando la condizione di buffer pieno allo stesso tempo.  In questo caso, il processo TACACS è uno strumento di registrazione degli allarmi impressionante. Poiché alarm-logger è una vittima, il riavvio del processo alarm-logger non sarà di aiuto in quanto il buffer di memoria condivisa rimane persistente dopo il riavvio del processo.

Soluzione

Il problema è stato risolto e risolto con il bug software CSCuh98484 - L'errore Tacacsd "Failed to get request for key" (Impossibile ottenere la richiesta per la chiave) causa un utilizzo elevato della CPU. Qui sono riportati i dettagli dei bug

Notare che il riavvio del processo tacacsd è una soluzione che dovrebbe arrestare i registri e l'utilizzo della CPU dovrebbe tornare al livello normale. Il riavvio del processo tacacsd non influirà sulle funzionalità o sull'inoltro dei pacchetti di dati, ma metterà il processo nello stato iniziale.

Questo bug è stato risolto nelle seguenti versioni di IOS XR.