From 10b0ece9d8428bde0583d28ed42e227ed353271f Mon Sep 17 00:00:00 2001 From: Simon McVittie Date: Thu, 23 Jul 2020 16:27:02 +0100 Subject: [PATCH 1/2] gmessages: Add API to move info and debug messages to stderr GLib code normally prints info and debug messages to stdout, but that interferes with programs that are documented to produce machine-readable output such as JSON or XML on stdout. In particular, if such a program uses a GLib-based library, setting G_MESSAGES_DEBUG will typically result in that library's debug messages going to the program's stdout and corrupting the machine-readable output. Unix programs can avoid this by using dup2() to move the original stdout to another fd, then dup2() again to make the new stdout a copy of stderr, but it's easier if we provide a way to not write debug messages to stdout in the first place. Calling g_log_writer_default_set_use_stderr (TRUE) results in behaviour resembling Python's logging.basicConfig(), with all diagnostics going to stderr. Suggested by Allison Karlitskaya on glib#2087. Signed-off-by: Simon McVittie --- docs/reference/glib/glib-sections.txt | 1 + glib/gmessages.c | 43 +++++++++++++++++++++++++-- glib/gmessages.h | 3 ++ glib/tests/logging.c | 21 +++++++++++++ 4 files changed, 65 insertions(+), 3 deletions(-) diff --git a/docs/reference/glib/glib-sections.txt b/docs/reference/glib/glib-sections.txt index 598b0366b..30e58de0c 100644 --- a/docs/reference/glib/glib-sections.txt +++ b/docs/reference/glib/glib-sections.txt @@ -1484,6 +1484,7 @@ g_log_writer_format_fields g_log_writer_journald g_log_writer_standard_streams g_log_writer_default +g_log_writer_default_set_use_stderr g_log_structured_standard diff --git a/glib/gmessages.c b/glib/gmessages.c index 0fde49f44..440abd507 100644 --- a/glib/gmessages.c +++ b/glib/gmessages.c @@ -197,6 +197,7 @@ #include "gstrfuncs.h" #include "gstring.h" #include "gpattern.h" +#include "gthreadprivate.h" #ifdef G_OS_UNIX #include @@ -1160,12 +1161,42 @@ static const gchar *log_level_to_color (GLogLevelFlags log_level, gboolean use_color); static const gchar *color_reset (gboolean use_color); +static gboolean gmessages_use_stderr = FALSE; + +/** + * g_log_writer_default_set_use_stderr: + * @use_stderr: If %TRUE, use `stderr` for log messages that would + * normally have appeared on `stdout` + * + * Configure whether the built-in log functions + * (g_log_default_handler() for the old-style API, and both + * g_log_writer_default() and g_log_writer_standard_streams() for the + * structured API) will output all log messages to `stderr`. + * + * By default, log messages of levels %G_LOG_LEVEL_INFO and + * %G_LOG_LEVEL_DEBUG are sent to `stdout`, and other log messages are + * sent to `stderr`. This is problematic for applications that intend + * to reserve `stdout` for structured output such as JSON or XML. + * + * This function sets global state. It is not thread-aware, and should be + * called at the very start of a program, before creating any other threads + * or creating objects that could create worker threads of their own. + * + * Since: 2.68 + */ +void +g_log_writer_default_set_use_stderr (gboolean use_stderr) +{ + g_return_if_fail (g_thread_n_created () == 0); + gmessages_use_stderr = use_stderr; +} + static FILE * mklevel_prefix (gchar level_prefix[STRING_BUFFER_SIZE], GLogLevelFlags log_level, gboolean use_color) { - gboolean to_stdout = TRUE; + gboolean to_stdout = !gmessages_use_stderr; /* we may not call _any_ GLib functions here */ @@ -1442,6 +1473,9 @@ log_level_to_priority (GLogLevelFlags log_level) static FILE * log_level_to_file (GLogLevelFlags log_level) { + if (gmessages_use_stderr) + return stderr; + if (log_level & (G_LOG_LEVEL_ERROR | G_LOG_LEVEL_CRITICAL | G_LOG_LEVEL_WARNING | G_LOG_LEVEL_MESSAGE)) return stderr; @@ -2524,7 +2558,9 @@ g_log_writer_journald (GLogLevelFlags log_level, * * 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 + * are sent to `stdout`, or to `stderr` if requested by + * g_log_writer_default_set_use_stderr(); + * 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. * @@ -3075,7 +3111,8 @@ escape_string (GString *string) * * stderr is used for levels %G_LOG_LEVEL_ERROR, %G_LOG_LEVEL_CRITICAL, * %G_LOG_LEVEL_WARNING and %G_LOG_LEVEL_MESSAGE. stdout is used for - * the rest. + * the rest, unless stderr was requested by + * g_log_writer_default_set_use_stderr(). * * This has no effect if structured logging is enabled; see * [Using Structured Logging][using-structured-logging]. diff --git a/glib/gmessages.h b/glib/gmessages.h index e910f7b73..29bc1736e 100644 --- a/glib/gmessages.h +++ b/glib/gmessages.h @@ -242,6 +242,9 @@ GLogWriterOutput g_log_writer_default (GLogLevelFlags log_level, gsize n_fields, gpointer user_data); +GLIB_AVAILABLE_IN_2_68 +void g_log_writer_default_set_use_stderr (gboolean use_stderr); + /** * G_DEBUG_HERE: * diff --git a/glib/tests/logging.c b/glib/tests/logging.c index 3ab34f58e..1e9192bef 100644 --- a/glib/tests/logging.c +++ b/glib/tests/logging.c @@ -121,6 +121,21 @@ test_default_handler_debug (void) g_setenv ("G_MESSAGES_DEBUG", "all", TRUE); + g_log ("foo", G_LOG_LEVEL_DEBUG, "6"); + g_log ("bar", G_LOG_LEVEL_DEBUG, "6"); + g_log ("baz", G_LOG_LEVEL_DEBUG, "6"); + + exit (0); +} + +static void +test_default_handler_debug_stderr (void) +{ + g_log_writer_default_set_use_stderr (TRUE); + g_log_set_default_handler (g_log_default_handler, NULL); + + g_setenv ("G_MESSAGES_DEBUG", "all", TRUE); + g_log ("foo", G_LOG_LEVEL_DEBUG, "6"); g_log ("bar", G_LOG_LEVEL_DEBUG, "6"); g_log ("baz", G_LOG_LEVEL_DEBUG, "6"); @@ -170,6 +185,11 @@ test_default_handler (void) g_test_trap_assert_passed (); g_test_trap_assert_stdout ("*DEBUG*6*6*6*"); + g_test_trap_subprocess ("/logging/default-handler/subprocess/debug-stderr", 0, 0); + g_test_trap_assert_passed (); + g_test_trap_assert_stdout_unmatched ("DEBUG"); + g_test_trap_assert_stderr ("*DEBUG*6*6*6*"); + g_test_trap_subprocess ("/logging/default-handler/subprocess/0x400", 0, 0); g_test_trap_assert_passed (); g_test_trap_assert_stdout ("*LOG-0x400*message7*"); @@ -578,6 +598,7 @@ main (int argc, char *argv[]) g_test_add_func ("/logging/default-handler/subprocess/bar-info", test_default_handler_bar_info); g_test_add_func ("/logging/default-handler/subprocess/baz-debug", test_default_handler_baz_debug); g_test_add_func ("/logging/default-handler/subprocess/debug", test_default_handler_debug); + g_test_add_func ("/logging/default-handler/subprocess/debug-stderr", test_default_handler_debug_stderr); g_test_add_func ("/logging/default-handler/subprocess/0x400", test_default_handler_0x400); g_test_add_func ("/logging/warnings", test_warnings); g_test_add_func ("/logging/fatal-log-mask", test_fatal_log_mask); From b17b537a7de15ec66a0dd2b1c708409f415426a2 Mon Sep 17 00:00:00 2001 From: Simon McVittie Date: Thu, 23 Jul 2020 17:57:44 +0100 Subject: [PATCH 2/2] gmessages: Expose our default filtering as API This allows programs that want to change how log messages are printed, such as gnome-terminal (gnome-terminal#42) and Flatpak, to override the log-writer or the legacy log-handler without having to reimplement the G_MESSAGES_DEBUG filtering logic. Signed-off-by: Simon McVittie --- docs/reference/glib/glib-sections.txt | 1 + glib/gmessages.c | 119 ++++++++++++++++++++------ glib/gmessages.h | 3 + glib/tests/logging.c | 51 +++++++++++ 4 files changed, 148 insertions(+), 26 deletions(-) diff --git a/docs/reference/glib/glib-sections.txt b/docs/reference/glib/glib-sections.txt index 30e58de0c..6c1c86198 100644 --- a/docs/reference/glib/glib-sections.txt +++ b/docs/reference/glib/glib-sections.txt @@ -1485,6 +1485,7 @@ g_log_writer_journald g_log_writer_standard_streams g_log_writer_default g_log_writer_default_set_use_stderr +g_log_writer_default_would_drop g_log_structured_standard diff --git a/glib/gmessages.c b/glib/gmessages.c index 440abd507..ec21d5d1d 100644 --- a/glib/gmessages.c +++ b/glib/gmessages.c @@ -127,7 +127,8 @@ * It is recommended that custom log writer functions re-use the * `G_MESSAGES_DEBUG` environment variable, rather than inventing a custom one, * so that developers can re-use the same debugging techniques and tools across - * projects. + * projects. Since GLib 2.68, this can be implemented by dropping messages + * for which g_log_writer_default_would_drop() returns %TRUE. * * ## Testing for Messages ## {#testing-for-messages} * @@ -2617,6 +2618,95 @@ log_is_old_api (const GLogField *fields, g_strcmp0 (fields[0].value, "1") == 0); } +/* + * Internal version of g_log_writer_default_would_drop(), which can + * read from either a log_domain or an array of fields. This avoids + * having to iterate through the fields if the @log_level is sufficient + * to make the decision. + */ +static gboolean +should_drop_message (GLogLevelFlags log_level, + const char *log_domain, + const GLogField *fields, + gsize n_fields) +{ + /* 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; + gsize i; + + domains = g_getenv ("G_MESSAGES_DEBUG"); + + if ((log_level & INFO_LEVELS) == 0 || + domains == NULL) + return TRUE; + + if (log_domain == NULL) + { + 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 TRUE; + } + + return FALSE; +} + +/** + * g_log_writer_default_would_drop: + * @log_domain: (nullable): log domain + * @log_level: log level, either from #GLogLevelFlags, or a user-defined + * level + * + * Check whether g_log_writer_default() and g_log_default_handler() would + * ignore a message with the given domain and level. + * + * As with g_log_default_handler(), this function drops debug and informational + * messages unless their log domain (or `all`) is listed in the space-separated + * `G_MESSAGES_DEBUG` environment variable. + * + * This can be used when implementing log writers with the same filtering + * behaviour as the default, but a different destination or output format: + * + * |[ + * if (g_log_writer_default_would_drop (log_level, log_domain)) + * return G_LOG_WRITER_HANDLED; + * ]| + * + * or to skip an expensive computation if it is only needed for a debugging + * message, and `G_MESSAGES_DEBUG` is not set: + * + * |[ + * if (!g_log_writer_default_would_drop (G_LOG_LEVEL_DEBUG, G_LOG_DOMAIN)) + * { + * gchar *result = expensive_computation (my_object); + * + * g_debug ("my_object result: %s", result); + * g_free (result); + * } + * ]| + * + * Returns: %TRUE if the log message would be dropped by GLib's + * default log handlers + * Since: 2.68 + */ +gboolean +g_log_writer_default_would_drop (GLogLevelFlags log_level, + const char *log_domain) +{ + return should_drop_message (log_level, log_domain, NULL, 0); +} + /** * g_log_writer_default: * @log_level: log level, either from #GLogLevelFlags, or a user-defined @@ -2661,31 +2751,8 @@ g_log_writer_default (GLogLevelFlags log_level, 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; - } + if (should_drop_message (log_level, NULL, fields, n_fields)) + return G_LOG_WRITER_HANDLED; /* Mark messages as fatal if they have a level set in * g_log_set_always_fatal(). diff --git a/glib/gmessages.h b/glib/gmessages.h index 29bc1736e..6a28443b4 100644 --- a/glib/gmessages.h +++ b/glib/gmessages.h @@ -244,6 +244,9 @@ GLogWriterOutput g_log_writer_default (GLogLevelFlags log_level, GLIB_AVAILABLE_IN_2_68 void g_log_writer_default_set_use_stderr (gboolean use_stderr); +GLIB_AVAILABLE_IN_2_68 +gboolean g_log_writer_default_would_drop (GLogLevelFlags log_level, + const char *log_domain); /** * G_DEBUG_HERE: diff --git a/glib/tests/logging.c b/glib/tests/logging.c index 1e9192bef..f16503ad1 100644 --- a/glib/tests/logging.c +++ b/glib/tests/logging.c @@ -139,6 +139,53 @@ test_default_handler_debug_stderr (void) g_log ("foo", G_LOG_LEVEL_DEBUG, "6"); g_log ("bar", G_LOG_LEVEL_DEBUG, "6"); g_log ("baz", G_LOG_LEVEL_DEBUG, "6"); + + exit (0); +} + +static void +test_default_handler_would_drop (void) +{ + g_unsetenv ("G_MESSAGES_DEBUG"); + + g_assert_false (g_log_writer_default_would_drop (G_LOG_LEVEL_ERROR, "foo")); + g_assert_false (g_log_writer_default_would_drop (G_LOG_LEVEL_CRITICAL, "foo")); + g_assert_false (g_log_writer_default_would_drop (G_LOG_LEVEL_WARNING, "foo")); + g_assert_false (g_log_writer_default_would_drop (G_LOG_LEVEL_MESSAGE, "foo")); + g_assert_true (g_log_writer_default_would_drop (G_LOG_LEVEL_INFO, "foo")); + g_assert_true (g_log_writer_default_would_drop (G_LOG_LEVEL_DEBUG, "foo")); + g_assert_false (g_log_writer_default_would_drop (1<