X-Git-Url: http://git.onelab.eu/?a=blobdiff_plain;f=lib%2Fvlog.c;h=a136e5634902e981461d3fc6fd93f7bae049ba04;hb=4528f887d1f035ad74388598e119f34a4910d3c3;hp=17f20a2cb9a9249b426eea77366622532190460a;hpb=c44bef2f6ec77d20e97e26decfb5335c6c110679;p=sliver-openvswitch.git diff --git a/lib/vlog.c b/lib/vlog.c index 17f20a2cb..a136e5634 100644 --- a/lib/vlog.c +++ b/lib/vlog.c @@ -31,6 +31,7 @@ * derivatives without specific, written prior permission. */ +#include #include "vlog.h" #include #include @@ -40,28 +41,32 @@ #include #include #include +#include #include "dynamic-string.h" +#include "sat-math.h" +#include "timeval.h" #include "util.h" +#define THIS_MODULE VLM_vlog + /* Name for each logging level. */ static const char *level_names[VLL_N_LEVELS] = { - [VLL_EMER] = "EMER", - [VLL_ERR] = "ERR", - [VLL_WARN] = "WARN", - [VLL_DBG] = "DBG", +#define VLOG_LEVEL(NAME) #NAME, + VLOG_LEVELS +#undef VLOG_LEVEL }; /* Name for each logging facility. */ static const char *facility_names[VLF_N_FACILITIES] = { - [VLF_CONSOLE] = "console", - [VLF_SYSLOG] = "syslog", +#define VLOG_FACILITY(NAME) #NAME, + VLOG_FACILITIES +#undef VLOG_FACILITY }; /* Name for each logging module */ static const char *module_names[VLM_N_MODULES] = { #define VLOG_MODULE(NAME) #NAME, - VLOG_MODULES -#undef VLOG_MODULES +#include "vlog-modules.def" }; static int levels[VLM_N_MODULES][VLF_N_FACILITIES]; @@ -171,7 +176,7 @@ vlog_set_levels(enum vlog_module module, enum vlog_facility facility, /* Set debugging levels: * - * mod:facility:level mod2:facility:level ... + * mod[:facility[:level]] mod2[:facility[:level]] ... * * Return null if successful, otherwise an error message that the caller must * free(). @@ -191,10 +196,6 @@ vlog_set_levels_from_string(const char *s_) facility = strtok_r(NULL, ":", &save_ptr); level = strtok_r(NULL, ":", &save_ptr); - if (level == NULL || facility == NULL) { - free(s); - return xstrdup("syntax error in level string"); - } if (!strcmp(module, "ANY")) { e_module = VLM_ANY_MODULE; @@ -207,7 +208,7 @@ vlog_set_levels_from_string(const char *s_) } } - if (!strcmp(facility, "ANY")) { + if (!facility || !strcmp(facility, "ANY")) { e_facility = VLF_ANY_FACILITY; } else { e_facility = vlog_get_facility_val(facility); @@ -218,7 +219,7 @@ vlog_set_levels_from_string(const char *s_) } } - e_level = vlog_get_level_val(level); + e_level = level ? vlog_get_level_val(level) : VLL_DBG; if (e_level >= VLL_N_LEVELS) { char *msg = xasprintf("unknown level \"%s\"", level); free(s); @@ -239,10 +240,10 @@ vlog_set_verbosity(const char *arg) if (arg) { char *msg = vlog_set_levels_from_string(arg); if (msg) { - fatal(0, "processing \"%s\": %s", arg, msg); + ofp_fatal(0, "processing \"%s\": %s", arg, msg); } } else { - vlog_set_levels(VLM_ANY_MODULE, VLF_CONSOLE, VLL_DBG); + vlog_set_levels(VLM_ANY_MODULE, VLF_ANY_FACILITY, VLL_DBG); } } @@ -250,8 +251,20 @@ vlog_set_verbosity(const char *arg) void vlog_init(void) { + time_t now; + openlog(program_name, LOG_NDELAY, LOG_DAEMON); - vlog_set_levels(VLM_ANY_MODULE, VLF_CONSOLE, VLL_WARN); + vlog_set_levels(VLM_ANY_MODULE, VLF_ANY_FACILITY, VLL_WARN); + + now = time_now(); + if (now < 0) { + struct tm tm; + char s[128]; + + localtime_r(&now, &tm); + strftime(s, sizeof s, "%a, %d %b %Y %H:%M:%S %z", &tm); + VLOG_ERR("current time is negative: %s (%ld)", s, (long int) now); + } } /* Closes the logging subsystem. */ @@ -296,7 +309,8 @@ vlog_is_enabled(enum vlog_module module, enum vlog_level level) * * Guaranteed to preserve errno. */ void -vlog(enum vlog_module module, enum vlog_level level, const char *message, ...) +vlog_valist(enum vlog_module module, enum vlog_level level, + const char *message, va_list args) { bool log_console = levels[module][VLF_CONSOLE] >= level; bool log_syslog = levels[module][VLF_SYSLOG] >= level; @@ -305,35 +319,100 @@ vlog(enum vlog_module module, enum vlog_level level, const char *message, ...) static int msg_num; const char *module_name = vlog_get_module_name(module); const char *level_name = vlog_get_level_name(level); - va_list args; - char s[1024]; - size_t len; - - len = sprintf(s, "%05d|%s|%s:", ++msg_num, module_name, level_name); - va_start(args, message); - len += vsnprintf(s + len, sizeof s - len, message, args); - va_end(args); - if (len >= sizeof s) { - len = sizeof s; - } - if (s[len - 1] == '\n') { - s[len - 1] = '\0'; - } + time_t now; + struct tm tm; + size_t time_len; + struct ds s; + + now = time_now(); + localtime_r(&now, &tm); + + /* Compose log message. */ + ds_init(&s); + ds_reserve(&s, 1024); + ds_put_strftime(&s, "%b %d %H:%M:%S|", &tm); + time_len = s.length; + ds_put_format(&s, "%05d|%s|%s:", ++msg_num, module_name, level_name); + ds_put_format_valist(&s, message, args); + ds_chomp(&s, '\n'); if (log_console) { - fprintf(stderr, "%s\n", s); + fprintf(stderr, "%s\n", s.string); } if (log_syslog) { - static const int syslog_levels[VLL_N_LEVELS] = { - [VLL_EMER] = LOG_EMERG, - [VLL_ERR] = LOG_ERR, - [VLL_WARN] = LOG_WARNING, - [VLL_DBG] = LOG_DEBUG, - }; - - syslog(syslog_levels[level], "%s", s); + int syslog_level = LOG_ALERT; + char *save_ptr = NULL; + char *line; + + switch (level) { + case VLL_EMER: syslog_level = LOG_ALERT; break; + case VLL_ERR: syslog_level = LOG_ERR; break; + case VLL_WARN: syslog_level = LOG_WARNING; break; + case VLL_DBG: syslog_level = LOG_DEBUG; break; + case VLL_N_LEVELS: NOT_REACHED(); + } + for (line = strtok_r(&s.string[time_len], "\n", &save_ptr); line; + line = strtok_r(NULL, "\n", &save_ptr)) { + syslog(syslog_level, "%s", line); + } } + + ds_destroy(&s); errno = save_errno; } } + +void +vlog(enum vlog_module module, enum vlog_level level, const char *message, ...) +{ + va_list args; + + va_start(args, message); + vlog_valist(module, level, message, args); + va_end(args); +} + +void +vlog_rate_limit(enum vlog_module module, enum vlog_level level, + struct vlog_rate_limit *rl, const char *message, ...) +{ + va_list args; + + if (!vlog_is_enabled(module, level)) { + return; + } + + if (rl->tokens < VLOG_MSG_TOKENS) { + time_t now = time_now(); + if (rl->last_fill > now) { + /* Last filled in the future? Time must have gone backward, or + * 'rl' has not been used before. */ + rl->tokens = rl->burst; + } else if (rl->last_fill < now) { + unsigned int add = sat_mul(rl->rate, now - rl->last_fill); + unsigned int tokens = sat_add(rl->tokens, add); + rl->tokens = MIN(tokens, rl->burst); + rl->last_fill = now; + } + if (rl->tokens < VLOG_MSG_TOKENS) { + if (!rl->n_dropped) { + rl->first_dropped = now; + } + rl->n_dropped++; + return; + } + } + rl->tokens -= VLOG_MSG_TOKENS; + + va_start(args, message); + vlog_valist(module, level, message, args); + va_end(args); + + if (rl->n_dropped) { + vlog(module, level, + "Dropped %u messages in last %u seconds due to excessive rate", + rl->n_dropped, (unsigned int) (time_now() - rl->first_dropped)); + rl->n_dropped = 0; + } +}