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