Make the format of vlog messages user-configurable.
authorBen Pfaff <blp@nicira.com>
Thu, 23 Oct 2008 18:08:23 +0000 (11:08 -0700)
committerBen Pfaff <blp@nicira.com>
Thu, 23 Oct 2008 18:08:23 +0000 (11:08 -0700)
controller/controller.8.in
include/vlog.h
lib/vlog.c
secchan/secchan.8.in
switch/switch.8.in
utilities/dpctl.8
utilities/ofp-discover.8.in
utilities/vlogconf.8

index 26c7c4cb388b09d6d35a0292454ef4cca3bf60a3..044125baa69dbfa4ea8e291206884dc0328889d6 100644 (file)
@@ -169,6 +169,11 @@ omitted, \fIlevel\fR defaults to \fBdbg\fR.
 Sets the maximum logging verbosity level, equivalent to
 \fB--verbose=ANY:ANY:dbg\fR.
 
+.TP
+\fB-vPATTERN:\fIfacility\fB:\fIpattern\fR, \fB--verbose=PATTERN:\fIfacility\fB:\fIpattern\fR
+Sets the log pattern for \fIfacility\fR to \fIpattern\fR.  Refer to
+\fBvlogconf\fR(8) for a description of the valid syntax for \fIpattern\fR.
+
 .TP
 .BR \-V ", " \-\^\-version
 Prints version information to the console.
index c6980a2f95476c87fd0a84de29ac7b8cbf851217..f96ce1a23e169e3f45695297a0537c164521219a 100644 (file)
 
 /* Logging importance levels. */
 #define VLOG_LEVELS                             \
