#include "ofpbuf.h"
#include "ovs-thread.h"
#include "sat-math.h"
+#include "socket-util.h"
#include "svec.h"
#include "timeval.h"
#include "unixctl.h"
VLOG_DEFINE_THIS_MODULE(vlog);
-COVERAGE_DEFINE(vlog_recursive);
-
/* ovs_assert() logs the assertion message, so using ovs_assert() in this
* source file could cause recursion. */
#undef ovs_assert
/* Name for each logging level. */
static const char *const level_names[VLL_N_LEVELS] = {
-#define VLOG_LEVEL(NAME, SYSLOG_LEVEL) #NAME,
+#define VLOG_LEVEL(NAME, SYSLOG_LEVEL, RFC5424) #NAME,
VLOG_LEVELS
#undef VLOG_LEVEL
};
/* Syslog value for each logging level. */
static const int syslog_levels[VLL_N_LEVELS] = {
-#define VLOG_LEVEL(NAME, SYSLOG_LEVEL) SYSLOG_LEVEL,
+#define VLOG_LEVEL(NAME, SYSLOG_LEVEL, RFC5424) SYSLOG_LEVEL,
VLOG_LEVELS
#undef VLOG_LEVEL
};
+/* RFC 5424 defines specific values for each syslog level. Normally LOG_* use
+ * the same values. Verify that in fact they're the same. If we get assertion
+ * failures here then we need to define a separate rfc5424_levels[] array. */
+#define VLOG_LEVEL(NAME, SYSLOG_LEVEL, RFC5424) \
+ BUILD_ASSERT_DECL(SYSLOG_LEVEL == RFC5424);
+VLOG_LEVELS
+#undef VLOG_LEVELS
+
+/* Similarly, RFC 5424 defines the local0 facility with the value ordinarily
+ * used for LOG_LOCAL0. */
+BUILD_ASSERT_DECL(LOG_LOCAL0 == (16 << 3));
+
/* The log modules. */
#if USE_LINKER_SECTIONS
extern struct vlog_module *__start_vlog_modules[];
#include "vlog-modules.def"
#undef VLOG_MODULE
+extern struct vlog_module *vlog_modules[];
struct vlog_module *vlog_modules[] = {
#define VLOG_MODULE(NAME) &VLM_##NAME,
#include "vlog-modules.def"
#define n_vlog_modules ARRAY_SIZE(vlog_modules)
#endif
+/* Protects the 'pattern' in all "struct facility"s, so that a race between
+ * changing and reading the pattern does not cause an access to freed
+ * memory. */
+static struct ovs_rwlock pattern_rwlock = OVS_RWLOCK_INITIALIZER;
+
/* Information about each facility. */
struct facility {
const char *name; /* Name. */
- char *pattern; /* Current pattern (see 'pattern_rwlock'). */
+ char *pattern OVS_GUARDED_BY(pattern_rwlock); /* Current pattern. */
bool default_pattern; /* Whether current pattern is the default. */
};
static struct facility facilities[VLF_N_FACILITIES] = {
#undef VLOG_FACILITY
};
-/* Protects the 'pattern' in all "struct facility"s, so that a race between
- * changing and reading the pattern does not cause an access to freed
- * memory. */
-static pthread_rwlock_t pattern_rwlock = PTHREAD_RWLOCK_INITIALIZER;
-
/* Sequence number for the message currently being composed. */
-DEFINE_PER_THREAD_DATA(unsigned int, msg_num, 0);
+DEFINE_STATIC_PER_THREAD_DATA(unsigned int, msg_num, 0);
/* VLF_FILE configuration.
*
* All of the following is protected by 'log_file_mutex', which nests inside
* pattern_rwlock. */
-static pthread_mutex_t log_file_mutex = PTHREAD_ADAPTIVE_MUTEX_INITIALIZER;
-static char *log_file_name;
-static int log_fd = -1;
-static struct async_append *log_writer;
+static struct ovs_mutex log_file_mutex = OVS_MUTEX_INITIALIZER;
+static char *log_file_name OVS_GUARDED_BY(log_file_mutex);
+static int log_fd OVS_GUARDED_BY(log_file_mutex) = -1;
+static struct async_append *log_writer OVS_GUARDED_BY(log_file_mutex);
+static bool log_async OVS_GUARDED_BY(log_file_mutex);
+
+/* Syslog export configuration. */
+static int syslog_fd OVS_GUARDED_BY(pattern_rwlock) = -1;
static void format_log_message(const struct vlog_module *, enum vlog_level,
- enum vlog_facility,
+ const char *pattern,
const char *message, va_list, struct ds *)
PRINTF_FORMAT(4, 0);
return module->levels[facility];
}
-static void OVS_MUST_HOLD(log_file_mutex)
-update_min_level(struct vlog_module *module)
+static void
+update_min_level(struct vlog_module *module) OVS_REQUIRES(&log_file_mutex)
{
enum vlog_facility facility;
assert(facility >= 0 && facility < VLF_N_FACILITIES);
assert(level < VLL_N_LEVELS);
- xpthread_mutex_lock(&log_file_mutex);
+ ovs_mutex_lock(&log_file_mutex);
if (!module) {
struct vlog_module **mp;
module->levels[facility] = level;
update_min_level(module);
}
- xpthread_mutex_unlock(&log_file_mutex);
+ ovs_mutex_unlock(&log_file_mutex);
}
/* Sets the logging level for the given 'module' and 'facility' to 'level'. A
{
struct facility *f = &facilities[facility];
- xpthread_rwlock_wrlock(&pattern_rwlock);
+ ovs_rwlock_wrlock(&pattern_rwlock);
if (!f->default_pattern) {
free(f->pattern);
} else {
f->default_pattern = false;
}
f->pattern = xstrdup(pattern);
- xpthread_rwlock_unlock(&pattern_rwlock);
+ ovs_rwlock_unlock(&pattern_rwlock);
}
/* Sets the pattern for the given 'facility' to 'pattern'. */
struct stat new_stat;
int new_log_fd;
bool same_file;
+ bool log_close;
/* Open new log file. */
new_log_file_name = (file_name
}
/* If the new log file is the same one we already have open, bail out. */
- xpthread_mutex_lock(&log_file_mutex);
+ ovs_mutex_lock(&log_file_mutex);
same_file = (log_fd >= 0
&& new_log_fd >= 0
&& !fstat(log_fd, &old_stat)
&& !fstat(new_log_fd, &new_stat)
&& old_stat.st_dev == new_stat.st_dev
&& old_stat.st_ino == new_stat.st_ino);
- xpthread_mutex_unlock(&log_file_mutex);
+ ovs_mutex_unlock(&log_file_mutex);
if (same_file) {
close(new_log_fd);
free(new_log_file_name);
}
/* Log closing old log file (we can't log while holding log_file_mutex). */
- if (log_fd >= 0) {
+ ovs_mutex_lock(&log_file_mutex);
+ log_close = log_fd >= 0;
+ ovs_mutex_unlock(&log_file_mutex);
+ if (log_close) {
VLOG_INFO("closing log file");
}
/* Close old log file, if any, and install new one. */
- xpthread_mutex_lock(&log_file_mutex);
+ ovs_mutex_lock(&log_file_mutex);
if (log_fd >= 0) {
free(log_file_name);
close(log_fd);
log_file_name = xstrdup(new_log_file_name);
log_fd = new_log_fd;
- log_writer = async_append_create(new_log_fd);
+ if (log_async) {
+ log_writer = async_append_create(new_log_fd);
+ }
for (mp = vlog_modules; mp < &vlog_modules[n_vlog_modules]; mp++) {
update_min_level(*mp);
}
- xpthread_mutex_unlock(&log_file_mutex);
+ ovs_mutex_unlock(&log_file_mutex);
/* Log opening new log file (we can't log while holding log_file_mutex). */
VLOG_INFO("opened log file %s", new_log_file_name);
{
char *fn;
- xpthread_mutex_lock(&log_file_mutex);
+ ovs_mutex_lock(&log_file_mutex);
fn = log_file_name ? xstrdup(log_file_name) : NULL;
- xpthread_mutex_unlock(&log_file_mutex);
+ ovs_mutex_unlock(&log_file_mutex);
if (fn) {
int error = vlog_set_log_file(fn);
}
}
+/* Set the vlog udp syslog target. */
+void
+vlog_set_syslog_target(const char *target)
+{
+ int new_fd;
+
+ inet_open_active(SOCK_DGRAM, target, 0, NULL, &new_fd, 0);
+
+ ovs_rwlock_wrlock(&pattern_rwlock);
+ if (syslog_fd >= 0) {
+ close(syslog_fd);
+ }
+ syslog_fd = new_fd;
+ ovs_rwlock_unlock(&pattern_rwlock);
+}
+
static void
vlog_unixctl_set(struct unixctl_conn *conn, int argc, const char *argv[],
void *aux OVS_UNUSED)
vlog_unixctl_reopen(struct unixctl_conn *conn, int argc OVS_UNUSED,
const char *argv[] OVS_UNUSED, void *aux OVS_UNUSED)
{
- if (log_file_name) {
+ bool has_log_file;
+
+ ovs_mutex_lock(&log_file_mutex);
+ has_log_file = log_file_name != NULL;
+ ovs_mutex_unlock(&log_file_mutex);
+
+ if (has_log_file) {
int error = vlog_reopen_log_file();
if (error) {
unixctl_command_reply_error(conn, ovs_strerror(errno));
vlog_init__(void)
{
static char *program_name_copy;
- time_t now;
+ long long int now;
/* openlog() is allowed to keep the pointer passed in, without making a
* copy. The daemonize code sometimes frees and replaces 'program_name',
program_name_copy = program_name ? xstrdup(program_name) : NULL;
openlog(program_name_copy, LOG_NDELAY, LOG_DAEMON);
- now = time_wall();
+ now = time_wall_msec();
if (now < 0) {
- char *s = xastrftime("%a, %d %b %Y %H:%M:%S", now, true);
- VLOG_ERR("current time is negative: %s (%ld)", s, (long int) now);
+ char *s = xastrftime_msec("%a, %d %b %Y %H:%M:%S", now, true);
+ VLOG_ERR("current time is negative: %s (%lld)", s, now);
free(s);
}
pthread_once(&once, vlog_init__);
}
+/* Enables VLF_FILE log output to be written asynchronously to disk.
+ * Asynchronous file writes avoid blocking the process in the case of a busy
+ * disk, but on the other hand they are less robust: there is a chance that the
+ * write will not make it to the log file if the process crashes soon after the
+ * log call. */
+void
+vlog_enable_async(void)
+{
+ ovs_mutex_lock(&log_file_mutex);
+ log_async = true;
+ if (log_fd >= 0 && !log_writer) {
+ log_writer = async_append_create(log_fd);
+ }
+ ovs_mutex_unlock(&log_file_mutex);
+}
+
/* Print the current logging level for each module. */
char *
vlog_get_levels(void)
static void
format_log_message(const struct vlog_module *module, enum vlog_level level,
- enum vlog_facility facility,
- const char *message, va_list args_, struct ds *s)
+ const char *pattern, 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'; ) {
+ for (p = pattern; *p != '\0'; ) {
const char *subprogram_name;
enum { LEFT, RIGHT } justify = RIGHT;
int pad = '0';
case 'A':
ds_put_cstr(s, program_name);
break;
+ case 'B':
+ ds_put_format(s, "%d", LOG_LOCAL0 + syslog_levels[level]);
+ 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, time_wall(), false);
+ p = fetch_braces(p, "%Y-%m-%d %H:%M:%S.###", tmp, sizeof tmp);
+ ds_put_strftime_msec(s, tmp, time_wall_msec(), false);
break;
case 'D':
- p = fetch_braces(p, "%Y-%m-%d %H:%M:%S", tmp, sizeof tmp);
- ds_put_strftime(s, tmp, time_wall(), true);
+ p = fetch_braces(p, "%Y-%m-%d %H:%M:%S.###", tmp, sizeof tmp);
+ ds_put_strftime_msec(s, tmp, time_wall_msec(), true);
+ break;
+ case 'E':
+ gethostname(tmp, sizeof tmp);
+ tmp[sizeof tmp - 1] = '\0';
+ ds_put_cstr(s, tmp);
break;
case 'm':
/* Format user-supplied log message and trim trailing new-lines. */
}
}
+/* Exports the given 'syslog_message' to the configured udp syslog sink. */
+static void
+send_to_syslog_fd(const char *s, size_t length)
+ OVS_REQ_RDLOCK(pattern_rwlock)
+{
+ static size_t max_length = SIZE_MAX;
+ size_t send_len = MIN(length, max_length);
+
+ while (write(syslog_fd, s, send_len) < 0 && errno == EMSGSIZE) {
+ send_len -= send_len / 20;
+ max_length = send_len;
+ }
+}
+
/* Writes 'message' to the log at the given 'level' and as coming from the
* given 'module'.
*
{
bool log_to_console = module->levels[VLF_CONSOLE] >= level;
bool log_to_syslog = module->levels[VLF_SYSLOG] >= level;
- bool log_to_file = module->levels[VLF_FILE] >= level && log_fd >= 0;
+ bool log_to_file;
+
+ ovs_mutex_lock(&log_file_mutex);
+ log_to_file = module->levels[VLF_FILE] >= level && log_fd >= 0;
+ ovs_mutex_unlock(&log_file_mutex);
if (log_to_console || log_to_syslog || log_to_file) {
int save_errno = errno;
struct ds s;
ds_reserve(&s, 1024);
++*msg_num_get();
- xpthread_rwlock_rdlock(&pattern_rwlock);
+ ovs_rwlock_rdlock(&pattern_rwlock);
if (log_to_console) {
- format_log_message(module, level, VLF_CONSOLE, message, args, &s);
+ format_log_message(module, level, facilities[VLF_CONSOLE].pattern,
+ message, args, &s);
ds_put_char(&s, '\n');
fputs(ds_cstr(&s), stderr);
}
char *save_ptr = NULL;
char *line;
- format_log_message(module, level, VLF_SYSLOG, message, args, &s);
+ format_log_message(module, level, facilities[VLF_SYSLOG].pattern,
+ 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);
}
+
+ if (syslog_fd >= 0) {
+ format_log_message(module, level,
+ "<%B>1 %D{%Y-%m-%dT%H:%M:%S.###Z} "
+ "%E %A %P %c - \xef\xbb\xbf%m",
+ message, args, &s);
+ send_to_syslog_fd(ds_cstr(&s), s.length);
+ }
}
if (log_to_file) {
- format_log_message(module, level, VLF_FILE, message, args, &s);
+ format_log_message(module, level, facilities[VLF_FILE].pattern,
+ message, args, &s);
ds_put_char(&s, '\n');
- xpthread_mutex_lock(&log_file_mutex);
+ ovs_mutex_lock(&log_file_mutex);
if (log_fd >= 0) {
- async_append_write(log_writer, s.string, s.length);
- if (level == VLL_EMER) {
- async_append_flush(log_writer);
+ if (log_writer) {
+ async_append_write(log_writer, s.string, s.length);
+ if (level == VLL_EMER) {
+ async_append_flush(log_writer);
+ }
+ } else {
+ ignore(write(log_fd, s.string, s.length));
}
}
- xpthread_mutex_unlock(&log_file_mutex);
+ ovs_mutex_unlock(&log_file_mutex);
}
- xpthread_rwlock_unlock(&pattern_rwlock);
+ ovs_rwlock_unlock(&pattern_rwlock);
ds_destroy(&s);
errno = save_errno;
return true;
}
- xpthread_mutex_lock(&rl->mutex);
+ ovs_mutex_lock(&rl->mutex);
if (!token_bucket_withdraw(&rl->token_bucket, VLOG_MSG_TOKENS)) {
time_t now = time_now();
if (!rl->n_dropped) {
}
rl->last_dropped = now;
rl->n_dropped++;
- xpthread_mutex_unlock(&rl->mutex);
+ ovs_mutex_unlock(&rl->mutex);
return true;
}
if (!rl->n_dropped) {
- xpthread_mutex_unlock(&rl->mutex);
+ ovs_mutex_unlock(&rl->mutex);
} else {
time_t now = time_now();
unsigned int n_dropped = rl->n_dropped;
unsigned int first_dropped_elapsed = now - rl->first_dropped;
unsigned int last_dropped_elapsed = now - rl->last_dropped;
rl->n_dropped = 0;
- xpthread_mutex_unlock(&rl->mutex);
+ ovs_mutex_unlock(&rl->mutex);
vlog(module, level,
"Dropped %u log messages in last %u seconds (most recently, "
void
vlog_usage(void)
{
- printf("\nLogging options:\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",
+ printf("\n\
+Logging options:\n\
+ -vSPEC, --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\
+ --syslog-target=HOST:PORT also send syslog msgs to HOST:PORT via UDP\n",
ovs_logdir(), program_name);
}
git://git.onelab.eu / sliver-openvswitch.git / blobdiff