After sudden power outage at customer site, they started observing FPC crashes on the PTX5K running 21.2R3-S2.9. All FPCs started crashing consistently few times a day. Extensive investigation revealed this to be LSP scaling issue.
Whenever any trigger happens due to LSP re-optimization, link flap etc. MBB kicks in increasing NH scale. Paradise ASIC does not have enough memory to handle so many next-hops during such transient state and it crashes. As part of a known PR fix, code changes to improve convergence and route download has increased rate and amount of state pushed to PFE. As a result, under heavy system churn there could be a scenario where system generates abnormally high number of transient unilist NHs leading to on-chip memory exhaustion and subsequent FPC crash. The longer FPC stays in this problematic state the more chances to crash. Example scenario: let’s say we have unilist NHs of 11 CBF LSPs (+11 bypass) and some negative triggers caused all LSPs to be down and re-signaled: 1) initially unilist U1 is added with only 4 ready LSPs out of 11 (only 4 LSPs came up by that time) 2) assume new unilist (say U2, now with 6 ready LSPs) is added and route change is received to point to new unilist (U2) 3) Kernel will not send a delete to old unilist (U1) unless route change to new unilist is acknowledged by all the PFE in the system. 4) Assume RPD creates another unilist (say U3, this time with 9 ready LSPs) as new set of RSVP LSP's came up and route points to U3. 5) Kernel pushes U3 to PFE also. So we have three sets of unilist U1, U2 and U3 for same route 6) Kernel did not send delete to U1 as one of the slow FPC did not acknowledge the route change to U2 Juniper Business Use Only This leads to more than expected increase in transient unilist. MBB will affect and increase transient scale even more. This does exhaust memory leading to a crash.
Complete traffic loss.
Alarms
-------------
root@cr2> show chassis alarms no-forwarding
12 alarms currently active
Alarm time Class Description
2023-09-05 21:49:28 UTC Minor FPC 7, PIC not power up
2023-09-05 21:45:59 UTC Major PDU 1 Not OK
2023-09-05 21:45:59 UTC Major PDU 1 Converter Failed
2023-09-05 21:45:59 UTC Minor No Redundant Power for System
2023-09-05 21:45:59 UTC Major PDU 1 PSM 0 Not OK
2023-09-05 21:45:59 UTC Major PDU 1 PSM 1 Not OK
2023-09-05 21:45:59 UTC Major PDU 1 PSM 2 Not OK
2023-09-05 21:45:59 UTC Major PDU 1 PSM 3 Not OK
2023-09-05 21:45:59 UTC Major PDU 1 PSM 4 Not OK
2023-09-05 21:45:59 UTC Major PDU 1 PSM 5 Not OK
2023-09-05 21:45:59 UTC Major PDU 1 PSM 6 Not OK
2023-09-05 21:45:59 UTC Major PDU 1 PSM 7 Not OK
Log messages
=========================
PIC 1 PSM 0-7
----------------
Sep 5 21:45:40 cr2 agentd[11998]: %DAEMON-3-AGENTD_PARENT_SENSOR_INSTALL_FAILED: Installing dynamic sensor sensor_1003 failed, ret -1
Sep 5 21:45:45 cr2 chassisd[11183]: %DAEMON-4-CHASSISD_PSM_NOT_OK: status failure for PDU 1 PSM 0 (status bits: 0x5F1C)
Sep 5 21:45:46 cr2 chassisd[11183]: %DAEMON-4-CHASSISD_PSM_NOT_OK: status failure for PDU 1 PSM 1 (status bits: 0x5F1C)
Sep 5 21:45:47 cr2 chassisd[11183]: %DAEMON-4-CHASSISD_PSM_NOT_OK: status failure for PDU 1 PSM 2 (status bits: 0x5F1C)
Sep 5 21:45:49 cr2 chassisd[11183]: %DAEMON-4-CHASSISD_PSM_NOT_OK: status failure for PDU 1 PSM 3 (status bits: 0x5F1C)
Sep 5 21:45:50 cr2 chassisd[11183]: %DAEMON-4-CHASSISD_PSM_NOT_OK: status failure for PDU 1 PSM 4 (status bits: 0x5F1C)
Sep 5 21:45:52 cr2 chassisd[11183]: %DAEMON-4-CHASSISD_PSM_NOT_OK: status failure for PDU 1 PSM 5 (status bits: 0x5F1C)
Sep 5 21:45:53 cr2 chassisd[11183]: %DAEMON-4-CHASSISD_PSM_NOT_OK: status failure for PDU 1 PSM 6 (status bits: 0x5F1C)
Sep 5 21:45:55 cr2 chassisd[11183]: %DAEMON-4-CHASSISD_PSM_NOT_OK: status failure for PDU 1 PSM 7 (status bits: 0x5F1C)
FPC 7 Logs
---------------
Sep 5 21:49:12 cr2 : %PFE-4: fpc7 CMSNG: Error requesting SET BOOLEAN, illegal setting 171. Setting it as warning!
Sep 5 21:49:13 cr2 : %PFE-3: fpc7 Error requesting cmsngfpc SET INTEGER, illegal setting 100032
Sep 5 21:49:19 cr2 : %PFE-3: fpc7 CM_SNGFPC: cmsngfpc_pic_state_check failed with PIC power, FPC 7 PIC 1
Sep 5 21:49:22 cr2 : %PFE-3: fpc7 CM_SNGFPC: cmsngfpc_pic_state_check failed with PIC power, FPC 7 PIC 1
Sep 5 21:49:24 cr2 : %PFE-3: fpc7 CM_SNGFPC: cmsngfpc_pic_state_check failed with PIC power, FPC 7 PIC 1
Sep 5 21:49:24 cr2 : %PFE-3: fpc7 CM_SNGFPC: cmsngfpc_pic_state_check failed with power, disable pic 1
Sep 5 21:49:28 cr2 chassisd[11183]: %DAEMON-5-CHASSISD_SNMP_TRAP0: ENTITY trap generated: entConfigChanged
Sep 5 21:49:28 cr2 alarmd[11984]: %DAEMON-4: Alarm set: FPC id=704644968, color=YELLOW, class=CHASSIS, reason=FPC 7, PIC not power up
Sep 5 21:49:28 cr2 chassisd[11183]: %DAEMON-5-CHASSISD_SNMP_TRAP10: SNMP trap generated: FRU power on (jnxFruContentsIndex 8, jnxFruL1Index 6, jnxFruL2Index 2, jnxFruL3Index 0, jnxFruName PIC: @ 5/1/*, jnxFruType 11, jnxFruSlot 5, jnxFruOfflineReason 2, jnxFruLastPowerOff 0, jnxFruLastPowerOn 23902)
Sep 5 21:49:28 cr2 chassisd[11183]: %DAEMON-5-CHASSISD_SNMP_TRAP3: ENTITY trap generated: entStateOperEnabled (entPhysicalIndex 120, entStateAdmin 4, entStateAlarm 0)
Log chassisd
Sep 5 21:46:10 fru_set_integer: send: set_integer_cmd SPMB 1 subfru 0 setting cfg bandwidth fpc mask 0
Sep 5 21:45:37 fpc_sng_handle_power_recovery: handling power recovery for FPC 0
Sep 5 21:45:37 fpc_sng_handle_power_recovery: handling power recovery for FPC 1
Sep 5 21:45:37 fpc_sng_handle_power_recovery: handling power recovery for FPC 2
Sep 5 21:45:37 fpc_sng_handle_power_recovery: handling power recovery for FPC 3
Sep 5 21:45:37 fpc_sng_handle_power_recovery: handling power recovery for FPC 4
Sep 5 21:45:37 fpc_sng_handle_power_recovery: handling power recovery for FPC 5
Sep 5 21:45:37 fpc_sng_handle_power_recovery: handling power recovery for FPC 6
Sep 5 21:45:37 fpc_sng_handle_power_recovery: handling power recovery for FPC 7
Sep 5 21:45:37 fan_sng_handle_power_recovery: handling power recovery for Fan Tray 0
Sep 5 21:45:38 psm_teq_watchdog_enable: Disabling Watchdog for PDU1PSM0
Sep 5 21:45:38 psm_teq_watchdog_enable: Disabling Watchdog for PDU1PSM1
Sep 5 21:45:38 psm_teq_watchdog_enable: Disabling Watchdog for PDU1PSM2
Sep 5 21:45:38 psm_teq_watchdog_enable: Disabling Watchdog for PDU1PSM3
Sep 5 21:45:39 psm_teq_watchdog_enable: Disabling Watchdog for PDU1PSM4
Sep 5 21:45:39 psm_teq_watchdog_enable: Disabling Watchdog for PDU1PSM5
Sep 5 21:45:39 psm_teq_watchdog_enable: Disabling Watchdog for PDU1PSM6
Sep 5 21:45:39 psm_teq_watchdog_enable: Disabling Watchdog for PDU1PSM7
Sep 5 21:45:44 reading PDU 1 PSM 0 initial state
Sep 5 21:45:44 psm_sng_initial_status_read: PDU 1 PSM 0 read status
Sep 5 21:45:44 pdu_teq_read_pdu_conf: i2c_read Pass - group 0x1c addr 0x20 offset 0x94 pdu_conf 0x92
Sep 5 21:45:44 pdu_teq_read_pdu_conf: i2c_read Pass - group 0x1d addr 0x20 offset 0x94 pdu_conf 0x92
Sep 5 21:45:45 send: red alarm set, device PDU 1 PSM 0, reason PDU 1 PSM 0 Not OK
Sep 5 21:45:45 CHASSISD_PSM_NOT_OK: status failure for PDU 1 PSM 0 (status bits: 0x5F1C)
Sep 5 21:45:45 pwr_zone_sng_chk_psm_types: zone_psm 0 non_zone_psm 8 prs 1 prs_new 1
Sep 5 21:45:45 pwr_zone_sng_chk_psm_types:1893 No PDU/PSM mode change
Sep 5 21:45:58 FPC 0: has sufficient power to power up
Sep 5 21:45:58 FPC 1: has sufficient power to power up
Sep 5 21:45:58 FPC 2: has sufficient power to power up
Sep 5 21:45:58 FPC 3: has sufficient power to power up
Sep 5 21:45:58 FPC 4: has sufficient power to power up
Sep 5 21:45:58 FPC 5: has sufficient power to power up
Sep 5 21:45:58 FPC 6: has sufficient power to power up
Sep 5 21:45:58 FPC 7: has sufficient power to power up
Sep 5 21:45:58 CHASSISD_SNMP_TRAP10: SNMP trap generated: FRU power on (jnxFruContentsIndex 7, jnxFruL1Index 1, jnxFruL2Index 0, jnxFruL3Index 0, jnxFruName FPC: FPC-P2 @ 0/*/*, jnxFruType 3, jnxFruSlot 0, jnxFruOfflineReason 2, jnxFruLastPowerOff 0, jnxFruLastPowerOn 12909)
Sep 5 21:45:58 CHASSISD_SNMP_TRAP10: SNMP trap generated: FRU power on (jnxFruContentsIndex 7, jnxFruL1Index 2, jnxFruL2Index 0, jnxFruL3Index 0, jnxFruName FPC: FPC-P2 @ 1/*/*, jnxFruType 3, jnxFruSlot 1, jnxFruOfflineReason 2, jnxFruLastPowerOff 9062, jnxFruLastPowerOn 12914)
Sep 5 21:45:58 CHASSISD_SNMP_TRAP10: SNMP trap generated: FRU power on (jnxFruContentsIndex 7, jnxFruL1Index 3, jnxFruL2Index 0, jnxFruL3Index 0, jnxFruName FPC: FPC-P2 @ 2/*/*, jnxFruType 3, jnxFruSlot 2, jnxFruOfflineReason 2, jnxFruLastPowerOff 9065, jnxFruLastPowerOn 12918)
Sep 5 21:45:58 CHASSISD_SNMP_TRAP10: SNMP trap generated: FRU power on (jnxFruContentsIndex 7, jnxFruL1Index 4, jnxFruL2Index 0, jnxFruL3Index 0, jnxFruName FPC: FPC-P2 @ 3/*/*, jnxFruType 3, jnxFruSlot 3, jnxFruOfflineReason 2, jnxFruLastPowerOff 0, jnxFruLastPowerOn 12923)
Sep 5 21:45:58 CHASSISD_SNMP_TRAP10: SNMP trap generated: FRU power on (jnxFruContentsIndex 7, jnxFruL1Index 5, jnxFruL2Index 0, jnxFruL3Index 0, jnxFruName FPC: FPC-P2 @ 4/*/*, jnxFruType 3, jnxFruSlot 4, jnxFruOfflineReason 2, jnxFruLastPowerOff 0, jnxFruLastPowerOn 12927)
Sep 5 21:45:58 CHASSISD_SNMP_TRAP10: SNMP trap generated: FRU power on (jnxFruContentsIndex 7, jnxFruL1Index 6, jnxFruL2Index 0, jnxFruL3Index 0, jnxFruName FPC: FPC-P2 @ 5/*/*, jnxFruType 3, jnxFruSlot 5, jnxFruOfflineReason 2, jnxFruLastPowerOff 0, jnxFruLastPowerOn 12932)
Sep 5 21:45:58 CHASSISD_SNMP_TRAP10: SNMP trap generated: FRU power on (jnxFruContentsIndex 7, jnxFruL1Index 7, jnxFruL2Index 0, jnxFruL3Index 0, jnxFruName FPC: FPC-P2 @ 6/*/*, jnxFruType 3, jnxFruSlot 6, jnxFruOfflineReason 2, jnxFruLastPowerOff 9076, jnxFruLastPowerOn 12936)
Sep 5 21:45:58 CHASSISD_SNMP_TRAP10: SNMP trap generated: FRU power on (jnxFruContentsIndex 7, jnxFruL1Index 8, jnxFruL2Index 0, jnxFruL3Index 0, jnxFruName FPC: FPC-P2 @ 7/*/*, jnxFruType 3, jnxFruSlot 7, jnxFruOfflineReason 2, jnxFruLastPowerOff 0, jnxFruLastPowerOn 12941)
Sep 5 21:45:58 pipe_write failure for alarmd; connection error: Broken pipe (errno 32)
Sep 5 21:45:58 send: red alarm set, device PDU 1 PSM 7, reason PDU 1 PSM 7 Not OK
Sep 5 21:45:58 CHASSISD_SNMP_TRAP10: SNMP trap generated: Fru Offline (jnxFruContentsIndex 14, jnxFruL1Index 1, jnxFruL2Index 0, jnxFruL3Index 0, jnxFruName SPMB 0, jnxFruType 10, jnxFruSlot 0, jnxFruOfflineReason 2, jnxFruLastPowerOff 12942, jnxFruLastPowerOn 0)
Sep 5 21:45:58 CHASSISD_SNMP_TRAP10: SNMP trap generated: Fru Offline (jnxFruContentsIndex 14, jnxFruL1Index 2, jnxFruL2Index 0, jnxFruL3Index 0, jnxFruName SPMB 1, jnxFruType 10, jnxFruSlot 1, jnxFruOfflineReason 2, jnxFruLastPowerOff 12942, jnxFruLastPowerOn 0)
Sep 5 21:46:01 fru_power_on_state_timer: FPC 6 step 8
Sep 5 21:46:01 FPC 6 ----- power ok, after 1075 ms
Sep 5 21:46:01 fru_power_on_state_timer: FPC 7 step 8
Sep 5 21:46:01 FPC 7 ----- power ok, after 1075 ms
Sep 5 21:46:01 fru_power_on_state_timer: FPC 0 step 9
Sep 5 21:46:01 FPC 0 ----- power ok, after 1825 ms
Sep 5 21:46:01 fru_power_on_state_timer: FPC 1 step 9
Sep 5 21:46:01 FPC 1 ----- power ok, after 1825 ms
Sep 5 21:46:01 fru_power_on_state_timer: FPC 2 step 9
Sep 5 21:46:01 FPC 2 ----- power ok, after 1825 ms
Sep 5 21:46:01 fru_power_on_state_timer: FPC 3 step 9
Sep 5 21:46:01 FPC 3 ----- power ok, after 1825 ms
Sep 5 21:46:01 fru_power_on_state_timer: FPC 4 step 9
Sep 5 21:46:01 FPC 4 ----- power ok, after 1825 ms
Sep 5 21:46:01 fru_power_on_state_timer: FPC 5 step 9
Sep 5 21:46:01 FPC 5 ----- power ok, after 1825 ms
Sep 5 21:46:01 fru_power_on_state_timer: FPC 6 step 30
Sep 5 21:46:01 i2cs_blue_led_on: FPC#6 - active(blue) LED turned on
Sep 5 21:46:01 fru_power_on_state_timer: FPC 7 step 30
Sep 5 21:46:01 i2cs_blue_led_on: FPC#7 - active(blue) LED turned on
Sep 5 21:46:02 psm_sng_calculate_input_usage: fru PSM 0 invalid input 1
Sep 5 21:46:02 psm_sng_jvision_property_get: fru PSM 0 calc input2 usage failed
Sep 5 21:46:02 psm_sng_calculate_input_usage: fru PSM 1 invalid input 1
Sep 5 21:46:02 psm_sng_jvision_property_get: fru PSM 1 calc input2 usage failed
Sep 5 21:46:02 psm_sng_calculate_input_usage: fru PSM 2 invalid input 1
Sep 5 21:46:02 psm_sng_jvision_property_get: fru PSM 2 calc input2 usage failed
Sep 5 21:46:04 fru_power_on_state_timer: FPC 0 step 30
Sep 5 21:46:08 psm_sng_calculate_input_usage: fru PSM 0 invalid input 1
Sep 5 21:46:08 psm_sng_jvision_property_get: fru PSM 0 calc input2 usage failed
Sep 5 21:46:08 psm_sng_calculate_input_usage: fru PSM 1 invalid input 1
Sep 5 21:46:08 psm_sng_jvision_property_get: fru PSM 1 calc input2 usage failed
Sep 5 21:46:08 psm_sng_calculate_input_usage: fru PSM 2 invalid input 1
Sep 5 21:46:08 psm_sng_jvision_property_get: fru PSM 2 calc input2 usage failed
Sep 5 21:46:10 psm_sng_calculate_input_usage: fru PSM 3 invalid input 1
Sep 5 21:46:10 psm_sng_jvision_property_get: fru PSM 3 calc input2 usage failed
Sep 5 21:46:10 psm_sng_calculate_input_usage: fru PSM 4 invalid input 1
Sep 5 21:46:10 psm_sng_jvision_property_get: fru PSM 4 calc input2 usage failed
Sep 5 21:46:10 psm_sng_calculate_input_usage: fru PSM 5 invalid input 1
Sep 5 21:46:10 psm_sng_jvision_property_get: fru PSM 5 calc input2 usage failed
Sep 5 21:46:10 psm_sng_calculate_input_usage: fru PSM 6 invalid input 1
Sep 5 21:46:10 psm_sng_jvision_property_get: fru PSM 6 calc input2 usage failed
Sep 5 21:46:10 psm_sng_calculate_input_usage: fru PSM 7 invalid input 1
Sep 5 21:46:10 psm_sng_jvision_property_get: fru PSM 7 calc input2 usage failed
WORKAROUND:
Hidden knob ‘route-nexthop-max-delayed-unrefs’ can be used to modify unrefs from 40000 to 10000 but it does not work in all scenarios. It helps when RE is fast and FPC is slow. If both are fast, it will not help. In this case, the system is close to consuming all ASIC memory in steady state and trigger will lead to out of ASIC memory state.
It must be noted that the issue is not seen in 17.4 code. The reason for that as stated above – 21.2 has code changes to improve convergence making it more “faster” than 17.4. As a result, system generates route updates faster creating higher number of NHs in transient state occupying more memory than it was in 17.4. As per further debugging and discussion:
1. It is a scale issue, not a memory leak. Tried running multiple triggers with reduced scale on 20.4 image and we do not see any substantial increase in NH memory usage over time.
2. Tested ASIC NH memory usage with same scale on both 17.4 and 20.4 images in CCL lab. Number of next-hops and ASIC memory consumed is same across both releases.
This proves two points: a) Under steady state, memory utilization is the same across both releases b) It is expected that transient state have more scale on 20.4/21.2 leading to crash.
Recommendation: we do not have any fix for this issue as it is ASIC limitation. Scale needs to be reduced. Issue was not seen after all logical systems were deactivated.