對多個資料處理卡因過多的npumgr崩潰而關閉進行故障排除

簡介

本文說明如何解決由於npumgr崩潰而在極短時間內關閉多個資料處理卡(DPC)時出現的問題。

必要條件

需求

思科建議您瞭解以下主題：

• ASR5000/5500的硬體知識
• StarOS
• 路由基礎知識

採用元件

本文件所述內容不限於特定軟體和硬體版本。

本文中的資訊是根據特定實驗室環境內的裝置所建立。文中使用到的所有裝置皆從已清除（預設）的組態來啟動。如果您的網路運作中，請確保您瞭解任何指令可能造成的影響

縮寫

SPGW	服務和封包資料網路閘道器
DPC	資料處理卡
VLAN	虛擬區域網
NPU	網路處理單元

問題 

作為計畫活動的一部分，新介面在VLAN中繫結到已完成的埠。本練習的第二部分是通過這些介面建立靜態路由。為流量開啟VLAN後，npumgr立即崩潰並隨後使所有DPC卡多次關閉。

疑難排解 

本節提供的資訊用於解決由於npumgr崩潰而在極短時間內關閉多個DPC卡的問題。

此處顯示收集的Show Support Details(SSD)、活動日誌和覆蓋問題日誌的系統日誌。首先，檢查rct統計資訊以確定這些關閉的原因。在此可以看到，它們由於過多的npumgr崩潰而關閉。

******** show rct stats verbose *******
Thursday September 19 03:57:04 IST 2019
RCT stats details (Last 18 Actions)
 #  Action        Type      From  To  Start Time                Duration     Status 
--- ------------- --------- ---- ---- ------------------------  -----------  -------
 7  Shutdown      N/A         2   10  2019-Sep-19+00:09:51.587    2.322 sec  Success 
 8  Shutdown      N/A         1    0  2019-Sep-19+00:10:14.541    0.005 sec  Success 
 9  Shutdown      N/A         3    0  2019-Sep-19+00:10:44.625    0.005 sec  Success 
10  Shutdown      N/A         4    0  2019-Sep-19+00:11:03.428    0.005 sec  Success 
11  Shutdown      N/A         7    0  2019-Sep-19+00:11:34.771    0.478 sec  Success 
12  Shutdown      N/A         8    0  2019-Sep-19+00:11:54.328    0.005 sec  Success 
13  Shutdown      N/A         9    0  2019-Sep-19+00:12:19.656    0.005 sec  Success 
14  Shutdown      N/A        10    0  2019-Sep-19+00:12:39.706    0.004 sec  Success 
15  Shutdown      N/A         1    9  2019-Sep-19+00:32:30.567    0.005 sec  Success 
16  Shutdown      N/A         2    0  2019-Sep-19+00:32:36.282    0.031 sec  Success 
17  Shutdown      N/A         3    0  2019-Sep-19+00:32:56.456    0.005 sec  Success 
18  Shutdown      N/A         4    0  2019-Sep-19+00:33:30.426    0.005 sec  Success 

RCT stats summary
-----------------
Migrations        =   2,  Average time = 10.890 sec
  Management Card =   2,  Average time = 10.890 sec
  Packet Card     =   0
Switchovers       =   2,  Average time = 18.526 sec

RCT stats verbose
-----------------
Stats  7:
  Action            : Shutdown
  Type              : N/A
  From              : 2
  To                : 10
  Start Time        : 2019-Sep-19+00:09:51.587
  Failure Reason    : NPUMGR_TOO_MANY_CRASHES
  Failure Device    : CARD
  Is Card Usable    : Yes
  Recovery Status   : Success
  Facility          : N/A
  Instance          : N/A
  Duration          : 2.322 sec
  Graceful          : Enabled

