X-Git-Url: http://git.onelab.eu/?a=blobdiff_plain;f=lib%2Fvlog.c;h=ddfab7614b37bbfa53a6931e949ab74112fd5b5e;hb=b9fddc9244da97d38b2fea80c69b0348a9b53d96;hp=6e098ef964ec8c1a9b254ebfbd403e793995101e;hpb=f12a5936173a7182fec670b2891137fc66adc929;p=sliver-openvswitch.git

diff --git a/lib/vlog.c b/lib/vlog.c
index 6e098ef96..ddfab7614 100644
--- a/lib/vlog.c
+++ b/lib/vlog.c
@@ -34,42 +34,70 @@
 #include <config.h>
 #include "vlog.h"
 #include <assert.h>
+#include <ctype.h>
 #include <errno.h>
 #include <stdarg.h>
 #include <stdlib.h>
 #include <string.h>
-#include <sys/ipc.h>
-#include <sys/shm.h>
+#include <sys/types.h>
 #include <syslog.h>
 #include <time.h>
+#include <unistd.h>
+#include "dirs.h"
 #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, SYSLOG_LEVEL) #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",
+/* Syslog value for each logging level. */
+static int syslog_levels[VLL_N_LEVELS] = {
+#define VLOG_LEVEL(NAME, SYSLOG_LEVEL) SYSLOG_LEVEL,
+    VLOG_LEVELS
+#undef VLOG_LEVEL
 };
 
 /* 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"
+#undef VLOG_MODULE
 };
 
+/* Information about each facility. */
+struct facility {
+    const char *name;           /* Name. */
+    char *pattern;              /* Current pattern. */
+    bool default_pattern;       /* Whether current pattern is the default. */
+};
+static struct facility facilities[VLF_N_FACILITIES] = {
+#define VLOG_FACILITY(NAME, PATTERN) {#NAME, PATTERN, true},
+    VLOG_FACILITIES
+#undef VLOG_FACILITY
+};
+
+/* Current log levels. */
 static int levels[VLM_N_MODULES][VLF_N_FACILITIES];
 
+/* For fast checking whether we're logging anything for a given module and
+ * level.*/
+enum vlog_level min_vlog_levels[VLM_N_MODULES];
+
+/* Time at which vlog was initialized, in milliseconds. */
+static long long int boot_time;
+
+/* VLF_FILE configuration. */
+static char *log_file_name;
+static FILE *log_file;
+
 /* Searches the 'n_names' in 'names'.  Returns the index of a match for
  * 'target', or 'n_names' if no name matches. */
 static size_t
@@ -107,7 +135,7 @@ const char *
 vlog_get_facility_name(enum vlog_facility facility) 
 {
     assert(facility < VLF_N_FACILITIES);
-    return facility_names[facility];
+    return facilities[facility].name;
 }
 
 /* Returns the logging facility named 'name', or VLF_N_FACILITIES if 'name' is
@@ -115,7 +143,14 @@ vlog_get_facility_name(enum vlog_facility facility)
 enum vlog_facility
 vlog_get_facility_val(const char *name) 
 {
-    return search_name_array(name, facility_names, ARRAY_SIZE(facility_names));
+    size_t i;
+
+    for (i = 0; i < VLF_N_FACILITIES; i++) {
+        if (!strcasecmp(facilities[i].name, name)) {
+            break;
+        }
+    }
+    return i;
 }
 
 /* Returns the name for logging module 'module'. */
@@ -142,6 +177,20 @@ vlog_get_level(enum vlog_module module, enum vlog_facility facility)
     return levels[module][facility];
 }
 
+static void
+update_min_level(enum vlog_module module)
+{
+    enum vlog_level min_level = VLL_EMER;
+    enum vlog_facility facility;
+
+    for (facility = 0; facility < VLF_N_FACILITIES; facility++) {
+        if (log_file || facility != VLF_FILE) {
+            min_level = MAX(min_level, levels[module][facility]); 
+        }
+    }
+    min_vlog_levels[module] = min_level;
+}
+
 static void
 set_facility_level(enum vlog_facility facility, enum vlog_module module,
                    enum vlog_level level)
@@ -152,9 +201,11 @@ set_facility_level(enum vlog_facility facility, enum vlog_module module,
     if (module == VLM_ANY_MODULE) {
         for (module = 0; module < VLM_N_MODULES; module++) {
             levels[module][facility] = level;
+            update_min_level(module);
         }
     } else {
         levels[module][facility] = level;
+        update_min_level(module);
     }
 }
 
