- 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>
#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,
.default_rate_limit = 50,
};
-static int
+int
last_log_entry ()
{
vlib_log_main_t *lm = &log_main;
#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__)
#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>
#define foreach_vpe_api_msg \
_(CONTROL_PING, control_ping) \
_(CLI, cli) \
-_(CLI_INBAND, cli_inband) \
+_(CLI_INBAND, cli_inband) \
_(GET_NODE_INDEX, get_node_index) \
-_(ADD_NODE_NEXT, add_node_next) \
-_(SHOW_VERSION, show_version) \
-_(SHOW_THREADS, show_threads) \
+_(ADD_NODE_NEXT, add_node_next) \
+_(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)
/* *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) \
* 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
- += 5 * sizeof (u32x4);
+ am->api_trace_cfg[VL_API_CLASSIFY_ADD_DEL_SESSION].size +=
+ 5 * sizeof (u32x4);
/*
* Thread-safe API messages
/* 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);
called through a shared memory interface.
*/
-option version = "1.1.0";
+option version = "1.3.0";
/*
* Note: API placement cleanup in progress
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")
--- /dev/null
+# 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)
Code Review / vpp.git / commitdiff