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