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 <errno.h>
  38 #include <stdarg.h>
  39 #include <stdlib.h>
  40 #include <string.h>
  41 #include <sys/ipc.h>
  42 #include <sys/shm.h>
  43 #include <syslog.h>
  44 #include <time.h>
  45 #include "dynamic-string.h"
  46 #include "sat-math.h"
  47 #include "timeval.h"
  48 #include "util.h"
  49
  50 #define THIS_MODULE VLM_vlog
  51
  52 /* Name for each logging level. */
  53 static const char *level_names[VLL_N_LEVELS] = {
  54 #define VLOG_LEVEL(NAME) #NAME,
  55     VLOG_LEVELS
  56 #undef VLOG_LEVEL
  57 };
  58
  59 /* Name for each logging facility. */
  60 static const char *facility_names[VLF_N_FACILITIES] = {
  61 #define VLOG_FACILITY(NAME) #NAME,
  62     VLOG_FACILITIES
  63 #undef VLOG_FACILITY
  64 };
  65
  66 /* Name for each logging module */
  67 static const char *module_names[VLM_N_MODULES] = {
  68 #define VLOG_MODULE(NAME) #NAME,
  69 #include "vlog-modules.def"
  70 };
  71
  72 static int levels[VLM_N_MODULES][VLF_N_FACILITIES];
  73
  74 /* Searches the 'n_names' in 'names'.  Returns the index of a match for
  75  * 'target', or 'n_names' if no name matches. */
  76 static size_t
  77 search_name_array(const char *target, const char **names, size_t n_names)
  78 {
  79     size_t i;
  80
  81     for (i = 0; i < n_names; i++) {
  82         assert(names[i]);
  83         if (!strcasecmp(names[i], target)) {
  84             break;
  85         }
  86     }
  87     return i;
  88 }
  89
  90 /* Returns the name for logging level 'level'. */
  91 const char *
  92 vlog_get_level_name(enum vlog_level level)
  93 {
  94     assert(level < VLL_N_LEVELS);
  95     return level_names[level];
  96 }
  97
  98 /* Returns the logging level with the given 'name', or VLL_N_LEVELS if 'name'
  99  * is not the name of a logging level. */
 100 enum vlog_level
 101 vlog_get_level_val(const char *name)
 102 {
 103     return search_name_array(name, level_names, ARRAY_SIZE(level_names));
 104 }
 105
 106 /* Returns the name for logging facility 'facility'. */
 107 const char *
 108 vlog_get_facility_name(enum vlog_facility facility)
 109 {
 110     assert(facility < VLF_N_FACILITIES);
 111     return facility_names[facility];
 112 }
 113
 114 /* Returns the logging facility named 'name', or VLF_N_FACILITIES if 'name' is
 115  * not the name of a logging facility. */
 116 enum vlog_facility
 117 vlog_get_facility_val(const char *name)
 118 {
 119     return search_name_array(name, facility_names, ARRAY_SIZE(facility_names));
 120 }
 121
 122 /* Returns the name for logging module 'module'. */
 123 const char *vlog_get_module_name(enum vlog_module module)
 124 {
 125     assert(module < VLM_N_MODULES);
 126     return module_names[module];
 127 }
 128
 129 /* Returns the logging module named 'name', or VLM_N_MODULES if 'name' is not
 130  * the name of a logging module. */
 131 enum vlog_module
 132 vlog_get_module_val(const char *name)
 133 {
 134     return search_name_array(name, module_names, ARRAY_SIZE(module_names));
 135 }
 136
 137 /* Returns the current logging level for the given 'module' and 'facility'. */
 138 enum vlog_level
 139 vlog_get_level(enum vlog_module module, enum vlog_facility facility)
 140 {
 141     assert(module < VLM_N_MODULES);
 142     assert(facility < VLF_N_FACILITIES);
 143     return levels[module][facility];
 144 }
 145
 146 static void
 147 set_facility_level(enum vlog_facility facility, enum vlog_module module,
 148                    enum vlog_level level)
 149 {
 150     assert(facility >= 0 && facility < VLF_N_FACILITIES);
 151     assert(level < VLL_N_LEVELS);
 152
 153     if (module == VLM_ANY_MODULE) {
 154         for (module = 0; module < VLM_N_MODULES; module++) {
 155             levels[module][facility] = level;
 156         }
 157     } else {
 158         levels[module][facility] = level;
 159     }
 160 }
 161
 162 /* Sets the logging level for the given 'module' and 'facility' to 'level'. */
 163 void
 164 vlog_set_levels(enum vlog_module module, enum vlog_facility facility,
 165                 enum vlog_level level)
 166 {
 167     assert(facility < VLF_N_FACILITIES || facility == VLF_ANY_FACILITY);
 168     if (facility == VLF_ANY_FACILITY) {
 169         for (facility = 0; facility < VLF_N_FACILITIES; facility++) {
 170             set_facility_level(facility, module, level);
 171         }
 172     } else {
 173         set_facility_level(facility, module, level);
 174     }
 175 }
 176
 177 /* Set debugging levels:
 178  *
 179  *  mod[:facility[:level]] mod2[:facility[:level]] ...
 180  *
 181  * Return null if successful, otherwise an error message that the caller must
 182  * free().
 183  */
 184 char *
 185 vlog_set_levels_from_string(const char *s_)
 186 {
 187     char *save_ptr;
 188     char *s = xstrdup(s_);
 189     char *module, *level, *facility;
 190
 191     for (module = strtok_r(s, ": \t", &save_ptr); module != NULL;
 192          module = strtok_r(NULL, ": \t", &save_ptr)) {
 193         enum vlog_module e_module;
 194         enum vlog_level e_level;
 195         enum vlog_facility e_facility;
 196
 197         facility = strtok_r(NULL, ":", &save_ptr);
 198         level = strtok_r(NULL, ":", &save_ptr);
 199
 200         if (!strcmp(module, "ANY")) {
 201             e_module = VLM_ANY_MODULE;
 202         } else {
 203             e_module = vlog_get_module_val(module);
 204             if (e_module >= VLM_N_MODULES) {
 205                 char *msg = xasprintf("unknown module \"%s\"", module);
 206                 free(s);
 207                 return msg;
 208             }
 209         }
 210
 211         if (!facility || !strcmp(facility, "ANY")) {
 212             e_facility = VLF_ANY_FACILITY;
 213         } else {
 214             e_facility = vlog_get_facility_val(facility);
 215             if (e_facility >= VLF_N_FACILITIES) {
 216                 char *msg = xasprintf("unknown facility \"%s\"", facility);
 217                 free(s);
 218                 return msg;
 219             }
 220         }
 221
 222         e_level = level ? vlog_get_level_val(level) : VLL_DBG;
 223         if (e_level >= VLL_N_LEVELS) {
 224             char *msg = xasprintf("unknown level \"%s\"", level);
 225             free(s);
 226             return msg;
 227         }
 228
 229         vlog_set_levels(e_module, e_facility, e_level);
 230     }
 231     free(s);
 232     return NULL;
 233 }
 234
 235 /* If 'arg' is null, configure maximum verbosity.  Otherwise, sets
 236  * configuration according to 'arg' (see vlog_set_levels_from_string()). */
 237 void
 238 vlog_set_verbosity(const char *arg)
 239 {
 240     if (arg) {
 241         char *msg = vlog_set_levels_from_string(arg);
 242         if (msg) {
 243             ofp_fatal(0, "processing \"%s\": %s", arg, msg);
 244         }
 245     } else {
 246         vlog_set_levels(VLM_ANY_MODULE, VLF_ANY_FACILITY, VLL_DBG);
 247     }
 248 }
 249
 250 /* Initializes the logging subsystem. */
 251 void
 252 vlog_init(void)
 253 {
 254     time_t now;
 255
 256     openlog(program_name, LOG_NDELAY, LOG_DAEMON);
 257     vlog_set_levels(VLM_ANY_MODULE, VLF_ANY_FACILITY, VLL_WARN);
 258
 259     now = time_now();
 260     if (now < 0) {
 261         struct tm tm;
 262         char s[128];
 263
 264         localtime_r(&now, &tm);
 265         strftime(s, sizeof s, "%a, %d %b %Y %H:%M:%S %z", &tm);
 266         VLOG_ERR("current time is negative: %s (%ld)", s, (long int) now);
 267     }
 268 }
 269
 270 /* Closes the logging subsystem. */
 271 void
 272 vlog_exit(void)
 273 {
 274     closelog();
 275 }
 276
 277 /* Print the current logging level for each module. */
 278 char *
 279 vlog_get_levels(void)
 280 {
 281     struct ds s = DS_EMPTY_INITIALIZER;
 282     enum vlog_module module;
 283
 284     ds_put_format(&s, "                 console    syslog\n");
 285     ds_put_format(&s, "                 -------    ------\n");
 286
 287     for (module = 0; module < VLM_N_MODULES; module++) {
 288         ds_put_format(&s, "%-16s  %4s       %4s\n",
 289            vlog_get_module_name(module),
 290            vlog_get_level_name(vlog_get_level(module, VLF_CONSOLE)),
 291            vlog_get_level_name(vlog_get_level(module, VLF_SYSLOG)));
 292     }
 293
 294     return ds_cstr(&s);
 295 }
 296
 297 /* Returns true if a log message emitted for the given 'module' and 'level'
 298  * would cause some log output, false if that module and level are completely
 299  * disabled. */
 300 bool
 301 vlog_is_enabled(enum vlog_module module, enum vlog_level level)
 302 {
 303     return (levels[module][VLF_CONSOLE] >= level
 304             || levels[module][VLF_SYSLOG] >= level);
 305 }
 306
 307 /* Writes 'message' to the log at the given 'level' and as coming from the
 308  * given 'module'.
 309  *
 310  * Guaranteed to preserve errno. */
 311 void
 312 vlog_valist(enum vlog_module module, enum vlog_level level,
 313             const char *message, va_list args)
 314 {
 315     bool log_console = levels[module][VLF_CONSOLE] >= level;
 316     bool log_syslog = levels[module][VLF_SYSLOG] >= level;
 317     if (log_console || log_syslog) {
 318         int save_errno = errno;
 319         static int msg_num;
 320         const char *module_name = vlog_get_module_name(module);
 321         const char *level_name = vlog_get_level_name(level);
 322         time_t now;
 323         struct tm tm;
 324         size_t time_len;
 325         struct ds s;
 326
 327         now = time_now();
 328         localtime_r(&now, &tm);
 329
 330         /* Compose log message. */
 331         ds_init(&s);
 332         ds_reserve(&s, 1024);
 333         ds_put_strftime(&s, "%b %d %H:%M:%S|", &tm);
 334         time_len = s.length;
 335         ds_put_format(&s, "%05d|%s|%s:", ++msg_num, module_name, level_name);
 336         ds_put_format_valist(&s, message, args);
 337         ds_chomp(&s, '\n');
 338
 339         if (log_console) {
 340             fprintf(stderr, "%s\n", s.string);
 341         }
 342
 343         if (log_syslog) {
 344             int syslog_level = LOG_ALERT;
 345             char *save_ptr = NULL;
 346             char *line;
 347
 348             switch (level) {
 349             case VLL_EMER: syslog_level = LOG_ALERT; break;
 350             case VLL_ERR: syslog_level = LOG_ERR; break;
 351             case VLL_WARN: syslog_level = LOG_WARNING; break;
 352             case VLL_DBG: syslog_level = LOG_DEBUG; break;
 353             case VLL_N_LEVELS: NOT_REACHED();
 354             }
 355             for (line = strtok_r(&s.string[time_len], "\n", &save_ptr); line;
 356                  line = strtok_r(NULL, "\n", &save_ptr)) {
 357                 syslog(syslog_level, "%s", line);
 358             }
 359         }
 360
 361         ds_destroy(&s);
 362         errno = save_errno;
 363     }
 364 }
 365
 366 void
 367 vlog(enum vlog_module module, enum vlog_level level, const char *message, ...)
 368 {
 369     va_list args;
 370
 371     va_start(args, message);
 372     vlog_valist(module, level, message, args);
 373     va_end(args);
 374 }
 375
 376 void
 377 vlog_rate_limit(enum vlog_module module, enum vlog_level level,
 378                 struct vlog_rate_limit *rl, const char *message, ...)
 379 {
 380     va_list args;
 381
 382     if (!vlog_is_enabled(module, level)) {
 383         return;
 384     }
 385
 386     if (rl->tokens < VLOG_MSG_TOKENS) {
 387         time_t now = time_now();
 388         if (rl->last_fill > now) {
 389             /* Last filled in the future?  Time must have gone backward, or
 390              * 'rl' has not been used before. */
 391             rl->tokens = rl->burst;
 392         } else if (rl->last_fill < now) {
 393             unsigned int add = sat_mul(rl->rate, now - rl->last_fill);
 394             unsigned int tokens = sat_add(rl->tokens, add);
 395             rl->tokens = MIN(tokens, rl->burst);
 396             rl->last_fill = now;
 397         }
 398         if (rl->tokens < VLOG_MSG_TOKENS) {
 399             if (!rl->n_dropped) {
 400                 rl->first_dropped = now;
 401             }
 402             rl->n_dropped++;
 403             return;
 404         }
 405     }
 406     rl->tokens -= VLOG_MSG_TOKENS;
 407
 408     va_start(args, message);
 409     vlog_valist(module, level, message, args);
 410     va_end(args);
 411
 412     if (rl->n_dropped) {
 413         vlog(module, level,
 414              "Dropped %u messages in last %u seconds due to excessive rate",
 415              rl->n_dropped, (unsigned int) (time_now() - rl->first_dropped));
 416         rl->n_dropped = 0;
 417     }
 418 }