Syslog puts the timestamp to every message anyway so this removes redundant data. --- src/util/logging.c | 121 +++++++++++++++++++++++++++++++-------------------- src/util/logging.h | 9 ++-- 2 files changed, 78 insertions(+), 52 deletions(-) diff --git a/src/util/logging.c b/src/util/logging.c index a638510..4ffaf75 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -98,7 +98,8 @@ static int virLogResetFilters(void); static int virLogResetOutputs(void); static int virLogOutputToFd(const char *category, int priority, const char *funcname, long long linenr, - const char *str, int len, void *data); + const char *timestamp, const char *str, + void *data); /* * Logs accesses must be serialized though a mutex @@ -282,16 +283,16 @@ void virLogShutdown(void) { /* * Store a string in the ring buffer */ -static void virLogStr(const char *str, int len) { +static void virLogStr(const char *str) +{ int tmp; + int len; if ((str == NULL) || (virLogBuffer == NULL) || (virLogSize <= 0)) return; - if (len <= 0) - len = strlen(str); + len = strlen(str); if (len >= virLogSize) return; - virLogLock(); /* * copy the data and reset the end, we cycle over the end of the buffer @@ -317,7 +318,6 @@ static void virLogStr(const char *str, int len) { if (virLogStart >= virLogSize) virLogStart -= virLogSize; } - virLogUnlock(); } static void virLogDumpAllFD(const char *msg, int len) { @@ -618,12 +618,28 @@ cleanup: return ret; } +static char * +virLogFormatTimestamp(void) +{ + struct timeval cur_time; + struct tm time_info; + char *str = NULL; + + gettimeofday(&cur_time, NULL); + localtime_r(&cur_time.tv_sec, &time_info); + + if (virAsprintf(&str, "%02d:%02d:%02d.%03d", + time_info.tm_hour, time_info.tm_min, time_info.tm_sec, + (int) (cur_time.tv_usec / 1000)) < 0) + return NULL; + + return str; +} + static int virLogFormatString(char **msg, const char *funcname, long long linenr, - struct tm *time_info, - struct timeval *cur_time, int priority, const char *str) { @@ -637,25 +653,19 @@ virLogFormatString(char **msg, * to just grep for it to find the right place. */ if ((funcname != NULL)) { - ret = virAsprintf(msg, "%02d:%02d:%02d.%03d: %d: %s : %s:%lld : %s\n", - time_info->tm_hour, time_info->tm_min, - time_info->tm_sec, (int) cur_time->tv_usec / 1000, - virThreadSelfID(), - virLogPriorityString(priority), funcname, linenr, str); + ret = virAsprintf(msg, "%d: %s : %s:%lld : %s\n", + virThreadSelfID(), virLogPriorityString(priority), + funcname, linenr, str); } else { - ret = virAsprintf(msg, "%02d:%02d:%02d.%03d: %d: %s : %s\n", - time_info->tm_hour, time_info->tm_min, - time_info->tm_sec, (int) cur_time->tv_usec / 1000, - virThreadSelfID(), - virLogPriorityString(priority), str); + ret = virAsprintf(msg, "%d: %s : %s\n", + virThreadSelfID(), virLogPriorityString(priority), + str); } return ret; } static int -virLogVersionString(char **msg, - struct tm *time_info, - struct timeval *cur_time) +virLogVersionString(char **msg) { #ifdef PACKAGER_VERSION # ifdef PACKAGER @@ -670,9 +680,7 @@ virLogVersionString(char **msg, "libvirt version: " VERSION #endif - return virLogFormatString(msg, NULL, 0, - time_info, cur_time, - VIR_LOG_INFO, LOG_VERSION_STRING); + return virLogFormatString(msg, NULL, 0, VIR_LOG_INFO, LOG_VERSION_STRING); } /** @@ -694,9 +702,8 @@ void virLogMessage(const char *category, int priority, const char *funcname, static bool logVersionStderr = true; char *str = NULL; char *msg = NULL; - struct timeval cur_time; - struct tm time_info; - int len, fprio, i, ret; + char *timestamp = NULL; + int fprio, i, ret; int saved_errno = errno; int emit = 1; va_list ap; @@ -730,16 +737,15 @@ void virLogMessage(const char *category, int priority, const char *funcname, goto cleanup; } va_end(ap); - gettimeofday(&cur_time, NULL); - localtime_r(&cur_time.tv_sec, &time_info); - ret = virLogFormatString(&msg, funcname, linenr, - &time_info, &cur_time, - priority, str); + ret = virLogFormatString(&msg, funcname, linenr, priority, str); VIR_FREE(str); if (ret < 0) goto cleanup; + if (!(timestamp = virLogFormatTimestamp())) + goto cleanup; + /* * Log based on defaults, first store in the history buffer, * then if emit push the message on the outputs defined, if none @@ -748,42 +754,49 @@ void virLogMessage(const char *category, int priority, const char *funcname, * threads, but avoid intermixing. Maybe set up locks per output * to improve paralellism. */ - len = strlen(msg); - virLogStr(msg, len); + virLogLock(); + virLogStr(timestamp); + virLogStr(msg); + virLogUnlock(); if (emit == 0) goto cleanup; virLogLock(); - for (i = 0; i < virLogNbOutputs;i++) { + for (i = 0; i < virLogNbOutputs; i++) { if (priority >= virLogOutputs[i].priority) { if (virLogOutputs[i].logVersion) { char *ver = NULL; - if (virLogVersionString(&ver, &time_info, &cur_time) >= 0) - virLogOutputs[i].f(category, VIR_LOG_INFO, __func__, __LINE__, - ver, strlen(ver), + if (virLogVersionString(&ver) >= 0) + virLogOutputs[i].f(category, VIR_LOG_INFO, + __func__, __LINE__, + timestamp, ver, virLogOutputs[i].data); VIR_FREE(ver); virLogOutputs[i].logVersion = false; } virLogOutputs[i].f(category, priority, funcname, linenr, - msg, len, virLogOutputs[i].data); + timestamp, msg, virLogOutputs[i].data); } } if ((virLogNbOutputs == 0) && (flags != 1)) { if (logVersionStderr) { char *ver = NULL; - if (virLogVersionString(&ver, &time_info, &cur_time) >= 0) - ignore_value (safewrite(STDERR_FILENO, - ver, strlen(ver))); + if (virLogVersionString(&ver) >= 0) + virLogOutputToFd(category, VIR_LOG_INFO, + __func__, __LINE__, + timestamp, ver, + (void *) STDERR_FILENO); VIR_FREE(ver); logVersionStderr = false; } - ignore_value (safewrite(STDERR_FILENO, msg, len)); + virLogOutputToFd(category, priority, funcname, linenr, + timestamp, msg, (void *) STDERR_FILENO); } virLogUnlock(); cleanup: VIR_FREE(msg); + VIR_FREE(timestamp); errno = saved_errno; } @@ -791,13 +804,23 @@ static int virLogOutputToFd(const char *category ATTRIBUTE_UNUSED, int priority ATTRIBUTE_UNUSED, const char *funcname ATTRIBUTE_UNUSED, long long linenr ATTRIBUTE_UNUSED, - const char *str, int len, void *data) { + const char *timestamp, + const char *str, + void *data) +{ int fd = (long) data; int ret; + char *msg; if (fd < 0) return -1; - ret = safewrite(fd, str, len); + + if (virAsprintf(&msg, "%s: %s", timestamp, str) < 0) + return -1; + + ret = safewrite(fd, msg, strlen(msg)); + VIR_FREE(msg); + return ret; } @@ -833,8 +856,10 @@ static int virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED, int priority, const char *funcname ATTRIBUTE_UNUSED, long long linenr ATTRIBUTE_UNUSED, - const char *str, int len ATTRIBUTE_UNUSED, - void *data ATTRIBUTE_UNUSED) { + const char *timestamp ATTRIBUTE_UNUSED, + const char *str, + void *data ATTRIBUTE_UNUSED) +{ int prio; switch (priority) { @@ -854,7 +879,7 @@ static int virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED, prio = LOG_ERR; } syslog(prio, "%s", str); - return len; + return strlen(str); } static char *current_ident = NULL; diff --git a/src/util/logging.h b/src/util/logging.h index 20c8948..2343de0 100644 --- a/src/util/logging.h +++ b/src/util/logging.h @@ -78,8 +78,8 @@ typedef enum { * @priority: the priority for the message * @funcname: the function emitting the message * @linenr: line where the message was emitted - * @msg: the message to log, preformatted and zero terminated - * @len: the lenght of the message in bytes without the terminating zero + * @timestamp: zero terminated string with timestamp of the message + * @str: the message to log, preformatted and zero terminated * @data: extra output logging data * * Callback function used to output messages @@ -87,8 +87,9 @@ typedef enum { * Returns the number of bytes written or -1 in case of error */ typedef int (*virLogOutputFunc) (const char *category, int priority, - const char *funcname, long long lineno, - const char *str, int len, void *data); + const char *funcname, long long linenr, + const char *timestamp, const char *str, + void *data); /** * virLogCloseFunc: -- 1.7.6.1

On Thu, Sep 29, 2011 at 09:05:59AM +0800, Daniel Veillard wrote: I think you might be mixing up virLogStr() with a different method. virLogStr() merely memcpy()'s the data into the ring buffer. Regards, Daniel -- |: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :| |: http://libvirt.org -o- http://virt-manager.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: http://entangle-photo.org -o- http://live.gnome.org/gtk-vnc :|

--- src/util/logging.c | 4 +++- 1 files changed, 3 insertions(+), 1 deletions(-) diff --git a/src/util/logging.c b/src/util/logging.c index 4ffaf75..9df9003 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -627,8 +627,10 @@ virLogFormatTimestamp(void) gettimeofday(&cur_time, NULL); localtime_r(&cur_time.tv_sec, &time_info); + time_info.tm_year += 1900; - if (virAsprintf(&str, "%02d:%02d:%02d.%03d", + if (virAsprintf(&str, "%4d-%02d-%02d %02d:%02d:%02d.%03d", + time_info.tm_year, time_info.tm_mon, time_info.tm_mday, time_info.tm_hour, time_info.tm_min, time_info.tm_sec, (int) (cur_time.tv_usec / 1000)) < 0) return NULL; -- 1.7.6.1