util: Introduce "subprogram_name" to identify subprocesses and threads.
[openvswitch] / lib / vlog.c
index 7d9c061e47bee0feb2c89d63ef966df02f3c06f8..128ed45dcf5b46b6bb6ba6aa650ea5df3f556065 100644 (file)
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2008, 2009, 2010, 2011 Nicira Networks.
+ * Copyright (c) 2008, 2009, 2010, 2011, 2012 Nicira, Inc.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -82,9 +82,6 @@ static struct facility facilities[VLF_N_FACILITIES] = {
 #undef VLOG_FACILITY
 };
 
-/* 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;
@@ -344,69 +341,78 @@ vlog_reopen_log_file(void)
     return vlog_set_log_file(log_file_name);
 }
 
-/* Set debugging levels:
- *
- *  mod[:facility[:level]] mod2[:facility[:level]] ...
- *
- * Return null if successful, otherwise an error message that the caller must
- * free().
- */
+/* Set debugging levels.  Returns null if successful, otherwise an error
+ * message that the caller must free(). */
 char *
 vlog_set_levels_from_string(const char *s_)
 {
-    char *save_ptr = NULL;
     char *s = xstrdup(s_);
-    char *module, *facility;
-
-    for (module = strtok_r(s, ": \t", &save_ptr); module != NULL;
-         module = strtok_r(NULL, ": \t", &save_ptr)) {
-        struct vlog_module *e_module;
-        enum vlog_facility e_facility;
+    char *save_ptr = NULL;
+    char *msg = NULL;
+    char *word;
 
-        facility = strtok_r(NULL, ":", &save_ptr);
+    word = strtok_r(s, " ,:\t", &save_ptr);
+    if (word && !strcasecmp(word, "PATTERN")) {
+        enum vlog_facility facility;
 
-        if (!facility || !strcasecmp(facility, "ANY")) {
-            e_facility = VLF_ANY_FACILITY;
-        } else {
-            e_facility = vlog_get_facility_val(facility);
-            if (e_facility >= VLF_N_FACILITIES) {
-                char *msg = xasprintf("unknown facility \"%s\"", facility);
-                free(s);
-                return msg;
-            }
+        word = strtok_r(NULL, " ,:\t", &save_ptr);
+        if (!word) {
+            msg = xstrdup("missing facility");
+            goto exit;
         }
 
-        if (!strcasecmp(module, "PATTERN")) {
-            vlog_set_pattern(e_facility, save_ptr);
-            break;
-        } else {
-            char *level;
-            enum vlog_level e_level;
-
-            if (!strcasecmp(module, "ANY")) {
-                e_module = NULL;
-            } else {
-                e_module = vlog_module_from_name(module);
-                if (!e_module) {
-                    char *msg = xasprintf("unknown module \"%s\"", module);
-                    free(s);
-                    return msg;
+        facility = (!strcasecmp(word, "ANY")
+                    ? VLF_ANY_FACILITY
+                    : vlog_get_facility_val(word));
+        if (facility == VLF_N_FACILITIES) {
+            msg = xasprintf("unknown facility \"%s\"", word);
+            goto exit;
+        }
+        vlog_set_pattern(facility, save_ptr);
+    } else {
+        struct vlog_module *module = NULL;
+        enum vlog_level level = VLL_N_LEVELS;
+        enum vlog_facility facility = VLF_N_FACILITIES;
+
+        for (; word != NULL; word = strtok_r(NULL, " ,:\t", &save_ptr)) {
+            if (!strcasecmp(word, "ANY")) {
+                continue;
+            } else if (vlog_get_facility_val(word) != VLF_N_FACILITIES) {
+                if (facility != VLF_N_FACILITIES) {
+                    msg = xstrdup("cannot specify multiple facilities");
+                    goto exit;
                 }
+                facility = vlog_get_facility_val(word);
+            } else if (vlog_get_level_val(word) != VLL_N_LEVELS) {
+                if (level != VLL_N_LEVELS) {
+                    msg = xstrdup("cannot specify multiple levels");
+                    goto exit;
+                }
+                level = vlog_get_level_val(word);
+            } else if (vlog_module_from_name(word)) {
+                if (module) {
+                    msg = xstrdup("cannot specify multiple modules");
+                    goto exit;
+                }
+                module = vlog_module_from_name(word);
+            } else {
+                msg = xasprintf("no facility, level, or module \"%s\"", word);
+                goto exit;
             }
+        }
 
-            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);
+        if (facility == VLF_N_FACILITIES) {
+            facility = VLF_ANY_FACILITY;
         }
+        if (level == VLL_N_LEVELS) {
+            level = VLL_DBG;
+        }
+        vlog_set_levels(module, facility, level);
     }
+
+exit:
     free(s);
-    return NULL;
+    return msg;
 }
 
 /* If 'arg' is null, configure maximum verbosity.  Otherwise, sets
@@ -433,12 +439,12 @@ vlog_unixctl_set(struct unixctl_conn *conn, int argc, const char *argv[],
     for (i = 1; i < argc; i++) {
         char *msg = vlog_set_levels_from_string(argv[i]);
         if (msg) {
-            unixctl_command_reply(conn, 501, msg);
+            unixctl_command_reply_error(conn, msg);
             free(msg);
             return;
         }
     }
-    unixctl_command_reply(conn, 202, NULL);
+    unixctl_command_reply(conn, NULL);
 }
 
 static void
@@ -446,7 +452,7 @@ vlog_unixctl_list(struct unixctl_conn *conn, int argc OVS_UNUSED,
                   const char *argv[] OVS_UNUSED, void *aux OVS_UNUSED)
 {
     char *msg = vlog_get_levels();
-    unixctl_command_reply(conn, 200, msg);
+    unixctl_command_reply(conn, msg);
     free(msg);
 }
 
@@ -457,12 +463,12 @@ vlog_unixctl_reopen(struct unixctl_conn *conn, int argc OVS_UNUSED,
     if (log_file_name) {
         int error = vlog_reopen_log_file();
         if (error) {
-            unixctl_command_reply(conn, 503, strerror(errno));
+            unixctl_command_reply_error(conn, strerror(errno));
         } else {
-            unixctl_command_reply(conn, 202, NULL);
+            unixctl_command_reply(conn, NULL);
         }
     } else {
-        unixctl_command_reply(conn, 403, "Logging to file not configured");
+        unixctl_command_reply_error(conn, "Logging to file not configured");
     }
 }
 
@@ -471,6 +477,7 @@ vlog_unixctl_reopen(struct unixctl_conn *conn, int argc OVS_UNUSED,
 void
 vlog_init(void)
 {
+    static char *program_name_copy;
     time_t now;
 
     if (vlog_inited) {
@@ -478,21 +485,26 @@ vlog_init(void)
     }
     vlog_inited = true;
 
-    openlog(program_name, LOG_NDELAY, LOG_DAEMON);
+    /* openlog() is allowed to keep the pointer passed in, without making a
+     * copy.  The daemonize code sometimes frees and replaces 'program_name',
+     * so make a private copy just for openlog().  (We keep a pointer to the
+     * private copy to suppress memory leak warnings in case openlog() does
+     * make its own copy.) */
+    program_name_copy = program_name ? xstrdup(program_name) : NULL;
+    openlog(program_name_copy, LOG_NDELAY, LOG_DAEMON);
 
-    boot_time = time_msec();
     now = time_wall();
     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);
+        gmtime_r(&now, &tm);
+        strftime(s, sizeof s, "%a, %d %b %Y %H:%M:%S", &tm);
         VLOG_ERR("current time is negative: %s (%ld)", s, (long int) now);
     }
 
     unixctl_command_register(
-        "vlog/set", "{module[:facility[:level]] | PATTERN:facility:pattern}",
+        "vlog/set", "{spec | PATTERN:facility:pattern}",
         1, INT_MAX, vlog_unixctl_set, NULL);
     unixctl_command_register("vlog/list", "", 0, 0, vlog_unixctl_list, NULL);
     unixctl_command_register("vlog/reopen", "", 0, 0,
@@ -639,7 +651,15 @@ format_log_message(const struct vlog_module *module, enum vlog_level level,
             ds_put_format(s, "%ld", (long int) getpid());
             break;
         case 'r':
-            ds_put_format(s, "%lld", time_msec() - boot_time);
+            ds_put_format(s, "%lld", time_msec() - time_boot_msec());
+            break;
+        case 't':
+            ds_put_cstr(s, subprogram_name[0] ? subprogram_name : "main");
+            break;
+        case 'T':
+            if (subprogram_name[0]) {
+                ds_put_format(s, "(%s)", subprogram_name);
+            }
             break;
         default:
             ds_put_char(s, p[-1]);
@@ -757,28 +777,15 @@ vlog_should_drop(const struct vlog_module *module, enum vlog_level level,
         return true;
     }
 
-    if (rl->tokens < VLOG_MSG_TOKENS) {
+    if (!token_bucket_withdraw(&rl->token_bucket, 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->last_dropped = now;
-            rl->n_dropped++;
-            return true;
+        if (!rl->n_dropped) {
+            rl->first_dropped = now;
         }
+        rl->last_dropped = now;
+        rl->n_dropped++;
+        return true;
     }
-    rl->tokens -= VLOG_MSG_TOKENS;
 
     if (rl->n_dropped) {
         time_t now = time_now();
@@ -812,7 +819,7 @@ void
 vlog_usage(void)
 {
     printf("\nLogging options:\n"
-           "  -v, --verbose=MODULE[:FACILITY[:LEVEL]]  set logging levels\n"
+           "  -v, --verbose=[SPEC]    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",