src/vlib/log.c

   1 /*
   2  * Copyright (c) 2018 Cisco and/or its affiliates.
   3  * Licensed under the Apache License, Version 2.0 (the "License");
   4  * you may not use this file except in compliance with the License.
   5  * You may obtain a copy of the License at:
   6  *
   7  *     http://www.apache.org/licenses/LICENSE-2.0
   8  *
   9  * Unless required by applicable law or agreed to in writing, software
  10  * distributed under the License is distributed on an "AS IS" BASIS,
  11  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  12  * See the License for the specific language governing permissions and
  13  * limitations under the License.
  14  */
  15
  16 #include <stdbool.h>
  17 #include <vlib/vlib.h>
  18 #include <vlib/log.h>
  19 #include <syslog.h>
  20
  21 typedef struct
  22 {
  23   vlib_log_level_t level;
  24   vlib_log_class_t class;
  25   f64 timestamp;
  26   u8 *string;
  27 } vlib_log_entry_t;
  28
  29 typedef struct
  30 {
  31   u32 index;
  32   u8 *name;
  33   // level of log messages kept for this subclass
  34   vlib_log_level_t level;
  35   // level of log messages sent to syslog for this subclass
  36   vlib_log_level_t syslog_level;
  37   // flag saying whether this subclass is logged to syslog
  38   f64 last_event_timestamp;
  39   int last_sec_count;
  40   int is_throttling;
  41   int rate_limit;
  42 } vlib_log_subclass_data_t;
  43
  44 typedef struct
  45 {
  46   u32 index;
  47   u8 *name;
  48   vlib_log_subclass_data_t *subclasses;
  49 } vlib_log_class_data_t;
  50
  51 typedef struct
  52 {
  53   vlib_log_entry_t *entries;
  54   vlib_log_class_data_t *classes;
  55   int size, next, count;
  56
  57   /* our own log class */
  58   vlib_log_class_t log_class;
  59
  60   int default_rate_limit;
  61   int default_log_level;
  62   int default_syslog_log_level;
  63   int unthrottle_time;
  64   u32 indent;
  65
  66   /* time zero */
  67   struct timeval time_zero_timeval;
  68   f64 time_zero;
  69
  70 } vlib_log_main_t;
  71
  72 vlib_log_main_t log_main = {
  73   .default_log_level = VLIB_LOG_LEVEL_NOTICE,
  74   .default_syslog_log_level = VLIB_LOG_LEVEL_WARNING,
  75   .unthrottle_time = 3,
  76   .size = 512,
  77   .default_rate_limit = 50,
  78 };
  79
  80 static int
  81 last_log_entry ()
  82 {
  83   vlib_log_main_t *lm = &log_main;
  84   int i;
  85
  86   i = lm->next - lm->count;
  87
  88   if (i < 0)
  89     i += lm->size;
  90   return i;
  91 }
  92
  93 static vlib_log_class_data_t *
  94 get_class_data (vlib_log_class_t ci)
  95 {
  96   vlib_log_main_t *lm = &log_main;
  97   return vec_elt_at_index (lm->classes, (ci >> 16));
  98 }
  99
 100 static vlib_log_subclass_data_t *
 101 get_subclass_data (vlib_log_class_t ci)
 102 {
 103   vlib_log_class_data_t *c = get_class_data (ci);
 104   return vec_elt_at_index (c->subclasses, (ci & 0xffff));
 105 }
 106
 107 static int
 108 vlib_log_level_to_syslog_priority (vlib_log_level_t level)
 109 {
 110   switch (level)
 111     {
 112 #define LOG_DISABLED LOG_DEBUG
 113 #define _(n,uc,lc) \
 114     case VLIB_LOG_LEVEL_##uc:\
 115       return LOG_##uc;
 116       foreach_vlib_log_level
 117 #undef _
 118 #undef LOG_DISABLED
 119     }
 120   return LOG_DEBUG;
 121 }
 122
 123 u8 *
 124 format_vlib_log_class (u8 * s, va_list * args)
 125 {
 126   vlib_log_class_t ci = va_arg (*args, vlib_log_class_t);
 127   vlib_log_class_data_t *c = get_class_data (ci);
 128   vlib_log_subclass_data_t *sc = get_subclass_data (ci);
 129
 130   if (sc->name)
 131     return format (s, "%v/%v", c->name, sc->name);
 132   else
 133     return format (s, "%v", c->name, 0);
 134 }
 135
 136
 137 void
 138 vlib_log (vlib_log_level_t level, vlib_log_class_t class, char *fmt, ...)
 139 {
 140   vlib_main_t *vm = vlib_get_main ();
 141   vlib_log_main_t *lm = &log_main;
 142   vlib_log_entry_t *e;
 143   vlib_log_subclass_data_t *sc = get_subclass_data (class);
 144   va_list va;
 145   f64 t = vlib_time_now (vm);
 146   f64 delta = t - sc->last_event_timestamp;
 147   u8 *s = 0;
 148   bool use_formatted_log_entry = true;
 149
 150   vec_validate (lm->entries, lm->size);
 151   /* make sure we are running on the main thread to avoid use in dataplane
 152      code, for dataplane logging consider use of event-logger */
 153   ASSERT (vlib_get_thread_index () == 0);
 154
 155   if (level > sc->level)
 156     {
 157       use_formatted_log_entry = false;
 158       goto syslog;
 159     }
 160
 161   if ((delta > lm->unthrottle_time) ||
 162       (sc->is_throttling == 0 && (delta > 1)))
 163     {
 164       sc->last_event_timestamp = t;
 165       sc->last_sec_count = 0;
 166       sc->is_throttling = 0;
 167     }
 168   else
 169     {
 170       sc->last_sec_count++;
 171       if (sc->last_sec_count > sc->rate_limit)
 172         return;
 173       else if (sc->last_sec_count == sc->rate_limit)
 174         {
 175           vec_reset_length (s);
 176           s = format (0, "--- message(s) throttled ---");
 177           sc->is_throttling = 1;
 178         }
 179     }
 180
 181   if (s == 0)
 182     {
 183       va_start (va, fmt);
 184       s = va_format (s, fmt, &va);
 185       va_end (va);
 186     }
 187
 188   e = vec_elt_at_index (lm->entries, lm->next);
 189   vec_free (e->string);
 190   e->level = level;
 191   e->class = class;
 192   e->string = s;
 193   e->timestamp = t;
 194
 195   lm->next = (lm->next + 1) % lm->size;
 196   if (lm->size > lm->count)
 197     lm->count++;
 198
 199 syslog:
 200   if (sc->syslog_level != VLIB_LOG_LEVEL_DISABLED &&
 201       level <= sc->syslog_level)
 202     {
 203       u8 *tmp = format (NULL, "%U", format_vlib_log_class, class);
 204       if (use_formatted_log_entry)
 205         {
 206           syslog (vlib_log_level_to_syslog_priority (level), "%.*s: %.*s",
 207                   (int) vec_len (tmp), tmp,
 208                   (int) (vec_len (s) -
 209                          (vec_c_string_is_terminated (s) ? 1 : 0)), s);
 210         }
 211       else
 212         {
 213           tmp = format (tmp, ": ");
 214           va_start (va, fmt);
 215           tmp = va_format (tmp, fmt, &va);
 216           va_end (va);
 217           syslog (vlib_log_level_to_syslog_priority (level), "%.*s",
 218                   (int) (vec_len (tmp) -
 219                          (vec_c_string_is_terminated (tmp) ? 1 : 0)), tmp);
 220         }
 221       vec_free (tmp);
 222     }
 223
 224 }
 225
 226 vlib_log_class_t
 227 vlib_log_register_class (char *class, char *subclass)
 228 {
 229   vlib_log_main_t *lm = &log_main;
 230   vlib_log_class_data_t *c = NULL;
 231   vlib_log_subclass_data_t *s;
 232   vlib_log_class_data_t *tmp;
 233   vec_foreach (tmp, lm->classes)
 234   {
 235     if (!memcmp (class, tmp->name, vec_len (tmp->name)))
 236       {
 237         c = tmp;
 238         break;
 239       }
 240   }
 241   if (!c)
 242     {
 243       vec_add2 (lm->classes, c, 1);
 244       c->index = c - lm->classes;
 245       c->name = format (0, "%s", class);
 246     }
 247
 248   vec_add2 (c->subclasses, s, 1);
 249   s->index = s - c->subclasses;
 250   s->name = subclass ? format (0, "%s", subclass) : 0;
 251   s->rate_limit = lm->default_rate_limit;
 252   s->level = lm->default_log_level;
 253   s->syslog_level = lm->default_syslog_log_level;
 254   return (c->index << 16) | (s->index);
 255 }
 256
 257 u8 *
 258 format_vlib_log_level (u8 * s, va_list * args)
 259 {
 260   vlib_log_level_t i = va_arg (*args, vlib_log_level_t);
 261   char *t = 0;
 262
 263   switch (i)
 264     {
 265 #define _(v,uc,lc) case VLIB_LOG_LEVEL_##uc: t = #lc; break;
 266       foreach_vlib_log_level
 267 #undef _
 268     default:
 269       return format (s, "unknown");
 270     }
 271   return format (s, "%s", t);
 272 }
 273
 274 u32
 275 vlib_log_get_indent ()
 276 {
 277   return log_main.indent;
 278 }
 279
 280 static clib_error_t *
 281 vlib_log_init (vlib_main_t * vm)
 282 {
 283   vlib_log_main_t *lm = &log_main;
 284
 285   gettimeofday (&lm->time_zero_timeval, 0);
 286   lm->time_zero = vlib_time_now (vm);
 287
 288   vec_validate (lm->entries, lm->size);
 289   lm->log_class = vlib_log_register_class ("log", 0);
 290   u8 *tmp = format (NULL, "%U %-10U %-10U ", format_time_float, 0, (f64) 0,
 291                     format_white_space, 255, format_white_space, 255);
 292   log_main.indent = vec_len (tmp);
 293   vec_free (tmp);
 294   return 0;
 295 }
 296
 297 VLIB_INIT_FUNCTION (vlib_log_init);
 298
 299
 300 static clib_error_t *
 301 show_log (vlib_main_t * vm,
 302           unformat_input_t * input, vlib_cli_command_t * cmd)
 303 {
 304   clib_error_t *error = 0;
 305   vlib_log_main_t *lm = &log_main;
 306   vlib_log_entry_t *e;
 307   int i = last_log_entry ();
 308   int count = lm->count;
 309   f64 time_offset;
 310
 311   time_offset = (f64) lm->time_zero_timeval.tv_sec
 312     + (((f64) lm->time_zero_timeval.tv_usec) * 1e-6) - lm->time_zero;
 313
 314   while (count--)
 315     {
 316       e = vec_elt_at_index (lm->entries, i);
 317       vlib_cli_output (vm, "%U %-10U %-10U %v",
 318                        format_time_float, 0, e->timestamp + time_offset,
 319                        format_vlib_log_level, e->level,
 320                        format_vlib_log_class, e->class, e->string);
 321       i = (i + 1) % lm->size;
 322     }
 323
 324   return error;
 325 }
 326
 327 /* *INDENT-OFF* */
 328 VLIB_CLI_COMMAND (cli_show_log, static) = {
 329   .path = "show logging",
 330   .short_help = "show logging",
 331   .function = show_log,
 332 };
 333 /* *INDENT-ON* */
 334
 335 static clib_error_t *
 336 show_log_config (vlib_main_t * vm,
 337                  unformat_input_t * input, vlib_cli_command_t * cmd)
 338 {
 339   clib_error_t *error = 0;
 340   vlib_log_main_t *lm = &log_main;
 341   vlib_log_class_data_t *c;
 342   vlib_log_subclass_data_t *sc;
 343
 344   vlib_cli_output (vm, "%-20s %u entries", "Buffer Size:", lm->size);
 345   vlib_cli_output (vm, "Defaults:\n");
 346   vlib_cli_output (vm, "%-20s %U", "  Log Level:",
 347                    format_vlib_log_level, lm->default_log_level);
 348   vlib_cli_output (vm, "%-20s %U", "  Syslog Log Level:",
 349                    format_vlib_log_level, lm->default_syslog_log_level);
 350   vlib_cli_output (vm, "%-20s %u msgs/sec", "  Rate Limit:",
 351                    lm->default_rate_limit);
 352   vlib_cli_output (vm, "\n");
 353   vlib_cli_output (vm, "%-22s %-14s %-14s %s",
 354                    "Class/Subclass", "Level", "Syslog Level", "Rate Limit");
 355
 356
 357   u8 *defstr = format (0, "default");
 358   vec_foreach (c, lm->classes)
 359   {
 360     vlib_cli_output (vm, "%v", c->name);
 361     vec_foreach (sc, c->subclasses)
 362     {
 363       vlib_cli_output (vm, "  %-20v %-14U %-14U %d",
 364                        sc->name ? sc->name : defstr,
 365                        format_vlib_log_level, sc->level,
 366                        format_vlib_log_level, sc->syslog_level,
 367                        sc->rate_limit);
 368     }
 369   }
 370   vec_free (defstr);
 371
 372   return error;
 373 }
 374
 375 /* *INDENT-OFF* */
 376 VLIB_CLI_COMMAND (cli_show_log_config, static) = {
 377   .path = "show logging configuration",
 378   .short_help = "show logging configuration",
 379   .function = show_log_config,
 380 };
 381 /* *INDENT-ON* */
 382
 383 static clib_error_t *
 384 clear_log (vlib_main_t * vm,
 385            unformat_input_t * input, vlib_cli_command_t * cmd)
 386 {
 387   clib_error_t *error = 0;
 388   vlib_log_main_t *lm = &log_main;
 389   vlib_log_entry_t *e;
 390   int i = last_log_entry ();
 391   int count = lm->count;
 392
 393   while (count--)
 394     {
 395       e = vec_elt_at_index (lm->entries, i);
 396       vec_free (e->string);
 397       i = (i + 1) % lm->size;
 398     }
 399
 400   lm->count = 0;
 401   lm->next = 0;
 402   vlib_log_info (lm->log_class, "log cleared");
 403   return error;
 404 }
 405
 406 /* *INDENT-OFF* */
 407 VLIB_CLI_COMMAND (cli_clear_log, static) = {
 408   .path = "clear logging",
 409   .short_help = "clear logging",
 410   .function = clear_log,
 411 };
 412 /* *INDENT-ON* */
 413
 414 static uword
 415 unformat_vlib_log_level (unformat_input_t * input, va_list * args)
 416 {
 417   vlib_log_level_t *level = va_arg (*args, vlib_log_level_t *);
 418   u8 *level_str = NULL;
 419   uword rv = 1;
 420   if (unformat (input, "%s", &level_str))
 421     {
 422 #define _(v, uc, lc)                                   \
 423   const char __##uc[] = #lc;                           \
 424   if (!strcmp ((const char *) level_str, __##uc))       \
 425     {                                                  \
 426       *level = VLIB_LOG_LEVEL_##uc;                 \
 427       rv = 1;                                          \
 428       goto done;                                       \
 429     }
 430       foreach_vlib_log_level;
 431       rv = 0;
 432 #undef _
 433     }
 434 done:
 435   vec_free (level_str);
 436   return rv;
 437 }
 438
 439 static uword
 440 unformat_vlib_log_class (unformat_input_t * input, va_list * args)
 441 {
 442   vlib_log_class_data_t **class = va_arg (*args, vlib_log_class_data_t **);
 443   uword rv = 0;
 444   u8 *class_str = NULL;
 445   vlib_log_main_t *lm = &log_main;
 446   if (unformat (input, "%v", &class_str))
 447     {
 448       vlib_log_class_data_t *cdata;
 449       vec_foreach (cdata, lm->classes)
 450       {
 451         if (vec_is_equal (cdata->name, class_str))
 452           {
 453             *class = cdata;
 454             rv = 1;
 455             break;
 456           }
 457       }
 458     }
 459   vec_free (class_str);
 460   return rv;
 461 }
 462
 463 static clib_error_t *
 464 set_log_class (vlib_main_t * vm,
 465                unformat_input_t * input, vlib_cli_command_t * cmd)
 466 {
 467   unformat_input_t _line_input, *line_input = &_line_input;
 468   clib_error_t *rv = NULL;
 469   int rate_limit;
 470   bool set_rate_limit = false;
 471   bool set_level = false;
 472   bool set_syslog_level = false;
 473   vlib_log_level_t level;
 474   vlib_log_level_t syslog_level;
 475
 476   /* Get a line of input. */
 477   if (!unformat_user (input, unformat_line_input, line_input))
 478     return 0;
 479
 480   vlib_log_class_data_t *class = NULL;
 481   if (!unformat (line_input, "%U", unformat_vlib_log_class, &class))
 482     {
 483       return clib_error_return (0, "unknown log class `%U'",
 484                                 format_unformat_error, line_input);
 485     }
 486   while (unformat_check_input (line_input) != UNFORMAT_END_OF_INPUT)
 487     {
 488       if (unformat (line_input, "rate-limit %d", &rate_limit))
 489         {
 490           set_rate_limit = true;
 491         }
 492       else
 493         if (unformat
 494             (line_input, "level %U", unformat_vlib_log_level, &level))
 495         {
 496           set_level = true;
 497         }
 498       else
 499         if (unformat
 500             (line_input, "syslog-level %U", unformat_vlib_log_level,
 501              &syslog_level))
 502         {
 503           set_syslog_level = true;
 504         }
 505       else
 506         {
 507           return clib_error_return (0, "unknown input `%U'",
 508                                     format_unformat_error, line_input);
 509         }
 510     }
 511
 512   if (set_level)
 513     {
 514       vlib_log_subclass_data_t *subclass;
 515       vec_foreach (subclass, class->subclasses)
 516       {
 517         subclass->level = level;
 518       }
 519     }
 520   if (set_syslog_level)
 521     {
 522       vlib_log_subclass_data_t *subclass;
 523       vec_foreach (subclass, class->subclasses)
 524       {
 525         subclass->syslog_level = syslog_level;
 526       }
 527     }
 528   if (set_rate_limit)
 529     {
 530       vlib_log_subclass_data_t *subclass;
 531       vec_foreach (subclass, class->subclasses)
 532       {
 533         subclass->rate_limit = rate_limit;
 534       }
 535     }
 536
 537   return rv;
 538 }
 539
 540 /* *INDENT-OFF* */
 541 VLIB_CLI_COMMAND (cli_set_log, static) = {
 542   .path = "set logging class",
 543   .short_help = "set loggging class <class> [rate-limit <int>] "
 544     "[level <level>] [syslog-level <level>]",
 545   .function = set_log_class,
 546 };
 547 /* *INDENT-ON* */
 548
 549 static clib_error_t *
 550 set_log_unth_time (vlib_main_t * vm,
 551                    unformat_input_t * input, vlib_cli_command_t * cmd)
 552 {
 553   unformat_input_t _line_input, *line_input = &_line_input;
 554   clib_error_t *rv = NULL;
 555   int unthrottle_time;
 556   vlib_log_main_t *lm = &log_main;
 557
 558   /* Get a line of input. */
 559   if (!unformat_user (input, unformat_line_input, line_input))
 560     return 0;
 561
 562   while (unformat_check_input (line_input) != UNFORMAT_END_OF_INPUT)
 563     {
 564       if (unformat (line_input, "%d", &unthrottle_time))
 565         lm->unthrottle_time = unthrottle_time;
 566       else
 567         return clib_error_return (0, "unknown input `%U'",
 568                                   format_unformat_error, line_input);
 569     }
 570
 571   return rv;
 572 }
 573
 574 /* *INDENT-OFF* */
 575 VLIB_CLI_COMMAND (cli_set_log_params, static) = {
 576   .path = "set logging unthrottle-time",
 577   .short_help = "set logging unthrottle-time <int>",
 578   .function = set_log_unth_time,
 579 };
 580 /* *INDENT-ON* */
 581
 582 static clib_error_t *
 583 set_log_size (vlib_main_t * vm,
 584               unformat_input_t * input, vlib_cli_command_t * cmd)
 585 {
 586   unformat_input_t _line_input, *line_input = &_line_input;
 587   clib_error_t *rv = NULL;
 588   int size;
 589   vlib_log_main_t *lm = &log_main;
 590
 591   /* Get a line of input. */
 592   if (!unformat_user (input, unformat_line_input, line_input))
 593     return 0;
 594
 595   while (unformat_check_input (line_input) != UNFORMAT_END_OF_INPUT)
 596     {
 597       if (unformat (line_input, "%d", &size))
 598         {
 599           lm->size = size;
 600           vec_validate (lm->entries, lm->size);
 601         }
 602       else
 603         return clib_error_return (0, "unknown input `%U'",
 604                                   format_unformat_error, line_input);
 605     }
 606
 607   return rv;
 608 }
 609
 610 /* *INDENT-OFF* */
 611 VLIB_CLI_COMMAND (cli_set_log_size, static) = {
 612   .path = "set logging size",
 613   .short_help = "set logging size <int>",
 614   .function = set_log_size,
 615 };
 616 /* *INDENT-ON* */
 617
 618 static uword
 619 unformat_vlib_log_subclass (unformat_input_t * input, va_list * args)
 620 {
 621   vlib_log_class_data_t *class = va_arg (*args, vlib_log_class_data_t *);
 622   vlib_log_subclass_data_t **subclass =
 623     va_arg (*args, vlib_log_subclass_data_t **);
 624   uword rv = 0;
 625   u8 *subclass_str = NULL;
 626   if (unformat (input, "%v", &subclass_str))
 627     {
 628       vlib_log_subclass_data_t *scdata;
 629       vec_foreach (scdata, class->subclasses)
 630       {
 631         if (vec_is_equal (scdata->name, subclass_str))
 632           {
 633             rv = 1;
 634             *subclass = scdata;
 635             break;
 636           }
 637       }
 638     }
 639   vec_free (subclass_str);
 640   return rv;
 641 }
 642
 643 static clib_error_t *
 644 test_log_class_subclass (vlib_main_t * vm,
 645                          unformat_input_t * input, vlib_cli_command_t * cmd)
 646 {
 647   unformat_input_t _line_input, *line_input = &_line_input;
 648   /* Get a line of input. */
 649   if (!unformat_user (input, unformat_line_input, line_input))
 650     return 0;
 651
 652   vlib_log_class_data_t *class = NULL;
 653   vlib_log_subclass_data_t *subclass = NULL;
 654   vlib_log_level_t level;
 655   if (unformat (line_input, "%U", unformat_vlib_log_level, &level))
 656     {
 657       if (unformat (line_input, "%U", unformat_vlib_log_class, &class))
 658         {
 659           if (unformat
 660               (line_input, "%U", unformat_vlib_log_subclass, class,
 661                &subclass))
 662             {
 663               vlib_log (level,
 664                         (class->index << 16) | (subclass->index), "%U",
 665                         format_unformat_input, line_input);
 666             }
 667           else
 668             {
 669               return clib_error_return (0,
 670                                         "unknown log subclass near beginning of `%U'",
 671                                         format_unformat_error, line_input);
 672             }
 673         }
 674       else
 675         {
 676           return clib_error_return (0,
 677                                     "unknown log class near beginning of `%U'",
 678                                     format_unformat_error, line_input);
 679         }
 680     }
 681   else
 682     {
 683       return clib_error_return (0, "unknown log level near beginning of `%U'",
 684                                 format_unformat_error, line_input);
 685     }
 686   return 0;
 687 }
 688
 689 /* *INDENT-OFF* */
 690 VLIB_CLI_COMMAND (cli_test_log, static) = {
 691   .path = "test log",
 692   .short_help = "test log <class> <subclass> <level> <message",
 693   .function = test_log_class_subclass,
 694 };
 695 /* *INDENT-ON* */
 696
 697 static clib_error_t *
 698 log_config (vlib_main_t * vm, unformat_input_t * input)
 699 {
 700   vlib_log_main_t *lm = &log_main;
 701
 702   while (unformat_check_input (input) != UNFORMAT_END_OF_INPUT)
 703     {
 704       if (unformat (input, "size %d", &lm->size))
 705         vec_validate (lm->entries, lm->size);
 706       else if (unformat (input, "unthrottle-time %d", &lm->unthrottle_time))
 707         ;
 708       else if (unformat (input, "default-log-level %U",
 709                          unformat_vlib_log_level, &lm->default_log_level))
 710         ;
 711       else if (unformat (input, "default-syslog-log-level %U",
 712                          unformat_vlib_log_level,
 713                          &lm->default_syslog_log_level))
 714         ;
 715       else
 716         {
 717           return unformat_parse_error (input);
 718         }
 719     }
 720
 721   return 0;
 722 }
 723
 724 VLIB_EARLY_CONFIG_FUNCTION (log_config, "logging");
 725
 726 /*
 727  * fd.io coding-style-patch-verification: ON
 728  *
 729  * Local Variables:
 730  * eval: (c-set-style "gnu")
 731  * End:
 732  */