BFD: handle timing wheel prematurely firing events

Improve handling of timeouts. Add a workaround for when timing wheel
fires an event a tiny amount of time before it should actually be
fired.  Don't delete unneeded events at all from timing wheel, instead
ignoring unexpected events. Enable the skipped BFD test, which passes
now.

Change-Id: I6ffd4fc0ba7a049ffe63bb0e5290641a7300dd6f
Signed-off-by: Klement Sekera <ksekera@cisco.com>

5 files changed, 88 insertions, 72 deletions

diff --git a/test/test_bfd.py b/test/test_bfd.py
index b48c3cc4e46..bf0e88ddcdd 100644
--- a/test/test_bfd.py
+++ b/test/test_bfd.py
@@ -252,14 +252,14 @@ class BFDTestCase(VppTestCase):
         e = self.vapi.wait_for_event(1, "bfd_udp_session_details")
         self.verify_event(e, expected_state=BFDState.down)
 
-    @unittest.skip("this test is not working yet")
     def test_large_required_min_rx(self):
+        """ large remote RequiredMinRxInterval """
         self.bfd_session_up()
-        interval = 5000000
+        interval = 3000000
         self.test_session.update(required_min_rx_interval=interval)
         self.test_session.send_packet()
         now = time.time()
-        count = 1
+        count = 0
         while time.time() < now + interval / 1000000:
             try:
                 p = self.wait_for_bfd_packet()
diff --git a/vnet/vnet/bfd/bfd_debug.h b/vnet/vnet/bfd/bfd_debug.h
index 0072ff8fe82..707ebab2ddd 100644
--- a/vnet/vnet/bfd/bfd_debug.h
+++ b/vnet/vnet/bfd/bfd_debug.h
@@ -23,32 +23,30 @@
 #define BFD_DEBUG (0)
 
 #if BFD_DEBUG
-#define BFD_DEBUG_FILE_DEF              \
-  static const char *__file = NULL;     \
-  if (!__file)                          \
-    {                                   \
-      __file = strrchr (__FILE__, '/'); \
-      if (__file)                       \
-        {                               \
-          ++__file;                     \
-        }                               \
-      else                              \
-        {                               \
-          __file = __FILE__;            \
-        }                               \
-    }
+#define BFD_DEBUG_FILE_DEF            \
+  static const char *__file = NULL;   \
+  {                                   \
+    __file = strrchr (__FILE__, '/'); \
+    if (__file)                       \
+      {                               \
+        ++__file;                     \
+      }                               \
+    else                              \
+      {                               \
+        __file = __FILE__;            \
+      }                               \
+  }
 
 #define BFD_DBG(fmt, ...)                                                \
   do                                                                     \
     {                                                                    \
       BFD_DEBUG_FILE_DEF                                                 \
-      u8 *_s = NULL;                                                     \
+      static u8 *_s = NULL;                                              \
       vlib_main_t *vm = vlib_get_main ();                                \
       _s = format (_s, "%6.02f:DBG:%s:%d:%s():" fmt, vlib_time_now (vm), \
                    __file, __LINE__, __func__, ##__VA_ARGS__);           \
-      printf ("%s\n", _s);                                               \
-      fflush (stdout);                                                   \
-      vec_free (_s);                                                     \
+      printf ("%.*s\n", vec_len (_s), _s);                               \
+      vec_reset_length (_s);                                             \
     }                                                                    \
   while (0);
 
@@ -56,13 +54,12 @@
   do                                                                     \
     {                                                                    \
       BFD_DEBUG_FILE_DEF                                                 \
-      u8 *_s = NULL;                                                     \
+      static u8 *_s = NULL;                                              \
       vlib_main_t *vm = vlib_get_main ();                                \
       _s = format (_s, "%6.02f:ERR:%s:%d:%s():" fmt, vlib_time_now (vm), \
                    __file, __LINE__, __func__, ##__VA_ARGS__);           \
-      printf ("%s\n", _s);                                               \
-      fflush (stdout);                                                   \
-      vec_free (_s);                                                     \
+      printf ("%.*s\n", vec_len (_s), _s);                               \
+      vec_reset_length (_s);                                             \
     }                                                                    \
   while (0);
 
diff --git a/vnet/vnet/bfd/bfd_main.c b/vnet/vnet/bfd/bfd_main.c
index ffc04ee4df0..e25eadfc510 100644
--- a/vnet/vnet/bfd/bfd_main.c
+++ b/vnet/vnet/bfd/bfd_main.c
@@ -129,6 +129,17 @@ bfd_calc_next_tx (bfd_main_t * bm, bfd_session_t * bs, u64 now)
 	  bs->tx_timeout_clocks = now +
 	    (1 - .25 * (random_f64 (&bm->random_seed))) *
 	    bs->transmit_interval_clocks;
+	  if (bs->tx_timeout_clocks < now)
+	    {
+	      /* huh, we've missed it already, skip the missed events */
+	      const u64 missed =
+		(now - bs->tx_timeout_clocks) / bs->transmit_interval_clocks;
+	      BFD_ERR ("Missed %lu transmit events (now is %lu, calc "
+		       "tx_timeout is %lu)!",
+		       missed, now, bs->tx_timeout_clocks);
+	      bs->tx_timeout_clocks +=
+		(missed + 1) * bs->transmit_interval_clocks;
+	    }
 	}
       else
 	{
@@ -137,6 +148,17 @@ bfd_calc_next_tx (bfd_main_t * bm, bfd_session_t * bs, u64 now)
 	    now +
 	    (.9 - .15 * (random_f64 (&bm->random_seed))) *
 	    bs->transmit_interval_clocks;
+	  if (bs->tx_timeout_clocks < now)
+	    {
+	      /* huh, we've missed it already, skip the missed events */
+	      const u64 missed =
+		(now - bs->tx_timeout_clocks) / bs->transmit_interval_clocks;
+	      BFD_ERR ("Missed %lu transmit events (now is %lu, calc "
+		       "tx_timeout is %lu)!",
+		       missed, now, bs->tx_timeout_clocks);
+	      bs->tx_timeout_clocks +=
+		(missed + 1) * bs->transmit_interval_clocks;
+	    }
 	}
     }
   else
