[tests] improve checking for log output

- now any non expected log output is considered an error, by setting a
  g_log default   handler.
- block_lasso_logs()/unblock_lasso_logs() will block logging output at
  the DEBUG level
- begin_check_do_log(level, message, endswith)/end_check_do_log() with
  check that the only message emitted between the two macros is one
  equals to "message" at the level "level", or ending (to work around
  variable parts in a log message) with "message" if "endswith" is True.

6 files changed, 98 insertions, 10 deletions

diff --git a/tests/basic_tests.c b/tests/basic_tests.c
index cb96a3c4..406e93b4 100644
--- a/tests/basic_tests.c
+++ b/tests/basic_tests.c
@@ -51,7 +51,9 @@ END_TEST
 START_TEST(test02_server_load_dump_random_string)
 {
 	LassoServer *serverContext;
+	begin_check_do_log(G_LOG_LEVEL_CRITICAL, "libxml2: Start tag expected, '<' not found\\n", FALSE);
 	serverContext = lasso_server_new_from_dump("foo");
+	end_check_do_log();
 	fail_unless(serverContext == NULL,
 			"serverContext was created from a fake dump");
 }
@@ -60,7 +62,9 @@ END_TEST
 START_TEST(test03_server_load_dump_random_xml)
 {
 	LassoServer *serverContext;
+	begin_check_do_log(G_LOG_LEVEL_CRITICAL, "(xml.c/:2307) Unable to build a LassoNode from a xmlNode", TRUE);
 	serverContext = lasso_server_new_from_dump("<?xml version=\"1.0\"?><foo/>");
+	end_check_do_log();
 	fail_unless(serverContext == NULL,
 			"serverContext was created from fake (but valid XML) dump");
 }
@@ -156,7 +160,9 @@ START_TEST(test08_test_new_from_xmlNode)
 			"LassoTest", &this_info, 0);
 	r = lasso_registry_default_add_direct_mapping("http://example.com", "Test1", LASSO_LASSO_HREF, "LassoTest");
 	fail_unless(r == 0, "no mapping for http://example.com:Test1 should exist");
+	begin_check_do_log(G_LOG_LEVEL_WARNING, "	Class LassoTest has no node_data so no initialization is possible", TRUE);
 	node = lasso_node_new_from_dump("<Test1 xmlns=\"http://example.com\"></Test1>");
+	end_check_do_log();
 	fail_unless(node != NULL, "parsing <Test1/> should return an object");
 	fail_unless(strcmp(G_OBJECT_TYPE_NAME(node), "LassoTest") == 0, "node classname should be LassoTest");
 	g_object_unref(node);
@@ -1960,11 +1966,13 @@ START_TEST(test13_test_lasso_server_load_metadata)
 			TESTSDATADIR "/idp5-saml2/private-key.pem",
 			NULL, /* Secret key to unlock private key */
 			NULL));
+	block_lasso_logs;
 	check_good_rc(lasso_server_load_metadata(server, LASSO_PROVIDER_ROLE_IDP,
 				TESTSDATADIR "/metadata/renater-metadata.xml",
 				TESTSDATADIR "/metadata/metadata-federation-renater.crt",
 				&blacklisted_1, &loaded_entity_ids,
 				LASSO_SERVER_LOAD_METADATA_FLAG_DEFAULT));
+	unblock_lasso_logs;
 	check_equals(g_hash_table_size(server->providers), 110);
 	check_equals(g_list_length(loaded_entity_ids), 110);
 
diff --git a/tests/login_tests.c b/tests/login_tests.c
index 5589b8d0..90573afc 100644
--- a/tests/login_tests.c
+++ b/tests/login_tests.c
@@ -285,7 +285,10 @@ START_TEST(test02_serviceProviderLogin)
 	fail_unless(found != NULL, "We must find an InResponseTo attribute");
 	found[sizeof("InResponseTo=\"")] = '?';
 	lasso_set_flag("no-verify-signature");
+	begin_check_do_log(G_LOG_LEVEL_DEBUG, " If inResponseTo attribute is present, a matching "
+			"request must be present too in the LassoLogin object", TRUE);
 	check_not_equals(lasso_login_process_response_msg(spLoginContext, soapResponseMsg), 0);
+	end_check_do_log();
 	lasso_set_flag("verify-signature");
 	check_good_rc(lasso_login_accept_sso(spLoginContext));
 	fail_unless(rc == 0, "lasso_login_accept_sso must fail");
diff --git a/tests/login_tests_saml2.c b/tests/login_tests_saml2.c
index c17c7500..1052c61a 100644
--- a/tests/login_tests_saml2.c
+++ b/tests/login_tests_saml2.c
@@ -785,8 +785,10 @@ START_TEST(test05_sso_idp_with_key_rollover)
 	check_good_rc(lasso_login_accept_sso(spLoginContext));
 
 	/* Process response 2 */
