vlib: print logs to stderr if interactive or nosyslog set

If VPP is started in interactive mode, instead of sending logs to syslog
server we print them directly to stderr.
Output is colorized, but that can be turned off with unix { nocolor }

Type: improvement
Change-Id: I9a0f0803e4cba2849a6efa0b6a86b9614ed33ced
Signed-off-by: Damjan Marion <damarion@cisco.com>

14 files changed, 171 insertions, 90 deletions

diff --git a/src/plugins/dhcp/client.c b/src/plugins/dhcp/client.c
index cd90df6a244..575f8b82625 100644
--- a/src/plugins/dhcp/client.c
+++ b/src/plugins/dhcp/client.c
@@ -1250,7 +1250,7 @@ dhcp_client_init (vlib_main_t * vm)
   dcm->seed = (u32) clib_cpu_time_now ();
 
   dhcp_logger = vlib_log_register_class ("dhcp", "client");
-  DHCP_INFO ("plugin initialized");
+  DHCP_DBG ("plugin initialized");
 
   return 0;
 }
diff --git a/src/plugins/dpdk/cryptodev/cryptodev.c b/src/plugins/dpdk/cryptodev/cryptodev.c
index 68a9126c3ae..f58b54634a7 100644
--- a/src/plugins/dpdk/cryptodev/cryptodev.c
+++ b/src/plugins/dpdk/cryptodev/cryptodev.c
@@ -1201,10 +1201,7 @@ cryptodev_get_session_sz (vlib_main_t *vm, uint32_t n_workers)
   u32 sess_data_sz = 0, i;
 
   if (rte_cryptodev_count () == 0)
-    {
-      clib_warning ("No cryptodev device available");
-      return -1;
-    }
+    return -1;
 
   for (i = 0; i < rte_cryptodev_count (); i++)
     {
diff --git a/src/plugins/dpdk/cryptodev/cryptodev_dp_api.c b/src/plugins/dpdk/cryptodev/cryptodev_dp_api.c
index 8fcfa2edf48..682295b703c 100644
--- a/src/plugins/dpdk/cryptodev/cryptodev_dp_api.c
+++ b/src/plugins/dpdk/cryptodev/cryptodev_dp_api.c
@@ -1348,10 +1348,7 @@ cryptodev_get_session_sz (vlib_main_t *vm, u32 n_workers)
   u32 sess_data_sz = 0, i;
 
   if (rte_cryptodev_count () == 0)
-    {
-      clib_warning ("Failed");
-      return -1;
-    }
+    return -1;
 
   for (i = 0; i < rte_cryptodev_count (); i++)
     {
diff --git a/src/plugins/dpdk/device/dpdk.h b/src/plugins/dpdk/device/dpdk.h
index 94842a56397..b094a1931cf 100644
--- a/src/plugins/dpdk/device/dpdk.h
+++ b/src/plugins/dpdk/device/dpdk.h
@@ -346,6 +346,8 @@ typedef struct
 
   /* logging */
   vlib_log_class_t log_default;
+  vlib_log_class_t log_cryptodev;
+  vlib_log_class_t log_ipsec;
 } dpdk_main_t;
 
 extern dpdk_main_t dpdk_main;
diff --git a/src/plugins/dpdk/device/init.c b/src/plugins/dpdk/device/init.c
index 2615f16364d..4b200cef8bb 100644
--- a/src/plugins/dpdk/device/init.c
+++ b/src/plugins/dpdk/device/init.c
@@ -862,7 +862,8 @@ dpdk_bind_devices_to_uio (dpdk_config_main_t * conf)
     d = vlib_pci_get_device_info (vm, addr, &error);
     if (error)
     {
-      clib_error_report (error);
+      vlib_log_warn (dpdk_main.log_default, "%U", format_clib_error, error);
+      clib_error_free (error);
       continue;
     }
 
@@ -1507,7 +1508,7 @@ dpdk_config (vlib_main_t * vm, unformat_input_t * input)
 
   vec_terminate_c_string (conf->eal_init_args_str);
 
-  dpdk_log_warn ("EAL init args: %s", conf->eal_init_args_str);
+  dpdk_log_notice ("EAL init args: %s", conf->eal_init_args_str);
   ret = rte_eal_init (vec_len (conf->eal_init_args),
 		      (char **) conf->eal_init_args);
 
@@ -1636,7 +1637,10 @@ dpdk_process (vlib_main_t * vm, vlib_node_runtime_t * rt, vlib_frame_t * f)
 
   error = dpdk_cryptodev_init (vm);
   if (error)
-    clib_error_report (error);
+    {
+      vlib_log_warn (dpdk_main.log_cryptodev, "%U", format_clib_error, error);
+      clib_error_free (error);
+    }
 
   tm->worker_thread_release = 1;
 
@@ -1720,6 +1724,8 @@ dpdk_init (vlib_main_t * vm)
   dm->link_state_poll_interval = DPDK_LINK_POLL_INTERVAL;
 
   dm->log_default = vlib_log_register_class ("dpdk", 0);
+  dm->log_cryptodev = vlib_log_register_class ("dpdk", "cryptodev");
+  dm->log_ipsec = vlib_log_register_class ("dpdk", "ipsec");
 
   return error;
 }