-    VLOG_LEVEL(EMER)                            \
-    VLOG_LEVEL(ERR)                             \
-    VLOG_LEVEL(WARN)                            \
-    VLOG_LEVEL(DBG)
+    VLOG_LEVEL(EMER, LOG_ALERT)                 \
+    VLOG_LEVEL(ERR, LOG_ERR)                    \
+    VLOG_LEVEL(WARN, LOG_WARNING)               \
+    VLOG_LEVEL(DBG, LOG_DEBUG)
 enum vlog_level {
-#define VLOG_LEVEL(NAME) VLL_##NAME,
+#define VLOG_LEVEL(NAME, SYSLOG_LEVEL) VLL_##NAME,
     VLOG_LEVELS
 #undef VLOG_LEVEL
     VLL_N_LEVELS
@@ -57,11 +57,11 @@ const char *vlog_get_level_name(enum vlog_level);
 enum vlog_level vlog_get_level_val(const char *name);
 
 /* Facilities that we can log to. */
-#define VLOG_FACILITIES                         \
-    VLOG_FACILITY(SYSLOG                      \
-    VLOG_FACILITY(CONSOLE)
+#define VLOG_FACILITIES                                         \
+    VLOG_FACILITY(SYSLOG, "%05N|%c|%p|%m")                      \
+    VLOG_FACILITY(CONSOLE, "%d{%b %d %H:%M:%S}|%05N|%c|%p|%m")
 enum vlog_facility {
-#define VLOG_FACILITY(NAME) VLF_##NAME,
+#define VLOG_FACILITY(NAME, PATTERN) VLF_##NAME,
     VLOG_FACILITIES
 #undef VLOG_FACILITY
     VLF_N_FACILITIES,
@@ -115,6 +115,7 @@ struct vlog_rate_limit {
 /* Configuring how each module logs messages. */
 enum vlog_level vlog_get_level(enum vlog_module, enum vlog_facility);
 void vlog_set_levels(enum vlog_module, enum vlog_facility, enum vlog_level);
+void vlog_set_pattern(enum vlog_facility, const char *pattern);
 char *vlog_set_levels_from_string(const char *);
 char *vlog_get_levels(void);
 bool vlog_is_enabled(enum vlog_module, enum vlog_level);
index a136e5634902e981461d3fc6fd93f7bae049ba04..057d6d58c33029e3efd518a9b20e9b5c5d7528e1 100644 (file)
 #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 "dynamic-string.h"
 #include "sat-math.h"
 #include "timeval.h"
 
 /* Name for each logging level. */
 static const char *level_names[VLL_N_LEVELS] = {
-#define VLOG_LEVEL(NAME) #NAME,
+#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] = { 
-#define VLOG_FACILITY(NAME) #NAME,
-    VLOG_FACILITIES
-#undef VLOG_FACILITY
+/* 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,
 #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];
 
+/* Time at which vlog was initialized, in milliseconds. */
+static long long int boot_time;
+
 /* Searches the 'n_names' in 'names'.  Returns the index of a match for
  * 'target', or 'n_names' if no name matches. */
 static size_t
@@ -108,7 +126,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
@@ -116,7 +134,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'. */
@@ -174,6 +199,32 @@ 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);
+    }
+}
+
 /* Set debugging levels:
  *
  *  mod[:facility[:level]] mod2[:facility[:level]] ...
@@ -186,27 +237,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;
@@ -219,14 +257,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;
+                }
+            }
 
-        vlog_set_levels(e_module, e_facility, e_level);
+            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);
+        }
     }
     free(s);
     return NULL;
@@ -256,6 +314,7 @@ vlog_init(void)
     openlog(program_name, LOG_NDELAY, LOG_DAEMON);
     vlog_set_levels(VLM_ANY_MODULE, VLF_ANY_FACILITY, VLL_WARN);
 
+    boot_time = time_msec();
     now = time_now();
     if (now < 0) {
         struct tm tm;
@@ -304,6 +363,107 @@ vlog_is_enabled(enum vlog_module module, enum vlog_level level)
             || levels[module][VLF_SYSLOG] >= 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
  * given 'module'.
  *
@@ -316,43 +476,28 @@ vlog_valist(enum vlog_module module, enum vlog_level level,
     bool log_syslog = levels[module][VLF_SYSLOG] >= level;
     if (log_console || log_syslog) {
         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;
-        size_t time_len;
+        static unsigned int msg_num;
         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');
+        msg_num++;
 
         if (log_console) {
-            fprintf(stderr, "%s\n", s.string);
+            format_log_message(module, level, VLF_CONSOLE, msg_num,
+                               message, args, &s);
+            ds_put_char(&s, '\n');
+            fputs(ds_cstr(&s), stderr);
         }
 
         if (log_syslog) {
-            int syslog_level = LOG_ALERT;
+            int syslog_level = syslog_levels[level];
             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;
+            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_level, "%s", line);
             }
index beb57b0477f23b1e61536de1c1c67ddb08d0e25c..5e887915b7b654b5cd5c8d8b9a135ca51315d6c3 100644 (file)
@@ -441,6 +441,11 @@ omitted, \fIlevel\fR defaults to \fBdbg\fR.
 Sets the maximum logging verbosity level, equivalent to
 \fB--verbose=ANY:ANY:dbg\fR.
 
+.TP
+\fB-vPATTERN:\fIfacility\fB:\fIpattern\fR, \fB--verbose=PATTERN:\fIfacility\fB:\fIpattern\fR
+Sets the log pattern for \fIfacility\fR to \fIpattern\fR.  Refer to
+\fBvlogconf\fR(8) for a description of the valid syntax for \fIpattern\fR.
+
 .TP
 .BR \-V ", " \-\^\-version
 Prints version information to the console.
index aa1bbc425d02a734e4efe22bd67f9e58d48e9273..6d1a33b4f87fd0005878c54e3cd88fb8881ac46e 100644 (file)
@@ -129,6 +129,11 @@ omitted, \fIlevel\fR defaults to \fBdbg\fR.
 Sets the maximum logging verbosity level, equivalent to
 \fB--verbose=ANY:ANY:dbg\fR.
 
+.TP
+\fB-vPATTERN:\fIfacility\fB:\fIpattern\fR, \fB--verbose=PATTERN:\fIfacility\fB:\fIpattern\fR
+Sets the log pattern for \fIfacility\fR to \fIpattern\fR.  Refer to
+\fBvlogconf\fR(8) for a description of the valid syntax for \fIpattern\fR.
+
 .TP
 .BR \-V ", " \-\^\-version
 Prints version information to the console.
index a1fcd077767fccbc1e1221cdd90dd4d472c7264a..c7805932282bc82c7f0aeaf6279c68b9e34ca762 100644 (file)
@@ -448,6 +448,11 @@ omitted, \fIlevel\fR defaults to \fBdbg\fR.
 Sets the maximum logging verbosity level, equivalent to
 \fB--verbose=ANY:ANY:dbg\fR.
 
+.TP
+\fB-vPATTERN:\fIfacility\fB:\fIpattern\fR, \fB--verbose=PATTERN:\fIfacility\fB:\fIpattern\fR
+Sets the log pattern for \fIfacility\fR to \fIpattern\fR.  Refer to
+\fBvlogconf\fR(8) for a description of the valid syntax for \fIpattern\fR.
+
 .TP
 .BR \-V ", " \-\^\-version
 Prints version information to the console.
index 694b3b932e5b8530f0ad3f9615c2d5748f54f5eb..772bccbd63543f9201751adf74018ddb49ff6cec 100644 (file)
@@ -116,6 +116,11 @@ omitted, \fIlevel\fR defaults to \fBdbg\fR.
 Sets the maximum logging verbosity level, equivalent to
 \fB--verbose=ANY:ANY:dbg\fR.
 
+.TP
+\fB-vPATTERN:\fIfacility\fB:\fIpattern\fR, \fB--verbose=PATTERN:\fIfacility\fB:\fIpattern\fR
+Sets the log pattern for \fIfacility\fR to \fIpattern\fR.  Refer to
+\fBvlogconf\fR(8) for a description of the valid syntax for \fIpattern\fR.
+
 .TP
 .BR \-V ", " \-\^\-version
 Prints version information to the console.
index 74e81616bf8e71ff8bd862f221dde28e7f2c2aa9..7298d29d995cad2b8b4bb3895687ef369e357631 100644 (file)
@@ -57,6 +57,92 @@ logging levels for both facilities.  If it is omitted,
 minimum severity of a message for it to be logged.  If it is omitted,
 \fIlevel\fR defaults to \fBdbg\fR.
 
+.TP
+\fB-s PATTERN:\fIfacility\fB:\fIpattern\fR, \fB--set=PATTERN:\fIfacility\fB:\fIpattern\fR
+
+Sets the log pattern for \fIfacility\fR to \fIpattern\fR.  Each time a
+message is logged to \fIfacility\fR, \fIpattern\fR determines the
+message's formatting.  Most characters in \fIpattern\fR are copied
+literally to the log, but special escapes beginning with \fB%\fR are
+expanded as follows:
+
+.RS
+.TP
+\fB%A\fR
+The name of the application logging the message, e.g. \fBsecchan\fR.
+
+.TP
+\fB%c\fR
+The name of the module (as shown by \fBvlogconf --list\fR) logging
+the message.
+
+.TP
+\fB%d\fR
+The current date and time in ISO 8601 format (YYYY-MM-DD HH:MM:SS).
+
+.TP
+\fB%d{\fIformat\fB}\fR
+The current date and time in the specified \fIformat\fR, which takes
+the same format as the \fItemplate\fR argument to \fBstrftime\fR(3).
+
+.TP
+\fB%m\fR
+The message being logged.
+
+.TP
+\fB%N\fR
+A serial number for this message within this run of the program, as a
+decimal number.  The first message a program logs has serial number 1,
+the second one has serial number 2, and so on.
+
+.TP
+\fB%n\fR
+A new-line.
+
+.TP
+\fB%p\fR
+The level at which the message is logged, e.g. \fBDBG\fR.
+
+.TP
+\fB%P\fR
+The program's process ID (pid), as a decimal number.
+
+.TP
+\fB%r\fR
+The number of milliseconds elapsed from the start of the application
+to the time the message was logged.
+
+.TP
+\fB%%\fR
+A literal \fB%\fR.
+.RE
+
+.IP
+A few options may appear between the \fB%\fR and the format specifier
+character, in this order:
+
+.RS
+.TP
+\fB-\fR
+Left justify the escape's expansion within its field width.  Right
+justification is the default.
+
+.TP
+\fB0\fR
+Pad the field to the field width with \fB0\fRs.  Padding with spaces
+is the default.
+
+.TP
+\fIwidth\fR
+A number specifies the minimum field width.  If the escape expands to
+fewer characters than \fIwidth\fR then it is padded to fill the field
+width.  (A field wider than \fIwidth\fR is not truncated to fit.)
+.RE
+
+.IP
+The default pattern for console output is \fB%d{%b %d
+%H:%M:%S}|%05N|%c|%p|%m\fR; for syslog output, \fB%05N|%c|%p|%m\fR.
+
 .SH OPTIONS
 .TP
 \fB\-h\fR, \fB\-\^\-help\fR