api: Implement log_dump/log_details

- Replaces the need to screen scrape "show log".
- Adds an api to return the system time.  When running over a socket, the
  api client may have different time than the vpp host.

expected use:
  vpp_time_before_command = self.vapi.show_vpe_system_time_ticks().vpe_system_time_ticks
  <run some commands>
  log_output = self.vapi.log_dump(start_timestamp=vpp_time_before_command)

Depends-on: https://gerrit.fd.io/r/20484
Depends-on: https://gerrit.fd.io/r/#/c/19581/

==============================================================================
TestVpeApi
==============================================================================
log_details(_0=838, context=3, timestamp_ticks=2.4954863503546518e+48, level=<vl_api_log_level_t.VPE_API_LOG_LEVEL_WARNING: 4>, timestamp=u'2019/07/04 20:35:41:281', msg_class=u'buffer', message=u'vlib_physmem_shared_map_create: clib_mem_create_hugetlb_fd: open: No such file or directory\n\n')
log_details(_0=838, context=3, timestamp_ticks=1.6101902879480125e+159, level=<vl_api_log_level_t.VPE_API_LOG_LEVEL_WARNING: 4>, timestamp=u'2019/07/04 20:35:41:281', msg_class=u'buffer', message=u'falling back to non-hugepage backed buffer pool')
test_log_dump_default (test_vpe_api.TestVpeApi)                          OK
log_details(_0=838, context=13, timestamp_ticks=2.4954863503546518e+48, level=<vl_api_log_level_t.VPE_API_LOG_LEVEL_WARNING: 4>, timestamp=u'2019/07/04 20:35:41:281', msg_class=u'buffer', message=u'vlib_physmem_shared_map_create: clib_mem_create_hugetlb_fd: open: No such file or directory\n\n')
log_details(_0=838, context=13, timestamp_ticks=1.6101902879480125e+159, level=<vl_api_log_level_t.VPE_API_LOG_LEVEL_WARNING: 4>, timestamp=u'2019/07/04 20:35:41:281', msg_class=u'buffer', message=u'falling back to non-hugepage backed buffer pool')
test_log_dump_timestamp_0 (test_vpe_api.TestVpeApi)                      OK
test_log_dump_timestamp_future (test_vpe_api.TestVpeApi)                 SKIP
test_show_vpe_system_time_ticks (test_vpe_api.TestVpeApi)                SKIP

==============================================================================
TEST RESULTS:
     Scheduled tests: 4
      Executed tests: 4
        Passed tests: 2
       Skipped tests: 2
==============================================================================

Test run was successful

Type: feature

Change-Id: I893fc0a65f39749d2091093c2c604659aadd8447
Signed-off-by: Paul Vinciguerra <pvinci@vinciconsulting.com>

src/vlib/log.c

@@ -18,57 +18,6 @@
 #include <vlib/log.h>
 #include <syslog.h>
 