Stats  8:
  Action            : Shutdown
  Type              : N/A
  From              : 1
  To                : 0
  Start Time        : 2019-Sep-19+00:10:14.541
  Failure Reason    : NPUMGR_TOO_MANY_CRASHES
  Failure Device    : CARD
  Is Card Usable    : Yes
  Recovery Status   : Success
  Facility          : N/A
  Instance          : N/A
  Duration          : 0.005 sec
  Graceful          : Enabled

Stats  9:
  Action            : Shutdown
  Type              : N/A
  From              : 3
  To                : 0
  Start Time        : 2019-Sep-19+00:10:44.625
  Failure Reason    : NPUMGR_TOO_MANY_CRASHES
  Failure Device    : CARD
  Is Card Usable    : Yes
  Recovery Status   : Success
  Facility          : N/A
  Instance          : N/A
  Duration          : 0.005 sec
  Graceful          : Enabled

Stats 10:
  Action            : Shutdown
  Type              : N/A
  From              : 4
  To                : 0
  Start Time        : 2019-Sep-19+00:11:03.428
  Failure Reason    : NPUMGR_TOO_MANY_CRASHES
  Failure Device    : CARD
  Is Card Usable    : Yes
  Recovery Status   : Success
  Facility          : N/A
  Instance          : N/A
  Duration          : 0.005 sec
  Graceful          : Enabled

Stats 11:
  Action            : Shutdown
  Type              : N/A
  From              : 7
  To                : 0
  Start Time        : 2019-Sep-19+00:11:34.771
  Failure Reason    : NPUMGR_TOO_MANY_CRASHES
  Failure Device    : CARD
  Is Card Usable    : Yes
  Recovery Status   : Success
  Facility          : N/A
  Instance          : N/A
  Duration          : 0.478 sec
  Graceful          : Enabled

Stats 12:
  Action            : Shutdown
  Type              : N/A
  From              : 8
  To                : 0
  Start Time        : 2019-Sep-19+00:11:54.328
  Failure Reason    : NPUMGR_TOO_MANY_CRASHES
  Failure Device    : CARD
  Is Card Usable    : Yes
  Recovery Status   : Success
  Facility          : N/A
  Instance          : N/A
  Duration          : 0.005 sec
  Graceful          : Enabled

Stats 13:
  Action            : Shutdown
  Type              : N/A
  From              : 9
  To                : 0
  Start Time        : 2019-Sep-19+00:12:19.656
  Failure Reason    : NPUMGR_TOO_MANY_CRASHES
  Failure Device    : CARD
  Is Card Usable    : Yes
  Recovery Status   : Success
  Facility          : N/A
  Instance          : N/A
  Duration          : 0.005 sec
  Graceful          : Enabled

Stats 14:
  Action            : Shutdown
  Type              : N/A
  From              : 10
  To                : 0
  Start Time        : 2019-Sep-19+00:12:39.706
  Failure Reason    : NPUMGR_TOO_MANY_CRASHES
  Failure Device    : CARD
  Is Card Usable    : Yes
  Recovery Status   : Success
  Facility          : N/A
  Instance          : N/A
  Duration          : 0.004 sec
  Graceful          : Enabled

Stats 15:
  Action            : Shutdown
  Type              : N/A
  From              : 1
  To                : 9
  Start Time        : 2019-Sep-19+00:32:30.567
  Failure Reason    : NPUMGR_TOO_MANY_CRASHES
  Failure Device    : CARD
  Is Card Usable    : Yes
  Recovery Status   : Success
  Facility          : N/A
  Instance          : N/A
  Duration          : 0.005 sec
  Graceful          : Enabled

Stats 16:
  Action            : Shutdown
  Type              : N/A
  From              : 2
  To                : 0
  Start Time        : 2019-Sep-19+00:32:36.282
  Failure Reason    : NPUMGR_TOO_MANY_CRASHES
  Failure Device    : CARD
  Is Card Usable    : Yes
  Recovery Status   : Success
  Facility          : N/A
  Instance          : N/A
  Duration          : 0.031 sec
  Graceful          : Enabled

