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>

5 files changed, 115 insertions, 51 deletions

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. */