diff --git a/src/plugins/dpdk/ipsec/ipsec.c b/src/plugins/dpdk/ipsec/ipsec.c
index db2b1d6c2e9..c7fd9222824 100644
--- a/src/plugins/dpdk/ipsec/ipsec.c
+++ b/src/plugins/dpdk/ipsec/ipsec.c
@@ -17,6 +17,7 @@
 #include <vnet/api_errno.h>
 #include <vnet/ipsec/ipsec.h>
 #include <vlib/node_funcs.h>
+#include <vlib/log.h>
 
 #include <dpdk/device/dpdk.h>
 #include <dpdk/buffer.h>
@@ -1028,7 +1029,8 @@ dpdk_ipsec_main_init (vlib_main_t * vm)
 
   if (!(dcm->enabled))
     {
-      clib_warning ("not enough DPDK crypto resources, default to OpenSSL");
+      vlib_log_warn (dpdk_main.log_default,
+		     "not enough DPDK crypto resources");
       crypto_disable ();
       return 0;
     }
diff --git a/src/vlib/log.c b/src/vlib/log.c
index 342c0d25cd9..a4514206bae 100644
--- a/src/vlib/log.c
+++ b/src/vlib/log.c
@@ -16,6 +16,7 @@
 #include <stdbool.h>
 #include <vlib/vlib.h>
 #include <vlib/log.h>
