diff options
Diffstat (limited to 'src')
| -rw-r--r-- | src/vlib.am | 2 | ||||
| -rw-r--r-- | src/vlib/log.c | 673 | ||||
| -rw-r--r-- | src/vlib/log.h | 63 | ||||
| -rw-r--r-- | src/vlib/vlib.h | 1 | ||||
| -rw-r--r-- | src/vnet/bfd/bfd_main.c | 118 | ||||
| -rw-r--r-- | src/vnet/bfd/bfd_main.h | 7 | ||||
| -rw-r--r-- | src/vnet/bfd/bfd_udp.c | 51 | ||||
| -rw-r--r-- | src/vnet/devices/tap/tap.c | 9 | ||||
| -rw-r--r-- | src/vnet/devices/tap/tap.h | 3 |
9 files changed, 875 insertions, 52 deletions
diff --git a/src/vlib.am b/src/vlib.am index 405bed95fba..55d6e65c2b9 100644 --- a/src/vlib.am +++ b/src/vlib.am @@ -35,6 +35,7 @@ libvlib_la_SOURCES = \ vlib/linux/pci.c \ vlib/linux/physmem.c \ vlib/linux/vfio.c \ + vlib/log.c \ vlib/main.c \ vlib/mc.c \ vlib/node.c \ @@ -61,6 +62,7 @@ nobase_include_HEADERS += \ vlib/i2c.h \ vlib/init.h \ vlib/linux/vfio.h \ + vlib/log.h \ vlib/main.h \ vlib/mc.h \ vlib/node_funcs.h \ diff --git a/src/vlib/log.c b/src/vlib/log.c new file mode 100644 index 00000000000..dd2ecf2c110 --- /dev/null +++ b/src/vlib/log.c @@ -0,0 +1,673 @@ +/* + * Copyright (c) 2018 Cisco and/or its affiliates. + * 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. + */ + +#include <stdbool.h> +#include <vlib/vlib.h> +#include <vlib/log.h> +#include <syslog.h> + +#define VLIB_LOG_DEFAULT_SIZE 50 +#define VLIB_LOG_DEFAULT_RATE_LIMIT 10 +#define VLIB_LOG_DEFAULT_UNTHROTTLE_TIME 3 +#define VLIB_LOG_DEFAULT_LOG_LEVEL VLIB_LOG_LEVEL_CRIT + +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 + bool syslog_enabled; + 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 unthrottle_time; + u32 indent; +} vlib_log_main_t; + +vlib_log_main_t log_main; + + +static int +last_log_entry () +{ + vlib_log_main_t *lm = &log_main; + int i; + + i = lm->next - lm->count; + + if (i < 0) + i += lm->size; + return i; +} + +static vlib_log_class_data_t * +get_class_data (vlib_log_class_t ci) +{ + vlib_log_main_t *lm = &log_main; + return vec_elt_at_index (lm->classes, (ci >> 16)); +} + +static vlib_log_subclass_data_t * +get_subclass_data (vlib_log_class_t ci) +{ + vlib_log_class_data_t *c = get_class_data (ci); + return vec_elt_at_index (c->subclasses, (ci & 0xffff)); +} + +static int +vlib_log_level_to_syslog_priority (vlib_log_level_t level) +{ + switch (level) + { +#define _(n,uc,lc) \ + case VLIB_LOG_LEVEL_##uc:\ + return LOG_##uc; + foreach_vlib_log_level +#undef _ + } + return LOG_DEBUG; +} + +u8 * +format_vlib_log_class (u8 * s, va_list * args) +{ + vlib_log_class_t ci = va_arg (*args, vlib_log_class_t); + vlib_log_class_data_t *c = get_class_data (ci); + vlib_log_subclass_data_t *sc = get_subclass_data (ci); + + if (sc->name) + return format (s, "%v/%v", c->name, sc->name); + else + return format (s, "%v", c->name, 0); +} + + +void +vlib_log (vlib_log_level_t level, vlib_log_class_t class, char *fmt, ...) +{ + vlib_main_t *vm = vlib_get_main (); + vlib_log_main_t *lm = &log_main; + vlib_log_entry_t *e; + vlib_log_subclass_data_t *sc = get_subclass_data (class); + va_list va; + f64 t = vlib_time_now (vm); + f64 delta = t - sc->last_event_timestamp; + u8 *s = 0; + bool use_formatted_log_entry = true; + + /* make sure we are running on the main thread to avoid use in dataplane + code, for dataplane logging consider use of event-logger */ + ASSERT (vlib_get_thread_index () == 0); + + if (level > sc->level) + { + use_formatted_log_entry = false; + goto syslog; + } + + if ((delta > lm->unthrottle_time) || + (sc->is_throttling == 0 && (delta > 1))) + { + sc->last_event_timestamp = t; + sc->last_sec_count = 0; + sc->is_throttling = 0; + } + else + { + sc->last_sec_count++; + if (sc->last_sec_count > sc->rate_limit) + return; + else if (sc->last_sec_count == sc->rate_limit) + { + vec_reset_length (s); + s = format (0, "--- message(s) throttled ---"); + sc->is_throttling = 1; + } + } + + if (s == 0) + { + va_start (va, fmt); + s = va_format (s, fmt, &va); + va_end (va); + } + + e = vec_elt_at_index (lm->entries, lm->next); + vec_free (e->string); + e->level = level; + e->class = class; + e->string = s; + e->timestamp = t; + + lm->next = (lm->next + 1) % lm->size; + if (lm->size > lm->count) + lm->count++; + +syslog: + if (sc->syslog_enabled && level <= sc->syslog_level) + { + u8 *tmp = format (NULL, "%U", format_vlib_log_class, class); + if (use_formatted_log_entry) + { + syslog (vlib_log_level_to_syslog_priority (level), "%.*s: %.*s", + vec_len (tmp), tmp, + vec_len (s) - (vec_c_string_is_terminated (s) ? 1 : 0), s); + } + else + { + tmp = format (tmp, ": "); + va_start (va, fmt); + tmp = va_format (tmp, fmt, &va); + va_end (va); + syslog (vlib_log_level_to_syslog_priority (level), "%.*s", + vec_len (tmp) - (vec_c_string_is_terminated (tmp) ? 1 : 0), + tmp); + } + vec_free (tmp); + } + +} + +vlib_log_class_t +vlib_log_register_class (char *class, char *subclass) +{ + vlib_log_main_t *lm = &log_main; + vlib_log_class_data_t *c = NULL; + vlib_log_subclass_data_t *s; + vlib_log_class_data_t *tmp; + vec_foreach (tmp, lm->classes) + { + if (!memcmp (class, tmp->name, vec_len (tmp->name))) + { + c = tmp; + break; + } + } + if (!c) + { + vec_add2 (lm->classes, c, 1); + c->index = c - lm->classes; + c->name = format (0, "%s", class); + } + + vec_add2 (c->subclasses, s, 1); + s->index = s - c->subclasses; + s->name = subclass ? format (0, "%s", subclass) : 0; + s->rate_limit = lm->default_rate_limit; + s->level = VLIB_LOG_DEFAULT_LOG_LEVEL; + return (c->index << 16) | (s->index); +} + +u8 * +format_vlib_log_level (u8 * s, va_list * args) +{ + vlib_log_level_t i = va_arg (*args, vlib_log_level_t); + char *t = 0; + + switch (i) + { +#define _(v,uc,lc) case VLIB_LOG_LEVEL_##uc: t = #lc; break; + foreach_vlib_log_level +#undef _ + default: + return format (s, "unknown"); + } + return format (s, "%s", t); +} + +u32 +vlib_log_get_indent () +{ + return log_main.indent; +} + +static clib_error_t * +vlib_log_init (vlib_main_t * vm) +{ + vlib_log_main_t *lm = &log_main; + lm->size = VLIB_LOG_DEFAULT_SIZE; + vec_validate (lm->entries, lm->size); + lm->log_class = vlib_log_register_class ("log", 0); + u8 *tmp = format (NULL, "%U %-10U %-10U ", format_time_float, 0, (f64) 0, + format_white_space, 255, format_white_space, 255); + log_main.indent = vec_len (tmp); + vec_free (tmp); + return 0; +} + +VLIB_INIT_FUNCTION (vlib_log_init); + + +static clib_error_t * +show_log (vlib_main_t * vm, + unformat_input_t * input, vlib_cli_command_t * cmd) +{ + clib_error_t *error = 0; + vlib_log_main_t *lm = &log_main; + vlib_log_entry_t *e; + int i = last_log_entry (); + int count = lm->count; + + while (count--) + { + e = vec_elt_at_index (lm->entries, i); + vlib_cli_output (vm, "%U %-10U %-10U %v (%d)", + format_time_float, 0, e->timestamp, + format_vlib_log_level, e->level, + format_vlib_log_class, e->class, e->string, i); + i = (i + 1) % lm->size; + } + + return error; +} + +/* *INDENT-OFF* */ +VLIB_CLI_COMMAND (cli_show_log, static) = { + .path = "show logging", + .short_help = "show logging", + .function = show_log, +}; +/* *INDENT-ON* */ + +static clib_error_t * +clear_log (vlib_main_t * vm, + unformat_input_t * input, vlib_cli_command_t * cmd) +{ + clib_error_t *error = 0; + vlib_log_main_t *lm = &log_main; + vlib_log_entry_t *e; + int i = last_log_entry (); + int count = lm->count; + + while (count--) + { + e = vec_elt_at_index (lm->entries, i); + vec_free (e->string); + i = (i + 1) % lm->size; + } + + lm->count = 0; + lm->next = 0; + vlib_log_info (lm->log_class, "log cleared"); + return error; +} + +/* *INDENT-OFF* */ +VLIB_CLI_COMMAND (cli_clear_log, static) = { + .path = "clear logging", + .short_help = "clear logging", + .function = clear_log, +}; +/* *INDENT-ON* */ + +static uword +unformat_vlib_log_level (unformat_input_t * input, va_list * args) +{ + vlib_log_level_t *level = va_arg (*args, vlib_log_level_t *); + u8 *level_str = NULL; + uword rv = 1; + if (unformat (input, "%v", &level_str)) + { +#define _(v, uc, lc) \ + const char __##uc[] = #lc; \ + if (!memcmp (level_str, __##uc, sizeof (__##uc))) \ + { \ + *level = VLIB_LOG_LEVEL_##uc; \ + rv = 1; \ + goto done; \ + } + foreach_vlib_log_level; + rv = 0; +#undef _ + } +done: + vec_free (level_str); + return rv; +} + +static uword +unformat_vlib_log_class (unformat_input_t * input, va_list * args) +{ + vlib_log_class_data_t **class = va_arg (*args, vlib_log_class_data_t **); + uword rv = 0; + u8 *class_str = NULL; + vlib_log_main_t *lm = &log_main; + if (unformat (input, "%v", &class_str)) + { + vlib_log_class_data_t *cdata; + vec_foreach (cdata, lm->classes) + { + if (vec_is_equal (cdata->name, class_str)) + { + *class = cdata; + rv = 1; + break; + } + } + } + vec_free (class_str); + return rv; +} + +static clib_error_t * +set_log_class (vlib_main_t * vm, + unformat_input_t * input, vlib_cli_command_t * cmd) +{ + unformat_input_t _line_input, *line_input = &_line_input; + clib_error_t *rv = NULL; + int rate_limit; + bool set_rate_limit = false; + bool set_level = false; + bool set_syslog_level = false; + vlib_log_level_t level; + vlib_log_level_t syslog_level; + + /* Get a line of input. */ + if (!unformat_user (input, unformat_line_input, line_input)) + return 0; + + vlib_log_class_data_t *class = NULL; + if (!unformat (line_input, "%U", unformat_vlib_log_class, &class)) + { + return clib_error_return (0, "unknown log class `%U'", + format_unformat_error, line_input); + } + while (unformat_check_input (line_input) != UNFORMAT_END_OF_INPUT) + { + if (unformat (line_input, "rate-limit %d", &rate_limit)) + { + set_rate_limit = true; + } + else + if (unformat + (line_input, "level %U", unformat_vlib_log_level, &level)) + { + set_level = true; + } + else + if (unformat + (line_input, "syslog-level %U", unformat_vlib_log_level, + &syslog_level)) + { + set_syslog_level = true; + } + else + { + return clib_error_return (0, "unknown input `%U'", + format_unformat_error, line_input); + } + } + + if (set_level) + { + vlib_log_subclass_data_t *subclass; + vec_foreach (subclass, class->subclasses) + { + subclass->level = level; + } + } + if (set_syslog_level) + { + vlib_log_subclass_data_t *subclass; + vec_foreach (subclass, class->subclasses) + { + subclass->syslog_level = syslog_level; + subclass->syslog_enabled = true; + } + } + else + { + vlib_log_subclass_data_t *subclass; + vec_foreach (subclass, class->subclasses) + { + subclass->syslog_enabled = false; + } + } + if (set_rate_limit) + { + vlib_log_subclass_data_t *subclass; + vec_foreach (subclass, class->subclasses) + { + subclass->rate_limit = rate_limit; + } + } + + return rv; +} + +/* *INDENT-OFF* */ +VLIB_CLI_COMMAND (cli_set_log, static) = { + .path = "set logging class", + .short_help = "set loggging class <class> [rate-limit <int>] " + "[level <level>] [syslog-level <level>]", + .function = set_log_class, +}; +/* *INDENT-ON* */ + +static clib_error_t * +set_log_unth_time (vlib_main_t * vm, + unformat_input_t * input, vlib_cli_command_t * cmd) +{ + unformat_input_t _line_input, *line_input = &_line_input; + clib_error_t *rv = NULL; + int unthrottle_time; + vlib_log_main_t *lm = &log_main; + + /* Get a line of input. */ + if (!unformat_user (input, unformat_line_input, line_input)) + return 0; + + while (unformat_check_input (line_input) != UNFORMAT_END_OF_INPUT) + { + if (unformat (line_input, "%d", &unthrottle_time)) + lm->unthrottle_time = unthrottle_time; + else + return clib_error_return (0, "unknown input `%U'", + format_unformat_error, line_input); + } + + return rv; +} + +/* *INDENT-OFF* */ +VLIB_CLI_COMMAND (cli_set_log_params, static) = { + .path = "set logging unthrottle-time", + .short_help = "set logging unthrottle-time <int>", + .function = set_log_unth_time, +}; +/* *INDENT-ON* */ + +static clib_error_t * +set_log_size (vlib_main_t * vm, + unformat_input_t * input, vlib_cli_command_t * cmd) +{ + unformat_input_t _line_input, *line_input = &_line_input; + clib_error_t *rv = NULL; + int size; + vlib_log_main_t *lm = &log_main; + + /* Get a line of input. */ + if (!unformat_user (input, unformat_line_input, line_input)) + return 0; + + while (unformat_check_input (line_input) != UNFORMAT_END_OF_INPUT) + { + if (unformat (line_input, "%d", &size)) + { + lm->size = size; + vec_validate (lm->entries, lm->size); + } + else + return clib_error_return (0, "unknown input `%U'", + format_unformat_error, line_input); + } + + return rv; +} + +/* *INDENT-OFF* */ +VLIB_CLI_COMMAND (cli_set_log_size, static) = { + .path = "set logging size", + .short_help = "set logging size <int>", + .function = set_log_size, +}; +/* *INDENT-ON* */ + +static uword +unformat_vlib_log_subclass (unformat_input_t * input, va_list * args) +{ + vlib_log_class_data_t *class = va_arg (*args, vlib_log_class_data_t *); + vlib_log_subclass_data_t **subclass = + va_arg (*args, vlib_log_subclass_data_t **); + uword rv = 0; + u8 *subclass_str = NULL; + if (unformat (input, "%v", &subclass_str)) + { + vlib_log_subclass_data_t *scdata; + vec_foreach (scdata, class->subclasses) + { + if (vec_is_equal (scdata->name, subclass_str)) + { + rv = 1; + *subclass = scdata; + break; + } + } + } + vec_free (subclass_str); + return rv; +} + +static clib_error_t * +test_log_class_subclass (vlib_main_t * vm, + unformat_input_t * input, vlib_cli_command_t * cmd) +{ + unformat_input_t _line_input, *line_input = &_line_input; + /* Get a line of input. */ + if (!unformat_user (input, unformat_line_input, line_input)) + return 0; + + vlib_log_class_data_t *class = NULL; + vlib_log_subclass_data_t *subclass = NULL; + vlib_log_level_t level; + if (unformat (line_input, "%U", unformat_vlib_log_level, &level)) + { + if (unformat (line_input, "%U", unformat_vlib_log_class, &class)) + { + if (unformat + (line_input, "%U", unformat_vlib_log_subclass, class, + &subclass)) + { + vlib_log (level, + (class->index << 16) | (subclass->index), "%U", + format_unformat_input, line_input); + } + else + { + return clib_error_return (0, + "unknown log subclass near beginning of `%U'", + format_unformat_error, line_input); + } + } + else + { + return clib_error_return (0, + "unknown log class near beginning of `%U'", + format_unformat_error, line_input); + } + } + else + { + return clib_error_return (0, "unknown log level near beginning of `%U'", + format_unformat_error, line_input); + } + return 0; +} + +/* *INDENT-OFF* */ +VLIB_CLI_COMMAND (cli_test_log, static) = { + .path = "test log", + .short_help = "test log <class> <subclass> <level> <message", + .function = test_log_class_subclass, +}; +/* *INDENT-ON* */ + +static clib_error_t * +log_config (vlib_main_t * vm, unformat_input_t * input) +{ + vlib_log_main_t *lm = &log_main; + int size; + + while (unformat_check_input (input) != UNFORMAT_END_OF_INPUT) + { + if (unformat (input, "size %d", &size)) + { + lm->size = size; + vec_validate (lm->entries, lm->size); + } + else if (unformat (input, "unthrottle-time %d", &lm->unthrottle_time)) + { + // nothing to do here + } + else + { + return unformat_parse_error (input); + } + } + + return 0; +} + +VLIB_EARLY_CONFIG_FUNCTION (log_config, "logging"); + +/* + * fd.io coding-style-patch-verification: ON + * + * Local Variables: + * eval: (c-set-style "gnu") + * End: + */ diff --git a/src/vlib/log.h b/src/vlib/log.h new file mode 100644 index 00000000000..90862dcc9ec --- /dev/null +++ b/src/vlib/log.h @@ -0,0 +1,63 @@ +/* + * Copyright (c) 2018 Cisco and/or its affiliates. + * 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. + */ + +#ifndef included_vlib_log_h +#define included_vlib_log_h + +#include <vppinfra/types.h> + +typedef u32 vlib_log_class_t; + +#define foreach_vlib_log_level \ + _(0, EMERG, emerg) \ + _(1, ALERT, alert) \ + _(2, CRIT, crit) \ + _(3, ERR, err) \ + _(4, WARNING, warn) \ + _(5, NOTICE, notice) \ + _(6, INFO, info) \ + _(7, DEBUG, debug) + +typedef enum +{ +#define _(n,uc,lc) VLIB_LOG_LEVEL_##uc = n, + foreach_vlib_log_level +#undef _ +} vlib_log_level_t; + + +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, + ...); + +#define vlib_log_emerg(...) vlib_log(VLIB_LOG_LEVEL_EMERG, __VA_ARGS__) +#define vlib_log_alert(...) vlib_log(VLIB_LOG_LEVEL_ALERT, __VA_ARGS__) +#define vlib_log_crit(...) vlib_log(VLIB_LOG_LEVEL_CRIT, __VA_ARGS__) +#define vlib_log_err(...) vlib_log(VLIB_LOG_LEVEL_ERR, __VA_ARGS__) +#define vlib_log_warn(...) vlib_log(VLIB_LOG_LEVEL_WARN, __VA_ARGS__) +#define vlib_log_notice(...) vlib_log(VLIB_LOG_LEVEL_NOTICE, __VA_ARGS__) +#define vlib_log_info(...) vlib_log(VLIB_LOG_LEVEL_INFO, __VA_ARGS__) +#define vlib_log_debug(...) vlib_log(VLIB_LOG_LEVEL_DEBUG, __VA_ARGS__) + +#endif /* included_vlib_log_h */ + +/* + * fd.io coding-style-patch-verification: ON + * + * Local Variables: + * eval: (c-set-style "gnu") + * End: + */ diff --git a/src/vlib/vlib.h b/src/vlib/vlib.h index eed5c5bc243..21c5b2aa814 100644 --- a/src/vlib/vlib.h +++ b/src/vlib/vlib.h @@ -59,6 +59,7 @@ struct vlib_main_t; #include <vlib/mc.h> #include <vlib/node.h> #include <vlib/trace.h> +#include <vlib/log.h> /* Main include depends on other vlib/ includes so we put it last. */ #include <vlib/main.h> diff --git a/src/vnet/bfd/bfd_main.c b/src/vnet/bfd/bfd_main.c index 668a44e89e5..28ece316438 100644 --- a/src/vnet/bfd/bfd_main.c +++ b/src/vnet/bfd/bfd_main.c @@ -34,6 +34,7 @@ #include <vnet/bfd/bfd_debug.h> #include <vnet/bfd/bfd_protocol.h> #include <vnet/bfd/bfd_main.h> +#include <vlib/log.h> static u64 bfd_calc_echo_checksum (u32 discriminator, u64 expire_time, u32 secret) @@ -403,6 +404,8 @@ void bfd_session_start (bfd_main_t * bm, bfd_session_t * bs) { BFD_DBG ("\nStarting session: %U", format_bfd_session, bs); + vlib_log_info (bm->log_class, "start BFD session: %U", + format_bfd_session_brief, bs); bfd_set_effective_required_min_rx (bm, bs, bs->config_required_min_rx_clocks); bfd_recalc_tx_interval (bm, bs); @@ -419,6 +422,8 @@ bfd_session_set_flags (bfd_session_t * bs, u8 admin_up_down) if (admin_up_down) { BFD_DBG ("Session set admin-up, bs-idx=%u", bs->bs_idx); + vlib_log_info (bm->log_class, "set session admin-up: %U", + format_bfd_session_brief, bs); bfd_set_state (bm, bs, BFD_STATE_down, 0); bfd_set_diag (bs, BFD_DIAG_CODE_no_diag); bfd_calc_next_tx (bm, bs, now); @@ -427,6 +432,8 @@ bfd_session_set_flags (bfd_session_t * bs, u8 admin_up_down) else { BFD_DBG ("Session set admin-down, bs-idx=%u", bs->bs_idx); + vlib_log_info (bm->log_class, "set session admin-down: %U", + format_bfd_session_brief, bs); bfd_set_diag (bs, BFD_DIAG_CODE_admin_down); bfd_set_state (bm, bs, BFD_STATE_admin_down, 0); bfd_calc_next_tx (bm, bs, now); @@ -668,6 +675,7 @@ bfd_add_sha1_auth_section (vlib_buffer_t * b, bfd_session_t * bs) static void bfd_add_auth_section (vlib_buffer_t * b, bfd_session_t * bs) { + bfd_main_t *bm = &bfd_main; if (bs->auth.curr_key) { const bfd_auth_type_e auth_type = bs->auth.curr_key->auth_type; @@ -680,8 +688,9 @@ bfd_add_auth_section (vlib_buffer_t * b, bfd_session_t * bs) case BFD_AUTH_TYPE_keyed_md5: /* fallthrough */ case BFD_AUTH_TYPE_meticulous_keyed_md5: - clib_warning ("Internal error, unexpected BFD auth type '%d'", - auth_type); + vlib_log_crit (bm->log_class, + "internal error, unexpected BFD auth type '%d'", + auth_type); break; #if WITH_LIBSSL > 0 case BFD_AUTH_TYPE_keyed_sha1: @@ -693,8 +702,9 @@ bfd_add_auth_section (vlib_buffer_t * b, bfd_session_t * bs) case BFD_AUTH_TYPE_keyed_sha1: /* fallthrough */ case BFD_AUTH_TYPE_meticulous_keyed_sha1: - clib_warning ("Internal error, unexpected BFD auth type '%d'", - auth_type); + vlib_log_crit (bm->log_class, + "internal error, unexpected BFD auth type '%d'", + auth_type); break; #endif } @@ -768,7 +778,7 @@ bfd_send_echo (vlib_main_t * vm, vlib_node_runtime_t * rt, u32 bi; if (vlib_buffer_alloc (vm, &bi, 1) != 1) { - clib_warning ("buffer allocation failure"); + vlib_log_crit (bm->log_class, "buffer allocation failure"); return; } vlib_buffer_t *b = vlib_get_buffer (vm, bi); @@ -842,7 +852,7 @@ bfd_send_periodic (vlib_main_t * vm, vlib_node_runtime_t * rt, u32 bi; if (vlib_buffer_alloc (vm, &bi, 1) != 1) { - clib_warning ("buffer allocation failure"); + vlib_log_crit (bm->log_class, "buffer allocation failure"); return; } vlib_buffer_t *b = vlib_get_buffer (vm, bi); @@ -1063,7 +1073,7 @@ bfd_process (vlib_main_t * vm, vlib_node_runtime_t * rt, vlib_frame_t * f) } break; default: - clib_warning ("BUG: event type 0x%wx", event_type); + vlib_log_err (bm->log_class, "BUG: event type 0x%wx", event_type); break; } BFD_DBG ("advancing wheel, now is %lu", now); @@ -1166,6 +1176,8 @@ bfd_main_init (vlib_main_t * vm) const u64 now = clib_cpu_time_now (); timing_wheel_init (&bm->wheel, now, bm->cpu_cps); bm->wheel_inaccuracy = 2 << bm->wheel.log2_clocks_per_bin; + bm->log_class = vlib_log_register_class ("bfd", 0); + vlib_log_debug (bm->log_class, "initialized"); return 0; } @@ -1186,8 +1198,9 @@ bfd_get_session (bfd_main_t * bm, bfd_transport_e t) result->local_discr = random_u32 (&bm->random_seed); if (counter > limit) { - clib_warning ("Couldn't allocate unused session discriminator even " - "after %u tries!", limit); + vlib_log_crit (bm->log_class, + "couldn't allocate unused session discriminator even " + "after %u tries!", limit); pool_put (bm->sessions, result); return NULL; } @@ -1202,6 +1215,8 @@ bfd_get_session (bfd_main_t * bm, bfd_transport_e t) void bfd_put_session (bfd_main_t * bm, bfd_session_t * bs) { + vlib_log_info (bm->log_class, "delete session: %U", + format_bfd_session_brief, bs); bfd_notify_listeners (bm, BFD_LISTEN_EVENT_DELETE, bs); if (bs->auth.curr_key) { @@ -1468,23 +1483,27 @@ bfd_verify_pkt_auth_key (const bfd_pkt_t * pkt, u32 pkt_size, bfd_session_t * bs, u8 bfd_key_id, bfd_auth_key_t * auth_key) { + bfd_main_t *bm = &bfd_main; switch (auth_key->auth_type) { case BFD_AUTH_TYPE_reserved: - clib_warning ("Internal error, unexpected auth_type=%d:%s", + vlib_log_err (bm->log_class, + "internal error, unexpected auth_type=%d:%s", auth_key->auth_type, bfd_auth_type_str (auth_key->auth_type)); return 0; case BFD_AUTH_TYPE_simple_password: - clib_warning - ("Internal error, not implemented, unexpected auth_type=%d:%s", - auth_key->auth_type, bfd_auth_type_str (auth_key->auth_type)); + vlib_log_err (bm->log_class, + "internal error, not implemented, unexpected auth_type=%d:%s", + auth_key->auth_type, + bfd_auth_type_str (auth_key->auth_type)); return 0; case BFD_AUTH_TYPE_keyed_md5: /* fallthrough */ case BFD_AUTH_TYPE_meticulous_keyed_md5: - clib_warning - ("Internal error, not implemented, unexpected auth_type=%d:%s", + vlib_log_err + (bm->log_class, + "internal error, not implemented, unexpected auth_type=%d:%s", auth_key->auth_type, bfd_auth_type_str (auth_key->auth_type)); return 0; case BFD_AUTH_TYPE_keyed_sha1: @@ -1504,8 +1523,9 @@ bfd_verify_pkt_auth_key (const bfd_pkt_t * pkt, u32 pkt_size, } while (0); #else - clib_warning - ("Internal error, attempt to use SHA1 without SSL support"); + vlib_log_err + (bm->log_class, + "internal error, attempt to use SHA1 without SSL support"); return 0; #endif } @@ -1625,8 +1645,9 @@ bfd_consume_pkt (bfd_main_t * bm, const bfd_pkt_t * pkt, u32 bs_idx) case BFD_AUTH_TYPE_keyed_md5: /* fallthrough */ case BFD_AUTH_TYPE_meticulous_keyed_md5: - clib_warning ("Internal error, unexpected auth_type=%d:%s", - auth_type, bfd_auth_type_str (auth_type)); + vlib_log_crit (bm->log_class, + "internal error, unexpected auth_type=%d:%s", + auth_type, bfd_auth_type_str (auth_type)); break; case BFD_AUTH_TYPE_keyed_sha1: /* fallthrough */ @@ -1768,7 +1789,7 @@ u8 * format_bfd_session (u8 * s, va_list * args) { const bfd_session_t *bs = va_arg (*args, bfd_session_t *); - u32 indent = format_get_indent (s); + u32 indent = format_get_indent (s) + vlib_log_get_indent (); s = format (s, "bs_idx=%u local-state=%s remote-state=%s\n" "%Ulocal-discriminator=%u remote-discriminator=%u\n" "%Ulocal-diag=%s echo-active=%s\n" @@ -1800,6 +1821,17 @@ format_bfd_session (u8 * s, va_list * args) return s; } +u8 * +format_bfd_session_brief (u8 * s, va_list * args) +{ + const bfd_session_t *bs = va_arg (*args, bfd_session_t *); + s = + format (s, "bs_idx=%u local-state=%s remote-state=%s", bs->bs_idx, + bfd_state_string (bs->local_state), + bfd_state_string (bs->remote_state)); + return s; +} + unsigned bfd_auth_type_supported (bfd_auth_type_e auth_type) { @@ -1820,7 +1852,8 @@ bfd_auth_activate (bfd_session_t * bs, u32 conf_key_id, hash_get (bm->auth_key_by_conf_key_id, conf_key_id); if (!key_idx_p) { - clib_warning ("Authentication key with config ID %u doesn't exist)", + vlib_log_err (bm->log_class, + "authentication key with config ID %u doesn't exist)", conf_key_id); return VNET_API_ERROR_BFD_ENOENT; } @@ -1854,12 +1887,15 @@ bfd_auth_activate (bfd_session_t * bs, u32 conf_key_id, } ++key->use_count; BFD_DBG ("\nSession auth modified: %U", format_bfd_session, bs); + vlib_log_info (bm->log_class, "session auth modified: %U", + format_bfd_session_brief, bs); return 0; } vnet_api_error_t bfd_auth_deactivate (bfd_session_t * bs, u8 is_delayed) { + bfd_main_t *bm = &bfd_main; #if WITH_LIBSSL > 0 if (!is_delayed) { @@ -1888,9 +1924,12 @@ bfd_auth_deactivate (bfd_session_t * bs, u8 is_delayed) bs->auth.next_key = NULL; } BFD_DBG ("\nSession auth modified: %U", format_bfd_session, bs); + vlib_log_info (bm->log_class, "session auth modified: %U", + format_bfd_session_brief, bs); return 0; #else - clib_warning ("SSL missing, cannot deactivate BFD authentication"); + vlib_log_err (bm->log_class, + "SSL missing, cannot deactivate BFD authentication"); return VNET_API_ERROR_BFD_NOTSUPP; #endif } @@ -1946,6 +1985,8 @@ bfd_session_set_params (bfd_main_t * bm, bfd_session_t * bs, bfd_usec_to_clocks (bm, required_min_rx_usec); BFD_DBG ("\nChanged session params: %U", format_bfd_session, bs); + vlib_log_info (bm->log_class, "changed session params: %U", + format_bfd_session_brief, bs); vlib_process_signal_event (bm->vlib_main, bm->bfd_process_node_index, BFD_EVENT_CONFIG_CHANGED, bs->bs_idx); } @@ -1960,24 +2001,24 @@ vnet_api_error_t bfd_auth_set_key (u32 conf_key_id, u8 auth_type, u8 key_len, const u8 * key_data) { + bfd_main_t *bm = &bfd_main; #if WITH_LIBSSL > 0 bfd_auth_key_t *auth_key = NULL; if (!key_len || key_len > bfd_max_key_len_for_auth_type (auth_type)) { - clib_warning ("Invalid authentication key length for auth_type=%d:%s " - "(key_len=%u, must be " - "non-zero, expected max=%u)", + vlib_log_err (bm->log_class, + "invalid authentication key length for auth_type=%d:%s " + "(key_len=%u, must be non-zero, expected max=%u)", auth_type, bfd_auth_type_str (auth_type), key_len, (u32) bfd_max_key_len_for_auth_type (auth_type)); return VNET_API_ERROR_INVALID_VALUE; } if (!bfd_auth_type_supported (auth_type)) { - clib_warning ("Unsupported auth type=%d:%s", auth_type, + vlib_log_err (bm->log_class, "unsupported auth type=%d:%s", auth_type, bfd_auth_type_str (auth_type)); return VNET_API_ERROR_BFD_NOTSUPP; } - bfd_main_t *bm = &bfd_main; uword *key_idx_p = hash_get (bm->auth_key_by_conf_key_id, conf_key_id); if (key_idx_p) { @@ -1986,9 +2027,10 @@ bfd_auth_set_key (u32 conf_key_id, u8 auth_type, u8 key_len, auth_key = pool_elt_at_index (bm->auth_keys, key_idx); if (auth_key->use_count > 0) { - clib_warning ("Authentication key with conf ID %u in use by %u BFD " - "session(s) - cannot modify", - conf_key_id, auth_key->use_count); + vlib_log_err (bm->log_class, + "authentication key with conf ID %u in use by %u BFD " + "session(s) - cannot modify", conf_key_id, + auth_key->use_count); return VNET_API_ERROR_BFD_EINUSE; } } @@ -2005,7 +2047,8 @@ bfd_auth_set_key (u32 conf_key_id, u8 auth_type, u8 key_len, clib_memcpy (auth_key->key, key_data, key_len); return 0; #else - clib_warning ("SSL missing, cannot manipulate authentication keys"); + vlib_log_err (bm->log_class, + "SSL missing, cannot manipulate authentication keys"); return VNET_API_ERROR_BFD_NOTSUPP; #endif } @@ -2024,9 +2067,10 @@ bfd_auth_del_key (u32 conf_key_id) auth_key = pool_elt_at_index (bm->auth_keys, key_idx); if (auth_key->use_count > 0) { - clib_warning ("Authentication key with conf ID %u in use by %u BFD " - "session(s) - cannot delete", - conf_key_id, auth_key->use_count); + vlib_log_err (bm->log_class, + "authentication key with conf ID %u in use by %u BFD " + "session(s) - cannot delete", conf_key_id, + auth_key->use_count); return VNET_API_ERROR_BFD_EINUSE; } hash_unset (bm->auth_key_by_conf_key_id, conf_key_id); @@ -2036,13 +2080,15 @@ bfd_auth_del_key (u32 conf_key_id) else { /* no such key */ - clib_warning ("Authentication key with conf ID %u does not exist", + vlib_log_err (bm->log_class, + "authentication key with conf ID %u does not exist", conf_key_id); return VNET_API_ERROR_BFD_ENOENT; } return 0; #else - clib_warning ("SSL missing, cannot manipulate authentication keys"); + vlib_log_err (bm->log_class, + "SSL missing, cannot manipulate authentication keys"); return VNET_API_ERROR_BFD_NOTSUPP; #endif } diff --git a/src/vnet/bfd/bfd_main.h b/src/vnet/bfd/bfd_main.h index 93adac3dc8d..9e2a12e1f9b 100644 --- a/src/vnet/bfd/bfd_main.h +++ b/src/vnet/bfd/bfd_main.h @@ -23,6 +23,7 @@ #include <vnet/vnet.h> #include <vnet/bfd/bfd_protocol.h> #include <vnet/bfd/bfd_udp.h> +#include <vlib/log.h> #define foreach_bfd_mode(F) \ F (asynchronous) \ @@ -296,8 +297,11 @@ typedef struct /** hashmap - index in pool auth_keys by conf_key_id */ u32 *auth_key_by_conf_key_id; - /** A vector of callback notification functions */ + /** vector of callback notification functions */ bfd_notify_fn_t *listeners; + + /** log class */ + vlib_log_class_t log_class; } bfd_main_t; extern bfd_main_t bfd_main; @@ -358,6 +362,7 @@ void bfd_init_final_control_frame (vlib_main_t * vm, vlib_buffer_t * b, bfd_main_t * bm, bfd_session_t * bs, int is_local); u8 *format_bfd_session (u8 * s, va_list * args); +u8 *format_bfd_session_brief (u8 * s, va_list * args); u8 *format_bfd_auth_key (u8 * s, va_list * args); void bfd_session_set_flags (bfd_session_t * bs, u8 admin_up_down); unsigned bfd_auth_type_supported (bfd_auth_type_e auth_type); diff --git a/src/vnet/bfd/bfd_udp.c b/src/vnet/bfd/bfd_udp.c index 533d98d6865..5464ce91f57 100644 --- a/src/vnet/bfd/bfd_udp.c +++ b/src/vnet/bfd/bfd_udp.c @@ -59,6 +59,8 @@ typedef struct u32 ip4_rewrite_idx; /* node index of "ip6-rewrite" node */ u32 ip6_rewrite_idx; + /* log class */ + vlib_log_class_t log_class; } bfd_udp_main_t; static vlib_node_registration_t bfd_udp4_input_node; @@ -481,7 +483,8 @@ bfd_udp_add_session_internal (bfd_udp_main_t * bum, u32 sw_if_index, const bfd_session_t *tmp = bfd_lookup_session (bum, key); if (tmp) { - clib_warning ("duplicate bfd-udp session, existing bs_idx=%d", + vlib_log_err (bum->log_class, + "duplicate bfd-udp session, existing bs_idx=%d", tmp->bs_idx); bfd_put_session (bum->bfd_main, bs); return VNET_API_ERROR_BFD_EEXIST; @@ -491,6 +494,8 @@ bfd_udp_add_session_internal (bfd_udp_main_t * bum, u32 sw_if_index, bs->bs_idx, key->sw_if_index, format_ip46_address, &key->local_addr, IP46_TYPE_ANY, format_ip46_address, &key->peer_addr, IP46_TYPE_ANY); + vlib_log_info (bum->log_class, "create BFD session: %U", + format_bfd_session, bs); if (BFD_TRANSPORT_UDP4 == t) { bus->adj_index = adj_nbr_add_or_lock (FIB_PROTOCOL_IP4, VNET_LINK_IP4, @@ -519,20 +524,24 @@ bfd_udp_validate_api_input (u32 sw_if_index, const ip46_address_t * local_addr, const ip46_address_t * peer_addr) { + bfd_udp_main_t *bum = &bfd_udp_main; vnet_sw_interface_t *sw_if = vnet_get_sw_interface_safe (bfd_udp_main.vnet_main, sw_if_index); u8 local_ip_valid = 0; ip_interface_address_t *ia = NULL; if (!sw_if) { - clib_warning ("got NULL sw_if"); + vlib_log_err (bum->log_class, + "got NULL sw_if when getting interface by index %u", + sw_if_index); return VNET_API_ERROR_INVALID_SW_IF_INDEX; } if (ip46_address_is_ip4 (local_addr)) { if (!ip46_address_is_ip4 (peer_addr)) { - clib_warning ("IP family mismatch"); + vlib_log_err (bum->log_class, + "IP family mismatch (local is ipv4, peer is ipv6)"); return VNET_API_ERROR_INVALID_ARGUMENT; } ip4_main_t *im = &ip4_main; @@ -555,7 +564,8 @@ bfd_udp_validate_api_input (u32 sw_if_index, { if (ip46_address_is_ip4 (peer_addr)) { - clib_warning ("IP family mismatch"); + vlib_log_err (bum->log_class, + "IP family mismatch (local is ipv6, peer is ipv4)"); return VNET_API_ERROR_INVALID_ARGUMENT; } ip6_main_t *im = &ip6_main; @@ -577,7 +587,10 @@ bfd_udp_validate_api_input (u32 sw_if_index, if (!local_ip_valid) { - clib_warning ("address not found on interface"); + vlib_log_err (bum->log_class, + "local address %U not found on interface with index %u", + format_ip46_address, IP46_TYPE_ANY, local_addr, + sw_if_index); return VNET_API_ERROR_ADDRESS_NOT_FOUND_FOR_INTERFACE; } @@ -604,10 +617,11 @@ bfd_udp_find_session_by_api_input (u32 sw_if_index, } else { - clib_warning - ("BFD session not found (sw_if_index=%u, local=%U, peer=%U", - sw_if_index, format_ip46_address, local_addr, IP46_TYPE_ANY, - format_ip46_address, peer_addr, IP46_TYPE_ANY); + vlib_log_err (bum->log_class, + "BFD session not found, sw_if_index=%u, local=%U, peer=%U", + sw_if_index, format_ip46_address, local_addr, + IP46_TYPE_ANY, format_ip46_address, peer_addr, + IP46_TYPE_ANY); return VNET_API_ERROR_BFD_ENOENT; } } @@ -620,6 +634,7 @@ bfd_api_verify_common (u32 sw_if_index, u32 desired_min_tx_usec, const ip46_address_t * local_addr, const ip46_address_t * peer_addr) { + bfd_udp_main_t *bum = &bfd_udp_main; vnet_api_error_t rv = bfd_udp_validate_api_input (sw_if_index, local_addr, peer_addr); if (rv) @@ -628,12 +643,12 @@ bfd_api_verify_common (u32 sw_if_index, u32 desired_min_tx_usec, } if (detect_mult < 1) { - clib_warning ("detect_mult < 1"); + vlib_log_err (bum->log_class, "detect_mult < 1"); return VNET_API_ERROR_INVALID_ARGUMENT; } if (desired_min_tx_usec < 1) { - clib_warning ("desired_min_tx_usec < 1"); + vlib_log_err (bum->log_class, "desired_min_tx_usec < 1"); return VNET_API_ERROR_INVALID_ARGUMENT; } return 0; @@ -675,7 +690,8 @@ bfd_udp_add_session (u32 sw_if_index, const ip46_address_t * local_addr, rv = bfd_auth_activate (bs, conf_key_id, bfd_key_id, 0 /* is not delayed */ ); #else - clib_warning ("SSL missing, cannot add authenticated BFD session"); + vlib_log_err (bfd_udp_main.log_class, + "SSL missing, cannot add authenticated BFD session"); rv = VNET_API_ERROR_BFD_NOTSUPP; #endif if (rv) @@ -763,7 +779,8 @@ bfd_udp_auth_activate (u32 sw_if_index, } return bfd_auth_activate (bs, conf_key_id, key_id, is_delayed); #else - clib_warning ("SSL missing, cannot activate BFD authentication"); + vlib_log_err (bfd_udp_main->log_class, + "SSL missing, cannot activate BFD authentication"); return VNET_API_ERROR_BFD_NOTSUPP; #endif } @@ -1443,6 +1460,7 @@ static clib_error_t * bfd_udp_sw_if_add_del (vnet_main_t * vnm, u32 sw_if_index, u32 is_create) { bfd_session_t **to_be_freed = NULL; + bfd_udp_main_t *bum = &bfd_udp_main; BFD_DBG ("sw_if_add_del called, sw_if_index=%u, is_create=%u", sw_if_index, is_create); if (!is_create) @@ -1463,8 +1481,9 @@ bfd_udp_sw_if_add_del (vnet_main_t * vnm, u32 sw_if_index, u32 is_create) bfd_session_t **bs; vec_foreach (bs, to_be_freed) { - clib_warning ("removal of sw_if_index=%u forces removal of bfd session " - "with bs_idx=%u", sw_if_index, (*bs)->bs_idx); + vlib_log_notice (bum->log_class, + "removal of sw_if_index=%u forces removal of bfd session " + "with bs_idx=%u", sw_if_index, (*bs)->bs_idx); bfd_session_set_flags (*bs, 0); bfd_udp_del_session_internal (*bs); } @@ -1502,6 +1521,8 @@ bfd_udp_init (vlib_main_t * vm) ASSERT (node); bfd_udp_main.ip6_rewrite_idx = node->index; + bfd_udp_main.log_class = vlib_log_register_class ("bfd", "udp"); + vlib_log_debug (bfd_udp_main.log_class, "initialized"); return 0; } diff --git a/src/vnet/devices/tap/tap.c b/src/vnet/devices/tap/tap.c index 8005b347391..7cffaafb1e2 100644 --- a/src/vnet/devices/tap/tap.c +++ b/src/vnet/devices/tap/tap.c @@ -31,6 +31,7 @@ #include <linux/rtnetlink.h> #include <vlib/vlib.h> +#include <vlib/log.h> #include <vlib/unix/unix.h> #include <vnet/ethernet/ethernet.h> #include <vnet/ip/ip4_packet.h> @@ -519,11 +520,19 @@ tap_dump_ifs (tap_interface_details_t ** out_tapids) return 0; } +#define vlib_log_info(...) vlib_log(VLIB_LOG_LEVEL_INFO, __VA_ARGS__) + static clib_error_t * tap_init (vlib_main_t * vm) { tap_main_t *tm = &tap_main; + clib_error_t *error; + error = vlib_call_init_function (vm, vlib_log_init); + if (error) + return error; tm->dev_instance_by_interface_id = hash_create (0, sizeof (uword)); + tm->log_default = vlib_log_register_class ("tap", 0); + vlib_log_info (tm->log_default, "initialized"); return 0; } diff --git a/src/vnet/devices/tap/tap.h b/src/vnet/devices/tap/tap.h index 98af0d8f3ab..6e46302770d 100644 --- a/src/vnet/devices/tap/tap.h +++ b/src/vnet/devices/tap/tap.h @@ -69,6 +69,9 @@ typedef struct { u32 last_used_interface_id; uword *dev_instance_by_interface_id; + + /* logging */ + vlib_log_class_t log_default; } tap_main_t; void tap_create_if (vlib_main_t * vm, tap_create_if_args_t * args); |