-typedef struct
-{
-  vlib_log_level_t level;
-  vlib_log_class_t class;
-  f64 timestamp;
-  u8 *string;
-} vlib_log_entry_t;
-
-typedef struct
-{
-  u32 index;
-  u8 *name;
-  // level of log messages kept for this subclass
-  vlib_log_level_t level;
-  // level of log messages sent to syslog for this subclass
-  vlib_log_level_t syslog_level;
-  // flag saying whether this subclass is logged to syslog
-  f64 last_event_timestamp;
-  int last_sec_count;
-  int is_throttling;
-  int rate_limit;
-} vlib_log_subclass_data_t;
-
-typedef struct
-{
-  u32 index;
-  u8 *name;
-  vlib_log_subclass_data_t *subclasses;
-} vlib_log_class_data_t;
-
-typedef struct
-{
-  vlib_log_entry_t *entries;
-  vlib_log_class_data_t *classes;
-  int size, next, count;
-
-  /* our own log class */
-  vlib_log_class_t log_class;
-
-  int default_rate_limit;
-  int default_log_level;
-  int default_syslog_log_level;
-  int unthrottle_time;
-  u32 indent;
-
-  /* time zero */
-  struct timeval time_zero_timeval;
-  f64 time_zero;
-
-} vlib_log_main_t;
-
 vlib_log_main_t log_main = {
   .default_log_level = VLIB_LOG_LEVEL_NOTICE,
   .default_syslog_log_level = VLIB_LOG_LEVEL_WARNING,
@@ -77,7 +26,7 @@ vlib_log_main_t log_main = {
   .default_rate_limit = 50,
 };
 
-static int
+int
 last_log_entry ()
 {
   vlib_log_main_t *lm = &log_main;

src/vlib/log.h

@@ -36,11 +36,65 @@ typedef enum
 #undef _
 } vlib_log_level_t;
 
+typedef struct
+{
+  vlib_log_level_t level;
+  vlib_log_class_t class;
+  f64 timestamp;
+  u8 *string;
+} vlib_log_entry_t;
+
+typedef struct
+{
+  u32 index;
+  u8 *name;
+  // level of log messages kept for this subclass
+  vlib_log_level_t level;
+  // level of log messages sent to syslog for this subclass
+  vlib_log_level_t syslog_level;
+  // flag saying whether this subclass is logged to syslog
+  f64 last_event_timestamp;
+  int last_sec_count;
+  int is_throttling;
+  int rate_limit;
+} vlib_log_subclass_data_t;
+
+typedef struct
+{
+  u32 index;
+  u8 *name;
+  vlib_log_subclass_data_t *subclasses;
+} vlib_log_class_data_t;
+
+typedef struct
+{
+  vlib_log_entry_t *entries;
+  vlib_log_class_data_t *classes;
+  int size, next, count;
+
+  /* our own log class */
+  vlib_log_class_t log_class;
+
+  int default_rate_limit;
+  int default_log_level;
+  int default_syslog_log_level;
+  int unthrottle_time;
+  u32 indent;
+
+  /* time zero */
+  struct timeval time_zero_timeval;
+  f64 time_zero;
+
+} vlib_log_main_t;
+
+extern vlib_log_main_t log_main;
 
 vlib_log_class_t vlib_log_register_class (char *vlass, char *subclass);
 u32 vlib_log_get_indent ();
 void vlib_log (vlib_log_level_t level, vlib_log_class_t class, char *fmt,
 	       ...);
+int last_log_entry ();
+u8 *format_vlib_log_class (u8 * s, va_list * args);
 
 #define vlib_log_emerg(...) vlib_log(VLIB_LOG_LEVEL_EMERG, __VA_ARGS__)
 #define vlib_log_alert(...) vlib_log(VLIB_LOG_LEVEL_ALERT, __VA_ARGS__)

src/vpp/api/api.c

@@ -48,6 +48,7 @@
 #include <vnet/api_errno.h>
 #include <vnet/vnet.h>
 
+#include <vlib/log.h>
 #include <vlib/vlib.h>
 #include <vlib/unix/unix.h>
 #include <vlibapi/api.h>
@@ -84,6 +85,8 @@ _(SHOW_VERSION, show_version)						\
 _(SHOW_THREADS, show_threads)						                    \
 _(GET_NODE_GRAPH, get_node_graph)                                       \
 _(GET_NEXT_INDEX, get_next_index)                                       \
+_(LOG_DUMP, log_dump)                                                   \
+_(SHOW_VPE_SYSTEM_TIME_TICKS, show_vpe_system_time_ticks)
 
 #define QUOTE_(x) #x
 #define QUOTE(x) QUOTE_(x)
@@ -473,6 +476,85 @@ vl_api_get_node_graph_t_handler (vl_api_get_node_graph_t * mp)
   /* *INDENT-ON* */
 }
 
