diff options
Diffstat (limited to 'src/vlib/log.c')
| -rw-r--r-- | src/vlib/log.c | 673 |
1 files changed, 673 insertions, 0 deletions
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: + */ |