lib/vlog.c

   1 /* Copyright (c) 2008 The Board of Trustees of The Leland Stanford
   2  * Junior University
   3  *
   4  * We are making the OpenFlow specification and associated documentation
   5  * (Software) available for public use and benefit with the expectation
   6  * that others will use, modify and enhance the Software and contribute
   7  * those enhancements back to the community. However, since we would
   8  * like to make the Software available for broadest use, with as few
   9  * restrictions as possible permission is hereby granted, free of
  10  * charge, to any person obtaining a copy of this Software to deal in
  11  * the Software under the copyrights without restriction, including
  12  * without limitation the rights to use, copy, modify, merge, publish,
  13  * distribute, sublicense, and/or sell copies of the Software, and to
  14  * permit persons to whom the Software is furnished to do so, subject to
  15  * the following conditions:
  16  *
  17  * The above copyright notice and this permission notice shall be
  18  * included in all copies or substantial portions of the Software.
  19  *
  20  * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
  21  * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
  22  * MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
  23  * NONINFRINGEMENT.  IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS
  24  * BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN
  25  * ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN
  26  * CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE
  27  * SOFTWARE.
  28  *
  29  * The name and trademarks of copyright holder(s) may NOT be used in
  30  * advertising or publicity pertaining to the Software or any
  31  * derivatives without specific, written prior permission.
  32  */
  33
  34 #include <config.h>
  35 #include "vlog.h"
  36 #include <assert.h>
  37 #include <ctype.h>
  38 #include <errno.h>
  39 #include <stdarg.h>
  40 #include <stdlib.h>
  41 #include <string.h>
  42 #include <sys/types.h>
  43 #include <syslog.h>
  44 #include <time.h>
  45 #include <unistd.h>
  46 #include "dynamic-string.h"
  47 #include "sat-math.h"
  48 #include "timeval.h"
  49 #include "util.h"
  50
  51 #define THIS_MODULE VLM_vlog
  52
  53 /* Name for each logging level. */
  54 static const char *level_names[VLL_N_LEVELS] = {
  55 #define VLOG_LEVEL(NAME, SYSLOG_LEVEL) #NAME,
  56     VLOG_LEVELS
  57 #undef VLOG_LEVEL
  58 };
  59
  60 /* Syslog value for each logging level. */
  61 static int syslog_levels[VLL_N_LEVELS] = {
  62 #define VLOG_LEVEL(NAME, SYSLOG_LEVEL) SYSLOG_LEVEL,
  63     VLOG_LEVELS
  64 #undef VLOG_LEVEL
  65 };
  66
  67 /* Name for each logging module */
  68 static const char *module_names[VLM_N_MODULES] = {
  69 #define VLOG_MODULE(NAME) #NAME,
  70 #include "vlog-modules.def"
  71 #undef VLOG_MODULE
  72 };
  73
  74 /* Information about each facility. */
  75 struct facility {
  76     const char *name;           /* Name. */
  77     char *pattern;              /* Current pattern. */
  78     bool default_pattern;       /* Whether current pattern is the default. */
  79 };
  80 static struct facility facilities[VLF_N_FACILITIES] = {
  81 #define VLOG_FACILITY(NAME, PATTERN) {#NAME, PATTERN, true},
  82     VLOG_FACILITIES
  83 #undef VLOG_FACILITY
  84 };
  85
  86 /* Current log levels. */
  87 static int levels[VLM_N_MODULES][VLF_N_FACILITIES];
  88
  89 /* For fast checking whether we're logging anything for a given module and
  90  * level.*/
  91 enum vlog_level min_vlog_levels[VLM_N_MODULES];
  92
  93 /* Time at which vlog was initialized, in milliseconds. */
  94 static long long int boot_time;
  95
  96 /* Searches the 'n_names' in 'names'.  Returns the index of a match for
  97  * 'target', or 'n_names' if no name matches. */
  98 static size_t
  99 search_name_array(const char *target, const char **names, size_t n_names)
 100 {
 101     size_t i;
 102
 103     for (i = 0; i < n_names; i++) {
 104         assert(names[i]);
 105         if (!strcasecmp(names[i], target)) {
 106             break;
 107         }
 108     }
 109     return i;
 110 }
 111
 112 /* Returns the name for logging level 'level'. */
 113 const char *
 114 vlog_get_level_name(enum vlog_level level)
 115 {
 116     assert(level < VLL_N_LEVELS);
 117     return level_names[level];
 118 }
 119
 120 /* Returns the logging level with the given 'name', or VLL_N_LEVELS if 'name'
 121  * is not the name of a logging level. */
 122 enum vlog_level
 123 vlog_get_level_val(const char *name)
 124 {
 125     return search_name_array(name, level_names, ARRAY_SIZE(level_names));
 126 }
 127
 128 /* Returns the name for logging facility 'facility'. */
 129 const char *
 130 vlog_get_facility_name(enum vlog_facility facility)
 131 {
 132     assert(facility < VLF_N_FACILITIES);
 133     return facilities[facility].name;
 134 }
 135
 136 /* Returns the logging facility named 'name', or VLF_N_FACILITIES if 'name' is
 137  * not the name of a logging facility. */
 138 enum vlog_facility
 139 vlog_get_facility_val(const char *name)
 140 {
 141     size_t i;
 142
 143     for (i = 0; i < VLF_N_FACILITIES; i++) {
 144         if (!strcasecmp(facilities[i].name, name)) {
 145             break;
 146         }
 147     }
 148     return i;
 149 }
 150
 151 /* Returns the name for logging module 'module'. */
 152 const char *vlog_get_module_name(enum vlog_module module)
 153 {
 154     assert(module < VLM_N_MODULES);
 155     return module_names[module];
 156 }
 157
 158 /* Returns the logging module named 'name', or VLM_N_MODULES if 'name' is not
 159  * the name of a logging module. */
 160 enum vlog_module
 161 vlog_get_module_val(const char *name)
 162 {
 163     return search_name_array(name, module_names, ARRAY_SIZE(module_names));
 164 }
 165
 166 /* Returns the current logging level for the given 'module' and 'facility'. */
 167 enum vlog_level
 168 vlog_get_level(enum vlog_module module, enum vlog_facility facility)
 169 {
 170     assert(module < VLM_N_MODULES);
 171     assert(facility < VLF_N_FACILITIES);
 172     return levels[module][facility];
 173 }
 174
 175 static void
 176 update_min_level(enum vlog_module module)
 177 {
 178     enum vlog_level min_level = VLL_EMER;
 179     enum vlog_facility facility;
 180
 181     for (facility = 0; facility < VLF_N_FACILITIES; facility++) {
 182         min_level = MAX(min_level, levels[module][facility]);
 183     }
 184     min_vlog_levels[module] = min_level;
 185 }
 186
 187 static void
 188 set_facility_level(enum vlog_facility facility, enum vlog_module module,
 189                    enum vlog_level level)
 190 {
 191     assert(facility >= 0 && facility < VLF_N_FACILITIES);
 192     assert(level < VLL_N_LEVELS);
 193
 194     if (module == VLM_ANY_MODULE) {
 195         for (module = 0; module < VLM_N_MODULES; module++) {
 196             levels[module][facility] = level;
 197             update_min_level(module);
 198         }
 199     } else {
 200         levels[module][facility] = level;
 201         update_min_level(module);
 202     }
 203 }
 204
 205 /* Sets the logging level for the given 'module' and 'facility' to 'level'. */
 206 void
 207 vlog_set_levels(enum vlog_module module, enum vlog_facility facility,
 208                 enum vlog_level level)
 209 {
 210     assert(facility < VLF_N_FACILITIES || facility == VLF_ANY_FACILITY);
 211     if (facility == VLF_ANY_FACILITY) {
 212         for (facility = 0; facility < VLF_N_FACILITIES; facility++) {
 213             set_facility_level(facility, module, level);
 214         }
 215     } else {
 216         set_facility_level(facility, module, level);
 217     }
 218 }
 219
 220 static void
 221 do_set_pattern(enum vlog_facility facility, const char *pattern)
 222 {
 223     struct facility *f = &facilities[facility];
 224     if (!f->default_pattern) {
 225         free(f->pattern);
 226     } else {
 227         f->default_pattern = false;
 228     }
 229     f->pattern = xstrdup(pattern);
 230 }
 231
 232 /* Sets the pattern for the given 'facility' to 'pattern'. */
 233 void
 234 vlog_set_pattern(enum vlog_facility facility, const char *pattern)
 235 {
 236     assert(facility < VLF_N_FACILITIES || facility == VLF_ANY_FACILITY);
 237     if (facility == VLF_ANY_FACILITY) {
 238         for (facility = 0; facility < VLF_N_FACILITIES; facility++) {
 239             do_set_pattern(facility, pattern);
 240         }
 241     } else {
 242         do_set_pattern(facility, pattern);
 243     }
 244 }
 245
 246 /* Set debugging levels:
 247  *
 248  *  mod[:facility[:level]] mod2[:facility[:level]] ...
 249  *
 250  * Return null if successful, otherwise an error message that the caller must
 251  * free().
 252  */
 253 char *
 254 vlog_set_levels_from_string(const char *s_)
 255 {
 256     char *save_ptr;
 257     char *s = xstrdup(s_);
 258     char *module, *facility;
 259
 260     for (module = strtok_r(s, ": \t", &save_ptr); module != NULL;
 261          module = strtok_r(NULL, ": \t", &save_ptr)) {
 262         enum vlog_module e_module;
 263         enum vlog_facility e_facility;
 264
 265         facility = strtok_r(NULL, ":", &save_ptr);
 266
 267         if (!facility || !strcmp(facility, "ANY")) {
 268             e_facility = VLF_ANY_FACILITY;
 269         } else {
 270             e_facility = vlog_get_facility_val(facility);
 271             if (e_facility >= VLF_N_FACILITIES) {
 272                 char *msg = xasprintf("unknown facility \"%s\"", facility);
 273                 free(s);
 274                 return msg;
 275             }
 276         }
 277
 278         if (!strcmp(module, "PATTERN")) {
 279             vlog_set_pattern(e_facility, save_ptr);
 280             break;
 281         } else {
 282             char *level;
 283             enum vlog_level e_level;
 284
 285             if (!strcmp(module, "ANY")) {
 286                 e_module = VLM_ANY_MODULE;
 287             } else {
 288                 e_module = vlog_get_module_val(module);
 289                 if (e_module >= VLM_N_MODULES) {
 290                     char *msg = xasprintf("unknown module \"%s\"", module);
 291                     free(s);
 292                     return msg;
 293                 }
 294             }
 295
 296             level = strtok_r(NULL, ":", &save_ptr);
 297             e_level = level ? vlog_get_level_val(level) : VLL_DBG;
 298             if (e_level >= VLL_N_LEVELS) {
 299                 char *msg = xasprintf("unknown level \"%s\"", level);
 300                 free(s);
 301                 return msg;
 302             }
 303
 304             vlog_set_levels(e_module, e_facility, e_level);
 305         }
 306     }
 307     free(s);
 308     return NULL;
 309 }
 310
 311 /* If 'arg' is null, configure maximum verbosity.  Otherwise, sets
 312  * configuration according to 'arg' (see vlog_set_levels_from_string()). */
 313 void
 314 vlog_set_verbosity(const char *arg)
 315 {
 316     if (arg) {
 317         char *msg = vlog_set_levels_from_string(arg);
 318         if (msg) {
 319             ofp_fatal(0, "processing \"%s\": %s", arg, msg);
 320         }
 321     } else {
 322         vlog_set_levels(VLM_ANY_MODULE, VLF_ANY_FACILITY, VLL_DBG);
 323     }
 324 }
 325
 326 /* Initializes the logging subsystem. */
 327 void
 328 vlog_init(void)
 329 {
 330     time_t now;
 331
 332     openlog(program_name, LOG_NDELAY, LOG_DAEMON);
 333     vlog_set_levels(VLM_ANY_MODULE, VLF_ANY_FACILITY, VLL_WARN);
 334
 335     boot_time = time_msec();
 336     now = time_now();
 337     if (now < 0) {
 338         struct tm tm;
 339         char s[128];
 340
 341         localtime_r(&now, &tm);
 342         strftime(s, sizeof s, "%a, %d %b %Y %H:%M:%S %z", &tm);
 343         VLOG_ERR("current time is negative: %s (%ld)", s, (long int) now);
 344     }
 345 }
 346
 347 /* Closes the logging subsystem. */
 348 void
 349 vlog_exit(void)
 350 {
 351     closelog();
 352 }
 353
 354 /* Print the current logging level for each module. */
 355 char *
 356 vlog_get_levels(void)
 357 {
 358     struct ds s = DS_EMPTY_INITIALIZER;
 359     enum vlog_module module;
 360
 361     ds_put_format(&s, "                 console    syslog\n");
 362     ds_put_format(&s, "                 -------    ------\n");
 363
 364     for (module = 0; module < VLM_N_MODULES; module++) {
 365         ds_put_format(&s, "%-16s  %4s       %4s\n",
 366            vlog_get_module_name(module),
 367            vlog_get_level_name(vlog_get_level(module, VLF_CONSOLE)),
 368            vlog_get_level_name(vlog_get_level(module, VLF_SYSLOG)));
 369     }
 370
 371     return ds_cstr(&s);
 372 }
 373
 374 /* Returns true if a log message emitted for the given 'module' and 'level'
 375  * would cause some log output, false if that module and level are completely
 376  * disabled. */
 377 bool
 378 vlog_is_enabled(enum vlog_module module, enum vlog_level level)
 379 {
 380     return min_vlog_levels[module] >= level;
 381 }
 382
 383 static const char *
 384 fetch_braces(const char *p, const char *def, char *out, size_t out_size)
 385 {
 386     if (*p == '{') {
 387         size_t n = strcspn(p + 1, "}");
 388         size_t n_copy = MIN(n, out_size - 1);
 389         memcpy(out, p + 1, n_copy);
 390         out[n_copy] = '\0';
 391         p += n + 2;
 392     } else {
 393         strlcpy(out, def, out_size);
 394     }
 395     return p;
 396 }
 397
 398 static void
 399 format_log_message(enum vlog_module module, enum vlog_level level,
 400                    enum vlog_facility facility, unsigned int msg_num,
 401                    const char *message, va_list args_, struct ds *s)
 402 {
 403     char tmp[128];
 404     va_list args;
 405     const char *p;
 406
 407     ds_clear(s);
 408     for (p = facilities[facility].pattern; *p != '\0'; ) {
 409         enum { LEFT, RIGHT } justify = RIGHT;
 410         int pad = '0';
 411         size_t length, field, used;
 412
 413         if (*p != '%') {
 414             ds_put_char(s, *p++);
 415             continue;
 416         }
 417
 418         p++;
 419         if (*p == '-') {
 420             justify = LEFT;
 421             p++;
 422         }
 423         if (*p == '0') {
 424             pad = '0';
 425             p++;
 426         }
 427         field = 0;
 428         while (isdigit(*p)) {
 429             field = (field * 10) + (*p - '0');
 430             p++;
 431         }
 432
 433         length = s->length;
 434         switch (*p++) {
 435         case 'A':
 436             ds_put_cstr(s, program_name);
 437             break;
 438         case 'c':
 439             p = fetch_braces(p, "", tmp, sizeof tmp);
 440             ds_put_cstr(s, vlog_get_module_name(module));
 441             break;
 442         case 'd':
 443             p = fetch_braces(p, "%Y-%m-%d %H:%M:%S", tmp, sizeof tmp);
 444             ds_put_strftime(s, tmp, NULL);
 445             break;
 446         case 'm':
 447             va_copy(args, args_);
 448             ds_put_format_valist(s, message, args);
 449             va_end(args);
 450             break;
 451         case 'N':
 452             ds_put_format(s, "%u", msg_num);
 453             break;
 454         case 'n':
 455             ds_put_char(s, '\n');
 456             break;
 457         case 'p':
 458             ds_put_cstr(s, vlog_get_level_name(level));
 459             break;
 460         case 'P':
 461             ds_put_format(s, "%ld", (long int) getpid());
 462             break;
 463         case 'r':
 464             ds_put_format(s, "%lld", time_msec() - boot_time);
 465             break;
 466         default:
 467             ds_put_char(s, p[-1]);
 468             break;
 469         }
 470         used = s->length - length;
 471         if (used < field) {
 472             size_t n_pad = field - used;
 473             if (justify == RIGHT) {
 474                 ds_put_uninit(s, n_pad);
 475                 memmove(&s->string[length + n_pad], &s->string[length], used);
 476                 memset(&s->string[length], pad, n_pad);
 477             } else {
 478                 ds_put_char_multiple(s, pad, n_pad);
 479             }
 480         }
 481     }
 482 }
 483
 484 /* Writes 'message' to the log at the given 'level' and as coming from the
 485  * given 'module'.
 486  *
 487  * Guaranteed to preserve errno. */
 488 void
 489 vlog_valist(enum vlog_module module, enum vlog_level level,
 490             const char *message, va_list args)
 491 {
 492     bool log_console = levels[module][VLF_CONSOLE] >= level;
 493     bool log_syslog = levels[module][VLF_SYSLOG] >= level;
 494     if (log_console || log_syslog) {
 495         int save_errno = errno;
 496         static unsigned int msg_num;
 497         struct ds s;
 498
 499         ds_init(&s);
 500         ds_reserve(&s, 1024);
 501         msg_num++;
 502
 503         if (log_console) {
 504             format_log_message(module, level, VLF_CONSOLE, msg_num,
 505                                message, args, &s);
 506             ds_put_char(&s, '\n');
 507             fputs(ds_cstr(&s), stderr);
 508         }
 509
 510         if (log_syslog) {
 511             int syslog_level = syslog_levels[level];
 512             char *save_ptr = NULL;
 513             char *line;
 514
 515             format_log_message(module, level, VLF_SYSLOG, msg_num,
 516                                message, args, &s);
 517             for (line = strtok_r(s.string, "\n", &save_ptr); line;
 518                  line = strtok_r(NULL, "\n", &save_ptr)) {
 519                 syslog(syslog_level, "%s", line);
 520             }
 521         }
 522
 523         ds_destroy(&s);
 524         errno = save_errno;
 525     }
 526 }
 527
 528 void
 529 vlog(enum vlog_module module, enum vlog_level level, const char *message, ...)
 530 {
 531     va_list args;
 532
 533     va_start(args, message);
 534     vlog_valist(module, level, message, args);
 535     va_end(args);
 536 }
 537
 538 void
 539 vlog_rate_limit(enum vlog_module module, enum vlog_level level,
 540                 struct vlog_rate_limit *rl, const char *message, ...)
 541 {
 542     va_list args;
 543
 544     if (!vlog_is_enabled(module, level)) {
 545         return;
 546     }
 547
 548     if (rl->tokens < VLOG_MSG_TOKENS) {
 549         time_t now = time_now();
 550         if (rl->last_fill > now) {
 551             /* Last filled in the future?  Time must have gone backward, or
 552              * 'rl' has not been used before. */
 553             rl->tokens = rl->burst;
 554         } else if (rl->last_fill < now) {
 555             unsigned int add = sat_mul(rl->rate, now - rl->last_fill);
 556             unsigned int tokens = sat_add(rl->tokens, add);
 557             rl->tokens = MIN(tokens, rl->burst);
 558             rl->last_fill = now;
 559         }
 560         if (rl->tokens < VLOG_MSG_TOKENS) {
 561             if (!rl->n_dropped) {
 562                 rl->first_dropped = now;
 563             }
 564             rl->n_dropped++;
 565             return;
 566         }
 567     }
 568     rl->tokens -= VLOG_MSG_TOKENS;
 569
 570     va_start(args, message);
 571     vlog_valist(module, level, message, args);
 572     va_end(args);
 573
 574     if (rl->n_dropped) {
 575         vlog(module, level,
 576              "Dropped %u messages in last %u seconds due to excessive rate",
 577              rl->n_dropped, (unsigned int) (time_now() - rl->first_dropped));
 578         rl->n_dropped = 0;
 579     }
 580 }