+#include <vlib/unix/unix.h>
 #include <syslog.h>
 
 vlib_log_main_t log_main = {
@@ -26,6 +27,17 @@ vlib_log_main_t log_main = {
   .default_rate_limit = 50,
 };
 
+static const int colors[] = {
+  [VLIB_LOG_LEVEL_EMERG] = 1,	/* red */
+  [VLIB_LOG_LEVEL_ALERT] = 1,	/* red */
+  [VLIB_LOG_LEVEL_CRIT] = 1,	/* red */
+  [VLIB_LOG_LEVEL_ERR] = 1,	/* red */
+  [VLIB_LOG_LEVEL_WARNING] = 3,	/* yellow */
+  [VLIB_LOG_LEVEL_NOTICE] = 2,	/* green */
+  [VLIB_LOG_LEVEL_INFO] = 4,	/* blue */
+  [VLIB_LOG_LEVEL_DEBUG] = 6,	/* cyan */
+};
+
 int
 last_log_entry ()
 {
@@ -82,6 +94,34 @@ format_vlib_log_class (u8 * s, va_list * args)
     return format (s, "%v", c->name, 0);
 }
 
+u8 *
+format_indent (u8 * s, va_list * args)
+{
+  u8 *v = va_arg (*args, u8 *);
+  u32 indent = va_arg (*args, u32);
+  u8 *c;
+
+  /* *INDENT-OFF* */
+  vec_foreach (c, v)
+    {
+      vec_add (s, c, 1);
+      if (c[0] == '\n')
+	for (u32 i = 0; i < indent; i++)
+	  vec_add1 (s, (u8) ' ');
+    }
+  /* *INDENT-ON* */
+  return s;
+}
+
+static int
+log_level_is_enabled (vlib_log_level_t level, vlib_log_level_t configured)
+{
+  if (configured == VLIB_LOG_LEVEL_DISABLED)
+    return 0;
+  if (level > configured)
+    return 0;
+  return 1;
+}
 
 void
 vlib_log (vlib_log_level_t level, vlib_log_class_t class, char *fmt, ...)
@@ -93,19 +133,18 @@ vlib_log (vlib_log_level_t level, vlib_log_class_t class, char *fmt, ...)
   va_list va;
   f64 t = vlib_time_now (vm);
   f64 delta = t - sc->last_event_timestamp;
+  int log_enabled = log_level_is_enabled (level, sc->level);
+  int syslog_enabled = log_level_is_enabled (level, sc->syslog_level);
   u8 *s = 0;
-  bool use_formatted_log_entry = true;
 
-  vec_validate (lm->entries, lm->size);
   /* 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 ((log_enabled || syslog_enabled) == 0)
+    return;
+
+  vec_validate (lm->entries, lm->size);
 
   if ((delta > lm->unthrottle_time) ||
       (sc->is_throttling == 0 && (delta > 1)))
@@ -122,7 +161,7 @@ vlib_log (vlib_log_level_t level, vlib_log_class_t class, char *fmt, ...)
       else if (sc->last_sec_count == sc->rate_limit)
 	{
 	  vec_reset_length (s);
-	  s = format (0, "--- message(s) throttled ---");
+	  s = format (s, "--- message(s) throttled ---");
 	  sc->is_throttling = 1;
 	}
     }
@@ -134,42 +173,58 @@ vlib_log (vlib_log_level_t level, vlib_log_class_t class, char *fmt, ...)
       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_level != VLIB_LOG_LEVEL_DISABLED &&
-      level <= sc->syslog_level)
+  if (syslog_enabled)
     {
-      u8 *tmp = format (NULL, "%U", format_vlib_log_class, class);
-      if (use_formatted_log_entry)
+      u8 *l = 0;
+      if (unix_main.flags & (UNIX_FLAG_INTERACTIVE | UNIX_FLAG_NOSYSLOG))
 	{
-	  syslog (vlib_log_level_to_syslog_priority (level), "%.*s: %.*s",
-		  (int) vec_len (tmp), tmp,
-		  (int) (vec_len (s) -
-			 (vec_c_string_is_terminated (s) ? 1 : 0)), s);
+	  int indent = 0;
+	  int with_colors = (unix_main.flags & UNIX_FLAG_NOCOLOR) == 0;
+	  u8 *fmt;
+	  if (with_colors)
+	    {
+	      l = format (l, "\x1b[%um", 90 + colors[level]);
+	      indent = vec_len (l);
+	    }
+	  fmt = format (0, "%%-%uU [%%-6U]: ", lm->max_class_name_length);
+	  l = format (l, (char *) fmt, format_vlib_log_class, class,
+		      format_vlib_log_level, level);
+	  vec_free (fmt);
+	  indent = vec_len (l) - indent;
+	  if (with_colors)
+	    l = format (l, "\x1b[0m");
+	  l = format (l, "%U", format_indent, s, indent);
+	  fformat (stderr, "%v\n", l);
+	  fflush (stderr);
 	}
       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",
-		  (int) (vec_len (tmp) -
-			 (vec_c_string_is_terminated (tmp) ? 1 : 0)), tmp);
+	  l = format (l, "%U", format_vlib_log_class, class);
+	  int prio = vlib_log_level_to_syslog_priority (level);
+	  int is_term = vec_c_string_is_terminated (l) ? 1 : 0;
+
+	  syslog (prio, "%.*s: %.*s", (int) vec_len (l), l,
+		  (int) vec_len (s) - is_term, s);
 	}
-      vec_free (tmp);
+      vec_free (l);
     }
 
+  if (log_enabled)
+    {
+      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;
+      s = 0;
+
+      lm->next = (lm->next + 1) % lm->size;
+      if (lm->size > lm->count)
+	lm->count++;
+    }
+
+  vec_free (s);
 }
 
 static vlib_log_class_t
@@ -179,6 +234,8 @@ vlib_log_register_class_internal (char *class, char *subclass, u32 limit)
   vlib_log_class_data_t *c = NULL;
   vlib_log_subclass_data_t *s;
   vlib_log_class_data_t *tmp;
+  u32 length = 0;
+
   vec_foreach (tmp, lm->classes)
   {
     if (vec_len (tmp->name) != strlen (class))
@@ -194,6 +251,7 @@ vlib_log_register_class_internal (char *class, char *subclass, u32 limit)
       vec_add2 (lm->classes, c, 1);
       c->index = c - lm->classes;
       c->name = format (0, "%s", class);
+      length = vec_len (c->name);
     }
 
   vec_add2 (c->subclasses, s, 1);
@@ -202,6 +260,10 @@ vlib_log_register_class_internal (char *class, char *subclass, u32 limit)
   s->rate_limit = (limit == 0) ? lm->default_rate_limit : limit;
   s->level = lm->default_log_level;
   s->syslog_level = lm->default_syslog_log_level;
+  if (subclass)
+    length += 1 + vec_len (s->name);
+  if (length > lm->max_class_name_length)
+    lm->max_class_name_length = length;
   return (c->index << 16) | (s->index);
 }
 
@@ -236,12 +298,6 @@ format_vlib_log_level (u8 * s, va_list * args)
   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)
 {
@@ -252,10 +308,6 @@ vlib_log_init (vlib_main_t * vm)
 
   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;
 }
 
diff --git a/src/vlib/log.h b/src/vlib/log.h
index 9206ad0fcc6..9a0c44475d2 100644
--- a/src/vlib/log.h
+++ b/src/vlib/log.h
@@ -22,7 +22,7 @@
   _(0, EMERG, emerg) \
   _(1, ALERT, alert) \
   _(2, CRIT, crit) \
-  _(3, ERR, err) \
+  _(3, ERR, error) \
   _(4, WARNING, warn) \
   _(5, NOTICE, notice) \
   _(6, INFO, info) \
@@ -79,7 +79,7 @@ typedef struct
   int default_log_level;
   int default_syslog_log_level;
   int unthrottle_time;
-  u32 indent;
+  u32 max_class_name_length;
 
   /* time zero */
   struct timeval time_zero_timeval;
@@ -93,11 +93,11 @@ vlib_log_class_t vlib_log_register_class (char *vlass, char *subclass);
 vlib_log_class_t
 vlib_log_register_class_rate_limit (char *class, char *subclass,
 				    u32 rate_limit);
-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);
+u8 *format_vlib_log_level (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/vlib/unix/cli.c b/src/vlib/unix/cli.c
index 2f34c8deae2..c7732ae431f 100644
--- a/src/vlib/unix/cli.c
+++ b/src/vlib/unix/cli.c
@@ -1263,9 +1263,9 @@ unix_cli_file_welcome (unix_cli_main_t * cm, unix_cli_file_t * cf)
    */
   unix_cli_add_pending_output (uf, cf, (u8 *) "\r", 1);
 
-  if (!um->cli_no_banner)
+  if (!um->cli_no_banner && (um->flags & UNIX_FLAG_NOBANNER) == 0)
     {
-      if (cf->ansi_capable)
+      if (cf->ansi_capable && (um->flags & UNIX_FLAG_NOCOLOR) == 0)
 	{
 	  banner = unix_cli_banner_color;
 	  len = ARRAY_LEN (unix_cli_banner_color);
diff --git a/src/vlib/unix/main.c b/src/vlib/unix/main.c
index 83a3a1f643b..2f1b6ecdae0 100644
--- a/src/vlib/unix/main.c
+++ b/src/vlib/unix/main.c
@@ -402,6 +402,10 @@ unix_config (vlib_main_t * vm, unformat_input_t * input)
 	um->flags |= UNIX_FLAG_NODAEMON;
       else if (unformat (input, "nosyslog"))
 	um->flags |= UNIX_FLAG_NOSYSLOG;
+      else if (unformat (input, "nocolor"))
+	um->flags |= UNIX_FLAG_NOCOLOR;
+      else if (unformat (input, "nobanner"))
+	um->flags |= UNIX_FLAG_NOBANNER;
       else if (unformat (input, "cli-prompt %s", &cli_prompt))
 	vlib_unix_cli_set_prompt (cli_prompt);
       else
@@ -576,6 +580,12 @@ unix_config (vlib_main_t * vm, unformat_input_t * input)
  * when invoking VPP applications from a process monitor which
  * pipe stdout/stderr to a dedicated logger service.
  *
+ * @cfgcmd{nocolor}
+ * Do not use colors in outputs.
+ * *
+ * @cfgcmd{nobanner}
+ * Do not display startup banner.
+ *
  * @cfgcmd{exec, &lt;filename&gt;}
  * @par <code>startup-config &lt;filename&gt;</code>
  * Read startup operational configuration from @c filename.
diff --git a/src/vlib/unix/unix.h b/src/vlib/unix/unix.h
index 9fa95a0c1d6..44dcf712e8d 100644
--- a/src/vlib/unix/unix.h
+++ b/src/vlib/unix/unix.h
@@ -60,6 +60,8 @@ typedef struct
 #define UNIX_FLAG_INTERACTIVE (1 << 0)
 #define UNIX_FLAG_NODAEMON (1 << 1)
 #define UNIX_FLAG_NOSYSLOG (1 << 2)
+#define UNIX_FLAG_NOCOLOR (1 << 3)
+#define UNIX_FLAG_NOBANNER (1 << 4)
 
 
   /* CLI listen socket. */
diff --git a/src/vnet/bfd/bfd_main.c b/src/vnet/bfd/bfd_main.c
index 80722163762..30d98f6ab34 100644
--- a/src/vnet/bfd/bfd_main.c
+++ b/src/vnet/bfd/bfd_main.c
@@ -1983,34 +1983,28 @@ 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) + 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"
-	      "%Udesired-min-tx=%u required-min-rx=%u\n"
-	      "%Urequired-min-echo-rx=%u detect-mult=%u\n"
-	      "%Uremote-min-rx=%u remote-min-echo-rx=%u\n"
-	      "%Uremote-demand=%s poll-state=%s\n"
-	      "%Uauth: local-seq-num=%u remote-seq-num=%u\n"
-	      "%U      is-delayed=%s\n"
-	      "%U      curr-key=%U\n"
-	      "%U      next-key=%U",
+	      "local-discriminator=%u remote-discriminator=%u\n"
+	      "local-diag=%s echo-active=%s\n"
+	      "desired-min-tx=%u required-min-rx=%u\n"
+	      "required-min-echo-rx=%u detect-mult=%u\n"
+	      "remote-min-rx=%u remote-min-echo-rx=%u\n"
+	      "remote-demand=%s poll-state=%s\n"
+	      "auth: local-seq-num=%u remote-seq-num=%u\n"
+	      "      is-delayed=%s\n"
+	      "      curr-key=%U\n"
+	      "      next-key=%U",
 	      bs->bs_idx, bfd_state_string (bs->local_state),
-	      bfd_state_string (bs->remote_state), format_white_space, indent,
-	      bs->local_discr, bs->remote_discr, format_white_space, indent,
-	      bfd_diag_code_string (bs->local_diag),
-	      (bs->echo ? "yes" : "no"), format_white_space, indent,
-	      bs->config_desired_min_tx_usec, bs->config_required_min_rx_usec,
-	      format_white_space, indent, 1, bs->local_detect_mult,
-	      format_white_space, indent, bs->remote_min_rx_usec,
-	      bs->remote_min_echo_rx_usec, format_white_space, indent,
+	      bfd_state_string (bs->remote_state), bs->local_discr,
+	      bs->remote_discr, bfd_diag_code_string (bs->local_diag),
+	      (bs->echo ? "yes" : "no"), bs->config_desired_min_tx_usec,
+	      bs->config_required_min_rx_usec, 1, bs->local_detect_mult,
+	      bs->remote_min_rx_usec, bs->remote_min_echo_rx_usec,
 	      (bs->remote_demand ? "yes" : "no"),
-	      bfd_poll_state_string (bs->poll_state), format_white_space,
-	      indent, bs->auth.local_seq_number, bs->auth.remote_seq_number,
-	      format_white_space, indent,
-	      (bs->auth.is_delayed ? "yes" : "no"), format_white_space,
-	      indent, format_bfd_auth_key, bs->auth.curr_key,
-	      format_white_space, indent, format_bfd_auth_key,
+	      bfd_poll_state_string (bs->poll_state),
+	      bs->auth.local_seq_number, bs->auth.remote_seq_number,
+	      (bs->auth.is_delayed ? "yes" : "no"),
+	      format_bfd_auth_key, bs->auth.curr_key, format_bfd_auth_key,
 	      bs->auth.next_key);
   return s;
 }
