From fc6852c47a65dfadf415a09706e3dadf97be5ec0 Mon Sep 17 00:00:00 2001 From: Philip Withnall Date: Tue, 14 Aug 2018 16:04:47 +0100 Subject: [PATCH] tests: Port log message handling in tests to use structured logging MIME-Version: 1.0 Content-Type: text/plain; charset=utf8 Content-Transfer-Encoding: 8bit Otherwise the tests fail now that we’re compiling with G_LOG_USE_STRUCTURED. Signed-off-by: Philip Withnall --- tests/client.c | 35 +++++------ tests/engine.c | 187 +++++++++++++++++++++++++++++++++++++++++++++------------ 2 files changed, 162 insertions(+), 60 deletions(-) diff --git a/tests/client.c b/tests/client.c index 6390438..4727e0c 100644 --- a/tests/client.c +++ b/tests/client.c @@ -86,28 +86,22 @@ fail_one_call (void) g_error_free (error); } -static void -log_handler (const gchar *log_domain, - GLogLevelFlags log_level, - const gchar *message, - gpointer user_data) +static GLogWriterOutput +log_writer_cb (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields, + gpointer user_data) { - if (strstr (message, "--expected error from testcase--")) - return; - - g_log_default_handler (log_domain, log_level, message, user_data); -} + gsize i; -static gboolean -fatal_log_handler (const gchar *log_domain, - GLogLevelFlags log_level, - const gchar *message, - gpointer user_data) -{ - if (strstr (message, "--expected error from testcase--")) - return FALSE; + for (i = 0; i < n_fields; i++) + { + if (g_strcmp0 (fields[i].key, "MESSAGE") == 0 && + strstr (fields[i].value, "--expected error from testcase--")) + return G_LOG_WRITER_HANDLED; + } - return TRUE; + return G_LOG_WRITER_UNHANDLED; } static void @@ -116,8 +110,7 @@ test_fast (void) DConfClient *client; gint i; - g_log_set_default_handler (log_handler, NULL); - g_test_log_set_fatal_handler (fatal_log_handler, NULL); + g_log_set_writer_func (log_writer_cb, NULL, NULL); client = dconf_client_new (); g_signal_connect (client, "changed", G_CALLBACK (changed), NULL); diff --git a/tests/engine.c b/tests/engine.c index 32b43f3..7f2a748 100644 --- a/tests/engine.c +++ b/tests/engine.c @@ -35,6 +35,14 @@ fopen (const char *filename, return (* real_fopen) (filename, mode); } +static void assert_no_messages (void); +static void assert_pop_message (const gchar *expected_domain, + GLogLevelFlags expected_log_level, + const gchar *expected_message_fragment); +static void assert_maybe_pop_message (const gchar *expected_domain, + GLogLevelFlags expected_log_level, + const gchar *expected_message_fragment); + static GThread *main_thread; static GString *change_log; @@ -360,12 +368,13 @@ test_file_source (void) g_assert (source != NULL); g_assert (source->values == NULL); g_assert (source->locks == NULL); - g_test_expect_message ("dconf", G_LOG_LEVEL_WARNING, "*unable to open file '/path/to/db'*"); reopened = dconf_engine_source_refresh (source); g_assert (source->values == NULL); g_assert (source->locks == NULL); dconf_engine_source_free (source); + assert_pop_message ("dconf", G_LOG_LEVEL_WARNING, "unable to open file '/path/to/db'"); + source = dconf_engine_source_new ("file-db:/path/to/db"); g_assert (source != NULL); g_assert (source->values == NULL); @@ -920,35 +929,6 @@ check_read (DConfEngine *engine, } } -static gboolean -is_expected (const gchar *log_domain, - GLogLevelFlags log_level, - const gchar *message) -{ - return g_str_equal (log_domain, "dconf") && - log_level == (G_LOG_LEVEL_WARNING | G_LOG_FLAG_FATAL) && - strstr (message, "unable to open file '" SYSCONFDIR "/dconf/db"); -} - -static gboolean -fatal_handler (const gchar *log_domain, - GLogLevelFlags log_level, - const gchar *message, - gpointer user_data) -{ - return !is_expected (log_domain, log_level, message); -} - -static void -normal_handler (const gchar *log_domain, - GLogLevelFlags log_level, - const gchar *message, - gpointer user_data) -{ - if (!is_expected (log_domain, log_level, message)) - g_error ("unexpected error: %s\n", message); -} - static void test_read (void) { @@ -959,13 +939,10 @@ test_read (void) DConfEngine *engine; guint i, j, k; guint n; - guint handler_id; /* This test throws a lot of messages about missing databases. * Capture and ignore them. */ - g_test_log_set_fatal_handler (fatal_handler, NULL); - handler_id = g_log_set_handler ("dconf", G_LOG_LEVEL_WARNING | G_LOG_FLAG_FATAL, normal_handler, NULL); /* Our test strategy is as follows: * @@ -1130,6 +1107,9 @@ test_read (void) /* Clean up */ setup_state (n, i, 0, NULL); dconf_engine_unref (engine); + + assert_maybe_pop_message ("dconf", G_LOG_LEVEL_WARNING, + "unable to open file '" SYSCONFDIR "/dconf/db"); } } @@ -1138,7 +1118,7 @@ test_read (void) g_free (profile_filename); dconf_mock_shm_reset (); - g_log_remove_handler ("dconf", handler_id); + assert_no_messages (); } static void @@ -1554,13 +1534,14 @@ test_change_fast (void) g_variant_unref (value); /* Fail the attempted write. This should cause a warning and a change. */ - g_test_expect_message ("dconf", G_LOG_LEVEL_WARNING, "failed to commit changes to dconf: something failed"); error = g_error_new_literal (G_FILE_ERROR, G_FILE_ERROR_NOENT, "something failed"); dconf_mock_dbus_async_reply (NULL, error); g_clear_error (&error); g_assert_cmpstr (change_log->str, ==, "/value:1::nil;"); g_string_set_size (change_log, 0); + assert_pop_message ("dconf", G_LOG_LEVEL_WARNING, "failed to commit changes to dconf: something failed"); + /* Verify that the value became unset due to the failure */ value = dconf_engine_read (engine, DCONF_READ_FLAGS_NONE, NULL, "value"); g_assert (value == NULL); @@ -1605,12 +1586,12 @@ test_change_fast (void) value = dconf_engine_read (engine, DCONF_READ_FLAGS_NONE, NULL, "/value"); g_assert_cmpstr (g_variant_get_string (value, NULL), ==, "value"); g_variant_unref (value); - g_test_expect_message ("dconf", G_LOG_LEVEL_WARNING, "failed to commit changes to dconf: something failed"); error = g_error_new_literal (G_FILE_ERROR, G_FILE_ERROR_NOENT, "something failed"); dconf_mock_dbus_async_reply (NULL, error); g_clear_error (&error); g_assert_cmpstr (change_log->str, ==, "/:2:to-reset,value:nil;"); g_string_set_size (change_log, 0); + assert_pop_message ("dconf", G_LOG_LEVEL_WARNING, "failed to commit changes to dconf: something failed"); value = dconf_engine_read (engine, DCONF_READ_FLAGS_NONE, NULL, "value"); g_assert (value == NULL); dconf_mock_dbus_assert_no_async (); @@ -1885,12 +1866,13 @@ test_sync (void) /* The write will try to check the system-db for a lock. That will * fail because it doesn't exist... */ - g_test_expect_message ("dconf", G_LOG_LEVEL_WARNING, "*unable to open file*"); change = dconf_changeset_new_write ("/value", g_variant_new_boolean (TRUE)); success = dconf_engine_change_fast (engine, change, NULL, &error); g_assert_no_error (error); g_assert (success); + assert_pop_message ("dconf", G_LOG_LEVEL_WARNING, "unable to open file"); + /* Spin up some waiters */ for (i = 0; i < G_N_ELEMENTS (waiter_threads); i++) waiter_threads[i] = g_thread_new ("test waiter", waiter_thread, engine); @@ -1911,10 +1893,12 @@ test_sync (void) waiter_threads[i] = g_thread_new ("test waiter", waiter_thread, engine); g_usleep(100 * G_TIME_SPAN_MILLISECOND); error = g_error_new_literal (G_FILE_ERROR, G_FILE_ERROR_NOENT, "some error"); - g_test_expect_message ("dconf", G_LOG_LEVEL_WARNING, "failed to commit changes to dconf: some error"); g_atomic_int_set (&it_is_good_to_be_done, TRUE); dconf_mock_dbus_async_reply (NULL, error); g_clear_error (&error); + + assert_pop_message ("dconf", G_LOG_LEVEL_WARNING, "failed to commit changes to dconf: some error"); + /* Make sure they all quit by joining them */ for (i = 0; i < G_N_ELEMENTS (waiter_threads); i++) g_thread_join (waiter_threads[i]); @@ -1950,6 +1934,122 @@ test_sync (void) dconf_mock_shm_reset (); } +/* Log handling. */ +typedef struct +{ + GLogLevelFlags log_level; + GLogField *fields; + gsize n_fields; +} LogMessage; + +static void +log_message_clear (LogMessage *message) +{ + gsize i; + + for (i = 0; i < message->n_fields; i++) + { + g_free ((gpointer) message->fields[i].key); + g_free ((gpointer) message->fields[i].value); + } +} + +static GArray *logged_messages = NULL; + +static GLogWriterOutput +log_writer_cb (GLogLevelFlags log_level, + const GLogField *fields, + gsize n_fields, + gpointer user_data) +{ + LogMessage *message; + gsize i; + + /* If we’re running as a subprocess, the parent process is going to be + * checking our stderr, so just behave normally. */ + if (g_test_subprocess ()) + return g_log_writer_default (log_level, fields, n_fields, user_data); + + /* We only care about dconf messages and non-debug messages. */ + if (log_level == G_LOG_LEVEL_DEBUG) + return G_LOG_WRITER_HANDLED; + + for (i = 0; i < n_fields; i++) + { + if (g_strcmp0 (fields[i].key, "GLIB_DOMAIN") == 0 && + g_strcmp0 (fields[i].value, "dconf") != 0) + return G_LOG_WRITER_HANDLED; + } + + /* Append the message to the queue. */ + g_array_set_size (logged_messages, logged_messages->len + 1); + message = &g_array_index (logged_messages, LogMessage, logged_messages->len - 1); + + message->log_level = log_level; + message->fields = g_new0 (GLogField, n_fields); + message->n_fields = n_fields; + + for (i = 0; i < n_fields; i++) + { + gsize length = (fields[i].length < 0) ? strlen (fields[i].value) + 1 : fields[i].length; + message->fields[i].key = g_strdup (fields[i].key); + message->fields[i].value = g_malloc0 (length); + memcpy ((gpointer) message->fields[i].value, fields[i].value, length); + message->fields[i].length = fields[i].length; + } + + return G_LOG_WRITER_HANDLED; +} + +/* Assert there are no logged messages in the queue. */ +static void +assert_no_messages (void) +{ + g_assert_cmpuint (logged_messages->len, ==, 0); +} + +/* Assert there is at least one logged message in the queue, and the oldest + * logged message matches the given expectations. If so, pop it from the queue; + * if not, abort. */ +static void +assert_pop_message (const gchar *expected_domain, + GLogLevelFlags expected_log_level, + const gchar *expected_message_fragment) +{ + const LogMessage *logged_message; + gsize i; + const gchar *message = NULL, *domain = NULL; + + g_assert_cmpuint (logged_messages->len, >, 0); + logged_message = &g_array_index (logged_messages, LogMessage, 0); + + for (i = 0; i < logged_message->n_fields; i++) + { + if (g_strcmp0 (logged_message->fields[i].key, "MESSAGE") == 0) + message = logged_message->fields[i].value; + else if (g_strcmp0 (logged_message->fields[i].key, "GLIB_DOMAIN") == 0) + domain = logged_message->fields[i].value; + } + + g_assert_cmpstr (domain, ==, expected_domain); + g_assert_cmpuint (logged_message->log_level, ==, expected_log_level); + g_assert_cmpstr (strstr (message, expected_message_fragment), !=, NULL); + + g_array_remove_index (logged_messages, 0); +} + +/* If there is at least one logged message in the queue, act like + * assert_pop_message(). Otherwise, if the queue is empty, return. */ +static void +assert_maybe_pop_message (const gchar *expected_domain, + GLogLevelFlags expected_log_level, + const gchar *expected_message_fragment) +{ + if (logged_messages->len == 0) + return; + + assert_pop_message (expected_domain, expected_log_level, expected_message_fragment); +} int main (int argc, char **argv) @@ -1966,6 +2066,10 @@ main (int argc, char **argv) g_setenv ("XDG_CONFIG_HOME", "/HOME/.config", TRUE); g_unsetenv ("DCONF_PROFILE"); + logged_messages = g_array_new (FALSE, FALSE, sizeof (LogMessage)); + g_array_set_clear_func (logged_messages, (GDestroyNotify) log_message_clear); + g_log_set_writer_func (log_writer_cb, NULL, NULL); + main_thread = g_thread_self (); g_test_init (&argc, &argv, NULL); @@ -1990,5 +2094,10 @@ main (int argc, char **argv) g_test_add_func ("/engine/signals", test_signals); g_test_add_func ("/engine/sync", test_sync); - return g_test_run (); + retval = g_test_run (); + + assert_no_messages (); + g_array_unref (logged_messages); + + return retval; } -- 2.11.4.GIT