From dfb3517d3790c014f7c964414405cd9775ad4b9d Mon Sep 17 00:00:00 2001 From: Philip Withnall Date: Mon, 25 Apr 2022 12:23:45 +0100 Subject: [PATCH] gmessages: Error if g_log_set_writer_func() is called multiple times Inspired by https://gitlab.gnome.org/GNOME/glib/-/issues/2638. This requires moving the tests to subprocesses, so that `g_log_set_writer_func()` is only called once per process. It also adds a test for the new error. Signed-off-by: Philip Withnall --- glib/gmessages.c | 9 ++ glib/tests/logging.c | 316 ++++++++++++++++++++++++++++--------------- 2 files changed, 216 insertions(+), 109 deletions(-) diff --git a/glib/gmessages.c b/glib/gmessages.c index 008bf5c13..c1fa98cb2 100644 --- a/glib/gmessages.c +++ b/glib/gmessages.c @@ -2059,9 +2059,18 @@ g_log_set_writer_func (GLogWriterFunc func, g_return_if_fail (func != NULL); g_mutex_lock (&g_messages_lock); + + if (log_writer_func != g_log_writer_default) + { + g_mutex_unlock (&g_messages_lock); + g_error ("g_log_set_writer_func() called multiple times"); + return; + } + log_writer_func = func; log_writer_user_data = user_data; log_writer_user_data_free = user_data_free; + g_mutex_unlock (&g_messages_lock); } diff --git a/glib/tests/logging.c b/glib/tests/logging.c index e9c4e396c..b79362a7d 100644 --- a/glib/tests/logging.c +++ b/glib/tests/logging.c @@ -445,136 +445,196 @@ expect_log_writer (GLogLevelFlags log_level, static void test_structured_logging_no_state (void) { - gpointer some_pointer = GUINT_TO_POINTER (0x100); - guint some_integer = 123; + /* Test has to run in a subprocess as it calls g_log_set_writer_func(), which + * can only be called once per process. */ + if (g_test_subprocess ()) + { + gpointer some_pointer = GUINT_TO_POINTER (0x100); + guint some_integer = 123; - log_count = 0; - g_log_set_writer_func (null_log_writer, NULL, NULL); + log_count = 0; + g_log_set_writer_func (null_log_writer, NULL, NULL); - g_log_structured ("some-domain", G_LOG_LEVEL_MESSAGE, - "MESSAGE_ID", "06d4df59e6c24647bfe69d2c27ef0b4e", - "MY_APPLICATION_CUSTOM_FIELD", "some debug string", - "MESSAGE", "This is a debug message about pointer %p and integer %u.", - some_pointer, some_integer); + g_log_structured ("some-domain", G_LOG_LEVEL_MESSAGE, + "MESSAGE_ID", "06d4df59e6c24647bfe69d2c27ef0b4e", + "MY_APPLICATION_CUSTOM_FIELD", "some debug string", + "MESSAGE", "This is a debug message about pointer %p and integer %u.", + some_pointer, some_integer); - g_assert_cmpint (log_count, ==, 1); + g_assert_cmpint (log_count, ==, 1); + } + else + { + g_test_trap_subprocess (NULL, 0, 0); + g_test_trap_assert_passed (); + } } 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 }, - }; + /* Test has to run in a subprocess as it calls g_log_set_writer_func(), which + * can only be called once per process. */ + if (g_test_subprocess ()) + { + 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 }, + }; - log_count = 0; - g_log_set_writer_func (null_log_writer, NULL, NULL); + log_count = 0; + g_log_set_writer_func (null_log_writer, NULL, NULL); - g_log_structured_array (G_LOG_LEVEL_DEBUG, fields, G_N_ELEMENTS (fields)); + g_log_structured_array (G_LOG_LEVEL_DEBUG, fields, G_N_ELEMENTS (fields)); - g_assert_cmpint (log_count, ==, 1); + g_assert_cmpint (log_count, ==, 1); + } + else + { + g_test_trap_subprocess (NULL, 0, 0); + g_test_trap_assert_passed (); + } } static void test_structured_logging_robustness (void) { - log_count = 0; - g_log_set_writer_func (null_log_writer, NULL, NULL); + /* Test has to run in a subprocess as it calls g_log_set_writer_func(), which + * can only be called once per process. */ + if (g_test_subprocess ()) + { + log_count = 0; + g_log_set_writer_func (null_log_writer, NULL, NULL); - /* NULL log_domain shouldn't crash */ - g_log (NULL, G_LOG_LEVEL_MESSAGE, "Test"); - g_log_structured (NULL, G_LOG_LEVEL_MESSAGE, "MESSAGE", "Test"); + /* NULL log_domain shouldn't crash */ + g_log (NULL, G_LOG_LEVEL_MESSAGE, "Test"); + g_log_structured (NULL, G_LOG_LEVEL_MESSAGE, "MESSAGE", "Test"); - g_assert_cmpint (log_count, ==, 1); + g_assert_cmpint (log_count, ==, 2); + } + else + { + g_test_trap_subprocess (NULL, 0, 0); + g_test_trap_assert_passed (); + } } static void test_structured_logging_roundtrip1 (void) { - gpointer some_pointer = GUINT_TO_POINTER (0x100); - gint some_integer = 123; - gchar message[200]; - GLogField fields[] = { - { "GLIB_DOMAIN", "some-domain", -1 }, - { "PRIORITY", "5", -1 }, - { "MESSAGE", "String assigned using g_snprintf() below", -1 }, - { "MESSAGE_ID", "fcfb2e1e65c3494386b74878f1abf893", -1 }, - { "MY_APPLICATION_CUSTOM_FIELD", "some debug string", -1 } - }; - ExpectedMessage expected = { fields, 5 }; - - /* %p format is implementation defined and depends on the platform */ - g_snprintf (message, sizeof (message), - "This is a debug message about pointer %p and integer %u.", - some_pointer, some_integer); - fields[2].value = message; - - expected_messages = g_slist_append (NULL, &expected); - g_log_set_writer_func (expect_log_writer, NULL, NULL); - - g_log_structured ("some-domain", G_LOG_LEVEL_MESSAGE, - "MESSAGE_ID", "fcfb2e1e65c3494386b74878f1abf893", - "MY_APPLICATION_CUSTOM_FIELD", "some debug string", - "MESSAGE", "This is a debug message about pointer %p and integer %u.", - some_pointer, some_integer); - - if (expected_messages != NULL) + /* Test has to run in a subprocess as it calls g_log_set_writer_func(), which + * can only be called once per process. */ + if (g_test_subprocess ()) { - char *str; - ExpectedMessage *msg = expected_messages->data; + gpointer some_pointer = GUINT_TO_POINTER (0x100); + gint some_integer = 123; + gchar message[200]; + GLogField fields[] = { + { "GLIB_DOMAIN", "some-domain", -1 }, + { "PRIORITY", "5", -1 }, + { "MESSAGE", "String assigned using g_snprintf() below", -1 }, + { "MESSAGE_ID", "fcfb2e1e65c3494386b74878f1abf893", -1 }, + { "MY_APPLICATION_CUSTOM_FIELD", "some debug string", -1 } + }; + ExpectedMessage expected = { fields, 5 }; - str = g_log_writer_format_fields (0, msg->fields, msg->n_fields, FALSE); - g_test_fail_printf ("Unexpected message: %s", str); - g_free (str); + /* %p format is implementation defined and depends on the platform */ + g_snprintf (message, sizeof (message), + "This is a debug message about pointer %p and integer %u.", + some_pointer, some_integer); + fields[2].value = message; + + expected_messages = g_slist_append (NULL, &expected); + g_log_set_writer_func (expect_log_writer, NULL, NULL); + + g_log_structured ("some-domain", G_LOG_LEVEL_MESSAGE, + "MESSAGE_ID", "fcfb2e1e65c3494386b74878f1abf893", + "MY_APPLICATION_CUSTOM_FIELD", "some debug string", + "MESSAGE", "This is a debug message about pointer %p and integer %u.", + some_pointer, some_integer); + + if (expected_messages != NULL) + { + char *str; + ExpectedMessage *msg = expected_messages->data; + + str = g_log_writer_format_fields (0, msg->fields, msg->n_fields, FALSE); + g_test_fail_printf ("Unexpected message: %s", str); + g_free (str); + } + } + else + { + g_test_trap_subprocess (NULL, 0, 0); + g_test_trap_assert_passed (); } } static void test_structured_logging_roundtrip2 (void) { - const gchar *some_string = "abc"; - const GLogField fields[] = { - { "GLIB_DOMAIN", "some-domain", -1 }, - { "PRIORITY", "5", -1 }, - { "MESSAGE", "This is a debug message about string 'abc'.", -1 }, - { "MESSAGE_ID", "fcfb2e1e65c3494386b74878f1abf893", -1 }, - { "MY_APPLICATION_CUSTOM_FIELD", "some debug string", -1 } - }; - ExpectedMessage expected = { fields, 5 }; + /* Test has to run in a subprocess as it calls g_log_set_writer_func(), which + * can only be called once per process. */ + if (g_test_subprocess ()) + { + const gchar *some_string = "abc"; + const GLogField fields[] = { + { "GLIB_DOMAIN", "some-domain", -1 }, + { "PRIORITY", "5", -1 }, + { "MESSAGE", "This is a debug message about string 'abc'.", -1 }, + { "MESSAGE_ID", "fcfb2e1e65c3494386b74878f1abf893", -1 }, + { "MY_APPLICATION_CUSTOM_FIELD", "some debug string", -1 } + }; + ExpectedMessage expected = { fields, 5 }; - expected_messages = g_slist_append (NULL, &expected); - g_log_set_writer_func (expect_log_writer, NULL, NULL); + expected_messages = g_slist_append (NULL, &expected); + g_log_set_writer_func (expect_log_writer, NULL, NULL); - g_log_structured ("some-domain", G_LOG_LEVEL_MESSAGE, - "MESSAGE_ID", "fcfb2e1e65c3494386b74878f1abf893", - "MY_APPLICATION_CUSTOM_FIELD", "some debug string", - "MESSAGE", "This is a debug message about string '%s'.", - some_string); + g_log_structured ("some-domain", G_LOG_LEVEL_MESSAGE, + "MESSAGE_ID", "fcfb2e1e65c3494386b74878f1abf893", + "MY_APPLICATION_CUSTOM_FIELD", "some debug string", + "MESSAGE", "This is a debug message about string '%s'.", + some_string); - g_assert (expected_messages == NULL); + g_assert (expected_messages == NULL); + } + else + { + g_test_trap_subprocess (NULL, 0, 0); + g_test_trap_assert_passed (); + } } static void test_structured_logging_roundtrip3 (void) { - const GLogField fields[] = { - { "GLIB_DOMAIN", "some-domain", -1 }, - { "PRIORITY", "4", -1 }, - { "MESSAGE", "Test test test.", -1 } - }; - ExpectedMessage expected = { fields, 3 }; + /* Test has to run in a subprocess as it calls g_log_set_writer_func(), which + * can only be called once per process. */ + if (g_test_subprocess ()) + { + const GLogField fields[] = { + { "GLIB_DOMAIN", "some-domain", -1 }, + { "PRIORITY", "4", -1 }, + { "MESSAGE", "Test test test.", -1 } + }; + ExpectedMessage expected = { fields, 3 }; - expected_messages = g_slist_append (NULL, &expected); - g_log_set_writer_func (expect_log_writer, NULL, NULL); + expected_messages = g_slist_append (NULL, &expected); + g_log_set_writer_func (expect_log_writer, NULL, NULL); - g_log_structured ("some-domain", G_LOG_LEVEL_WARNING, - "MESSAGE", "Test test test."); + g_log_structured ("some-domain", G_LOG_LEVEL_WARNING, + "MESSAGE", "Test test test."); - g_assert (expected_messages == NULL); + g_assert (expected_messages == NULL); + } + else + { + g_test_trap_subprocess (NULL, 0, 0); + g_test_trap_assert_passed (); + } } static GVariant * @@ -597,36 +657,73 @@ create_variant_fields (void) static void test_structured_logging_variant1 (void) { - GVariant *v = create_variant_fields (); + /* Test has to run in a subprocess as it calls g_log_set_writer_func(), which + * can only be called once per process. */ + if (g_test_subprocess ()) + { + GVariant *v = create_variant_fields (); - log_count = 0; - g_log_set_writer_func (null_log_writer, NULL, NULL); + log_count = 0; + g_log_set_writer_func (null_log_writer, NULL, NULL); - g_log_variant ("some-domain", G_LOG_LEVEL_MESSAGE, v); - g_variant_unref (v); - g_assert_cmpint (log_count, ==, 1); + g_log_variant ("some-domain", G_LOG_LEVEL_MESSAGE, v); + g_variant_unref (v); + g_assert_cmpint (log_count, ==, 1); + } + else + { + g_test_trap_subprocess (NULL, 0, 0); + g_test_trap_assert_passed (); + } } static void test_structured_logging_variant2 (void) { - const GLogField fields[] = { - { "GLIB_DOMAIN", "some-domain", -1 }, - { "PRIORITY", "5", -1 }, - { "MESSAGE", "This is a debug message", -1 }, - { "MESSAGE_ID", "06d4df59e6c24647bfe69d2c27ef0b4e", -1 }, - { "MY_APPLICATION_CUSTOM_FIELD", "some debug string", -1 }, - { "MY_APPLICATION_CUSTOM_FIELD_BINARY", binary_field, sizeof (binary_field) } - }; - ExpectedMessage expected = { fields, 6 }; - GVariant *v = create_variant_fields (); + /* Test has to run in a subprocess as it calls g_log_set_writer_func(), which + * can only be called once per process. */ + if (g_test_subprocess ()) + { + const GLogField fields[] = { + { "GLIB_DOMAIN", "some-domain", -1 }, + { "PRIORITY", "5", -1 }, + { "MESSAGE", "This is a debug message", -1 }, + { "MESSAGE_ID", "06d4df59e6c24647bfe69d2c27ef0b4e", -1 }, + { "MY_APPLICATION_CUSTOM_FIELD", "some debug string", -1 }, + { "MY_APPLICATION_CUSTOM_FIELD_BINARY", binary_field, sizeof (binary_field) } + }; + ExpectedMessage expected = { fields, 6 }; + GVariant *v = create_variant_fields (); - expected_messages = g_slist_append (NULL, &expected); - g_log_set_writer_func (expect_log_writer, NULL, NULL); + expected_messages = g_slist_append (NULL, &expected); + g_log_set_writer_func (expect_log_writer, NULL, NULL); - g_log_variant ("some-domain", G_LOG_LEVEL_MESSAGE, v); - g_variant_unref (v); - g_assert (expected_messages == NULL); + g_log_variant ("some-domain", G_LOG_LEVEL_MESSAGE, v); + g_variant_unref (v); + g_assert (expected_messages == NULL); + } + else + { + g_test_trap_subprocess (NULL, 0, 0); + g_test_trap_assert_passed (); + } +} + +static void +test_structured_logging_set_writer_func_twice (void) +{ + /* Test has to run in a subprocess as it calls g_log_set_writer_func() and + * causes an error. */ + if (g_test_subprocess ()) + { + g_log_set_writer_func (null_log_writer, NULL, NULL); + g_log_set_writer_func (expect_log_writer, NULL, NULL); + } + else + { + g_test_trap_subprocess (NULL, 0, 0); + g_test_trap_assert_failed (); + } } int @@ -663,6 +760,7 @@ main (int argc, char *argv[]) g_test_add_func ("/structured-logging/roundtrip3", test_structured_logging_roundtrip3); g_test_add_func ("/structured-logging/variant1", test_structured_logging_variant1); g_test_add_func ("/structured-logging/variant2", test_structured_logging_variant2); + g_test_add_func ("/structured-logging/set-writer-func-twice", test_structured_logging_set_writer_func_twice); return g_test_run (); }