RP/0/RP0/CPU0:PE1#show mpls traffic-eng trace head-end Tue Sep 15 02:57:35.052 UTC 75 wrapping entries (264256 possible, 320 allocated, 0 filtered, 75 total) Sep 15 02:27:54.799 mpls_te/head-end 0/RP0/CPU0 t4559 [PCALC-ECMP] Max BWV Allocated: 20 Sep 15 02:27:54.799 mpls_te/head-end 0/RP0/CPU0 t4559 [PCALC-ECMP] Max BWVE Allocated: 15 Sep 15 02:27:58.500 mpls_te/head-end 0/RP0/CPU0 t4559 NOTFN OwnedResEnd Sep 15 02:27:59.917 mpls_te/head-end 0/RP0/CPU0 t4559 Validating ifindexes for all vifs Sep 15 02:33:58.819 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, Start sync retry timer Sep 15 02:33:58.819 mpls_te/head-end 0/RP0/CPU0 t4559 Batch op IF CREATE with 1 items Sep 15 02:33:58.825 mpls_te/head-end 0/RP0/CPU0 t4559 ifh:0x1c, NOTFN INITIAL; caps ; proto NONE; state not ready Sep 15 02:33:58.825 mpls_te/head-end 0/RP0/CPU0 t4559 ifh:0x1c, NOTFN INITIAL; caps mpls_te; proto NONE; state not ready Sep 15 02:33:58.826 mpls_te/head-end 0/RP0/CPU0 t4559 Batch op CAPS ADD with 1 items Sep 15 02:33:58.826 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, ifh:0x1c, NOTFN STATE, caps ; proto NONE; state down Sep 15 02:33:58.827 mpls_te/head-end 0/RP0/CPU0 t4559 Batch op STATE UPDATE with 1 items Sep 15 02:33:58.895 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, IM op STATE UPDATE for tunnel-te0 (ifhndl 0x1c) Sep 15 02:33:58.895 mpls_te/head-end 0/RP0/CPU0 t4559 ifh:0x1c, NOTFN INITIAL; caps mpls; proto mpls; state not ready Sep 15 02:33:58.895 mpls_te/head-end 0/RP0/CPU0 t4559 ifh:0x1c, NOTFN MTU; caps mpls; proto mpls; mtu 1500 Sep 15 02:33:58.895 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, IM op CAPS ADD for tunnel-te0 (ifhndl 0x1c) Sep 15 02:33:58.895 mpls_te/head-end 0/RP0/CPU0 t4559 Batch op CAPS ADD with 1 items Sep 15 02:33:58.895 mpls_te/head-end 0/RP0/CPU0 t4559 Batch op MTU UPDATE with 1 items Sep 15 02:33:58.899 mpls_te/head-end 0/RP0/CPU0 t4559 ifh:0x1c, NOTFN CREATE; caps ipv4; proto ipv4; Sep 15 02:33:58.899 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, IP address is now available Sep 15 02:33:58.899 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, handling vif (0x64ecbd38) scheduled action ACT_CHECK Sep 15 02:33:58.915 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, IM op CAPS ADD for tunnel-te0 (ifhndl 0x1c) Sep 15 02:33:59.022 mpls_te/head-end 0/RP0/CPU0 t4559 tunnel-te0 (ifhndl 0x1c) : queued IM dest update: 22.22.22.22 Sep 15 02:33:59.022 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, Send IM attribute: old dest = 0.0.0.0, new dest = 22.22.22.22 Sep 15 02:33:59.022 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, Start sync retry timer Sep 15 02:33:59.023 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, Start sync retry timer Sep 15 02:33:59.023 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, POIndex:10, POType:2, ComputationType:0, Holddown:0 Sep 15 02:33:59.024 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, Start sync retry timer Sep 15 02:33:59.024 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, L:2, LL:1048577, TE rewrite delete queueing succeeded Sep 15 02:33:59.024 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, IFH:0x01C, moving state to down Sep 15 02:33:59.024 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, POIndex:10, POType:2, ComputationType:0, Holddown:0 Sep 15 02:33:59.026 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, handling vif (0x64ecbd38) scheduled action ACT_CHECK Sep 15 02:33:59.026 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, handling vif (0x64ecbd38) scheduled action ACT_MODIFY_IN_PLACE Sep 15 02:33:59.028 mpls_te/head-end 0/RP0/CPU0 t4559 Batch op STATE UPDATE with 1 items Sep 15 02:33:59.028 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, IM op STATE UPDATE for tunnel-te0 (ifhndl 0x1c) Sep 15 02:33:59.302 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, L:3, LL:24016, TE rewrite queueing succeeded Sep 15 02:33:59.303 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, [CURRENT] L:3, ifh:0x1c, TE rewrite returned TRUE Sep 15 02:33:59.303 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, IFH:0x01C, moving state to up Sep 15 02:33:59.303 mpls_te/head-end 0/RP0/CPU0 t4559 Created autoroute entry 22.22.22.22, area 2 0; total AA entries 1 Sep 15 02:33:59.303 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, added AA, D:22.22.22.22, IGP: 2, area 0 Sep 15 02:33:59.303 mpls_te/head-end 0/RP0/CPU0 t4559 Batch op STATE UPDATE with 1 items Sep 15 02:33:59.304 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, IM op STATE UPDATE for tunnel-te0 (ifhndl 0x1c) Sep 15 02:33:59.304 mpls_te/head-end 0/RP0/CPU0 t4559 Sent autoroute-announce tunnel list for 22.22.22.22 to IGP: OSPF, area 0: 1 tunnels Sep 15 02:33:59.819 mpls_te/head-end 0/RP0/CPU0 t4559 Validating ifindexes for all vifs Sep 15 02:33:59.819 mpls_te/head-end 0/RP0/CPU0 t4559 Bulk ifindex lookup for 1 vifs Sep 15 02:33:59.821 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, ifindex set to 9 Sep 15 02:34:14.025 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, Sync retry timer expired Sep 15 02:42:03.173 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, L:3, LL:24016, TE rewrite delete queueing succeeded Sep 15 02:42:03.173 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, IFH:0x01C, moving state to down Sep 15 02:42:03.173 mpls_te/head-end 0/RP0/CPU0 t4559 Removed tunnel T:0, D:22.22.22.22 from autoroute list for IGP: OSPF, area 0 Sep 15 02:42:03.174 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, handling vif (0x64ecbd38) scheduled action ACT_CHECK Sep 15 02:42:03.174 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, POIndex:10, POType:2, ComputationType:0, Holddown:0 Sep 15 02:42:03.174 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, POIndex:20, POType:1, ComputationType:0, Holddown:0 Sep 15 02:42:03.175 mpls_te/head-end 0/RP0/CPU0 t4559 Batch op STATE UPDATE with 1 items Sep 15 02:42:03.177 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, IM op STATE UPDATE for tunnel-te0 (ifhndl 0x1c) Sep 15 02:42:03.177 mpls_te/head-end 0/RP0/CPU0 t4559 Sent autoroute-announce tunnel list for 22.22.22.22 to IGP: OSPF, area 0: 0 tunnels Sep 15 02:42:03.177 mpls_te/head-end 0/RP0/CPU0 t4559 Deleted autoroute entry 22.22.22.22, area 2 0; total AA entries 0 Sep 15 02:42:03.585 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, L:4, LL:24016, TE rewrite queueing succeeded Sep 15 02:42:03.586 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, [CURRENT] L:4, ifh:0x1c, TE rewrite returned TRUE Sep 15 02:42:03.586 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, IFH:0x01C, moving state to up Sep 15 02:42:03.586 mpls_te/head-end 0/RP0/CPU0 t4559 Created autoroute entry 22.22.22.22, area 2 0; total AA entries 1 Sep 15 02:42:03.586 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, added AA, D:22.22.22.22, IGP: 2, area 0 Sep 15 02:42:03.586 mpls_te/head-end 0/RP0/CPU0 t4559 Batch op STATE UPDATE with 1 items Sep 15 02:42:03.587 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, IM op STATE UPDATE for tunnel-te0 (ifhndl 0x1c) Sep 15 02:42:03.587 mpls_te/head-end 0/RP0/CPU0 t4559 Sent autoroute-announce tunnel list for 22.22.22.22 to IGP: OSPF, area 0: 1 tunnels Sep 15 02:51:09.732 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, handling vif (0x64ecbd38) scheduled action ACT_MODIFY_IN_PLACE Sep 15 02:51:10.726 mpls_te/head-end 0/RP0/CPU0 t4559 Validating ifindexes for all vifs Sep 15 02:51:50.525 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, handling vif (0x64ecbd38) scheduled action ACTION_REOPTIMIZE_CLI Sep 15 02:51:50.525 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, POIndex:10, POType:2, ComputationType:1, Holddown:0 Sep 15 02:51:50.525 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, working-reopt initiated: trigger: CLI request, reason: better path option indices Sep 15 02:51:50.525 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, [REOPT] L:5, better path option indices Sep 15 02:51:50.703 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, started install timer:20 secs, 100 msec, [CURRENT] L:4, [REOPT] L:5 Sep 15 02:52:10.803 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, Timer[0] expired; install RW for [REOPT] L:5 and start cleanup timer:20 secs Sep 15 02:52:10.803 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, [REOPT] L:5, TE rewrite returned TRUE Sep 15 02:52:10.804 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, [REOPT] L:5, ifh:0x1c, TE rewrite returned TRUE Sep 15 02:52:30.905 mpls_te/head-end 0/RP0/CPU0 t4559 T:0, Type:TE, cleanup timer expired; destroying [CLEAN] L:4 RP/0/RP0/CPU0:PE1#show mpls traffic-eng trace link Tue Sep 15 02:57:35.199 UTC 117 wrapping entries (67648 possible, 320 allocated, 0 filtered, 117 total) Sep 15 02:27:54.799 mpls_te/link 0/RP0/CPU0 t4559 DS-TE mode change: prev - 0, new - 1 Sep 15 02:27:54.799 mpls_te/link 0/RP0/CPU0 t4559 TE process restarting; aborting DS-TE mode change Sep 15 02:27:56.596 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:381: lm_iarm_control_cb_fn: connection to IARM established. Sep 15 02:27:58.627 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:1534: mpls_lcac_ifrs_add: Added new IFRS entry Sep 15 02:27:58.627 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:1128: rrr_lm_list_link: Inserted link GigabitEthernet0/0/0/1 (ifh 0x20) into db based on name and handle Sep 15 02:27:58.695 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:5569: rrr_lm_update_link_neighbors(): link GigabitEthernet0/0/0/1 (ifh 0x20), flood 0, force 0, Nbr cnt 0 Sep 15 02:27:58.695 mpls_te/link 0/RP0/CPU0 t4559 RSI: Registering interface GigabitEthernet0/0/0/1 (ifhndl 0x20) (0x20) for SRLG Notification Sep 15 02:27:58.695 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:2544: rrr_lm_create_link: link GigabitEthernet0/0/0/1 (ifh 0x20) Created [1 links total], enable 0 Sep 15 02:27:58.697 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_idb_capacity: link GigabitEthernet0/0/0/1 (ifh 0x20) BW attribute 0 kbps Sep 15 02:27:58.698 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_link_capacity: link GigabitEthernet0/0/0/1 (ifh 0x20) physical_bw 125000000 Bps Sep 15 02:27:58.702 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: mpls_lcac_cfg_int_bandwidth_rdm_apply: link GigabitEthernet0/0/0/1 (ifh 0x20) max_bw 1000000 (Kbps), pool0_bw 1000000 (Kbps) Sep 15 02:27:58.702 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: mpls_lcac_cfg_int_bandwidth_rdm_apply: link GigabitEthernet0/0/0/1 (ifh 0x20) pool1_bw 0 (Kbps) Sep 15 02:27:58.702 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_set_link_bandwidth(): link GigabitEthernet0/0/0/1 (ifh 0x20), max_res_bw 1000000 (Kbps), Old max_res_bw 0 (Kbps), IP addr 0.0.0.0 Sep 15 02:27:58.702 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_set_link_bandwidth(): link GigabitEthernet0/0/0/1 (ifh 0x20), Pool0* max_bw 1000000 (Kbps), Old max_bw 0 (Kbps), IP addr 0.0.0.0 Sep 15 02:27:58.702 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_set_link_bandwidth(): link GigabitEthernet0/0/0/1 (ifh 0x20), max_res_bw 1000000 (Kbps), Old max_res_bw 0 (Kbps), IP addr 0.0.0.0 Sep 15 02:27:58.702 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_set_link_bandwidth(): link GigabitEthernet0/0/0/1 (ifh 0x20), Pool0* max_bw 1000000 (Kbps), Old max_bw 0 (Kbps), IP addr 0.0.0.0 Sep 15 02:27:58.702 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:518: Bandwidth update handling ignored, link GigabitEthernet0/0/0/1 (ifh 0x20) state down Sep 15 02:27:58.705 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:741: lm_iarm_reg_ipv4_add: added IPv4 register(True) request for interface GigabitEthernet0/0/0/1 (ifh 0x20) to IARM batch Sep 15 02:27:58.705 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:756: lm_iarm_reg_ipv4_add: sent pulse (0) to flush IARM IPv4 registration batch. Sep 15 02:27:58.706 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3722: lm_im_handler: link GigabitEthernet0/0/0/1 (ifh 0x20), state 17, proto 0, opcode 35 (CREATE/DEL) Sep 15 02:27:58.706 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3727: lm_im_handler: link GigabitEthernet0/0/0/1 (ifh 0x20), intf_type 15, parent i/f None (ifh 0x0), caps 0 Sep 15 02:27:58.706 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3808: lm_im_handler: IM_CREATE: link GigabitEthernet0/0/0/1 (ifh 0x20), state 17, proto 0, opcode 35 Sep 15 02:27:58.706 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3881: lm_im_handler: Updating link GigabitEthernet0/0/0/1 (ifh 0x20), intf_type 15, data_parent i/f None (ifh 0x0) (IM_CREATE) Sep 15 02:27:58.706 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_idb_capacity: link GigabitEthernet0/0/0/1 (ifh 0x20) BW attribute 0 kbps Sep 15 02:27:58.706 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_link_capacity: link GigabitEthernet0/0/0/1 (ifh 0x20) physical_bw 125000000 Bps Sep 15 02:27:58.706 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: mpls_lcac_cfg_int_bandwidth_rdm_apply: link GigabitEthernet0/0/0/1 (ifh 0x20) max_bw 1000000 (Kbps), pool0_bw 1000000 (Kbps) Sep 15 02:27:58.706 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: mpls_lcac_cfg_int_bandwidth_rdm_apply: link GigabitEthernet0/0/0/1 (ifh 0x20) pool1_bw 0 (Kbps) Sep 15 02:27:58.706 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: mpls_lcac_cfg_int_bandwidth_mam_apply: link GigabitEthernet0/0/0/1 (ifh 0x20) max_bw 0 (Kbps), pool0_bw 0 (Kbps) Sep 15 02:27:58.706 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: mpls_lcac_cfg_int_bandwidth_mam_apply: link GigabitEthernet0/0/0/1 (ifh 0x20) pool1_bw 0 (Kbps) Sep 15 02:27:58.706 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:5281: Flooding on link GigabitEthernet0/0/0/1 (ifh 0x20) suppressed, system not ready Sep 15 02:27:58.707 mpls_te/link 0/RP0/CPU0 t4559 RSI: Synchronous batch handler: 1 items Sep 15 02:27:58.707 mpls_te/link 0/RP0/CPU0 t4559 RSI: Event Update with 0 SRLG values for GigabitEthernet0/0/0/1 (ifhndl 0x20) (0x20) [change: NO, old count 0] Sep 15 02:27:58.707 mpls_te/link 0/RP0/CPU0 t4559 RSI: Sent registration for 1 interfaces (Success 1, failure 0) Sep 15 02:27:58.707 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_im_attr_capacity_handler: link MgmtEth0/RP0/CPU0/0 (ifh 0x10),bw 1000000 (kbps), bw2 125000000 (Bps), event 0 Sep 15 02:27:58.707 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_im_attr_capacity_handler: link GigabitEthernet0/0/0/0 (ifh 0x18),bw 1000000 (kbps), bw2 125000000 (Bps), event 0 Sep 15 02:27:58.707 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_im_attr_capacity_handler: link GigabitEthernet0/0/0/1 (ifh 0x20),bw 1000000 (kbps), bw2 125000000 (Bps), event 0 Sep 15 02:27:58.707 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_process_link_capacity(): capacity not changed link GigabitEthernet0/0/0/1 (ifh 0x20), current bw 125000000 (Kbps), new bw 125000000 (Kbps) Sep 15 02:27:58.707 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: mpls_lcac_cfg_int_bandwidth_rdm_apply: link GigabitEthernet0/0/0/1 (ifh 0x20) max_bw 1000000 (Kbps), pool0_bw 1000000 (Kbps) Sep 15 02:27:58.707 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: mpls_lcac_cfg_int_bandwidth_rdm_apply: link GigabitEthernet0/0/0/1 (ifh 0x20) pool1_bw 0 (Kbps) Sep 15 02:27:58.707 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: mpls_lcac_cfg_int_bandwidth_mam_apply: link GigabitEthernet0/0/0/1 (ifh 0x20) max_bw 0 (Kbps), pool0_bw 0 (Kbps) Sep 15 02:27:58.707 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: mpls_lcac_cfg_int_bandwidth_mam_apply: link GigabitEthernet0/0/0/1 (ifh 0x20) pool1_bw 0 (Kbps) Sep 15 02:27:58.707 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_im_attr_capacity_handler: link GigabitEthernet0/0/0/2 (ifh 0x28),bw 1000000 (kbps), bw2 125000000 (Bps), event 0 Sep 15 02:27:58.707 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_im_attr_capacity_handler: link GigabitEthernet0/0/0/3 (ifh 0x30),bw 1000000 (kbps), bw2 125000000 (Bps), event 0 Sep 15 02:27:58.707 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:279: lm_iarm_handle_pulse: received pulse (0), flushing IARM IPv4 registration batch. Sep 15 02:27:58.708 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:623: lm_iarm_flush: sent 1 IPv4 (un)register requests to IARM. Sep 15 02:27:59.206 mpls_te/link 0/RP0/CPU0 t4559 SRLG-producer connected Sep 15 02:27:59.209 mpls_te/link 0/RP0/CPU0 t4559 RSI SRLG-producer registration done successfully Sep 15 02:27:59.209 mpls_te/link 0/RP0/CPU0 t4559 Replaying learned SRLGs on all links to RSI Sep 15 02:27:59.209 mpls_te/link 0/RP0/CPU0 t4559 Replaying learned SRLGs on all termination interfaces to RSI Sep 15 02:27:59.695 mpls_te/link 0/RP0/CPU0 t4559 Validating ifindexes for all links Sep 15 02:27:59.695 mpls_te/link 0/RP0/CPU0 t4559 Bulk ifindex lookup for 1 links Sep 15 02:27:59.701 mpls_te/link 0/RP0/CPU0 t4559 Link GigabitEthernet0/0/0/1 (ifhndl 0x20) (0x20) ifindex set to 5 Sep 15 02:27:59.701 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:5569: rrr_lm_update_link_neighbors(): link GigabitEthernet0/0/0/1 (ifh 0x20), flood 0, force 1, Nbr cnt 0 Sep 15 02:28:00.298 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:119: Unable to process adj-change from IGP OSPFarea 0 on link Loopback0 (ifh 0x14) with handle 0x14, reverting to name Sep 15 02:28:00.298 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:145: Unable to process adj-change from IGP OSPF area 0 on link Loopback0 (ifh 0x14) (0 nbrs): link not found Sep 15 02:28:02.500 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:2611: Handling area change: IGP OSPF area 0, is_up = 1, router-id 11.11.11.11 Sep 15 02:28:02.500 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:5569: rrr_lm_update_link_neighbors(): link GigabitEthernet0/0/0/1 (ifh 0x20), flood 0, force 0, Nbr cnt 0 Sep 15 02:28:02.500 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:5406: Periodic Flooding for igp-type: 2 area: 0 0 seconds Sep 15 02:28:02.501 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:5214: System change: flooding to all links/areas: reason area state change Sep 15 02:28:06.901 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3722: lm_im_handler: link GigabitEthernet0/0/0/1 (ifh 0x20), state 17, proto 12, opcode 35 (CREATE/DEL) Sep 15 02:28:06.901 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3727: lm_im_handler: link GigabitEthernet0/0/0/1 (ifh 0x20), intf_type 15, parent i/f None (ifh 0x0), caps 26 Sep 15 02:28:06.901 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3808: lm_im_handler: IM_CREATE: link GigabitEthernet0/0/0/1 (ifh 0x20), state 17, proto 12, opcode 35 Sep 15 02:28:06.904 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:875: mpls_lcac_if_state_register: link GigabitEthernet0/0/0/1 (ifh 0x20), add True Sep 15 02:28:06.904 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:741: lm_iarm_reg_ipv4_add: added IPv4 register(True) request for interface GigabitEthernet0/0/0/1 (ifh 0x20) to IARM batch Sep 15 02:28:06.904 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:756: lm_iarm_reg_ipv4_add: sent pulse (0) to flush IARM IPv4 registration batch. Sep 15 02:28:06.904 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3881: lm_im_handler: Updating link GigabitEthernet0/0/0/1 (ifh 0x20), intf_type 15, data_parent i/f None (ifh 0x0) (IM_CREATE) Sep 15 02:28:06.904 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_idb_capacity: link GigabitEthernet0/0/0/1 (ifh 0x20) BW attribute 0 kbps Sep 15 02:28:06.904 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_link_capacity: link GigabitEthernet0/0/0/1 (ifh 0x20) physical_bw 125000000 Bps Sep 15 02:28:06.904 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: mpls_lcac_cfg_int_bandwidth_rdm_apply: link GigabitEthernet0/0/0/1 (ifh 0x20) max_bw 1000000 (Kbps), pool0_bw 1000000 (Kbps) Sep 15 02:28:06.904 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: mpls_lcac_cfg_int_bandwidth_rdm_apply: link GigabitEthernet0/0/0/1 (ifh 0x20) pool1_bw 0 (Kbps) Sep 15 02:28:06.904 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: mpls_lcac_cfg_int_bandwidth_mam_apply: link GigabitEthernet0/0/0/1 (ifh 0x20) max_bw 0 (Kbps), pool0_bw 0 (Kbps) Sep 15 02:28:06.904 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: mpls_lcac_cfg_int_bandwidth_mam_apply: link GigabitEthernet0/0/0/1 (ifh 0x20) pool1_bw 0 (Kbps) Sep 15 02:28:06.904 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:5304: Flooding on link GigabitEthernet0/0/0/1 (ifh 0x20) suppressed, no change Sep 15 02:28:06.904 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3700: lm_im_handler: link GigabitEthernet0/0/0/1 (ifh 0x20), state 1, proto 12, caps 26, opcode=STATE_VALUE Sep 15 02:28:06.904 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3765: lm_im_handler: IFSTATE_VAL: link GigabitEthernet0/0/0/1 (ifh 0x20), state 1, proto 12, opcode 37 Sep 15 02:28:06.905 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:279: lm_iarm_handle_pulse: received pulse (0), flushing IARM IPv4 registration batch. Sep 15 02:28:06.905 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:623: lm_iarm_flush: sent 1 IPv4 (un)register requests to IARM. Sep 15 02:28:07.197 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:797: lm_ipv4_addr_callback: link GigabitEthernet0/0/0/1 (ifh 0x20), ct=0x0, ps=0x0, addr 10.1.11.11 Sep 15 02:28:07.702 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3700: lm_im_handler: link GigabitEthernet0/0/0/1 (ifh 0x20), state 2, proto 12, caps 26, opcode=STATE_VALUE Sep 15 02:28:07.702 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3765: lm_im_handler: IFSTATE_VAL: link GigabitEthernet0/0/0/1 (ifh 0x20), state 2, proto 12, opcode 37 Sep 15 02:28:08.101 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3700: lm_im_handler: link GigabitEthernet0/0/0/1 (ifh 0x20), state 3, proto 12, caps 26, opcode=STATE_VALUE Sep 15 02:28:08.101 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3765: lm_im_handler: IFSTATE_VAL: link GigabitEthernet0/0/0/1 (ifh 0x20), state 3, proto 12, opcode 37 Sep 15 02:28:08.101 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:5569: rrr_lm_update_link_neighbors(): link GigabitEthernet0/0/0/1 (ifh 0x20), flood 0, force 0, Nbr cnt 0 Sep 15 02:28:08.101 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:5494: Request link adjacencies for link GigabitEthernet0/0/0/1 (ifh 0x20), area 0, IGP OSPF Sep 15 02:28:08.197 mpls_te/link 0/RP0/CPU0 t4559 Validating ifindexes for all links Sep 15 02:28:08.202 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:2565: Processing adj-change for link GigabitEthernet0/0/0/1 (ifh 0x20) (0 nbrs) in area 0, IGP OSPF Sep 15 02:28:08.202 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:2451: rrr_lm_handle_igp_link_info_change: OSPF- link GigabitEthernet0/0/0/1 (ifh 0x20), tot_nbrs 0, subnet type 0, flags 0x2 Sep 15 02:28:08.202 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:2471: rrr_lm_handle_igp_link_info_change: link GigabitEthernet0/0/0/1 (ifh 0x20) new igp admin weight 10, prev. isis wt 0, ospf wt 0 Sep 15 02:28:08.202 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:935: Link GigabitEthernet0/0/0/1 (ifh 0x20): Added area 0 IGP OSPF Sep 15 02:28:08.202 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:1019: Link GigabitEthernet0/0/0/1 (ifh 0x20): Update nbrs for area 0 IGP OSPF Sep 15 02:28:08.202 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:1345: setting IGP cost for link GigabitEthernet0/0/0/1 (ifh 0x20), area 0, protocol OSPF, weight 10 Sep 15 02:28:08.202 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:2523: link GigabitEthernet0/0/0/1 (ifh 0x20), IGP OSPF area 0: no neighbor changes Sep 15 02:28:08.203 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:5295: Flooding on link GigabitEthernet0/0/0/1 (ifh 0x20) data changed Sep 15 02:28:08.203 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:2565: Processing adj-change for link GigabitEthernet0/0/0/1 (ifh 0x20) (0 nbrs) in area 0, IGP OSPF Sep 15 02:28:08.203 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:2451: rrr_lm_handle_igp_link_info_change: OSPF- link GigabitEthernet0/0/0/1 (ifh 0x20), tot_nbrs 0, subnet type 0, flags 0x2 Sep 15 02:28:08.203 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:2471: rrr_lm_handle_igp_link_info_change: link GigabitEthernet0/0/0/1 (ifh 0x20) new igp admin weight 10, prev. isis wt 0, ospf wt 0 Sep 15 02:28:08.203 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:2523: link GigabitEthernet0/0/0/1 (ifh 0x20), IGP OSPF area 0: no neighbor changes Sep 15 02:28:18.228 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:2565: Processing adj-change for link GigabitEthernet0/0/0/1 (ifh 0x20) (0 nbrs) in area 0, IGP OSPF Sep 15 02:28:18.228 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:2451: rrr_lm_handle_igp_link_info_change: OSPF- link GigabitEthernet0/0/0/1 (ifh 0x20), tot_nbrs 0, subnet type 1, flags 0xb Sep 15 02:28:18.228 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:1019: Link GigabitEthernet0/0/0/1 (ifh 0x20): Update nbrs for area 0 IGP OSPF Sep 15 02:28:18.228 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:1515: setting subnet type for link GigabitEthernet0/0/0/1 (ifh 0x20), area 0, protocol 2, subnet type 1 Sep 15 02:28:18.228 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:2471: rrr_lm_handle_igp_link_info_change: link GigabitEthernet0/0/0/1 (ifh 0x20) new igp admin weight 10, prev. isis wt 0, ospf wt 0 Sep 15 02:28:18.228 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:2498: Link GigabitEthernet0/0/0/1 (ifh 0x20): update DB for 1 neighbors Sep 15 02:28:18.228 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:1559: Received neighbor 10.1.11.1 on link GigabitEthernet0/0/0/1 (ifh 0x20), IGP OSPF area 0 Sep 15 02:28:18.229 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:1578: Rcvd nbr node ID 1.1.1.1, state 1 Sep 15 02:28:18.229 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:1596: Matching existing neighbor found? False Sep 15 02:28:18.229 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:1714: Neighbor unknown: creating new one Sep 15 02:28:18.229 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:1286: link GigabitEthernet0/0/0/1 (ifh 0x20): setting IGP cost: 10, in area 0, protocol OSPF Sep 15 02:28:18.229 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:1429: link GigabitEthernet0/0/0/1 (ifh 0x20), IGP OSPF area 0: subnet type changed to 1 Sep 15 02:28:18.229 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:1825: Neighbor created link GigabitEthernet0/0/0/1 (ifh 0x20) nbr addr 10.1.11.1, count 1, nbr state 1 Sep 15 02:28:18.229 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:5295: Flooding on link GigabitEthernet0/0/0/1 (ifh 0x20) data changed Sep 15 02:30:58.899 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:5471: Forced Flooding for IGP OSPF, area 0 Sep 15 02:33:58.895 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK: rrr_lm_im_attr_capacity_handler: link tunnel-te0 (ifh 0x1c),bw 0 (kbps), bw2 0 (Bps), event 0 Sep 15 02:33:58.898 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3722: lm_im_handler: link tunnel-te0 (ifh 0x1c), state 17, proto 12, opcode 35 (CREATE/DEL) Sep 15 02:33:58.898 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3727: lm_im_handler: link tunnel-te0 (ifh 0x1c), intf_type 36, parent i/f None (ifh 0x0), caps 26 Sep 15 02:33:58.898 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:3808: lm_im_handler: IM_CREATE: link tunnel-te0 (ifh 0x1c), state 17, proto 12, opcode 35 Sep 15 02:42:03.172 mpls_te/link 0/RP0/CPU0 t4559 LM_LINK:18474: Link:10.1.2.1, IGP OSPF, area 0 helddown in topology for 10 secs (due to path error) RP/0/RP0/CPU0:PE1#show mpls traffic-eng trace bselect Tue Sep 15 02:57:35.428 UTC 45 wrapping entries (67648 possible, 320 allocated, 0 filtered, 45 total) Sep 15 02:28:02.600 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:18.230 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:18.236 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:18.236 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:20.574 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:20.607 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:20.607 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:29.176 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:29.209 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:29.209 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:48.084 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:48.118 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:48.118 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:49.008 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:49.041 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:49.042 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:53.886 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:53.919 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:53.919 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:57.920 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:57.920 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:58.602 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:58.635 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:58.670 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:58.938 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:28:58.971 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:30:59.216 mpls_te/bselect 0/RP0/CPU0 t4559 tebm_verify_bkup_db: Verifying existing bkup data Sep 15 02:42:03.172 mpls_te/bselect 0/RP0/CPU0 t4559 frr_event_lsp_down: T:0, L:3, prot_if GigabitEthernet0/0/0/1 (ifhndl 0x20) , NH:10.1.11.1 Sep 15 02:49:36.061 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:49:36.094 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7897: frr_plsp_promote_backup: cur promo timer 300, delay 10 sec, 0 ms Sep 15 02:51:09.732 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:6987: frr_event_reroute_added: T:0, L:4, prot_des 0, NH:10.1.11.1 Sep 15 02:51:09.733 mpls_te/bselect 0/RP0/CPU0 t4559 te_frr_add_new_plsp: T:0, L:4 prot_if GigabitEthernet0/0/0/1 (ifhndl 0x20) , backup_if None (ifhndl 0x0) , protection None Sep 15 02:51:09.733 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:6883: te_frr_add_new_plsp: adding T:0, in no_bkup Sep 15 02:51:09.733 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:3665: te_frr_find_backup: find backup bw 0, bw_type 2 Sep 15 02:51:50.701 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7058: frr_event_resv_arrive: T:0, L:5, backup None (ifh 0x0), NH:10.1.11.1 Sep 15 02:51:50.701 mpls_te/bselect 0/RP0/CPU0 t4559 te_frr_add_new_plsp: T:0, L:5 prot_if GigabitEthernet0/0/0/1 (ifhndl 0x20) , backup_if None (ifhndl 0x0) , protection None Sep 15 02:51:50.701 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:6883: te_frr_add_new_plsp: adding T:0, in no_bkup Sep 15 02:51:50.701 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:3665: te_frr_find_backup: find backup bw 0, bw_type 2 Sep 15 02:51:50.702 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:7058: frr_event_resv_arrive: T:0, L:5, backup None (ifh 0x0), NH:10.1.11.1 Sep 15 02:51:50.702 mpls_te/bselect 0/RP0/CPU0 t4559 te_frr_add_new_plsp: T:0, L:5 prot_if GigabitEthernet0/0/0/1 (ifhndl 0x20) , backup_if None (ifhndl 0x0) , protection None Sep 15 02:51:50.702 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:6818: te_frr_add_new_plsp: T:0, is already in nobackup database Sep 15 02:51:50.702 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:3665: te_frr_find_backup: find backup bw 0, bw_type 2 Sep 15 02:52:30.905 mpls_te/bselect 0/RP0/CPU0 t4559 frr_event_lsp_down: T:0, L:4, prot_if GigabitEthernet0/0/0/1 (ifhndl 0x20) , NH:10.1.11.1 Sep 15 02:54:46.095 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:3665: te_frr_find_backup: find backup bw 0, bw_type 2 Sep 15 02:54:46.095 mpls_te/bselect 0/RP0/CPU0 t4559 FRR:4296: frr_event_promote_intf_plsp: All intf processed: promotion complete .. RP/0/RP0/CPU0:PE1#show rsvp trace signalling Tue Sep 15 02:57:35.629 UTC 84 wrapping entries (264256 possible, 320 allocated, 0 filtered, 84 total) Sep 15 02:33:59.098 rsvp/sig 0/RP0/CPU0 t4383 SIG:4545: PATH creating head: local/nbor/nhop (11.11.11.11/1.1.1.1/10.1.11.1), GigabitEthernet0/0/0/1 (ifh 0x20), psbs: 0, rsbs: 0 Sep 15 02:33:59.098 rsvp/sig 0/RP0/CPU0 t4383 SIG:2836: PATH outgoing creating: flags:0xc0000005, local_rid:11.11.11.11, nbor:1.1.1.1, nhop:10.1.11.1, next_ifh:GigabitEthernet0/0/0/1 (ifh 0x20), obj_len: 0 Sep 15 02:33:59.098 rsvp/sig 0/RP0/CPU0 t4383 SIG:887: PATH Tunnel IPv4 outgoing: dst (22.22.22.22:0), src (11.11.11.11:3) Sep 15 02:33:59.100 rsvp/sig 0/RP0/CPU0 t4383 SIG:721: PATH Tunnel IPv4 created: dst (22.22.22.22:0), src (11.11.11.11:3) Sep 15 02:33:59.253 rsvp/sig 0/RP0/CPU0 t4383 SIG:4654: RESV creating network: GigabitEthernet0/0/0/1 (ifh 0x20), in GigabitEthernet0/0/0/1 (ifh 0x20), obj len: 148, IP src: 10.1.11.1, psbs: 1, rsbs: 0 Sep 15 02:33:59.253 rsvp/sig 0/RP0/CPU0 t4383 TC:276: Bandwidth allocation: GigabitEthernet0/0/0/1 (ifh 0x20), current (0 Bps), port 0, src 11.11.11.11 id 3 Sep 15 02:33:59.253 rsvp/sig 0/RP0/CPU0 t4383 SIG:2881: RESV outgoing creating: rsb flags: 0xc0000011, psb flags: 0xc0000004, local/nbor 11.11.11.11/0.0.0.0, obj len: 0x94, wedged 0 Sep 15 02:33:59.253 rsvp/sig 0/RP0/CPU0 t4383 SIG:362: RESV Tunnel IPv4 created: dst (22.22.22.22:0), src (11.11.11.11:3) Sep 15 02:33:59.305 rsvp/sig 0/RP0/CPU0 t4383 SIG:492: Assigned backup None (ifh 0x0): dst (22.22.22.22:0), src (11.11.11.11:3) Sep 15 02:34:06.852 rsvp/sig 0/RP0/CPU0 t4383 SIG:4549: PATH creating network: GigabitEthernet0/0/0/1 (ifh 0x20), obj len: 236, IP src: 10.1.11.1 IP dst: 10.1.11.11, psbs: 0, rsbs: 0 Sep 15 02:34:06.852 rsvp/sig 0/RP0/CPU0 t4383 SIG:721: PATH Tunnel IPv4 created: dst (11.11.11.11:0), src (22.22.22.22:3) Sep 15 02:34:06.858 rsvp/sig 0/RP0/CPU0 t4383 SIG:4649: RESV creating tail: local/nbor (11.11.11.11/1.1.1.1), obj len: 80, None (ifh 0x0), psbs: 1, rsbs: 0 Sep 15 02:34:06.858 rsvp/sig 0/RP0/CPU0 t4383 SIG:2881: RESV outgoing creating: rsb flags: 0xd0000005, psb flags: 0xc0000018, local/nbor 11.11.11.11/1.1.1.1, obj len: 0x50, wedged 0 Sep 15 02:34:06.858 rsvp/sig 0/RP0/CPU0 t4383 SIG:528: RESV Tunnel IPv4 outgoing: dst (11.11.11.11:0), src (22.22.22.22:3) Sep 15 02:34:06.858 rsvp/sig 0/RP0/CPU0 t4383 SIG:362: RESV Tunnel IPv4 created: dst (11.11.11.11:0), src (22.22.22.22:3) Sep 15 02:42:03.167 rsvp/sig 0/RP0/CPU0 t4383 SIG:9276: PathErr: from network for dst (22.22.22.22:0), src (11.11.11.11:3); PSB flags: 0xc0000004 Sep 15 02:42:03.167 rsvp/sig 0/RP0/CPU0 t4383 SIG:9279: PathErr: (24, 5)-(Error: routing (24), Suberror: no route to dest (5)) at 10.1.2.1; flags: 0x4 Sep 15 02:42:03.168 rsvp/sig 0/RP0/CPU0 t4383 SIG:3904: Head PATH destroy pending : dst (22.22.22.22:0), src (11.11.11.11:3) reason: (16): State deleted due to PERR w/ PSR from network Sep 15 02:42:03.168 rsvp/sig 0/RP0/CPU0 t4383 SIG:1214: RESV destroy: dst (22.22.22.22:0), src (11.11.11.11:3) reason: (2): State deleted due to signaling Sep 15 02:42:03.168 rsvp/sig 0/RP0/CPU0 t4383 SIG:1216: RESV destroy: flags 0x0, rsb flags 0xc0000030, request flags 0x0 Sep 15 02:42:03.168 rsvp/sig 0/RP0/CPU0 t4383 TC:276: Bandwidth allocation: GigabitEthernet0/0/0/1 (ifh 0x20), current (0 Bps), port 0, src 11.11.11.11 id 3 Sep 15 02:42:03.168 rsvp/sig 0/RP0/CPU0 t4383 SIG:3904: Head PATH destroy pending : dst (22.22.22.22:0), src (11.11.11.11:3) reason: (2): State deleted due to signaling Sep 15 02:42:03.168 rsvp/sig 0/RP0/CPU0 t4383 SIG:3929: PATH destroy: dst (11.11.11.11:0), src (22.22.22.22:3) reason: (2): State deleted due to signaling Sep 15 02:42:03.168 rsvp/sig 0/RP0/CPU0 t4383 SIG:3931: PATH destroy: flags 0x0, psb flags 0xc0000018, pfc flags 0x0 Sep 15 02:42:03.168 rsvp/sig 0/RP0/CPU0 t4383 SIG:1214: RESV destroy: dst (11.11.11.11:0), src (22.22.22.22:3) reason: (2): State deleted due to signaling Sep 15 02:42:03.168 rsvp/sig 0/RP0/CPU0 t4383 SIG:1216: RESV destroy: flags 0x190000, rsb flags 0xc0000004, request flags 0x86001846 Sep 15 02:42:03.175 rsvp/sig 0/RP0/CPU0 t4383 SIG:3929: PATH destroy: dst (22.22.22.22:0), src (11.11.11.11:3) reason: (5): State deleted due to client app Sep 15 02:42:03.175 rsvp/sig 0/RP0/CPU0 t4383 SIG:3931: PATH destroy: flags 0x0, psb flags 0xc0000004, pfc flags 0x80180009 Sep 15 02:42:03.180 rsvp/sig 0/RP0/CPU0 t4383 SIG:4545: PATH creating head: local/nbor/nhop (11.11.11.11/1.1.1.1/10.1.11.1), GigabitEthernet0/0/0/1 (ifh 0x20), psbs: 0, rsbs: 0 Sep 15 02:42:03.180 rsvp/sig 0/RP0/CPU0 t4383 SIG:2836: PATH outgoing creating: flags:0xc0000005, local_rid:11.11.11.11, nbor:1.1.1.1, nhop:10.1.11.1, next_ifh:GigabitEthernet0/0/0/1 (ifh 0x20), obj_len: 0 Sep 15 02:42:03.180 rsvp/sig 0/RP0/CPU0 t4383 SIG:887: PATH Tunnel IPv4 outgoing: dst (22.22.22.22:0), src (11.11.11.11:4) Sep 15 02:42:03.180 rsvp/sig 0/RP0/CPU0 t4383 SIG:721: PATH Tunnel IPv4 created: dst (22.22.22.22:0), src (11.11.11.11:4) Sep 15 02:42:03.390 rsvp/sig 0/RP0/CPU0 t4383 SIG:4549: PATH creating network: GigabitEthernet0/0/0/1 (ifh 0x20), obj len: 252, IP src: 1.1.1.1 IP dst: 10.1.11.11, psbs: 0, rsbs: 0 Sep 15 02:42:03.390 rsvp/sig 0/RP0/CPU0 t4383 SIG:721: PATH Tunnel IPv4 created: dst (11.11.11.11:0), src (22.22.22.22:4) Sep 15 02:42:03.396 rsvp/sig 0/RP0/CPU0 t4383 SIG:4649: RESV creating tail: local/nbor (11.11.11.11/1.1.1.1), obj len: 80, None (ifh 0x0), psbs: 1, rsbs: 0 Sep 15 02:42:03.396 rsvp/sig 0/RP0/CPU0 t4383 SIG:2881: RESV outgoing creating: rsb flags: 0xd0000005, psb flags: 0xc0000018, local/nbor 11.11.11.11/1.1.1.1, obj len: 0x50, wedged 0 Sep 15 02:42:03.396 rsvp/sig 0/RP0/CPU0 t4383 SIG:528: RESV Tunnel IPv4 outgoing: dst (11.11.11.11:0), src (22.22.22.22:4) Sep 15 02:42:03.396 rsvp/sig 0/RP0/CPU0 t4383 SIG:362: RESV Tunnel IPv4 created: dst (11.11.11.11:0), src (22.22.22.22:4) Sep 15 02:42:03.580 rsvp/sig 0/RP0/CPU0 t4383 SIG:4654: RESV creating network: GigabitEthernet0/0/0/1 (ifh 0x20), in GigabitEthernet0/0/0/1 (ifh 0x20), obj len: 308, IP src: 10.1.11.1, psbs: 1, rsbs: 0 Sep 15 02:42:03.580 rsvp/sig 0/RP0/CPU0 t4383 TC:276: Bandwidth allocation: GigabitEthernet0/0/0/1 (ifh 0x20), current (0 Bps), port 0, src 11.11.11.11 id 4 Sep 15 02:42:03.580 rsvp/sig 0/RP0/CPU0 t4383 SIG:2881: RESV outgoing creating: rsb flags: 0xc0000011, psb flags: 0xc0000004, local/nbor 11.11.11.11/0.0.0.0, obj len: 0x134, wedged 0 Sep 15 02:42:03.580 rsvp/sig 0/RP0/CPU0 t4383 SIG:362: RESV Tunnel IPv4 created: dst (22.22.22.22:0), src (11.11.11.11:4) Sep 15 02:42:03.588 rsvp/sig 0/RP0/CPU0 t4383 SIG:492: Assigned backup None (ifh 0x0): dst (22.22.22.22:0), src (11.11.11.11:4) Sep 15 02:42:31.329 rsvp/sig 0/RP0/CPU0 t4383 TC:276: Bandwidth allocation: GigabitEthernet0/0/0/1 (ifh 0x20), current (0 Bps), port 0, src 11.11.11.11 id 4 Sep 15 02:42:31.329 rsvp/sig 0/RP0/CPU0 t4383 SIG:2881: RESV outgoing creating: rsb flags: 0xc0000130, psb flags: 0xc0000004, local/nbor 11.11.11.11/0.0.0.0, obj len: 0x134, wedged 0 Sep 15 02:42:31.329 rsvp/sig 0/RP0/CPU0 t4383 SIG:445: RESV Tunnel IPv4 changed: dst (22.22.22.22:0), src (11.11.11.11:4) Sep 15 02:51:09.735 rsvp/sig 0/RP0/CPU0 t4383 SIG:2836: PATH outgoing creating: flags:0xc0000204, local_rid:0.0.0.0, nbor:1.1.1.1, nhop:10.1.11.1, next_ifh:GigabitEthernet0/0/0/1 (ifh 0x20), obj_len: 0 Sep 15 02:51:09.735 rsvp/sig 0/RP0/CPU0 t4383 SIG:887: PATH Tunnel IPv4 outgoing: dst (22.22.22.22:0), src (11.11.11.11:4) Sep 15 02:51:09.735 rsvp/sig 0/RP0/CPU0 t4383 SIG:804: PATH Tunnel IPv4 changed: dst (22.22.22.22:0), src (11.11.11.11:4) Sep 15 02:51:09.735 rsvp/sig 0/RP0/CPU0 t4383 SIG:492: Assigned backup None (ifh 0x0): dst (22.22.22.22:0), src (11.11.11.11:4) Sep 15 02:51:15.890 rsvp/sig 0/RP0/CPU0 t4383 SIG:2881: RESV outgoing creating: rsb flags: 0xc0000004, psb flags: 0xc0000218, local/nbor 11.11.11.11/1.1.1.1, obj len: 0x50, wedged 0 Sep 15 02:51:15.890 rsvp/sig 0/RP0/CPU0 t4383 SIG:528: RESV Tunnel IPv4 outgoing: dst (11.11.11.11:0), src (22.22.22.22:4) Sep 15 02:51:15.890 rsvp/sig 0/RP0/CPU0 t4383 SIG:804: PATH Tunnel IPv4 changed: dst (11.11.11.11:0), src (22.22.22.22:4) Sep 15 02:51:15.896 rsvp/sig 0/RP0/CPU0 t4383 SIG:445: RESV Tunnel IPv4 changed: dst (11.11.11.11:0), src (22.22.22.22:4) Sep 15 02:51:36.647 rsvp/sig 0/RP0/CPU0 t4383 TC:276: Bandwidth allocation: GigabitEthernet0/0/0/1 (ifh 0x20), current (0 Bps), port 0, src 11.11.11.11 id 4 Sep 15 02:51:36.647 rsvp/sig 0/RP0/CPU0 t4383 SIG:2881: RESV outgoing creating: rsb flags: 0xc0000130, psb flags: 0xc0000004, local/nbor 11.11.11.11/0.0.0.0, obj len: 0x134, wedged 0 Sep 15 02:51:36.647 rsvp/sig 0/RP0/CPU0 t4383 SIG:445: RESV Tunnel IPv4 changed: dst (22.22.22.22:0), src (11.11.11.11:4) Sep 15 02:51:43.636 rsvp/sig 0/RP0/CPU0 t4383 TC:276: Bandwidth allocation: GigabitEthernet0/0/0/1 (ifh 0x20), current (0 Bps), port 0, src 11.11.11.11 id 4 Sep 15 02:51:43.636 rsvp/sig 0/RP0/CPU0 t4383 SIG:2881: RESV outgoing creating: rsb flags: 0xc0000130, psb flags: 0xc0000004, local/nbor 11.11.11.11/0.0.0.0, obj len: 0x134, wedged 0 Sep 15 02:51:43.636 rsvp/sig 0/RP0/CPU0 t4383 SIG:445: RESV Tunnel IPv4 changed: dst (22.22.22.22:0), src (11.11.11.11:4) Sep 15 02:51:50.529 rsvp/sig 0/RP0/CPU0 t4383 SIG:4545: PATH creating head: local/nbor/nhop (11.11.11.11/1.1.1.1/10.1.11.1), GigabitEthernet0/0/0/1 (ifh 0x20), psbs: 1, rsbs: 1 Sep 15 02:51:50.529 rsvp/sig 0/RP0/CPU0 t4383 SIG:2836: PATH outgoing creating: flags:0xc0000005, local_rid:11.11.11.11, nbor:1.1.1.1, nhop:10.1.11.1, next_ifh:GigabitEthernet0/0/0/1 (ifh 0x20), obj_len: 0 Sep 15 02:51:50.529 rsvp/sig 0/RP0/CPU0 t4383 SIG:887: PATH Tunnel IPv4 outgoing: dst (22.22.22.22:0), src (11.11.11.11:5) Sep 15 02:51:50.529 rsvp/sig 0/RP0/CPU0 t4383 SIG:721: PATH Tunnel IPv4 created: dst (22.22.22.22:0), src (11.11.11.11:5) Sep 15 02:51:50.697 rsvp/sig 0/RP0/CPU0 t4383 SIG:4654: RESV creating network: GigabitEthernet0/0/0/1 (ifh 0x20), in GigabitEthernet0/0/0/1 (ifh 0x20), obj len: 244, IP src: 10.1.11.1, psbs: 2, rsbs: 1 Sep 15 02:51:50.697 rsvp/sig 0/RP0/CPU0 t4383 TC:276: Bandwidth allocation: GigabitEthernet0/0/0/1 (ifh 0x20), current (0 Bps), port 0, src 11.11.11.11 id 5 Sep 15 02:51:50.697 rsvp/sig 0/RP0/CPU0 t4383 SIG:2881: RESV outgoing creating: rsb flags: 0xc0000011, psb flags: 0xc0000004, local/nbor 11.11.11.11/0.0.0.0, obj len: 0xf4, wedged 0 Sep 15 02:51:50.697 rsvp/sig 0/RP0/CPU0 t4383 SIG:362: RESV Tunnel IPv4 created: dst (22.22.22.22:0), src (11.11.11.11:5) Sep 15 02:51:50.705 rsvp/sig 0/RP0/CPU0 t4383 SIG:492: Assigned backup None (ifh 0x0): dst (22.22.22.22:0), src (11.11.11.11:5) Sep 15 02:51:54.280 rsvp/sig 0/RP0/CPU0 t4383 SIG:4549: PATH creating network: GigabitEthernet0/0/0/1 (ifh 0x20), obj len: 236, IP src: 10.1.11.1 IP dst: 10.1.11.11, psbs: 1, rsbs: 1 Sep 15 02:51:54.280 rsvp/sig 0/RP0/CPU0 t4383 SIG:721: PATH Tunnel IPv4 created: dst (11.11.11.11:0), src (22.22.22.22:5) Sep 15 02:51:54.287 rsvp/sig 0/RP0/CPU0 t4383 SIG:4649: RESV creating tail: local/nbor (11.11.11.11/1.1.1.1), obj len: 80, None (ifh 0x0), psbs: 2, rsbs: 1 Sep 15 02:51:54.287 rsvp/sig 0/RP0/CPU0 t4383 SIG:2881: RESV outgoing creating: rsb flags: 0xd0000005, psb flags: 0xc0000018, local/nbor 11.11.11.11/1.1.1.1, obj len: 0x50, wedged 0 Sep 15 02:51:54.287 rsvp/sig 0/RP0/CPU0 t4383 SIG:528: RESV Tunnel IPv4 outgoing: dst (11.11.11.11:0), src (22.22.22.22:5) Sep 15 02:51:54.287 rsvp/sig 0/RP0/CPU0 t4383 SIG:362: RESV Tunnel IPv4 created: dst (11.11.11.11:0), src (22.22.22.22:5) Sep 15 02:52:30.908 rsvp/sig 0/RP0/CPU0 t4383 SIG:3929: PATH destroy: dst (22.22.22.22:0), src (11.11.11.11:4) reason: (5): State deleted due to client app Sep 15 02:52:30.908 rsvp/sig 0/RP0/CPU0 t4383 SIG:3931: PATH destroy: flags 0x0, psb flags 0xc0000004, pfc flags 0x80180009 Sep 15 02:52:30.908 rsvp/sig 0/RP0/CPU0 t4383 SIG:1214: RESV destroy: dst (22.22.22.22:0), src (11.11.11.11:4) reason: (5): State deleted due to client app Sep 15 02:52:30.908 rsvp/sig 0/RP0/CPU0 t4383 SIG:1216: RESV destroy: flags 0x180000, rsb flags 0xc0000030, request flags 0x0 Sep 15 02:52:30.908 rsvp/sig 0/RP0/CPU0 t4383 TC:276: Bandwidth allocation: GigabitEthernet0/0/0/1 (ifh 0x20), current (0 Bps), port 0, src 11.11.11.11 id 4 Sep 15 02:52:34.570 rsvp/sig 0/RP0/CPU0 t4383 SIG:3929: PATH destroy: dst (11.11.11.11:0), src (22.22.22.22:4) reason: (2): State deleted due to signaling Sep 15 02:52:34.570 rsvp/sig 0/RP0/CPU0 t4383 SIG:3931: PATH destroy: flags 0x0, psb flags 0xc0000018, pfc flags 0x0 Sep 15 02:52:34.570 rsvp/sig 0/RP0/CPU0 t4383 SIG:1214: RESV destroy: dst (11.11.11.11:0), src (22.22.22.22:4) reason: (2): State deleted due to signaling Sep 15 02:52:34.570 rsvp/sig 0/RP0/CPU0 t4383 SIG:1216: RESV destroy: flags 0x190000, rsb flags 0xc0000004, request flags 0x86003846