bfd: add tracing support to bfd-process

Outgoing packets can be now traced via:

trace add bfd-process <count>

Type: improvement
Change-Id: Ia19af6054289b18f55e518dbea251a2bee9b9457
Signed-off-by: Klement Sekera <klement.sekera@gmail.com>
diff --git a/src/vnet/bfd/bfd_main.c b/src/vnet/bfd/bfd_main.c
index 1ca1d7e..1423da9 100644
--- a/src/vnet/bfd/bfd_main.c
+++ b/src/vnet/bfd/bfd_main.c
@@ -500,30 +500,29 @@
 }
 
 u8 *
-bfd_input_format_trace (u8 * s, va_list * args)
+format_bfd_pkt (u8 *s, va_list *args)
 {
-  CLIB_UNUSED (vlib_main_t * vm) = va_arg (*args, vlib_main_t *);
-  CLIB_UNUSED (vlib_node_t * node) = va_arg (*args, vlib_node_t *);
-  const bfd_input_trace_t *t = va_arg (*args, bfd_input_trace_t *);
-  const bfd_pkt_t *pkt = (bfd_pkt_t *) t->data;
-  if (t->len > STRUCT_SIZE_OF (bfd_pkt_t, head))
+  u32 len = va_arg (*args, u32);
+  u8 *data = va_arg (*args, u8 *);
+
+  const bfd_pkt_t *pkt = (bfd_pkt_t *) data;
+  if (len > STRUCT_SIZE_OF (bfd_pkt_t, head))
     {
-      s = format (s, "BFD v%u, diag=%u(%s), state=%u(%s),\n"
-		  "    flags=(P:%u, F:%u, C:%u, A:%u, D:%u, M:%u), "
-		  "detect_mult=%u, length=%u\n",
-		  bfd_pkt_get_version (pkt), bfd_pkt_get_diag_code (pkt),
-		  bfd_diag_code_string (bfd_pkt_get_diag_code (pkt)),
-		  bfd_pkt_get_state (pkt),
-		  bfd_state_string (bfd_pkt_get_state (pkt)),
-		  bfd_pkt_get_poll (pkt), bfd_pkt_get_final (pkt),
-		  bfd_pkt_get_control_plane_independent (pkt),
-		  bfd_pkt_get_auth_present (pkt), bfd_pkt_get_demand (pkt),
-		  bfd_pkt_get_multipoint (pkt), pkt->head.detect_mult,
-		  pkt->head.length);
-      if (t->len >= sizeof (bfd_pkt_t) &&
-	  pkt->head.length >= sizeof (bfd_pkt_t))
+      s = format (
+	s,
+	"BFD v%u, diag=%u(%s), state=%u(%s),\n"
+	"    flags=(P:%u, F:%u, C:%u, A:%u, D:%u, M:%u), "
+	"detect_mult=%u, length=%u",
+	bfd_pkt_get_version (pkt), bfd_pkt_get_diag_code (pkt),
+	bfd_diag_code_string (bfd_pkt_get_diag_code (pkt)),
+	bfd_pkt_get_state (pkt), bfd_state_string (bfd_pkt_get_state (pkt)),
+	bfd_pkt_get_poll (pkt), bfd_pkt_get_final (pkt),
+	bfd_pkt_get_control_plane_independent (pkt),
+	bfd_pkt_get_auth_present (pkt), bfd_pkt_get_demand (pkt),
+	bfd_pkt_get_multipoint (pkt), pkt->head.detect_mult, pkt->head.length);
+      if (len >= sizeof (bfd_pkt_t) && pkt->head.length >= sizeof (bfd_pkt_t))
 	{
-	  s = format (s, "    my discriminator: %u\n",
+	  s = format (s, "\n    my discriminator: %u\n",
 		      clib_net_to_host_u32 (pkt->my_disc));
 	  s = format (s, "    your discriminator: %u\n",
 		      clib_net_to_host_u32 (pkt->your_disc));
@@ -534,16 +533,16 @@
 	  s = format (s, "    required min echo rx interval: %u",
 		      clib_net_to_host_u32 (pkt->req_min_echo_rx));
 	}
-      if (t->len >= sizeof (bfd_pkt_with_common_auth_t) &&
+      if (len >= sizeof (bfd_pkt_with_common_auth_t) &&
 	  pkt->head.length >= sizeof (bfd_pkt_with_common_auth_t) &&
 	  bfd_pkt_get_auth_present (pkt))
 	{
 	  const bfd_pkt_with_common_auth_t *with_auth = (void *) pkt;
 	  const bfd_auth_common_t *common = &with_auth->common_auth;
 	  s = format (s, "\n    auth len: %u\n", common->len);
-	  s = format (s, "    auth type: %u:%s\n", common->type,
+	  s = format (s, "    auth type: %u:%s", common->type,
 		      bfd_auth_type_str (common->type));
-	  if (t->len >= sizeof (bfd_pkt_with_sha1_auth_t) &&
+	  if (len >= sizeof (bfd_pkt_with_sha1_auth_t) &&
 	      pkt->head.length >= sizeof (bfd_pkt_with_sha1_auth_t) &&
 	      (BFD_AUTH_TYPE_keyed_sha1 == common->type ||
 	       BFD_AUTH_TYPE_meticulous_keyed_sha1 == common->type))
@@ -557,15 +556,23 @@
 			  sizeof (sha1->hash));
 	    }
 	}
-      else
-	{
-	  s = format (s, "\n");
-	}
     }
 
   return s;
 }
 
+u8 *
+bfd_input_format_trace (u8 *s, va_list *args)
+{
+  CLIB_UNUSED (vlib_main_t * vm) = va_arg (*args, vlib_main_t *);
+  CLIB_UNUSED (vlib_node_t * node) = va_arg (*args, vlib_node_t *);
+  const bfd_input_trace_t *t = va_arg (*args, bfd_input_trace_t *);
+
+  s = format (s, "%U", format_bfd_pkt, t->len, t->data);
+
+  return s;
+}
+
 typedef struct
 {
   u32 bs_idx;
@@ -739,17 +746,18 @@
 }
 
 static int
-bfd_transport_control_frame (vlib_main_t * vm, u32 bi, bfd_session_t * bs)
+bfd_transport_control_frame (vlib_main_t *vm, vlib_node_runtime_t *rt, u32 bi,
+			     bfd_session_t *bs)
 {
   switch (bs->transport)
     {
     case BFD_TRANSPORT_UDP4:
       BFD_DBG ("Transport bfd via udp4, bs_idx=%u", bs->bs_idx);
-      return bfd_transport_udp4 (vm, bi, bs, 0 /* is_echo */);
+      return bfd_transport_udp4 (vm, rt, bi, bs, 0 /* is_echo */);
       break;
     case BFD_TRANSPORT_UDP6:
       BFD_DBG ("Transport bfd via udp6, bs_idx=%u", bs->bs_idx);
-      return bfd_transport_udp6 (vm, bi, bs, 0 /* is_echo */);
+      return bfd_transport_udp6 (vm, rt, bi, bs, 0 /* is_echo */);
       break;
     }
   return 0;
@@ -773,17 +781,18 @@
 }
 
 static int
-bfd_transport_echo (vlib_main_t * vm, u32 bi, bfd_session_t * bs)
+bfd_transport_echo (vlib_main_t *vm, vlib_node_runtime_t *rt, u32 bi,
+		    bfd_session_t *bs)
 {
   switch (bs->transport)
     {
     case BFD_TRANSPORT_UDP4:
       BFD_DBG ("Transport bfd echo via udp4, bs_idx=%u", bs->bs_idx);
-      return bfd_transport_udp4 (vm, bi, bs, 1 /* is_echo */);
+      return bfd_transport_udp4 (vm, rt, bi, bs, 1 /* is_echo */);
       break;
     case BFD_TRANSPORT_UDP6:
       BFD_DBG ("Transport bfd echo via udp6, bs_idx=%u", bs->bs_idx);
-      return bfd_transport_udp6 (vm, bi, bs, 1 /* is_echo */);
+      return bfd_transport_udp6 (vm, rt, bi, bs, 1 /* is_echo */);
       break;
     }
   return 0;
@@ -902,8 +911,39 @@
   b->current_length = bfd_length;
 }
 
+typedef struct
+{
+  u32 bs_idx;
+  u32 len;
+  u8 data[400];
+} bfd_process_trace_t;
+
 static void
-bfd_send_echo (vlib_main_t *vm, bfd_main_t *bm, bfd_session_t *bs, u64 now)
+bfd_process_trace_buf (vlib_main_t *vm, vlib_node_runtime_t *rt,
+		       vlib_buffer_t *b, bfd_session_t *bs)
+{
+  u32 n_trace = vlib_get_trace_count (vm, rt);
+  if (n_trace > 0)
+    {
+      bfd_process_trace_t *tr;
+      if (vlib_trace_buffer (vm, rt, 0, b, 0))
+	{
+	  tr = vlib_add_trace (vm, rt, b, sizeof (*tr));
+	  tr->bs_idx = bs->bs_idx;
+	  u64 len = (b->current_length < sizeof (tr->data)) ?
+			    b->current_length :
+			    sizeof (tr->data);
+	  tr->len = len;
+	  clib_memcpy_fast (tr->data, vlib_buffer_get_current (b), len);
+	  --n_trace;
+	  vlib_set_trace_count (vm, rt, n_trace);
+	}
+    }
+}
+
+static void
+bfd_send_echo (vlib_main_t *vm, vlib_node_runtime_t *rt, bfd_main_t *bm,
+	       bfd_session_t *bs, u64 now)
 {
   if (!bfd_is_echo_possible (bs))
     {
@@ -931,6 +971,7 @@
 	bfd_calc_echo_checksum (bs->local_discr, pkt->expire_time_nsec,
 				bs->echo_secret);
       b->current_length = sizeof (*pkt);
+      bfd_process_trace_buf (vm, rt, b, bs);
       if (!bfd_echo_add_transport_layer (vm, bi, bs))
 	{
 	  BFD_ERR ("cannot send echo packet out, turning echo off");
@@ -938,7 +979,7 @@
 	  vlib_buffer_free_one (vm, bi);
 	  return;
 	}
-      if (!bfd_transport_echo (vm, bi, bs))
+      if (!bfd_transport_echo (vm, rt, bi, bs))
 	{
 	  BFD_ERR ("cannot send echo packet out, turning echo off");
 	  bs->echo = 0;
@@ -957,7 +998,8 @@
 }
 
 static void
-bfd_send_periodic (vlib_main_t *vm, bfd_main_t *bm, bfd_session_t *bs, u64 now)
+bfd_send_periodic (vlib_main_t *vm, vlib_node_runtime_t *rt, bfd_main_t *bm,
+		   bfd_session_t *bs, u64 now)
 {
   if (!bs->remote_min_rx_usec && BFD_POLL_NOT_NEEDED == bs->poll_state)
     {
@@ -1014,8 +1056,9 @@
 	  break;
 	}
       bfd_add_auth_section (vm, b, bs);
+      bfd_process_trace_buf (vm, rt, b, bs);
       bfd_add_transport_layer (vm, bi, bs);
-      if (!bfd_transport_control_frame (vm, bi, bs))
+      if (!bfd_transport_control_frame (vm, rt, bi, bs))
 	{
 	  vlib_buffer_free_one (vm, bi);
 	}
@@ -1090,7 +1133,8 @@
 }
 
 void
-bfd_on_timeout (vlib_main_t *vm, bfd_main_t *bm, bfd_session_t *bs, u64 now)
+bfd_on_timeout (vlib_main_t *vm, vlib_node_runtime_t *rt, bfd_main_t *bm,
+		bfd_session_t *bs, u64 now)
 {
   BFD_DBG ("Timeout for bs_idx=%lu", bs->bs_idx);
   switch (bs->local_state)
@@ -1098,11 +1142,11 @@
     case BFD_STATE_admin_down:
       /* fallthrough */
     case BFD_STATE_down:
-      bfd_send_periodic (vm, bm, bs, now);
+      bfd_send_periodic (vm, rt, bm, bs, now);
       break;
     case BFD_STATE_init:
       bfd_check_rx_timeout (vm, bm, bs, now, 1);
-      bfd_send_periodic (vm, bm, bs, now);
+      bfd_send_periodic (vm, rt, bm, bs, now);
       break;
     case BFD_STATE_up:
       bfd_check_rx_timeout (vm, bm, bs, now, 1);
@@ -1119,20 +1163,33 @@
 			  bs->config_required_min_rx_nsec));
 	  bfd_set_poll_state (bs, BFD_POLL_NEEDED);
 	}
-      bfd_send_periodic (vm, bm, bs, now);
+      bfd_send_periodic (vm, rt, bm, bs, now);
       if (bs->echo)
 	{
-	  bfd_send_echo (vm, bm, bs, now);
+	  bfd_send_echo (vm, rt, bm, bs, now);
 	}
       break;
     }
 }
 
