Solução de problemas de várias placas de processamento de dados desligamento devido a muitos travamentos de bombeador

Introduction

Este documento descreve como solucionar um problema que ocorre quando várias placas de processamento de dados (DPCs) são desligadas em um período muito curto devido a travamentos do nbomgr.

Prerequisites

Requirements

A Cisco recomenda que você tenha conhecimento destes tópicos:

• Conhecimento de hardware do ASR5000/5500
• StarOS
• Conhecimento básico de roteamento

Componentes Utilizados

Este documento não se restringe a versões de software e hardware específicas.

The information in this document was created from the devices in a specific lab environment. All of the devices used in this document started with a cleared (default) configuration. Se a rede estiver ativa, certifique-se de que você entenda o impacto potencial de qualquer comando

Abreviaturas

SPGW	Gateway de rede de dados de servidor e pacote
DPC	Placa de processamento de dados
VLAN	Rede local virtual
NPU	Unidade de processamento de rede

Problema 

Como parte de uma atividade planejada, novas interfaces são ligadas em VLANs sob portas feitas. A segunda parte da atividade é criar rotas estáticas através dessas interfaces. Assim que a VLAN é aberta para o tráfego, o nbomgr trava e, posteriormente, fez com que todas as placas DPC fossem fechadas várias vezes.

Troubleshoot 

Esta seção fornece informações para solucionar o problema de vários desligamentos de placas DPC em um período muito curto devido a travamentos de Nbomgr.

Mostre os detalhes de suporte (SSD), os registros de atividade e os syslogs que cobrem os registros do problema são mostrados aqui. Em primeiro lugar, as estatísticas de rct são verificadas para ver o motivo desses desligamentos. Pode-se ver aqui que eles estão desligados devido a muitos acidentes de bombeiros.

******** 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

Em seguida, verifique os detalhes de travamentos do nabo. Aqui, você vê que o nbomgr é interrompido na função nexthop_get. Portanto, você vê uma indicação de alguns problemas quando tenta obter o salto seguinte.

********************* 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
*******************************************************

Você pode verificar os registros de atividades e aqui está a cronologia dos eventos que aconteceram. Como parte de uma atividade, as interfaces são criadas seguidas de rotas estáticas.

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)#

A VLAN é então configurada dentro da porta e aberta para o tráfego por volta de 19 de setembro 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

Aqui, as etapas e as configurações da atividade planejada para criar interfaces e rotas estáticas são seguidas pela associação dentro da VLAN parecem boas. Mas logo depois disso, percebeu-se que o bombeador começou a travar seguido de desligamentos de placa DPC devido a muitos travamentos de bombeiros.

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

Como solução alternativa imediata, as VLANs são removidas da porta. Em breve, depois de remover VLANs, os travamentos do nbomgr pararão.

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

Quando você verifica os syslogs, pode-se ver que o sistema tentou obter o próximo salto, mas não obteve êxito em 19 de setembro, 00:08:16. ou seja, logo após a VLAN ter sido aberta para tráfego.

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

Quando você verifica ainda mais a configuração do SSD, também pode ver que já existe uma rota estática antes do início da atividade planejada (configurações de interface e rota estática).

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

A partir da configuração, pode-se ver que já havia uma rota estática presente para IP a:b:c:d:1/128 através da interface C próximo salto como salto x:y:z:w::1. Mas como parte da atividade, mais uma rota estática é definida com o próximo salto como salto x:y:z:w::2.

Assim, quando as VLANs são abertas para tráfego, o sistema não pode obter o próximo salto x:y:z:w::1 conforme definido primeiro. Além disso, houve registros que indicaram que o roteamento de multi-caminho de custo igual (ECMP) para o próximo salto não foi bem-sucedido porque não está acessível. Como resultado, ele não conseguiu encaminhar pacotes desses tráfego de VLANs, o que acabou levando a travamentos de nabo.

O switchover de placa múltipla é um subproduto de muitos travamentos de nbomgr no sistema.

Solução

Há várias rotas estáticas para o mesmo destino através da mesma interface, mas o próximo salto diferente que leva ao nbomgr não consegue encaminhar pacotes seguidos de travamentos do nbomgr.

Portanto, a rota estática incorreta é removida da configuração. As mesmas configurações são então aplicadas com êxito em outra janela de manutenção sem problemas.