[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.
This commit is contained in:
Benjamin Dauvergne 2011-12-10 12:56:34 +01:00
parent c3467ed48c
commit 65b94cc1f5
6 changed files with 98 additions and 10 deletions

View File

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

View File

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

View File

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

View File

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

View File

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

View File

@ -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__ */