+u8 *
+format_bfd_process_trace (u8 *s, va_list *args)
+{
+  CLIB_UNUSED (vlib_main_t * vm) = va_arg (*args, vlib_main_t *);
+  CLIB_UNUSED (vlib_node_t * node) = va_arg (*args, vlib_node_t *);
+  bfd_process_trace_t *t = va_arg (*args, bfd_process_trace_t *);
+
+  s =
+    format (s, "bs_idx=%u => %U", t->bs_idx, format_bfd_pkt, t->len, t->data);
+
+  return s;
+}
+
 /*
  * bfd process node function
  */
 static uword
-bfd_process (vlib_main_t *vm, CLIB_UNUSED (vlib_node_runtime_t *rt),
+bfd_process (vlib_main_t *vm, vlib_node_runtime_t *rt,
 	     CLIB_UNUSED (vlib_frame_t *f))
 {
   bfd_main_t *bm = &bfd_main;
@@ -1213,7 +1270,7 @@
 	      {
 		bfd_session_t *bs =
 		  pool_elt_at_index (bm->sessions, *session_index);
-		bfd_send_periodic (vm, bm, bs, now);
+		bfd_send_periodic (vm, rt, bm, bs, now);
 		bfd_set_timer (bm, bs, now, 1);
 	      }
 	    else
@@ -1259,7 +1316,7 @@
 	  {
 	    bfd_session_t *bs = pool_elt_at_index (bm->sessions, bs_idx);
 	    bs->tw_id = 0;	/* timer is gone because it expired */
-	    bfd_on_timeout (vm, bm, bs, now);
+	    bfd_on_timeout (vm, rt, bm, bs, now);
 	    bfd_set_timer (bm, bs, now, 1);
 	  }
       }
@@ -1280,13 +1337,25 @@
 /*
  * bfd process node declaration
  */
-VLIB_REGISTER_NODE (bfd_process_node, static) = {
+// clang-format off
+VLIB_REGISTER_NODE (bfd_process_node, static) =
+{
   .function = bfd_process,
   .type = VLIB_NODE_TYPE_PROCESS,
   .name = "bfd-process",
-  .n_next_nodes = 0,
-  .next_nodes = {},
+  .flags = (VLIB_NODE_FLAG_TRACE_SUPPORTED),
+  .format_trace = format_bfd_process_trace,
+  .n_next_nodes = BFD_TX_N_NEXT,
+  .next_nodes = {
+    [BFD_TX_IP4_ARP] = "ip4-arp",
+    [BFD_TX_IP6_NDP] = "ip6-discover-neighbor",
+    [BFD_TX_IP4_REWRITE] = "ip4-rewrite",
+    [BFD_TX_IP6_REWRITE] = "ip6-rewrite",
+    [BFD_TX_IP4_MIDCHAIN] = "ip4-midchain",
+    [BFD_TX_IP6_MIDCHAIN] = "ip6-midchain",
+  }
 };
+// clang-format on
 
 static clib_error_t *
 bfd_sw_interface_up_down (CLIB_UNUSED (vnet_main_t *vnm),
diff --git a/src/vnet/bfd/bfd_main.h b/src/vnet/bfd/bfd_main.h
index 4fc4ef8..22d9334 100644
--- a/src/vnet/bfd/bfd_main.h
+++ b/src/vnet/bfd/bfd_main.h
@@ -476,6 +476,17 @@
  */
 void bfd_register_listener (bfd_notify_fn_t fn);
 
+typedef enum
+{
+  BFD_TX_IP4_ARP,
+  BFD_TX_IP6_NDP,
+  BFD_TX_IP4_REWRITE,
+  BFD_TX_IP6_REWRITE,
+  BFD_TX_IP4_MIDCHAIN,
+  BFD_TX_IP6_MIDCHAIN,
+  BFD_TX_N_NEXT,
+} bfd_tx_next_t;
+
 #endif /* __included_bfd_main_h__ */
 
 /*
diff --git a/src/vnet/bfd/bfd_udp.c b/src/vnet/bfd/bfd_udp.c
index 36ecdf1..37bb102 100644
--- a/src/vnet/bfd/bfd_udp.c
+++ b/src/vnet/bfd/bfd_udp.c
@@ -54,18 +54,6 @@
   int echo_source_is_set;
   /* loopback interface used to get echo source ip */
   u32 echo_source_sw_if_index;
-  /* node index of "ip4-arp" node */
-  u32 ip4_arp_idx;
-  /* node index of "ip6-discover-neighbor" node */
-  u32 ip6_ndp_idx;
-  /* node index of "ip4-rewrite" node */
-  u32 ip4_rewrite_idx;
-  /* node index of "ip6-rewrite" node */
-  u32 ip6_rewrite_idx;
-  /* node index of "ip4-midchain" node */
-  u32 ip4_midchain_idx;
-  /* node index of "ip6-midchain" node */
-  u32 ip6_midchain_idx;
   /* log class */
   vlib_log_class_t log_class;
   /* number of active udp4 sessions */
@@ -384,16 +372,23 @@
 }
 
 static void
-bfd_create_frame_to_next_node (vlib_main_t *vm, bfd_main_t *bm,
-			       const bfd_session_t *bs, u32 bi, u32 next_node,
+bfd_create_frame_to_next_node (vlib_main_t *vm, vlib_node_runtime_t *rt,
+			       u32 bi, const bfd_session_t *bs, u32 next,
 			       vlib_combined_counter_main_t *tx_counter)
 {
-  vlib_frame_t *f = vlib_get_frame_to_node (vm, next_node);
+  vlib_buffer_t *b = vlib_get_buffer (vm, bi);
+  vlib_node_t *from_node = vlib_get_node (vm, rt->node_index);
+  ASSERT (next < vec_len (from_node->next_nodes));
+  u32 to_node_index = from_node->next_nodes[next];
+  vlib_frame_t *f = vlib_get_frame_to_node (vm, to_node_index);
   u32 *to_next = vlib_frame_vector_args (f);
   to_next[0] = bi;
   f->n_vectors = 1;
-  vlib_put_frame_to_node (vm, next_node, f);
-  vlib_buffer_t *b = vlib_get_buffer (vm, bi);
+  if (b->flags & VLIB_BUFFER_IS_TRACED)
+    {
+      f->frame_flags |= VLIB_NODE_FLAG_TRACE;
+    }
+  vlib_put_frame_to_node (vm, to_node_index, f);
   vlib_increment_combined_counter (tx_counter, vm->thread_index, bs->bs_idx, 1,
 				   vlib_buffer_length_in_chain (vm, b));
 }
@@ -415,10 +410,10 @@
       switch (bs->transport)
 	{
 	case BFD_TRANSPORT_UDP4:
-	  *next_node = bfd_udp_main.ip4_arp_idx;
+	  *next_node = BFD_TX_IP4_ARP;
 	  return 1;
 	case BFD_TRANSPORT_UDP6:
-	  *next_node = bfd_udp_main.ip6_ndp_idx;
+	  *next_node = BFD_TX_IP6_NDP;
 	  return 1;
 	}
       break;
@@ -426,10 +421,10 @@
       switch (bs->transport)
 	{
 	case BFD_TRANSPORT_UDP4:
-	  *next_node = bfd_udp_main.ip4_rewrite_idx;
+	  *next_node = BFD_TX_IP4_REWRITE;
 	  return 1;
 	case BFD_TRANSPORT_UDP6:
-	  *next_node = bfd_udp_main.ip6_rewrite_idx;
+	  *next_node = BFD_TX_IP6_REWRITE;
 	  return 1;
 	}
       break;
@@ -437,10 +432,10 @@
       switch (bs->transport)
 	{
 	case BFD_TRANSPORT_UDP4:
-	  *next_node = bfd_udp_main.ip4_midchain_idx;
+	  *next_node = BFD_TX_IP4_MIDCHAIN;
 	  return 1;
 	case BFD_TRANSPORT_UDP6:
-	  *next_node = bfd_udp_main.ip6_midchain_idx;
+	  *next_node = BFD_TX_IP6_MIDCHAIN;
 	  return 1;
 	}
       break;
@@ -452,33 +447,33 @@
 }
 
 int
-bfd_transport_udp4 (vlib_main_t *vm, u32 bi, const struct bfd_session_s *bs,
-		    int is_echo)
+bfd_transport_udp4 (vlib_main_t *vm, vlib_node_runtime_t *rt, u32 bi,
+		    const struct bfd_session_s *bs, int is_echo)
 {
   u32 next_node;
   int rv = bfd_udp_calc_next_node (bs, &next_node);
   bfd_main_t *bm = bfd_udp_main.bfd_main;
   if (rv)
     {
-      bfd_create_frame_to_next_node (vm, bm, bs, bi, next_node,
+      bfd_create_frame_to_next_node (vm, rt, bi, bs, next_node,
 				     is_echo ? &bm->tx_echo_counter :
-					       &bm->tx_counter);
+						     &bm->tx_counter);
     }
   return rv;
 }
 
 int
-bfd_transport_udp6 (vlib_main_t *vm, u32 bi, const struct bfd_session_s *bs,
-		    int is_echo)
+bfd_transport_udp6 (vlib_main_t *vm, vlib_node_runtime_t *rt, u32 bi,
+		    const struct bfd_session_s *bs, int is_echo)
 {
   u32 next_node;
   int rv = bfd_udp_calc_next_node (bs, &next_node);
   bfd_main_t *bm = bfd_udp_main.bfd_main;
   if (rv)
     {
-      bfd_create_frame_to_next_node (
-	vm, bfd_udp_main.bfd_main, bs, bi, next_node,
-	is_echo ? &bm->tx_echo_counter : &bm->tx_counter);
+      bfd_create_frame_to_next_node (vm, rt, bi, bs, next_node,
+				     is_echo ? &bm->tx_echo_counter :
+						     &bm->tx_counter);
     }
   return 1;
 }
@@ -1639,25 +1634,6 @@
 	      sizeof (bfd_udp_key_t));
   bfd_udp_main.bfd_main = &bfd_main;
   bfd_udp_main.vnet_main = vnet_get_main ();
-  vlib_node_t *node = vlib_get_node_by_name (vm, (u8 *) "ip4-arp");
-  ASSERT (node);
-  bfd_udp_main.ip4_arp_idx = node->index;
-  node = vlib_get_node_by_name (vm, (u8 *) "ip6-discover-neighbor");
-  ASSERT (node);
-  bfd_udp_main.ip6_ndp_idx = node->index;
-  node = vlib_get_node_by_name (vm, (u8 *) "ip4-rewrite");
-  ASSERT (node);
-  bfd_udp_main.ip4_rewrite_idx = node->index;
-  node = vlib_get_node_by_name (vm, (u8 *) "ip6-rewrite");
-  ASSERT (node);
-  bfd_udp_main.ip6_rewrite_idx = node->index;
-  node = vlib_get_node_by_name (vm, (u8 *) "ip4-midchain");
-  ASSERT (node);
-  bfd_udp_main.ip4_midchain_idx = node->index;
-  node = vlib_get_node_by_name (vm, (u8 *) "ip6-midchain");
-  ASSERT (node);
-  bfd_udp_main.ip6_midchain_idx = node->index;
-
   bfd_udp_stats_init (&bfd_udp_main);
 
   bfd_udp_main.log_class = vlib_log_register_class ("bfd", "udp");
diff --git a/src/vnet/bfd/bfd_udp.h b/src/vnet/bfd/bfd_udp.h
index 866b586..8f4bfee 100644
--- a/src/vnet/bfd/bfd_udp.h
+++ b/src/vnet/bfd/bfd_udp.h
@@ -82,7 +82,7 @@
  *
  * @return 1 on success, 0 on failure
  */
-int bfd_transport_udp4 (vlib_main_t *vm, u32 bi,
+int bfd_transport_udp4 (vlib_main_t *vm, vlib_node_runtime_t *rt, u32 bi,
 			const struct bfd_session_s *bs, int is_echo);
 
 /**
@@ -90,7 +90,7 @@
  *
  * @return 1 on success, 0 on failure
  */
-int bfd_transport_udp6 (vlib_main_t *vm, u32 bi,
+int bfd_transport_udp6 (vlib_main_t *vm, vlib_node_runtime_t *rt, u32 bi,
 			const struct bfd_session_s *bs, int is_echo);
 
 /**