@@ -200,12 +222,11 @@ bfd_set_timer (bfd_main_t * bm, bfd_session_t * bs, u64 now,
   BFD_DBG ("bs_idx=%u, tx_timeout=%lu, rx_timeout=%lu, next=%s", bs->bs_idx,
 	   bs->tx_timeout_clocks, rx_timeout,
 	   next == bs->tx_timeout_clocks ? "tx" : "rx");
-  if (next && (next < bs->wheel_time_clocks || !bs->wheel_time_clocks))
+  /* sometimes the wheel expires an event a bit sooner than requested, account
+     for that here */
+  if (next && (now + bm->wheel_inaccuracy > bs->wheel_time_clocks ||
+	       next < bs->wheel_time_clocks || !bs->wheel_time_clocks))
     {
-      if (bs->wheel_time_clocks)
-	{
-	  timing_wheel_delete (&bm->wheel, bs->bs_idx);
-	}
       bs->wheel_time_clocks = next;
       BFD_DBG ("timing_wheel_insert(%p, %lu (%ld clocks/%.2fs in the "
 	       "future), %u);",
@@ -238,6 +259,22 @@ bfd_set_desired_min_tx (bfd_main_t * bm, bfd_session_t * bs, u64 now,
   bfd_set_timer (bm, bs, now, handling_wakeup);
 }
 
+static void
+bfd_set_remote_required_min_rx (bfd_main_t * bm, bfd_session_t * bs,
+				u64 now,
+				u32 remote_required_min_rx_us,
+				int handling_wakeup)
+{
+  bs->remote_min_rx_us = remote_required_min_rx_us;
+  bs->remote_min_rx_clocks = bfd_us_to_clocks (bm, bs->remote_min_rx_us);
+  BFD_DBG ("Set remote min rx to %uus/%lu clocks/%.2fs", bs->remote_min_rx_us,
+	   bs->remote_min_rx_clocks, bs->remote_min_rx_clocks / bm->cpu_cps);
+  bfd_recalc_detection_time (bm, bs);
+  bfd_recalc_tx_interval (bm, bs);
+  bfd_calc_next_tx (bm, bs, now);
+  bfd_set_timer (bm, bs, now, handling_wakeup);
+}
+
 void
 bfd_session_start (bfd_main_t * bm, bfd_session_t * bs)
 {
@@ -470,7 +507,9 @@ bfd_send_periodic (vlib_main_t * vm, vlib_node_runtime_t * rt,
      bfd.SessionState is Up, and bfd.RemoteSessionState is Up) and a Poll
      Sequence is not being transmitted.
    */
-  if (now >= bs->tx_timeout_clocks)
+  /* sometimes the wheel expires an event a bit sooner than requested, account
+     for that here */
+  if (now + bm->wheel_inaccuracy >= bs->tx_timeout_clocks)
     {
       BFD_DBG ("Send periodic control frame for bs_idx=%lu", bs->bs_idx);
       vlib_buffer_t *b = bfd_create_frame (vm, rt, bs);
@@ -484,7 +523,9 @@ bfd_send_periodic (vlib_main_t * vm, vlib_node_runtime_t * rt,
     }
   else
     {
-      BFD_DBG ("No need to send control frame now");
+      BFD_DBG
+	("No need to send control frame now, now is %lu, tx_timeout is %lu",
+	 now, bs->tx_timeout_clocks);
     }
   bfd_set_timer (bm, bs, now, handling_wakeup);
 }
@@ -502,7 +543,10 @@ static void
 bfd_check_rx_timeout (bfd_main_t * bm, bfd_session_t * bs, u64 now,
 		      int handling_wakeup)
 {
-  if (bs->last_rx_clocks + bs->detection_time_clocks < now)
+  /* sometimes the wheel expires an event a bit sooner than requested, account
+     for that here */
+  if (bs->last_rx_clocks + bs->detection_time_clocks <=
+      now + bm->wheel_inaccuracy)
     {
       BFD_DBG ("Rx timeout, session goes down");
       bfd_set_diag (bs, BFD_DIAG_CODE_det_time_exp);
@@ -538,31 +582,6 @@ bfd_on_timeout (vlib_main_t * vm, vlib_node_runtime_t * rt, bfd_main_t * bm,
 }
 
 /*
- * bfd input routine
- */
-bfd_error_t
-bfd_input (vlib_main_t * vm, vlib_buffer_t * b0, u32 bi0)
-{
-  // bfd_main_t *bm = &bfd_main;
-  bfd_error_t e;
-
-  /* find our interface */
-  bfd_session_t *s = NULL;
-  // bfd_get_intf (lm, vnet_buffer (b0)->sw_if_index[VLIB_RX]);
-
-  if (!s)
-    {
-      /* bfd disabled on this interface, we're done */
-      return BFD_ERROR_DISABLED;
-    }
-
-  /* Actually scan the packet */
-  e = BFD_ERROR_NONE;		// bfd_packet_scan (lm, n, vlib_buffer_get_current (b0));
-
-  return e;
-}
-
-/*
  * bfd process node function
  */
 static uword
@@ -637,7 +656,6 @@ bfd_process (vlib_main_t * vm, vlib_node_runtime_t * rt, vlib_frame_t * f)
 	if (!pool_is_free_index (bm->sessions, bs_idx))
 	  {
 	    bfd_session_t *bs = pool_elt_at_index (bm->sessions, bs_idx);
-	    bs->wheel_time_clocks = 0;	/* no longer scheduled */
 	    bfd_on_timeout (vm, rt, bm, bs, now);
 	  }
       }
@@ -714,6 +732,7 @@ bfd_main_init (vlib_main_t * vm)
   BFD_DBG ("cps is %.2f", bm->cpu_cps);
   const u64 now = clib_cpu_time_now ();
   timing_wheel_init (&bm->wheel, now, bm->cpu_cps);
+  bm->wheel_inaccuracy = 2 << bm->wheel.log2_clocks_per_bin;
 
   return 0;
 }
@@ -864,14 +883,12 @@ bfd_consume_pkt (bfd_main_t * bm, const bfd_pkt_t * pkt, u32 bs_idx)
   bs->remote_discr = pkt->my_disc;
   bs->remote_state = bfd_pkt_get_state (pkt);
   bs->remote_demand = bfd_pkt_get_demand (pkt);
-  bs->remote_min_rx_us = clib_net_to_host_u32 (pkt->req_min_rx);
-  bs->remote_min_rx_clocks = bfd_us_to_clocks (bm, bs->remote_min_rx_us);
-  BFD_DBG ("Set remote min rx to %lu clocks/%.2fs", bs->remote_min_rx_clocks,
-	   bs->remote_min_rx_clocks / bm->cpu_cps);
+  u64 now = clib_cpu_time_now ();
+  bs->last_rx_clocks = now;
   bs->remote_desired_min_tx_us = clib_net_to_host_u32 (pkt->des_min_tx);
   bs->remote_detect_mult = pkt->head.detect_mult;
-  bfd_recalc_detection_time (bm, bs);
-  bs->last_rx_clocks = clib_cpu_time_now ();
+  bfd_set_remote_required_min_rx (bm, bs, now,
+				  clib_net_to_host_u32 (pkt->req_min_rx), 0);
   /* FIXME
      If the Required Min Echo RX Interval field is zero, the
      transmission of Echo packets, if any, MUST cease.
diff --git a/vnet/vnet/bfd/bfd_main.h b/vnet/vnet/bfd/bfd_main.h
index 727903bd286..c72ea92a70f 100644
--- a/vnet/vnet/bfd/bfd_main.h
+++ b/vnet/vnet/bfd/bfd_main.h
@@ -49,7 +49,7 @@ typedef enum
 typedef struct
 {
   /* index in bfd_main.sessions pool */
-  uword bs_idx;
+  u32 bs_idx;
 
   /* session state */
   bfd_state_e local_state;
@@ -93,10 +93,13 @@ typedef struct
   /* 1 if remote system sets demand mode, 0 otherwise */
   u8 remote_demand;
 
+  /* local detect multiplier */
   u8 local_detect_mult;
+
+  /* remote detect multiplier */
   u8 remote_detect_mult;
 
-  /* set to value of timer in timing wheel, 0 if not set */
+  /* set to value of timer in timing wheel, 0 if never set */
   u64 wheel_time_clocks;
 
   /* transmit interval */
@@ -134,6 +137,9 @@ typedef struct
   /* timing wheel for scheduling timeouts */
   timing_wheel_t wheel;
 
+  /* timing wheel inaccuracy, in clocks */
+  u64 wheel_inaccuracy;
+
   /* hashmap - bfd session by discriminator */
   u32 *session_by_disc;
 
@@ -150,9 +156,6 @@ typedef struct
   /* for generating random numbers */
   u32 random_seed;
 
-  /* pool of event subscribers */
-  //event_subscriber_t *subscribers;
-
 } bfd_main_t;
 
 extern bfd_main_t bfd_main;
@@ -184,7 +187,6 @@ enum
   BFD_EVENT_NEW_SESSION,
 } bfd_process_event_e;
 
-bfd_error_t bfd_input (vlib_main_t * vm, vlib_buffer_t * b0, u32 bi0);
 u8 *bfd_input_format_trace (u8 * s, va_list * args);
 
 bfd_session_t *bfd_get_session (bfd_main_t * bm, bfd_transport_t t);
diff --git a/vnet/vnet/bfd/bfd_udp.c b/vnet/vnet/bfd/bfd_udp.c
index 9d75e3ad9e0..3c747d86a10 100644
--- a/vnet/vnet/bfd/bfd_udp.c
+++ b/vnet/vnet/bfd/bfd_udp.c
@@ -442,7 +442,7 @@ static bfd_udp_error_t bfd_udp4_scan (vlib_main_t *vm, vlib_node_runtime_t *rt,
       BFD_ERR ("BFD session lookup failed - no session matches BFD pkt");
       return BFD_UDP_ERROR_BAD;
     }
-  BFD_DBG ("BFD session found, bs_idx=%d", bs->bs_idx);
+  BFD_DBG ("BFD session found, bs_idx=%u", bs->bs_idx);
   if (!bfd_verify_pkt_session (pkt, b->current_length, bs))
     {
       return BFD_UDP_ERROR_BAD;