@@ -173,6 +224,97 @@ vlog_set_levels(enum vlog_module module, enum vlog_facility facility,
     }
 }
 
+static void
+do_set_pattern(enum vlog_facility facility, const char *pattern) 
+{
+    struct facility *f = &facilities[facility];
+    if (!f->default_pattern) {
+        free(f->pattern);
+    } else {
+        f->default_pattern = false;
+    }
+    f->pattern = xstrdup(pattern);
+}
+
+/* Sets the pattern for the given 'facility' to 'pattern'. */
+void
+vlog_set_pattern(enum vlog_facility facility, const char *pattern)
+{
+    assert(facility < VLF_N_FACILITIES || facility == VLF_ANY_FACILITY);
+    if (facility == VLF_ANY_FACILITY) {
+        for (facility = 0; facility < VLF_N_FACILITIES; facility++) {
+            do_set_pattern(facility, pattern);
+        }
+    } else {
+        do_set_pattern(facility, pattern);
+    }
+}
+
+/* Returns the name of the log file used by VLF_FILE, or a null pointer if no
+ * log file has been set.  (A non-null return value does not assert that the
+ * named log file is in use: if vlog_set_log_file() or vlog_reopen_log_file()
+ * fails, it still sets the log file name.) */
+const char *
+vlog_get_log_file(void)
+{
+    return log_file_name;
+}
+
+/* Sets the name of the log file used by VLF_FILE to 'file_name', or to the
+ * default file name if 'file_name' is null.  Returns 0 if successful,
+ * otherwise a positive errno value. */
+int
+vlog_set_log_file(const char *file_name)
+{
+    char *old_log_file_name;
+    enum vlog_module module;
+    int error;
+
+    /* Close old log file. */
+    if (log_file) {
+        VLOG_WARN("closing log file");
+        fclose(log_file);
+        log_file = NULL;
+    }
+
+    /* Update log file name and free old name.  The ordering is important
+     * because 'file_name' might be 'log_file_name' or some suffix of it. */
+    old_log_file_name = log_file_name;
+    log_file_name = (file_name
+                     ? xstrdup(file_name)
+                     : xasprintf("%s/%s.log", ofp_logdir, program_name));
+    free(old_log_file_name);
+    file_name = NULL;           /* Might have been freed. */
+
+    /* Open new log file and update min_levels[] to reflect whether we actually
+     * have a log_file. */
+    log_file = fopen(log_file_name, "a");
+    for (module = 0; module < VLM_N_MODULES; module++) {
+        update_min_level(module);
+    }
+
+    /* Log success or failure. */
+    if (!log_file) {
+        VLOG_WARN("failed to open %s for logging: %s",
+                  log_file_name, strerror(errno));
+        error = errno;
+    } else {
+        VLOG_WARN("opened log file %s", log_file_name);
+        error = 0;
+    }
+
+    return error;
+}
+
+/* Closes and then attempts to re-open the current log file.  (This is useful
+ * just after log rotation, to ensure that the new log file starts being used.)
+ * Returns 0 if successful, otherwise a positive errno value. */
+int
+vlog_reopen_log_file(void)
+{
+    return vlog_set_log_file(log_file_name);
+}
+
 /* Set debugging levels:
  *
  *  mod[:facility[:level]] mod2[:facility[:level]] ...
@@ -185,27 +327,14 @@ vlog_set_levels_from_string(const char *s_)
 {
     char *save_ptr;
     char *s = xstrdup(s_);
-    char *module, *level, *facility;
+    char *module, *facility;
 
     for (module = strtok_r(s, ": \t", &save_ptr); module != NULL;
          module = strtok_r(NULL, ": \t", &save_ptr)) {
         enum vlog_module e_module;
-        enum vlog_level e_level;
         enum vlog_facility e_facility;
 
         facility = strtok_r(NULL, ":", &save_ptr);
-        level = strtok_r(NULL, ":", &save_ptr);
-
-        if (!strcmp(module, "ANY")) {
-            e_module = VLM_ANY_MODULE;
-        } else {
-            e_module = vlog_get_module_val(module);
-            if (e_module >= VLM_N_MODULES) {
-                char *msg = xasprintf("unknown module \"%s\"", module);
-                free(s);
-                return msg;
-            }
-        }
 
         if (!facility || !strcmp(facility, "ANY")) {
             e_facility = VLF_ANY_FACILITY;
@@ -218,14 +347,34 @@ vlog_set_levels_from_string(const char *s_)
             }
         }
 
-        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);
-            return msg;
-        }
+        if (!strcmp(module, "PATTERN")) {
+            vlog_set_pattern(e_facility, save_ptr);
+            break;
+        } else {
+            char *level;
+            enum vlog_level e_level;
+
+            if (!strcmp(module, "ANY")) {
+                e_module = VLM_ANY_MODULE;
+            } else {
+                e_module = vlog_get_module_val(module);
+                if (e_module >= VLM_N_MODULES) {
+                    char *msg = xasprintf("unknown module \"%s\"", module);
+                    free(s);
+                    return msg;
+                }
+            }
+
+            level = strtok_r(NULL, ":", &save_ptr);
+            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);
+                return msg;
+            }
 
-        vlog_set_levels(e_module, e_facility, e_level);
+            vlog_set_levels(e_module, e_facility, e_level);
+        }
     }
     free(s);
     return NULL;
@@ -239,7 +388,7 @@ 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_ANY_FACILITY, VLL_DBG);
@@ -255,7 +404,8 @@ vlog_init(void)
     openlog(program_name, LOG_NDELAY, LOG_DAEMON);
     vlog_set_levels(VLM_ANY_MODULE, VLF_ANY_FACILITY, VLL_WARN);
 
-    now = time(0);
+    boot_time = time_msec();
+    now = time_now();
     if (now < 0) {
         struct tm tm;
         char s[128];
@@ -280,14 +430,15 @@ vlog_get_levels(void)
     struct ds s = DS_EMPTY_INITIALIZER;
     enum vlog_module module;
 
-    ds_put_format(&s, "                 console    syslog\n");
-    ds_put_format(&s, "                 -------    ------\n");
+    ds_put_format(&s, "                 console    syslog    file\n");
+    ds_put_format(&s, "                 -------    ------    ------\n");
 
     for (module = 0; module < VLM_N_MODULES; module++) {
-        ds_put_format(&s, "%-16s  %4s       %4s\n",
+        ds_put_format(&s, "%-16s  %4s       %4s       %4s\n",
            vlog_get_module_name(module),
            vlog_get_level_name(vlog_get_level(module, VLF_CONSOLE)),
-           vlog_get_level_name(vlog_get_level(module, VLF_SYSLOG)));
+           vlog_get_level_name(vlog_get_level(module, VLF_SYSLOG)),
+           vlog_get_level_name(vlog_get_level(module, VLF_FILE)));
     }
 
     return ds_cstr(&s);
@@ -299,8 +450,108 @@ vlog_get_levels(void)
 bool
 vlog_is_enabled(enum vlog_module module, enum vlog_level level)
 {
-    return (levels[module][VLF_CONSOLE] >= level
-            || levels[module][VLF_SYSLOG] >= level);
+    return min_vlog_levels[module] >= level;
+}
+
+static const char *
+fetch_braces(const char *p, const char *def, char *out, size_t out_size)
+{
+    if (*p == '{') {
+        size_t n = strcspn(p + 1, "}");
+        size_t n_copy = MIN(n, out_size - 1);
+        memcpy(out, p + 1, n_copy);
+        out[n_copy] = '\0';
+        p += n + 2;
+    } else {
+        strlcpy(out, def, out_size);
+    }
+    return p;
+}
+
+static void
+format_log_message(enum vlog_module module, enum vlog_level level,
+                   enum vlog_facility facility, unsigned int msg_num,
+                   const char *message, va_list args_, struct ds *s)
+{
+    char tmp[128];
+    va_list args;
+    const char *p;
+
+    ds_clear(s);
+    for (p = facilities[facility].pattern; *p != '\0'; ) {
+        enum { LEFT, RIGHT } justify = RIGHT;
+        int pad = '0';
+        size_t length, field, used;
+
+        if (*p != '%') {
+            ds_put_char(s, *p++);
+            continue;
+        }
+
+        p++;
+        if (*p == '-') {
+            justify = LEFT;
+            p++;
+        }
+        if (*p == '0') {
+            pad = '0';
+            p++;
+        }
+        field = 0;
+        while (isdigit(*p)) {
+            field = (field * 10) + (*p - '0');
+            p++;
+        }
+
+        length = s->length;
+        switch (*p++) {
+        case 'A':
+            ds_put_cstr(s, program_name);
+            break;
+        case 'c':
+            p = fetch_braces(p, "", tmp, sizeof tmp);
+            ds_put_cstr(s, vlog_get_module_name(module));
+            break;
+        case 'd':
+            p = fetch_braces(p, "%Y-%m-%d %H:%M:%S", tmp, sizeof tmp);
+            ds_put_strftime(s, tmp, NULL);
+            break;
+        case 'm':
+            va_copy(args, args_);
+            ds_put_format_valist(s, message, args);
+            va_end(args);
+            break;
+        case 'N':
+            ds_put_format(s, "%u", msg_num);
+            break;
+        case 'n':
+            ds_put_char(s, '\n');
+            break;
+        case 'p':
+            ds_put_cstr(s, vlog_get_level_name(level));
+            break;
+        case 'P':
+            ds_put_format(s, "%ld", (long int) getpid());
+            break;
+        case 'r':
+            ds_put_format(s, "%lld", time_msec() - boot_time);
+            break;
+        default:
+            ds_put_char(s, p[-1]);
+            break;
+        }
+        used = s->length - length;
+        if (used < field) {
+            size_t n_pad = field - used;
+            if (justify == RIGHT) {
+                ds_put_uninit(s, n_pad);
+                memmove(&s->string[length + n_pad], &s->string[length], used);
+                memset(&s->string[length], pad, n_pad);
+            } else {
+                ds_put_char_multiple(s, pad, n_pad);
+            }
+        }
+    }
 }
 
 /* Writes 'message' to the log at the given 'level' and as coming from the
@@ -308,56 +559,115 @@ 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;
-    if (log_console || log_syslog) {
+    bool log_to_console = levels[module][VLF_CONSOLE] >= level;
+    bool log_to_syslog = levels[module][VLF_SYSLOG] >= level;
+    bool log_to_file = levels[module][VLF_FILE] >= level && log_file;
+    if (log_to_console || log_to_syslog || log_to_file) {
         int save_errno = errno;
-        static int msg_num;
-        const char *module_name = vlog_get_module_name(module);
-        const char *level_name = vlog_get_level_name(level);
-        time_t now;
-        struct tm tm;
-        va_list args;
-        char s[1024];
-        size_t len, time_len;
-
-        now = time(0);
-        localtime_r(&now, &tm);
-
-        len = time_len = strftime(s, sizeof s, "%b %d %H:%M:%S|", &tm);
-        len += sprintf(s + len, "%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';
+        static unsigned int msg_num;
+        struct ds s;
+
+        ds_init(&s);
+        ds_reserve(&s, 1024);
+        msg_num++;
+
+        if (log_to_console) {
+            format_log_message(module, level, VLF_CONSOLE, msg_num,
+                               message, args, &s);
+            ds_put_char(&s, '\n');
+            fputs(ds_cstr(&s), stderr);
         }
 
-        if (log_console) {
-            fprintf(stderr, "%s\n", s);
-        }
-
-        if (log_syslog) {
-            static const int syslog_levels[VLL_N_LEVELS] = {
-                [VLL_EMER] = LOG_ALERT,
-                [VLL_ERR] = LOG_ERR,
-                [VLL_WARN] = LOG_WARNING,
-                [VLL_DBG] = LOG_DEBUG,
-            };
+        if (log_to_syslog) {
+            int syslog_level = syslog_levels[level];
             char *save_ptr = NULL;
             char *line;
 
-            for (line = strtok_r(s + time_len, "\n", &save_ptr); line != NULL;
+            format_log_message(module, level, VLF_SYSLOG, msg_num,
+                               message, args, &s);
+            for (line = strtok_r(s.string, "\n", &save_ptr); line;
                  line = strtok_r(NULL, "\n", &save_ptr)) {
-                syslog(syslog_levels[level], "%s", line);
+                syslog(syslog_level, "%s", line);
             }
         }
+
+        if (log_to_file) {
+            format_log_message(module, level, VLF_FILE, msg_num,
+                               message, args, &s);
+            ds_put_char(&s, '\n');
+            fputs(ds_cstr(&s), log_file);
+            fflush(log_file);
+        }
+
+        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;
+    }
+}
+
+void
+vlog_usage(void) 
+{
+    printf("\nLogging options:\n"
+           "  -v, --verbose=MODULE[:FACILITY[:LEVEL]]  set logging levels\n"
+           "  -v, --verbose           set maximum verbosity level\n"
+           "  --log-file[=FILE]       enable logging to specified FILE\n"
+           "                          (default: %s/%s.log)\n",
+           ofp_logdir, program_name);
+}