summaryrefslogtreecommitdiffstats
path: root/vlib-api
AgeCommit message (Expand)AuthorFilesLines
2016-08-15VPP-327 Coding standards cleanup for vppinfraDave Barach2-5/+6
2016-08-15VPP-236 Support 64-bit vector lengths, shared memory segments >4 GBDave Barach4-4/+79
2016-08-12VPP-237: indent fixes in prep for checkstyleEd Warnicke5-19/+21
2016-08-05vpp-189 Clean up more coverity warningsDave Barach1-0/+2
2016-07-27VPP-210: Clearer error codes in vlib-api for API trace saveroot1-2/+14
2016-07-27VPP-189 coverity warning cleanupsDave Barach3-0/+3
2016-07-26Fix coverity warningsDave Barach4-1/+10
2016-07-25Author: Dave Barach <dave@barachs.net>Dave Barach1-2/+4
2016-07-08fd-io-styleify passDave Barach17-3544/+4130
2016-07-08Remove unnecessary and obsolete configure.ac directivesDamjan Marion1-1/+0
2016-06-17vpp-83: fix double-unlockDave Barach1-2/+3
2016-06-07VPP-83: fix collateral damageDave Barach1-0/+1
2016-06-01VPP-83 Allow non-privileged clients to use the vpp binary API.Dave Barach5-46/+61
2016-05-21Add per-thread, per-node runtime stats serializationDave Barach4-59/+306
2016-04-26Make automake silent rules defaultDamjan Marion1-1/+1
2016-04-22Add clib_memcpy macro based on DPDK rte_memcpy implementationDamjan Marion4-11/+11
2016-04-20Python-API: Inital commit of Python bindings for the VPP API.Ole Troan2-8/+13
2016-04-19VPP-6: set epoll wait-time to zero when binary API messages are waitingDave Barach1-0/+2
2016-04-18Add support for AArch32Christophe Fontaine1-3/+3
2016-03-07build: fix call to mkdirJean-Mickael Guerin1-1/+1
2016-02-19Serialize and upload the data plane node graphDave Barach3-1/+147
2016-02-10Replace AC_PROG_LIBTOOL with LT_INITDave Barach1-1/+1
2016-01-22Enable shared-VM namespace supportDave Barach2-11/+12
2015-12-15Remove autotools generated productsDave Barach10-39229/+0
2015-12-14Move rpc handler where it belongs, related cleanupDave Barach3-22/+87
2015-12-08Initial commit of vpp code.v1.0.0Ed Warnicke30-0/+44561
n501'>501 502 503 504 505 506 507 508 509 510 511 512 513 514 515 516 517 518 519 520 521 522 523 524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539 540 541 542 543 544 545 546 547 548 549 550 551 552 553 554 555 556 557 558 559 560 561 562 563 564 565 566 567 568 569 570 571 572 573 574 575 576 577 578 579 580 581 582 583 584 585 586 587 588 589 590 591 592 593 594 595 596 597 598 599 600 601 602 603 604 605 606 607 608 609 610 611 612 613 614 615 616 617 618 619 620 621 622 623 624 625 626 627 628 629 630 631 632 633 634 635 636 637 638 639 640 641 642 643 644 645 646 647 648 649 650 651 652 653 654 655 656 657 658 659 660 661 662 663 664 665 666 667 668 669 670 671 672 673 674 675 676 677 678 679 680 681 682 683 684 685 686 687 688 689 690 691 692 693 694 695 696 697 698 699 700 701 702 703 704 705 706 707 708 709 710 711 712 713 714 715 716 717 718 719 720 721 722 723 724 725 726 727 728 729 730 731 732 733 734 
/*
 * 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>

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
  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 default_log_level;
  int default_syslog_log_level;
  int unthrottle_time;
  u32 indent;

  /* time zero */
  struct timeval time_zero_timeval;
  f64 time_zero;

} vlib_log_main_t;

