GNOME Bugzilla – Bug 679556
it's hard to use gtest when g_warning() is expected
Last modified: 2012-08-20 18:32:36 UTC
dconf has a few test cases for things like parsing invalid profile configuration files. In the even that you have an invalid profile file, dconf will g_warning() you about it and then proceed. It's possible to test this in gtest but quite difficult. You have to install a handler to prevent the warning from being fatal (g_test_log_set_fatal_handler) and another to capture the message and prevent it from going to stderr (g_log_set_default_handler). Then you have to undo both of these. A nicer API would perhaps look something like the GDK API for dealing with X errors: g_test_trap_messages_push(const gchar *domain, GLogLevel levels); g_test_trap_message_pop(); It would then be possible to use the existing API or one like it to examine the printed warnings (g_test_trap_assert_stderr() could be augmented with g_test_trap_assert_log_message() or such).
note: of course one could use the existing fork functionality to test this case but the problem is that you would still need to setup the fatal log handler to ignore the warning messages if you wanted to test the warning being successfully issued and then execution continuing sanely (ie: to make sure you get the expected result even after the warning is issued).
okay... so you can immediately do this in the child: g_log_set_always_fatal (G_LOG_LEVEL_ERROR); and then issues g_warning() without aborting it. Still leaves something to be desired though, considering fork() is not always possible during testcases.
the fork is also problematic with gcov - it doesn't seem to notice any lines executed in fork-without-exec
I'd suggest something like: g_test_expect_message ("libsoup", G_LOG_LEVEL_CRITICAL, "assertion.*SOUP_IS_CONNECTION.*failed"); g_test_expect_message ("libsoup", G_LOG_LEVEL_WARNING, "Disposing socket 0x.* while still connected"); g_object_unref (socket); g_test_assert_expected_messages (); g_test_expect_message() would append the domain/level/regexp to the queue of expected messages. When the log handler runs, if there's a non-empty expected-message queue, it would pop the first element, and assert that the message it was supposed to log matches that expectation (and return silently if it does). g_test_assert_expected_messages() would just check that the expected-messages queue was empty, and if not, would print out the unfulfilled expectation and then abort.
That does seem a bit nicer...
Created attachment 219931 [details] [review] g_logv: only expand the message once Hoist the g_strdup_printf()'ing out of the loop, since the message is the same for every handler that gets called.
Created attachment 219932 [details] [review] gtestutils: add g_text_expect_message() Add g_test_expect_message() and g_test_assert_expected_messages(), to allow tests of warnings, error messages, return-if-fails, etc.
Created attachment 219933 [details] [review] glib/tests: use g_test_expect_message() Replace some tests that used to use g_test_trap_fork() with g_test_expect_message() instead.
one problem with this; g_error is defined as: /* for(;;) ; so that GCC knows that control doesn't go past g_error(). * Put space before ending semicolon to avoid C++ build warnings. */ #define g_error(...) G_STMT_START { \ g_log (G_LOG_DOMAIN, \ G_LOG_LEVEL_ERROR, \ __VA_ARGS__); \ for (;;) ; \ } G_STMT_END So you can't catch and ignore a g_error()...
I think of g_error() as "abort with a reason" and I very much think that it should never ever be possible for code to run after g_error(). For that case, the fork is really the only way.
Review of attachment 219932 [details] [review]: This looks really great, except for one small note. ::: glib/gtestutils.h @@ +302,3 @@ +gint g_test_count_expected_messages (void); + +#define g_test_assert_expected_messages() g_assert_cmpint (g_test_count_expected_messages (), ==, 0) Would be nice if we had this as a proper function that told us what the unexpected messages were (instead of just telling us how many there are).
Created attachment 220068 [details] [review] glib/tests/testing, logging: don't use g_test_undefined() We are verifying the behavior of the test/logging functions here; this is not undefined behavior.
Created attachment 220069 [details] [review] gtestutils: add g_text_expect_message() Add g_test_expect_message() and g_test_assert_expected_messages(), to allow tests of warnings, error messages, return-if-fails, etc. ==== Now prints "didn't get expected message" if either you g_test_assert_expected_messages() when there are expected messages, or if you g_log the wrong message. Also, adds tests to tests/testing.c
Created attachment 220070 [details] [review] glib/tests: use g_test_expect_message() Replace some tests that used to use g_test_trap_fork() with g_test_expect_message() instead.
Review of attachment 220069 [details] [review]: Looks great. Love the API. Would recommend! A++! ::: glib/gmessages.c @@ +1066,3 @@ + * Indicates that a message with the given @log_domain and @log_level, + * with text matching @pattern, is expected to be logged. When this + * message is logged, it will not be printed, and the program will maybe say "test case" here instead of program. otherwise i'm thinking that this lets me intercept g_error() because that's the only case i'd normally expect a program to abort... ::: glib/gtestutils.c @@ +147,3 @@ + * Returns %TRUE if tests may provoke assertions and other + * formally-undefined behaviour under g_test_trap_fork() or after + * g_test_expect_message(), to verify that appropriate warnings are this comment needs to be taken out back and shot. maybe just modify it by adding another sentence at the end: "if you want to test for proper warning messages being emitted, see ...."?
Review of attachment 219931 [details] [review]: I was wondering why we went to all of this effort when I was touching this code a while ago... Glad to see it cleaned up.
updated and pushed. We agreed on IRC that the existing use/definition of g_test_undefined is broken, but that can be fixed later. Attachment 219931 [details] pushed as 78a8aec - g_logv: only expand the message once Attachment 220068 [details] pushed as f78931c - glib/tests/testing, logging: don't use g_test_undefined() Attachment 220069 [details] pushed as 25ac137 - gtestutils: add g_text_expect_message() Attachment 220070 [details] pushed as cc24dac - glib/tests: use g_test_expect_message()
Review of attachment 220069 [details] [review]: ::: glib/gmessages.c @@ +1098,3 @@ +g_test_expect_message (const gchar *log_domain, + GLogLevelFlags log_level, + const gchar *pattern) Wouldn't it help to add g_return_if_fail(check log_domain != NULL) and g_return_if_fail(pattern != NULL) instead of crashing later? (even if it will only happen when a test is badly written)