Stats 17:
  Action            : Shutdown
  Type              : N/A
  From              : 3
  To                : 0
  Start Time        : 2019-Sep-19+00:32:56.456
  Failure Reason    : NPUMGR_TOO_MANY_CRASHES
  Failure Device    : CARD
  Is Card Usable    : Yes
  Recovery Status   : Success
  Facility          : N/A
  Instance          : N/A
  Duration          : 0.005 sec
  Graceful          : Enabled

Stats 18:
  Action            : Shutdown
  Type              : N/A
  From              : 4
  To                : 0
  Start Time        : 2019-Sep-19+00:33:30.426
  Failure Reason    : NPUMGR_TOO_MANY_CRASHES
  Failure Device    : CARD
  Is Card Usable    : Yes
  Recovery Status   : Success
  Facility          : N/A
  Instance          : N/A
  Duration          : 0.005 sec
  Graceful          : Enabled

然後，檢查npumgr崩潰的詳細資訊。在此，您會看到npumgr在函式nexthop_get處崩潰。因此，當您嘗試獲取下一跳時，您會看到一些問題的指示。

********************* CRASH #09 ***********************
SW Version          : 21.9.7
Similar Crash Count : 16
Time of First Crash : 2019-Sep-19+00:08:16

Assertion failure at npu/npumgr/ares_npumgr_forwarding_handler.c:1829
  Function: ares_npumgr_nexthop_get()
  Expression: (nh_id) >= 0 && (nh_id) < ares_npumgr_db_get_count(SN_NPUSHM_TABREC_NH, (ares_inst)->profile)
  Proclet: npumgr (f=103000,i=30)
  Process: card=3 cpu=0 arch=X pid=7066 cpu=~0% argv0=npumgr
  Crash time: 2019-Sep-18+19:01:11 UTC
  Recent errno: 11 Resource temporarily unavailable
  Build_number: 71001
  Stack (18024@0x0xffff0000):
    [ffffe430/X] __kernel_vsyscall() sp=0xffff0428
    [0c7df834/X] sn_assert() sp=0xffff0468
    [002fcedb/X] ares_npumgr_nexthop_get() sp=0xffff04b8
    [002feb23/X] ares_npumgr_fwd_ddf2_tcam_entry_update() sp=0xffff0948
    [00301896/X] ares_npumgr_lpm_add() sp=0xffff0e98
    [003c4345/X] ares_npumgr_fwd_add() sp=0xffff1768
    [003e38fa/X] ares_npumgr_fwd_func() sp=0xffff1bf8
    [003e444a/X] ares_sn_npumgr_forwarding_add_del_mod_handler() sp=0xffff2048
    [0c892918/X] sn_msg_arriving_handle() sp=0xffff4138
    [0c8713a6/X] sn_loop_run() sp=0xffff45e8
    [0c55a3b5/X] main() sp=0xffff4658
*******************************************************

********************* CRASH #10 ***********************
SW Version          : 21.9.7
Similar Crash Count : 1
Time of First Crash : 2019-Sep-19+00:31:22

Assertion failure at npu/npumgr/ares_npumgr_port_handler.c:8409
  Note: failed to find index of created lport 5/11#11-65: status=SN_STATUS_FAILURE[1]
  Function: ares_sn_npumgr_port_lp_create_func()
  Expression: 0
  Code: CRASH
  Proclet: npumgr (f=103000,i=11)
  Process: card=1 cpu=1 arch=X pid=7181 argv0=npumgr
  Crash time: 2019-Sep-18+19:01:22 UTC
  Recent errno: 11 Resource temporarily unavailable
  Build_number: 71001
  Stack (14728@0x0xffcb8000):
    [ffffe430/X] __kernel_vsyscall() sp=0xffcb8a48
    [0c7df834/X] sn_assert() sp=0xffcb8a88
    [003bd590/X] ares_sn_npumgr_port_lp_create_func() sp=0xffcb8f18
    [003c10d4/X] ares_sn_npumgr_port_lp_create_handler() sp=0xffcb9368
    [0c892918/X] sn_msg_arriving_handle() sp=0xffcbb458
    [0c8713a6/X] sn_loop_run() sp=0xffcbb908
    [0c55a3b5/X] main() sp=0xffcbb978
