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