[libvirt] [PATCH 00/12] Structured syslog (Lumberjack/CEE) support
This patch set adds structured syslog support to libvirt. In short, the idea is to embed JSON in a syslog record. This format is used in a new log output type called "syslog/json". Example "syslog/json" record (line-wrapped for readability): Sep 20 19:59:40 kulicka libvirt: @cee: {"msg":"libvirt version: 0.10.1", "category":"../../src/test/test_driver.c","priority":"info", "funcname":"virLogVMessage","line":769, "timestamp":"2012-09-20 17:59:40.853+0000"} compared with existing "syslog" record format: Sep 20 20:02:24 kulicka libvirt: 5896: info : libvirt version: 0.10.1 This JSON embedding format is defined by the Lumberjack project led by the major Open Source syslog implementations (https://fedorahosted.org/lumberjack/). The format is also a base for a future MITRE CEE standard. Some of the fields are specified at https://fedorahosted.org/lumberjack/wiki/FieldList , but applications are free to use whatever fields make sense for them. The JSON structure makes easy to process logs by programs without writing code that understands the specific format used by each application, or using unreliable regexps (https://fedorahosted.org/ceelog/ is a companion project that allows processing such logs). Current systems will store and these records unmodified and present them to users unmodified, but tools (and probably /var/log/messages) will be able to show only the "msg" field; this allows us to add more detailed information without worsening the user experience (the example above already shows added information that is currently being thrown away when logging to syslog). The patch set, aside from building the required infrastructure, has two main components: * Add the "syslog/json" output type, and use it to record all information passed to virLogMessage. The example result is shown above. This primarily makes it easier to parse the message. * Allow callers of virLogMessage to add arbitrary additional JSON fields, and use it in virRaiseErrorFull and its callers. 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 about a situation that requires immediate attention, or automatically suggesting a solution. This has not been possible until now because the current logs contain only a translated error message, so the log record doesn't contain anything stable that could be detected by a program. It is assumed that other parts of libvirt may add more event-specific JSON fields in the future, based on demand by applications that process the logs; I have, however, no immediate plans to add more. Miloslav Trmač (12): Drop unused return value of virLogOutputFunc Add JSON API for preallocated objects. Split yajl_gen allocation into a separate function. Split adding object properties from virJSONValueToStringOne Add a JSON generator API. Pass the "raw" log message to each virLogOutputFunc Split priority conversion from virLogOutputToSyslog Add "syslog/json" log output format. Add a JSON properties parameter to virLog{,V}Message Add a JSON properties parameter to virLogOutputFunc Add detailed error information to JSON syslog Add a test for the new error reporting mechanism. docs/logging.html.in | 3 + src/libvirt_private.syms | 4 + src/uml/uml_conf.c | 2 +- src/util/json.c | 232 +++++++++++++++++++++++++++++++++++++++++----- src/util/json.h | 26 ++++++ src/util/logging.c | 233 ++++++++++++++++++++++++++++++++++------------- src/util/logging.h | 35 +++---- src/util/viraudit.c | 4 +- src/util/virterror.c | 32 ++++++- tests/Makefile.am | 6 +- tests/errorjsontest.c | 211 ++++++++++++++++++++++++++++++++++++++++++ tests/testutils.c | 7 +- 12 files changed, 684 insertions(+), 111 deletions(-) create mode 100644 tests/errorjsontest.c -- 1.7.11.4
Nothing uses the return value, and creating it requries otherwise unnecessary strlen () calls. This cleanup is conceptually independent from the rest of the series (although the later patches won't apply without it). This just seems a good opportunity to clean this up, instead of entrenching the unnecessary return value in the virLogOutputFunc instance that will be added in this series. Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 56 +++++++++++++++++++++++++----------------------------- src/util/logging.h | 14 ++++++-------- tests/testutils.c | 5 ++--- 3 files changed, 34 insertions(+), 41 deletions(-) diff --git a/src/util/logging.c b/src/util/logging.c index 6048151..537c764 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -98,12 +98,12 @@ static virLogPriority virLogDefaultPriority = VIR_LOG_DEFAULT; static int virLogResetFilters(void); static int virLogResetOutputs(void); -static int virLogOutputToFd(const char *category, int priority, - const char *funcname, long long linenr, - const char *timestamp, - unsigned int flags, - const char *str, - void *data); +static void virLogOutputToFd(const char *category, int priority, + const char *funcname, long long linenr, + const char *timestamp, + unsigned int flags, + const char *str, + void *data); /* * Logs accesses must be serialized though a mutex @@ -807,32 +807,29 @@ static void virLogStackTraceToFd(int fd) #undef STRIP_DEPTH } -static int virLogOutputToFd(const char *category ATTRIBUTE_UNUSED, - int priority ATTRIBUTE_UNUSED, - const char *funcname ATTRIBUTE_UNUSED, - long long linenr ATTRIBUTE_UNUSED, - const char *timestamp, - unsigned int flags, - const char *str, - void *data) +static void virLogOutputToFd(const char *category ATTRIBUTE_UNUSED, + int priority ATTRIBUTE_UNUSED, + const char *funcname ATTRIBUTE_UNUSED, + long long linenr ATTRIBUTE_UNUSED, + const char *timestamp, + unsigned int flags, + const char *str, + void *data) { int fd = (intptr_t) data; - int ret; char *msg; if (fd < 0) - return -1; + return; if (virAsprintf(&msg, "%s: %s", timestamp, str) < 0) - return -1; + return; - ret = safewrite(fd, msg, strlen(msg)); + ignore_value(safewrite(fd, msg, strlen(msg))); VIR_FREE(msg); if (flags & VIR_LOG_STACK_TRACE) virLogStackTraceToFd(fd); - - return ret; } static void virLogCloseFd(void *data) @@ -865,18 +862,18 @@ static int virLogAddOutputToFile(int priority, const char *file) { } #if HAVE_SYSLOG_H -static int virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED, - int priority, - const char *funcname ATTRIBUTE_UNUSED, - long long linenr ATTRIBUTE_UNUSED, - const char *timestamp ATTRIBUTE_UNUSED, - unsigned int flags, - const char *str, - void *data ATTRIBUTE_UNUSED) +static void virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED, + int priority, + const char *funcname ATTRIBUTE_UNUSED, + long long linenr ATTRIBUTE_UNUSED, + const char *timestamp ATTRIBUTE_UNUSED, + unsigned int flags, + const char *str, + void *data ATTRIBUTE_UNUSED) { int prio; - virCheckFlags(VIR_LOG_STACK_TRACE, -1); + virCheckFlags(VIR_LOG_STACK_TRACE,); switch (priority) { case VIR_LOG_DEBUG: @@ -895,7 +892,6 @@ static int virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED, prio = LOG_ERR; } syslog(prio, "%s", str); - return strlen(str); } static char *current_ident = NULL; diff --git a/src/util/logging.h b/src/util/logging.h index 137bad2..1c484bb 100644 --- a/src/util/logging.h +++ b/src/util/logging.h @@ -94,15 +94,13 @@ typedef enum { * @data: extra output logging data * * Callback function used to output messages - * - * 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 linenr, - const char *timestamp, - unsigned int flags, - const char *str, - void *data); +typedef void (*virLogOutputFunc) (const char *category, int priority, + const char *funcname, long long linenr, + const char *timestamp, + unsigned int flags, + const char *str, + void *data); /** * virLogCloseFunc: diff --git a/tests/testutils.c b/tests/testutils.c index ecd3d2d..5c32f14 100644 --- a/tests/testutils.c +++ b/tests/testutils.c @@ -478,7 +478,7 @@ struct virtTestLogData { static struct virtTestLogData testLog = { VIR_BUFFER_INITIALIZER }; -static int +static void virtTestLogOutput(const char *category ATTRIBUTE_UNUSED, int priority ATTRIBUTE_UNUSED, const char *funcname ATTRIBUTE_UNUSED, @@ -489,9 +489,8 @@ virtTestLogOutput(const char *category ATTRIBUTE_UNUSED, void *data) { struct virtTestLogData *log = data; - virCheckFlags(VIR_LOG_STACK_TRACE, -1); + virCheckFlags(VIR_LOG_STACK_TRACE,); virBufferAsprintf(&log->buf, "%s: %s", timestamp, str); - return strlen(timestamp) + 2 + strlen(str); } static void -- 1.7.11.4
On Thu, Sep 20, 2012 at 08:24:00PM +0200, Miloslav Trmač wrote:
Nothing uses the return value, and creating it requries otherwise unnecessary strlen () calls.
This cleanup is conceptually independent from the rest of the series (although the later patches won't apply without it). This just seems a good opportunity to clean this up, instead of entrenching the unnecessary return value in the virLogOutputFunc instance that will be added in this series.
Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 56 +++++++++++++++++++++++++----------------------------- src/util/logging.h | 14 ++++++-------- tests/testutils.c | 5 ++--- 3 files changed, 34 insertions(+), 41 deletions(-)
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 09/21/2012 02:39 AM, Daniel P. Berrange wrote:
On Thu, Sep 20, 2012 at 08:24:00PM +0200, Miloslav Trmač wrote:
Nothing uses the return value, and creating it requries otherwise unnecessary strlen () calls.
This cleanup is conceptually independent from the rest of the series (although the later patches won't apply without it). This just seems a good opportunity to clean this up, instead of entrenching the unnecessary return value in the virLogOutputFunc instance that will be added in this series.
Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 56 +++++++++++++++++++++++++----------------------------- src/util/logging.h | 14 ++++++-------- tests/testutils.c | 5 ++--- 3 files changed, 34 insertions(+), 41 deletions(-)
ACK
I've pushed this one. The rest of the series is big enough that it is probably worth deferring to post-0.10.2 release. -- Eric Blake eblake@redhat.com +1-919-301-3266 Libvirt virtualization library http://libvirt.org
Add a JSON API that allows creating a JSON data structure within variables preallocated on the stack, without allocating memory in the heap. Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/json.c | 82 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++ src/util/json.h | 11 ++++++++ 2 files changed, 93 insertions(+) diff --git a/src/util/json.c b/src/util/json.c index 0507244..8529b5f 100644 --- a/src/util/json.c +++ b/src/util/json.c @@ -23,6 +23,8 @@ #include <config.h> +#include <stdio.h> + #include "json.h" #include "memory.h" #include "virterror_internal.h" @@ -659,6 +661,86 @@ int virJSONValueObjectIsNull(virJSONValuePtr object, const char *key) } +/** + * virJSONStaticObjectInitialize: + * @object: destination object + * @pairs_buf: a buffer for storing property pairs. + * + * Initialize a pre-allocated object so that virJSONStaticObjectAppend* can + * be called on it. + * + * The caller is responsible for sizing @pairs_buf appropriately, one entry + * per virJSONStaticObjectAppend* call. + */ +void virJSONStaticObjectInitialize(virJSONObjectPtr object, + virJSONObjectPairPtr pairs_buf) +{ + object->npairs = 0; + object->pairs = pairs_buf; +} + +/** + * virJSONStaticObjectAppendString: + * @object: destination object + * @key: property key + * @value_dest: a preallocated object for storing the JSON value + * @value: value of the property + * + * Add a string value to @object. Does not make any copies, so it is not + * necessary to free anything, but the caller is responsible for keeping + * @key, @value_dest and @value valid until it stops using @object. + */ +void virJSONStaticObjectAppendString(virJSONObjectPtr object, const char *key, + virJSONValuePtr value_dest, + const char *value) +{ + virJSONObjectPairPtr pair; + + value_dest->type = VIR_JSON_TYPE_STRING; + value_dest->protect = 0; + value_dest->data.string = (char *)value; + + pair = object->pairs + object->npairs; + pair->key = (char *)key; + pair->value = value_dest; + object->npairs++; +} + +/** + * virJSONStaticObjectAppendNumberInt: + * @object: destination object + * @key: property key + * @value_dest: a preallocated object for storing the JSON value + * @buf: a preallocated buffer for storing the string representation of @value + * @buf_size: size of @buf + * @value: value of the property + * + * Add an integer value to @object. Does not make any copies, so it is not + * necessary to free anything, but the caller is responsible for keeping + * @key, @value_dest, @buf and @value valid until it stops using @object. + * + * @buf_size should be at least INT_BUFSIZE_BOUND(@value). + */ +void virJSONStaticObjectAppendNumberInt(virJSONObjectPtr object, + const char *key, + virJSONValuePtr value_dest, + char *buf, size_t buf_size, + int value) +{ + virJSONObjectPairPtr pair; + + snprintf(buf, buf_size, "%d", value); + value_dest->type = VIR_JSON_TYPE_NUMBER; + value_dest->protect = 0; + value_dest->data.number = buf; + + pair = object->pairs + object->npairs; + pair->key = (char *)key; + pair->value = value_dest; + object->npairs++; +} + + #if HAVE_YAJL static int virJSONParserInsertValue(virJSONParserPtr parser, virJSONValuePtr value) diff --git a/src/util/json.h b/src/util/json.h index bdba3dd..e2cfe6a 100644 --- a/src/util/json.h +++ b/src/util/json.h @@ -131,6 +131,17 @@ int virJSONValueObjectAppendNumberDouble(virJSONValuePtr object, const char *key int virJSONValueObjectAppendBoolean(virJSONValuePtr object, const char *key, int boolean); int virJSONValueObjectAppendNull(virJSONValuePtr object, const char *key); +void virJSONStaticObjectInitialize(virJSONObjectPtr object, + virJSONObjectPairPtr pairs_buf); +void virJSONStaticObjectAppendString(virJSONObjectPtr object, const char *key, + virJSONValuePtr value_dest, + const char *value); +void virJSONStaticObjectAppendNumberInt(virJSONObjectPtr object, + const char *key, + virJSONValuePtr value_dest, + char *buf, size_t buf_size, + int value); + virJSONValuePtr virJSONValueFromString(const char *jsonstring); char *virJSONValueToString(virJSONValuePtr object, bool pretty); -- 1.7.11.4
Split yajl_gen (and handling of the yajl version differences) into virYAJLInit(). No functionality changed; the function will be used in a later patch. Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/json.c | 35 ++++++++++++++++++++++------------- 1 file changed, 22 insertions(+), 13 deletions(-) diff --git a/src/util/json.c b/src/util/json.c index 8529b5f..1accde9 100644 --- a/src/util/json.c +++ b/src/util/json.c @@ -1073,6 +1073,27 @@ cleanup: } +static yajl_gen virYAJLInit(bool pretty) +{ + yajl_gen g; +# ifndef HAVE_YAJL2 + yajl_gen_config conf = { pretty ? 1 : 0, pretty ? " " : " "}; +# endif + +# ifdef HAVE_YAJL2 + g = yajl_gen_alloc(NULL); + if (g) { + yajl_gen_config(g, yajl_gen_beautify, pretty ? 1 : 0); + yajl_gen_config(g, yajl_gen_indent_string, pretty ? " " : " "); + yajl_gen_config(g, yajl_gen_validate_utf8, 1); + } +# else + g = yajl_gen_alloc(&conf, NULL); +# endif + + return g; +} + static int virJSONValueToStringOne(virJSONValuePtr object, yajl_gen g) { @@ -1143,22 +1164,10 @@ char *virJSONValueToString(virJSONValuePtr object, const unsigned char *str; char *ret = NULL; yajl_size_t len; -# ifndef HAVE_YAJL2 - yajl_gen_config conf = { pretty ? 1 : 0, pretty ? " " : " "}; -# endif VIR_DEBUG("object=%p", object); -# ifdef HAVE_YAJL2 - g = yajl_gen_alloc(NULL); - if (g) { - yajl_gen_config(g, yajl_gen_beautify, pretty ? 1 : 0); - yajl_gen_config(g, yajl_gen_indent_string, pretty ? " " : " "); - yajl_gen_config(g, yajl_gen_validate_utf8, 1); - } -# else - g = yajl_gen_alloc(&conf, NULL); -# endif + g = virYAJLInit(pretty); if (!g) { virReportError(VIR_ERR_INTERNAL_ERROR, "%s", _("Unable to create JSON formatter")); -- 1.7.11.4
No functionality change (well, the index is now a size_t instead of int), the function will be used later. Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/json.c | 35 ++++++++++++++++++++++++++--------- src/util/json.h | 12 ++++++++++++ 2 files changed, 38 insertions(+), 9 deletions(-) diff --git a/src/util/json.c b/src/util/json.c index 1accde9..9b0a6dd 100644 --- a/src/util/json.c +++ b/src/util/json.c @@ -1105,15 +1105,8 @@ static int virJSONValueToStringOne(virJSONValuePtr object, case VIR_JSON_TYPE_OBJECT: if (yajl_gen_map_open(g) != yajl_gen_status_ok) return -1; - for (i = 0; i < object->data.object.npairs ; i++) { - if (yajl_gen_string(g, - (unsigned char *)object->data.object.pairs[i].key, - strlen(object->data.object.pairs[i].key)) - != yajl_gen_status_ok) - return -1; - if (virJSONValueToStringOne(object->data.object.pairs[i].value, g) < 0) - return -1; - } + if (virJSONStringGeneratorAddProperties(g, &object->data.object) != 0) + return -1; if (yajl_gen_map_close(g) != yajl_gen_status_ok) return -1; break; @@ -1157,6 +1150,30 @@ static int virJSONValueToStringOne(virJSONValuePtr object, return 0; } +/** + * virJSONStringGeneratorAddProperties: + * @gen: the destination generator + * @object: a JSON object + * + * Add properties contained in @object into the string generated by @gen. + * Note that this adds each property into the "current" object, it does not + * add a subobject. + */ +int virJSONStringGeneratorAddProperties(virJSONStringGeneratorPtr gen, + virJSONObjectPtr object) +{ + size_t i; + + for (i = 0; i < object->npairs ; i++) { + if (yajl_gen_string(gen, (unsigned char *)object->pairs[i].key, + strlen(object->pairs[i].key)) != yajl_gen_status_ok) + return -1; + if (virJSONValueToStringOne(object->pairs[i].value, gen) < 0) + return -1; + } + return 0; +} + char *virJSONValueToString(virJSONValuePtr object, bool pretty) { diff --git a/src/util/json.h b/src/util/json.h index e2cfe6a..390e68d 100644 --- a/src/util/json.h +++ b/src/util/json.h @@ -26,6 +26,9 @@ # include "internal.h" +# if HAVE_YAJL +# include <yajl/yajl_gen.h> +# endif typedef enum { VIR_JSON_TYPE_OBJECT, @@ -77,6 +80,12 @@ struct _virJSONValue { } data; }; +# if HAVE_YAJL +typedef yajl_gen virJSONStringGeneratorPtr; +# else +typedef void *virJSONStringGeneratorPtr; +# endif + void virJSONValueFree(virJSONValuePtr value); virJSONValuePtr virJSONValueNewString(const char *data); @@ -142,6 +151,9 @@ void virJSONStaticObjectAppendNumberInt(virJSONObjectPtr object, char *buf, size_t buf_size, int value); +int virJSONStringGeneratorAddProperties(virJSONStringGeneratorPtr gen, + virJSONObjectPtr object); + virJSONValuePtr virJSONValueFromString(const char *jsonstring); char *virJSONValueToString(virJSONValuePtr object, bool pretty); -- 1.7.11.4
This allows incremental use of virJSONStringGeneratorAddProperties without constructing a full object first, while isolating the rest of libvirt from the yajl dependency. Will be used later. Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/json.c | 60 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++ src/util/json.h | 3 +++ 2 files changed, 63 insertions(+) diff --git a/src/util/json.c b/src/util/json.c index 9b0a6dd..03362c4 100644 --- a/src/util/json.c +++ b/src/util/json.c @@ -1094,6 +1094,66 @@ static yajl_gen virYAJLInit(bool pretty) return g; } +/** + * virJSONStringGeneratorInitObject: + * + * Allocate a generator for creating a string representation of an object using + * one or more calls to virJSONStringGeneratorAddProperties(). + * + * Returns the generator on success, NULL on error. + */ +virJSONStringGeneratorPtr virJSONStringGeneratorInitObject(void) +{ + yajl_gen g; + + g = virYAJLInit(false); + if (g == NULL) + goto error; + if (yajl_gen_map_open(g) != yajl_gen_status_ok) + goto error; + return g; + + error: + if (g != NULL) + yajl_gen_free(g); + return NULL; +} + +/** + * virJSONStringGeneratorFinishObject: + * @gen: the destination generator + * + * Terminate the object being generated in @gen, and return its string value + * (or NULL on error). The value is valid until @gen is freed. + */ +const char *virJSONStringGeneratorFinishObject(virJSONStringGeneratorPtr gen) +{ + const unsigned char *res; + yajl_size_t len; + + if (yajl_gen_map_close(gen) != yajl_gen_status_ok) + goto error; + if (yajl_gen_get_buf(gen, &res, &len) != yajl_gen_status_ok) + goto error; + return (const char *)res; + + error: + return NULL; +} + +/** + * virJSONStringGeneratorFree: + * @gen: the generator + * + * Free @gen if it is not NULL. Invalidates the result of + * virJSONStringGeneratorFinishObject(). + */ +void virJSONStringGeneratorFree(virJSONStringGeneratorPtr gen) +{ + if (gen != NULL) + yajl_gen_free(gen); +} + static int virJSONValueToStringOne(virJSONValuePtr object, yajl_gen g) { diff --git a/src/util/json.h b/src/util/json.h index 390e68d..80041eb 100644 --- a/src/util/json.h +++ b/src/util/json.h @@ -151,8 +151,11 @@ void virJSONStaticObjectAppendNumberInt(virJSONObjectPtr object, char *buf, size_t buf_size, int value); +virJSONStringGeneratorPtr virJSONStringGeneratorInitObject(void); int virJSONStringGeneratorAddProperties(virJSONStringGeneratorPtr gen, virJSONObjectPtr object); +const char *virJSONStringGeneratorFinishObject(virJSONStringGeneratorPtr gen); +void virJSONStringGeneratorFree(virJSONStringGeneratorPtr gen); virJSONValuePtr virJSONValueFromString(const char *jsonstring); char *virJSONValueToString(virJSONValuePtr object, -- 1.7.11.4
In addition to the preformatted text line, pass the raw message as well, to allow the output functions to use a different output format. This patch only changes the interface and callers, an output function that takes advantage of this will follow. Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 23 ++++++++++++++--------- src/util/logging.h | 3 ++- tests/testutils.c | 1 + 3 files changed, 17 insertions(+), 10 deletions(-) diff --git a/src/util/logging.c b/src/util/logging.c index 537c764..5471552 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -102,7 +102,7 @@ static void virLogOutputToFd(const char *category, int priority, const char *funcname, long long linenr, const char *timestamp, unsigned int flags, - const char *str, + const char *rawstr, const char *str, void *data); /* @@ -631,7 +631,7 @@ virLogFormatString(char **msg, } static int -virLogVersionString(char **msg) +virLogVersionString(const char **rawmsg, char **msg) { #ifdef PACKAGER_VERSION # ifdef PACKAGER @@ -646,6 +646,7 @@ virLogVersionString(char **msg) "libvirt version: " VERSION #endif + *rawmsg = LOG_VERSION_STRING; return virLogFormatString(msg, NULL, 0, VIR_LOG_INFO, LOG_VERSION_STRING); } @@ -725,7 +726,6 @@ void virLogVMessage(const char *category, int priority, const char *funcname, } ret = virLogFormatString(&msg, funcname, linenr, priority, str); - VIR_FREE(str); if (ret < 0) goto cleanup; @@ -751,38 +751,41 @@ void virLogVMessage(const char *category, int priority, const char *funcname, for (i = 0; i < virLogNbOutputs; i++) { if (priority >= virLogOutputs[i].priority) { if (virLogOutputs[i].logVersion) { + const char *rawver; char *ver = NULL; - if (virLogVersionString(&ver) >= 0) + if (virLogVersionString(&rawver, &ver) >= 0) virLogOutputs[i].f(category, VIR_LOG_INFO, __func__, __LINE__, - timestamp, 0, ver, + timestamp, 0, rawver, ver, virLogOutputs[i].data); VIR_FREE(ver); virLogOutputs[i].logVersion = false; } virLogOutputs[i].f(category, priority, funcname, linenr, timestamp, filterflags, - msg, virLogOutputs[i].data); + str, msg, virLogOutputs[i].data); } } if ((virLogNbOutputs == 0) && (flags != 1)) { if (logVersionStderr) { + const char *rawver; char *ver = NULL; - if (virLogVersionString(&ver) >= 0) + if (virLogVersionString(&rawver, &ver) >= 0) virLogOutputToFd(category, VIR_LOG_INFO, __func__, __LINE__, - timestamp, 0, ver, + timestamp, 0, rawver, ver, (void *) STDERR_FILENO); VIR_FREE(ver); logVersionStderr = false; } virLogOutputToFd(category, priority, funcname, linenr, timestamp, filterflags, - msg, (void *) STDERR_FILENO); + str, msg, (void *) STDERR_FILENO); } virLogUnlock(); cleanup: + VIR_FREE(str); VIR_FREE(msg); errno = saved_errno; } @@ -813,6 +816,7 @@ static void virLogOutputToFd(const char *category ATTRIBUTE_UNUSED, long long linenr ATTRIBUTE_UNUSED, const char *timestamp, unsigned int flags, + const char *rawstr ATTRIBUTE_UNUSED, const char *str, void *data) { @@ -868,6 +872,7 @@ static void virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED, long long linenr ATTRIBUTE_UNUSED, const char *timestamp ATTRIBUTE_UNUSED, unsigned int flags, + const char *rawstr ATTRIBUTE_UNUSED, const char *str, void *data ATTRIBUTE_UNUSED) { diff --git a/src/util/logging.h b/src/util/logging.h index 1c484bb..10ff6c9 100644 --- a/src/util/logging.h +++ b/src/util/logging.h @@ -90,6 +90,7 @@ typedef enum { * @linenr: line where the message was emitted * @timestamp: zero terminated string with timestamp of the message * @flags: flags associated with the message + * @rawstr: the unformatted message to log, zero terminated * @str: the message to log, preformatted and zero terminated * @data: extra output logging data * @@ -99,7 +100,7 @@ typedef void (*virLogOutputFunc) (const char *category, int priority, const char *funcname, long long linenr, const char *timestamp, unsigned int flags, - const char *str, + const char *rawstr, const char *str, void *data); /** diff --git a/tests/testutils.c b/tests/testutils.c index 5c32f14..6978020 100644 --- a/tests/testutils.c +++ b/tests/testutils.c @@ -485,6 +485,7 @@ virtTestLogOutput(const char *category ATTRIBUTE_UNUSED, long long lineno ATTRIBUTE_UNUSED, const char *timestamp, unsigned int flags, + const char *rawstr ATTRIBUTE_UNUSED, const char *str, void *data) { -- 1.7.11.4
On Thu, Sep 20, 2012 at 08:24:05PM +0200, Miloslav Trmač wrote:
In addition to the preformatted text line, pass the raw message as well, to allow the output functions to use a different output format.
This patch only changes the interface and callers, an output function that takes advantage of this will follow.
Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 23 ++++++++++++++--------- src/util/logging.h | 3 ++- tests/testutils.c | 1 + 3 files changed, 17 insertions(+), 10 deletions(-)
Independantly of my opinion of the patch series in general, I think something like this patch is worthwhile. I would take a slightly different approach though. Instead of passing the rawstr + str into the output functions, I'd only pass the rawstr, and actually move the virLogFormatString() call down into the output functions, instead of virLogVMessage 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 Tue, Sep 25, 2012 at 03:09:22PM +0100, Daniel P. Berrange wrote:
On Thu, Sep 20, 2012 at 08:24:05PM +0200, Miloslav Trmač wrote:
In addition to the preformatted text line, pass the raw message as well, to allow the output functions to use a different output format.
This patch only changes the interface and callers, an output function that takes advantage of this will follow.
Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 23 ++++++++++++++--------- src/util/logging.h | 3 ++- tests/testutils.c | 1 + 3 files changed, 17 insertions(+), 10 deletions(-)
Independantly of my opinion of the patch series in general, I think something like this patch is worthwhile. I would take a slightly different approach though. Instead of passing the rawstr + str into the output functions, I'd only pass the rawstr, and actually move the virLogFormatString() call down into the output functions, instead of virLogVMessage
Urgh, sadly this turns out to not be practical because we need to populate the in memory log buffer with the data. So ACK to this patch - I'll apply it now. 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 :|
No change in functionality; the newly separated virLogPrioritySyslog function will be used by the next patch. Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 36 +++++++++++++++++------------------- 1 file changed, 17 insertions(+), 19 deletions(-) diff --git a/src/util/logging.c b/src/util/logging.c index 5471552..b71eacc 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -866,6 +866,22 @@ static int virLogAddOutputToFile(int priority, const char *file) { } #if HAVE_SYSLOG_H +static int virLogPrioritySyslog(virLogPriority priority) +{ + switch (priority) { + case VIR_LOG_DEBUG: + return LOG_DEBUG; + case VIR_LOG_INFO: + return LOG_INFO; + case VIR_LOG_WARN: + return LOG_WARNING; + case VIR_LOG_ERROR: + return LOG_ERR; + default: + return LOG_ERR; + } +} + static void virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED, int priority, const char *funcname ATTRIBUTE_UNUSED, @@ -876,27 +892,9 @@ static void virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED, const char *str, void *data ATTRIBUTE_UNUSED) { - int prio; - virCheckFlags(VIR_LOG_STACK_TRACE,); - switch (priority) { - case VIR_LOG_DEBUG: - prio = LOG_DEBUG; - break; - case VIR_LOG_INFO: - prio = LOG_INFO; - break; - case VIR_LOG_WARN: - prio = LOG_WARNING; - break; - case VIR_LOG_ERROR: - prio = LOG_ERR; - break; - default: - prio = LOG_ERR; - } - syslog(prio, "%s", str); + syslog(virLogPrioritySyslog(priority), "%s", str); } static char *current_ident = NULL; -- 1.7.11.4
On Thu, Sep 20, 2012 at 08:24:06PM +0200, Miloslav Trmač wrote:
No change in functionality; the newly separated virLogPrioritySyslog function will be used by the next patch.
Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 36 +++++++++++++++++------------------- 1 file changed, 17 insertions(+), 19 deletions(-)
diff --git a/src/util/logging.c b/src/util/logging.c index 5471552..b71eacc 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -866,6 +866,22 @@ static int virLogAddOutputToFile(int priority, const char *file) { }
#if HAVE_SYSLOG_H +static int virLogPrioritySyslog(virLogPriority priority) +{ + switch (priority) { + case VIR_LOG_DEBUG: + return LOG_DEBUG; + case VIR_LOG_INFO: + return LOG_INFO; + case VIR_LOG_WARN: + return LOG_WARNING; + case VIR_LOG_ERROR: + return LOG_ERR; + default: + return LOG_ERR; + } +} + static void virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED, int priority, const char *funcname ATTRIBUTE_UNUSED, @@ -876,27 +892,9 @@ static void virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED, const char *str, void *data ATTRIBUTE_UNUSED) { - int prio; - virCheckFlags(VIR_LOG_STACK_TRACE,);
- switch (priority) { - case VIR_LOG_DEBUG: - prio = LOG_DEBUG; - break; - case VIR_LOG_INFO: - prio = LOG_INFO; - break; - case VIR_LOG_WARN: - prio = LOG_WARNING; - break; - case VIR_LOG_ERROR: - prio = LOG_ERR; - break; - default: - prio = LOG_ERR; - } - syslog(prio, "%s", str); + syslog(virLogPrioritySyslog(priority), "%s", str); }
ACK, useful refactoring independant of the rest of the code 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 :|
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): Sep 17 21:47:22 kulicka libvirt: @cee: {"msg":"Domain not found", "category":"../../src/test/test_driver.c","libvirt_priority":"error", "funcname":"testLookupDomainByName","line":1403, "timestamp":"2012-09-17 19:47:22.731+0000"} None of the existing log output formats (e.g. "syslog" or "file") is affected. The JSON objects are allocated on the stack, which is a little less convenient than allocating them from the heap, but we don't have to care about the allocations failing, calling virReportOOMError and deadlocking on virLogMutex. Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- docs/logging.html.in | 3 ++ src/util/json.c | 20 +++++++++- src/util/logging.c | 110 +++++++++++++++++++++++++++++++++++++++++++++++++-- src/util/logging.h | 1 + 4 files changed, 128 insertions(+), 6 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/json.c b/src/util/json.c index 03362c4..96786c8 100644 --- a/src/util/json.c +++ b/src/util/json.c @@ -672,6 +672,8 @@ int virJSONValueObjectIsNull(virJSONValuePtr object, const char *key) * The caller is responsible for sizing @pairs_buf appropriately, one entry * per virJSONStaticObjectAppend* call. */ +/* Don't call any error reporting or logging functions from this function, + the error loging mechanism may use this! */ void virJSONStaticObjectInitialize(virJSONObjectPtr object, virJSONObjectPairPtr pairs_buf) { @@ -690,6 +692,8 @@ void virJSONStaticObjectInitialize(virJSONObjectPtr object, * necessary to free anything, but the caller is responsible for keeping * @key, @value_dest and @value valid until it stops using @object. */ +/* Don't call any error reporting or logging functions from this function, + the error loging mechanism may use this! */ void virJSONStaticObjectAppendString(virJSONObjectPtr object, const char *key, virJSONValuePtr value_dest, const char *value) @@ -721,6 +725,8 @@ void virJSONStaticObjectAppendString(virJSONObjectPtr object, const char *key, * * @buf_size should be at least INT_BUFSIZE_BOUND(@value). */ +/* Don't call any error reporting or logging functions from this function, + the error loging mechanism may use this! */ void virJSONStaticObjectAppendNumberInt(virJSONObjectPtr object, const char *key, virJSONValuePtr value_dest, @@ -1073,6 +1079,8 @@ cleanup: } +/* Don't call any error reporting or logging functions from this function, + the error loging mechanism may use this! */ static yajl_gen virYAJLInit(bool pretty) { yajl_gen g; @@ -1102,6 +1110,8 @@ static yajl_gen virYAJLInit(bool pretty) * * Returns the generator on success, NULL on error. */ +/* Don't call any error reporting or logging functions from this function, + the error loging mechanism may use this! */ virJSONStringGeneratorPtr virJSONStringGeneratorInitObject(void) { yajl_gen g; @@ -1126,6 +1136,8 @@ virJSONStringGeneratorPtr virJSONStringGeneratorInitObject(void) * Terminate the object being generated in @gen, and return its string value * (or NULL on error). The value is valid until @gen is freed. */ +/* Don't call any error reporting or logging functions from this function, + the error loging mechanism may use this! */ const char *virJSONStringGeneratorFinishObject(virJSONStringGeneratorPtr gen) { const unsigned char *res; @@ -1148,19 +1160,21 @@ const char *virJSONStringGeneratorFinishObject(virJSONStringGeneratorPtr gen) * Free @gen if it is not NULL. Invalidates the result of * virJSONStringGeneratorFinishObject(). */ +/* Don't call any error reporting or logging functions from this function, + the error loging mechanism may use this! */ void virJSONStringGeneratorFree(virJSONStringGeneratorPtr gen) { if (gen != NULL) yajl_gen_free(gen); } +/* Don't call any error reporting or logging functions from this function, + the error loging mechanism may use this! */ static int virJSONValueToStringOne(virJSONValuePtr object, yajl_gen g) { int i; - VIR_DEBUG("object=%p type=%d gen=%p", object, object->type, g); - switch (object->type) { case VIR_JSON_TYPE_OBJECT: if (yajl_gen_map_open(g) != yajl_gen_status_ok) @@ -1219,6 +1233,8 @@ static int virJSONValueToStringOne(virJSONValuePtr object, * Note that this adds each property into the "current" object, it does not * add a subobject. */ +/* Don't call any error reporting or logging functions from this function, + the error loging mechanism may use this! */ int virJSONStringGeneratorAddProperties(virJSONStringGeneratorPtr gen, virJSONObjectPtr object) { diff --git a/src/util/logging.c b/src/util/logging.c index b71eacc..97431b2 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> @@ -39,12 +40,15 @@ #include "virterror_internal.h" #include "logging.h" #include "memory.h" +#include "json.h" #include "util.h" #include "buf.h" #include "threads.h" #include "virfile.h" #include "virtime.h" +#include "intprops.h" + #define VIR_FROM_THIS VIR_FROM_NONE /* @@ -127,6 +131,8 @@ static const char *virLogOutputString(virLogDestination ldest) { return "syslog"; case VIR_LOG_TO_FILE: return "file"; + case VIR_LOG_TO_SYSLOG_JSON: + return "syslog/json"; } return "unknown"; } @@ -575,7 +581,8 @@ int virLogDefineOutput(virLogOutputFunc f, virLogCloseFunc c, void *data, 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); @@ -897,6 +904,82 @@ static void virLogOutputToSyslog(const char *category 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"; +} + +static void virLogOutputToSyslogJSON(const char *category, int priority, + const char *funcname, long long linenr, + const char *timestamp, + unsigned int flags, + const char *rawstr, const char *str, + void *data ATTRIBUTE_UNUSED) +{ + /* This can't use virJSONValueToString because that function can create log + messages, which would lead to infinite recursion. */ + virJSONStringGeneratorPtr g = NULL; + virJSONObject json; + virJSONObjectPair json_pairs[6]; + virJSONValue json_msg, json_category, json_priority, json_funcname; + virJSONValue json_line, json_timestamp; + char line_buf[INT_BUFSIZE_BOUND(linenr)]; + const char *json_string; + + virCheckFlags(VIR_LOG_STACK_TRACE,); + + /* 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. + + 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). */ + virJSONStaticObjectInitialize(&json, json_pairs); + virJSONStaticObjectAppendString(&json, "msg", &json_msg, rawstr); + virJSONStaticObjectAppendString(&json, "category", &json_category, + category); + virJSONStaticObjectAppendString(&json, "priority", &json_priority, + virLogPriorityJSONString(priority)); + if (funcname != NULL) + virJSONStaticObjectAppendString(&json, "funcname", &json_funcname, + funcname); + virJSONStaticObjectAppendNumberInt(&json, "line", &json_line, + line_buf, sizeof(line_buf), linenr); + virJSONStaticObjectAppendString(&json, "timestamp", &json_timestamp, + timestamp); + + g = virJSONStringGeneratorInitObject(); + if (g == NULL) + goto error; + if (virJSONStringGeneratorAddProperties(g, &json) != 0) + goto error; + json_string = virJSONStringGeneratorFinishObject(g); + if (json_string == NULL) + goto error; + + syslog(virLogPrioritySyslog(priority), "@cee: %s", json_string); + virJSONStringGeneratorFree(g); + return; + + error: + virJSONStringGeneratorFree(g); + virLogOutputToSyslog(category, priority, funcname, linenr, timestamp, flags, + rawstr, str, NULL); +} +#endif + static char *current_ident = NULL; static void virLogCloseSyslog(void *data ATTRIBUTE_UNUSED) { @@ -904,7 +987,17 @@ static void virLogCloseSyslog(void *data ATTRIBUTE_UNUSED) { VIR_FREE(current_ident); } -static int virLogAddOutputToSyslog(int priority, const char *ident) { +static int virLogAddOutputToSyslog(int priority, 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 */ @@ -914,7 +1007,7 @@ static int virLogAddOutputToSyslog(int priority, const char *ident) { 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); @@ -975,7 +1068,16 @@ int 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++; @@ -988,7 +1090,7 @@ int 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 10ff6c9..a66f5dc 100644 --- a/src/util/logging.h +++ b/src/util/logging.h @@ -80,6 +80,7 @@ typedef enum { VIR_LOG_TO_STDERR = 1, VIR_LOG_TO_SYSLOG, VIR_LOG_TO_FILE, + VIR_LOG_TO_SYSLOG_JSON, } virLogDestination; /** -- 1.7.11.4
... and update all users. No change in functionality, the parameter will be used in later patches. Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/uml/uml_conf.c | 2 +- src/util/logging.c | 13 +++++++++---- src/util/logging.h | 17 +++++++++-------- src/util/viraudit.c | 4 ++-- src/util/virterror.c | 2 +- 5 files changed, 22 insertions(+), 16 deletions(-) diff --git a/src/uml/uml_conf.c b/src/uml/uml_conf.c index 410f3e2..6ad7a7b 100644 --- a/src/uml/uml_conf.c +++ b/src/uml/uml_conf.c @@ -53,7 +53,7 @@ #define VIR_FROM_THIS VIR_FROM_UML #define umlLog(level, msg, ...) \ - virLogMessage(__FILE__, level, 0, msg, __VA_ARGS__) + virLogMessage(__FILE__, level, NULL, 0, msg, __VA_ARGS__) static int umlDefaultConsoleType(const char *ostype ATTRIBUTE_UNUSED) diff --git a/src/util/logging.c b/src/util/logging.c index 97431b2..feef711 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -663,6 +663,7 @@ virLogVersionString(const char **rawmsg, char **msg) * @priority: the priority level * @funcname: the function emitting the (debug) message * @linenr: line where the message was emitted + * @properties: additional JSON properties to add to the log object, or NULL * @flags: extra flags, 1 if coming from the error handler * @fmt: the string format * @...: the arguments @@ -671,11 +672,13 @@ virLogVersionString(const char **rawmsg, char **msg) * the message may be stored, sent to output or just discarded */ void virLogMessage(const char *category, int priority, const char *funcname, - long long linenr, unsigned int flags, const char *fmt, ...) + long long linenr, virJSONObjectPtr properties, + unsigned int flags, const char *fmt, ...) { va_list ap; va_start(ap, fmt); - virLogVMessage(category, priority, funcname, linenr, flags, fmt, ap); + virLogVMessage(category, priority, funcname, linenr, properties, flags, fmt, + ap); va_end(ap); } @@ -685,6 +688,7 @@ void virLogMessage(const char *category, int priority, const char *funcname, * @priority: the priority level * @funcname: the function emitting the (debug) message * @linenr: line where the message was emitted + * @properties: additional JSON properties to add to the log object, or NULL * @flags: extra flags, 1 if coming from the error handler * @fmt: the string format * @vargs: format args @@ -693,8 +697,9 @@ void virLogMessage(const char *category, int priority, const char *funcname, * the message may be stored, sent to output or just discarded */ void virLogVMessage(const char *category, int priority, const char *funcname, - long long linenr, unsigned int flags, const char *fmt, - va_list vargs) + long long linenr, + virJSONObjectPtr properties ATTRIBUTE_UNUSED, + unsigned int flags, const char *fmt, va_list vargs) { static bool logVersionStderr = true; char *str = NULL; diff --git a/src/util/logging.h b/src/util/logging.h index a66f5dc..14b7b7c 100644 --- a/src/util/logging.h +++ b/src/util/logging.h @@ -24,6 +24,7 @@ # include "internal.h" # include "buf.h" +# include "json.h" /* * If configured with --enable-debug=yes then library calls @@ -32,7 +33,7 @@ */ # ifdef ENABLE_DEBUG # define VIR_DEBUG_INT(category, f, l, ...) \ - virLogMessage(category, VIR_LOG_DEBUG, f, l, 0, __VA_ARGS__) + virLogMessage(category, VIR_LOG_DEBUG, f, l, NULL, 0, __VA_ARGS__) # else /** * virLogEatParams: @@ -49,11 +50,11 @@ static inline void virLogEatParams(const char *unused, ...) # endif /* !ENABLE_DEBUG */ # define VIR_INFO_INT(category, f, l, ...) \ - virLogMessage(category, VIR_LOG_INFO, f, l, 0, __VA_ARGS__) + virLogMessage(category, VIR_LOG_INFO, f, l, NULL, 0, __VA_ARGS__) # define VIR_WARN_INT(category, f, l, ...) \ - virLogMessage(category, VIR_LOG_WARN, f, l, 0, __VA_ARGS__) + virLogMessage(category, VIR_LOG_WARN, f, l, NULL, 0, __VA_ARGS__) # define VIR_ERROR_INT(category, f, l, ...) \ - virLogMessage(category, VIR_LOG_ERROR, f, l, 0, __VA_ARGS__) + virLogMessage(category, VIR_LOG_ERROR, f, l, NULL, 0, __VA_ARGS__) # define VIR_DEBUG(...) \ VIR_DEBUG_INT("file." __FILE__, __func__, __LINE__, __VA_ARGS__) @@ -141,13 +142,13 @@ extern int virLogParseFilters(const char *filters); extern int virLogParseOutputs(const char *output); extern void virLogMessage(const char *category, int priority, const char *funcname, long long linenr, - unsigned int flags, - const char *fmt, ...) ATTRIBUTE_FMT_PRINTF(6, 7); + virJSONObjectPtr properties, unsigned int flags, + const char *fmt, ...) ATTRIBUTE_FMT_PRINTF(7, 8); extern void virLogVMessage(const char *category, int priority, const char *funcname, long long linenr, - unsigned int flags, + virJSONObjectPtr properties, unsigned int flags, 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 691d2f1..9437155 100644 --- a/src/util/viraudit.c +++ b/src/util/viraudit.c @@ -103,10 +103,10 @@ void virAuditSend(const char *file ATTRIBUTE_UNUSED, const char *func, if (auditlog && str) { if (success) - virLogMessage("audit", VIR_LOG_INFO, func, linenr, 0, + virLogMessage("audit", VIR_LOG_INFO, func, linenr, NULL, 0, "success=yes %s", str); else - virLogMessage("audit", VIR_LOG_WARN, func, linenr, 0, + virLogMessage("audit", VIR_LOG_WARN, func, linenr, NULL, 0, "success=no %s", str); } diff --git a/src/util/virterror.c b/src/util/virterror.c index 7caa69e..f93b9f6 100644 --- a/src/util/virterror.c +++ b/src/util/virterror.c @@ -677,7 +677,7 @@ virRaiseErrorFull(const char *filename ATTRIBUTE_UNUSED, if (virErrorLogPriorityFilter) priority = virErrorLogPriorityFilter(to, priority); virLogMessage(filename, priority, - funcname, linenr, + funcname, linenr, NULL, virErrorLogPriorityFilter ? 0 : 1, "%s", str); -- 1.7.11.4
On Thu, Sep 20, 2012 at 08:24:08PM +0200, Miloslav Trmač wrote:
... and update all users. No change in functionality, the parameter will be used in later patches.
Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/uml/uml_conf.c | 2 +- src/util/logging.c | 13 +++++++++---- src/util/logging.h | 17 +++++++++-------- src/util/viraudit.c | 4 ++-- src/util/virterror.c | 2 +- 5 files changed, 22 insertions(+), 16 deletions(-)
diff --git a/src/util/logging.h b/src/util/logging.h index a66f5dc..14b7b7c 100644 --- a/src/util/logging.h +++ b/src/util/logging.h @@ -141,13 +142,13 @@ extern int virLogParseFilters(const char *filters); extern int virLogParseOutputs(const char *output); extern void virLogMessage(const char *category, int priority, const char *funcname, long long linenr, - unsigned int flags, - const char *fmt, ...) ATTRIBUTE_FMT_PRINTF(6, 7); + virJSONObjectPtr properties, unsigned int flags, + const char *fmt, ...) ATTRIBUTE_FMT_PRINTF(7, 8); extern void virLogVMessage(const char *category, int priority, const char *funcname, long long linenr, - unsigned int flags, + virJSONObjectPtr properties, unsigned int flags, 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
Definite NACK to this change, since it is exposing the impl details of the Lumberjack log output function to all users of the libvirt logging API, not to mention the general unpleasant usability aspects of having to build up JSON objects simply to pass a few extra metadata fields. I'm all for allowing more metadata properties to be passed into the logging functions, but we need a simpler API along the lines of the systemd journal sd_journal_send() style which allows for a set of key=value pairs to be passed in. I'd not try to shoe-horn it into the existing virLogMessage() APIs. In the same way that there is sd_journal_print() for simple string messages, vis sd_journal_send() for arbitrary key=value pair log messages, I'd create a new API for this called virLogMetadata and virLogVMetadata. eg to allow sending a message with an error no virLogMetadata(__FILE__, VIR_LOG_WARN, __FUNC__, __LINE__, 0, "MESSAGE=Unable to open file %s: %s", "/some/file", strerror(errno), "ERRNO=%d", errno, NULL); 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 :|
Thanks for the review. ----- Original Message -----
On Thu, Sep 20, 2012 at 08:24:08PM +0200, Miloslav Trmač wrote:
... and update all users. No change in functionality, the parameter will be used in later patches.
diff --git a/src/util/logging.h b/src/util/logging.h index a66f5dc..14b7b7c 100644 --- a/src/util/logging.h +++ b/src/util/logging.h @@ -141,13 +142,13 @@ extern int virLogParseFilters(const char *filters); extern int virLogParseOutputs(const char *output); extern void virLogMessage(const char *category, int priority, const char *funcname, long long linenr, - unsigned int flags, - const char *fmt, ...) ATTRIBUTE_FMT_PRINTF(6, 7); + virJSONObjectPtr properties, unsigned int flags, + const char *fmt, ...)
Definite NACK to this change, since it is exposing the impl details of the Lumberjack log output function to all users of the libvirt logging API, not to mention the general unpleasant usability aspects of having to build up JSON objects simply to pass a few extra metadata fields.
I didn't think adding an abstraction for a single user was worth it, but you're right, the result did end up rather uglier than I expected.
I'm all for allowing more metadata properties to be passed into the logging functions, but we need a simpler API along the lines of the systemd journal sd_journal_send() style which allows for a set of key=value pairs to be passed in. I'd not try to shoe-horn it into the existing virLogMessage() APIs. In the same way that there is sd_journal_print() for simple string messages, vis sd_journal_send() for arbitrary key=value pair log messages, I'd create a new API for this called virLogMetadata and virLogVMetadata. eg to allow sending a message with an error no
virLogMetadata(__FILE__, VIR_LOG_WARN, __FUNC__, __LINE__, 0, "MESSAGE=Unable to open file %s: %s", "/some/file", strerror(errno), "ERRNO=%d", errno, NULL);
I'm afraid this is not possible to implement portably and reliably without reimplementing 50% of sprintf(), especially in the presence of translations and the associated %5$s formats.[1][2] One problem with the above is that it is possible to send a log event without the MESSAGE field, which would leave non-structured formats with nothing to log. I can see three options: 1) as proposed above, silently failing if the MESSAGE field is missing (or if there is a typo in the field name); with type fields added to represent JSON integers as integers. 2) MESSAGE is mandatory, everything pre-formatted virAsprintf(&msg, "Unable to open file %s: %s", "/some/file", strerror(errno)); virLogMetadata(... __LINE__, msg, "ERRNO", VIR_LOG_INT, errno, NULL) 3) MESSAGE is printf-like, everything else in an array. struct virLogMetadata meta[2] = { { "ERRNO", VIR_LOG_INT, .i = errno }, { NULL, } }; virLogMetadata(... __LINE__, meta, "Unable to open file %s: %s", "/some/file", strerror(errno)); or equivalently: virLogMetadata(... __LINE__, &(struct virLogMetadata []) { { "ERRNO", VIR_LOG_INT, .i = errno }, { NULL, } }, "Unable to open file %s: %s", "/some/file", strerror(errno)); which could be hidden by macros: virLogMetadata(VIR_LOG_INT("ERRNO", errno"), VIR_LOG_END, "Unable to open file %s: %s", "/some/file", strerror(errno)); Do you have any preference? I'm leaning towards the first variant of 3) for now, we can add fancy macros later when/if more callers of virLogMetadata are added. Thanks again, Mirek [1] The unportable way to do this is to use parse_printf_format() from glibc. [2] The logging API could implement only a subset of the printf formats, but it would be rather difficult to notice if a newly added caller used an unsupported format a few years later, especially when translators can use different formats than the original string.
... 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 | 20 +++++++++++--------- src/util/logging.h | 2 ++ tests/testutils.c | 1 + 3 files changed, 14 insertions(+), 9 deletions(-) diff --git a/src/util/logging.c b/src/util/logging.c index feef711..987dffc 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -104,7 +104,7 @@ static int virLogResetFilters(void); static int virLogResetOutputs(void); static void virLogOutputToFd(const char *category, int priority, const char *funcname, long long linenr, - const char *timestamp, + const char *timestamp, virJSONObjectPtr properties, unsigned int flags, const char *rawstr, const char *str, void *data); @@ -697,8 +697,7 @@ void virLogMessage(const char *category, int priority, const char *funcname, * the message may be stored, sent to output or just discarded */ void virLogVMessage(const char *category, int priority, const char *funcname, - long long linenr, - virJSONObjectPtr properties ATTRIBUTE_UNUSED, + long long linenr, virJSONObjectPtr properties, unsigned int flags, const char *fmt, va_list vargs) { static bool logVersionStderr = true; @@ -768,13 +767,13 @@ void virLogVMessage(const char *category, int priority, const char *funcname, if (virLogVersionString(&rawver, &ver) >= 0) virLogOutputs[i].f(category, VIR_LOG_INFO, __func__, __LINE__, - timestamp, 0, rawver, ver, + timestamp, NULL, 0, rawver, ver, virLogOutputs[i].data); VIR_FREE(ver); virLogOutputs[i].logVersion = false; } virLogOutputs[i].f(category, priority, funcname, linenr, - timestamp, filterflags, + timestamp, properties, filterflags, str, msg, virLogOutputs[i].data); } } @@ -785,13 +784,13 @@ void virLogVMessage(const char *category, int priority, const char *funcname, if (virLogVersionString(&rawver, &ver) >= 0) virLogOutputToFd(category, VIR_LOG_INFO, __func__, __LINE__, - timestamp, 0, rawver, ver, + timestamp, NULL, 0, rawver, ver, (void *) STDERR_FILENO); VIR_FREE(ver); logVersionStderr = false; } virLogOutputToFd(category, priority, funcname, linenr, - timestamp, filterflags, + timestamp, properties, filterflags, str, msg, (void *) STDERR_FILENO); } virLogUnlock(); @@ -827,6 +826,7 @@ static void virLogOutputToFd(const char *category ATTRIBUTE_UNUSED, const char *funcname ATTRIBUTE_UNUSED, long long linenr ATTRIBUTE_UNUSED, const char *timestamp, + virJSONObjectPtr properties ATTRIBUTE_UNUSED, unsigned int flags, const char *rawstr ATTRIBUTE_UNUSED, const char *str, @@ -899,6 +899,7 @@ static void virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED, const char *funcname ATTRIBUTE_UNUSED, long long linenr ATTRIBUTE_UNUSED, const char *timestamp ATTRIBUTE_UNUSED, + virJSONObjectPtr properties ATTRIBUTE_UNUSED, unsigned int flags, const char *rawstr ATTRIBUTE_UNUSED, const char *str, @@ -928,6 +929,7 @@ static const char *virLogPriorityJSONString(virLogPriority lvl) { static void virLogOutputToSyslogJSON(const char *category, int priority, const char *funcname, long long linenr, const char *timestamp, + virJSONObjectPtr properties, unsigned int flags, const char *rawstr, const char *str, void *data ATTRIBUTE_UNUSED) @@ -980,8 +982,8 @@ static void virLogOutputToSyslogJSON(const char *category, int priority, error: virJSONStringGeneratorFree(g); - virLogOutputToSyslog(category, priority, funcname, linenr, timestamp, flags, - rawstr, str, NULL); + virLogOutputToSyslog(category, priority, funcname, linenr, timestamp, + properties, flags, rawstr, str, NULL); } #endif diff --git a/src/util/logging.h b/src/util/logging.h index 14b7b7c..c1431ec 100644 --- a/src/util/logging.h +++ b/src/util/logging.h @@ -90,6 +90,7 @@ typedef enum { * @priority: the priority for the message * @funcname: the function emitting the message * @linenr: line where the message was emitted + * @properties: additional JSON properties to add to the log object, or NULL * @timestamp: zero terminated string with timestamp of the message * @flags: flags associated with the message * @rawstr: the unformatted message to log, zero terminated @@ -101,6 +102,7 @@ typedef enum { typedef void (*virLogOutputFunc) (const char *category, int priority, const char *funcname, long long linenr, const char *timestamp, + virJSONObjectPtr properties, unsigned int flags, const char *rawstr, const char *str, void *data); diff --git a/tests/testutils.c b/tests/testutils.c index 6978020..abd8424 100644 --- a/tests/testutils.c +++ b/tests/testutils.c @@ -484,6 +484,7 @@ virtTestLogOutput(const char *category ATTRIBUTE_UNUSED, const char *funcname ATTRIBUTE_UNUSED, long long lineno ATTRIBUTE_UNUSED, const char *timestamp, + virJSONObjectPtr properties ATTRIBUTE_UNUSED, unsigned int flags, const char *rawstr ATTRIBUTE_UNUSED, const char *str, -- 1.7.11.4
When logging an error, don't throw away the detailed information. Example record when using the syslog/json output (line-wrapped for readability): Sep 18 17:03:24 kulicka libvirt: @cee: {"msg":"Domain not found", "category":"../../src/test/test_driver.c","priority":"err", "funcname":"testLookupDomainByName","line":1405, "timestamp":"2012-09-18 15:03:24.314+0000","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 JSON object is again allocated on the stack to avoid the risk of allocations falling, and for similarity with virLogOutputToSyslogJSON(). Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/util/logging.c | 3 +++ src/util/virterror.c | 32 +++++++++++++++++++++++++++++--- 2 files changed, 32 insertions(+), 3 deletions(-) diff --git a/src/util/logging.c b/src/util/logging.c index 987dffc..642d410 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -972,6 +972,9 @@ static void virLogOutputToSyslogJSON(const char *category, int priority, goto error; if (virJSONStringGeneratorAddProperties(g, &json) != 0) goto error; + if (properties != NULL + && virJSONStringGeneratorAddProperties(g, properties) != 0) + goto error; json_string = virJSONStringGeneratorFinishObject(g); if (json_string == NULL) goto error; diff --git a/src/util/virterror.c b/src/util/virterror.c index f93b9f6..9fb60e3 100644 --- a/src/util/virterror.c +++ b/src/util/virterror.c @@ -32,8 +32,11 @@ #include "logging.h" #include "memory.h" #include "threads.h" +#include "json.h" #include "util.h" +#include "intprops.h" + virThreadLocal virLastErr; virErrorFunc virErrorHandler = NULL; /* global error handler */ @@ -579,8 +582,6 @@ virDispatchError(virConnectPtr conn) } } - - /** * virRaiseErrorFull: * @filename: filename where error was raised @@ -614,6 +615,14 @@ virRaiseErrorFull(const char *filename ATTRIBUTE_UNUSED, int int2, const char *fmt, ...) { + virJSONObject json; + virJSONObjectPair json_pairs[7]; + virJSONValue json_domain, json_code, json_str1, json_str2, json_str3; + virJSONValue json_int1, json_int2; + char domain_buf[INT_BUFSIZE_BOUND(domain)]; + char code_buf[INT_BUFSIZE_BOUND(code)]; + char int1_buf[INT_BUFSIZE_BOUND(int1)]; + char int2_buf[INT_BUFSIZE_BOUND(int2)]; int save_errno = errno; virErrorPtr to; char *str; @@ -676,8 +685,25 @@ virRaiseErrorFull(const char *filename ATTRIBUTE_UNUSED, priority = virErrorLevelPriority(level); if (virErrorLogPriorityFilter) priority = virErrorLogPriorityFilter(to, priority); + virJSONStaticObjectInitialize (&json, json_pairs); + virJSONStaticObjectAppendNumberInt(&json, "domain", &json_domain, + domain_buf, sizeof(domain_buf), domain); + virJSONStaticObjectAppendNumberInt(&json, "code", &json_code, + code_buf, sizeof(code_buf), code); + if (str1 != NULL) + virJSONStaticObjectAppendString(&json, "str1", &json_str1, str1); + if (str1 != NULL) + virJSONStaticObjectAppendString(&json, "str2", &json_str2, str2); + if (str3 != NULL) + virJSONStaticObjectAppendString(&json, "str3", &json_str3, str3); + if (int1 != -1) + virJSONStaticObjectAppendNumberInt(&json, "int1", &json_int1, + int1_buf, sizeof(int1_buf), int1); + if (int2 != -1) + virJSONStaticObjectAppendNumberInt(&json, "int2", &json_int2, + int2_buf, sizeof(int2_buf), int2); virLogMessage(filename, priority, - funcname, linenr, NULL, + funcname, linenr, &json, virErrorLogPriorityFilter ? 0 : 1, "%s", str); -- 1.7.11.4
Signed-off-by: Miloslav Trmač <mitr@redhat.com> --- src/libvirt_private.syms | 4 + tests/Makefile.am | 6 +- tests/errorjsontest.c | 211 +++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 220 insertions(+), 1 deletion(-) create mode 100644 tests/errorjsontest.c diff --git a/src/libvirt_private.syms b/src/libvirt_private.syms index 0b6068d..1f24de2 100644 --- a/src/libvirt_private.syms +++ b/src/libvirt_private.syms @@ -704,6 +704,10 @@ iptablesRemoveUdpInput; # json.h +virJSONStringGeneratorAddProperties; +virJSONStringGeneratorFinishObject; +virJSONStringGeneratorFree; +virJSONStringGeneratorInitObject; virJSONValueArrayAppend; virJSONValueArrayGet; virJSONValueArraySize; diff --git a/tests/Makefile.am b/tests/Makefile.am index 8dbad97..a46502b 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -138,7 +138,7 @@ test_programs += object-locking endif if HAVE_YAJL -test_programs += jsontest +test_programs += jsontest errorjsontest endif test_programs += networkxml2xmltest @@ -598,6 +598,10 @@ jsontest_SOURCES = \ jsontest.c testutils.h testutils.c jsontest_LDADD = $(LDADDS) +errorjsontest_SOURCES = \ + errorjsontest.c testutils.h testutils.c +errorjsontest_LDADD = $(LDADDS) + utiltest_SOURCES = \ utiltest.c testutils.h testutils.c utiltest_LDADD = $(LDADDS) diff --git a/tests/errorjsontest.c b/tests/errorjsontest.c new file mode 100644 index 0000000..491306b --- /dev/null +++ b/tests/errorjsontest.c @@ -0,0 +1,211 @@ +#include <config.h> + +#include <stdio.h> +#include <stdlib.h> +#include <string.h> + +#include "internal.h" +#include "json.h" +#include "logging.h" +#include "testutils.h" +#include "virterror_internal.h" + +#define VIR_FROM_THIS VIR_FROM_NONE + +/* Ideally we should test the syslog/json output, this tests only the inputs to + the logging function. */ + +struct lastMessage +{ + int priority; + char *properties; +}; + +static void +lmReset(struct lastMessage *lm) +{ + lm->priority = -1; + VIR_FREE(lm->properties); +} + +static void +logOutputToLM(const char *category ATTRIBUTE_UNUSED, int priority, + const char *funcname ATTRIBUTE_UNUSED, + long long linenr ATTRIBUTE_UNUSED, + const char *timestamp ATTRIBUTE_UNUSED, + virJSONObjectPtr properties, unsigned int flags, + const char *rawstr ATTRIBUTE_UNUSED, + const char *str ATTRIBUTE_UNUSED, void *data) +{ + struct lastMessage *lm; + virJSONStringGeneratorPtr g = NULL; + const char *json_string; + + virCheckFlags(VIR_LOG_STACK_TRACE,); + + lm = data; + lmReset(lm); + /* category (== file name) is not expected to be stable */ + lm->priority = priority; + /* funcname, linenr, timestamp, rawstr, str are not expected to be stable */ + + g = virJSONStringGeneratorInitObject(); + if (g == NULL) + goto cleanup; + if (properties != NULL + && virJSONStringGeneratorAddProperties(g, properties) != 0) + goto cleanup; + json_string = strdup(virJSONStringGeneratorFinishObject(g)); + if (json_string == NULL) + goto cleanup; + lm->properties = strdup(json_string); + cleanup: + virJSONStringGeneratorFree(g); +} + +static int +testBasicMessage(const void *data) +{ + struct lastMessage *lm; + virConnectPtr conn = NULL; + virDomainPtr dom = NULL; + int ret = -1; + + lm = (struct lastMessage *)data; + conn = virConnectOpen("test:///default"); + if (conn == NULL) { + if (virTestGetVerbose()) + fprintf(stderr, "Could not connect to test URI\n"); + goto cleanup; + } + + dom = virDomainLookupByName(conn, "this_doesnt_exist"); + if (dom != NULL) { + if (virTestGetVerbose()) + fprintf(stderr, + "Should not have connected to nonexistent domain\n"); + goto cleanup; + } + + if (lm->priority != VIR_LOG_ERROR) { + if (virTestGetVerbose()) + fprintf(stderr, "Unexpected priority\n"); + goto cleanup; + } + + ret = 0; + + cleanup: + if (dom != NULL) + virDomainFree(dom); + if (conn != NULL) + virConnectClose(conn); + return ret; +} + +static int +testJSONError(const void *data) +{ + struct lastMessage *lm; + virConnectPtr conn = NULL; + virDomainPtr dom = NULL; + virJSONValuePtr json = NULL; + int ret = -1, val; + + lm = (struct lastMessage *)data; + conn = virConnectOpen("test:///default"); + if (conn == NULL) { + if (virTestGetVerbose()) + fprintf(stderr, "Could not connect to test URI\n"); + goto cleanup; + } + + dom = virDomainLookupByName(conn, "this_doesnt_exist"); + if (dom != NULL) { + if (virTestGetVerbose()) + fprintf(stderr, + "Should not have connected to nonexistent domain\n"); + goto cleanup; + } + + if (lm->properties == NULL) { + if (virTestGetVerbose()) + fprintf(stderr, "Properties missing\n"); + goto cleanup; + } + json = virJSONValueFromString(lm->properties); + if (json == NULL) { + if (virTestGetVerbose()) + fprintf(stderr, "Error parsing properties\n"); + goto cleanup; + } + if (json->type != VIR_JSON_TYPE_OBJECT) { + if (virTestGetVerbose()) + /* logOutputToLM did create an object for us */ + fprintf(stderr, "Didn't get an object?!\n"); + goto cleanup; + } + + if (virJSONValueObjectGetNumberInt(json, "domain", &val) != 0) { + if (virTestGetVerbose()) + fprintf(stderr, "\"domain\" missing\n"); + goto cleanup; + } + if (val != VIR_FROM_TEST) { + if (virTestGetVerbose()) + fprintf(stderr, "Unexpected domain %d (wanted %d)\n", val, + VIR_FROM_TEST); + goto cleanup; + } + + if (virJSONValueObjectGetNumberInt(json, "code", &val) != 0) { + if (virTestGetVerbose()) + fprintf(stderr, "\"code\" missing\n"); + goto cleanup; + } + if (val != VIR_ERR_NO_DOMAIN) { + if (virTestGetVerbose()) + fprintf(stderr, "Unexpected code %d (wanted %d)\n", val, + VIR_ERR_NO_DOMAIN); + goto cleanup; + } + + ret = 0; + + cleanup: + virJSONValueFree(json); + if (dom != NULL) + virDomainFree(dom); + if (conn != NULL) + virConnectClose(conn); + return ret; +} + +static void +testQuietError(void *userData ATTRIBUTE_UNUSED, + virErrorPtr error ATTRIBUTE_UNUSED) +{ + /* nothing */ +} + +static int +mymain(void) +{ + struct lastMessage lm; + int ret = 0; + + memset(&lm, 0, sizeof(lm)); + if (virLogReset() < 0) + return EXIT_FAILURE; + if (virLogDefineOutput(logOutputToLM, NULL, &lm, 0, 0, NULL, 0) < 0) + return EXIT_FAILURE; + virSetErrorFunc(NULL, testQuietError); + if (virtTestRun("Basic message details", 1, testBasicMessage, &lm) != 0) + ret = -1; + if (virtTestRun("JSON error details", 1, testJSONError, &lm) != 0) + ret = -1; + lmReset(&lm); + return (ret == 0) ? EXIT_SUCCESS : EXIT_FAILURE; +} + +VIRT_TEST_MAIN(mymain) -- 1.7.11.4
On Thu, Sep 20, 2012 at 08:23:59PM +0200, Miloslav Trmač wrote:
This patch set adds structured syslog support to libvirt.
In short, the idea is to embed JSON in a syslog record. This format is used in a new log output type called "syslog/json".
Example "syslog/json" record (line-wrapped for readability):
Sep 20 19:59:40 kulicka libvirt: @cee: {"msg":"libvirt version: 0.10.1", "category":"../../src/test/test_driver.c","priority":"info", "funcname":"virLogVMessage","line":769, "timestamp":"2012-09-20 17:59:40.853+0000"}
compared with existing "syslog" record format:
Sep 20 20:02:24 kulicka libvirt: 5896: info : libvirt version: 0.10.1
This JSON embedding format is defined by the Lumberjack project led by the major Open Source syslog implementations (https://fedorahosted.org/lumberjack/). The format is also a base for a future MITRE CEE standard. Some of the fields are specified at https://fedorahosted.org/lumberjack/wiki/FieldList , but applications are free to use whatever fields make sense for them.
The JSON structure makes easy to process logs by programs without writing code that understands the specific format used by each application, or using unreliable regexps (https://fedorahosted.org/ceelog/ is a companion project that allows processing such logs).
Current systems will store and these records unmodified and present them to users unmodified, but tools (and probably /var/log/messages) will be able to show only the "msg" field; this allows us to add more detailed information without worsening the user experience (the example above already shows added information that is currently being thrown away when logging to syslog).
While I agree with the effort to try to standardize on metadata to be collected with log messages, I can't say I like the Lumberjack design, or this proposed usage in libvirt. First it is not possible for libvirt to detect whether messages it sends to syslog() are going to be processed by a syslog daemon which actually understands the JSON format. This means we can't turn on use of this JSON format automatically, without causing all existing distros to get their logs filled with JSON data. I also don't like the use of JSON for this purpose in the first place. Application logging facilities really need to be simple, reliable, and safe to use in any context. For example in between a fork() and execve() where POSIX requires only use of async signal safe functions. Now I know that technically speaking syslog() itself is not async signal safe in general, but the way libvirt uses it for logging makes it safe(ish) in our case. We can not, however, imagine that JSON (or really any general JSON library) is going to be async signal safe. Note, I don't care what data format is used server side for storing the logs - if syslogd wants to use JSON format, that's fine. Pushing this format into client applications is what I dislike. I can see the appeal of JSON in that it allows applications to send arbitrarily complex nested data structures into the logs, but that kind of generality for what is IMHO niche usage, really compromises the common case. What makes it worse is that the standard field list quoted above actually demonstrates that you don't actually even need the nesting in many cases, because it shows use of {"user!name":"bob"} as an alternative to {"user":{"name":"bob"}} This patch series goes to great lengths to introduce a whole series of new JSON APIs in libvirt, to avoid memory allocation from the heap, but this work is negated by the fact that the YAJL APIs used at the end all allocate from the heap anyway. Finally alot of the metadata items listed in the "standard fields" doc above would be better filled in by the server (from SCM_RIGHTS), than the client, so that the server can prevent an application from lying about its uid/gid/pid etc. By way of comparison the systemd journal APIs deal with all theses issues. The actual journald client side logging API is possible to implement and use without doing any memory allocation at all, in a completely async signal safe manner, using only socket() + sendmsg() with a stack allocated iovec[] for storing individual metadata fields to be sent. The API is soooo simple to use too, for example, a traditional syslog() call, can be replaced with something like: sd_journal_send("MESSAGE=%s", str, "PRIORITY=%d", prio, "CODE_LINE=%lld", linenr, "CODE_FUNC=%s", funcname, ...arbirary other key=value metadata... NULL); The journald communication uses a new UNIX socket, so apps can automatically determine whether journald is available and if not, fallback to plain syslog for old systems. It uses SCM_RIGHTS to automatically fill in a number of key fields in an unspoofable way. The way the data is transferred using sendmsg + iovec means there is no need for client applications to do any kind of magic escaping of special characters in strings. The journald log processing tools can easily output the log data in many different formats, including JSON, without the apps having to get involved in dealing with JSON themselves. As I mentioned right at the start, I think it is good to have structured standardized metadata associated with log messages. I just don't think that the way applications/libraries like libvirt are being asked to implement this is a good idea. It would be entirely practical for rsyslog or syslog-ng to provide a client/daemon protocol (+library) that worked in exactly the same way systemd's journal protocol (+library) do, and then turn the received raw data into their preferred JSON format on the server. FYI, I already have a local patch which adds support for journald to libvirt logging which I am yet to submit, but is so much simpler than this lumberjack support. 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, Thanks for the review, and I'm sorry about the late response. ----- Original Message -----
While I agree with the effort to try to standardize on metadata to be collected with log messages, I can't say I like the Lumberjack design, or this proposed usage in libvirt.
First it is not possible for libvirt to detect whether messages it sends to syslog() are going to be processed by a syslog daemon which actually understands the JSON format. This means we can't turn on use of this JSON format automatically, without causing all existing distros to get their logs filled with JSON data.
True, but that's an inevitable consequence of being compatible with the syslog protocol.[1] Yes, it does make the question of a default awkward. However, considering that journal has been switched on by default, and MESSAGE= of everything sent to journal goes to syslog, is there still a chance of enabling a syslog output by default at the same time? Doing so would cause each message to appear in syslog twice on systems that have journald.
I also don't like the use of JSON for this purpose in the first place. I'm afraid this is not really open to a change, however I'll try to explain why I don't see JSON as a problem.
Application logging facilities really need to be simple, reliable, and safe to use in any context. For example in between a fork() and execve() where POSIX requires only use of async signal safe functions. Now I know that technically speaking syslog() itself is not async signal safe in general, but the way libvirt uses it for logging makes it safe(ish) in our case. We can not, however, imagine that JSON (or really any general JSON library) is going to be async signal safe.
You can also view JSON syntax as a sequence of (fixed field identifier string, field value with some characters escaped) pairs, which is pretty much the minimum standard for _any_ representation of data in a text format. Choosing JSON was just simpler than trying to committee-invent something new.[2] The journal protocol has a similarly inconvenient case of handling \n - it's only not as noticeable because there are fewer characters to escape, and \n is rarer. Re: async-signal-safe use: Yes, using a JSON library is more convenient and generally preferred to writing a yet another JSON encoder, and yes, a typical JSON library will not be async-signal-safe. However, applications are not required to use all JSON facilities. An application that wants to log a static string between fork() and execve() can just as easily log a static JSON string. If the multi-threaded application wanted to log something dynamic at that inconvenient time, the application author would have to write string formatting code manually in any case (sprintf() is also not async signal safe) - and I don't think JSON escaping is really difficult. Sure, it is more difficult than no escaping, but there needs to be _some_ escaping if we want to keep the existing syslog transport. Regarding libvirt specifically, virLogVMessage is rather far from async-signal-safe (e.g. virVasprintf(), virLogLock()), so this doesn't seem to be a concern for libvirt.
This patch series goes to great lengths to introduce a whole series of new JSON APIs in libvirt, to avoid memory allocation from the heap, but this work is negated by the fact that the YAJL APIs used at the end all allocate from the heap anyway.
The major problem here was not memory allocation itself (as noted above, other parts of the log path allocate memory), but possible recursion through virReportOOMError() -> virLogMessage() and deadlock on virLogMutex. Alocating data on the stack is primarily a way to avoid OOM, not signal safety. In retrospect, the virJSON* data structure is unnecessarily complex for the simple list of key-type-value triples that libvirt actually needs for logging, making the code rather more complex than necessary. I'll replace that, see the other reply.
Finally alot of the metadata items listed in the "standard fields" doc above would be better filled in by the server (from SCM_RIGHTS), than the client, so that the server can prevent an application from lying about its uid/gid/pid etc.
rsyslog does add these fields automatically, and the patch set does not add them manually. This is a bug in the FieldList wiki page, I'll get it fixed.
By way of comparison the systemd journal APIs deal with all theses issues.
The actual journald client side logging API is possible to implement and use without doing any memory allocation at all,
virLogOutputToJournald can be implemented like that, but not the libsystemd-journal API: you'll find a fairly liberal use of alloca() in journal-send.c. If alloca() is allowed, a JSON formatting API can be implemented without "memory allocation" as well.
in a completely async signal safe manner, using only socket() + sendmsg() with a stack allocated iovec[] for storing individual metadata fields to be sent.
Looking at how libvirt currently sends journal data, is the /run/systemd/journal/socket protocol a stable ABI? I can't find anything documenting it within the systemd git tree, and it is not mentioned at http://www.freedesktop.org/wiki/Software/systemd/InterfaceStabilityPromise .
The API is soooo simple to use too, for example, a traditional syslog() call, can be replaced with something like:
sd_journal_send("MESSAGE=%s", str, "PRIORITY=%d", prio, "CODE_LINE=%lld", linenr, "CODE_FUNC=%s", funcname, ...arbirary other key=value metadata... NULL);
There actually is a library (libumberlog) providing just such a simple API. A corresponding call is
ul_syslog(prio, str, "code_line", "%s", service, "code_func", "%s", auth_method, ... arbitrary other metadata... NULL);
However, I thought that libvirt would prefer not adding yet another dependency, especially when the extensions for virRaiseErrorFull require a per-field data structure in any case.[3] Mirek [1] Whether JSON is desired or not also ultimately depends on the final recipient of the data, not on the system that generates it - an "old" system could generate JSON that will be forwarded to a log aggregation server. [2] Especially because the major syslog implementations already supported the JSON format for other reasons. [3] And, to be honest, the library does not nicely support the case of virRaiseErrorFull adding more data. It would be possible, but ugly - we'll make it easier in the future.
On Mon, Oct 08, 2012 at 02:44:04PM -0400, Miloslav Trmac wrote:
Hello, Thanks for the review, and I'm sorry about the late response.
----- Original Message -----
While I agree with the effort to try to standardize on metadata to be collected with log messages, I can't say I like the Lumberjack design, or this proposed usage in libvirt.
First it is not possible for libvirt to detect whether messages it sends to syslog() are going to be processed by a syslog daemon which actually understands the JSON format. This means we can't turn on use of this JSON format automatically, without causing all existing distros to get their logs filled with JSON data.
True, but that's an inevitable consequence of being compatible with the syslog protocol.[1]
IMHO this is the first of many design flaws in - given that you have to write all this new code in applications to support the structured logging, and ideally want new syslog server to get tools to process the data, it would have been easy to also define a new protocol to send the data, isntead of trying to hang onto the syslog() API call or protocol.
Yes, it does make the question of a default awkward. However, considering that journal has been switched on by default, and MESSAGE= of everything sent to journal goes to syslog, is there still a chance of enabling a syslog output by default at the same time? Doing so would cause each message to appear in syslog twice on systems that have journald.
Given systemd's fast adoption across a wide range of Linux distros, in particular the enterprise distros from Red Hat & SUSE, we're going to have journald support in places where structured logging really matters, likely expanding to all Linux distros in a reasonably short period. As such I don't really have a desire to also support Lumberjack format in libvirt natively. IMHO, system services should just log to journald and either journald can forward plain messages to syslog, or a tool can be created which pulls structured log data out of the journal and formats it in Lumberjack format.
I also don't like the use of JSON for this purpose in the first place.
I'm afraid this is not really open to a change, however I'll try to explain why I don't see JSON as a problem.
Application logging facilities really need to be simple, reliable, and safe to use in any context. For example in between a fork() and execve() where POSIX requires only use of async signal safe functions. Now I know that technically speaking syslog() itself is not async signal safe in general, but the way libvirt uses it for logging makes it safe(ish) in our case. We can not, however, imagine that JSON (or really any general JSON library) is going to be async signal safe.
You can also view JSON syntax as a sequence of (fixed field identifier string, field value with some characters escaped) pairs, which is pretty much the minimum standard for _any_ representation of data in a text format. Choosing JSON was just simpler than trying to committee-invent something new.[2]
The journal protocol has a similarly inconvenient case of handling \n it's only not as noticeable because there are fewer characters to escape, and \n is rarer.
Actually the difference is more significant than that. While, \n is special, you do not actually have todo any escaping of the \n when sending the data to the journald. The wire protocol has special handling where you just specify the length of the string to be sent, and any newlines in it will be ignored for the purposes of identifying structured field boundaries. Not having todo any escaping in this way is very good because it means you do not need to further copy the data to be logged - you can just fill out the iovec structs in the write way and get zero-copy logging.
Re: async-signal-safe use: Yes, using a JSON library is more convenien and generally preferred to writing a yet another JSON encoder, and yes, a typical JSON library will not be async-signal-safe. However, applications are not required to use all JSON facilities. An application that wants to log a static string between fork() and execve() can just as easily log a static JSON string.
I don't really see logging preformatted static JSON strings as a satisfactory approach, especially when compared to the way you can use journald.
Regarding libvirt specifically, virLogVMessage is rather far from async-signal-safe (e.g. virVasprintf(), virLogLock()), so this doesn't seem to be a concern for libvirt.
It actually *is* very much a concern for libvirt. The virLogLock() is in fact designed so that we can safely use it in between fork+exec(). ALl our code which runs external programs uses our virCommand/virRun wrappers which synchronize on the logging mutex, so we can avoid the deadlock issues with mutexes here. Before we did this we did indeed have problems with deadlocks in our logging code. We also have also hit problems with the locatime() function not being async signal safe, so we had to re-write our log message formatting code to avoid using gmtime/localtime, to avoid deadlocks. While there are some functions still used which are not technically async signal safe, this does not mean we don't care. In practice the reason by asprintf() and friends are not declared safe by POSIX is that they can malloc() and malloc() is not declared safe. We are however fortunate that GLibc's malloc is safe. We do still, however, have a goal to eliminate use of these unsafe functions in the future, but it is not immediately pressing. We certainly do *not* want to introduce new code that causes us further complication in this area.
By way of comparison the systemd journal APIs deal with all theses issues.
The actual journald client side logging API is possible to implement and use without doing any memory allocation at all,
virLogOutputToJournald can be implemented like that, but not the libsystemd-journal API: you'll find a fairly liberal use of alloca() in journal-send.c. If alloca() is allowed, a JSON formatting API can be implemented without "memory allocation" as well.
Yes, that is one of the reasons I ended up writing to the journald protocol directly. While the current APIs in libsystemd-journal do require alloca(), it would actually be possible to make add some functions which avoided this need. This is something I intend to pursue with systemd devs when I have more free time.
in a completely async signal safe manner, using only socket() + sendmsg() with a stack allocated iovec[] for storing individual metadata fields to be sent.
Looking at how libvirt currently sends journal data, is the /run/systemd/journal/socket protocol a stable ABI? I can't find anything documenting it within the systemd git tree, and it is not mentioned at http://www.freedesktop.org/wiki/Software/systemd/InterfaceStabilityPromise .
Hmm, that's a good point actually, I must confirm that.
The API is soooo simple to use too, for example, a traditional syslog() call, can be replaced with something like:
sd_journal_send("MESSAGE=%s", str, "PRIORITY=%d", prio, "CODE_LINE=%lld", linenr, "CODE_FUNC=%s", funcname, ...arbirary other key=value metadata... NULL);
There actually is a library (libumberlog) providing just such a simple API. A corresponding call is
ul_syslog(prio, str, "code_line", "%s", service, "code_func", "%s", auth_method, ... arbitrary other metadata... NULL);
However, I thought that libvirt would prefer not adding yet another dependency, especially when the extensions for virRaiseErrorFull require a per-field data structure in any case.[3]
Mostly I'd want to avoid external libraries here due to the async signal safety issues. 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 :|
----- Original Message -----
Given systemd's fast adoption across a wide range of Linux distros, in particular the enterprise distros from Red Hat & SUSE, we're going to have journald support in places where structured logging really matters, likely expanding to all Linux distros in a reasonably short period. As such I don't really have a desire to also support Lumberjack format in libvirt natively. IMHO, system services should just log to journald and either journald can forward plain messages to syslog, or a tool can be created which pulls structured log data out of the journal and formats it in Lumberjack format.
I can live with that; however the libvirt use case I am looking at does require adding more metadata fields, and I can't see how doing that without memory allocation or imposing arbitrary limits is possible. Imposing arbitrary limits it is, I guess.
Re: async-signal-safe use: Yes, using a JSON library is more convenien and generally preferred to writing a yet another JSON encoder, and yes, a typical JSON library will not be async-signal-safe. However, applications are not required to use all JSON facilities. An application that wants to log a static string between fork() and execve() can just as easily log a static JSON string.
I don't really see logging preformatted static JSON strings as a satisfactory approach, especially when compared to the way you can use journald.
That is either write 150 lines of code, or rely on libsystemd-journal code that was not promised to be async-signal-safe?
Regarding libvirt specifically, virLogVMessage is rather far from async-signal-safe (e.g. virVasprintf(), virLogLock()), so this doesn't seem to be a concern for libvirt.
It actually *is* very much a concern for libvirt.
OK. Mirek
On Tue, Oct 09, 2012 at 06:53:36AM -0400, Miloslav Trmac wrote:
----- Original Message -----
Given systemd's fast adoption across a wide range of Linux distros, in particular the enterprise distros from Red Hat & SUSE, we're going to have journald support in places where structured logging really matters, likely expanding to all Linux distros in a reasonably short period. As such I don't really have a desire to also support Lumberjack format in libvirt natively. IMHO, system services should just log to journald and either journald can forward plain messages to syslog, or a tool can be created which pulls structured log data out of the journal and formats it in Lumberjack format.
I can live with that; however the libvirt use case I am looking at does require adding more metadata fields, and I can't see how doing that without memory allocation or imposing arbitrary limits is possible. Imposing arbitrary limits it is, I guess.
I do have some ideas of adding more metadata too. What sort of pieces of info are you looking for ? Based on your previous patches, I am assuming the various virError struct fields at the very least ? Any others ? I think arbitrary limits will be ok, since while the number of metadata fields is theoretically unlimited, in practice I don't see us needing more than say 15 fields. 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 :|
participants (4)
-
Daniel P. Berrange -
Eric Blake -
Miloslav Trmac -
Miloslav Trmač