*******************************************************

********************* CRASH #11 ***********************
SW Version          : 21.9.7
Similar Crash Count : 107
Time of First Crash : 2019-Sep-19+00:09:03

Assertion failure at npu/npumgr/ares_npumgr_forwarding_handler.c:1829
  Function: ares_npumgr_nexthop_get()
  Expression: (nh_id) >= 0 && (nh_id) < ares_npumgr_db_get_count(SN_NPUSHM_TABREC_NH, (ares_inst)->profile)
  Proclet: npumgr (f=103000,i=80)
  Process: card=8 cpu=0 arch=X pid=9130 cpu=~98% argv0=npumgr
  Crash time: 2019-Sep-18+19:03:35 UTC
  Recent errno: 115 Operation now in progress
  Build_number: 71001
  Stack (10360@0x0xffe58000):
    [ffffe430/X] __kernel_vsyscall() sp=0xffe58618
    [0c7df834/X] sn_assert() sp=0xffe58658
    [002fcedb/X] ares_npumgr_nexthop_get() sp=0xffe586a8
    [002feb23/X] ares_npumgr_fwd_ddf2_tcam_entry_update() sp=0xffe58b38
    [00301896/X] ares_npumgr_lpm_add() sp=0xffe59088
    [003c4345/X] ares_npumgr_fwd_add() sp=0xffe59958
    [003e1191/X] fwddb_import_add_entry() sp=0xffe59dd8
    [003e2452/X] ares_npumgr_fwddb_import() sp=0xffe5a2c8
    [0025e4ea/X] npumgr_rx_db_evt() sp=0xffe5a2f8
    [0c8660d4/X] sn_epoll_run_events() sp=0xffe5a348
    [0c872bca/X] sn_loop_run() sp=0xffe5a7f8
    [0c55a3b5/X] main() sp=0xffe5a868
*******************************************************

您可以檢查活動日誌，以下是所發生事件的時間順序。作為練習的一部分，介面建立後是靜態路由。

show ipv6 interface summary

Thursday September 19 00:09:16 IST 2019
Interface Name                 Address/Mask        Port               Status
============================== =================== ================== ======
SGi_LAG100_vlan50              2401:4900:c:f::201/126 5/10 vlan 50       UP           [sec]
SGi_LAG100_vlan64_VO4G_SBC     2401:4900:c:10::1/126  5/10 vlan 64       UP    
SGi_LAG200_vlan51              2401:4900:c:f::205/126 5/11 vlan 51       UP           [sec]
SGi_LAG200_vlan65_VO4G_SBC     2401:4900:c:10::5/126  5/11 vlan 65       UP      

Total interface count: 4

(config-ctx)# ipv6 route a:b:c:d:1/128 next-hop x:y:z:w::2 interface A
Thursday September 19 00:07:13 IST 2019
(config-ctx)#
(config-ctx)# ipv6 route a:b:c:d:1/128 next-hop x:y:z:w::2 interface B
Thursday September 19 00:07:21 IST 2019
Failure: Invalid Nexthop address!
(config-ctx)#
(config-ctx)# ipv6 route a:b:c:d:1/128 next-hop x:y:z:w::6 interface C
Thursday September 19 00:07:36 IST 2019
(config-ctx)# exit
Thursday September 19 00:07:50 IST 2019
[SGi]MOH-C25-SPG-04(config)#

然後，在埠內部配置VLAN，並在9月19日00:08:16前後為流量開啟。

