diff options
| -rw-r--r-- | src/vlib/log.c | 53 | ||||
| -rw-r--r-- | src/vlib/log.h | 54 | ||||
| -rw-r--r-- | src/vpp/api/api.c | 97 | ||||
| -rw-r--r-- | src/vpp/api/vpe.api | 51 | ||||
| -rw-r--r-- | test/test_vpe_api.py | 46 |
5 files changed, 241 insertions, 60 deletions
diff --git a/src/vlib/log.c b/src/vlib/log.c index 9a0d75fe3ac..578fc942604 100644 --- a/src/vlib/log.c +++ b/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; diff --git a/src/vlib/log.h b/src/vlib/log.h index 9b285429b9a..663d7fe86ed 100644 --- a/src/vlib/log.h +++ b/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__) diff --git a/src/vpp/api/api.c b/src/vpp/api/api.c index c21d562d8f3..66857fbac9f 100644 --- a/src/vpp/api/api.c +++ b/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> @@ -77,13 +78,15 @@ #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) @@ -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 - += 5 * sizeof (u32x4); + am->api_trace_cfg[VL_API_CLASSIFY_ADD_DEL_SESSION].size += + 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); diff --git a/src/vpp/api/vpe.api b/src/vpp/api/vpe.api index 735b31d3faa..bd6b9d5638f 100644 --- a/src/vpp/api/vpe.api +++ b/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") diff --git a/test/test_vpe_api.py b/test/test_vpe_api.py new file mode 100644 index 00000000000..81c9d9a78a6 --- /dev/null +++ b/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) |