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