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 <pwithnall@endlessos.org>
This commit is contained in:
Philip Withnall 2022-04-25 12:23:45 +01:00
parent cc99d6ee97
commit dfb3517d37
2 changed files with 216 additions and 109 deletions

View File

@ -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);
}

View File

@ -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 ();
}