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