[libvirt] [PATCH 0/5] Structured error logging and syslog support
This is sort of a v2 of the "Structured syslog" series. Patches 1-4 allow callers virLogMessage to add arbitrary additional data, and use it in virRaiseErrorFull and its callers. This data is sent to journal (and ignored for other outputs). Because the additional fields for errors include virErrorDomain and virErrorNumber, this allows _programs_ to _automatically_ detect the event and react to it, perhaps alerting the user. Patch 5 adds the "syslog/json" log output type, in a way that is comparably async-signal-safe to the other log outputs (i.e. it's not safe by the letter of the standard, but safe in practice). I still think that having this format output is desirable, but I'll accept it if you decide that it is not wanted in libvirt. Miloslav Trmač (5): Add a metadata parameter to virLog{,V}Message Add metadata to virLogOutputFunc Use helper functions to format the journal iov array Add detailed error information to journal Add "syslog/json" log output format. docs/logging.html.in | 3 + src/util/logging.c | 445 +++++++++++++++++++++++++++++++++++++++++++-------- src/util/logging.h | 27 +++- src/util/viraudit.c | 4 +- src/util/virterror.c | 33 +++- tests/testutils.c | 1 + 6 files changed, 437 insertions(+), 76 deletions(-) -- 1.7.11.7
... and update all users. No change in functionality, the parameter will be used later. The metadata representation is as minimal as possible, but requires the caller to allocate an array on stack explicitly. The alternative of using varargs in the virLogMessage() callers: * Would not allow the caller to optionally omit some metadata elements, except by having two calls to virLogMessage. * Would not be as type-safe (e.g. using int vs. size_t), and the compiler wouldn't be able to do type checking * Depending on parameter order: a) virLogMessage(..., message format, message params..., metadata..., NULL) can not be portably implemented (parse_printf_format() is a glibc function) b) virLogMessage(..., metadata..., NULL, message format, message params...) would prevent usage of ATTRIBUTE_FMT_PRINTF and the associated compiler checking. Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 6 +++++- src/util/logging.h | 24 ++++++++++++++++++------ src/util/viraudit.c | 4 ++-- src/util/virterror.c | 2 +- 4 files changed, 26 insertions(+), 10 deletions(-) diff --git a/src/util/logging.c b/src/util/logging.c index 9a8bba1..71fb6bd 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -729,6 +729,7 @@ virLogVersionString(const char **rawmsg, * @filename: file where the message was emitted * @linenr: line where the message was emitted * @funcname: the function emitting the (debug) message + * @metadata: NULL or metadata array, terminated by an item with NULL key * @fmt: the string format * @...: the arguments * @@ -741,13 +742,14 @@ virLogMessage(virLogSource source, const char *filename, int linenr, const char *funcname, + virLogMetadataPtr metadata, const char *fmt, ...) { va_list ap; va_start(ap, fmt); virLogVMessage(source, priority, filename, linenr, funcname, - fmt, ap); + metadata, fmt, ap); va_end(ap); } @@ -759,6 +761,7 @@ virLogMessage(virLogSource source, * @filename: file where the message was emitted * @linenr: line where the message was emitted * @funcname: the function emitting the (debug) message + * @metadata: NULL or metadata array, terminated by an item with NULL key * @fmt: the string format * @vargs: format args * @@ -771,6 +774,7 @@ virLogVMessage(virLogSource source, const char *filename, int linenr, const char *funcname, + virLogMetadataPtr metadata ATTRIBUTE_UNUSED, const char *fmt, va_list vargs) { diff --git a/src/util/logging.h b/src/util/logging.h index c67377f..024814f 100644 --- a/src/util/logging.h +++ b/src/util/logging.h @@ -61,7 +61,7 @@ typedef enum { */ # ifdef ENABLE_DEBUG # define VIR_DEBUG_INT(src, filename, linenr, funcname, ...) \ - virLogMessage(src, VIR_LOG_DEBUG, filename, linenr, funcname, __VA_ARGS__) + virLogMessage(src, VIR_LOG_DEBUG, filename, linenr, funcname, NULL, __VA_ARGS__) # else /** * virLogEatParams: @@ -78,11 +78,11 @@ static inline void virLogEatParams(virLogSource unused, ...) # endif /* !ENABLE_DEBUG */ # define VIR_INFO_INT(src, filename, linenr, funcname, ...) \ - virLogMessage(src, VIR_LOG_INFO, filename, linenr, funcname, __VA_ARGS__) + virLogMessage(src, VIR_LOG_INFO, filename, linenr, funcname, NULL, __VA_ARGS__) # define VIR_WARN_INT(src, filename, linenr, funcname, ...) \ - virLogMessage(src, VIR_LOG_WARN, filename, linenr, funcname, __VA_ARGS__) + virLogMessage(src, VIR_LOG_WARN, filename, linenr, funcname, NULL, __VA_ARGS__) # define VIR_ERROR_INT(src, filename, linenr, funcname, ...) \ - virLogMessage(src, VIR_LOG_ERROR, filename, linenr, funcname, __VA_ARGS__) + virLogMessage(src, VIR_LOG_ERROR, filename, linenr, funcname, NULL, __VA_ARGS__) # define VIR_DEBUG(...) \ VIR_DEBUG_INT(VIR_LOG_FROM_FILE, __FILE__, __LINE__, __func__, __VA_ARGS__) @@ -93,6 +93,16 @@ static inline void virLogEatParams(virLogSource unused, ...) # define VIR_ERROR(...) \ VIR_ERROR_INT(VIR_LOG_FROM_FILE, __FILE__, __LINE__, __func__, __VA_ARGS__) + +struct _virLogMetadata { + const char *key; + const char *s; /* String value, or NULL to use "i" */ + int i; +}; + +typedef struct _virLogMetadata virLogMetadata; +typedef struct _virLogMetadata *virLogMetadataPtr; + /** * virLogOutputFunc: * @src: the src for the message @@ -164,14 +174,16 @@ extern void virLogMessage(virLogSource src, const char *filename, int linenr, const char *funcname, - const char *fmt, ...) ATTRIBUTE_FMT_PRINTF(6, 7); + virLogMetadataPtr metadata, + const char *fmt, ...) ATTRIBUTE_FMT_PRINTF(7, 8); extern void virLogVMessage(virLogSource src, virLogPriority priority, const char *filename, int linenr, const char *funcname, + virLogMetadataPtr metadata, const char *fmt, - va_list vargs) ATTRIBUTE_FMT_PRINTF(6, 0); + va_list vargs) ATTRIBUTE_FMT_PRINTF(7, 0); extern int virLogSetBufferSize(int size); extern void virLogEmergencyDumpAll(int signum); #endif diff --git a/src/util/viraudit.c b/src/util/viraudit.c index 61f09eb..9bdc5ed 100644 --- a/src/util/viraudit.c +++ b/src/util/viraudit.c @@ -106,11 +106,11 @@ void virAuditSend(const char *filename, if (success) virLogMessage(VIR_LOG_FROM_AUDIT, VIR_LOG_INFO, filename, linenr, funcname, - "success=yes %s", str); + NULL, "success=yes %s", str); else virLogMessage(VIR_LOG_FROM_AUDIT, VIR_LOG_WARN, filename, linenr, funcname, - "success=no %s", str); + NULL, "success=no %s", str); } #if HAVE_AUDIT diff --git a/src/util/virterror.c b/src/util/virterror.c index 9572116..df8b6fd 100644 --- a/src/util/virterror.c +++ b/src/util/virterror.c @@ -679,7 +679,7 @@ virRaiseErrorFull(const char *filename ATTRIBUTE_UNUSED, virLogMessage(virErrorLogPriorityFilter ? VIR_LOG_FROM_FILE : VIR_LOG_FROM_ERROR, priority, filename, linenr, funcname, - "%s", str); + NULL, "%s", str); errno = save_errno; } -- 1.7.11.7
On Wed, Oct 17, 2012 at 08:17:14PM +0200, Miloslav Trmač wrote:
... and update all users. No change in functionality, the parameter will be used later.
The metadata representation is as minimal as possible, but requires the caller to allocate an array on stack explicitly.
The alternative of using varargs in the virLogMessage() callers: * Would not allow the caller to optionally omit some metadata elements, except by having two calls to virLogMessage. * Would not be as type-safe (e.g. using int vs. size_t), and the compiler wouldn't be able to do type checking * Depending on parameter order: a) virLogMessage(..., message format, message params..., metadata..., NULL) can not be portably implemented (parse_printf_format() is a glibc function) b) virLogMessage(..., metadata..., NULL, message format, message params...) would prevent usage of ATTRIBUTE_FMT_PRINTF and the associated compiler checking.
Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 6 +++++- src/util/logging.h | 24 ++++++++++++++++++------ src/util/viraudit.c | 4 ++-- src/util/virterror.c | 2 +- 4 files changed, 26 insertions(+), 10 deletions(-)
diff --git a/src/util/logging.c b/src/util/logging.c index 9a8bba1..71fb6bd 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -729,6 +729,7 @@ virLogVersionString(const char **rawmsg, * @filename: file where the message was emitted * @linenr: line where the message was emitted * @funcname: the function emitting the (debug) message + * @metadata: NULL or metadata array, terminated by an item with NULL key * @fmt: the string format * @...: the arguments * @@ -741,13 +742,14 @@ virLogMessage(virLogSource source, const char *filename, int linenr, const char *funcname, + virLogMetadataPtr metadata, const char *fmt, ...) { va_list ap; va_start(ap, fmt); virLogVMessage(source, priority, filename, linenr, funcname, - fmt, ap); + metadata, fmt, ap); va_end(ap); }
@@ -759,6 +761,7 @@ virLogMessage(virLogSource source, * @filename: file where the message was emitted * @linenr: line where the message was emitted * @funcname: the function emitting the (debug) message + * @metadata: NULL or metadata array, terminated by an item with NULL key * @fmt: the string format * @vargs: format args * @@ -771,6 +774,7 @@ virLogVMessage(virLogSource source, const char *filename, int linenr, const char *funcname, + virLogMetadataPtr metadata ATTRIBUTE_UNUSED, const char *fmt, va_list vargs) { diff --git a/src/util/logging.h b/src/util/logging.h index c67377f..024814f 100644 --- a/src/util/logging.h +++ b/src/util/logging.h @@ -61,7 +61,7 @@ typedef enum { */ # ifdef ENABLE_DEBUG # define VIR_DEBUG_INT(src, filename, linenr, funcname, ...) \ - virLogMessage(src, VIR_LOG_DEBUG, filename, linenr, funcname, __VA_ARGS__) + virLogMessage(src, VIR_LOG_DEBUG, filename, linenr, funcname, NULL, __VA_ARGS__) # else /** * virLogEatParams: @@ -78,11 +78,11 @@ static inline void virLogEatParams(virLogSource unused, ...) # endif /* !ENABLE_DEBUG */
# define VIR_INFO_INT(src, filename, linenr, funcname, ...) \ - virLogMessage(src, VIR_LOG_INFO, filename, linenr, funcname, __VA_ARGS__) + virLogMessage(src, VIR_LOG_INFO, filename, linenr, funcname, NULL, __VA_ARGS__) # define VIR_WARN_INT(src, filename, linenr, funcname, ...) \ - virLogMessage(src, VIR_LOG_WARN, filename, linenr, funcname, __VA_ARGS__) + virLogMessage(src, VIR_LOG_WARN, filename, linenr, funcname, NULL, __VA_ARGS__) # define VIR_ERROR_INT(src, filename, linenr, funcname, ...) \ - virLogMessage(src, VIR_LOG_ERROR, filename, linenr, funcname, __VA_ARGS__) + virLogMessage(src, VIR_LOG_ERROR, filename, linenr, funcname, NULL, __VA_ARGS__)
# define VIR_DEBUG(...) \ VIR_DEBUG_INT(VIR_LOG_FROM_FILE, __FILE__, __LINE__, __func__, __VA_ARGS__) @@ -93,6 +93,16 @@ static inline void virLogEatParams(virLogSource unused, ...) # define VIR_ERROR(...) \ VIR_ERROR_INT(VIR_LOG_FROM_FILE, __FILE__, __LINE__, __func__, __VA_ARGS__)
+ +struct _virLogMetadata { + const char *key; + const char *s; /* String value, or NULL to use "i" */ + int i; +}; + +typedef struct _virLogMetadata virLogMetadata; +typedef struct _virLogMetadata *virLogMetadataPtr; + /** * virLogOutputFunc: * @src: the src for the message @@ -164,14 +174,16 @@ extern void virLogMessage(virLogSource src, const char *filename, int linenr, const char *funcname, - const char *fmt, ...) ATTRIBUTE_FMT_PRINTF(6, 7); + virLogMetadataPtr metadata, + const char *fmt, ...) ATTRIBUTE_FMT_PRINTF(7, 8); extern void virLogVMessage(virLogSource src, virLogPriority priority, const char *filename, int linenr, const char *funcname, + virLogMetadataPtr metadata, const char *fmt, - va_list vargs) ATTRIBUTE_FMT_PRINTF(6, 0); + va_list vargs) ATTRIBUTE_FMT_PRINTF(7, 0); extern int virLogSetBufferSize(int size); extern void virLogEmergencyDumpAll(int signum); #endif diff --git a/src/util/viraudit.c b/src/util/viraudit.c index 61f09eb..9bdc5ed 100644 --- a/src/util/viraudit.c +++ b/src/util/viraudit.c @@ -106,11 +106,11 @@ void virAuditSend(const char *filename, if (success) virLogMessage(VIR_LOG_FROM_AUDIT, VIR_LOG_INFO, filename, linenr, funcname, - "success=yes %s", str); + NULL, "success=yes %s", str); else virLogMessage(VIR_LOG_FROM_AUDIT, VIR_LOG_WARN, filename, linenr, funcname, - "success=no %s", str); + NULL, "success=no %s", str); }
#if HAVE_AUDIT diff --git a/src/util/virterror.c b/src/util/virterror.c index 9572116..df8b6fd 100644 --- a/src/util/virterror.c +++ b/src/util/virterror.c @@ -679,7 +679,7 @@ virRaiseErrorFull(const char *filename ATTRIBUTE_UNUSED, virLogMessage(virErrorLogPriorityFilter ? VIR_LOG_FROM_FILE : VIR_LOG_FROM_ERROR, priority, filename, linenr, funcname, - "%s", str); + NULL, "%s", str);
errno = save_errno; }
ACK 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 :|
... and update all users. No change in functionality, the parameter will be used in the next patch. Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 14 +++++++++----- src/util/logging.h | 2 ++ tests/testutils.c | 1 + 3 files changed, 12 insertions(+), 5 deletions(-) diff --git a/src/util/logging.c b/src/util/logging.c index 71fb6bd..a41ae8b 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -123,6 +123,7 @@ static void virLogOutputToFd(virLogSource src, int linenr, const char *funcname, const char *timestamp, + virLogMetadataPtr metadata, unsigned int flags, const char *rawstr, const char *str, @@ -774,7 +775,7 @@ virLogVMessage(virLogSource source, const char *filename, int linenr, const char *funcname, - virLogMetadataPtr metadata ATTRIBUTE_UNUSED, + virLogMetadataPtr metadata, const char *fmt, va_list vargs) { @@ -845,14 +846,14 @@ virLogVMessage(virLogSource source, if (virLogVersionString(&rawver, &ver) >= 0) virLogOutputs[i].f(VIR_LOG_FROM_FILE, VIR_LOG_INFO, __FILE__, __LINE__, __func__, - timestamp, 0, rawver, ver, + timestamp, NULL, 0, rawver, ver, virLogOutputs[i].data); VIR_FREE(ver); virLogOutputs[i].logVersion = false; } virLogOutputs[i].f(source, priority, filename, linenr, funcname, - timestamp, filterflags, + timestamp, metadata, filterflags, str, msg, virLogOutputs[i].data); } } @@ -863,14 +864,14 @@ virLogVMessage(virLogSource source, if (virLogVersionString(&rawver, &ver) >= 0) virLogOutputToFd(VIR_LOG_FROM_FILE, VIR_LOG_INFO, __FILE__, __LINE__, __func__, - timestamp, 0, rawver, ver, + timestamp, NULL, 0, rawver, ver, (void *) STDERR_FILENO); VIR_FREE(ver); logVersionStderr = false; } virLogOutputToFd(source, priority, filename, linenr, funcname, - timestamp, filterflags, + timestamp, metadata, filterflags, str, msg, (void *) STDERR_FILENO); } virLogUnlock(); @@ -909,6 +910,7 @@ virLogOutputToFd(virLogSource source ATTRIBUTE_UNUSED, int linenr ATTRIBUTE_UNUSED, const char *funcname ATTRIBUTE_UNUSED, const char *timestamp, + virLogMetadataPtr metadata ATTRIBUTE_UNUSED, unsigned int flags, const char *rawstr ATTRIBUTE_UNUSED, const char *str, @@ -995,6 +997,7 @@ virLogOutputToSyslog(virLogSource source ATTRIBUTE_UNUSED, int linenr ATTRIBUTE_UNUSED, const char *funcname ATTRIBUTE_UNUSED, const char *timestamp ATTRIBUTE_UNUSED, + virLogMetadataPtr metadata ATTRIBUTE_UNUSED, unsigned int flags, const char *rawstr ATTRIBUTE_UNUSED, const char *str, @@ -1063,6 +1066,7 @@ virLogOutputToJournald(virLogSource source, int linenr, const char *funcname, const char *timestamp ATTRIBUTE_UNUSED, + virLogMetadataPtr metadata ATTRIBUTE_UNUSED, unsigned int flags, const char *rawstr, const char *str ATTRIBUTE_UNUSED, diff --git a/src/util/logging.h b/src/util/logging.h index 024814f..52feecc 100644 --- a/src/util/logging.h +++ b/src/util/logging.h @@ -111,6 +111,7 @@ typedef struct _virLogMetadata *virLogMetadataPtr; * @linenr: line where the message was emitted * @funcname: the function emitting the message * @timestamp: zero terminated string with timestamp of the message + * @metadata: NULL or metadata array, terminated by an item with NULL key * @flags: flags associated with the message * @rawstr: the unformatted message to log, zero terminated * @str: the message to log, preformatted and zero terminated @@ -124,6 +125,7 @@ typedef void (*virLogOutputFunc) (virLogSource src, int linenr, const char *funcname, const char *timestamp, + virLogMetadataPtr metadata, unsigned int flags, const char *rawstr, const char *str, diff --git a/tests/testutils.c b/tests/testutils.c index 2a9102b..75c7284 100644 --- a/tests/testutils.c +++ b/tests/testutils.c @@ -486,6 +486,7 @@ virtTestLogOutput(virLogSource source ATTRIBUTE_UNUSED, int lineno ATTRIBUTE_UNUSED, const char *funcname ATTRIBUTE_UNUSED, const char *timestamp, + virLogMetadataPtr metadata ATTRIBUTE_UNUSED, unsigned int flags, const char *rawstr ATTRIBUTE_UNUSED, const char *str, -- 1.7.11.7
On Wed, Oct 17, 2012 at 08:17:15PM +0200, Miloslav Trmač wrote:
... and update all users. No change in functionality, the parameter will be used in the next patch.
Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 14 +++++++++----- src/util/logging.h | 2 ++ tests/testutils.c | 1 + 3 files changed, 12 insertions(+), 5 deletions(-)
diff --git a/src/util/logging.c b/src/util/logging.c index 71fb6bd..a41ae8b 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -123,6 +123,7 @@ static void virLogOutputToFd(virLogSource src, int linenr, const char *funcname, const char *timestamp, + virLogMetadataPtr metadata, unsigned int flags, const char *rawstr, const char *str, @@ -774,7 +775,7 @@ virLogVMessage(virLogSource source, const char *filename, int linenr, const char *funcname, - virLogMetadataPtr metadata ATTRIBUTE_UNUSED, + virLogMetadataPtr metadata, const char *fmt, va_list vargs) { @@ -845,14 +846,14 @@ virLogVMessage(virLogSource source, if (virLogVersionString(&rawver, &ver) >= 0) virLogOutputs[i].f(VIR_LOG_FROM_FILE, VIR_LOG_INFO, __FILE__, __LINE__, __func__, - timestamp, 0, rawver, ver, + timestamp, NULL, 0, rawver, ver, virLogOutputs[i].data); VIR_FREE(ver); virLogOutputs[i].logVersion = false; } virLogOutputs[i].f(source, priority, filename, linenr, funcname, - timestamp, filterflags, + timestamp, metadata, filterflags, str, msg, virLogOutputs[i].data); } } @@ -863,14 +864,14 @@ virLogVMessage(virLogSource source, if (virLogVersionString(&rawver, &ver) >= 0) virLogOutputToFd(VIR_LOG_FROM_FILE, VIR_LOG_INFO, __FILE__, __LINE__, __func__, - timestamp, 0, rawver, ver, + timestamp, NULL, 0, rawver, ver, (void *) STDERR_FILENO); VIR_FREE(ver); logVersionStderr = false; } virLogOutputToFd(source, priority, filename, linenr, funcname, - timestamp, filterflags, + timestamp, metadata, filterflags, str, msg, (void *) STDERR_FILENO); } virLogUnlock(); @@ -909,6 +910,7 @@ virLogOutputToFd(virLogSource source ATTRIBUTE_UNUSED, int linenr ATTRIBUTE_UNUSED, const char *funcname ATTRIBUTE_UNUSED, const char *timestamp, + virLogMetadataPtr metadata ATTRIBUTE_UNUSED, unsigned int flags, const char *rawstr ATTRIBUTE_UNUSED, const char *str, @@ -995,6 +997,7 @@ virLogOutputToSyslog(virLogSource source ATTRIBUTE_UNUSED, int linenr ATTRIBUTE_UNUSED, const char *funcname ATTRIBUTE_UNUSED, const char *timestamp ATTRIBUTE_UNUSED, + virLogMetadataPtr metadata ATTRIBUTE_UNUSED, unsigned int flags, const char *rawstr ATTRIBUTE_UNUSED, const char *str, @@ -1063,6 +1066,7 @@ virLogOutputToJournald(virLogSource source, int linenr, const char *funcname, const char *timestamp ATTRIBUTE_UNUSED, + virLogMetadataPtr metadata ATTRIBUTE_UNUSED, unsigned int flags, const char *rawstr, const char *str ATTRIBUTE_UNUSED, diff --git a/src/util/logging.h b/src/util/logging.h index 024814f..52feecc 100644 --- a/src/util/logging.h +++ b/src/util/logging.h @@ -111,6 +111,7 @@ typedef struct _virLogMetadata *virLogMetadataPtr; * @linenr: line where the message was emitted * @funcname: the function emitting the message * @timestamp: zero terminated string with timestamp of the message + * @metadata: NULL or metadata array, terminated by an item with NULL key * @flags: flags associated with the message * @rawstr: the unformatted message to log, zero terminated * @str: the message to log, preformatted and zero terminated @@ -124,6 +125,7 @@ typedef void (*virLogOutputFunc) (virLogSource src, int linenr, const char *funcname, const char *timestamp, + virLogMetadataPtr metadata, unsigned int flags, const char *rawstr, const char *str, diff --git a/tests/testutils.c b/tests/testutils.c index 2a9102b..75c7284 100644 --- a/tests/testutils.c +++ b/tests/testutils.c @@ -486,6 +486,7 @@ virtTestLogOutput(virLogSource source ATTRIBUTE_UNUSED, int lineno ATTRIBUTE_UNUSED, const char *funcname ATTRIBUTE_UNUSED, const char *timestamp, + virLogMetadataPtr metadata ATTRIBUTE_UNUSED, unsigned int flags, const char *rawstr ATTRIBUTE_UNUSED, const char *str,
ACK 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 :|
This simplifies the top-level code, at the cost of using a little more stack space. The primary benefit is being able to send more fields without knowing in advance how many of them, and of which types, these fields will be, and without having to individually add buffer variables. The code imposes an upper limit on the total number of iovs/buffers used, and fields that wouldn't fit are silently dropped. This is not significant in this patch, but will affect the following one. Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 144 ++++++++++++++++++++++++++++++++--------------------- 1 file changed, 87 insertions(+), 57 deletions(-) diff --git a/src/util/logging.c b/src/util/logging.c index a41ae8b..a6d00c9 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -1043,19 +1043,78 @@ virLogAddOutputToSyslog(virLogPriority priority, # if USE_JOURNALD -# define IOVEC_SET_STRING(iov, str) \ - do { \ - struct iovec *_i = &(iov); \ - _i->iov_base = (char*)str; \ - _i->iov_len = strlen(str); \ +# define IOVEC_SET(iov, data, size) \ + do { \ + struct iovec *_i = &(iov); \ + _i->iov_base = (void*)(data); \ + _i->iov_len = (size); \ } while (0) -# define IOVEC_SET_INT(iov, buf, val) \ - do { \ - struct iovec *_i = &(iov); \ - _i->iov_base = virFormatIntDecimal(buf, sizeof(buf), val); \ - _i->iov_len = strlen(buf); \ - } while (0) +# define IOVEC_SET_STRING(iov, str) IOVEC_SET(iov, str, strlen(str)) + +/* Used for conversion of numbers to strings, and for length of binary data */ +#define JOURNAL_BUF_SIZE (MAX(INT_BUFSIZE_BOUND(int), sizeof(uint64_t))) + +struct journalState +{ + struct iovec *iov, *iov_end; + char (*bufs)[JOURNAL_BUF_SIZE], (*bufs_end)[JOURNAL_BUF_SIZE]; +}; + +static void +journalAddString(struct journalState *state, const char *field, + const char *value) +{ + static const char newline = '\n', equals = '='; + + if (strchr(value, '\n') != NULL) { + uint64_t nstr; + + /* If 'str' contains a newline, then we must + * encode the string length, since we can't + * rely on the newline for the field separator + */ + if (state->iov_end - state->iov < 5 || state->bufs == state->bufs_end) + return; /* Silently drop */ + nstr = htole64(strlen(value)); + memcpy(state->bufs[0], &nstr, sizeof(nstr)); + + IOVEC_SET_STRING(state->iov[0], field); + IOVEC_SET(state->iov[1], &newline, sizeof(newline)); + IOVEC_SET(state->iov[2], state->bufs[0], sizeof(nstr)); + state->bufs++; + state->iov += 3; + } else { + if (state->iov_end - state->iov < 4) + return; /* Silently drop */ + IOVEC_SET_STRING(state->iov[0], field); + IOVEC_SET(state->iov[1], (void *)&equals, sizeof(equals)); + state->iov += 2; + } + IOVEC_SET_STRING(state->iov[0], value); + IOVEC_SET(state->iov[1], (void *)&newline, sizeof(newline)); + state->iov += 2; +} + +static void +journalAddInt(struct journalState *state, const char *field, int value) +{ + static const char newline = '\n', equals = '='; + + char *num; + + if (state->iov_end - state->iov < 4 || state->bufs == state->bufs_end) + return; /* Silently drop */ + + num = virFormatIntDecimal(state->bufs[0], sizeof(state->bufs[0]), value); + + IOVEC_SET_STRING(state->iov[0], field); + IOVEC_SET(state->iov[1], (void *)&equals, sizeof(equals)); + IOVEC_SET_STRING(state->iov[2], num); + IOVEC_SET(state->iov[3], (void *)&newline, sizeof(newline)); + state->bufs++; + state->iov += 4; +} static int journalfd = -1; @@ -1074,7 +1133,6 @@ virLogOutputToJournald(virLogSource source, { virCheckFlags(VIR_LOG_STACK_TRACE,); int buffd = -1; - size_t niov = 0; struct msghdr mh; struct sockaddr_un sa; union { @@ -1086,52 +1144,24 @@ virLogOutputToJournald(virLogSource source, * be a tmpfs, and one that is available from early boot on * and where unprivileged users can create files. */ char path[] = "/dev/shm/journal.XXXXXX"; - char priostr[INT_BUFSIZE_BOUND(priority)]; - char linestr[INT_BUFSIZE_BOUND(linenr)]; - - /* First message takes up to 4 iovecs, and each - * other field needs 3, assuming they don't have - * newlines in them - */ -# define IOV_SIZE (4 + (5 * 3)) - struct iovec iov[IOV_SIZE]; - - if (strchr(rawstr, '\n')) { - uint64_t nstr; - /* If 'str' contains a newline, then we must - * encode the string length, since we can't - * rely on the newline for the field separator - */ - IOVEC_SET_STRING(iov[niov++], "MESSAGE\n"); - nstr = htole64(strlen(rawstr)); - iov[niov].iov_base = (char*)&nstr; - iov[niov].iov_len = sizeof(nstr); - niov++; - } else { - IOVEC_SET_STRING(iov[niov++], "MESSAGE="); - } - IOVEC_SET_STRING(iov[niov++], rawstr); - IOVEC_SET_STRING(iov[niov++], "\n"); - - IOVEC_SET_STRING(iov[niov++], "PRIORITY="); - IOVEC_SET_INT(iov[niov++], priostr, priority); - IOVEC_SET_STRING(iov[niov++], "\n"); - - IOVEC_SET_STRING(iov[niov++], "LIBVIRT_SOURCE="); - IOVEC_SET_STRING(iov[niov++], virLogSourceTypeToString(source)); - IOVEC_SET_STRING(iov[niov++], "\n"); - IOVEC_SET_STRING(iov[niov++], "CODE_FILE="); - IOVEC_SET_STRING(iov[niov++], filename); - IOVEC_SET_STRING(iov[niov++], "\n"); +# define NUM_FIELDS 6 + struct iovec iov[NUM_FIELDS * 5]; + char iov_bufs[NUM_FIELDS][JOURNAL_BUF_SIZE]; + struct journalState state; - IOVEC_SET_STRING(iov[niov++], "CODE_LINE="); - IOVEC_SET_INT(iov[niov++], linestr, linenr); - IOVEC_SET_STRING(iov[niov++], "\n"); + state.iov = iov; + state.iov_end = iov + ARRAY_CARDINALITY(iov); + state.bufs = iov_bufs; + state.bufs_end = iov_bufs + ARRAY_CARDINALITY(iov_bufs); - IOVEC_SET_STRING(iov[niov++], "CODE_FUNC="); - IOVEC_SET_STRING(iov[niov++], funcname); - IOVEC_SET_STRING(iov[niov++], "\n"); + journalAddString(&state ,"MESSAGE", rawstr); + journalAddInt(&state, "PRIORITY", priority); + journalAddString(&state, "LIBVIRT_SOURCE", + virLogSourceTypeToString(source)); + journalAddString(&state, "CODE_FILE", filename); + journalAddInt(&state, "CODE_LINE", linenr); + journalAddString(&state, "CODE_FUNC", funcname); memset(&sa, 0, sizeof(sa)); sa.sun_family = AF_UNIX; @@ -1142,7 +1172,7 @@ virLogOutputToJournald(virLogSource source, mh.msg_name = &sa; mh.msg_namelen = offsetof(struct sockaddr_un, sun_path) + strlen(sa.sun_path); mh.msg_iov = iov; - mh.msg_iovlen = niov; + mh.msg_iovlen = state.iov - iov; if (sendmsg(journalfd, &mh, MSG_NOSIGNAL) >= 0) return; @@ -1166,7 +1196,7 @@ virLogOutputToJournald(virLogSource source, if (unlink(path) < 0) goto cleanup; - if (writev(buffd, iov, niov) < 0) + if (writev(buffd, iov, state.iov - iov) < 0) goto cleanup; mh.msg_iov = NULL; -- 1.7.11.7
On Wed, Oct 17, 2012 at 08:17:16PM +0200, Miloslav Trmač wrote:
This simplifies the top-level code, at the cost of using a little more stack space. The primary benefit is being able to send more fields without knowing in advance how many of them, and of which types, these fields will be, and without having to individually add buffer variables.
The code imposes an upper limit on the total number of iovs/buffers used, and fields that wouldn't fit are silently dropped. This is not significant in this patch, but will affect the following one.
Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 144 ++++++++++++++++++++++++++++++++--------------------- 1 file changed, 87 insertions(+), 57 deletions(-)
diff --git a/src/util/logging.c b/src/util/logging.c index a41ae8b..a6d00c9 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -1043,19 +1043,78 @@ virLogAddOutputToSyslog(virLogPriority priority,
# if USE_JOURNALD -# define IOVEC_SET_STRING(iov, str) \ - do { \ - struct iovec *_i = &(iov); \ - _i->iov_base = (char*)str; \ - _i->iov_len = strlen(str); \ +# define IOVEC_SET(iov, data, size) \ + do { \ + struct iovec *_i = &(iov); \ + _i->iov_base = (void*)(data); \ + _i->iov_len = (size); \ } while (0)
-# define IOVEC_SET_INT(iov, buf, val) \ - do { \ - struct iovec *_i = &(iov); \ - _i->iov_base = virFormatIntDecimal(buf, sizeof(buf), val); \ - _i->iov_len = strlen(buf); \ - } while (0) +# define IOVEC_SET_STRING(iov, str) IOVEC_SET(iov, str, strlen(str)) + +/* Used for conversion of numbers to strings, and for length of binary data */ +#define JOURNAL_BUF_SIZE (MAX(INT_BUFSIZE_BOUND(int), sizeof(uint64_t))) + +struct journalState +{ + struct iovec *iov, *iov_end; + char (*bufs)[JOURNAL_BUF_SIZE], (*bufs_end)[JOURNAL_BUF_SIZE]; +}; + +static void +journalAddString(struct journalState *state, const char *field, + const char *value) +{ + static const char newline = '\n', equals = '='; + + if (strchr(value, '\n') != NULL) { + uint64_t nstr; + + /* If 'str' contains a newline, then we must + * encode the string length, since we can't + * rely on the newline for the field separator + */ + if (state->iov_end - state->iov < 5 || state->bufs == state->bufs_end) + return; /* Silently drop */ + nstr = htole64(strlen(value)); + memcpy(state->bufs[0], &nstr, sizeof(nstr)); + + IOVEC_SET_STRING(state->iov[0], field); + IOVEC_SET(state->iov[1], &newline, sizeof(newline)); + IOVEC_SET(state->iov[2], state->bufs[0], sizeof(nstr)); + state->bufs++; + state->iov += 3; + } else { + if (state->iov_end - state->iov < 4) + return; /* Silently drop */ + IOVEC_SET_STRING(state->iov[0], field); + IOVEC_SET(state->iov[1], (void *)&equals, sizeof(equals)); + state->iov += 2; + } + IOVEC_SET_STRING(state->iov[0], value); + IOVEC_SET(state->iov[1], (void *)&newline, sizeof(newline)); + state->iov += 2; +} + +static void +journalAddInt(struct journalState *state, const char *field, int value) +{ + static const char newline = '\n', equals = '='; + + char *num; + + if (state->iov_end - state->iov < 4 || state->bufs == state->bufs_end) + return; /* Silently drop */ + + num = virFormatIntDecimal(state->bufs[0], sizeof(state->bufs[0]), value); + + IOVEC_SET_STRING(state->iov[0], field); + IOVEC_SET(state->iov[1], (void *)&equals, sizeof(equals)); + IOVEC_SET_STRING(state->iov[2], num); + IOVEC_SET(state->iov[3], (void *)&newline, sizeof(newline)); + state->bufs++; + state->iov += 4; +}
static int journalfd = -1;
@@ -1074,7 +1133,6 @@ virLogOutputToJournald(virLogSource source, { virCheckFlags(VIR_LOG_STACK_TRACE,); int buffd = -1; - size_t niov = 0; struct msghdr mh; struct sockaddr_un sa; union { @@ -1086,52 +1144,24 @@ virLogOutputToJournald(virLogSource source, * be a tmpfs, and one that is available from early boot on * and where unprivileged users can create files. */ char path[] = "/dev/shm/journal.XXXXXX"; - char priostr[INT_BUFSIZE_BOUND(priority)]; - char linestr[INT_BUFSIZE_BOUND(linenr)]; - - /* First message takes up to 4 iovecs, and each - * other field needs 3, assuming they don't have - * newlines in them - */ -# define IOV_SIZE (4 + (5 * 3)) - struct iovec iov[IOV_SIZE]; - - if (strchr(rawstr, '\n')) { - uint64_t nstr; - /* If 'str' contains a newline, then we must - * encode the string length, since we can't - * rely on the newline for the field separator - */ - IOVEC_SET_STRING(iov[niov++], "MESSAGE\n"); - nstr = htole64(strlen(rawstr)); - iov[niov].iov_base = (char*)&nstr; - iov[niov].iov_len = sizeof(nstr); - niov++; - } else { - IOVEC_SET_STRING(iov[niov++], "MESSAGE="); - } - IOVEC_SET_STRING(iov[niov++], rawstr); - IOVEC_SET_STRING(iov[niov++], "\n"); - - IOVEC_SET_STRING(iov[niov++], "PRIORITY="); - IOVEC_SET_INT(iov[niov++], priostr, priority); - IOVEC_SET_STRING(iov[niov++], "\n"); - - IOVEC_SET_STRING(iov[niov++], "LIBVIRT_SOURCE="); - IOVEC_SET_STRING(iov[niov++], virLogSourceTypeToString(source)); - IOVEC_SET_STRING(iov[niov++], "\n");
- IOVEC_SET_STRING(iov[niov++], "CODE_FILE="); - IOVEC_SET_STRING(iov[niov++], filename); - IOVEC_SET_STRING(iov[niov++], "\n"); +# define NUM_FIELDS 6 + struct iovec iov[NUM_FIELDS * 5]; + char iov_bufs[NUM_FIELDS][JOURNAL_BUF_SIZE]; + struct journalState state;
- IOVEC_SET_STRING(iov[niov++], "CODE_LINE="); - IOVEC_SET_INT(iov[niov++], linestr, linenr); - IOVEC_SET_STRING(iov[niov++], "\n"); + state.iov = iov; + state.iov_end = iov + ARRAY_CARDINALITY(iov); + state.bufs = iov_bufs; + state.bufs_end = iov_bufs + ARRAY_CARDINALITY(iov_bufs);
- IOVEC_SET_STRING(iov[niov++], "CODE_FUNC="); - IOVEC_SET_STRING(iov[niov++], funcname); - IOVEC_SET_STRING(iov[niov++], "\n"); + journalAddString(&state ,"MESSAGE", rawstr); + journalAddInt(&state, "PRIORITY", priority); + journalAddString(&state, "LIBVIRT_SOURCE", + virLogSourceTypeToString(source)); + journalAddString(&state, "CODE_FILE", filename); + journalAddInt(&state, "CODE_LINE", linenr); + journalAddString(&state, "CODE_FUNC", funcname);
memset(&sa, 0, sizeof(sa)); sa.sun_family = AF_UNIX; @@ -1142,7 +1172,7 @@ virLogOutputToJournald(virLogSource source, mh.msg_name = &sa; mh.msg_namelen = offsetof(struct sockaddr_un, sun_path) + strlen(sa.sun_path); mh.msg_iov = iov; - mh.msg_iovlen = niov; + mh.msg_iovlen = state.iov - iov;
if (sendmsg(journalfd, &mh, MSG_NOSIGNAL) >= 0) return; @@ -1166,7 +1196,7 @@ virLogOutputToJournald(virLogSource source, if (unlink(path) < 0) goto cleanup;
- if (writev(buffd, iov, niov) < 0) + if (writev(buffd, iov, state.iov - iov) < 0) goto cleanup;
mh.msg_iov = NULL;
ACK 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 :|
On 11/14/2012 08:30 AM, Daniel P. Berrange wrote:
On Wed, Oct 17, 2012 at 08:17:16PM +0200, Miloslav Trmač wrote:
This simplifies the top-level code, at the cost of using a little more stack space. The primary benefit is being able to send more fields without knowing in advance how many of them, and of which types, these fields will be, and without having to individually add buffer variables.
The code imposes an upper limit on the total number of iovs/buffers used, and fields that wouldn't fit are silently dropped. This is not significant in this patch, but will affect the following one.
ACK
I've applied 1-3; 4 is waiting for a resend, and 5 is too controversial at the moment. -- Eric Blake eblake@redhat.com +1-919-301-3266 Libvirt virtualization library http://libvirt.org
When logging an error, don't throw away the detailed information. Example record when using the journald output: MESSAGE=Domain not found PRIORITY=4 LIBVIRT_SOURCE=error CODE_FILE=../../src/test/test_driver.c CODE_LINE=1405 CODE_FUNC=testLookupDomainByName DOMAIN=12 CODE=42 STR1=Domain not found STR2= The format used in other output destinations (e.g. "syslog", "file") is still unchanged. The "domain" and "code" numbers are part of the libvirt ABI in <libvirt/virterror.h>; therefore log processing tools can rely on them, unlike the text log string (which is translated depending on locale, and may be modified for other reasons as well). Alternatively, the "domain" and "code" fields could contain strings instead of numbers, but it's not clear that it's worth it: Advantages of numbers: * the numbers are shorter * the ABI guarantees that the numbers won't change Disadvantages of strings: * adding a ABI-stable string mapping for virErrorNumber would result in additional work each time a new error number is added (note that virErrorMsg cannot be used for this because it is translated) * a change in the string mapping would be less likely to be noticed The advantage of using strings is more readability, but note that the "msg" field above already contains a readable description of the error. The inability to allocate memory imposes a fixed limit on the number of metadata fields that can be supported by the journal; fields beyond this limit are silently dropped (but the initial part of the message sent). This was implemented in the previous patch, here we just increase the limit to 32 fields total. Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 13 +++++++++++-- src/util/virterror.c | 33 ++++++++++++++++++++++++++++++++- 2 files changed, 43 insertions(+), 3 deletions(-) diff --git a/src/util/logging.c b/src/util/logging.c index a6d00c9..5166def 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -1125,7 +1125,7 @@ virLogOutputToJournald(virLogSource source, int linenr, const char *funcname, const char *timestamp ATTRIBUTE_UNUSED, - virLogMetadataPtr metadata ATTRIBUTE_UNUSED, + virLogMetadataPtr metadata, unsigned int flags, const char *rawstr, const char *str ATTRIBUTE_UNUSED, @@ -1145,7 +1145,7 @@ virLogOutputToJournald(virLogSource source, * and where unprivileged users can create files. */ char path[] = "/dev/shm/journal.XXXXXX"; -# define NUM_FIELDS 6 +# define NUM_FIELDS 32 struct iovec iov[NUM_FIELDS * 5]; char iov_bufs[NUM_FIELDS][JOURNAL_BUF_SIZE]; struct journalState state; @@ -1162,6 +1162,15 @@ virLogOutputToJournald(virLogSource source, journalAddString(&state, "CODE_FILE", filename); journalAddInt(&state, "CODE_LINE", linenr); journalAddString(&state, "CODE_FUNC", funcname); + if (metadata != NULL) { + while (metadata->key != NULL) { + if (metadata->s != NULL) + journalAddString(&state, metadata->key, metadata->s); + else + journalAddInt(&state, metadata->key, metadata->i); + metadata++; + } + } memset(&sa, 0, sizeof(sa)); sa.sun_family = AF_UNIX; diff --git a/src/util/virterror.c b/src/util/virterror.c index df8b6fd..64dca58 100644 --- a/src/util/virterror.c +++ b/src/util/virterror.c @@ -619,6 +619,8 @@ virRaiseErrorFull(const char *filename ATTRIBUTE_UNUSED, virErrorPtr to; char *str; int priority; + virLogMetadata meta[8]; + size_t i; /* * All errors are recorded in thread local storage @@ -676,10 +678,39 @@ virRaiseErrorFull(const char *filename ATTRIBUTE_UNUSED, priority = virErrorLevelPriority(level); if (virErrorLogPriorityFilter) priority = virErrorLogPriorityFilter(to, priority); + + i = 0; +#define META_ADD_STRING(KEY, VALUE) \ + do { \ + meta[i].key = (KEY); \ + meta[i].s = (VALUE); \ + i++; \ + } while (0) +#define META_ADD_INT(KEY, VALUE) \ + do { \ + meta[i].key = (KEY); \ + meta[i].s = NULL; \ + meta[i].i = (VALUE); \ + i++; \ + } while (0) + + META_ADD_INT("DOMAIN", domain); + META_ADD_INT("CODE", code); + if (str1 != NULL) + META_ADD_STRING("STR1", str1); + if (str2 != NULL) + META_ADD_STRING("STR2", str2); + if (str3 != NULL) + META_ADD_STRING("STR3", str3); + if (int1 != -1) + META_ADD_INT("INT1", int1); + if (int2 != -1) + META_ADD_INT("INT2", int2); + meta[i].key = NULL; virLogMessage(virErrorLogPriorityFilter ? VIR_LOG_FROM_FILE : VIR_LOG_FROM_ERROR, priority, filename, linenr, funcname, - NULL, "%s", str); + meta, "%s", str); errno = save_errno; } -- 1.7.11.7
On Wed, Oct 17, 2012 at 08:17:17PM +0200, Miloslav Trmač wrote:
When logging an error, don't throw away the detailed information. Example record when using the journald output:
MESSAGE=Domain not found PRIORITY=4 LIBVIRT_SOURCE=error CODE_FILE=../../src/test/test_driver.c CODE_LINE=1405 CODE_FUNC=testLookupDomainByName DOMAIN=12 CODE=42 STR1=Domain not found STR2=
The format used in other output destinations (e.g. "syslog", "file") is still unchanged.
The "domain" and "code" numbers are part of the libvirt ABI in <libvirt/virterror.h>; therefore log processing tools can rely on them, unlike the text log string (which is translated depending on locale, and may be modified for other reasons as well).
Alternatively, the "domain" and "code" fields could contain strings instead of numbers, but it's not clear that it's worth it: Advantages of numbers: * the numbers are shorter * the ABI guarantees that the numbers won't change Disadvantages of strings: * adding a ABI-stable string mapping for virErrorNumber would result in additional work each time a new error number is added (note that virErrorMsg cannot be used for this because it is translated) * a change in the string mapping would be less likely to be noticed The advantage of using strings is more readability, but note that the "msg" field above already contains a readable description of the error.
Agreed, the numeric values are the only part we want to consider ABI stable. We have often changed the string values, even for the error codes.
@@ -676,10 +678,39 @@ virRaiseErrorFull(const char *filename ATTRIBUTE_UNUSED, priority = virErrorLevelPriority(level); if (virErrorLogPriorityFilter) priority = virErrorLogPriorityFilter(to, priority); + + i = 0; +#define META_ADD_STRING(KEY, VALUE) \ + do { \ + meta[i].key = (KEY); \ + meta[i].s = (VALUE); \ + i++; \ + } while (0) +#define META_ADD_INT(KEY, VALUE) \ + do { \ + meta[i].key = (KEY); \ + meta[i].s = NULL; \ + meta[i].i = (VALUE); \ + i++; \ + } while (0) + + META_ADD_INT("DOMAIN", domain); + META_ADD_INT("CODE", code); + if (str1 != NULL) + META_ADD_STRING("STR1", str1); + if (str2 != NULL) + META_ADD_STRING("STR2", str2); + if (str3 != NULL) + META_ADD_STRING("STR3", str3); + if (int1 != -1) + META_ADD_INT("INT1", int1); + if (int2 != -1) + META_ADD_INT("INT2", int2);
At this point in time, I would like us to leave out the str1, str2, str3, int1 and int2 values. These are a badly defined part of our error reporting system. My goal is that for each error code, we will define explicit semantics for the str1/str2/str3/int1/int2 fields (or defined them to be unused). For example, with VIR_ERR_SYSTEM_ERROR, we'll declare that 'int1' is always the errno values. Once we have this kind of stuff defined, then we can make the structured error reports contain the appropriate extra fields for the code in question. So for VIR_ERR_SYSTEM_ERROR, the structured error log would contain an 'errno' field instead of an 'int1' field. Can you re-submit, just this patch in the series, with those parts commented out or removed. 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 :|
This is independent from the rest of the series, sending it anyway for consideration; this makes the metadata available to users on non-systemd platforms. I believe the technical objections (primarily async-signal-safety) have been resolved; the question of whether the project wants to support this or not is still open, of course. Add a "syslog/json" output format, which uses a JSON representation (as specified in Lumberjack project, and planned for the CEE standard) to format individual components, making the result easy to parse without writing custom code or using unreliable regexps. Example message (line-wrapped for readability, the actual output is a single line): Oct 17 16:29:56 kulicka libvirt: @cee: {"msg":"Domain not found", "LIBVIRT_SOURCE":"error","priority":"err", "CODE_FILE":"../../src/test/test_driver.c","CODE_LINE":1405, "CODE_FUNC":"testLookupDomainByName", "timestamp":"2012-10-17 14:29:56.683+0000","DOMAIN":12,"CODE":42, "STR1":"Domain not found","STR2":""} None of the existing log output formats (e.g. "syslog" or "file") is affected. Async-signal-safety is preserved by a) providing a custom allocation function to yajl, and b) using a custom print function. Both use memory allocated within the stack frame. Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- docs/logging.html.in | 3 + src/util/logging.c | 272 ++++++++++++++++++++++++++++++++++++++++++++++++++- src/util/logging.h | 1 + 3 files changed, 272 insertions(+), 4 deletions(-) diff --git a/docs/logging.html.in b/docs/logging.html.in index a95f7bc..4f8ad87 100644 --- a/docs/logging.html.in +++ b/docs/logging.html.in @@ -143,6 +143,9 @@ <li><code>x:stderr</code> output goes to stderr</li> <li><code>x:syslog:name</code> use syslog for the output and use the given <code>name</code> as the ident</li> + <li><code>x:syslog/json:name</code> use JSON-formatted syslog (also + called the CEE format or Lumberjack) for the output and use the given + <code>name</code> as the ident</li> <li><code>x:file:file_path</code> output to a file, with the given filepath</li> </ul> diff --git a/src/util/logging.c b/src/util/logging.c index 5166def..0dafa59 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -21,6 +21,7 @@ #include <config.h> +#include <stdbool.h> #include <stdio.h> #include <stdarg.h> #include <stdlib.h> @@ -50,6 +51,15 @@ #include "virtime.h" #include "intprops.h" +#if HAVE_YAJL +# include <yajl/yajl_gen.h> +# ifdef HAVE_YAJL2 +# define yajl_size_t size_t +# else +# define yajl_size_t unsigned int +# endif +#endif + /* Journald output is only supported on Linux new enough to expose * htole64. */ #if HAVE_SYSLOG_H && defined(__linux__) && HAVE_DECL_HTOLE64 @@ -160,6 +170,8 @@ virLogOutputString(virLogDestination ldest) return "file"; case VIR_LOG_TO_JOURNALD: return "journald"; + case VIR_LOG_TO_SYSLOG_JSON: + return "syslog/json"; } return "unknown"; } @@ -645,7 +657,8 @@ virLogDefineOutput(virLogOutputFunc f, if (f == NULL) return -1; - if (dest == VIR_LOG_TO_SYSLOG || dest == VIR_LOG_TO_FILE) { + if (dest == VIR_LOG_TO_SYSLOG || dest == VIR_LOG_TO_SYSLOG_JSON + || dest == VIR_LOG_TO_FILE) { if (name == NULL) return -1; ndup = strdup(name); @@ -1008,6 +1021,238 @@ virLogOutputToSyslog(virLogSource source ATTRIBUTE_UNUSED, syslog(virLogPrioritySyslog(priority), "%s", str); } + +#if HAVE_YAJL +static const char * +virLogPriorityJSONString(virLogPriority lvl) +{ + /* This follows "prioritynames" from <sys/syslog.h> */ + switch (virLogPrioritySyslog(lvl)) { + case LOG_DEBUG: + return "debug"; + case LOG_INFO: + return "info"; + case LOG_WARNING: + return "warn"; + case LOG_ERR: + return "err"; + } + return "unknown"; +} + + +/* A trivial "arena" stack allocator for yajl to avoid malloc(). */ +union stackAllocMaxAlign +{ + intmax_t i; + long double dbl; + void (*p); + void (*fp)(void); +}; + +#define YAJL_ALLOC_SPACE 1024 +struct stackAlloc +{ + union + { + unsigned char buf[YAJL_ALLOC_SPACE]; + union stackAllocMaxAlign align; /* To align buf correctly */ + } v; + void *next_free; /* Within v.buf */ +}; + +static void * +stackMalloc(void *ctx, yajl_size_t sz) +{ + struct stackAlloc *stack; + void *end, *res; + + stack = ctx; + sz = ((sz + sizeof(union stackAllocMaxAlign) - 1) + / sizeof(union stackAllocMaxAlign) + * sizeof(union stackAllocMaxAlign)); + end = stack->v.buf + ARRAY_CARDINALITY(stack->v.buf); + if ((unsigned char *)end - (unsigned char *)stack->next_free < sz) + return NULL; + res = stack->next_free; + stack->next_free = (unsigned char *)stack->next_free + sz; + return res; +} + +static void * +stackRealloc(void *ctx ATTRIBUTE_UNUSED, void *ptr ATTRIBUTE_UNUSED, + yajl_size_t sz ATTRIBUTE_UNUSED) +{ + return NULL; /* realloc is not necessary in our case. */ +} + +static void +stackFree(void *ctx ATTRIBUTE_UNUSED, void *ptr ATTRIBUTE_UNUSED) +{ +} + +static void +stackAllocInit(yajl_alloc_funcs *dest, struct stackAlloc *stack) +{ + stack->next_free = stack->v.buf; + + dest->malloc = stackMalloc; + dest->realloc = stackRealloc; + dest->free = stackFree; + dest->ctx = stack; +} + + +#define MAX_JSON_OUTPUT_SIZE 2048 +struct JSONOutput +{ + char buf[MAX_JSON_OUTPUT_SIZE]; + char *next; + bool failed; +}; + +static void +JSONOutputPrint(void *ctx, const char *str, yajl_size_t len) +{ + struct JSONOutput *dest; + + dest = ctx; + if (dest->failed + || (dest->buf + ARRAY_CARDINALITY(dest->buf)) - dest->next < len) + dest->failed = true; + else { + memcpy(dest->next, str, len); + dest->next += len; + } +} + +static int +yajlAddString(yajl_gen g, const char *key, const char *value) +{ + if (yajl_gen_string(g, (const unsigned char *)key, strlen(key)) + != yajl_gen_status_ok) + return -1; + if (yajl_gen_string(g, (const unsigned char *)value, strlen(value)) + != yajl_gen_status_ok) + return -1; + return 0; +} + + +static int +yajlAddInt(yajl_gen g, const char *key, int value) +{ + char buf[INT_BUFSIZE_BOUND(value)], *p; + + if (yajl_gen_string(g, (const unsigned char *)key, strlen(key)) + != yajl_gen_status_ok) + return -1; + p = virFormatIntDecimal(buf, sizeof(buf), value); + if (yajl_gen_number(g, p, strlen(p)) != yajl_gen_status_ok) + return -1; + return 0; +} + + +static void +virLogOutputToSyslogJSON(virLogSource source, + virLogPriority priority, + const char *filename, + int linenr, + const char *funcname, + const char *timestamp, + virLogMetadataPtr metadata, + unsigned int flags, + const char *rawstr, + const char *str, + void *data ATTRIBUTE_UNUSED) +{ + struct stackAlloc stack_alloc; + struct JSONOutput output; + yajl_alloc_funcs alloc_funcs; + yajl_gen g = NULL; +# ifndef HAVE_YAJL2 + yajl_gen_config conf = { 0, " "}; +# endif + + virCheckFlags(VIR_LOG_STACK_TRACE,); + + output.next = output.buf; + output.failed = false; + +# ifdef HAVE_YAJL2 + stackAllocInit(&alloc_funcs, &stack_alloc); + g = yajl_gen_alloc(&alloc_funcs); + if (g) { + yajl_gen_config(g, yajl_gen_beautify, 0); + yajl_gen_config(g, yajl_gen_indent_string, " "); + yajl_gen_config(g, yajl_gen_validate_utf8, 1); + yajl_gen_config(g, yajl_gen_print_callback, JSONOutputPrint, + (void *)&output); + } +# else + g = yajl_gen_alloc2(JSONOutputPrint, &conf, &alloc_funcs, &output); +# endif + if (g == NULL) + goto error; + + /* The field names follow https://fedorahosted.org/lumberjack/wiki/FieldList + - use the same field names when the purpose and type matches, use a + different field name otherwise. + + Consistency with the journal names is also recommended. + + msg goes first, so that the most important information is in a fixed + position on the screen (= easy to find); the metadata comes later (or + perhaps does not fit into the terminal/log viewer window). */ + + if (yajl_gen_map_open(g) != yajl_gen_status_ok) + goto error; + +#define CHECK(E) \ + do { \ + if ((E) != 0) \ + goto error; \ + } while (0) + CHECK(yajlAddString(g, "msg", rawstr)); + CHECK(yajlAddString(g, "LIBVIRT_SOURCE", virLogSourceTypeToString(source))); + CHECK(yajlAddString(g, "priority", virLogPriorityJSONString(priority))); + CHECK(yajlAddString(g, "CODE_FILE", filename)); + CHECK(yajlAddInt(g, "CODE_LINE", linenr)); + if (funcname != NULL) + CHECK(yajlAddString(g, "CODE_FUNC", funcname)); + CHECK(yajlAddString(g, "timestamp", timestamp)); + + if (metadata != NULL) { + while (metadata->key != NULL) { + if (metadata->s != NULL) + CHECK(yajlAddString(g, metadata->key, metadata->s)); + else + CHECK(yajlAddInt(g, metadata->key, metadata->i)); + metadata++; + } + } +#undef CHECK + + if (yajl_gen_map_close(g) != yajl_gen_status_ok) + goto error; + JSONOutputPrint(&output, "", 1); + if (output.failed) + goto error; + + syslog(virLogPrioritySyslog(priority), "@cee: %s", output.buf); + yajl_gen_free(g); + return; + + error: + if (g != NULL) + yajl_gen_free(g); + virLogOutputToSyslog(source, priority, filename, linenr, funcname, + timestamp, metadata, flags, rawstr, str, NULL); +} +#endif + + static char *current_ident = NULL; @@ -1021,8 +1266,18 @@ virLogCloseSyslog(void *data ATTRIBUTE_UNUSED) static int virLogAddOutputToSyslog(virLogPriority priority, - const char *ident) + const char *ident, + bool is_json) { + virLogOutputFunc f; + +#ifdef HAVE_YAJL + if (is_json) + f = virLogOutputToSyslogJSON; + else +#endif + f = virLogOutputToSyslog; + /* * ident needs to be kept around on Solaris */ @@ -1032,7 +1287,7 @@ virLogAddOutputToSyslog(virLogPriority priority, return -1; openlog(current_ident, 0, 0); - if (virLogDefineOutput(virLogOutputToSyslog, virLogCloseSyslog, NULL, + if (virLogDefineOutput(f, virLogCloseSyslog, NULL, priority, VIR_LOG_TO_SYSLOG, ident, 0) < 0) { closelog(); VIR_FREE(current_ident); @@ -1307,7 +1562,16 @@ virLogParseOutputs(const char *outputs) if (virLogAddOutputToStderr(prio) == 0) count++; } else if (STREQLEN(cur, "syslog", 6)) { + bool is_json; + cur += 6; + if (*cur == ':') + is_json = false; + else if (STREQLEN(cur, "/json", 5)) { + is_json = true; + cur += 5; + } else + goto cleanup; if (*cur != ':') goto cleanup; cur++; @@ -1320,7 +1584,7 @@ virLogParseOutputs(const char *outputs) name = strndup(str, cur - str); if (name == NULL) goto cleanup; - if (virLogAddOutputToSyslog(prio, name) == 0) + if (virLogAddOutputToSyslog(prio, name, is_json) == 0) count++; VIR_FREE(name); #endif /* HAVE_SYSLOG_H */ diff --git a/src/util/logging.h b/src/util/logging.h index 52feecc..4b589cb 100644 --- a/src/util/logging.h +++ b/src/util/logging.h @@ -42,6 +42,7 @@ typedef enum { VIR_LOG_TO_SYSLOG, VIR_LOG_TO_FILE, VIR_LOG_TO_JOURNALD, + VIR_LOG_TO_SYSLOG_JSON, } virLogDestination; typedef enum { -- 1.7.11.7
On Wed, Oct 17, 2012 at 08:17:18PM +0200, Miloslav Trmač wrote:
This is independent from the rest of the series, sending it anyway for consideration; this makes the metadata available to users on non-systemd platforms. I believe the technical objections (primarily async-signal-safety) have been resolved; the question of whether the project wants to support this or not is still open, of course.
Add a "syslog/json" output format, which uses a JSON representation (as specified in Lumberjack project, and planned for the CEE standard) to format individual components, making the result easy to parse without writing custom code or using unreliable regexps.
Example message (line-wrapped for readability, the actual output is a single line):
Oct 17 16:29:56 kulicka libvirt: @cee: {"msg":"Domain not found", "LIBVIRT_SOURCE":"error","priority":"err", "CODE_FILE":"../../src/test/test_driver.c","CODE_LINE":1405, "CODE_FUNC":"testLookupDomainByName", "timestamp":"2012-10-17 14:29:56.683+0000","DOMAIN":12,"CODE":42, "STR1":"Domain not found","STR2":""}
None of the existing log output formats (e.g. "syslog" or "file") is affected.
Async-signal-safety is preserved by a) providing a custom allocation function to yajl, and b) using a custom print function. Both use memory allocated within the stack frame.
I appreciate that you were able to re-work this to be async safe. Personally though I would prefer not to have this in libvirt, because I feel that syslog json support is really bad approach to the problem and I don't want to validate it in the eyes of others as a good solution by including it in libvirt. 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 :|
Hello, ----- Original Message -----
This is sort of a v2 of the "Structured syslog" series.
Patches 1-4 allow callers virLogMessage to add arbitrary additional data, and use it in virRaiseErrorFull and its callers. This data is sent to journal (and ignored for other outputs).
Any comments on the series, or at least on 1-4? Even a "hell no, go away" would be beneficial. :) Thank you, Mirek
On Wed, Oct 31, 2012 at 11:38:43AM -0400, Miloslav Trmac wrote:
Hello, ----- Original Message -----
This is sort of a v2 of the "Structured syslog" series.
Patches 1-4 allow callers virLogMessage to add arbitrary additional data, and use it in virRaiseErrorFull and its callers. This data is sent to journal (and ignored for other outputs).
Any comments on the series, or at least on 1-4? Even a "hell no, go away" would be beneficial. :)
I've been away for much of the past two weeks, but this is on my todo list to review real soon. 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 :|
participants (4)
-
Daniel P. Berrange -
Eric Blake -
Miloslav Trmac -
Miloslav Trmač