(config)# port ethernet 5/10
Thursday September 19 00:08:01 IST 2019
(config-port-5/10)# vla
(config-port-5/10)# vlan 64
Thursday September 19 00:08:05 IST 2019
(config-port-5/10-vlan-64)# bind interface C SGi
Thursday September 19 00:08:14 IST 2019
(config-port-5/10-vlan-64)# no shu
(config-port-5/10-vlan-64)# no shutdown
Thursday September 19 00:08:17 IST 2019
(config-port-5/10-vlan-64)# exit
Thursday September 19 00:08:19 IST 2019
(config-port-5/10)# exit
Thursday September 19 00:08:21 IST 2019

在這裡，用於建立介面和靜態路由的計畫活動的步驟和配置以及隨後的VLAN內部繫結看起來不錯。但在此之後不久，可以看到npumgr開始崩潰，然後由於npumgr崩潰過多而導致DPC卡關閉。

show snmp trap history verbose | grep -i mgr
Thursday September 19 00:20:22 IST 2019
Thu Sep 19 00:08:18 2019 Internal trap notification 73 (ManagerFailure) facility npumgr instance 30 card 3 cpu 0
Thu Sep 19 00:08:18 2019 Internal trap notification 150 (TaskFailed) facility npumgr instance 30 on card 3 cpu 0
Thu Sep 19 00:08:18 2019 Internal trap notification 73 (ManagerFailure) facility npumgr instance 40 card 4 cpu 0
Thu Sep 19 00:08:18 2019 Internal trap notification 150 (TaskFailed) facility npumgr instance 40 on card 4 cpu 0

作為即時解決辦法，VLAN會從連線埠中移除。很快，刪除VLAN後，npumgr崩潰將停止。

configure
Thursday September 19 00:29:31 IST 2019
(config)# port eth
(config)# port ethernet 5/10
Thursday September 19 00:33:13 IST 2019
(config-port-5/10)# no vlan 64
Thursday September 19 00:33:23 IST 2019
(config-port-5/10)# exit
Thursday September 19 00:33:38 IST 2019
(config)# port ethernet 5/11
Thursday September 19 00:33:42 IST 2019
(config-port-5/11)# no vlan 65
Thursday September 19 00:33:50 IST 2019
(config-port-5/11)# end
Thursday September 19 00:33:52 IST 2019


******** show crash list *******
Thursday September 19 03:54:39 IST 2019
=== ==================== ======== ========== =============== =======================
# Time Process Card/CPU/ SW HW_SER_NUM
PID VERSION MIO / Crash Card
=== ==================== ======== ========== =============== =======================
 9 2019-Sep-19+00:31:11 npumgr 03/0/07066 21.9.7 FLM221503A5/FLM221404FF
10 2019-Sep-19+00:31:22 npumgr 01/1/07181 21.9.7 FLM221503A5/FLM221404FH
11 2019-Sep-19+00:33:35 npumgr 08/0/09130 21.9.7 FLM221503A5/FLM221404FU

當您進一步檢查syslogs時，可以看到系統嘗試獲取下一跳，但是在9月19日00:08:16失敗，即在為流量開啟VLAN後不久。

Sep 19 00:08:16 10.107.211.36 evlogd: [local-60sec16.758] [npumgr-fwd 168001 error] [3/2/7024 
     
     
       rding_handler.c:7739] [software internal system syslog] ECMP create fail - no nexthop ARP: vpnid=6, type=ip[0], action=add[1], ip=2401:4900:c:f::408/128, tb_ver=3 ifentry-flag=0, ifroute-flag=0, updatettl-flag=1, nh=2401:4900:c:10::1 dpti=0 priority=0, tos=0, ttl-decr=1, nhlfe_ix=0, lport=0x050a000a 
     
Sep 19 00:08:18 10.107.211.36 evlogd: [local-60sec18.448] [sitmain 4103 warning] [1/0/7008 
     
     
       sitproc.c:2653] [software internal system critical-info syslog] [npumgr pid 7102] async core transfer and proclet recovery is not set! 
     
