api: enable binary API event logging in vat

Cleaned up a few instances of side-bet elog_string hash table
usage. Elog_string handles that problem itself.

Add cli commands to vat to initialize, enable/disable, and save an
event log.

Event logging at the same time in both vpp and vat yields a pair
of event logs which can be merged by the "test_elog" tool.

Type: refactor

Change-Id: I8d6a72206f2309c967ea1630077fba31aef47f93
Signed-off-by: Dave Barach <dave@barachs.net>

9 files changed, 254 insertions, 65 deletions

diff --git a/src/vat/api_format.c b/src/vat/api_format.c
index 5bba7efea46..a8d4a0db09d 100644
--- a/src/vat/api_format.c
+++ b/src/vat/api_format.c
@@ -85,6 +85,9 @@
 #define __plugin_msg_base 0
 #include <vlibapi/vat_helper_macros.h>
 
+void vl_api_set_elog_main (elog_main_t * m);
+int vl_api_set_elog_trace_api_messages (int enable);
+
 #if VPP_API_TEST_BUILTIN == 0
 #include <netdb.h>
 
@@ -164,7 +167,8 @@ errmsg (char *fmt, ...)
     if (vam->ifp != stdin)
       fformat (vam->ofp, "%s(%d): \n", vam->current_file,
 	       vam->input_line_number);
-    fformat (vam->ofp, (char *) s);
+    else
+      fformat (vam->ofp, "%s\n", (char *) s);
     fflush (vam->ofp);
   }
 #endif
@@ -21403,6 +21407,98 @@ comment (vat_main_t * vam)
 }
 
 static int
+elog_save (vat_main_t * vam)
+{
+#if VPP_API_TEST_BUILTIN == 0
+  elog_main_t *em = &vam->elog_main;
+  unformat_input_t *i = vam->input;
+  char *file, *chroot_file;
+  clib_error_t *error;
+
+  if (!unformat (i, "%s", &file))
+    {
+      errmsg ("expected file name, got `%U'", format_unformat_error, i);
+      return 0;
+    }
+
+  /* It's fairly hard to get "../oopsie" through unformat; just in case */
+  if (strstr (file, "..") || index (file, '/'))
+    {
+      errmsg ("illegal characters in filename '%s'", file);
+      return 0;
+    }
+
+  chroot_file = (char *) format (0, "/tmp/%s%c", file, 0);
+
+  vec_free (file);
+
+  errmsg ("Saving %wd of %wd events to %s",
+	  elog_n_events_in_buffer (em),
+	  elog_buffer_capacity (em), chroot_file);
+
+  error = elog_write_file (em, chroot_file, 1 /* flush ring */ );
+  vec_free (chroot_file);
+
+  if (error)
+    clib_error_report (error);
+#else
+  errmsg ("Use the vpp event loger...");
+#endif
+
+  return 0;
+}
+
+static int
+elog_setup (vat_main_t * vam)
+{
+#if VPP_API_TEST_BUILTIN == 0
+  elog_main_t *em = &vam->elog_main;
+  unformat_input_t *i = vam->input;
+  u32 nevents = 128 << 10;
+
+  (void) unformat (i, "nevents %d", &nevents);
+
+  elog_init (em, nevents);
+  vl_api_set_elog_main (em);
+  vl_api_set_elog_trace_api_messages (1);
+  errmsg ("Event logger initialized with %u events", nevents);
+#else
+  errmsg ("Use the vpp event loger...");
+#endif
+  return 0;
+}
+
+static int
+elog_enable (vat_main_t * vam)
+{
+#if VPP_API_TEST_BUILTIN == 0
+  elog_main_t *em = &vam->elog_main;
+
+  elog_enable_disable (em, 1 /* enable */ );
+  vl_api_set_elog_trace_api_messages (1);
+  errmsg ("Event logger enabled...");
+#else
+  errmsg ("Use the vpp event loger...");
+#endif
+  return 0;
+}
+
+static int
+elog_disable (vat_main_t * vam)
+{
+#if VPP_API_TEST_BUILTIN == 0
+  elog_main_t *em = &vam->elog_main;
+
+  elog_enable_disable (em, 0 /* enable */ );
+  vl_api_set_elog_trace_api_messages (1);
+  errmsg ("Event logger disabled...");
+#else
+  errmsg ("Use the vpp event loger...");
+#endif
+  return 0;
+}
+
+static int
 statseg (vat_main_t * vam)
 {
   ssvm_private_t *ssvmp = &vam->stat_segment;
@@ -22286,6 +22382,10 @@ _(dump_ipv6_table, "usage: dump_ipv6_table")                    \
 _(dump_macro_table, "usage: dump_macro_table ")                 \
 _(dump_node_table, "usage: dump_node_table")			\
 _(dump_msg_api_table, "usage: dump_msg_api_table")		\
+_(elog_setup, "usage: elog_setup [nevents, default 128K]")      \
+_(elog_disable, "usage: elog_disable")                          \
+_(elog_enable, "usage: elog_enable")                            \
+_(elog_save, "usage: elog_save <filename>")                     \
 _(get_msg_id, "usage: get_msg_id name_and_crc")			\
 _(echo, "usage: echo <message>")				\
 _(exec, "usage: exec <vpe-debug-CLI-command>")                  \
diff --git a/src/vat/vat.h b/src/vat/vat.h
index c71446519a3..0d93af7b0f2 100644
--- a/src/vat/vat.h
+++ b/src/vat/vat.h
@@ -24,6 +24,7 @@
 #include <vppinfra/clib.h>
 #include <vppinfra/format.h>
 #include <vppinfra/error.h>
+#include <vppinfra/elog.h>
 #include <vppinfra/time.h>
 #include <vppinfra/macros.h>
 #include <vppinfra/socket.h>
@@ -215,6 +216,10 @@ typedef struct
   socket_client_main_t *socket_client_main;
   u8 *socket_name;
 
+#if VPP_API_TEST_BUILTIN == 0
+  elog_main_t elog_main;
+#endif
+
   /* Convenience */
   vlib_main_t *vlib_main;
 } vat_main_t;