+	block_lasso_logs;
 	check_good_rc(lasso_login_process_authn_response_msg(spLoginContext,
 				idpLoginContext2->parent.msg_body));
+	unblock_lasso_logs;
 	check_good_rc(lasso_login_accept_sso(spLoginContext));
 
 	/* Cleanup */
@@ -838,7 +840,9 @@ sso_sp_with_key_rollover(LassoServer *idp_context, LassoServer *sp_context)
 			LASSO_SAML2_NAME_IDENTIFIER_FORMAT_PERSISTENT);
 	LASSO_SAMLP2_AUTHN_REQUEST(idp_login_context->parent.request)->NameIDPolicy->AllowCreate = 1;
 
+	block_lasso_logs;
 	check_good_rc(lasso_login_process_authn_request_msg(idp_login_context, NULL));
+	unblock_lasso_logs;
 	check_good_rc(lasso_login_validate_request_msg(idp_login_context,
 			1, /* authentication_result */
 		        0 /* is_consent_obtained */
@@ -855,8 +859,10 @@ sso_sp_with_key_rollover(LassoServer *idp_context, LassoServer *sp_context)
 	check_not_null(idp_login_context->parent.msg_url);
 
 	/* Process response */
+	block_lasso_logs;
 	check_good_rc(lasso_login_process_authn_response_msg(sp_login_context,
 				idp_login_context->parent.msg_body));
+	unblock_lasso_logs;
 	check_good_rc(lasso_login_accept_sso(sp_login_context));
 
 	/* Cleanup */
@@ -986,7 +992,9 @@ START_TEST(test07_sso_sp_with_hmac_sha1_signatures)
 	test07_make_context(idp_context, "idp6-saml2", LASSO_PROVIDER_ROLE_SP, "sp6-saml2", key)
 	test07_make_context(sp_context, "sp6-saml2", LASSO_PROVIDER_ROLE_IDP, "idp6-saml2", key)
 
+	block_lasso_logs;
 	sso_initiated_by_sp(idp_context, sp_context);
+	unblock_lasso_logs;
 
 	/* Cleanup */
 	lasso_release_gobject(idp_context);
diff --git a/tests/non_regression_tests.c b/tests/non_regression_tests.c
index 03c11a35..64886e94 100644
--- a/tests/non_regression_tests.c
+++ b/tests/non_regression_tests.c
@@ -165,26 +165,17 @@ START_TEST(indexed_endpoints_20101008)
 }
 END_TEST
 
-void error_log_func(G_GNUC_UNUSED const gchar *log_domain, G_GNUC_UNUSED GLogLevelFlags log_level,
-		const gchar *message, G_GNUC_UNUSED gpointer user_data)
-{
-	fail_unless(FALSE, "error_func called... %s", message);
-}
-
 START_TEST(remove_warning_when_parssing_unknown_SNIPPET_LIST_NODES_20111007)
 {
 	LassoNode *node;
 	xmlDoc *xmldoc;
 	const char content[] = "<saml:Attribute Name=\"urn:oid:1.3.6.1.4.1.5923.1.1.1.10\" NameFormat=\"urn:oasis:names:tc:SAML:2.0:attrname-format:uri\" FriendlyName=\"eduPersonTargetedID\" xmlns:saml=\"urn:oasis:names:tc:SAML:2.0:assertion\"><saml:AttributeValue><NameID Format=\"urn:oasis:names:tc:SAML:2.0:nameid-format:persistent\" NameQualifier=\"https://services-federation.renater.fr/test/idp\" SPNameQualifier=\"https://univnautes.entrouvert.lan/authsaml2/metadata\">C8NQsm1Y3Gas9m0AMDhxU7UxCSI=</NameID></saml:AttributeValue></saml:Attribute>";
-	guint log_handler;
 
 	xmldoc = xmlReadMemory(content, sizeof(content)-1, NULL, NULL, 0);
 	check_not_null(xmldoc);
-	log_handler = g_log_set_handler("Lasso", G_LOG_LEVEL_MASK, error_log_func, NULL);
 	node = lasso_node_new_from_xmlNode(xmlDocGetRootElement(xmldoc));
 	check_not_null(node);
 	check_true(LASSO_IS_SAML2_ATTRIBUTE(node));
-	g_log_remove_handler("Lasso", log_handler);
 	check_true(LASSO_IS_NODE(node));
 	xmlFreeDoc(xmldoc);
 	lasso_release_gobject(node);
diff --git a/tests/tests.c b/tests/tests.c
index a32d32e9..8ec4a40f 100644
--- a/tests/tests.c
+++ b/tests/tests.c
@@ -26,8 +26,9 @@
 #include <config.h>
 
 #include <check.h>
+#include <glib.h>
 #include "../lasso/lasso.h"
-#include "lasso_config.h"
+#include "../lasso/lasso_config.h"
 
 extern Suite* basic_suite();
 extern Suite* login_suite();
@@ -55,6 +56,12 @@ SuiteFunction suites[] = {
 #endif
 	NULL
 };
+void error_logger(const gchar *log_domain, GLogLevelFlags log_level,
+		const gchar *message, G_GNUC_UNUSED gpointer user_data)
+{
+	fail("No logging output expected: message «%s» was emitted for domain «%s» at the level"
+			" «%d»", message, log_domain, log_level);
+}
 
 int
 main(int argc, char *argv[])
@@ -71,6 +78,7 @@ main(int argc, char *argv[])
 	}
 
 	lasso_init();
+	g_log_set_default_handler(error_logger, NULL);
 
 	sr = srunner_create(suites[0]());
 
diff --git a/tests/tests.h b/tests/tests.h
index ce89ac98..62f01719 100644
--- a/tests/tests.h
+++ b/tests/tests.h
@@ -23,6 +23,8 @@
 #ifndef __TESTS_H__
 #define __TESTS_H__
 
+#include "../lasso/lasso_config.h"
+
 #define check_not_null(what) \
 	fail_unless((what) != NULL, "%s:%i: " #what " returned NULL", __func__, __LINE__);
 
@@ -72,4 +74,72 @@
 	fail_unless(g_strcmp0(__tmp, to) != 0, "%s:%i: " #what " is equal to %s", __func__, __LINE__, to); \
 }
 
+static inline void mute_logger(G_GNUC_UNUSED const gchar *domain,
+		G_GNUC_UNUSED GLogLevelFlags log_level, G_GNUC_UNUSED const gchar *message,
+		G_GNUC_UNUSED gpointer user_data) {
+}
+G_GNUC_UNUSED static guint mute_log_handler = 0;
+
+#define block_lasso_logs mute_log_handler = g_log_set_handler(LASSO_LOG_DOMAIN, G_LOG_LEVEL_DEBUG, \
+		mute_logger, NULL)
+
+#define unblock_lasso_logs g_log_remove_handler(LASSO_LOG_DOMAIN, mute_log_handler)
+
+struct CheckingLogHandlerUserData {
+		GLogLevelFlags log_level;
+		const char *message;
+		gboolean endswith;
+		GLogLevelFlags log_level_found;
+		const char *message_found;
+};
+G_GNUC_UNUSED static guint checking_log_handler = 0;
+G_GNUC_UNUSED static guint checking_log_handler_flag = 0;
+G_GNUC_UNUSED static struct CheckingLogHandlerUserData checking_logger_user_data;
+
+static inline gboolean check_message(const char *a, const char *b, gboolean endswith) {
+	if (endswith) {
+		return strlen(a) >= strlen(b) &&
+			strcmp(a+(strlen(a)-strlen(b)), b) == 0;
+	} else {
+		return strcmp(a, b) == 0;
+	}
+}
+
+static inline void checking_logger(G_GNUC_UNUSED const gchar *domain,
+		G_GNUC_UNUSED GLogLevelFlags log_level, G_GNUC_UNUSED const gchar *message,
+		G_GNUC_UNUSED gpointer user_data) {
+	struct CheckingLogHandlerUserData *ck_user_data = user_data;
+	if (log_level == ck_user_data->log_level && check_message(message, ck_user_data->message,
+				ck_user_data->endswith)) {
+	} else {
+		g_log_default_handler(domain, log_level, message, user_data);
+		checking_log_handler_flag = 0;
+	}
+	ck_user_data->log_level_found = log_level;
+	ck_user_data->message_found = g_strdup(message);
+}
+/* begin_check_do_log(level, message, endswith)/end_check_do_log() with check that the only
+ * message emitted between the two macros is one equals to message at the level level,
+ * or ending with message if endswith is True.
+ */
+static inline void begin_check_do_log(GLogLevelFlags level, const char *message, gboolean endswith) {
+	memset(&checking_logger_user_data, 0, sizeof(struct CheckingLogHandlerUserData));
+	checking_logger_user_data.log_level = level;
+	checking_logger_user_data.message = message;
+	checking_logger_user_data.endswith = endswith;
+	checking_log_handler = g_log_set_handler(LASSO_LOG_DOMAIN, level, checking_logger, &checking_logger_user_data);
+	checking_log_handler_flag = 1;
+}
+
+static inline void end_check_do_log() {
+	g_log_remove_handler(LASSO_LOG_DOMAIN, checking_log_handler);
+	checking_log_handler = 0;
+	fail_unless(checking_log_handler_flag, "Logging failure: expected log level %d and message «%s», got %d and «%s»",
+			checking_logger_user_data.log_level,
+			checking_logger_user_data.message,
+			checking_logger_user_data.log_level_found,
+			checking_logger_user_data.message_found);
+	checking_log_handler_flag = 0;
+}
+
 #endif /*__TESTS_H__ */