vlib_log_main_t log_main = {
  .default_log_level = VLIB_LOG_LEVEL_NOTICE,
  .default_syslog_log_level = VLIB_LOG_LEVEL_WARNING,
  .unthrottle_time = 3,
  .size = 512,
  .default_rate_limit = 50,
};

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 LOG_DISABLED LOG_DEBUG
#define _(n,uc,lc) \
    case VLIB_LOG_LEVEL_##uc:\
      return LOG_##uc;
      foreach_vlib_log_level
#undef _
#undef LOG_DISABLED
    }
  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;

  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 ((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_level != VLIB_LOG_LEVEL_DISABLED &&
      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",
		  (int) vec_len (tmp), tmp,
		  (int) (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",
		  (int) (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 (vec_len (tmp->name) != strlen (class))
      continue;
    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 = lm->default_log_level;
  s->syslog_level = lm->default_syslog_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;

  gettimeofday (&lm->time_zero_timeval, 0);
  lm->time_zero = vlib_time_now (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;
}

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;
  f64 time_offset;

  time_offset = (f64) lm->time_zero_timeval.tv_sec
    + (((f64) lm->time_zero_timeval.tv_usec) * 1e-6) - lm->time_zero;

  while (count--)
    {
      e = vec_elt_at_index (lm->entries, i);
      vlib_cli_output (vm, "%U %-10U %-10U %v",
		       format_time_float, 0, e->timestamp + time_offset,
		       format_vlib_log_level, e->level,
		       format_vlib_log_class, e->class, e->string);
      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 *
show_log_config (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_class_data_t *c;
  vlib_log_subclass_data_t *sc;

  vlib_cli_output (vm, "%-20s %u entries", "Buffer Size:", lm->size);
  vlib_cli_output (vm, "Defaults:\n");
  vlib_cli_output (vm, "%-20s %U", "  Log Level:",
		   format_vlib_log_level, lm->default_log_level);
  vlib_cli_output (vm, "%-20s %U", "  Syslog Log Level:",
		   format_vlib_log_level, lm->default_syslog_log_level);
  vlib_cli_output (vm, "%-20s %u msgs/sec", "  Rate Limit:",
		   lm->default_rate_limit);
  vlib_cli_output (vm, "\n");
  vlib_cli_output (vm, "%-22s %-14s %-14s %s",
		   "Class/Subclass", "Level", "Syslog Level", "Rate Limit");


  u8 *defstr = format (0, "default");
  vec_foreach (c, lm->classes)
  {
    vlib_cli_output (vm, "%v", c->name);
    vec_foreach (sc, c->subclasses)
    {
      vlib_cli_output (vm, "  %-20v %-14U %-14U %d",
		       sc->name ? sc->name : defstr,
		       format_vlib_log_level, sc->level,
		       format_vlib_log_level, sc->syslog_level,
		       sc->rate_limit);
    }
  }
  vec_free (defstr);

  return error;
}

/* *INDENT-OFF* */
VLIB_CLI_COMMAND (cli_show_log_config, static) = {
  .path = "show logging configuration",
  .short_help = "show logging configuration",
  .function = show_log_config,
};
/* *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, "%s", &level_str))
    {
#define _(v, uc, lc)                                   \
  const char __##uc[] = #lc;                           \
  if (!strcmp ((const char *) level_str, __##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;
      }
    }
  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 <level> <class> <subclass> <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;

  while (unformat_check_input (input) != UNFORMAT_END_OF_INPUT)
    {
      if (unformat (input, "size %d", &lm->size))
	vec_validate (lm->entries, lm->size);
      else if (unformat (input, "unthrottle-time %d", &lm->unthrottle_time))
	;
      else if (unformat (input, "default-log-level %U",
			 unformat_vlib_log_level, &lm->default_log_level))
	;
      else if (unformat (input, "default-syslog-log-level %U",
			 unformat_vlib_log_level,
			 &lm->default_syslog_log_level))
	;
      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:
 */