diff --git a/src/vlib/cli.c b/src/vlib/cli.c
index bf0670da1c9..60895bacb1c 100644
--- a/src/vlib/cli.c
+++ b/src/vlib/cli.c
@@ -44,6 +44,9 @@
 #include <unistd.h>
 #include <ctype.h>
 
+int vl_api_set_elog_trace_api_messages (int enable);
+int vl_api_get_elog_trace_api_messages (void);
+
 static void *current_traced_heap;
 
 /* Root of all show commands. */
@@ -633,7 +636,7 @@ vlib_cli_dispatch_sub_commands (vlib_main_t * vm,
 		    u32 c;
 		  } *ed;
 		  ed = ELOG_DATA (&vm->elog_main, e);
-		  ed->c = elog_global_id_for_msg_name (c->path);
+		  ed->c = elog_string (&vm->elog_main, c->path);
 		}
 
 	      if (!c->is_mp_safe)
@@ -658,16 +661,16 @@ vlib_cli_dispatch_sub_commands (vlib_main_t * vm,
 		    u32 c, err;
 		  } *ed;
 		  ed = ELOG_DATA (&vm->elog_main, e);
-		  ed->c = elog_global_id_for_msg_name (c->path);
+		  ed->c = elog_string (&vm->elog_main, c->path);
 		  if (c_error)
 		    {
 		      vec_add1 (c_error->what, 0);
-		      ed->err = elog_global_id_for_msg_name
-			((const char *) c_error->what);
+		      ed->err = elog_string (&vm->elog_main,
+					     (char *) c_error->what);
 		      _vec_len (c_error->what) -= 1;
 		    }
 		  else
-		    ed->err = elog_global_id_for_msg_name ("OK");
+		    ed->err = elog_string (&vm->elog_main, "OK");
 		}
 
 	      if (c_error)
@@ -1630,7 +1633,8 @@ elog_trace_command_fn (vlib_main_t * vm,
     }
   unformat_free (line_input);
 
-  vm->elog_trace_api_messages = api ? enable : vm->elog_trace_api_messages;
+  vl_api_set_elog_trace_api_messages
+    (api ? enable : vl_api_get_elog_trace_api_messages ());
   vm->elog_trace_cli_commands = cli ? enable : vm->elog_trace_cli_commands;
   vm->elog_trace_graph_dispatch = dispatch ?
     enable : vm->elog_trace_graph_dispatch;
