Reset Search
 

 

Article

VRRP transition from INIT-to-BACKUP takes more than 40 seconds with track-ping

« Go Back

Information

 
TitleVRRP transition from INIT-to-BACKUP takes more than 40 seconds with track-ping
Objective
  • If we configure the below provided VRRP track-ping configuration:

​configure vrrp vlan test_data vrid 10 add track-ping 1.1.1.1 frequency 2 miss 1

  • When the VRRP track-ping fails on the VRRP Master, it goes into INIT state.
  • When it is back to normal, the VRRP state change on Master takes more than >40 seconds to change from INIT -to- Backup state. However, from Backup -to- Master takes only 3 seconds. 
  • Even when the continuous ping to vlan/IP restored immediately and back to normal, the VRRP state change is not spontaneous.
  • Below provided outputs shows the VRRP transition time:

SW-1_A2:U31.91 # show log
02/28/2017 16:09:20.13 <Noti:VRRP.StateChng> VLAN test_data vrid 10: transitioning to MASTER(2)
02/28/2017 16:09:19.53 <Warn:VRRP.Advert.Ign> Advert for VR on vlan test_data vrid 10 ignored: ignoring lower priority/preempted advert
02/28/2017 16:09:17.52 <Warn:VRRP.Advert.Ign> Previous message repeated 5 additional times in the last 2 second(s)
02/28/2017 16:09:16.92 <Noti:VRRP.StateChng> VLAN test_data vrid 10: transitioning to BACKUP(1)
02/28/2017 16:08:02.93 <Noti:VRRP.StateChng> VLAN test_data vrid 10: transitioning to INIT(0)


 
Environment
  • EXOS 16.1.2.14patch1-1
  • Summit ALL
Procedure
  • The issue will not seen with track-iproute/track-vlan because, when we configure track-ping, time for vrrp router to change from INITàBACKUP after ping restores depends upon the "frequency/miss" configuration in the below command:      
  1. configure vrrp vlan <vlan_name> vrid <vr_id> add track-ping <ip_add> frequency <interval_b/n_pings> miss <num_misses>

                                e.g. if frequency=1, miss=1 then time taken from INIT àBACKUP after ping restores should be 10 x (miss) x (freq) i.e. 10 sec in this case.
                                if frequency=3, miss=2 then it should be 10*2*3 = 60 seconds

  •  Actually the time taken for VRRP transition from INIT->BACKUP depends on when the VRRP ping is restored (Trigger for VRRP state machine to change from INIT) i.e. after the link restored.
  • If there is intermittent VRRP tracked ping failures due to any network flaps/link flaps during the transition from INIT to BACKUP, then this timer will be restarted again (i.e. 10 x miss x frequency). This is just to avoid additional VRRP flaps and hence to avoid further traffic loss because of above network flaps/link flaps.
  • Regarding the transition from BACKUP to MASTER, once the VRRP state transits to BACKUP, it will start Master_Down_Timer (3 x Advertisement_Interval + Skew Time), Skew Time = (((256 - priority) * Master_Adver_Interval) / 256).

 
Additional notes
  • Enabling the below log filter and then calculating the time from when ping restores to VRRP state transition to BACKUP will give us exact transition time as per configured. 
enable log debug-mode
configure log filter "DefaultFilter" add events NetTools severity debug-verbose
  • We can disable the log debug-mode once the transition time has been verified.
​For e.g.:
  • If we have configured the VRRP track-ping switch with Frequency-1 and miss-1, the below provided lab output will show the time taken for VRRP transitions:

03/02/2017 17:38:53.04 <Noti:VRRP.StateChng> : VLAN test_data vrid 10: transitioning to MASTER(2)
03/02/2017 17:38:52.80 <Verb:NetTools.RxPingReply> : Echo reply; 8 bytes from 1.1.1.1: icmp_seq=37 ttl=64 [1488443932.804069 - 1488443932.802855]
03/02/2017 17:38:52.80 <Verb:NetTools.ICMPPktRxFmSock> : ICMP packet from 1.1.1.1 to 20.1.1.1 on socket 42-2 type 0 code 0
03/02/2017 17:38:52.80 <Verb:NetTools.ProcTrackingEvent> : Received event 1 for target 1.1.1.1, VR id 2, freq 1, misses 1(0)
03/02/2017 17:38:52.38 <Warn:VRRP.Advert.Ign> : Advert for VR on vlan test_data vrid 10 ignored: ignoring lower priority/preempted advert
03/02/2017 17:38:52.38 <Warn:VRRP.Advert.Ign> : Advert for VR on vlan test_data vrid 10 ignored: ignoring lower priority/preempted advert
03/02/2017 17:38:51.80 <Verb:NetTools.RxPingReply> : Echo reply; 8 bytes from 1.1.1.1: icmp_seq=36 ttl=64 [1488443931.804249 - 1488443931.802834]
03/02/2017 17:38:51.80 <Verb:NetTools.ICMPPktRxFmSock> : ICMP packet from 1.1.1.1 to 20.1.1.1 on socket 42-2 type 0 code 0
03/02/2017 17:38:51.80 <Verb:NetTools.ProcTrackingEvent> : Received event 1 for target 1.1.1.1, VR id 2, freq 1, misses 1(0)
03/02/2017 17:38:51.39 <Warn:VRRP.Advert.Ign> : Advert for VR on vlan test_data vrid 10 ignored: ignoring lower priority/preempted advert
03/02/2017 17:38:51.39 <Warn:VRRP.Advert.Ign> : Advert for VR on vlan test_data vrid 10 ignored: ignoring lower priority/preempted advert
03/02/2017 17:38:50.80 <Verb:NetTools.RxPingReply> : Echo reply; 8 bytes from 1.1.1.1: icmp_seq=35 ttl=64 [1488443930.804026 - 1488443930.802837]
03/02/2017 17:38:50.80 <Verb:NetTools.ICMPPktRxFmSock> : ICMP packet from 1.1.1.1 to 20.1.1.1 on socket 42-2 type 0 code 0
03/02/2017 17:38:50.80 <Verb:NetTools.ProcTrackingEvent> : Received event 1 for target 1.1.1.1, VR id 2, freq 1, misses 1(0)
03/02/2017 17:38:50.40 <Warn:VRRP.Advert.Ign> : Advert for VR on vlan test_data vrid 10 ignored: ignoring lower priority/preempted advert
03/02/2017 17:38:50.40 <Warn:VRRP.Advert.Ign> : Advert for VR on vlan test_data vrid 10 ignored: ignoring lower priority/preempted advert
03/02/2017 17:38:49.80 <Verb:NetTools.RxPingReply> : Echo reply; 8 bytes from 1.1.1.1: icmp_seq=34 ttl=64 [1488443929.805918 - 1488443929.803030]
03/02/2017 17:38:49.80 <Verb:NetTools.ICMPPktRxFmSock> : ICMP packet from 1.1.1.1 to 20.1.1.1 on socket 42-2 type 0 code 0
03/02/2017 17:38:49.80 <Noti:VRRP.StateChng> : VLAN test_data vrid 10: transitioning to BACKUP(1)
03/02/2017 17:38:49.80 <Verb:NetTools.ProcTrackingEvent> : Received event 2 for target 1.1.1.1, VR id 2, freq 1, misses 1(0)
03/02/2017 17:38:49.80 <Verb:NetTools.ProcTrackingEvent> : Received event 1 for target 1.1.1.1, VR id 2, freq 1, misses 1(0)
03/02/2017 17:38:48.80 <Verb:NetTools.RxPingReply> : Echo reply; 8 bytes from 1.1.1.1: icmp_seq=33 ttl=64 [1488443928.804024 - 1488443928.802857]
03/02/2017 17:38:48.80 <Verb:NetTools.ICMPPktRxFmSock> : ICMP packet from 1.1.1.1 to 20.1.1.1 on socket 42-2 type 0 code 0
03/02/2017 17:38:48.80 <Verb:NetTools.ProcTrackingEvent> : Received event 1 for target 1.1.1.1, VR id 2, freq 1, misses 1(0)
03/02/2017 17:38:47.80 <Verb:NetTools.RxPingReply> : Echo reply; 8 bytes from 1.1.1.1: icmp_seq=32 ttl=64 [1488443927.804190 - 1488443927.802892]
03/02/2017 17:38:47.80 <Verb:NetTools.ICMPPktRxFmSock> : ICMP packet from 1.1.1.1 to 20.1.1.1 on socket 42-2 type 0 code 0
03/02/2017 17:38:47.80 <Verb:NetTools.ProcTrackingEvent> : Received event 1 for target 1.1.1.1, VR id 2, freq 1, misses 1(0)
03/02/2017 17:38:46.80 <Verb:NetTools.RxPingReply> : Echo reply; 8 bytes from 1.1.1.1: icmp_seq=31 ttl=64 [1488443926.804015 - 1488443926.802848]
03/02/2017 17:38:46.80 <Verb:NetTools.ICMPPktRxFmSock> : ICMP packet from 1.1.1.1 to 20.1.1.1 on socket 42-2 type 0 code 0
03/02/2017 17:38:46.80 <Verb:NetTools.ProcTrackingEvent> : Received event 1 for target 1.1.1.1, VR id 2, freq 1, misses 1(0)
03/02/2017 17:38:45.80 <Verb:NetTools.RxPingReply> : Echo reply; 8 bytes from 1.1.1.1: icmp_seq=30 ttl=64 [1488443925.804105 - 1488443925.802860]
03/02/2017 17:38:45.80 <Verb:NetTools.ICMPPktRxFmSock> : ICMP packet from 1.1.1.1 to 20.1.1.1 on socket 42-2 type 0 code 0
03/02/2017 17:38:45.80 <Verb:NetTools.ProcTrackingEvent> : Received event 1 for target 1.1.1.1, VR id 2, freq 1, misses 1(0)
03/02/2017 17:38:44.80 <Verb:NetTools.RxPingReply> : Echo reply; 8 bytes from 1.1.1.1: icmp_seq=29 ttl=64 [1488443924.806237 - 1488443924.800279]
03/02/2017 17:38:44.80 <Verb:NetTools.ICMPPktRxFmSock> : ICMP packet from 1.1.1.1 to 20.1.1.1 on socket 42-2 type 0 code 0
03/02/2017 17:38:44.80 <Verb:NetTools.ProcTrackingEvent> : Received event 1 for target 1.1.1.1, VR id 2, freq 1, misses 1(0)
03/02/2017 17:38:43.80 <Verb:NetTools.RxPingReply> : Echo reply; 8 bytes from 1.1.1.1: icmp_seq=28 ttl=64 [1488443923.801410 - 1488443923.800261]
03/02/2017 17:38:43.80 <Verb:NetTools.ICMPPktRxFmSock> : ICMP packet from 1.1.1.1 to 20.1.1.1 on socket 42-2 type 0 code 0
03/02/2017 17:38:43.80 <Verb:NetTools.ProcTrackingEvent> : Received event 1 for target 1.1.1.1, VR id 2, freq 1, misses 1(0)
03/02/2017 17:38:42.80 <Verb:NetTools.RxPingReply> : Echo reply; 8 bytes from 1.1.1.1: icmp_seq=27 ttl=64 [1488443922.801492 - 1488443922.800264]
03/02/2017 17:38:42.80 <Verb:NetTools.ICMPPktRxFmSock> : ICMP packet from 1.1.1.1 to 20.1.1.1 on socket 42-2 type 0 code 0
03/02/2017 17:38:42.80 <Verb:NetTools.ProcTrackingEvent> : Received event 1 for target 1.1.1.1, VR id 2, freq 1, misses 1(0)
03/02/2017 17:38:41.80 <Verb:NetTools.RxPingReply> : Echo reply; 8 bytes from 1.1.1.1: icmp_seq=26 ttl=64 [1488443921.801771 - 1488443921.800383]
03/02/2017 17:38:41.80 <Verb:NetTools.ICMPPktRxFmSock> : ICMP packet from 1.1.1.1 to 20.1.1.1 on socket 42-2 type 0 code 0
03/02/2017 17:38:41.80 <Verb:NetTools.ProcTrackingEvent> : Received event 1 for target 1.1.1.1, VR id 2, freq 1, misses 1(0)
03/02/2017 17:38:40.80 <Verb:NetTools.RxPingReply> : Echo reply; 8 bytes from 1.1.1.1: icmp_seq=25 ttl=64 [1488443920.801830 - 1488443920.800578]
03/02/2017 17:38:40.80 <Verb:NetTools.ICMPPktRxFmSock> : ICMP packet from 1.1.1.1 to 20.1.1.1 on socket 42-2 type 0 code 0
03/02/2017 17:38:40.80 <Verb:NetTools.ProcTrackingEvent> : Received event 1 for target 1.1.1.1, VR id 2, freq 1, misses 1(11)
03/02/2017 17:38:39.80 <Verb:NetTools.RxPingReply> : Echo reply; 8 bytes from 1.1.1.1: icmp_seq=24 ttl=64 [1488443919.802138 - 1488443919.800931]
03/02/2017 17:38:39.80 <Verb:NetTools.ICMPPktRxFmSock> : ICMP packet from 1.1.1.1 to 20.1.1.1 on socket 42-2 type 0 code 0