diff --git a/src/vpp/conf/startup.conf b/src/vpp/conf/startup.conf
index 32bfea04e91..8b02ac89085 100644
--- a/src/vpp/conf/startup.conf
+++ b/src/vpp/conf/startup.conf
@@ -5,6 +5,15 @@ unix {
   full-coredump
   cli-listen /run/vpp/cli.sock
   gid vpp
+
+  ## run vpp in the interactive mode
+  # interactive
+
+  ## do not use colors in terminal output
+  # nocolor
+
+  ## do not display banner
+  # nobanner
 }
 
 api-trace {
@@ -223,3 +232,11 @@ cpu {
    #  num-buckets 524288
    # }
 # }
+
+# logging {
+   ## set default logging level for logging buffer
+   ## logging levels: emerg, alert,crit, error, warn, notice, info, debug, disabled
+   # default-log-level debug
+   ## set default logging level for syslog or stderr output
+   # default-syslog-log-level info
+# }
diff --git a/src/vppinfra/error.c b/src/vppinfra/error.c
index a00e8dbd21a..b2b1a83e552 100644
--- a/src/vppinfra/error.c
+++ b/src/vppinfra/error.c
@@ -210,7 +210,9 @@ format_clib_error (u8 * s, va_list * va)
 	vec_free (where);
       }
 
-    s = format (s, "%v\n", e->what);
+    s = format (s, "%v", e->what);
+    if ((vec_end (errors) - 1) != e)
+      s = format (s, "\n");
   }
 
   return s;