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 /* Time at which vlog was initialized, in milliseconds. */
  90 static long long int boot_time;
  91
  92 /* Searches the 'n_names' in 'names'.  Returns the index of a match for
  93  * 'target', or 'n_names' if no name matches. */
  94 static size_t
  95 search_name_array(const char *target, const char **names, size_t n_names)
  96 {
  97     size_t i;
  98
  99     for (i = 0; i < n_names; i++) {
 100         assert(names[i]);
 101         if (!strcasecmp(names[i], target)) {
 102             break;
 103         }
 104     }
 105     return i;
 106 }
 107
 108 /* Returns the name for logging level 'level'. */
 109 const char *
 110 vlog_get_level_name(enum vlog_level level)
 111 {
 112     assert(level < VLL_N_LEVELS);
 113     return level_names[level];
 114 }
 115
 116 /* Returns the logging level with the given 'name', or VLL_N_LEVELS if 'name'
 117  * is not the name of a logging level. */
 118 enum vlog_level
 119 vlog_get_level_val(const char *name)
 120 {
 121     return search_name_array(name, level_names, ARRAY_SIZE(level_names));
 122 }
 123
 124 /* Returns the name for logging facility 'facility'. */
 125 const char *
 126 vlog_get_facility_name(enum vlog_facility facility)
 127 {
 128     assert(facility < VLF_N_FACILITIES);
 129     return facilities[facility].name;
 130 }
 131
 132 /* Returns the logging facility named 'name', or VLF_N_FACILITIES if 'name' is
 133  * not the name of a logging facility. */
 134 enum vlog_facility
 135 vlog_get_facility_val(const char *name)
 136 {
 137     size_t i;
 138
 139     for (i = 0; i < VLF_N_FACILITIES; i++) {
 140         if (!strcasecmp(facilities[i].name, name)) {
 141             break;
 142         }
 143     }
 144     return i;
 145 }
 146
 147 /* Returns the name for logging module 'module'. */
 148 const char *vlog_get_module_name(enum vlog_module module)
 149 {
 150     assert(module < VLM_N_MODULES);
 151     return module_names[module];
 152 }
 153
 154 /* Returns the logging module named 'name', or VLM_N_MODULES if 'name' is not
 155  * the name of a logging module. */
 156 enum vlog_module
 157 vlog_get_module_val(const char *name)
 158 {
 159     return search_name_array(name, module_names, ARRAY_SIZE(module_names));
 160 }
 161
 162 /* Returns the current logging level for the given 'module' and 'facility'. */
 163 enum vlog_level
 164 vlog_get_level(enum vlog_module module, enum vlog_facility facility)
 165 {
 166     assert(module < VLM_N_MODULES);
 167     assert(facility < VLF_N_FACILITIES);
 168     return levels[module][facility];
 169 }
 170
 171 static void
 172 set_facility_level(enum vlog_facility facility, enum vlog_module module,
 173                    enum vlog_level level)
 174 {
 175     assert(facility >= 0 && facility < VLF_N_FACILITIES);
 176     assert(level < VLL_N_LEVELS);
 177
 178     if (module == VLM_ANY_MODULE) {
 179         for (module = 0; module < VLM_N_MODULES; module++) {
 180             levels[module][facility] = level;
 181         }
 182     } else {
 183         levels[module][facility] = level;
 184     }
 185 }
 186
 187 /* Sets the logging level for the given 'module' and 'facility' to 'level'. */
 188 void
 189 vlog_set_levels(enum vlog_module module, enum vlog_facility facility,
 190                 enum vlog_level level)
 191 {
 192     assert(facility < VLF_N_FACILITIES || facility == VLF_ANY_FACILITY);
 193     if (facility == VLF_ANY_FACILITY) {
 194         for (facility = 0; facility < VLF_N_FACILITIES; facility++) {
 195             set_facility_level(facility, module, level);
 196         }
 197     } else {
 198         set_facility_level(facility, module, level);
 199     }
 200 }
 201
 202 static void
 203 do_set_pattern(enum vlog_facility facility, const char *pattern)
 204 {
 205     struct facility *f = &facilities[facility];
 206     if (!f->default_pattern) {
 207         free(f->pattern);
 208     } else {
 209         f->default_pattern = false;
 210     }
 211     f->pattern = xstrdup(pattern);
 212 }
 213
 214 /* Sets the pattern for the given 'facility' to 'pattern'. */
 215 void
 216 vlog_set_pattern(enum vlog_facility facility, const char *pattern)
 217 {
 218     assert(facility < VLF_N_FACILITIES || facility == VLF_ANY_FACILITY);
 219     if (facility == VLF_ANY_FACILITY) {
 220         for (facility = 0; facility < VLF_N_FACILITIES; facility++) {
 221             do_set_pattern(facility, pattern);
 222         }
 223     } else {
 224         do_set_pattern(facility, pattern);
 225     }
 226 }
 227
 228 /* Set debugging levels:
 229  *
 230  *  mod[:facility[:level]] mod2[:facility[:level]] ...
 231  *
 232  * Return null if successful, otherwise an error message that the caller must
 233  * free().
 234  */
 235 char *
 236 vlog_set_levels_from_string(const char *s_)
 237 {
 238     char *save_ptr;
 239     char *s = xstrdup(s_);
 240     char *module, *facility;
 241
 242     for (module = strtok_r(s, ": \t", &save_ptr); module != NULL;
 243          module = strtok_r(NULL, ": \t", &save_ptr)) {
 244         enum vlog_module e_module;
 245         enum vlog_facility e_facility;
 246
 247         facility = strtok_r(NULL, ":", &save_ptr);
 248
 249         if (!facility || !strcmp(facility, "ANY")) {
 250             e_facility = VLF_ANY_FACILITY;
 251         } else {
 252             e_facility = vlog_get_facility_val(facility);
 253             if (e_facility >= VLF_N_FACILITIES) {
 254                 char *msg = xasprintf("unknown facility \"%s\"", facility);
 255                 free(s);
 256                 return msg;
 257             }
 258         }
 259
 260         if (!strcmp(module, "PATTERN")) {
 261             vlog_set_pattern(e_facility, save_ptr);
 262             break;
 263         } else {
 264             char *level;
 265             enum vlog_level e_level;
 266
 267             if (!strcmp(module, "ANY")) {
 268                 e_module = VLM_ANY_MODULE;
 269             } else {
 270                 e_module = vlog_get_module_val(module);
 271                 if (e_module >= VLM_N_MODULES) {
 272                     char *msg = xasprintf("unknown module \"%s\"", module);
 273                     free(s);
 274                     return msg;
 275                 }
 276             }
 277
 278             level = strtok_r(NULL, ":", &save_ptr);
 279             e_level = level ? vlog_get_level_val(level) : VLL_DBG;
 280             if (e_level >= VLL_N_LEVELS) {
 281                 char *msg = xasprintf("unknown level \"%s\"", level);
 282                 free(s);
 283                 return msg;
 284             }
 285
 286             vlog_set_levels(e_module, e_facility, e_level);
 287         }
 288     }
 289     free(s);
 290     return NULL;
 291 }
 292
 293 /* If 'arg' is null, configure maximum verbosity.  Otherwise, sets
 294  * configuration according to 'arg' (see vlog_set_levels_from_string()). */
 295 void
 296 vlog_set_verbosity(const char *arg)
 297 {
 298     if (arg) {
 299         char *msg = vlog_set_levels_from_string(arg);
 300         if (msg) {
 301             ofp_fatal(0, "processing \"%s\": %s", arg, msg);
 302         }
 303     } else {
 304         vlog_set_levels(VLM_ANY_MODULE, VLF_ANY_FACILITY, VLL_DBG);
 305     }
 306 }
 307
 308 /* Initializes the logging subsystem. */
 309 void
 310 vlog_init(void)
 311 {
 312     time_t now;
 313
 314     openlog(program_name, LOG_NDELAY, LOG_DAEMON);
 315     vlog_set_levels(VLM_ANY_MODULE, VLF_ANY_FACILITY, VLL_WARN);
 316
 317     boot_time = time_msec();
 318     now = time_now();
 319     if (now < 0) {
 320         struct tm tm;
 321         char s[128];
 322
 323         localtime_r(&now, &tm);
 324         strftime(s, sizeof s, "%a, %d %b %Y %H:%M:%S %z", &tm);
 325         VLOG_ERR("current time is negative: %s (%ld)", s, (long int) now);
 326     }
 327 }
 328
 329 /* Closes the logging subsystem. */
 330 void
 331 vlog_exit(void)
 332 {
 333     closelog();
 334 }
 335
 336 /* Print the current logging level for each module. */
 337 char *
 338 vlog_get_levels(void)
 339 {
 340     struct ds s = DS_EMPTY_INITIALIZER;
 341     enum vlog_module module;
 342
 343     ds_put_format(&s, "                 console    syslog\n");
 344     ds_put_format(&s, "                 -------    ------\n");
 345
 346     for (module = 0; module < VLM_N_MODULES; module++) {
 347         ds_put_format(&s, "%-16s  %4s       %4s\n",
 348            vlog_get_module_name(module),
 349            vlog_get_level_name(vlog_get_level(module, VLF_CONSOLE)),
 350            vlog_get_level_name(vlog_get_level(module, VLF_SYSLOG)));
 351     }
 352
 353     return ds_cstr(&s);
 354 }
 355
 356 /* Returns true if a log message emitted for the given 'module' and 'level'
 357  * would cause some log output, false if that module and level are completely
 358  * disabled. */
 359 bool
 360 vlog_is_enabled(enum vlog_module module, enum vlog_level level)
 361 {
 362     return (levels[module][VLF_CONSOLE] >= level
 363             || levels[module][VLF_SYSLOG] >= level);
 364 }
 365
 366 static const char *
 367 fetch_braces(const char *p, const char *def, char *out, size_t out_size)
 368 {
 369     if (*p == '{') {
 370         size_t n = strcspn(p + 1, "}");
 371         size_t n_copy = MIN(n, out_size - 1);
 372         memcpy(out, p + 1, n_copy);
 373         out[n_copy] = '\0';
 374         p += n + 2;
 375     } else {
 376         strlcpy(out, def, out_size);
 377     }
 378     return p;
 379 }
 380
 381 static void
 382 format_log_message(enum vlog_module module, enum vlog_level level,
 383                    enum vlog_facility facility, unsigned int msg_num,
 384                    const char *message, va_list args_, struct ds *s)
 385 {
 386     char tmp[128];
 387     va_list args;
 388     const char *p;
 389
 390     ds_clear(s);
 391     for (p = facilities[facility].pattern; *p != '\0'; ) {
 392         enum { LEFT, RIGHT } justify = RIGHT;
 393         int pad = '0';
 394         size_t length, field, used;
 395
 396         if (*p != '%') {
 397             ds_put_char(s, *p++);
 398             continue;
 399         }
 400
 401         p++;
 402         if (*p == '-') {
 403             justify = LEFT;
 404             p++;
 405         }
 406         if (*p == '0') {
 407             pad = '0';
 408             p++;
 409         }
 410         field = 0;
 411         while (isdigit(*p)) {
 412             field = (field * 10) + (*p - '0');
 413             p++;
 414         }
 415
 416         length = s->length;
 417         switch (*p++) {
 418         case 'A':
 419             ds_put_cstr(s, program_name);
 420             break;
 421         case 'c':
 422             p = fetch_braces(p, "", tmp, sizeof tmp);
 423             ds_put_cstr(s, vlog_get_module_name(module));
 424             break;
 425         case 'd':
 426             p = fetch_braces(p, "%Y-%m-%d %H:%M:%S", tmp, sizeof tmp);
 427             ds_put_strftime(s, tmp, NULL);
 428             break;
 429         case 'm':
 430             va_copy(args, args_);
 431             ds_put_format_valist(s, message, args);
 432             va_end(args);
 433             break;
 434         case 'N':
 435             ds_put_format(s, "%u", msg_num);
 436             break;
 437         case 'n':
 438             ds_put_char(s, '\n');
 439             break;
 440         case 'p':
 441             ds_put_cstr(s, vlog_get_level_name(level));
 442             break;
 443         case 'P':
 444             ds_put_format(s, "%ld", (long int) getpid());
 445             break;
 446         case 'r':
 447             ds_put_format(s, "%lld", time_msec() - boot_time);
 448             break;
 449         default:
 450             ds_put_char(s, p[-1]);
 451             break;
 452         }
 453         used = s->length - length;
 454         if (used < field) {
 455             size_t n_pad = field - used;
 456             if (justify == RIGHT) {
 457                 ds_put_uninit(s, n_pad);
 458                 memmove(&s->string[length + n_pad], &s->string[length], used);
 459                 memset(&s->string[length], pad, n_pad);
 460             } else {
 461                 ds_put_char_multiple(s, pad, n_pad);
 462             }
 463         }
 464     }
 465 }
 466
 467 /* Writes 'message' to the log at the given 'level' and as coming from the
 468  * given 'module'.
 469  *
 470  * Guaranteed to preserve errno. */
 471 void
 472 vlog_valist(enum vlog_module module, enum vlog_level level,
 473             const char *message, va_list args)
 474 {
 475     bool log_console = levels[module][VLF_CONSOLE] >= level;
 476     bool log_syslog = levels[module][VLF_SYSLOG] >= level;
 477     if (log_console || log_syslog) {
 478         int save_errno = errno;
 479         static unsigned int msg_num;
 480         struct ds s;
 481
 482         ds_init(&s);
 483         ds_reserve(&s, 1024);
 484         msg_num++;
 485
 486         if (log_console) {
 487             format_log_message(module, level, VLF_CONSOLE, msg_num,
 488                                message, args, &s);
 489             ds_put_char(&s, '\n');
 490             fputs(ds_cstr(&s), stderr);
 491         }
 492
 493         if (log_syslog) {
 494             int syslog_level = syslog_levels[level];
 495             char *save_ptr = NULL;
 496             char *line;
 497
 498             format_log_message(module, level, VLF_SYSLOG, msg_num,
 499                                message, args, &s);
 500             for (line = strtok_r(s.string, "\n", &save_ptr); line;
 501                  line = strtok_r(NULL, "\n", &save_ptr)) {
 502                 syslog(syslog_level, "%s", line);
 503             }
 504         }
 505
 506         ds_destroy(&s);
 507         errno = save_errno;
 508     }
 509 }
 510
 511 void
 512 vlog(enum vlog_module module, enum vlog_level level, const char *message, ...)
 513 {
 514     va_list args;
 515
 516     va_start(args, message);
 517     vlog_valist(module, level, message, args);
 518     va_end(args);
 519 }
 520
 521 void
 522 vlog_rate_limit(enum vlog_module module, enum vlog_level level,
 523                 struct vlog_rate_limit *rl, const char *message, ...)
 524 {
 525     va_list args;
 526
 527     if (!vlog_is_enabled(module, level)) {
 528         return;
 529     }
 530
 531     if (rl->tokens < VLOG_MSG_TOKENS) {
 532         time_t now = time_now();
 533         if (rl->last_fill > now) {
 534             /* Last filled in the future?  Time must have gone backward, or
 535              * 'rl' has not been used before. */
 536             rl->tokens = rl->burst;
 537         } else if (rl->last_fill < now) {
 538             unsigned int add = sat_mul(rl->rate, now - rl->last_fill);
 539             unsigned int tokens = sat_add(rl->tokens, add);
 540             rl->tokens = MIN(tokens, rl->burst);
 541             rl->last_fill = now;
 542         }
 543         if (rl->tokens < VLOG_MSG_TOKENS) {
 544             if (!rl->n_dropped) {
 545                 rl->first_dropped = now;
 546             }
 547             rl->n_dropped++;
 548             return;
 549         }
 550     }
 551     rl->tokens -= VLOG_MSG_TOKENS;
 552
 553     va_start(args, message);
 554     vlog_valist(module, level, message, args);
 555     va_end(args);
 556
 557     if (rl->n_dropped) {
 558         vlog(module, level,
 559              "Dropped %u messages in last %u seconds due to excessive rate",
 560              rl->n_dropped, (unsigned int) (time_now() - rl->first_dropped));
 561         rl->n_dropped = 0;
 562     }
 563 }