@@ -1660,7 +1664,7 @@ print_status:
 
   vlib_cli_output
     (vm, "    Event log API message trace: %s\n    CLI command trace: %s",
-     vm->elog_trace_api_messages ? "on" : "off",
+     vl_api_get_elog_trace_api_messages ()? "on" : "off",
      vm->elog_trace_cli_commands ? "on" : "off");
   vlib_cli_output
     (vm, "    Barrier sync trace: %s",
diff --git a/src/vlib/main.c b/src/vlib/main.c
index 3c0e754169f..055ea93cec1 100644
--- a/src/vlib/main.c
+++ b/src/vlib/main.c
@@ -1990,6 +1990,29 @@ clib_error_t *name (vlib_main_t *vm) { return 0; }
 foreach_weak_reference_stub;
 #undef _
 
+void vl_api_set_elog_main (elog_main_t * m) __attribute__ ((weak));
+void
+vl_api_set_elog_main (elog_main_t * m)
+{
+  clib_warning ("STUB");
+}
+
+int vl_api_set_elog_trace_api_messages (int enable) __attribute__ ((weak));
+int
+vl_api_set_elog_trace_api_messages (int enable)
+{
+  clib_warning ("STUB");
+  return 0;
+}
+
+int vl_api_get_elog_trace_api_messages (void) __attribute__ ((weak));
+int
+vl_api_get_elog_trace_api_messages (void)
+{
+  clib_warning ("STUB");
+  return 0;
+}
+
 /* Main function. */
 int
 vlib_main (vlib_main_t * volatile vm, unformat_input_t * input)
@@ -2006,6 +2029,8 @@ vlib_main (vlib_main_t * volatile vm, unformat_input_t * input)
     vm->elog_main.event_ring_size = 128 << 10;
   elog_init (&vm->elog_main, vm->elog_main.event_ring_size);
   elog_enable_disable (&vm->elog_main, 1);
+  vl_api_set_elog_main (&vm->elog_main);
+  (void) vl_api_set_elog_trace_api_messages (1);
 
   /* Default name. */
   if (!vm->name)
diff --git a/src/vlib/threads.c b/src/vlib/threads.c
index 91125387248..e59919e7a26 100644
--- a/src/vlib/threads.c
+++ b/src/vlib/threads.c
@@ -44,28 +44,6 @@ vlib_thread_main_t vlib_thread_main;
  * imapacts observed timings.
  */
 
-u32
-elog_global_id_for_msg_name (const char *msg_name)
-{
-  uword *p, r;
-  static uword *h;
-  u8 *name_copy;
-
-  if (!h)
-    h = hash_create_string (0, sizeof (uword));
-
-  p = hash_get_mem (h, msg_name);
-  if (p)
-    return p[0];
-  r = elog_string (&vlib_global_main.elog_main, "%s", msg_name);
-
-  name_copy = format (0, "%s%c", msg_name, 0);
-
-  hash_set_mem (h, name_copy, r);
-
-  return r;
-}
-
 static inline void
 barrier_trace_sync (f64 t_entry, f64 t_open, f64 t_closed)
 {
@@ -86,8 +64,8 @@ barrier_trace_sync (f64 t_entry, f64 t_open, f64 t_closed)
 
   ed = ELOG_DATA (&vlib_global_main.elog_main, e);
   ed->count = (int) vlib_worker_threads[0].barrier_sync_count;
-  ed->caller = elog_global_id_for_msg_name
-    (vlib_worker_threads[0].barrier_caller);
+  ed->caller = elog_string (&vlib_global_main.elog_main,
+			    (char *) vlib_worker_threads[0].barrier_caller);
   ed->t_entry = (int) (1000000.0 * t_entry);
   ed->t_open = (int) (1000000.0 * t_open);
   ed->t_closed = (int) (1000000.0 * t_closed);
@@ -113,8 +91,8 @@ barrier_trace_sync_rec (f64 t_entry)
 
   ed = ELOG_DATA (&vlib_global_main.elog_main, e);
   ed->depth = (int) vlib_worker_threads[0].recursion_level - 1;
-  ed->caller = elog_global_id_for_msg_name
-    (vlib_worker_threads[0].barrier_caller);
+  ed->caller = elog_string (&vlib_global_main.elog_main,
+			    (char *) vlib_worker_threads[0].barrier_caller);
 }
 
 static inline void
diff --git a/src/vlib/threads.h b/src/vlib/threads.h
index fc34074127f..79f44c8f502 100644
--- a/src/vlib/threads.h
+++ b/src/vlib/threads.h
@@ -613,8 +613,6 @@ void
 vlib_process_signal_event_mt_helper (vlib_process_signal_event_mt_args_t *
 				     args);
 void vlib_rpc_call_main_thread (void *function, u8 * args, u32 size);
-
-u32 elog_global_id_for_msg_name (const char *msg_name);
 #endif /* included_vlib_threads_h */
 
 /*
diff --git a/src/vlibapi/api_common.h b/src/vlibapi/api_common.h
index 735921b30f7..98fcbdefef9 100644
--- a/src/vlibapi/api_common.h
+++ b/src/vlibapi/api_common.h
@@ -25,6 +25,7 @@
  */
 
 #include <vppinfra/clib_error.h>
+#include <vppinfra/elog.h>
 #include <vlibapi/api_types.h>
 #include <svm/svm_common.h>
 #include <svm/queue.h>
@@ -339,6 +340,10 @@ typedef struct
   /** List of API client reaper functions */
   _vl_msg_api_function_list_elt_t *reaper_function_registrations;
 
+  /** event log */
+  elog_main_t *elog_main;
+  int elog_trace_api_messages;
+
 } api_main_t;
 
 extern api_main_t api_main;
