Merge branch 'debug-invocation' into 'main'

gmessages: Treat DEBUG_INVOCATION=1 same as G_MESSAGES_DEBUG=all

See merge request GNOME/glib!4412
This commit is contained in:
Philip Withnall 2024-11-29 16:13:02 +00:00
commit c50836535a
3 changed files with 131 additions and 76 deletions

View File

@ -92,13 +92,14 @@ The default log functions (`g_log_default_handler()` for the old-style API
and `g_log_writer_default()` for the structured API) both drop debug and
informational messages by default, unless the log domains of those messages
are listed in the `G_MESSAGES_DEBUG` environment variable (or it is set to
`all`).
`all`), or `DEBUG_INVOCATION=1` is set in the environment.
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. Since GLib 2.68, this can be implemented by dropping messages for
which `g_log_writer_default_would_drop()` returns `TRUE`.
`G_MESSAGES_DEBUG` and `DEBUG_INVOCATION` environment variables, rather than
inventing a custom one, so that developers can re-use the same debugging
techniques and tools across 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

View File

@ -316,8 +316,9 @@
* manually.
*
* Such messages are suppressed by the [func@GLib.log_default_handler] and
* [func@GLib.log_writer_default] unless the `G_MESSAGES_DEBUG` environment variable is
* set appropriately. If you need to set the allowed domains at runtime, use
* [func@GLib.log_writer_default] unless the `G_MESSAGES_DEBUG` or
* `DEBUG_INVOCATION` environment variables are set appropriately. If you need
* to set the allowed domains at runtime, use
* [func@GLib.log_writer_default_set_debug_domains].
*
* If structured logging is enabled, this will use [func@GLib.log_structured];
@ -341,8 +342,9 @@
* manually.
*
* Such messages are suppressed by the [func@GLib.log_default_handler] and
* [func@GLib.log_writer_default] unless the `G_MESSAGES_DEBUG` environment variable is
* set appropriately. If you need to set the allowed domains at runtime, use
* [func@GLib.log_writer_default] unless the `G_MESSAGES_DEBUG` or
* `DEBUG_INVOCATION` environment variables are set appropriately. If you need
* to set the allowed domains at runtime, use
* [func@GLib.log_writer_default_set_debug_domains].
*
* If structured logging is enabled, this will use [func@GLib.log_structured];
@ -2705,7 +2707,7 @@ static struct {
* `NULL` or an array with no values means none. Array with a single value `"all"` means all.
*
* Reset the list of domains to be logged, that might be initially set by the
* `G_MESSAGES_DEBUG` environment variable.
* `G_MESSAGES_DEBUG` or `DEBUG_INVOCATION` environment variables.
*
* This function is thread-safe.
*
@ -2737,7 +2739,7 @@ should_drop_message (GLogLevelFlags log_level,
const GLogField *fields,
gsize n_fields)
{
/* Disable debug message output unless specified in G_MESSAGES_DEBUG. */
/* Disable debug message output unless specified in G_MESSAGES_DEBUG/DEBUG_INVOCATION. */
if (!(log_level & DEFAULT_LEVELS) &&
!(log_level >> G_LOG_LEVEL_USER_SHIFT) &&
!g_log_get_debug_enabled ())
@ -2750,6 +2752,8 @@ should_drop_message (GLogLevelFlags log_level,
if (G_UNLIKELY (!g_log_global.domains_set))
{
g_log_global.domains = g_strdup (g_getenv ("G_MESSAGES_DEBUG"));
if (g_log_global.domains == NULL && g_strcmp0 (g_getenv ("DEBUG_INVOCATION"), "1") == 0)
g_log_global.domains = g_strdup ("all");
g_log_global.domains_set = TRUE;
}
@ -2804,7 +2808,8 @@ should_drop_message (GLogLevelFlags log_level,
*
* As with [func@GLib.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, or by [func@GLib.log_writer_default_set_debug_domains].
* `G_MESSAGES_DEBUG` environment variable, or `DEBUG_INVOCATION=1` is set in
* the environment, or by [func@GLib.log_writer_default_set_debug_domains].
*
* This can be used when implementing log writers with the same filtering
* behaviour as the default, but a different destination or output format:
@ -2815,7 +2820,7 @@ should_drop_message (GLogLevelFlags log_level,
* ]|
*
* or to skip an expensive computation if it is only needed for a debugging
* message, and `G_MESSAGES_DEBUG` is not set:
* message, and `G_MESSAGES_DEBUG` and `DEBUG_INVOCATION` are not set:
*
* ```c
* if (!g_log_writer_default_would_drop (G_LOG_LEVEL_DEBUG, G_LOG_DOMAIN))
@ -2862,7 +2867,8 @@ g_log_writer_default_would_drop (GLogLevelFlags log_level,
*
* As with [func@GLib.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, or set at runtime by [func@GLib.log_writer_default_set_debug_domains].
* `G_MESSAGES_DEBUG` environment variable, or `DEBUG_INVOCATION=1` is set in
* the environment, or set at runtime by [func@GLib.log_writer_default_set_debug_domains].
*
* [func@GLib.log_writer_default] uses the mask set by [func@GLib.log_set_always_fatal] to
* determine which messages are fatal. When using a custom writer function instead it is
@ -3005,7 +3011,8 @@ _g_log_writer_fallback (GLogLevelFlags log_level,
* implementations.
*
* Note also that the value of this does not depend on `G_MESSAGES_DEBUG`, nor
* [func@GLib.log_writer_default_set_debug_domains]; see the docs for [func@GLib.log_set_debug_enabled].
* `DEBUG_INVOCATION`, nor [func@GLib.log_writer_default_set_debug_domains]; see
* the docs for [func@GLib.log_set_debug_enabled].
*
* Returns: `TRUE` if debug output is enabled, `FALSE` otherwise
*
@ -3023,7 +3030,7 @@ g_log_get_debug_enabled (void)
*
* Enable or disable debug output from the GLib logging system for all domains.
*
* This value interacts disjunctively with `G_MESSAGES_DEBUG` and
* This value interacts disjunctively with `G_MESSAGES_DEBUG`, `DEBUG_INVOCATION` and
* [func@GLib.log_writer_default_set_debug_domains] if any of them would allow
* a debug message to be outputted, it will be.
*
@ -3355,6 +3362,9 @@ escape_string (GString *string)
* which debug and informational messages are printed. By default
* these messages are not printed. If you need to set the allowed
* domains at runtime, use [func@GLib.log_writer_default_set_debug_domains].
* - `DEBUG_INVOCATION`: If set to `1`, this is equivalent to
* `G_MESSAGES_DEBUG=all`. `DEBUG_INVOCATION` is a standard environment
* variable set by systemd to prompt debug output. (Since: 2.84)
*
* `stderr` is used for levels [flags@GLib.LogLevelFlags.LEVEL_ERROR],
* [flags@GLib.LogLevelFlags.LEVEL_CRITICAL], [flags@GLib.LogLevelFlags.LEVEL_WARNING] and

View File

@ -153,7 +153,7 @@ test_default_handler_bar_info (void)
g_log_writer_default_set_use_stderr (FALSE);
g_log_set_default_handler (g_log_default_handler, NULL);
g_setenv ("G_MESSAGES_DEBUG", "foo bar baz", TRUE);
g_assert_cmpstr (g_getenv ("G_MESSAGES_DEBUG"), ==, "foo bar baz");
g_log ("bar", G_LOG_LEVEL_INFO, "message5");
exit (0);
@ -165,7 +165,7 @@ test_default_handler_baz_debug (void)
g_log_writer_default_set_use_stderr (FALSE);
g_log_set_default_handler (g_log_default_handler, NULL);
g_setenv ("G_MESSAGES_DEBUG", "foo bar baz", TRUE);
g_assert_cmpstr (g_getenv ("G_MESSAGES_DEBUG"), ==, "foo bar baz");
g_log ("baz", G_LOG_LEVEL_DEBUG, "message6");
exit (0);
@ -177,7 +177,7 @@ test_default_handler_debug (void)
g_log_writer_default_set_use_stderr (FALSE);
g_log_set_default_handler (g_log_default_handler, NULL);
g_setenv ("G_MESSAGES_DEBUG", "all", TRUE);
g_assert_cmpstr (g_getenv ("G_MESSAGES_DEBUG"), ==, "all");
g_log ("foo", G_LOG_LEVEL_DEBUG, "6");
g_log ("bar", G_LOG_LEVEL_DEBUG, "6");
@ -192,7 +192,7 @@ 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_assert_cmpstr (g_getenv ("G_MESSAGES_DEBUG"), ==, "all");
g_log ("foo", G_LOG_LEVEL_DEBUG, "6");
g_log ("bar", G_LOG_LEVEL_DEBUG, "6");
@ -201,10 +201,19 @@ test_default_handler_debug_stderr (void)
exit (0);
}
static void
test_default_handler_would_drop_env_systemd (void)
{
g_assert_cmpstr (g_getenv ("DEBUG_INVOCATION"), ==, "1");
g_assert_false (g_log_writer_default_would_drop (G_LOG_LEVEL_DEBUG, "foo"));
g_assert_false (g_log_writer_default_would_drop (G_LOG_LEVEL_DEBUG, "bar"));
}
static void
test_default_handler_would_drop_env5 (void)
{
g_setenv ("G_MESSAGES_DEBUG", "foobar", TRUE);
g_assert_cmpstr (g_getenv ("G_MESSAGES_DEBUG"), ==, "foobar");
g_assert_true (g_log_writer_default_would_drop (G_LOG_LEVEL_DEBUG, "foo"));
g_assert_true (g_log_writer_default_would_drop (G_LOG_LEVEL_DEBUG, "bar"));
@ -213,7 +222,7 @@ test_default_handler_would_drop_env5 (void)
static void
test_default_handler_would_drop_env4 (void)
{
g_setenv ("G_MESSAGES_DEBUG", "all", TRUE);
g_assert_cmpstr (g_getenv ("G_MESSAGES_DEBUG"), ==, "all");
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"));
@ -227,7 +236,7 @@ test_default_handler_would_drop_env4 (void)
static void
test_default_handler_would_drop_env3 (void)
{
g_setenv ("G_MESSAGES_DEBUG", "foo bar", TRUE);
g_assert_cmpstr (g_getenv ("G_MESSAGES_DEBUG"), ==, "foo bar");
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"));
@ -241,7 +250,7 @@ test_default_handler_would_drop_env3 (void)
static void
test_default_handler_would_drop_env2 (void)
{
g_setenv ("G_MESSAGES_DEBUG", " bar baz ", TRUE);
g_assert_cmpstr (g_getenv ("G_MESSAGES_DEBUG"), ==, " bar baz ");
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"));
@ -255,7 +264,7 @@ test_default_handler_would_drop_env2 (void)
static void
test_default_handler_would_drop_env1 (void)
{
g_unsetenv ("G_MESSAGES_DEBUG");
g_assert_null (g_getenv ("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"));
@ -269,7 +278,7 @@ test_default_handler_would_drop_env1 (void)
static void
test_default_handler_would_drop (void)
{
g_unsetenv ("G_MESSAGES_DEBUG");
g_assert_null (g_getenv ("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"));
@ -440,7 +449,7 @@ test_default_handler_structured_logging_non_nul_terminated_strings (void)
{
g_log_writer_default_set_use_stderr (FALSE);
g_log_set_default_handler (g_log_default_handler, NULL);
g_setenv ("G_MESSAGES_DEBUG", "foo", TRUE);
g_assert_cmpstr (g_getenv ("G_MESSAGES_DEBUG"), ==, "foo");
const gchar domain_1[] = {'f', 'o', 'o' };
const gchar domain_2[] = { 'b', 'a', 'r' };
@ -461,108 +470,143 @@ test_default_handler_structured_logging_non_nul_terminated_strings (void)
exit (0);
}
/* Helper wrapper around g_test_trap_subprocess_with_envp() which sets the
* logging-related environment variables. `NULL` will unset a variable. */
static void
test_trap_subprocess_with_logging_envp (const char *test_path,
const char *g_messages_debug,
const char *debug_invocation)
{
char **envp = g_get_environ ();
if (g_messages_debug != NULL)
envp = g_environ_setenv (g_steal_pointer (&envp), "G_MESSAGES_DEBUG", g_messages_debug, TRUE);
else
envp = g_environ_unsetenv (g_steal_pointer (&envp), "G_MESSAGES_DEBUG");
if (debug_invocation != NULL)
envp = g_environ_setenv (g_steal_pointer (&envp), "DEBUG_INVOCATION", debug_invocation, TRUE);
else
envp = g_environ_unsetenv (g_steal_pointer (&envp), "DEBUG_INVOCATION");
g_test_trap_subprocess_with_envp (test_path, (const char * const *) envp, 0, G_TEST_SUBPROCESS_DEFAULT);
g_strfreev (envp);
}
static void
test_default_handler (void)
{
g_test_trap_subprocess ("/logging/default-handler/subprocess/error", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/error",
NULL, NULL);
g_test_trap_assert_failed ();
g_test_trap_assert_stderr ("*ERROR*message1*");
g_test_trap_subprocess ("/logging/default-handler/subprocess/error-stderr", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/error-stderr",
NULL, NULL);
g_test_trap_assert_failed ();
g_test_trap_assert_stderr ("*ERROR*message1*");
g_test_trap_subprocess ("/logging/default-handler/subprocess/critical", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/critical",
NULL, NULL);
g_test_trap_assert_failed ();
g_test_trap_assert_stderr ("*CRITICAL*message2*");
g_test_trap_subprocess ("/logging/default-handler/subprocess/critical-stderr", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/critical-stderr",
NULL, NULL);
g_test_trap_assert_failed ();
g_test_trap_assert_stderr ("*CRITICAL*message2*");
g_test_trap_subprocess ("/logging/default-handler/subprocess/warning", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/warning",
NULL, NULL);
g_test_trap_assert_failed ();
g_test_trap_assert_stderr ("*WARNING*message3*");
g_test_trap_subprocess ("/logging/default-handler/subprocess/warning-stderr", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/warning-stderr",
NULL, NULL);
g_test_trap_assert_failed ();
g_test_trap_assert_stderr ("*WARNING*message3*");
g_test_trap_subprocess ("/logging/default-handler/subprocess/message", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/message",
NULL, NULL);
g_test_trap_assert_passed ();
g_test_trap_assert_stderr ("*Message*message4*");
g_test_trap_subprocess ("/logging/default-handler/subprocess/message-stderr", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/message-stderr",
NULL, NULL);
g_test_trap_assert_passed ();
g_test_trap_assert_stderr ("*Message*message4*");
g_test_trap_subprocess ("/logging/default-handler/subprocess/info", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/info",
NULL, NULL);
g_test_trap_assert_passed ();
g_test_trap_assert_stdout_unmatched ("*INFO*message5*");
g_test_trap_subprocess ("/logging/default-handler/subprocess/info-stderr", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/info-stderr",
NULL, NULL);
g_test_trap_assert_passed ();
g_test_trap_assert_stderr_unmatched ("*INFO*message5*");
g_test_trap_subprocess ("/logging/default-handler/subprocess/bar-info", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/bar-info",
"foo bar baz", NULL);
g_test_trap_assert_passed ();
g_test_trap_assert_stdout ("*INFO*message5*");
g_test_trap_subprocess ("/logging/default-handler/subprocess/baz-debug", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/baz-debug",
"foo bar baz", NULL);
g_test_trap_assert_passed ();
g_test_trap_assert_stdout ("*DEBUG*message6*");
g_test_trap_subprocess ("/logging/default-handler/subprocess/debug", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/debug",
"all", NULL);
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,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/debug-stderr",
"all", NULL);
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,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/0x400",
NULL, NULL);
g_test_trap_assert_passed ();
g_test_trap_assert_stdout ("*LOG-0x400*message7*");
g_test_trap_subprocess ("/logging/default-handler/subprocess/would-drop", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/would-drop",
NULL, NULL);
g_test_trap_assert_passed ();
g_test_trap_subprocess ("/logging/default-handler/subprocess/would-drop-env1", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/would-drop-env1",
NULL, NULL);
g_test_trap_assert_passed ();
g_test_trap_subprocess ("/logging/default-handler/subprocess/would-drop-env2", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/would-drop-env2",
" bar baz ", NULL);
g_test_trap_assert_passed ();
g_test_trap_subprocess ("/logging/default-handler/subprocess/would-drop-env3", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/would-drop-env3",
"foo bar", NULL);
g_test_trap_assert_passed ();
g_test_trap_subprocess ("/logging/default-handler/subprocess/would-drop-env4", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/would-drop-env4",
"all", NULL);
g_test_trap_assert_passed ();
g_test_trap_subprocess ("/logging/default-handler/subprocess/would-drop-env5", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/would-drop-env5",
"foobar", NULL);
g_test_trap_assert_passed ();
g_test_trap_subprocess ("/logging/default-handler/subprocess/would-drop-robustness", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/would-drop-env-systemd",
NULL, "1");
g_test_trap_assert_passed ();
g_test_trap_subprocess ("/logging/default-handler/subprocess/structured-logging-non-null-terminated-strings", 0,
G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/would-drop-robustness",
NULL, NULL);
g_test_trap_assert_passed ();
test_trap_subprocess_with_logging_envp ("/logging/default-handler/subprocess/structured-logging-non-null-terminated-strings",
"foo", NULL);
g_test_trap_assert_passed ();
g_test_trap_assert_stdout_unmatched ("*bar*");
g_test_trap_assert_stdout_unmatched ("*bla*");
@ -575,10 +619,11 @@ test_fatal_log_mask (void)
if (g_test_subprocess ())
{
g_log_set_fatal_mask ("bu", G_LOG_LEVEL_INFO);
g_assert_null (g_getenv ("G_MESSAGES_DEBUG"));
g_log ("bu", G_LOG_LEVEL_INFO, "fatal");
return;
}
g_test_trap_subprocess (NULL, 0, G_TEST_SUBPROCESS_DEFAULT);
test_trap_subprocess_with_logging_envp (NULL, NULL, NULL);
g_test_trap_assert_failed ();
/* G_LOG_LEVEL_INFO isn't printed by default */
g_test_trap_assert_stdout_unmatched ("*fatal*");
@ -1079,8 +1124,6 @@ test_structured_logging_set_writer_func_twice (void)
int
main (int argc, char *argv[])
{
g_unsetenv ("G_MESSAGES_DEBUG");
g_test_init (&argc, &argv, NULL);
g_test_add_func ("/logging/default-handler", test_default_handler);
@ -1105,6 +1148,7 @@ main (int argc, char *argv[])
g_test_add_func ("/logging/default-handler/subprocess/would-drop-env3", test_default_handler_would_drop_env3);
g_test_add_func ("/logging/default-handler/subprocess/would-drop-env4", test_default_handler_would_drop_env4);
g_test_add_func ("/logging/default-handler/subprocess/would-drop-env5", test_default_handler_would_drop_env5);
g_test_add_func ("/logging/default-handler/subprocess/would-drop-env-systemd", test_default_handler_would_drop_env_systemd);
g_test_add_func ("/logging/default-handler/subprocess/would-drop-robustness", test_default_handler_would_drop_robustness);
g_test_add_func ("/logging/default-handler/subprocess/structured-logging-non-null-terminated-strings", test_default_handler_structured_logging_non_nul_terminated_strings);
g_test_add_func ("/logging/warnings", test_warnings);