diff options
author | Philip Withnall <philip.withnall@collabora.co.uk> | 2016-02-20 12:34:29 +0000 |
---|---|---|
committer | Matthias Clasen <mclasen@redhat.com> | 2016-07-16 23:52:18 -0400 |
commit | 052eaf24f7789e6c9fd5c9432e91065d98946b7e (patch) | |
tree | 48f63d4ac883c15e2cf40db3b94fb124704c455d | |
parent | 8345a42cd0deec27664f1a2a815feadeb53e2556 (diff) | |
download | glib-052eaf24f7789e6c9fd5c9432e91065d98946b7e.tar.gz |
gmessages: Add a structured logging API
In parallel with g_log(), add a new structured logging API, based around
g_log_structured() and various helper functions which are exposed
publicly to allow programs to build their own logging policies easily,
without having to rewrite a lot of gmessages.c because it’s all
internal.
See the expanded documentation at the top of gmessages.c for some
rationale. See the g_log_structured() documentation for some example
code.
https://bugzilla.gnome.org/show_bug.cgi?id=744456
-rw-r--r-- | configure.ac | 15 | ||||
-rw-r--r-- | glib/Makefile.am | 4 | ||||
-rw-r--r-- | glib/gmessages.c | 812 | ||||
-rw-r--r-- | glib/gmessages.h | 261 | ||||
-rw-r--r-- | glib/tests/logging.c | 30 |
5 files changed, 1118 insertions, 4 deletions
diff --git a/configure.ac b/configure.ac index 9552b9965..5a3368f9e 100644 --- a/configure.ac +++ b/configure.ac @@ -1730,6 +1730,21 @@ if test x$have_libelf = xyes; then AC_DEFINE(HAVE_LIBELF, 1, [Define if libelf is available]) fi +dnl ************************* +dnl *** check for systemd *** +dnl ************************* +AC_ARG_ENABLE([libsystemd], + [AS_HELP_STRING([--disable-libsystemd], + [build without libsystemd support])]) +AS_IF([test "$enable_libsystemd" != "no"],[ + PKG_CHECK_MODULES([LIBSYSTEMD], [libsystemd], + [have_libsystemd=yes], [have_libsystemd=no]) +]) + +AS_IF([test "$have_libsystemd" = "yes"],[ + AC_DEFINE([HAVE_LIBSYSTEMD],[1],[Define if libsystemd is available]) +]) + dnl **************************************** dnl *** platform dependent source checks *** dnl **************************************** diff --git a/glib/Makefile.am b/glib/Makefile.am index 14d314119..0726b58a8 100644 --- a/glib/Makefile.am +++ b/glib/Makefile.am @@ -350,8 +350,8 @@ pcre_lib = pcre/libpcre.la pcre_inc = endif -libglib_2_0_la_CFLAGS = $(AM_CFLAGS) $(GLIB_HIDDEN_VISIBILITY_CFLAGS) -libglib_2_0_la_LIBADD = libcharset/libcharset.la $(printf_la) @GIO@ @GSPAWN@ @PLATFORMDEP@ @ICONV_LIBS@ @G_LIBS_EXTRA@ $(pcre_lib) $(G_THREAD_LIBS_EXTRA) $(G_THREAD_LIBS_FOR_GTHREAD) +libglib_2_0_la_CFLAGS = $(AM_CFLAGS) $(GLIB_HIDDEN_VISIBILITY_CFLAGS) $(LIBSYSTEMD_CFLAGS) +libglib_2_0_la_LIBADD = libcharset/libcharset.la $(printf_la) @GIO@ @GSPAWN@ @PLATFORMDEP@ @ICONV_LIBS@ @G_LIBS_EXTRA@ $(pcre_lib) $(G_THREAD_LIBS_EXTRA) $(G_THREAD_LIBS_FOR_GTHREAD) $(LIBSYSTEMD_LIBS) libglib_2_0_la_DEPENDENCIES = libcharset/libcharset.la $(printf_la) @GIO@ @GSPAWN@ @PLATFORMDEP@ $(glib_win32_res) $(glib_def) libglib_2_0_la_LDFLAGS = $(GLIB_LINK_FLAGS) \ diff --git a/glib/gmessages.c b/glib/gmessages.c index d29563a93..d87b33885 100644 --- a/glib/gmessages.c +++ b/glib/gmessages.c @@ -43,6 +43,47 @@ * generally considered undefined after one of these checks fails. * They are not intended for normal control flow, only to give a * perhaps-helpful warning before giving up. + * + * Structured logging output is supported using g_log_structured(). This differs + * from the traditional g_log() API in that log messages are handled as a + * collection of key–value pairs representing individual pieces of information, + * rather than as a single string containing all the information in an arbitrary + * format. + * + * The support for structured logging was motivated by the following needs (some + * of which were supported previously; others weren’t): + * * Support for multiple logging levels. + * * Structured log support with the ability to add `MESSAGE_ID`s (see + * g_log_structured()). + * * Moving the responsibility for filtering log messages from the program to + * the log viewer — instead of libraries and programs installing log handlers + * (with g_log_set_handler()) which filter messages before output, all log + * messages are outputted, and the log viewer program (such as `journalctl`) + * must filter them. This is based on the idea that bugs are sometimes hard + * to reproduce, so it is better to log everything possible and then use + * tools to analyse the logs than it is to not be able to reproduce a bug to + * get additional log data. Code which uses logging in performance-critical + * sections should compile out the g_log_structured() calls in + * release builds, and compile them in in debugging builds. + * * A single writer function which handles all log messages in a process, from + * all libraries and program code; rather than multiple log handlers with + * poorly defined interactions between them. This allows a program to easily + * change its logging policy by changing the writer function, for example to + * log to an additional location or to change what logging output fallbacks + * are used. The log writer functions provided by GLib are exposed publicly + * so they can be used from programs’ log writers. This allows log writer + * policy and implementation to be kept separate. + * * If a library wants to add standard information to all of its log messages + * (such as library state) or to redact private data (such as passwords or + * network credentials), it should use a wrapper function around its + * g_log_structured() calls or implement that in the single log writer + * function. + * * If a program wants to pass context data from a g_log_structured() call to + * its log writer function so that, for example, it can use the correct + * server connection to submit logs to, that user data can be passed as a + * zero-length #GLogField to g_log_structured_array(). + * * Colour output needed to be supported on the terminal, to make reading + * through logs easier. */ #include "config.h" @@ -56,6 +97,7 @@ #include <errno.h> #include "glib-init.h" +#include "galloca.h" #include "gbacktrace.h" #include "gcharset.h" #include "gconvert.h" @@ -79,6 +121,11 @@ # include <windows.h> #endif +#ifdef HAVE_LIBSYSTEMD +#include <sys/uio.h> +#include <systemd/sd-journal.h> +#endif + /** * SECTION:messages @@ -299,10 +346,14 @@ static GLogDomain *g_log_domains = NULL; static GPrintFunc glib_print_func = NULL; static GPrintFunc glib_printerr_func = NULL; static GPrivate g_log_depth; +static GPrivate g_log_structured_depth; static GLogFunc default_log_func = g_log_default_handler; static gpointer default_log_data = NULL; static GTestLogFatalFunc fatal_log_func = NULL; static gpointer fatal_log_data; +static GLogWriterFunc log_writer_func = g_log_writer_default; +static gpointer log_writer_user_data = NULL; +static GDestroyNotify log_writer_user_data_free = NULL; /* --- functions --- */ @@ -376,6 +427,18 @@ write_string (FILE *stream, fputs (string, stream); } +static void +write_string_sized (FILE *stream, + const gchar *string, + gssize length) +{ + /* Is it nul-terminated? */ + if (length < 0) + write_string (stream, string); + else + fwrite (string, 1, length, stream); +} + static GLogDomain* g_log_find_domain_L (const gchar *log_domain) { @@ -475,6 +538,14 @@ g_log_domain_get_handler_L (GLogDomain *domain, * the `G_DEBUG` environment variable (see * [Running GLib Applications](glib-running.html)). * + * Libraries should not call this function, as it affects all messages logged + * by a process, including those from other libraries. + * + * Structured log messages (using g_log_structured() and + * g_log_structured_array()) are fatal only if the default log writer is used; + * otherwise it is up to the writer function to determine which log messages + * are fatal. + * * Returns: the old fatal mask */ GLogLevelFlags @@ -507,6 +578,11 @@ g_log_set_always_fatal (GLogLevelFlags fatal_mask) * Sets the log levels which are fatal in the given domain. * %G_LOG_LEVEL_ERROR is always fatal. * + * This has no effect on structured log messages (using g_log_structured() or + * g_log_structured_array()). To change the fatal behaviour for specific log + * messages, programs must install a custom log writer function using + * g_log_set_writer_func(). + * * Returns: the old fatal mask for the log domain */ GLogLevelFlags @@ -518,7 +594,7 @@ g_log_set_fatal_mask (const gchar *log_domain, if (!log_domain) log_domain = ""; - + /* force errors to be fatal */ fatal_mask |= G_LOG_LEVEL_ERROR; /* remove bogus flag */ @@ -695,6 +771,11 @@ g_log_set_default_handler (GLogFunc log_func, * * This handler has no effect on g_error messages. * + * This handler also has no effect on structured log messages (using + * g_log_structured() or g_log_structured_array()). To change the fatal + * behaviour for specific log messages, programs must install a custom log + * writer function using g_log_set_writer_func(). + * * Since: 2.22 **/ void @@ -1128,6 +1209,733 @@ g_log (const gchar *log_domain, va_end (args); } +/* Return value must be 1 byte long (plus nul byte). + * Reference: http://man7.org/linux/man-pages/man3/syslog.3.html#DESCRIPTION + */ +static const gchar * +log_level_to_priority (GLogLevelFlags log_level) +{ + if (log_level & G_LOG_LEVEL_ERROR) + return "3"; + else if (log_level & G_LOG_LEVEL_CRITICAL) + return "4"; + else if (log_level & G_LOG_LEVEL_WARNING) + return "4"; + else if (log_level & G_LOG_LEVEL_MESSAGE) + return "5"; + else if (log_level & G_LOG_LEVEL_INFO) + return "6"; + else if (log_level & G_LOG_LEVEL_DEBUG) + return "7"; + + /* Default to LOG_NOTICE for custom log levels. */ + return "5"; +} + +static FILE * +log_level_to_file (GLogLevelFlags log_level) +{ + if (log_level & (G_LOG_LEVEL_ERROR | G_LOG_LEVEL_CRITICAL | + G_LOG_LEVEL_WARNING | G_LOG_LEVEL_MESSAGE)) + return stderr; + else + return stdout; +} + +/** + * g_log_structured: + * @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 key–value + * pairs of structured data to add to the log message, terminated with a + * %NULL + * + * 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 + * message is fatal (i.e. its log level is %G_LOG_LEVEL_ERROR), the program will + * be aborted at the end of this function. + * + * The structured data is provided as key–value pairs, where keys are UTF-8 + * strings, and values are arbitrary pointers — typically pointing to UTF-8 + * strings, but that is not a requirement. To pass binary (non-nul-terminated) + * structured data, use g_log_structured_array(). The keys for structured data + * should follow the [systemd journal + * fields](https://www.freedesktop.org/software/systemd/man/systemd.journal-fields.html) + * specification. + * + * The @log_domain will be converted into a `GLIB_DOMAIN` field. @log_level will + * be converted into a `PRIORITY` field. @format will have its placeholders + * substituted for the provided values and be converted into a `MESSAGE` field. + * + * Other fields you may commonly want to pass into this function: + * + * * [`MESSAGE_ID`](https://www.freedesktop.org/software/systemd/man/systemd.journal-fields.html#MESSAGE_ID=) + * * [`CODE_FILE`](https://www.freedesktop.org/software/systemd/man/systemd.journal-fields.html#CODE_FILE=) + * * [`CODE_LINE`](https://www.freedesktop.org/software/systemd/man/systemd.journal-fields.html#CODE_LINE=) + * * [`CODE_FUNC`](https://www.freedesktop.org/software/systemd/man/systemd.journal-fields.html#CODE_FUNC=) + * * [`ERRNO`](https://www.freedesktop.org/software/systemd/man/systemd.journal-fields.html#ERRNO=) + * + * Note that `CODE_FILE`, `CODE_LINE` and `CODE_FUNC` are automatically set by + * the logging macros, g_debug_structured(), G_DEBUG_HERE(), + * g_message_structured(), g_warning_structured(), g_critical_structured() and + * g_error_structured(). + * + * 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); + * ``` + * + * Note that each `MESSAGE_ID` **must** be [uniquely and randomly + * generated](https://www.freedesktop.org/software/systemd/man/systemd.journal-fields.html#MESSAGE_ID=). + * If adding a `MESSAGE_ID`, consider shipping a [message + * catalog](https://www.freedesktop.org/wiki/Software/systemd/catalog/) with + * your software. + * + * To pass a user data pointer to the log writer function which is specific to + * this logging call, you must use g_log_structured_array() and pass the pointer + * as a field with #GLogField.length set to zero, otherwise it will be + * interpreted as a string. + * + * For example: + * ``` + * const GLogField fields[] = { + * { "MESSAGE", "This is a debug message.", -1 }, + * { "MESSAGE_ID", "fcfb2e1e65c3494386b74878f1abf893", -1 }, + * { "MY_APPLICATION_CUSTOM_FIELD", "some debug string", -1 }, + * { "MY_APPLICATION_STATE", state_object, 0 }, + * }; + * 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. + * + * The default writer function for `stdout` and `stderr` will automatically + * append a new-line character to the @format, so you should not add one + * manually. + * + * Since: 2.50 + */ +void +g_log_structured (const gchar *log_domain, + GLogLevelFlags log_level, + const gchar *format, + ...) +{ + va_list args, field_args; + gchar buffer[1025], *message_allocated = NULL; + const gchar *message, *priority; + gpointer p; + gsize n_fields, i; + GLogField *fields = NULL; + + /* Format the message. */ + va_start (args, format); + + if (log_level & G_LOG_FLAG_RECURSION) + { + /* we use a stack buffer of fixed size, since we're likely + * in an out-of-memory situation + */ + gsize size G_GNUC_UNUSED; + + size = _g_vsnprintf (buffer, sizeof (buffer), format, args); + message = buffer; + } + else + { + 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. */ + 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[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 (message_allocated); + va_end (field_args); + va_end (args); +} + +static GLogWriterOutput _g_log_writer_fallback (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields, + gpointer user_data); + +/** + * g_log_structured_array: + * @log_level: log level, either from #GLogLevelFlags, or a user-defined + * level + * @fields: (array length=n_fields): key–value pairs of structured data to add + * to the log message + * @n_fields: number of elements in the @fields array + * + * 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 + * message is fatal (i.e. its log level is %G_LOG_LEVEL_ERROR), the program will + * be aborted at the end of this function. + * + * See g_log_structured() for more documentation. + * + * This assumes that @log_level is already present in @fields (typically as the + * `PRIORITY` field). + * + * Since: 2.50 + */ +void +g_log_structured_array (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields) +{ + GLogWriterFunc writer_func; + gpointer writer_user_data; + gboolean recursion; + guint depth; + + if (n_fields == 0) + return; + + /* Check for recursion and look up the writer function. */ + depth = GPOINTER_TO_UINT (g_private_get (&g_log_structured_depth)); + recursion = (depth > 0); + + g_mutex_lock (&g_messages_lock); + + writer_func = recursion ? _g_log_writer_fallback : log_writer_func; + writer_user_data = log_writer_user_data; + + g_mutex_unlock (&g_messages_lock); + + /* Write the log entry. */ + g_private_set (&g_log_structured_depth, GUINT_TO_POINTER (++depth)); + + g_assert (writer_func != NULL); + writer_func (log_level, fields, n_fields, writer_user_data); + + g_private_set (&g_log_structured_depth, GUINT_TO_POINTER (--depth)); + + /* Abort if the message was fatal. */ + if (log_level & G_LOG_FATAL_MASK) + _g_log_abort (!(log_level & G_LOG_FLAG_RECURSION)); +} + +/** + * g_log_set_writer_func: + * @func: log writer function, which must not be %NULL + * @user_data: (closure func): user data to pass to @func + * @user_data_free: (destroy func): function to free @user_data once it’s + * finished with, if non-%NULL + * + * Set a writer function which will be called to format and write out each log + * message. Each program should set a writer function, or the default writer + * (g_log_writer_default()) will be used. + * + * Libraries **must not** call this function — only programs are allowed to + * install a writer function, as there must be a single, central point where + * log messages are formatted and outputted. + * + * There can only be one writer function. It is an error to set more than one. + * + * Since: 2.50 + */ +void +g_log_set_writer_func (GLogWriterFunc func, + gpointer user_data, + GDestroyNotify user_data_free) +{ + g_return_if_fail (func != NULL); + g_return_if_fail (log_writer_func == g_log_writer_default); + + g_mutex_lock (&g_messages_lock); + log_writer_func = func; + log_writer_user_data = user_data; + log_writer_user_data_free = user_data_free; + g_mutex_unlock (&g_messages_lock); +} + +/** + * g_log_writer_is_journald: + * @output_fd: output file descriptor to check + * + * Check whether the given @output_fd file descriptor is a connection to the + * systemd journal, or something else (like a log file or `stdout` or + * `stderr`). + * + * Returns: %TRUE if @output_fd points to the journal, %FALSE otherwise + * Since: 2.50 + */ +gboolean +g_log_writer_is_journald (gint output_fd) +{ +#ifdef HAVE_LIBSYSTEMD + /* FIXME: Use the new journal API for detecting whether we’re writing to the + * journal. See: https://github.com/systemd/systemd/issues/2473 + */ + static gsize initialized; + static gboolean stdout_is_socket; + + g_return_val_if_fail (output_fd >= 0, FALSE); + + if (g_once_init_enter (&initialized)) + { + guint64 pid = (guint64) getpid (); + char *fdpath = g_strdup_printf ("/proc/%" G_GUINT64_FORMAT "/fd/%d", + pid, output_fd); + char buf[1024]; + ssize_t bytes_read; + + if ((bytes_read = readlink (fdpath, buf, sizeof(buf) - 1)) != -1) + { + buf[bytes_read] = '\0'; + stdout_is_socket = g_str_has_prefix (buf, "socket:"); + } + else + stdout_is_socket = FALSE; + + g_free (fdpath); + g_once_init_leave (&initialized, TRUE); + } + + return stdout_is_socket; +#else /* if !HAVE_LIBSYSTEMD */ + return FALSE; +#endif +} + +static void escape_string (GString *string); + +/** + * g_log_writer_format_fields: + * @log_level: log level, either from #GLogLevelFlags, or a user-defined + * level + * @fields: (array length=n_fields): key–value pairs of structured data forming + * the log message + * @n_fields: number of elements in the @fields array + * + * Format a structured log message as a string suitable for outputting to the + * terminal (or elsewhere). This will include the values of all fields it knows + * how to interpret, which includes `MESSAGE` and `GLIB_DOMAIN` (see the + * documentation for g_log_structured()). It does not include values from + * unknown fields. + * + * The returned string does **not** have a trailing new-line character. It is + * encoded in the character set of the current locale, which is not necessarily + * UTF-8. + * + * Returns: (transfer full): string containing the formatted log message, in + * the character set of the current locale + * Since: 2.50 + */ +gchar * +g_log_writer_format_fields (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields) +{ + gsize i; + const gchar *message = NULL; + const gchar *log_domain = NULL; + gchar level_prefix[STRING_BUFFER_SIZE]; + GString *gstring; + + /* Extract some common fields. */ + for (i = 0; (message == NULL || log_domain == NULL) && i < n_fields; i++) + { + const GLogField *field = &fields[i]; + + if (g_strcmp0 (field->key, "MESSAGE") == 0) + message = field->value; + else if (g_strcmp0 (field->key, "GLIB_DOMAIN") == 0) + log_domain = field->value; + } + + /* Format things. */ + mklevel_prefix (level_prefix, log_level); + + gstring = g_string_new (NULL); + if (log_level & ALERT_LEVELS) + g_string_append (gstring, "\n"); + if (!log_domain) + g_string_append (gstring, "** "); + + if ((g_log_msg_prefix & (log_level & G_LOG_LEVEL_MASK)) == + (log_level & G_LOG_LEVEL_MASK)) + { + const gchar *prg_name = g_get_prgname (); + gulong pid = getpid (); + + if (prg_name == NULL) + g_string_append_printf (gstring, "(process:%lu): ", pid); + else + g_string_append_printf (gstring, "(%s:%lu): ", prg_name, pid); + } + + if (log_domain != NULL) + { + g_string_append (gstring, log_domain); + g_string_append_c (gstring, '-'); + } + g_string_append (gstring, level_prefix); + + g_string_append (gstring, ": "); + if (message == NULL) + { + g_string_append (gstring, "(NULL) message"); + } + else + { + GString *msg; + const gchar *charset; + + msg = g_string_new (message); + escape_string (msg); + + if (g_get_charset (&charset)) + { + /* charset is UTF-8 already */ + g_string_append (gstring, msg->str); + } + else + { + gchar *lstring = strdup_convert (msg->str, charset); + g_string_append (gstring, lstring); + g_free (lstring); + } + + g_string_free (msg, TRUE); + } + + return g_string_free (gstring, FALSE); +} + +/** + * g_log_writer_journald: + * @log_level: log level, either from #GLogLevelFlags, or a user-defined + * level + * @fields: (array length=n_fields): key–value pairs of structured data forming + * the log message + * @n_fields: number of elements in the @fields array + * @user_data: user data passed to g_log_set_writer_func() + * + * Format a structured log message and send it to the systemd journal as a set + * of key–value pairs. All fields are sent to the journal, but if a field has + * length zero (indicating program-specific data) then only its key will be + * sent. + * + * This is suitable for use as a #GLogWriterFunc. + * + * If GLib has been compiled without systemd support, this function is still + * defined, but will always return %G_LOG_WRITER_UNHANDLED. + * + * Returns: %G_LOG_WRITER_HANDLED on success, %G_LOG_WRITER_UNHANDLED otherwise + * Since: 2.50 + */ +GLogWriterOutput +g_log_writer_journald (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields, + gpointer user_data) +{ +#ifdef HAVE_LIBSYSTEMD + gsize i; + struct iovec *pairs; + gint retval; + + g_return_val_if_fail (fields != NULL, G_LOG_WRITER_UNHANDLED); + g_return_val_if_fail (n_fields > 0, G_LOG_WRITER_UNHANDLED); + + /* According to systemd.journal-fields(7), the journal allows fields in any + * format (including arbitrary binary), but expects text fields to be UTF-8. + * This is great, because we require input strings to be in UTF-8, so no + * conversion is necessary and we don’t need to care about the current + * locale’s character set. + */ + + pairs = g_alloca (sizeof (struct iovec) * n_fields); + + for (i = 0; i < n_fields; i++) + { + guint8 *buf = NULL; + gsize key_length; + gsize value_length; + + /* Build the iovec for this field. */ + key_length = strlen (fields[i].key); + value_length = + (fields[i].length < 0) ? strlen (fields[i].value) : fields[i].length; + + buf = g_malloc (key_length + 1 + value_length + 1); + pairs[i].iov_base = buf; + pairs[i].iov_len = key_length + 1 + value_length; + + strncpy ((char *) buf, fields[i].key, key_length); + buf[key_length] = '='; + memcpy ((char *) buf + key_length + 1, fields[i].value, value_length); + buf[key_length + 1 + value_length] = '\0'; + } + + retval = sd_journal_sendv (pairs, n_fields); + + for (i = 0; i < n_fields; i++) + g_free (pairs[i].iov_base); + + return (retval == 0) ? G_LOG_WRITER_HANDLED : G_LOG_WRITER_UNHANDLED; +#else /* if !HAVE_LIBSYSTEMD */ + return G_LOG_WRITER_UNHANDLED; +#endif +} + +/** + * g_log_writer_standard_streams: + * @log_level: log level, either from #GLogLevelFlags, or a user-defined + * level + * @fields: (array length=n_fields): key–value pairs of structured data forming + * the log message + * @n_fields: number of elements in the @fields array + * @user_data: user data passed to g_log_set_writer_func() + * + * Format a structured log message and print it to either `stdout` or `stderr`, + * depending on its log level. %G_LOG_LEVEL_INFO and %G_LOG_LEVEL_DEBUG messages + * are sent to `stdout`; all other log levels are sent to `stderr`. Only fields + * which are understood by this function are included in the formatted string + * which is printed. + * + * A trailing new-line character is added to the log message when it is printed. + * + * This is suitable for use as a #GLogWriterFunc. + * + * Returns: %G_LOG_WRITER_HANDLED on success, %G_LOG_WRITER_UNHANDLED otherwise + * Since: 2.50 + */ +GLogWriterOutput +g_log_writer_standard_streams (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields, + gpointer user_data) +{ + FILE *stream; + gchar *out = NULL; /* in the current locale’s character set */ + + g_return_val_if_fail (fields != NULL, G_LOG_WRITER_UNHANDLED); + g_return_val_if_fail (n_fields > 0, G_LOG_WRITER_UNHANDLED); + + stream = log_level_to_file (log_level); + out = g_log_writer_format_fields (log_level, fields, n_fields); + _g_fprintf (stream, "%s\n", out); + g_free (out); + + return G_LOG_WRITER_HANDLED; +} + +/** + * g_log_writer_default: + * @log_level: log level, either from #GLogLevelFlags, or a user-defined + * level + * @fields: (array length=n_fields): key–value pairs of structured data forming + * the log message + * @n_fields: number of elements in the @fields array + * @user_data: user data passed to g_log_set_writer_func() + * + * Format a structured log message and output it to the default log destination + * for the platform. On Linux, this is typically the systemd journal, falling + * back to `stdout` or `stderr` if running from the terminal or if output is + * being redirected to a file. + * + * Support for other platform-specific logging mechanisms may be added in + * future. Distributors of GLib may modify this function to impose their own + * (documented) platform-specific log writing policies. + * + * This is suitable for use as a #GLogWriterFunc, and is the default writer used + * if no other is set using g_log_set_writer_func(). + * + * Returns: %G_LOG_WRITER_HANDLED on success, %G_LOG_WRITER_UNHANDLED otherwise + * Since: 2.50 + */ +GLogWriterOutput +g_log_writer_default (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields, + gpointer user_data) +{ + g_return_val_if_fail (fields != NULL, G_LOG_WRITER_UNHANDLED); + g_return_val_if_fail (n_fields > 0, G_LOG_WRITER_UNHANDLED); + + /* Disable debug message output unless specified in G_MESSAGES_DEBUG. */ + if (!(log_level & DEFAULT_LEVELS) && !(log_level >> G_LOG_LEVEL_USER_SHIFT)) + { + const gchar *domains, *log_domain = NULL; + gsize i; + + domains = g_getenv ("G_MESSAGES_DEBUG"); + + if ((log_level & INFO_LEVELS) == 0 || + domains == NULL) + return G_LOG_WRITER_HANDLED; + + for (i = 0; i < n_fields; i++) + { + if (g_strcmp0 (fields[i].key, "GLIB_DOMAIN") == 0) + { + log_domain = fields[i].value; + break; + } + } + + if (strcmp (domains, "all") != 0 && + (log_domain == NULL || !strstr (domains, log_domain))) + return G_LOG_WRITER_HANDLED; + } + + /* Mark messages as fatal if they have a level set in + * g_log_set_always_fatal(). + */ + if (log_level & g_log_always_fatal) + log_level |= G_LOG_FLAG_FATAL; + + /* Try logging to the systemd journal as first choice. */ + if (g_log_writer_is_journald (fileno (stderr)) && + g_log_writer_journald (log_level, fields, n_fields, user_data) == + G_LOG_WRITER_HANDLED) + goto handled; + + /* FIXME: Add support for the Windows log. */ + + if (g_log_writer_standard_streams (log_level, fields, n_fields, user_data) == + G_LOG_WRITER_HANDLED) + goto handled; + + return G_LOG_WRITER_UNHANDLED; + +handled: + /* Abort if the message was fatal. */ + if (log_level & G_LOG_FLAG_FATAL) + { +#ifdef G_OS_WIN32 + if (!g_test_initialized ()) + { + gchar *locale_msg = NULL; + + locale_msg = g_locale_from_utf8 (fatal_msg_buf, -1, NULL, NULL, NULL); + MessageBox (NULL, locale_msg, NULL, + MB_ICONERROR | MB_SETFOREGROUND); + g_free (locale_msg); + } +#endif /* !G_OS_WIN32 */ + + _g_log_abort (!(log_level & G_LOG_FLAG_RECURSION)); + } + + return G_LOG_WRITER_HANDLED; +} + +static GLogWriterOutput +_g_log_writer_fallback (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields, + gpointer user_data) +{ + FILE *stream; + gsize i; + + /* we cannot call _any_ GLib functions in this fallback handler, + * which is why we skip UTF-8 conversion, etc. + * since we either recursed or ran out of memory, we're in a pretty + * pathologic situation anyways, what we can do is giving the + * the process ID unconditionally however. + */ + + stream = log_level_to_file (log_level); + + for (i = 0; i < n_fields; i++) + { + const GLogField *field = &fields[i]; + + /* Only print fields we definitely recognise, otherwise we could end up + * printing a random non-string pointer provided by the user to be + * interpreted by their writer function. + */ + if (strcmp (field->key, "MESSAGE") != 0 && + strcmp (field->key, "MESSAGE_ID") != 0 && + strcmp (field->key, "PRIORITY") != 0 && + strcmp (field->key, "CODE_FILE") != 0 && + strcmp (field->key, "CODE_LINE") != 0 && + strcmp (field->key, "CODE_FUNC") != 0 && + strcmp (field->key, "ERRNO") != 0 && + strcmp (field->key, "SYSLOG_FACILITY") != 0 && + strcmp (field->key, "SYSLOG_IDENTIFIER") != 0 && + strcmp (field->key, "SYSLOG_PID") != 0 && + strcmp (field->key, "GLIB_DOMAIN") != 0) + continue; + + write_string (stream, field->key); + write_string (stream, "="); + write_string_sized (stream, field->value, field->length); + } + +#ifndef G_OS_WIN32 + { + gchar pid_string[FORMAT_UNSIGNED_BUFSIZE]; + + format_unsigned (pid_string, getpid (), 10); + write_string (stream, "_PID="); + write_string (stream, pid_string); + } +#endif + + return G_LOG_WRITER_HANDLED; +} + /** * g_return_if_fail_warning: (skip) * @log_domain: (nullable): @@ -1472,7 +2280,7 @@ g_log_default_handler (const gchar *log_domain, if ((g_log_msg_prefix & (log_level & G_LOG_LEVEL_MASK)) == (log_level & G_LOG_LEVEL_MASK)) { const gchar *prg_name = g_get_prgname (); - + if (!prg_name) g_string_append_printf (gstring, "(process:%lu): ", (gulong)getpid ()); else diff --git a/glib/gmessages.h b/glib/gmessages.h index 1c5a9ee6c..ae5168661 100644 --- a/glib/gmessages.h +++ b/glib/gmessages.h @@ -30,6 +30,7 @@ #endif #include <stdarg.h> +#include <stdio.h> #include <glib/gtypes.h> #include <glib/gmacros.h> @@ -113,6 +114,266 @@ GLogLevelFlags g_log_set_fatal_mask (const gchar *log_domain, GLIB_AVAILABLE_IN_ALL GLogLevelFlags g_log_set_always_fatal (GLogLevelFlags fatal_mask); +/* Structured logging mechanism. */ + +/** + * GLogWriterOutput: + * @G_LOG_WRITER_HANDLED: Log writer has handled the log entry. + * @G_LOG_WRITER_UNHANDLED: Log writer could not handle the log entry. + * + * Return values from #GLogWriterFuncs to indicate whether the given log entry + * was successfully handled by the writer, or whether there was an error in + * handling it (and hence a fallback writer should be used). + * + * If a #GLogWriterFunc ignores a log entry, it should return + * %G_LOG_WRITER_HANDLED. + * + * Since: 2.50 + */ +typedef enum +{ + G_LOG_WRITER_HANDLED = 1, + G_LOG_WRITER_UNHANDLED = 0, +} GLogWriterOutput; + +/** + * GLogField: + * @key: field name (UTF-8 string) + * @value: field value (arbitrary bytes) + * @length: length of @value, in bytes, or -1 if it is nul-terminated + * + * Structure representing a single field in a structured log entry. See + * g_log_structured() for details. + * + * Log fields may contain arbitrary values, including binary with embedded nul + * bytes. If the field contains a string, the string must be UTF-8 encoded and + * have a trailing nul byte. Otherwise, @length must be set to a non-negative + * value. + * + * Since: 2.50 + */ +typedef struct +{ + const gchar *key; + gconstpointer value; + gssize length; +} GLogField; + +/** + * GLogWriterFunc: + * @log_level: log level of the message + * @fields: (array length=n_fields): fields forming the message + * @n_fields: number of @fields + * @user_data: user data passed to g_log_set_writer_func() + * + * Writer function for log entries. A log entry is a collection of one or more + * #GLogFields, using the standard [field names from journal + * specification](https://www.freedesktop.org/software/systemd/man/systemd.journal-fields.html). + * See g_log_structured() for more information. + * + * Writer functions must ignore fields which they do not recognise, unless they + * can write arbitrary binary output, as field values may be arbitrary binary. + * + * @log_level is guaranteed to be included in @fields as the `PRIORITY` field, + * but is provided separately for convenience of deciding whether or where to + * output the log entry. + * + * Returns: %G_LOG_WRITER_HANDLED if the log entry was handled successfully; + * %G_LOG_WRITER_UNHANDLED otherwise + * Since: 2.50 + */ +typedef GLogWriterOutput (*GLogWriterFunc) (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields, + gpointer user_data); + +GLIB_AVAILABLE_IN_2_50 +void g_log_structured (const gchar *log_domain, + GLogLevelFlags log_level, + const gchar *format, + ...) + G_GNUC_NULL_TERMINATED; + +GLIB_AVAILABLE_IN_2_50 +void g_log_structured_array (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields); + +GLIB_AVAILABLE_IN_2_50 +void g_log_set_writer_func (GLogWriterFunc func, + gpointer user_data, + GDestroyNotify user_data_free); + +GLIB_AVAILABLE_IN_2_50 +gboolean g_log_writer_is_journald (gint output_fd); + +GLIB_AVAILABLE_IN_2_50 +gchar *g_log_writer_format_fields (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields); + +GLIB_AVAILABLE_IN_2_50 +GLogWriterOutput g_log_writer_journald (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields, + gpointer user_data); +GLIB_AVAILABLE_IN_2_50 +GLogWriterOutput g_log_writer_standard_streams (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields, + gpointer user_data); +GLIB_AVAILABLE_IN_2_50 +GLogWriterOutput g_log_writer_default (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields, + gpointer user_data); + +/** + * G_DEBUG_HERE: + * + * A convenience form of g_debug_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(format, __va_args__) \ + g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_DEBUG, \ + format, ##__va_args__, \ + "CODE_FILE", G_STRINGIFY (__FILE__), \ + "CODE_LINE", G_STRINGIFY (__LINE__), \ + "CODE_FUNC", G_STRINGIFY (__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(format, __va_args__) \ + g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_INFO, \ + format, ##__va_args__, \ + "CODE_FILE", G_STRINGIFY (__FILE__), \ + "CODE_LINE", G_STRINGIFY (__LINE__), \ + "CODE_FUNC", G_STRINGIFY (__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(format, __va_args__) \ + g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_MESSAGE, \ + format, ##__va_args__, \ + "CODE_FILE", G_STRINGIFY (__FILE__), \ + "CODE_LINE", G_STRINGIFY (__LINE__), \ + "CODE_FUNC", G_STRINGIFY (__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(format, __va_args__) \ + g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_WARNING, \ + format, ##__va_args__, \ + "CODE_FILE", G_STRINGIFY (__FILE__), \ + "CODE_LINE", G_STRINGIFY (__LINE__), \ + "CODE_FUNC", G_STRINGIFY (__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(format, __va_args__) \ + g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_CRITICAL, \ + format, ##__va_args__, \ + "CODE_FILE", G_STRINGIFY (__FILE__), \ + "CODE_LINE", G_STRINGIFY (__LINE__), \ + "CODE_FUNC", G_STRINGIFY (__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(format, __va_args__) \ + g_log_structured (G_LOG_DOMAIN, G_LOG_LEVEL_ERROR, \ + format, ##__va_args__, \ + "CODE_FILE", G_STRINGIFY (__FILE__), \ + "CODE_LINE", G_STRINGIFY (__LINE__), \ + "CODE_FUNC", G_STRINGIFY (__FUNC__), \ + NULL) + /* internal */ void _g_log_fallback_handler (const gchar *log_domain, GLogLevelFlags log_level, diff --git a/glib/tests/logging.c b/glib/tests/logging.c index fc5795614..2307c6d05 100644 --- a/glib/tests/logging.c +++ b/glib/tests/logging.c @@ -294,6 +294,34 @@ test_gibberish (void) g_test_trap_assert_stderr ("*bla bla \\x9e\\x9f\\u000190*"); } +static void +test_structured_logging_no_state (void) +{ + gpointer some_pointer = GUINT_TO_POINTER (0x100); + guint some_integer = 123; + + g_log_structured ("some-domain", G_LOG_LEVEL_MESSAGE, + "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); +} + +static void +test_structured_logging_some_state (void) +{ + gpointer state_object = NULL; /* this must not be dereferenced */ + const GLogField fields[] = { + { "MESSAGE", "This is a debug message.", -1 }, + { "MESSAGE_ID", "fcfb2e1e65c3494386b74878f1abf893", -1 }, + { "MY_APPLICATION_CUSTOM_FIELD", "some debug string", -1 }, + { "MY_APPLICATION_STATE", state_object, 0 }, + }; + + g_log_structured_array (G_LOG_LEVEL_DEBUG, fields, G_N_ELEMENTS (fields)); +} + int main (int argc, char *argv[]) { @@ -319,6 +347,8 @@ main (int argc, char *argv[]) g_test_add_func ("/logging/printerr-handler", test_printerr_handler); g_test_add_func ("/logging/653052", bug653052); g_test_add_func ("/logging/gibberish", test_gibberish); + g_test_add_func ("/structured-logging/no-state", test_structured_logging_no_state); + g_test_add_func ("/structured-logging/some-state", test_structured_logging_some_state); return g_test_run (); } |