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 "dirs.h"
  47 #include "dynamic-string.h"
  48 #include "sat-math.h"
  49 #include "timeval.h"
  50 #include "util.h"
  51
  52 #define THIS_MODULE VLM_vlog
  53
  54 /* Name for each logging level. */
  55 static const char *level_names[VLL_N_LEVELS] = {
  56 #define VLOG_LEVEL(NAME, SYSLOG_LEVEL) #NAME,
  57     VLOG_LEVELS
  58 #undef VLOG_LEVEL
  59 };
  60
  61 /* Syslog value for each logging level. */
  62 static int syslog_levels[VLL_N_LEVELS] = {
  63 #define VLOG_LEVEL(NAME, SYSLOG_LEVEL) SYSLOG_LEVEL,
  64     VLOG_LEVELS
  65 #undef VLOG_LEVEL
  66 };
  67
  68 /* Name for each logging module */
  69 static const char *module_names[VLM_N_MODULES] = {
  70 #define VLOG_MODULE(NAME) #NAME,
  71 #include "vlog-modules.def"
  72 #undef VLOG_MODULE
  73 };
  74
  75 /* Information about each facility. */
  76 struct facility {
  77     const char *name;           /* Name. */
  78     char *pattern;              /* Current pattern. */
  79     bool default_pattern;       /* Whether current pattern is the default. */
  80 };
  81 static struct facility facilities[VLF_N_FACILITIES] = {
  82 #define VLOG_FACILITY(NAME, PATTERN) {#NAME, PATTERN, true},
  83     VLOG_FACILITIES
  84 #undef VLOG_FACILITY
  85 };
  86
  87 /* Current log levels. */
  88 static int levels[VLM_N_MODULES][VLF_N_FACILITIES];
  89
  90 /* For fast checking whether we're logging anything for a given module and
  91  * level.*/
  92 enum vlog_level min_vlog_levels[VLM_N_MODULES];
  93
  94 /* Time at which vlog was initialized, in milliseconds. */
  95 static long long int boot_time;
  96
  97 /* VLF_FILE configuration. */
  98 static char *log_file_name;
  99 static FILE *log_file;
 100
 101 /* Searches the 'n_names' in 'names'.  Returns the index of a match for
 102  * 'target', or 'n_names' if no name matches. */
 103 static size_t
 104 search_name_array(const char *target, const char **names, size_t n_names)
 105 {
 106     size_t i;
 107
 108     for (i = 0; i < n_names; i++) {
 109         assert(names[i]);
 110         if (!strcasecmp(names[i], target)) {
 111             break;
 112         }
 113     }
 114     return i;
 115 }
 116
 117 /* Returns the name for logging level 'level'. */
 118 const char *
 119 vlog_get_level_name(enum vlog_level level)
 120 {
 121     assert(level < VLL_N_LEVELS);
 122     return level_names[level];
 123 }
 124
 125 /* Returns the logging level with the given 'name', or VLL_N_LEVELS if 'name'
 126  * is not the name of a logging level. */
 127 enum vlog_level
 128 vlog_get_level_val(const char *name)
 129 {
 130     return search_name_array(name, level_names, ARRAY_SIZE(level_names));
 131 }
 132
 133 /* Returns the name for logging facility 'facility'. */
 134 const char *
 135 vlog_get_facility_name(enum vlog_facility facility)
 136 {
 137     assert(facility < VLF_N_FACILITIES);
 138     return facilities[facility].name;
 139 }
 140
 141 /* Returns the logging facility named 'name', or VLF_N_FACILITIES if 'name' is
 142  * not the name of a logging facility. */
 143 enum vlog_facility
 144 vlog_get_facility_val(const char *name)
 145 {
 146     size_t i;
 147
 148     for (i = 0; i < VLF_N_FACILITIES; i++) {
 149         if (!strcasecmp(facilities[i].name, name)) {
 150             break;
 151         }
 152     }
 153     return i;
 154 }
 155
 156 /* Returns the name for logging module 'module'. */
 157 const char *vlog_get_module_name(enum vlog_module module)
 158 {
 159     assert(module < VLM_N_MODULES);
 160     return module_names[module];
 161 }
 162
 163 /* Returns the logging module named 'name', or VLM_N_MODULES if 'name' is not
 164  * the name of a logging module. */
 165 enum vlog_module
 166 vlog_get_module_val(const char *name)
 167 {
 168     return search_name_array(name, module_names, ARRAY_SIZE(module_names));
 169 }
 170
 171 /* Returns the current logging level for the given 'module' and 'facility'. */
 172 enum vlog_level
 173 vlog_get_level(enum vlog_module module, enum vlog_facility facility)
 174 {
 175     assert(module < VLM_N_MODULES);
 176     assert(facility < VLF_N_FACILITIES);
 177     return levels[module][facility];
 178 }
 179
 180 static void
 181 update_min_level(enum vlog_module module)
 182 {
 183     enum vlog_level min_level = VLL_EMER;
 184     enum vlog_facility facility;
 185
 186     for (facility = 0; facility < VLF_N_FACILITIES; facility++) {
 187         if (log_file || facility != VLF_FILE) {
 188             min_level = MAX(min_level, levels[module][facility]);
 189         }
 190     }
 191     min_vlog_levels[module] = min_level;
 192 }
 193
 194 static void
 195 set_facility_level(enum vlog_facility facility, enum vlog_module module,
 196                    enum vlog_level level)
 197 {
 198     assert(facility >= 0 && facility < VLF_N_FACILITIES);
 199     assert(level < VLL_N_LEVELS);
 200
 201     if (module == VLM_ANY_MODULE) {
 202         for (module = 0; module < VLM_N_MODULES; module++) {
 203             levels[module][facility] = level;
 204             update_min_level(module);
 205         }
 206     } else {
 207         levels[module][facility] = level;
 208         update_min_level(module);
 209     }
 210 }
 211
 212 /* Sets the logging level for the given 'module' and 'facility' to 'level'. */
 213 void
 214 vlog_set_levels(enum vlog_module module, enum vlog_facility facility,
 215                 enum vlog_level level)
 216 {
 217     assert(facility < VLF_N_FACILITIES || facility == VLF_ANY_FACILITY);
 218     if (facility == VLF_ANY_FACILITY) {
 219         for (facility = 0; facility < VLF_N_FACILITIES; facility++) {
 220             set_facility_level(facility, module, level);
 221         }
 222     } else {
 223         set_facility_level(facility, module, level);
 224     }
 225 }
 226
 227 static void
 228 do_set_pattern(enum vlog_facility facility, const char *pattern)
 229 {
 230     struct facility *f = &facilities[facility];
 231     if (!f->default_pattern) {
 232         free(f->pattern);
 233     } else {
 234         f->default_pattern = false;
 235     }
 236     f->pattern = xstrdup(pattern);
 237 }
 238
 239 /* Sets the pattern for the given 'facility' to 'pattern'. */
 240 void
 241 vlog_set_pattern(enum vlog_facility facility, const char *pattern)
 242 {
 243     assert(facility < VLF_N_FACILITIES || facility == VLF_ANY_FACILITY);
 244     if (facility == VLF_ANY_FACILITY) {
 245         for (facility = 0; facility < VLF_N_FACILITIES; facility++) {
 246             do_set_pattern(facility, pattern);
 247         }
 248     } else {
 249         do_set_pattern(facility, pattern);
 250     }
 251 }
 252
 253 /* Returns the name of the log file used by VLF_FILE, or a null pointer if no
 254  * log file has been set.  (A non-null return value does not assert that the
 255  * named log file is in use: if vlog_set_log_file() or vlog_reopen_log_file()
 256  * fails, it still sets the log file name.) */
 257 const char *
 258 vlog_get_log_file(void)
 259 {
 260     return log_file_name;
 261 }
 262
 263 /* Sets the name of the log file used by VLF_FILE to 'file_name', or to the
 264  * default file name if 'file_name' is null.  Returns 0 if successful,
 265  * otherwise a positive errno value. */
 266 int
 267 vlog_set_log_file(const char *file_name)
 268 {
 269     char *old_log_file_name;
 270     enum vlog_module module;
 271     int error;
 272
 273     /* Close old log file. */
 274     if (log_file) {
 275         VLOG_WARN("closing log file");
 276         fclose(log_file);
 277         log_file = NULL;
 278     }
 279
 280     /* Update log file name and free old name.  The ordering is important
 281      * because 'file_name' might be 'log_file_name' or some suffix of it. */
 282     old_log_file_name = log_file_name;
 283     log_file_name = (file_name
 284                      ? xstrdup(file_name)
 285                      : xasprintf("%s/%s.log", ofp_logdir, program_name));
 286     free(old_log_file_name);
 287     file_name = NULL;           /* Might have been freed. */
 288
 289     /* Open new log file and update min_levels[] to reflect whether we actually
 290      * have a log_file. */
 291     log_file = fopen(log_file_name, "a");
 292     for (module = 0; module < VLM_N_MODULES; module++) {
 293         update_min_level(module);
 294     }
 295
 296     /* Log success or failure. */
 297     if (!log_file) {
 298         VLOG_WARN("failed to open %s for logging: %s",
 299                   log_file_name, strerror(errno));
 300         error = errno;
 301     } else {
 302         VLOG_WARN("opened log file %s", log_file_name);
 303         error = 0;
 304     }
 305
 306     return error;
 307 }
 308
 309 /* Closes and then attempts to re-open the current log file.  (This is useful
 310  * just after log rotation, to ensure that the new log file starts being used.)
 311  * Returns 0 if successful, otherwise a positive errno value. */
 312 int
 313 vlog_reopen_log_file(void)
 314 {
 315     return vlog_set_log_file(log_file_name);
 316 }
 317
 318 /* Set debugging levels:
 319  *
 320  *  mod[:facility[:level]] mod2[:facility[:level]] ...
 321  *
 322  * Return null if successful, otherwise an error message that the caller must
 323  * free().
 324  */
 325 char *
 326 vlog_set_levels_from_string(const char *s_)
 327 {
 328     char *save_ptr;
 329     char *s = xstrdup(s_);
 330     char *module, *facility;
 331
 332     for (module = strtok_r(s, ": \t", &save_ptr); module != NULL;
 333          module = strtok_r(NULL, ": \t", &save_ptr)) {
 334         enum vlog_module e_module;
 335         enum vlog_facility e_facility;
 336
 337         facility = strtok_r(NULL, ":", &save_ptr);
 338
 339         if (!facility || !strcmp(facility, "ANY")) {
 340             e_facility = VLF_ANY_FACILITY;
 341         } else {
 342             e_facility = vlog_get_facility_val(facility);
 343             if (e_facility >= VLF_N_FACILITIES) {
 344                 char *msg = xasprintf("unknown facility \"%s\"", facility);
 345                 free(s);
 346                 return msg;
 347             }
 348         }
 349
 350         if (!strcmp(module, "PATTERN")) {
 351             vlog_set_pattern(e_facility, save_ptr);
 352             break;
 353         } else {
 354             char *level;
 355             enum vlog_level e_level;
 356
 357             if (!strcmp(module, "ANY")) {
 358                 e_module = VLM_ANY_MODULE;
 359             } else {
 360                 e_module = vlog_get_module_val(module);
 361                 if (e_module >= VLM_N_MODULES) {
 362                     char *msg = xasprintf("unknown module \"%s\"", module);
 363                     free(s);
 364                     return msg;
 365                 }
 366             }
 367
 368             level = strtok_r(NULL, ":", &save_ptr);
 369             e_level = level ? vlog_get_level_val(level) : VLL_DBG;
 370             if (e_level >= VLL_N_LEVELS) {
 371                 char *msg = xasprintf("unknown level \"%s\"", level);
 372                 free(s);
 373                 return msg;
 374             }
 375
 376             vlog_set_levels(e_module, e_facility, e_level);
 377         }
 378     }
 379     free(s);
 380     return NULL;
 381 }
 382
 383 /* If 'arg' is null, configure maximum verbosity.  Otherwise, sets
 384  * configuration according to 'arg' (see vlog_set_levels_from_string()). */
 385 void
 386 vlog_set_verbosity(const char *arg)
 387 {
 388     if (arg) {
 389         char *msg = vlog_set_levels_from_string(arg);
 390         if (msg) {
 391             ofp_fatal(0, "processing \"%s\": %s", arg, msg);
 392         }
 393     } else {
 394         vlog_set_levels(VLM_ANY_MODULE, VLF_ANY_FACILITY, VLL_DBG);
 395     }
 396 }
 397
 398 /* Initializes the logging subsystem. */
 399 void
 400 vlog_init(void)
 401 {
 402     time_t now;
 403
 404     openlog(program_name, LOG_NDELAY, LOG_DAEMON);
 405     vlog_set_levels(VLM_ANY_MODULE, VLF_ANY_FACILITY, VLL_WARN);
 406
 407     boot_time = time_msec();
 408     now = time_now();
 409     if (now < 0) {
 410         struct tm tm;
 411         char s[128];
 412
 413         localtime_r(&now, &tm);
 414         strftime(s, sizeof s, "%a, %d %b %Y %H:%M:%S %z", &tm);
 415         VLOG_ERR("current time is negative: %s (%ld)", s, (long int) now);
 416     }
 417 }
 418
 419 /* Closes the logging subsystem. */
 420 void
 421 vlog_exit(void)
 422 {
 423     closelog();
 424 }
 425
 426 /* Print the current logging level for each module. */
 427 char *
 428 vlog_get_levels(void)
 429 {
 430     struct ds s = DS_EMPTY_INITIALIZER;
 431     enum vlog_module module;
 432
 433     ds_put_format(&s, "                 console    syslog    file\n");
 434     ds_put_format(&s, "                 -------    ------    ------\n");
 435
 436     for (module = 0; module < VLM_N_MODULES; module++) {
 437         ds_put_format(&s, "%-16s  %4s       %4s       %4s\n",
 438            vlog_get_module_name(module),
 439            vlog_get_level_name(vlog_get_level(module, VLF_CONSOLE)),
 440            vlog_get_level_name(vlog_get_level(module, VLF_SYSLOG)),
 441            vlog_get_level_name(vlog_get_level(module, VLF_FILE)));
 442     }
 443
 444     return ds_cstr(&s);
 445 }
 446
 447 /* Returns true if a log message emitted for the given 'module' and 'level'
 448  * would cause some log output, false if that module and level are completely
 449  * disabled. */
 450 bool
 451 vlog_is_enabled(enum vlog_module module, enum vlog_level level)
 452 {
 453     return min_vlog_levels[module] >= level;
 454 }
 455
 456 static const char *
 457 fetch_braces(const char *p, const char *def, char *out, size_t out_size)
 458 {
 459     if (*p == '{') {
 460         size_t n = strcspn(p + 1, "}");
 461         size_t n_copy = MIN(n, out_size - 1);
 462         memcpy(out, p + 1, n_copy);
 463         out[n_copy] = '\0';
 464         p += n + 2;
 465     } else {
 466         strlcpy(out, def, out_size);
 467     }
 468     return p;
 469 }
 470
 471 static void
 472 format_log_message(enum vlog_module module, enum vlog_level level,
 473                    enum vlog_facility facility, unsigned int msg_num,
 474                    const char *message, va_list args_, struct ds *s)
 475 {
 476     char tmp[128];
 477     va_list args;
 478     const char *p;
 479
 480     ds_clear(s);
 481     for (p = facilities[facility].pattern; *p != '\0'; ) {
 482         enum { LEFT, RIGHT } justify = RIGHT;
 483         int pad = '0';
 484         size_t length, field, used;
 485
 486         if (*p != '%') {
 487             ds_put_char(s, *p++);
 488             continue;
 489         }
 490
 491         p++;
 492         if (*p == '-') {
 493             justify = LEFT;
 494             p++;
 495         }
 496         if (*p == '0') {
 497             pad = '0';
 498             p++;
 499         }
 500         field = 0;
 501         while (isdigit(*p)) {
 502             field = (field * 10) + (*p - '0');
 503             p++;
 504         }
 505
 506         length = s->length;
 507         switch (*p++) {
 508         case 'A':
 509             ds_put_cstr(s, program_name);
 510             break;
 511         case 'c':
 512             p = fetch_braces(p, "", tmp, sizeof tmp);
 513             ds_put_cstr(s, vlog_get_module_name(module));
 514             break;
 515         case 'd':
 516             p = fetch_braces(p, "%Y-%m-%d %H:%M:%S", tmp, sizeof tmp);
 517             ds_put_strftime(s, tmp, NULL);
 518             break;
 519         case 'm':
 520             va_copy(args, args_);
 521             ds_put_format_valist(s, message, args);
 522             va_end(args);
 523             break;
 524         case 'N':
 525             ds_put_format(s, "%u", msg_num);
 526             break;
 527         case 'n':
 528             ds_put_char(s, '\n');
 529             break;
 530         case 'p':
 531             ds_put_cstr(s, vlog_get_level_name(level));
 532             break;
 533         case 'P':
 534             ds_put_format(s, "%ld", (long int) getpid());
 535             break;
 536         case 'r':
 537             ds_put_format(s, "%lld", time_msec() - boot_time);
 538             break;
 539         default:
 540             ds_put_char(s, p[-1]);
 541             break;
 542         }
 543         used = s->length - length;
 544         if (used < field) {
 545             size_t n_pad = field - used;
 546             if (justify == RIGHT) {
 547                 ds_put_uninit(s, n_pad);
 548                 memmove(&s->string[length + n_pad], &s->string[length], used);
 549                 memset(&s->string[length], pad, n_pad);
 550             } else {
 551                 ds_put_char_multiple(s, pad, n_pad);
 552             }
 553         }
 554     }
 555 }
 556
 557 /* Writes 'message' to the log at the given 'level' and as coming from the
 558  * given 'module'.
 559  *
 560  * Guaranteed to preserve errno. */
 561 void
 562 vlog_valist(enum vlog_module module, enum vlog_level level,
 563             const char *message, va_list args)
 564 {
 565     bool log_to_console = levels[module][VLF_CONSOLE] >= level;
 566     bool log_to_syslog = levels[module][VLF_SYSLOG] >= level;
 567     bool log_to_file = levels[module][VLF_FILE] >= level && log_file;
 568     if (log_to_console || log_to_syslog || log_to_file) {
 569         int save_errno = errno;
 570         static unsigned int msg_num;
 571         struct ds s;
 572
 573         ds_init(&s);
 574         ds_reserve(&s, 1024);
 575         msg_num++;
 576
 577         if (log_to_console) {
 578             format_log_message(module, level, VLF_CONSOLE, msg_num,
 579                                message, args, &s);
 580             ds_put_char(&s, '\n');
 581             fputs(ds_cstr(&s), stderr);
 582         }
 583
 584         if (log_to_syslog) {
 585             int syslog_level = syslog_levels[level];
 586             char *save_ptr = NULL;
 587             char *line;
 588
 589             format_log_message(module, level, VLF_SYSLOG, msg_num,
 590                                message, args, &s);
 591             for (line = strtok_r(s.string, "\n", &save_ptr); line;
 592                  line = strtok_r(NULL, "\n", &save_ptr)) {
 593                 syslog(syslog_level, "%s", line);
 594             }
 595         }
 596
 597         if (log_to_file) {
 598             format_log_message(module, level, VLF_FILE, msg_num,
 599                                message, args, &s);
 600             ds_put_char(&s, '\n');
 601             fputs(ds_cstr(&s), log_file);
 602             fflush(log_file);
 603         }
 604
 605         ds_destroy(&s);
 606         errno = save_errno;
 607     }
 608 }
 609
 610 void
 611 vlog(enum vlog_module module, enum vlog_level level, const char *message, ...)
 612 {
 613     va_list args;
 614
 615     va_start(args, message);
 616     vlog_valist(module, level, message, args);
 617     va_end(args);
 618 }
 619
 620 void
 621 vlog_rate_limit(enum vlog_module module, enum vlog_level level,
 622                 struct vlog_rate_limit *rl, const char *message, ...)
 623 {
 624     va_list args;
 625
 626     if (!vlog_is_enabled(module, level)) {
 627         return;
 628     }
 629
 630     if (rl->tokens < VLOG_MSG_TOKENS) {
 631         time_t now = time_now();
 632         if (rl->last_fill > now) {
 633             /* Last filled in the future?  Time must have gone backward, or
 634              * 'rl' has not been used before. */
 635             rl->tokens = rl->burst;
 636         } else if (rl->last_fill < now) {
 637             unsigned int add = sat_mul(rl->rate, now - rl->last_fill);
 638             unsigned int tokens = sat_add(rl->tokens, add);
 639             rl->tokens = MIN(tokens, rl->burst);
 640             rl->last_fill = now;
 641         }
 642         if (rl->tokens < VLOG_MSG_TOKENS) {
 643             if (!rl->n_dropped) {
 644                 rl->first_dropped = now;
 645             }
 646             rl->n_dropped++;
 647             return;
 648         }
 649     }
 650     rl->tokens -= VLOG_MSG_TOKENS;
 651
 652     va_start(args, message);
 653     vlog_valist(module, level, message, args);
 654     va_end(args);
 655
 656     if (rl->n_dropped) {
 657         vlog(module, level,
 658              "Dropped %u messages in last %u seconds due to excessive rate",
 659              rl->n_dropped, (unsigned int) (time_now() - rl->first_dropped));
 660         rl->n_dropped = 0;
 661     }
 662 }
 663
 664 void
 665 vlog_usage(void)
 666 {
 667     printf("\nLogging options:\n"
 668            "  -v, --verbose=MODULE[:FACILITY[:LEVEL]]  set logging levels\n"
 669            "  -v, --verbose           set maximum verbosity level\n"
 670            "  --log-file[=FILE]       enable logging to specified FILE\n"
 671            "                          (default: %s/%s.log)\n",
 672            ofp_logdir, program_name);
 673 }