+static void
+show_log_details (vl_api_registration_t * reg, u32 context,
+		  f64 timestamp_ticks, u8 * timestamp,
+		  vl_api_log_level_t * level, u8 * msg_class, u8 * message)
+{
+  u32 msg_size;
+
+  vl_api_log_details_t *rmp;
+  msg_size =
+    sizeof (*rmp) + vec_len (timestamp) + vec_len (msg_class) +
+    vec_len (message);
+
+  rmp = vl_msg_api_alloc (msg_size);
+  clib_memset (rmp, 0, msg_size);
+  rmp->_vl_msg_id = ntohs (VL_API_LOG_DETAILS);
+
+  rmp->context = context;
+  rmp->timestamp_ticks = clib_host_to_net_f64 (timestamp_ticks);
+  rmp->level = htonl (*level);
+  char *p = (char *) &rmp->timestamp;
+
+  p += vl_api_vec_to_api_string (timestamp, (vl_api_string_t *) p);
+  p += vl_api_vec_to_api_string (msg_class, (vl_api_string_t *) p);
+  p += vl_api_vec_to_api_string (message, (vl_api_string_t *) p);
+
+  vl_api_send_msg (reg, (u8 *) rmp);
+}
+
+static void
+vl_api_log_dump_t_handler (vl_api_log_dump_t * mp)
+{
+
+  /* from log.c */
+  vlib_log_main_t *lm = &log_main;
+  vlib_log_entry_t *e;
+  int i = last_log_entry ();
+  int count = lm->count;
+  f64 time_offset, start_time;
+  vl_api_registration_t *reg;
+
+  reg = vl_api_client_index_to_registration (mp->client_index);
+  if (reg == 0)
+    return;
+
+  start_time = clib_net_to_host_f64 (mp->start_timestamp);
+
+  time_offset = (f64) lm->time_zero_timeval.tv_sec
+    + (((f64) lm->time_zero_timeval.tv_usec) * 1e-6) - lm->time_zero;
+
+  while (count--)
+    {
+      e = vec_elt_at_index (lm->entries, i);
+      if (start_time <= e->timestamp + time_offset)
+	show_log_details (reg, mp->context, e->timestamp + time_offset,
+			  format (0, "%U", format_time_float, 0,
+				  e->timestamp + time_offset),
+			  (vl_api_log_level_t *) & e->level,
+			  format (0, "%U", format_vlib_log_class, e->class),
+			  e->string);
+      i = (i + 1) % lm->size;
+    }
+
+}
+
+static void
+  vl_api_show_vpe_system_time_ticks_t_handler
+  (vl_api_show_vpe_system_time_ticks_t * mp)
+{
+  int rv = 0;
+  vl_api_show_vpe_system_time_ticks_reply_t *rmp;
+  /* *INDENT-OFF* */
+  REPLY_MACRO2(VL_API_SHOW_VPE_SYSTEM_TIME_TICKS_REPLY,
+  ({
+    rmp->vpe_system_time_ticks = clib_host_to_net_f64 (unix_time_now ());
+  }));
+  /* *INDENT-ON* */
+}
+
+
 #define BOUNCE_HANDLER(nn)                                              \
 static void vl_api_##nn##_t_handler (                                   \
     vl_api_##nn##_t *mp)                                                \
@@ -531,8 +613,8 @@ vpe_api_hookup (vlib_main_t * vm)
    * Trace space for classifier mask+match
    */
   am->api_trace_cfg[VL_API_CLASSIFY_ADD_DEL_TABLE].size += 5 * sizeof (u32x4);
