Redo structured logging API

It turns out that the current approach of parsing g_log_structured
varargs is unworkable, because vprintf is not guaranteed to advance
the passed-in va_list. So, we have to reshuffle the argument list
a bit; I've come up with this approach:

g_log_structured (domain, level,
                  key-value pairs...
                  "MESSAGE", format,
                  printf arguments);

This requires a "MESSAGE" key to always be present, and it requires
the "MESSAGE"-format pair to be last, but it avoids an extra NULL
as marker after the key-value pairs. And it can be parsed with a
single pass over the va_list, without any va_copy.

Since we have G_LOG_USE_STRUCTURED, the separate ...structured()
convenience macros are pretty pointless, and I have dropped them
for now.
This commit is contained in:
Matthias Clasen 2016-07-20 18:36:52 -04:00
parent fec01b630a
commit bdcf9e8b4e
2 changed files with 80 additions and 217 deletions

View File

@ -1295,10 +1295,9 @@ color_reset (gboolean use_color)
* @log_domain: log domain, usually %G_LOG_DOMAIN
* @log_level: log level, either from #GLogLevelFlags, or a user-defined
* level
* @format: message format, in printf() style
* @...: parameters to insert into the format string, followed by keyvalue
* pairs of structured data to add to the log message, terminated with a
* %NULL
* @...: key-value pairs of structured data to add to the log entry, followed
* by the key "MESSAGE", followed by a printf()-style message format,
* followed by parameters to insert in the format string
*
* Log a message with structured data. The message will be passed through to the
* log writer set by the application using g_log_set_writer_func(). If the
@ -1335,11 +1334,10 @@ color_reset (gboolean use_color)
* For example:
* ```
* g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_DEBUG,
* "This is a debug message about pointer %p and integer %u.",
* some_pointer, some_integer,
* "MESSAGE_ID", "06d4df59e6c24647bfe69d2c27ef0b4e",
* "MY_APPLICATION_CUSTOM_FIELD", "some debug string",
* NULL);
* "MESSAGE", "This is a debug message about pointer %p and integer %u.",
* some_pointer, some_integer);
* ```
*
* Note that each `MESSAGE_ID` **must** be [uniquely and randomly
@ -1364,8 +1362,8 @@ color_reset (gboolean use_color)
* g_log_structured_array (G_LOG_LEVEL_DEBUG, fields, G_N_ELEMENTS (fields));
* ```
*
* Note also that, even if no structured fields are specified, the argument list
* **must** be %NULL-terminated.
* Note also that, even if no structured fields are specified, the key-value part
* of the argument list **must** be %NULL-terminated.
*
* The default writer function for `stdout` and `stderr` will automatically
* append a new-line character to the @format, so you should not add one
@ -1376,18 +1374,60 @@ color_reset (gboolean use_color)
void
g_log_structured (const gchar *log_domain,
GLogLevelFlags log_level,
const gchar *format,
...)
{
va_list args, field_args;
va_list args;
gchar buffer[1025], *message_allocated = NULL;
const gchar *message, *priority;
const char *format;
const gchar *message;
gpointer p;
gsize n_fields, i;
GLogField *fields = NULL;
GLogField stack_fields[16];
GLogField *fields = stack_fields;
GLogField *fields_allocated = NULL;
GArray *array = NULL;
/* Format the message. */
va_start (args, format);
va_start (args, log_level);
for (p = va_arg (args, gchar *), i = 3;
strcmp (p, "MESSAGE") != 0;
p = va_arg (args, gchar *), i++)
{
GLogField field;
const gchar *key = p;
gconstpointer value = va_arg (args, gpointer);
field.key = key;
field.value = value;
field.length = -1;
if (i < 16)
stack_fields[i] = field;
else
{
/* Don't allow dynamic allocation, since we're likely
* in an out-of-memory situation. For lack of a better solution,
* just ignore further key-value pairs.
*/
if (log_level & G_LOG_FLAG_RECURSION)
continue;
if (i == 16)
{
array = g_array_sized_new (FALSE, FALSE, sizeof (GLogField), 32);
g_array_append_vals (array, stack_fields, 16);
}
g_array_append_val (array, field);
}
}
n_fields = i;
if (array)
fields = fields_allocated = (GLogField *) g_array_free (array, FALSE);
format = va_arg (args, gchar *);
if (log_level & G_LOG_FLAG_RECURSION)
{
@ -1404,58 +1444,25 @@ g_log_structured (const gchar *log_domain,
message = message_allocated = g_strdup_vprintf (format, args);
}
/* Format the priority. */
priority = log_level_to_priority (log_level);
/* Work out how many fields we have. */
G_VA_COPY (field_args, args);
for (p = va_arg (args, gchar *), n_fields = 0;
p != NULL;
p = va_arg (args, gchar *), n_fields++)
va_arg (args, gpointer);
/* Add MESSAGE, PRIORITY and GLIB_DOMAIN. */
n_fields += 3;
/* Build the fields array. */
fields = g_alloca (sizeof (GLogField) * n_fields);
fields[0].key = "MESSAGE";
fields[0].value = message;
fields[0].length = -1;
fields[1].key = "PRIORITY";
fields[1].value = priority;
fields[1].length = 1; /* byte */
fields[1].value = log_level_to_priority (log_level);
fields[1].length = 1;
fields[2].key = "GLIB_DOMAIN";
fields[2].value = log_domain;
fields[2].length = -1;
for (p = va_arg (field_args, gchar *), i = 3;
p != NULL;
p = va_arg (field_args, gchar *), i++)
{
GLogField *field = &fields[i];
const gchar *key = p;
gconstpointer value = va_arg (field_args, gpointer);
/* These are already provided as @format, @log_level and @log_domain. */
g_warn_if_fail (g_strcmp0 (key, "MESSAGE") != 0);
g_warn_if_fail (g_strcmp0 (key, "PRIORITY") != 0);
g_warn_if_fail (g_strcmp0 (key, "GLIB_DOMAIN") != 0);
field->key = key;
field->value = value;
field->length = -1;
}
/* Log it. */
g_log_structured_array (log_level, fields, n_fields);
g_free (fields_allocated);
g_free (message_allocated);
va_end (field_args);
va_end (args);
}

View File

@ -190,10 +190,7 @@ typedef GLogWriterOutput (*GLogWriterFunc) (GLogLevelFlags log_level,
GLIB_AVAILABLE_IN_2_50
void g_log_structured (const gchar *log_domain,
GLogLevelFlags log_level,
const gchar *format,
...) G_GNUC_PRINTF (3, 0)
G_GNUC_NULL_TERMINATED;
...);
GLIB_AVAILABLE_IN_2_50
void g_log_structured_array (GLogLevelFlags log_level,
const GLogField *fields,
@ -234,148 +231,19 @@ GLogWriterOutput g_log_writer_default (GLogLevelFlags log_level,
/**
* G_DEBUG_HERE:
*
* A convenience form of g_debug_structured(), recommended to be added to
* A convenience form of g_log_structured(), recommended to be added to
* functions when debugging. It prints the current monotonic time and the code
* location using %G_STRLOC.
*
* Since: 2.50
*/
#define G_DEBUG_HERE() \
g_debug_structured ("%" G_GINT64_FORMAT ": %s", g_get_monotonic_time (), \
G_STRLOC)
/**
* g_debug_structured:
* @format: message format, in printf() style
* @...: parameters to insert into the format string
*
* Convenience wrapper around g_log_structured() to output a log message at
* %G_LOG_LEVEL_DEBUG in %G_LOG_DOMAIN with the given message and the
* `CODE_FILE`, `CODE_LINE` and `CODE_FUNC` fields added automatically. As this
* macro uses `__LINE__`, it cannot be wrapped in a helper function.
*
* The provided structured fields may change in future.
*
* Since: 2.50
*/
#define g_debug_structured(...) \
g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_DEBUG, \
__VA_ARGS__, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
/**
* g_info_structured:
* @format: message format, in printf() style
* @...: parameters to insert into the format string
*
* Convenience wrapper around g_log_structured() to output a log message at
* %G_LOG_LEVEL_INFO in %G_LOG_DOMAIN with the given message and the
* `CODE_FILE`, `CODE_LINE` and `CODE_FUNC` fields added automatically. As this
* macro uses `__LINE__`, it cannot be wrapped in a helper function.
*
* The provided structured fields may change in future.
*
* Since: 2.50
*/
#define g_info_structured(...) \
g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_INFO, \
__VA_ARGS__, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
/**
* g_message_structured:
* @format: message format, in printf() style
* @...: parameters to insert into the format string
*
* Convenience wrapper around g_log_structured() to output a log message at
* %G_LOG_LEVEL_MESSAGE in %G_LOG_DOMAIN with the given message and the
* `CODE_FILE`, `CODE_LINE` and `CODE_FUNC` fields added automatically. As this
* macro uses `__LINE__`, it cannot be wrapped in a helper function.
*
* The provided structured fields may change in future.
*
* Since: 2.50
*/
#define g_message_structured(...) \
g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_MESSAGE, \
__VA_ARGS__, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
/**
* g_warning_structured:
* @format: message format, in printf() style
* @...: parameters to insert into the format string
*
* Convenience wrapper around g_log_structured() to output a log message at
* %G_LOG_LEVEL_WARNING in %G_LOG_DOMAIN with the given message and the
* `CODE_FILE`, `CODE_LINE` and `CODE_FUNC` fields added automatically. As this
* macro uses `__LINE__`, it cannot be wrapped in a helper function.
*
* The provided structured fields may change in future.
*
* Since: 2.50
*/
#define g_warning_structured(...) \
g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_WARNING, \
__VA_ARGS__, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
/**
* g_critical_structured:
* @format: message format, in printf() style
* @...: parameters to insert into the format string
*
* Convenience wrapper around g_log_structured() to output a log message at
* %G_LOG_LEVEL_CRITICAL in %G_LOG_DOMAIN with the given message and the
* `CODE_FILE`, `CODE_LINE` and `CODE_FUNC` fields added automatically. As this
* macro uses `__LINE__`, it cannot be wrapped in a helper function.
*
* The provided structured fields may change in future.
*
* Since: 2.50
*/
#define g_critical_structured(...) \
g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_CRITICAL, \
__VA_ARGS__, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
/**
* g_error_structured:
* @format: message format, in printf() style
* @...: parameters to insert into the format string
*
* Convenience wrapper around g_log_structured() to output a log message at
* %G_LOG_LEVEL_ERROR in %G_LOG_DOMAIN with the given message and the
* `CODE_FILE`, `CODE_LINE` and `CODE_FUNC` fields added automatically. As this
* macro uses `__LINE__`, it cannot be wrapped in a helper function.
*
* The provided structured fields may change in future.
*
* Since: 2.50
*/
#define g_error_structured(...) \
g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_ERROR, \
__VA_ARGS__, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
#define G_DEBUG_HERE() \
g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_DEBUG, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
"MESSAGE", "%" G_GINT64_FORMAT ": %s", \
g_get_monotonic_time (), G_STRLOC)
/* internal */
void _g_log_fallback_handler (const gchar *log_domain,
@ -410,43 +278,37 @@ void g_assert_warning (const char *log_domain,
#ifdef G_LOG_USE_STRUCTURED
#define g_error(...) G_STMT_START { \
g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_ERROR, \
__VA_ARGS__, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL); \
"MESSAGE", __VA_ARGS__); \
for (;;) ; \
} G_STMT_END
#define g_message(...) g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_MESSAGE, \
__VA_ARGS__, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
"MESSAGE", __VA_ARGS__)
#define g_critical(...) g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_CRITICAL, \
__VA_ARGS__, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
"MESSAGE", __VA_ARGS__)
#define g_warning(...) g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_WARNING, \
__VA_ARGS__, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
"MESSAGE", __VA_ARGS__)
#define g_info(...) g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_INFO, \
__VA_ARGS__, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
"MESSAGE", __VA_ARGS__)
#define g_debug(...) g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_DEBUG, \
__VA_ARGS__, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
"MESSAGE", __VA_ARGS__)
#else
/* for(;;) ; so that GCC knows that control doesn't go past g_error().
* Put space before ending semicolon to avoid C++ build warnings.
@ -477,43 +339,37 @@ void g_assert_warning (const char *log_domain,
#ifdef G_LOG_USE_STRUCTURED
#define g_error(format...) G_STMT_START { \
g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_ERROR, \
format, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL); \
"MESSAGE", format); \
for (;;) ; \
} G_STMT_END
#define g_message(format...) g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_MESSAGE, \
format, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
"MESSAGE", format)
#define g_critical(format...) g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_CRITICAL, \
format, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
"MESSAGE", format)
#define g_warning(format...) g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_WARNING, \
format, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
"MESSAGE", format)
#define g_info(format...) g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_INFO, \
format, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
"MESSAGE", format)
#define g_debug(format...) g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_DEBUG, \
format, \
"CODE_FILE", __FILE__, \
"CODE_LINE", G_STRINGIFY (__LINE__), \
"CODE_FUNC", __func__, \
NULL)
"MESSAGE", format)
#else
#define g_error(format...) G_STMT_START { \
g_log (G_LOG_DOMAIN, \