vppinfra: improve clocks_per_second convergence
[vpp.git] / src / vnet / bfd / bfd_main.c
index b58a513..a9a6d05 100644 (file)
@@ -25,6 +25,7 @@
 #include <x86intrin.h>
 #endif
 
+#include <vlibmemory/api.h>
 #include <vppinfra/random.h>
 #include <vppinfra/error.h>
 #include <vppinfra/hash.h>
 #include <vnet/bfd/bfd_debug.h>
 #include <vnet/bfd/bfd_protocol.h>
 #include <vnet/bfd/bfd_main.h>
+#include <vlib/log.h>
 
 static u64
 bfd_calc_echo_checksum (u32 discriminator, u64 expire_time, u32 secret)
 {
   u64 checksum = 0;
-#if __SSE4_2__ && !defined (__i386__)
-  checksum = _mm_crc32_u64 (0, discriminator);
-  checksum = _mm_crc32_u64 (checksum, expire_time);
-  checksum = _mm_crc32_u64 (checksum, secret);
+#if defined(clib_crc32c_uses_intrinsics) && !defined (__i386__)
+  checksum = crc32_u64 (0, discriminator);
+  checksum = crc32_u64 (checksum, expire_time);
+  checksum = crc32_u64 (checksum, secret);
 #else
   checksum = clib_xxhash (discriminator ^ expire_time ^ secret);
 #endif
@@ -58,7 +60,7 @@ bfd_usec_to_clocks (const bfd_main_t * bm, u64 us)
 u32
 bfd_clocks_to_usec (const bfd_main_t * bm, u64 clocks)
 {
-  return (clocks / bm->cpu_cps) * USEC_PER_SECOND;
+  return ((f64) clocks / bm->cpu_cps) * USEC_PER_SECOND;
 }
 
 static vlib_node_registration_t bfd_process_node;
@@ -314,6 +316,7 @@ bfd_set_timer (bfd_main_t * bm, bfd_session_t * bs, u64 now,
   if (next && (now + bm->wheel_inaccuracy > bs->wheel_time_clocks ||
               next < bs->wheel_time_clocks || !bs->wheel_time_clocks))
     {
+      int send_signal = 0;
       bs->wheel_time_clocks = next;
       BFD_DBG ("timing_wheel_insert(%p, %lu (%ld clocks/%.2fs in the "
               "future), %u);",
@@ -321,12 +324,41 @@ bfd_set_timer (bfd_main_t * bm, bfd_session_t * bs, u64 now,
               (i64) bs->wheel_time_clocks - clib_cpu_time_now (),
               (i64) (bs->wheel_time_clocks - clib_cpu_time_now ()) /
               bm->cpu_cps, bs->bs_idx);
+      bfd_lock (bm);
       timing_wheel_insert (&bm->wheel, bs->wheel_time_clocks, bs->bs_idx);
+
       if (!handling_wakeup)
        {
-         vlib_process_signal_event (bm->vlib_main,
-                                    bm->bfd_process_node_index,
-                                    BFD_EVENT_RESCHEDULE, bs->bs_idx);
+
+         /* Send only if it is earlier than current awaited wakeup time */
+         send_signal =
+           (bs->wheel_time_clocks < bm->bfd_process_next_wakeup_clocks) &&
+           /*
+            * If the wake-up time is within 2x the delay of the event propagation delay,
+            * avoid the expense of sending the event. The 2x multiplier is to workaround the race whereby
+            * simultaneous event + expired timer create one recurring bogus wakeup/suspend instance,
+            * due to double scheduling of the node on the pending list.
+            */
+           (bm->bfd_process_next_wakeup_clocks - bs->wheel_time_clocks >
+            2 * bm->bfd_process_wakeup_event_delay_clocks) &&
+           /* Must be no events in flight to send an event */
+           (!bm->bfd_process_wakeup_events_in_flight);
+
+         /* If we do send the signal, note this down along with the start timestamp */
+         if (send_signal)
+           {
+             bm->bfd_process_wakeup_events_in_flight++;
+             bm->bfd_process_wakeup_event_start_clocks = now;
+           }
+       }
+      bfd_unlock (bm);
+
+      /* Use the multithreaded event sending so the workers can send events too */
+      if (send_signal)
+       {
+         vlib_process_signal_event_mt (bm->vlib_main,
+                                       bm->bfd_process_node_index,
+                                       BFD_EVENT_RESCHEDULE, ~0);
        }
     }
 }
@@ -403,6 +435,8 @@ void
 bfd_session_start (bfd_main_t * bm, bfd_session_t * bs)
 {
   BFD_DBG ("\nStarting session: %U", format_bfd_session, bs);
+  vlib_log_info (bm->log_class, "start BFD session: %U",
+                format_bfd_session_brief, bs);
   bfd_set_effective_required_min_rx (bm, bs,
                                     bs->config_required_min_rx_clocks);
   bfd_recalc_tx_interval (bm, bs);
@@ -419,6 +453,8 @@ bfd_session_set_flags (bfd_session_t * bs, u8 admin_up_down)
   if (admin_up_down)
     {
       BFD_DBG ("Session set admin-up, bs-idx=%u", bs->bs_idx);
+      vlib_log_info (bm->log_class, "set session admin-up: %U",
+                    format_bfd_session_brief, bs);
       bfd_set_state (bm, bs, BFD_STATE_down, 0);
       bfd_set_diag (bs, BFD_DIAG_CODE_no_diag);
       bfd_calc_next_tx (bm, bs, now);
@@ -427,6 +463,8 @@ bfd_session_set_flags (bfd_session_t * bs, u8 admin_up_down)
   else
     {
       BFD_DBG ("Session set admin-down, bs-idx=%u", bs->bs_idx);
+      vlib_log_info (bm->log_class, "set session admin-down: %U",
+                    format_bfd_session_brief, bs);
       bfd_set_diag (bs, BFD_DIAG_CODE_admin_down);
       bfd_set_state (bm, bs, BFD_STATE_admin_down, 0);
       bfd_calc_next_tx (bm, bs, now);
@@ -501,12 +539,98 @@ bfd_input_format_trace (u8 * s, va_list * args)
   return s;
 }
 
+typedef struct
+{
+  u32 bs_idx;
+} bfd_rpc_event_t;
+
+static void
+bfd_rpc_event_cb (const bfd_rpc_event_t * a)
+{
+  bfd_main_t *bm = &bfd_main;
+  u32 bs_idx = a->bs_idx;
+  u32 valid_bs = 0;
+  bfd_session_t session_data;
+
+  bfd_lock (bm);
+  if (!pool_is_free_index (bm->sessions, bs_idx))
+    {
+      bfd_session_t *bs = pool_elt_at_index (bm->sessions, bs_idx);
+      clib_memcpy (&session_data, bs, sizeof (bfd_session_t));
+      valid_bs = 1;
+    }
+  else
+    {
+      BFD_DBG ("Ignoring event RPC for non-existent session index %u",
+              bs_idx);
+    }
+  bfd_unlock (bm);
+
+  if (valid_bs)
+    bfd_event (bm, &session_data);
+}
+
+static void
+bfd_event_rpc (u32 bs_idx)
+{
+  const u32 data_size = sizeof (bfd_rpc_event_t);
+  u8 data[data_size];
+  bfd_rpc_event_t *event = (bfd_rpc_event_t *) data;
+
+  event->bs_idx = bs_idx;
+  vl_api_rpc_call_main_thread (bfd_rpc_event_cb, data, data_size);
+}
+
+typedef struct
+{
+  u32 bs_idx;
+} bfd_rpc_notify_listeners_t;
+
+static void
+bfd_rpc_notify_listeners_cb (const bfd_rpc_notify_listeners_t * a)
+{
+  bfd_main_t *bm = &bfd_main;
+  u32 bs_idx = a->bs_idx;
+  bfd_lock (bm);
+  if (!pool_is_free_index (bm->sessions, bs_idx))
+    {
+      bfd_session_t *bs = pool_elt_at_index (bm->sessions, bs_idx);
+      bfd_notify_listeners (bm, BFD_LISTEN_EVENT_UPDATE, bs);
+    }
+  else
+    {
+      BFD_DBG ("Ignoring notify RPC for non-existent session index %u",
+              bs_idx);
+    }
+  bfd_unlock (bm);
+}
+
+static void
+bfd_notify_listeners_rpc (u32 bs_idx)
+{
+  const u32 data_size = sizeof (bfd_rpc_notify_listeners_t);
+  u8 data[data_size];
+  bfd_rpc_notify_listeners_t *notify = (bfd_rpc_notify_listeners_t *) data;
+  notify->bs_idx = bs_idx;
+  vl_api_rpc_call_main_thread (bfd_rpc_notify_listeners_cb, data, data_size);
+}
+
 static void
 bfd_on_state_change (bfd_main_t * bm, bfd_session_t * bs, u64 now,
                     int handling_wakeup)
 {
   BFD_DBG ("\nState changed: %U", format_bfd_session, bs);
-  bfd_event (bm, bs);
+
+  if (vlib_get_thread_index () == 0)
+    {
+      bfd_event (bm, bs);
+    }
+  else
+    {
+      /* without RPC - a REGRESSION: BFD event are not propagated */
+      bfd_event_rpc (bs->bs_idx);
+    }
+
   switch (bs->local_state)
     {
     case BFD_STATE_admin_down:
@@ -546,7 +670,15 @@ bfd_on_state_change (bfd_main_t * bm, bfd_session_t * bs, u64 now,
       bfd_set_timer (bm, bs, now, handling_wakeup);
       break;
     }
-  bfd_notify_listeners (bm, BFD_LISTEN_EVENT_UPDATE, bs);
+  if (vlib_get_thread_index () == 0)
+    {
+      bfd_notify_listeners (bm, BFD_LISTEN_EVENT_UPDATE, bs);
+    }
+  else
+    {
+      /* without RPC - a REGRESSION: state changes are not propagated */
+      bfd_notify_listeners_rpc (bs->bs_idx);
+    }
 }
 
 static void
@@ -642,7 +774,7 @@ bfd_add_sha1_auth_section (vlib_buffer_t * b, bfd_session_t * bs)
   b->current_length += sizeof (*auth);
   pkt->pkt.head.length += sizeof (*auth);
   bfd_pkt_set_auth_present (&pkt->pkt);
-  memset (auth, 0, sizeof (*auth));
+  clib_memset (auth, 0, sizeof (*auth));
   auth->type_len.type = bs->auth.curr_key->auth_type;
   /*
    * only meticulous authentication types require incrementing seq number
@@ -668,6 +800,7 @@ bfd_add_sha1_auth_section (vlib_buffer_t * b, bfd_session_t * bs)
 static void
 bfd_add_auth_section (vlib_buffer_t * b, bfd_session_t * bs)
 {
+  bfd_main_t *bm = &bfd_main;
   if (bs->auth.curr_key)
     {
       const bfd_auth_type_e auth_type = bs->auth.curr_key->auth_type;
@@ -680,8 +813,9 @@ bfd_add_auth_section (vlib_buffer_t * b, bfd_session_t * bs)
        case BFD_AUTH_TYPE_keyed_md5:
          /* fallthrough */
        case BFD_AUTH_TYPE_meticulous_keyed_md5:
-         clib_warning ("Internal error, unexpected BFD auth type '%d'",
-                       auth_type);
+         vlib_log_crit (bm->log_class,
+                        "internal error, unexpected BFD auth type '%d'",
+                        auth_type);
          break;
 #if WITH_LIBSSL > 0
        case BFD_AUTH_TYPE_keyed_sha1:
@@ -693,8 +827,9 @@ bfd_add_auth_section (vlib_buffer_t * b, bfd_session_t * bs)
        case BFD_AUTH_TYPE_keyed_sha1:
          /* fallthrough */
        case BFD_AUTH_TYPE_meticulous_keyed_sha1:
-         clib_warning ("Internal error, unexpected BFD auth type '%d'",
-                       auth_type);
+         vlib_log_crit (bm->log_class,
+                        "internal error, unexpected BFD auth type '%d'",
+                        auth_type);
          break;
 #endif
        }
@@ -725,7 +860,7 @@ bfd_init_control_frame (bfd_main_t * bm, bfd_session_t * bs,
   bfd_pkt_t *pkt = vlib_buffer_get_current (b);
   u32 bfd_length = 0;
   bfd_length = sizeof (bfd_pkt_t);
-  memset (pkt, 0, sizeof (*pkt));
+  clib_memset (pkt, 0, sizeof (*pkt));
   bfd_pkt_set_version (pkt, 1);
   bfd_pkt_set_diag_code (pkt, bs->local_diag);
   bfd_pkt_set_state (pkt, bs->local_state);
@@ -768,15 +903,14 @@ bfd_send_echo (vlib_main_t * vm, vlib_node_runtime_t * rt,
       u32 bi;
       if (vlib_buffer_alloc (vm, &bi, 1) != 1)
        {
-         clib_warning ("buffer allocation failure");
+         vlib_log_crit (bm->log_class, "buffer allocation failure");
          return;
        }
       vlib_buffer_t *b = vlib_get_buffer (vm, bi);
       ASSERT (b->current_data == 0);
-      memset (vnet_buffer (b), 0, sizeof (*vnet_buffer (b)));
       VLIB_BUFFER_TRACE_TRAJECTORY_INIT (b);
       bfd_echo_pkt_t *pkt = vlib_buffer_get_current (b);
-      memset (pkt, 0, sizeof (*pkt));
+      clib_memset (pkt, 0, sizeof (*pkt));
       pkt->discriminator = bs->local_discr;
       pkt->expire_time_clocks =
        now + bs->echo_transmit_interval_clocks * bs->local_detect_mult;
@@ -842,12 +976,11 @@ bfd_send_periodic (vlib_main_t * vm, vlib_node_runtime_t * rt,
       u32 bi;
       if (vlib_buffer_alloc (vm, &bi, 1) != 1)
        {
-         clib_warning ("buffer allocation failure");
+         vlib_log_crit (bm->log_class, "buffer allocation failure");
          return;
        }
       vlib_buffer_t *b = vlib_get_buffer (vm, bi);
       ASSERT (b->current_data == 0);
-      memset (vnet_buffer (b), 0, sizeof (*vnet_buffer (b)));
       VLIB_BUFFER_TRACE_TRAJECTORY_INIT (b);
       bfd_init_control_frame (bm, bs, b);
       switch (bs->poll_state)
@@ -921,6 +1054,19 @@ bfd_check_rx_timeout (bfd_main_t * bm, bfd_session_t * bs, u64 now,
       now + bm->wheel_inaccuracy)
     {
       BFD_DBG ("Rx timeout, session goes down");
+      /*
+       * RFC 5880 6.8.1. State Variables
+
+       * bfd.RemoteDiscr
+
+       * The remote discriminator for this BFD session.  This is the
+       * discriminator chosen by the remote system, and is totally opaque
+       * to the local system.  This MUST be initialized to zero.  If a
+       * period of a Detection Time passes without the receipt of a valid,
+       * authenticated BFD packet from the remote system, this variable
+       * MUST be set to zero.
+       */
+      bs->remote_discr = 0;
       bfd_set_diag (bs, BFD_DIAG_CODE_det_time_exp);
       bfd_set_state (bm, bs, BFD_STATE_down, handling_wakeup);
       /*
@@ -1001,9 +1147,13 @@ bfd_process (vlib_main_t * vm, vlib_node_runtime_t * rt, vlib_frame_t * f)
   while (1)
     {
       u64 now = clib_cpu_time_now ();
+      bfd_lock (bm);
       u64 next_expire = timing_wheel_next_expiring_elt_time (&bm->wheel);
       BFD_DBG ("timing_wheel_next_expiring_elt_time(%p) returns %lu",
               &bm->wheel, next_expire);
+      bm->bfd_process_next_wakeup_clocks =
+       (i64) next_expire >= 0 ? next_expire : ~0;
+      bfd_unlock (bm);
       if ((i64) next_expire < 0)
        {
          BFD_DBG ("wait for event without timeout");
@@ -1026,49 +1176,66 @@ bfd_process (vlib_main_t * vm, vlib_node_runtime_t * rt, vlib_frame_t * f)
            }
        }
       now = clib_cpu_time_now ();
+      uword *session_index;
       switch (event_type)
        {
        case ~0:                /* no events => timeout */
          /* nothing to do here */
          break;
        case BFD_EVENT_RESCHEDULE:
+         bfd_lock (bm);
+         bm->bfd_process_wakeup_event_delay_clocks =
+           now - bm->bfd_process_wakeup_event_start_clocks;
+         bm->bfd_process_wakeup_events_in_flight--;
+         bfd_unlock (bm);
          /* nothing to do here - reschedule is done automatically after
           * each event or timeout */
          break;
        case BFD_EVENT_NEW_SESSION:
-         if (!pool_is_free_index (bm->sessions, *event_data))
-           {
-             bfd_session_t *bs =
-               pool_elt_at_index (bm->sessions, *event_data);
-             bfd_send_periodic (vm, rt, bm, bs, now);
-             bfd_set_timer (bm, bs, now, 1);
-           }
-         else
-           {
-             BFD_DBG ("Ignoring event for non-existent session index %u",
-                      (u32) * event_data);
-           }
+         vec_foreach (session_index, event_data)
+         {
+           bfd_lock (bm);
+           if (!pool_is_free_index (bm->sessions, *session_index))
+             {
+               bfd_session_t *bs =
+                 pool_elt_at_index (bm->sessions, *session_index);
+               bfd_send_periodic (vm, rt, bm, bs, now);
+               bfd_set_timer (bm, bs, now, 1);
+             }
+           else
+             {
+               BFD_DBG ("Ignoring event for non-existent session index %u",
+                        (u32) * session_index);
+             }
+           bfd_unlock (bm);
+         }
          break;
        case BFD_EVENT_CONFIG_CHANGED:
-         if (!pool_is_free_index (bm->sessions, *event_data))
-           {
-             bfd_session_t *bs =
-               pool_elt_at_index (bm->sessions, *event_data);
-             bfd_on_config_change (vm, rt, bm, bs, now);
-           }
-         else
-           {
-             BFD_DBG ("Ignoring event for non-existent session index %u",
-                      (u32) * event_data);
-           }
+         vec_foreach (session_index, event_data)
+         {
+           bfd_lock (bm);
+           if (!pool_is_free_index (bm->sessions, *session_index))
+             {
+               bfd_session_t *bs =
+                 pool_elt_at_index (bm->sessions, *session_index);
+               bfd_on_config_change (vm, rt, bm, bs, now);
+             }
+           else
+             {
+               BFD_DBG ("Ignoring event for non-existent session index %u",
+                        (u32) * session_index);
+             }
+           bfd_unlock (bm);
+         }
          break;
        default:
-         clib_warning ("BUG: event type 0x%wx", event_type);
+         vlib_log_err (bm->log_class, "BUG: event type 0x%wx", event_type);
          break;
        }
       BFD_DBG ("advancing wheel, now is %lu", now);
       BFD_DBG ("timing_wheel_advance (%p, %lu, %p, 0);", &bm->wheel, now,
               expired);
+      bfd_lock (bm);
       expired = timing_wheel_advance (&bm->wheel, now, expired, 0);
       BFD_DBG ("Expired %d elements", vec_len (expired));
       u32 *p = NULL;
@@ -1082,6 +1249,7 @@ bfd_process (vlib_main_t * vm, vlib_node_runtime_t * rt, vlib_frame_t * f)
            bfd_set_timer (bm, bs, now, 1);
          }
       }
+      bfd_unlock (bm);
       if (expired)
        {
          _vec_len (expired) = 0;
@@ -1149,6 +1317,8 @@ bfd_register_listener (bfd_notify_fn_t fn)
 static clib_error_t *
 bfd_main_init (vlib_main_t * vm)
 {
+  vlib_thread_main_t *tm = &vlib_thread_main;
+  u32 n_vlib_mains = tm->n_vlib_mains;
 #if BFD_DEBUG
   setbuf (stdout, NULL);
 #endif
@@ -1156,8 +1326,8 @@ bfd_main_init (vlib_main_t * vm)
   bm->random_seed = random_default_seed ();
   bm->vlib_main = vm;
   bm->vnet_main = vnet_get_main ();
-  memset (&bm->wheel, 0, sizeof (bm->wheel));
-  bm->cpu_cps = vm->clib_time.clocks_per_second;
+  clib_memset (&bm->wheel, 0, sizeof (bm->wheel));
+  bm->cpu_cps = (u64) vm->clib_time.clocks_per_second;
   BFD_DBG ("cps is %.2f", bm->cpu_cps);
   bm->default_desired_min_tx_clocks =
     bfd_usec_to_clocks (bm, BFD_DEFAULT_DESIRED_MIN_TX_USEC);
@@ -1166,6 +1336,11 @@ bfd_main_init (vlib_main_t * vm)
   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;
+  bm->log_class = vlib_log_register_class ("bfd", 0);
+  vlib_log_debug (bm->log_class, "initialized");
+  bm->owner_thread_index = ~0;
+  if (n_vlib_mains > 1)
+    clib_spinlock_init (&bm->lock);
   return 0;
 }
 
@@ -1175,8 +1350,11 @@ bfd_session_t *
 bfd_get_session (bfd_main_t * bm, bfd_transport_e t)
 {
   bfd_session_t *result;
+
+  bfd_lock (bm);
+
   pool_get (bm->sessions, result);
-  memset (result, 0, sizeof (*result));
+  clib_memset (result, 0, sizeof (*result));
   result->bs_idx = result - bm->sessions;
   result->transport = t;
   const unsigned limit = 1000;
@@ -1186,9 +1364,11 @@ bfd_get_session (bfd_main_t * bm, bfd_transport_e t)
       result->local_discr = random_u32 (&bm->random_seed);
       if (counter > limit)
        {
-         clib_warning ("Couldn't allocate unused session discriminator even "
-                       "after %u tries!", limit);
+         vlib_log_crit (bm->log_class,
+                        "couldn't allocate unused session discriminator even "
+                        "after %u tries!", limit);
          pool_put (bm->sessions, result);
+         bfd_unlock (bm);
          return NULL;
        }
       ++counter;
@@ -1196,12 +1376,17 @@ bfd_get_session (bfd_main_t * bm, bfd_transport_e t)
   while (hash_get (bm->session_by_disc, result->local_discr));
   bfd_set_defaults (bm, result);
   hash_set (bm->session_by_disc, result->local_discr, result->bs_idx);
+  bfd_unlock (bm);
   return result;
 }
 
 void
 bfd_put_session (bfd_main_t * bm, bfd_session_t * bs)
 {
+  bfd_lock (bm);
+
+  vlib_log_info (bm->log_class, "delete session: %U",
+                format_bfd_session_brief, bs);
   bfd_notify_listeners (bm, BFD_LISTEN_EVENT_DELETE, bs);
   if (bs->auth.curr_key)
     {
@@ -1213,11 +1398,13 @@ bfd_put_session (bfd_main_t * bm, bfd_session_t * bs)
     }
   hash_unset (bm->session_by_disc, bs->local_discr);
   pool_put (bm->sessions, bs);
+  bfd_unlock (bm);
 }
 
 bfd_session_t *
 bfd_find_session_by_idx (bfd_main_t * bm, uword bs_idx)
 {
+  bfd_lock_check (bm);
   if (!pool_is_free_index (bm->sessions, bs_idx))
     {
       return pool_elt_at_index (bm->sessions, bs_idx);
@@ -1228,6 +1415,7 @@ bfd_find_session_by_idx (bfd_main_t * bm, uword bs_idx)
 bfd_session_t *
 bfd_find_session_by_disc (bfd_main_t * bm, u32 disc)
 {
+  bfd_lock_check (bm);
   uword *p = hash_get (bfd_main.session_by_disc, disc);
   if (p)
     {
@@ -1468,23 +1656,27 @@ bfd_verify_pkt_auth_key (const bfd_pkt_t * pkt, u32 pkt_size,
                         bfd_session_t * bs, u8 bfd_key_id,
                         bfd_auth_key_t * auth_key)
 {
+  bfd_main_t *bm = &bfd_main;
   switch (auth_key->auth_type)
     {
     case BFD_AUTH_TYPE_reserved:
-      clib_warning ("Internal error, unexpected auth_type=%d:%s",
+      vlib_log_err (bm->log_class,
+                   "internal error, unexpected auth_type=%d:%s",
                    auth_key->auth_type,
                    bfd_auth_type_str (auth_key->auth_type));
       return 0;
     case BFD_AUTH_TYPE_simple_password:
-      clib_warning
-       ("Internal error, not implemented, unexpected auth_type=%d:%s",
-        auth_key->auth_type, bfd_auth_type_str (auth_key->auth_type));
+      vlib_log_err (bm->log_class,
+                   "internal error, not implemented, unexpected auth_type=%d:%s",
+                   auth_key->auth_type,
+                   bfd_auth_type_str (auth_key->auth_type));
       return 0;
     case BFD_AUTH_TYPE_keyed_md5:
       /* fallthrough */
     case BFD_AUTH_TYPE_meticulous_keyed_md5:
-      clib_warning
-       ("Internal error, not implemented, unexpected auth_type=%d:%s",
+      vlib_log_err
+       (bm->log_class,
+        "internal error, not implemented, unexpected auth_type=%d:%s",
         auth_key->auth_type, bfd_auth_type_str (auth_key->auth_type));
       return 0;
     case BFD_AUTH_TYPE_keyed_sha1:
@@ -1504,8 +1696,9 @@ bfd_verify_pkt_auth_key (const bfd_pkt_t * pkt, u32 pkt_size,
        }
       while (0);
 #else
-      clib_warning
-       ("Internal error, attempt to use SHA1 without SSL support");
+      vlib_log_err
+       (bm->log_class,
+        "internal error, attempt to use SHA1 without SSL support");
       return 0;
 #endif
     }
@@ -1600,6 +1793,8 @@ bfd_verify_pkt_auth (const bfd_pkt_t * pkt, u16 pkt_size, bfd_session_t * bs)
 void
 bfd_consume_pkt (bfd_main_t * bm, const bfd_pkt_t * pkt, u32 bs_idx)
 {
+  bfd_lock_check (bm);
+
   bfd_session_t *bs = bfd_find_session_by_idx (bm, bs_idx);
   if (!bs || (pkt->your_disc && pkt->your_disc != bs->local_discr))
     {
@@ -1625,8 +1820,9 @@ bfd_consume_pkt (bfd_main_t * bm, const bfd_pkt_t * pkt, u32 bs_idx)
        case BFD_AUTH_TYPE_keyed_md5:
          /* fallthrough */
        case BFD_AUTH_TYPE_meticulous_keyed_md5:
-         clib_warning ("Internal error, unexpected auth_type=%d:%s",
-                       auth_type, bfd_auth_type_str (auth_type));
+         vlib_log_crit (bm->log_class,
+                        "internal error, unexpected auth_type=%d:%s",
+                        auth_type, bfd_auth_type_str (auth_type));
          break;
        case BFD_AUTH_TYPE_keyed_sha1:
          /* fallthrough */
@@ -1768,7 +1964,7 @@ u8 *
 format_bfd_session (u8 * s, va_list * args)
 {
   const bfd_session_t *bs = va_arg (*args, bfd_session_t *);
-  uword indent = format_get_indent (s);
+  u32 indent = format_get_indent (s) + vlib_log_get_indent ();
   s = format (s, "bs_idx=%u local-state=%s remote-state=%s\n"
              "%Ulocal-discriminator=%u remote-discriminator=%u\n"
              "%Ulocal-diag=%s echo-active=%s\n"
@@ -1800,6 +1996,17 @@ format_bfd_session (u8 * s, va_list * args)
   return s;
 }
 
+u8 *
+format_bfd_session_brief (u8 * s, va_list * args)
+{
+  const bfd_session_t *bs = va_arg (*args, bfd_session_t *);
+  s =
+    format (s, "bs_idx=%u local-state=%s remote-state=%s", bs->bs_idx,
+           bfd_state_string (bs->local_state),
+           bfd_state_string (bs->remote_state));
+  return s;
+}
+
 unsigned
 bfd_auth_type_supported (bfd_auth_type_e auth_type)
 {
@@ -1820,7 +2027,8 @@ bfd_auth_activate (bfd_session_t * bs, u32 conf_key_id,
     hash_get (bm->auth_key_by_conf_key_id, conf_key_id);
   if (!key_idx_p)
     {
-      clib_warning ("Authentication key with config ID %u doesn't exist)",
+      vlib_log_err (bm->log_class,
+                   "authentication key with config ID %u doesn't exist)",
                    conf_key_id);
       return VNET_API_ERROR_BFD_ENOENT;
     }
@@ -1854,12 +2062,15 @@ bfd_auth_activate (bfd_session_t * bs, u32 conf_key_id,
     }
   ++key->use_count;
   BFD_DBG ("\nSession auth modified: %U", format_bfd_session, bs);
+  vlib_log_info (bm->log_class, "session auth modified: %U",
+                format_bfd_session_brief, bs);
   return 0;
 }
 
 vnet_api_error_t
 bfd_auth_deactivate (bfd_session_t * bs, u8 is_delayed)
 {
+  bfd_main_t *bm = &bfd_main;
 #if WITH_LIBSSL > 0
   if (!is_delayed)
     {
@@ -1888,9 +2099,12 @@ bfd_auth_deactivate (bfd_session_t * bs, u8 is_delayed)
       bs->auth.next_key = NULL;
     }
   BFD_DBG ("\nSession auth modified: %U", format_bfd_session, bs);
+  vlib_log_info (bm->log_class, "session auth modified: %U",
+                format_bfd_session_brief, bs);
   return 0;
 #else
-  clib_warning ("SSL missing, cannot deactivate BFD authentication");
+  vlib_log_err (bm->log_class,
+               "SSL missing, cannot deactivate BFD authentication");
   return VNET_API_ERROR_BFD_NOTSUPP;
 #endif
 }
@@ -1946,6 +2160,8 @@ bfd_session_set_params (bfd_main_t * bm, bfd_session_t * bs,
        bfd_usec_to_clocks (bm, required_min_rx_usec);
       BFD_DBG ("\nChanged session params: %U", format_bfd_session, bs);
 
+      vlib_log_info (bm->log_class, "changed session params: %U",
+                    format_bfd_session_brief, bs);
       vlib_process_signal_event (bm->vlib_main, bm->bfd_process_node_index,
                                 BFD_EVENT_CONFIG_CHANGED, bs->bs_idx);
     }
@@ -1960,24 +2176,24 @@ vnet_api_error_t
 bfd_auth_set_key (u32 conf_key_id, u8 auth_type, u8 key_len,
                  const u8 * key_data)
 {
+  bfd_main_t *bm = &bfd_main;
 #if WITH_LIBSSL > 0
   bfd_auth_key_t *auth_key = NULL;
   if (!key_len || key_len > bfd_max_key_len_for_auth_type (auth_type))
     {
-      clib_warning ("Invalid authentication key length for auth_type=%d:%s "
-                   "(key_len=%u, must be "
-                   "non-zero, expected max=%u)",
+      vlib_log_err (bm->log_class,
+                   "invalid authentication key length for auth_type=%d:%s "
+                   "(key_len=%u, must be non-zero, expected max=%u)",
                    auth_type, bfd_auth_type_str (auth_type), key_len,
                    (u32) bfd_max_key_len_for_auth_type (auth_type));
       return VNET_API_ERROR_INVALID_VALUE;
     }
   if (!bfd_auth_type_supported (auth_type))
     {
-      clib_warning ("Unsupported auth type=%d:%s", auth_type,
+      vlib_log_err (bm->log_class, "unsupported auth type=%d:%s", auth_type,
                    bfd_auth_type_str (auth_type));
       return VNET_API_ERROR_BFD_NOTSUPP;
     }
-  bfd_main_t *bm = &bfd_main;
   uword *key_idx_p = hash_get (bm->auth_key_by_conf_key_id, conf_key_id);
   if (key_idx_p)
     {
@@ -1986,9 +2202,10 @@ bfd_auth_set_key (u32 conf_key_id, u8 auth_type, u8 key_len,
       auth_key = pool_elt_at_index (bm->auth_keys, key_idx);
       if (auth_key->use_count > 0)
        {
-         clib_warning ("Authentication key with conf ID %u in use by %u BFD "
-                       "session(s) - cannot modify",
-                       conf_key_id, auth_key->use_count);
+         vlib_log_err (bm->log_class,
+                       "authentication key with conf ID %u in use by %u BFD "
+                       "session(s) - cannot modify", conf_key_id,
+                       auth_key->use_count);
          return VNET_API_ERROR_BFD_EINUSE;
        }
     }
@@ -2001,11 +2218,12 @@ bfd_auth_set_key (u32 conf_key_id, u8 auth_type, u8 key_len,
                auth_key - bm->auth_keys);
     }
   auth_key->auth_type = auth_type;
-  memset (auth_key->key, 0, sizeof (auth_key->key));
+  clib_memset (auth_key->key, 0, sizeof (auth_key->key));
   clib_memcpy (auth_key->key, key_data, key_len);
   return 0;
 #else
-  clib_warning ("SSL missing, cannot manipulate authentication keys");
+  vlib_log_err (bm->log_class,
+               "SSL missing, cannot manipulate authentication keys");
   return VNET_API_ERROR_BFD_NOTSUPP;
 #endif
 }
@@ -2024,25 +2242,28 @@ bfd_auth_del_key (u32 conf_key_id)
       auth_key = pool_elt_at_index (bm->auth_keys, key_idx);
       if (auth_key->use_count > 0)
        {
-         clib_warning ("Authentication key with conf ID %u in use by %u BFD "
-                       "session(s) - cannot delete",
-                       conf_key_id, auth_key->use_count);
+         vlib_log_err (bm->log_class,
+                       "authentication key with conf ID %u in use by %u BFD "
+                       "session(s) - cannot delete", conf_key_id,
+                       auth_key->use_count);
          return VNET_API_ERROR_BFD_EINUSE;
        }
       hash_unset (bm->auth_key_by_conf_key_id, conf_key_id);
-      memset (auth_key, 0, sizeof (*auth_key));
+      clib_memset (auth_key, 0, sizeof (*auth_key));
       pool_put (bm->auth_keys, auth_key);
     }
   else
     {
       /* no such key */
-      clib_warning ("Authentication key with conf ID %u does not exist",
+      vlib_log_err (bm->log_class,
+                   "authentication key with conf ID %u does not exist",
                    conf_key_id);
       return VNET_API_ERROR_BFD_ENOENT;
     }
   return 0;
 #else
-  clib_warning ("SSL missing, cannot manipulate authentication keys");
+  vlib_log_err (bm->log_class,
+               "SSL missing, cannot manipulate authentication keys");
   return VNET_API_ERROR_BFD_NOTSUPP;
 #endif
 }