Sep 19 00:08:18 10.107.211.36 evlogd: [local-60sec18.852] [sitmain 4027 critical] [2/0/6993 
     
     
       crash_mini.c:602] [software internal system callhome-crash] Process Crash Info: time 2019-Sep-18+18:38:16(hex time 5d827998) card 02 cpu 00 pid 07146 procname npumgr   crash_details  Assertion failure at npu/npumgr/ares_npumgr_forwarding_handler.c:1829   Function: ares_npumgr_nexthop_get()   Expression: (nh_id) >= 0 && (nh_id) < ares_npumgr_db_get_count(SN_NPUSHM_TABREC_NH, (ares_inst)->profile)   Proclet: npumgr (f=103000,i=20)   Process: card=2 cpu=0 arch=X pid=7146 cpu=~0% argv0=npumgr   Crash time: 2019-Sep-18+18:38:16 UTC   Recent errno: 11 Resource temporarily unavailable   Build_number: 71001   Stack (20600@0x0xffce5000):     [ffffe430/X] __kernel_vsyscall() sp=0xffce5e38     [0c7df834/X] sn_assert() sp=0xffce5e78     [002fcedb/X] ares_npumgr_nexthop_get() sp=0xffce5ec8     [002feb23/X] ares_npumgr_fwd_ddf2_tcam_entry_update() sp=0xffce6358     [00301896/X] ares_npumgr_lpm_add() sp=0xffce68a8     [003c4345 
     
Sep-18+18:38:16(hex time 5d827998) card 02 cpu 00 pid 07146 procname npumgr   crash_details  Assertion failure at npu/npumgr/ares_npumgr_forwarding_handler.c:1829   Function: ares_npumgr_nexthop_get()   Expression: (nh_id) >= 0 && (nh_id) < ares_npumgr_db_get_count(SN_NPUSHM_TABREC_NH, (ares_inst)->profile)   Proclet: npumgr (f=103000,i=20)   Process: card=2 cpu=0 arch=X pid=7146 cpu=~0% argv0=npumgr   Crash time: 2019-Sep-18+18:38:16 UTC   Recent errno: 11 Resource temporarily unavailable   Build_number: 71001   Stack (20600@0x0xffce5000):     [ffffe430/X] __kernel_vsyscall() sp=0xffce5e38     [0c7df834/X] sn_assert() sp=0xffce5e78     [002fcedb/X] ares_npumgr_nexthop_get() sp=0xffce5ec8     [002feb23/X] ares_npumgr_fwd_ddf2_tcam_entry_update() sp=0xffce6358     [00301896/X] ares_npumgr_lpm_add() sp=0xffce68a8     [003c4345

當您進一步從SSD檢查配置時，還可以看到在計畫活動開始之前（介面和靜態路由配置）已經存在一個靜態路由。

context SGi
  ipv6 route a:b:c:d:1/128 next-hop x:y:z:w::1 interface C
#exit

從配置中可以看到，已經存在通過介面C下一跳作為跳的x:y:z:w::1的IP a:b:c:d:1/128靜態路由。但是，在練習中，又將下一跳定義為跳的x:y:z:w::2。

因此，當為流量開啟VLAN時，系統無法按最初定義獲取下一跳x:y:z:w::1。此外，還有日誌顯示無法到達下一躍點的等價多路徑(ECMP)路由失敗。因此，它無法轉發這些VLAN流量的資料包，這最終會導致npumgr崩潰。

多卡切換是系統中過多的npumgr崩潰的副產品。

解決方案

有多個靜態路由通過同一介面到達同一目標，但不同的下一跳導致npumgr無法轉發資料包，然後是npumgr崩潰。

因此，會從配置中刪除錯誤的靜態路由。相同的配置隨後成功應用到另一個維護視窗，沒有任何問題。