Add logging support

Change-Id: Ieac9cf50156dbbb4962411e900d59256441915ef
Signed-off-by: Damjan Marion <damarion@cisco.com>
Signed-off-by: Klement Sekera <ksekera@cisco.com>

3 files changed, 737 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:
+ */
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>