IOS-XR を実行するルータでのアラーム ロガー プロセスによる高い CPU 使用率

はじめに

tacacsd は、Tacacs AAA サービスに関連する IOS XR プロセスです。このドキュメントでは、IOS XR バージョン 4.2.X またはそれより前のバージョンが動作しているルータで、CPU 使用率が常に高くなる原因となりうるソフトウェア バグ、およびその症状について説明します。

前提条件

このドキュメントに関する固有の要件はありません。

使用するコンポーネント

このドキュメントに記載されている問題は、IOS XR を実行する Cisco GSR、ASR9000、CRS などのルータに当てはまります。以下で使用されている出力は、4.2.X よりも前のバージョンの IOS が動作しているラボのルータの出力です。 

問題

IOS XR バージョン 4.2.X、またはそれより前のバージョンが動作しているルータは、既知のソフトウェア バグによるアラーム ロガー プロセスが原因で、CPU 使用率が常に高くなる可能性があります。show process cpu の出力に、alarm-logger プロセスが最大 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>

ロギング バッファに、次のようなログが続いて記録される可能性があります。

tacacsd[XXXX]: %SECURITY-TACACSD-7-GENERIC_ERROR：キー – 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 および tacacsd プロセスの詳細として次のようなものが示される可能性があります。

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>

syslog メッセージが大量に発生して、アラーム ロガーのバッファがいっぱいになった結果、CPU 使用率が高くなっています。そのため、アラーム ロガー プロセスは、バッファーがいっぱいの状況で、メッセージの処理に追われ続けています。  このような場合は、TACACS プロセスがアラーム ロガーを圧倒することになります。アラーム ロガーは被害を受ける側であるため、アラーム ロガー プロセスを再起動したとしても改善はされません。これは、共有メモリ バッファがプロセスの再起動後にも残っているためです。

解決方法

この問題は、ソフトウェアのバグCSCuh98484で解決されています - Tacacsd「Failed to get request for key」エラーが原因でCPU使用率が高くなる。バグの詳細はこちらをご覧ください。

回避策として tacacsd プロセスを再起動すると、ログが停止し、CPU 使用率が通常のレベルに戻ります。tacacsd プロセスを再起動しても、プロセスが初期状態に戻るだけで、他の機能やパケット転送への影響はありません。

このバグは、次の IOS XR バージョンでは修正済みです。