-  am->api_trace_cfg[VL_API_CLASSIFY_ADD_DEL_SESSION].size
+  am->api_trace_cfg[VL_API_CLASSIFY_ADD_DEL_SESSION].size +=
-    += 5 * sizeof (u32x4);
+    5 * sizeof (u32x4);
 
   /*
    * Thread-safe API messages
@@ -653,7 +735,8 @@ api_segment_config (vlib_main_t * vm, unformat_input_t * input)
 	  /* lookup the group name */
 	  grp = NULL;
 	  while (((rv =
-		   getgrnam_r (s, &_grp, buf, vec_len (buf), &grp)) == ERANGE)
+		   getgrnam_r (s, &_grp, buf, vec_len (buf),
+			       &grp)) == ERANGE)
 		 && (vec_len (buf) <= max_buf_size))
 	    {
 	      vec_resize (buf, vec_len (buf) * 2);

src/vpp/api/vpe.api

@@ -19,7 +19,7 @@
     called through a shared memory interface. 
 */
 
-option version = "1.1.0";
+option version = "1.3.0";
 
 /* 
  * Note: API placement cleanup in progress
@@ -283,6 +283,55 @@ define get_next_index_reply
   u32 next_index;
 };
 
+enum log_level {
+  VPE_API_LOG_LEVEL_EMERG = 0,    /* emerg */
+  VPE_API_LOG_LEVEL_ALERT = 1,    /* alert */
+  VPE_API_LOG_LEVEL_CRIT = 2,     /* crit */
+  VPE_API_LOG_LEVEL_ERR = 3,      /* err  */
+  VPE_API_LOG_LEVEL_WARNING = 4,  /* warn */
+  VPE_API_LOG_LEVEL_NOTICE = 5,   /* notice */
+  VPE_API_LOG_LEVEL_INFO = 6,     /* info */
+  VPE_API_LOG_LEVEL_DEBUG = 7,    /* debug */
+  VPE_API_LOG_LEVEL_DISABLED = 8, /* disabled */
+};
+
+define log_dump {
+  u32 client_index;
+  u32 context;
+  f64 start_timestamp;
+};
+
+define log_details {
+  u32 context;
+  f64 timestamp_ticks;
+  vl_api_log_level_t level;
+  string timestamp [limit=24];
+  string msg_class [limit=32];
+  string message [limit=256];
+};
+
+/** \brief Show the current system timestamp.
+    @param client_index - opaque cookie to identify the sender
+    @param context - sender context, to match reply w/ request
+*/
+define show_vpe_system_time_ticks
+{
+  u32 client_index;
+  u32 context;
+};
+
+/** \brief Reply for show vpe system time ticks.
+    @param context - sender context which was passed in the request
+    @param retval - return value
+    @param vpe_system_time_ticks - the time in ticks of the host system.
+*/
+define show_vpe_system_time_ticks_reply
+{
+  u32 context;
+  i32 retval;
+  f64 vpe_system_time_ticks;
+};
+
 /*
  * Local Variables:
  * eval: (c-set-style "gnu")

test/test_vpe_api.py

@@ -0,0 +1,46 @@
+#  Copyright (c) 2019. Vinci Consulting Corp. All Rights Reserved.
+#
+#  Licensed under the Apache License, Version 2.0 (the "License");
+#  you may not use this file except in compliance with the License.
+#  You may obtain a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+#  Unless required by applicable law or agreed to in writing, software
+#  distributed under the License is distributed on an "AS IS" BASIS,
+#  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+#  See the License for the specific language governing permissions and
+#  limitations under the License.
+import time
+import unittest
+from framework import VppTestCase
+
+
+class TestVpeApi(VppTestCase):
+    """TestVpeApi"""
+
+    def test_log_dump_default(self):
+        rv = self.vapi.cli('test log notice fib entry this is a test')
+        rv = self.vapi.log_dump()
+        # print('\n'.join([str(v) for v in rv]))
+        self.assertTrue(rv)
+
+    def test_log_dump_timestamp_0(self):
+        rv = self.vapi.cli('test log notice fib entry this is a test')
+        rv = self.vapi.log_dump(start_timestamp=0.0)
+        # print('\n'.join([str(v) for v in rv]))
+        self.assertTrue(rv)
+
+    @unittest.skip('Requires https://gerrit.fd.io/r/#/c/19581/ '
+                   'to use timestamp_ticks.')
+    def test_log_dump_timestamp_future(self):
+        rv = self.vapi.cli('test log debug fib entry test')
+        rv = self.vapi.log_dump(start_timestamp=time.time() + 60.0)
+        # print('\n'.join([str(v) for v in rv]))
+        self.assertFalse(rv)
+
+    @unittest.skip('Requires https://gerrit.fd.io/r/#/c/19581/ '
+                   'to use timestamp_ticks.')
+    def test_show_vpe_system_time_ticks(self):
+        rv = self.vapi.show_vpe_system_time_ticks()
+        self.assertTrue(rv.vpe_system_time_ticks > 1.0)