diff --git a/src/vlibapi/api_shared.c b/src/vlibapi/api_shared.c
index 9579fe1c60f..18eb83b68b7 100644
--- a/src/vlibapi/api_shared.c
+++ b/src/vlibapi/api_shared.c
@@ -398,6 +398,26 @@ msg_handler_internal (api_main_t * am,
   u16 id = clib_net_to_host_u16 (*((u16 *) the_msg));
   u8 *(*print_fp) (void *, void *);
 
+  if (PREDICT_FALSE (am->elog_trace_api_messages))
+    {
+      /* *INDENT-OFF* */
+      ELOG_TYPE_DECLARE (e) =
+        {
+          .format = "api-msg: %s",
+          .format_args = "T4",
+        };
+      /* *INDENT-ON* */
+      struct
+      {
+	u32 c;
+      } *ed;
+      ed = ELOG_DATA (am->elog_main, e);
+      if (id < vec_len (am->msg_names))
+	ed->c = elog_string (am->elog_main, (char *) am->msg_names[id]);
+      else
+	ed->c = elog_string (am->elog_main, "BOGUS");
+    }
+
   if (id < vec_len (am->msg_handlers) && am->msg_handlers[id])
     {
       if (trace_it)
@@ -436,28 +456,35 @@ msg_handler_internal (api_main_t * am,
 
   if (free_it)
     vl_msg_api_free (the_msg);
-}
 
-static u32
-elog_id_for_msg_name (vlib_main_t * vm, const char *msg_name)
-{
-  uword *p, r;
-  static uword *h;
-  u8 *name_copy;
-
-  if (!h)
-    h = hash_create_string (0, sizeof (uword));
-
-  p = hash_get_mem (h, msg_name);
-  if (p)
-    return p[0];
-  r = elog_string (&vm->elog_main, "%s", msg_name);
-
-  name_copy = format (0, "%s%c", msg_name, 0);
-
-  hash_set_mem (h, name_copy, r);
+  if (PREDICT_FALSE (am->elog_trace_api_messages))
+    {
+      /* *INDENT-OFF* */
+      ELOG_TYPE_DECLARE (e) =
+        {
+          .format = "api-msg-done(%s): %s",
+          .format_args = "t4T4",
+          .n_enum_strings = 2,
+          .enum_strings =
+          {
+            "barrier",
+            "mp-safe",
+          }
+        };
+      /* *INDENT-ON* */
 
-  return r;
+      struct
+      {
+	u32 barrier;
+	u32 c;
+      } *ed;
+      ed = ELOG_DATA (am->elog_main, e);
+      if (id < vec_len (am->msg_names))
+	ed->c = elog_string (am->elog_main, (char *) am->msg_names[id]);
+      else
+	ed->c = elog_string (am->elog_main, "BOGUS");
+      ed->barrier = !am->is_mp_safe[id];
+    }
 }
 
 /* This is only to be called from a vlib/vnet app */
@@ -471,7 +498,7 @@ vl_msg_api_handler_with_vm_node (api_main_t * am,
   u8 *(*print_fp) (void *, void *);
   int is_mp_safe = 1;
 
-  if (PREDICT_FALSE (vm->elog_trace_api_messages))
+  if (PREDICT_FALSE (am->elog_trace_api_messages))
     {
       /* *INDENT-OFF* */
       ELOG_TYPE_DECLARE (e) =
@@ -484,11 +511,11 @@ vl_msg_api_handler_with_vm_node (api_main_t * am,
       {
 	u32 c;
       } *ed;
-      ed = ELOG_DATA (&vm->elog_main, e);
+      ed = ELOG_DATA (am->elog_main, e);
       if (id < vec_len (am->msg_names))
-	ed->c = elog_id_for_msg_name (vm, (const char *) am->msg_names[id]);
+	ed->c = elog_string (am->elog_main, (char *) am->msg_names[id]);
       else
-	ed->c = elog_id_for_msg_name (vm, "BOGUS");
+	ed->c = elog_string (am->elog_main, "BOGUS");
     }
 
   if (id < vec_len (am->msg_handlers) && am->msg_handlers[id])
@@ -534,7 +561,7 @@ vl_msg_api_handler_with_vm_node (api_main_t * am,
   if (!(am->message_bounce[id]))
     vl_msg_api_free (the_msg);
 
-  if (PREDICT_FALSE (vm->elog_trace_api_messages))
+  if (PREDICT_FALSE (am->elog_trace_api_messages))
     {
       /* *INDENT-OFF* */
       ELOG_TYPE_DECLARE (e) =
@@ -555,11 +582,11 @@ vl_msg_api_handler_with_vm_node (api_main_t * am,
 	u32 barrier;
 	u32 c;
       } *ed;
-      ed = ELOG_DATA (&vm->elog_main, e);
+      ed = ELOG_DATA (am->elog_main, e);
       if (id < vec_len (am->msg_names))
-	ed->c = elog_id_for_msg_name (vm, (const char *) am->msg_names[id]);
+	ed->c = elog_string (am->elog_main, (char *) am->msg_names[id]);
       else
-	ed->c = elog_id_for_msg_name (vm, "BOGUS");
+	ed->c = elog_string (am->elog_main, "BOGUS");
       ed->barrier = is_mp_safe;
     }
 }
@@ -1033,6 +1060,32 @@ vl_api_from_api_to_vec (vl_api_string_t * astr)
   return v;
 }
 
+void
+vl_api_set_elog_main (elog_main_t * m)
+{
+  api_main_t *am = &api_main;
+  am->elog_main = m;
+}
+
+int
+vl_api_set_elog_trace_api_messages (int enable)
+{
+  int rv;
+  api_main_t *am = &api_main;
+
+  rv = am->elog_trace_api_messages;
+  am->elog_trace_api_messages = enable;
+  return rv;
+}
+
+int
+vl_api_get_elog_trace_api_messages (void)
+{
+  api_main_t *am = &api_main;
+
+  return am->elog_trace_api_messages;
+}
+
 /*
  * fd.io coding-style-patch-verification: ON
  *
diff --git a/src/vlibmemory/memory_shared.c b/src/vlibmemory/memory_shared.c
index fa9936982ee..f44ab7c4106 100644
--- a/src/vlibmemory/memory_shared.c
+++ b/src/vlibmemory/memory_shared.c
@@ -29,6 +29,7 @@
 #include <vppinfra/format.h>
 #include <vppinfra/byte_order.h>
 #include <vppinfra/error.h>
+#include <vppinfra/elog.h>
 #include <svm/queue.h>
 #include <vlib/vlib.h>
 #include <vlib/unix/unix.h>
@@ -764,7 +765,27 @@ vl_msg_api_send_shmem (svm_queue_t * q, u8 * elem)
    */
   if (PREDICT_FALSE
       (am->vl_clients /* vpp side */  && (q->cursize == q->maxsize)))
-    clib_warning ("WARNING: client input queue at %llx is stuffed...", q);
+    {
+      if (PREDICT_FALSE (am->elog_trace_api_messages))
+	{
+          /* *INDENT-OFF* */
+          ELOG_TYPE_DECLARE (e) =
+            {
+              .format = "api-client-queue-stuffed: %x%x",
+              .format_args = "i4i4",
+            };
+          /* *INDENT-ON* */
+	  struct
+	  {
+	    u32 hi, low;
+	  } *ed;
+	  ed = ELOG_DATA (am->elog_main, e);
+	  ed->hi = (uword) q >> 32;
+	  ed->low = (uword) q & 0xFFFFFFFF;
+	  clib_warning ("WARNING: client input queue at %llx is stuffed...",
+			q);
+	}
+    }
   (void) svm_queue_add (q, elem, 0 /* nowait */ );
 }