03/02/2017 17:38:39.80 <Verb:NetTools.ProcTrackingEvent> : Received event 0 for target 1.1.1.1, VR id 2, freq 1, misses 1(10)
03/02/2017 17:38:38.80 <Verb:NetTools.ProcTrackingEvent> : Received event 0 for target 1.1.1.1, VR id 2, freq 1, misses 1(9)
03/02/2017 17:38:37.80 <Verb:NetTools.ProcTrackingEvent> : Received event 0 for target 1.1.1.1, VR id 2, freq 1, misses 1(8)
03/02/2017 17:38:36.80 <Verb:NetTools.ProcTrackingEvent> : Received event 0 for target 1.1.1.1, VR id 2, freq 1, misses 1(7)
03/02/2017 17:38:35.80 <Verb:NetTools.ProcTrackingEvent> : Received event 0 for target 1.1.1.1, VR id 2, freq 1, misses 1(6)
03/02/2017 17:38:34.80 <Verb:NetTools.ProcTrackingEvent> : Received event 0 for target 1.1.1.1, VR id 2, freq 1, misses 1(5)
03/02/2017 17:38:33.80 <Verb:NetTools.ProcTrackingEvent> : Received event 0 for target 1.1.1.1, VR id 2, freq 1, misses 1(4)
03/02/2017 17:38:32.80 <Verb:NetTools.ProcTrackingEvent> : Received event 0 for target 1.1.1.1, VR id 2, freq 1, misses 1(3)
03/02/2017 17:38:31.79 <Verb:NetTools.ProcTrackingEvent> : Received event 0 for target 1.1.1.1, VR id 2, freq 1, misses 1(2)
03/02/2017 17:38:30.79 <Verb:NetTools.ProcTrackingEvent> : Received event 0 for target 1.1.1.1, VR id 2, freq 1, misses 1(1)
03/02/2017 17:38:29.78 <Noti:VRRP.StateChng> : VLAN test_data vrid 10: transitioning to INIT(0)

Feedback

 

Was this article helpful?


   

Feedback

Please tell us how we can make this article more useful.

Characters Remaining: 255