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