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>

diff --git a/src/plugins/dhcp/client.c b/src/plugins/dhcp/client.c
index cd90df6..575f8b8 100644 (file)
--- 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 68a9126..f58b546 100644 (file)
--- 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 8fcfa2e..682295b 100644 (file)
--- 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 94842a5..b094a19 100644 (file)
--- 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 2615f16..4b200ce 100644 (file)
--- 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 db2b1d6..c7fd922 100644 (file)
--- 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 342c0d2..a451420 100644 (file)
--- 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 9206ad0..9a0c444 100644 (file)
--- 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 2f34c8d..c7732ae 100644 (file)
--- 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 83a3a1f..2f1b6ec 100644 (file)
--- 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, <filename>}
  * @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 9fa95a0..44dcf71 100644 (file)
--- 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 8072216..30d98f6 100644 (file)
--- 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 32bfea0..8b02ac8 100644 (file)
--- 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 a00e8db..b2b1a83 100644 (file)
--- 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;