diff --git a/src/test/log_test_helpers.c b/src/test/log_test_helpers.c index 5eba566d1c..7f7f1d1d42 100644 --- a/src/test/log_test_helpers.c +++ b/src/test/log_test_helpers.c @@ -105,6 +105,12 @@ mock_saved_logs(void) return saved_logs; } +int +mock_saved_log_n_entries(void) +{ + return saved_logs ? smartlist_len(saved_logs) : 0; +} + /** * Return true iff there is a message recorded by log capture * that is exactly equal to msg diff --git a/src/test/log_test_helpers.h b/src/test/log_test_helpers.h index bf2f9a6beb..fd990845d9 100644 --- a/src/test/log_test_helpers.h +++ b/src/test/log_test_helpers.h @@ -26,6 +26,7 @@ int mock_saved_log_has_message(const char *msg); int mock_saved_log_has_message_containing(const char *msg); int mock_saved_log_has_severity(int severity); int mock_saved_log_has_entry(void); +int mock_saved_log_n_entries(void); void mock_dump_saved_logs(void); #define assert_log_predicate(predicate, failure_msg) \ @@ -50,11 +51,19 @@ void mock_dump_saved_logs(void); mock_saved_log_has_message_containing(str2), \ "expected log to contain " # str1 " or " # str2); +#define expect_single_log_msg(str) \ + do { \ + \ + assert_log_predicate(mock_saved_log_has_message_containing(str) && \ + mock_saved_log_n_entries() == 1, \ + "expected log to contain exactly 1 message: " # str); \ + } while (0); + #define expect_single_log_msg_containing(str) \ - do { \ - assert_log_predicate(mock_saved_log_has_message_containing(str), \ - "expected log to contain " # str); \ - tt_int_op(smartlist_len(mock_saved_logs()), OP_EQ, 1); \ + do { \ + assert_log_predicate(mock_saved_log_has_message_containing(str)&& \ + mock_saved_log_n_entries() == 1 , \ + "expected log to contain 1 message, containing" # str); \ } while (0); #define expect_no_log_msg(str) \ diff --git a/src/test/test_dir.c b/src/test/test_dir.c index 65b04af779..0afc0b7129 100644 --- a/src/test/test_dir.c +++ b/src/test/test_dir.c @@ -36,6 +36,7 @@ #include "test_dir_common.h" #include "torcert.h" #include "relay.h" +#include "log_test_helpers.h" #define NS_MODULE dir @@ -3268,6 +3269,8 @@ static void test_dir_fetch_type(void *arg) { (void)arg; + int log_level = 0; + tt_int_op(dir_fetch_type(DIR_PURPOSE_FETCH_EXTRAINFO, ROUTER_PURPOSE_BRIDGE, NULL), OP_EQ, EXTRAINFO_DIRINFO | BRIDGE_DIRINFO); tt_int_op(dir_fetch_type(DIR_PURPOSE_FETCH_EXTRAINFO, ROUTER_PURPOSE_GENERAL, @@ -3293,9 +3296,15 @@ test_dir_fetch_type(void *arg) tt_int_op(dir_fetch_type(DIR_PURPOSE_FETCH_MICRODESC, ROUTER_PURPOSE_GENERAL, NULL), OP_EQ, MICRODESC_DIRINFO); + /* This will give a warning, because this function isn't supposed to be + * used for HS descriptors. */ + log_level = setup_full_capture_of_logs(LOG_WARN); tt_int_op(dir_fetch_type(DIR_PURPOSE_FETCH_RENDDESC_V2, ROUTER_PURPOSE_GENERAL, NULL), OP_EQ, NO_DIRINFO); - done: ; + expect_single_log_msg_containing("Unexpected purpose"); + done: + if (log_level) + teardown_capture_of_logs(log_level); } static void @@ -3963,6 +3972,7 @@ static void test_dir_conn_purpose_to_string(void *data) { (void)data; + int log_level = 0; #define EXPECT_CONN_PURPOSE(purpose, expected) \ tt_str_op(dir_conn_purpose_to_string(purpose), OP_EQ, expected); @@ -3984,9 +3994,15 @@ test_dir_conn_purpose_to_string(void *data) EXPECT_CONN_PURPOSE(DIR_PURPOSE_UPLOAD_RENDDESC_V2, "hidden-service v2 descriptor upload"); EXPECT_CONN_PURPOSE(DIR_PURPOSE_FETCH_MICRODESC, "microdescriptor fetch"); - EXPECT_CONN_PURPOSE(1024, "(unknown)"); - done: ; + /* This will give a warning, because there is no purpose 1024. */ + log_level = setup_full_capture_of_logs(LOG_WARN); + EXPECT_CONN_PURPOSE(1024, "(unknown)"); + expect_single_log_msg_containing("Called with unknown purpose 1024"); + + done: + if (log_level) + teardown_capture_of_logs(log_level); } NS_DECL(int, diff --git a/src/test/test_guardfraction.c b/src/test/test_guardfraction.c index 130aff11aa..3cc83f91c4 100644 --- a/src/test/test_guardfraction.c +++ b/src/test/test_guardfraction.c @@ -17,6 +17,7 @@ #include "test.h" #include "test_helpers.h" +#include "log_test_helpers.h" /** Generate a vote_routerstatus_t for a router with identity digest * digest_in_hex. */ @@ -280,6 +281,7 @@ test_parse_guardfraction_consensus(void *arg) const char *guardfraction_str_bad2 = "GuardFraction=166"; /* no percentage */ routerstatus_t rs_bad2; + int log_level = 0; (void) arg; /* GuardFraction use is currently disabled by default. So we need to @@ -304,11 +306,16 @@ test_parse_guardfraction_consensus(void *arg) memset(&rs_no_guard, 0, sizeof(routerstatus_t)); tt_assert(!rs_no_guard.is_possible_guard); + log_level = setup_full_capture_of_logs(LOG_WARN); retval = routerstatus_parse_guardfraction(guardfraction_str_good, NULL, NULL, &rs_no_guard); tt_int_op(retval, ==, 0); tt_assert(!rs_no_guard.has_guardfraction); + expect_single_log_msg_containing("Got GuardFraction for non-guard . " + "This is not supposed to happen."); + teardown_capture_of_logs(log_level); + log_level = 0; } { /* Bad GuardFraction. Function should fail and not apply. */ @@ -334,7 +341,8 @@ test_parse_guardfraction_consensus(void *arg) } done: - ; + if (log_level) + teardown_capture_of_logs(log_level); } /** Make sure that we use GuardFraction information when we should, diff --git a/src/test/test_rendcache.c b/src/test/test_rendcache.c index e210e053b6..17d86bc39e 100644 --- a/src/test/test_rendcache.c +++ b/src/test/test_rendcache.c @@ -12,6 +12,7 @@ #include "config.h" #include #include "rend_test_helpers.h" +#include "log_test_helpers.h" #define NS_MODULE rend_cache @@ -646,6 +647,7 @@ test_rend_cache_init(void *data) static void test_rend_cache_decrement_allocation(void *data) { + int log_level = 0; (void)data; // Test when the cache has enough allocations @@ -655,20 +657,27 @@ test_rend_cache_decrement_allocation(void *data) // Test when there are not enough allocations rend_cache_total_allocation = 1; + log_level = setup_full_capture_of_logs(LOG_WARN); rend_cache_decrement_allocation(2); tt_int_op(rend_cache_total_allocation, OP_EQ, 0); + expect_single_log_msg_containing( + "Underflow in rend_cache_decrement_allocation"); + teardown_capture_of_logs(log_level); + log_level = 0; // And again rend_cache_decrement_allocation(2); tt_int_op(rend_cache_total_allocation, OP_EQ, 0); done: - (void)0; + if (log_level) + teardown_capture_of_logs(log_level); } static void test_rend_cache_increment_allocation(void *data) { + int log_level = 0; (void)data; // Test when the cache is not overflowing @@ -678,15 +687,21 @@ test_rend_cache_increment_allocation(void *data) // Test when there are too many allocations rend_cache_total_allocation = SIZE_MAX-1; + log_level = setup_full_capture_of_logs(LOG_WARN); rend_cache_increment_allocation(2); tt_u64_op(rend_cache_total_allocation, OP_EQ, SIZE_MAX); + expect_single_log_msg_containing( + "Overflow in rend_cache_increment_allocation"); + teardown_capture_of_logs(log_level); + log_level = 0; // And again rend_cache_increment_allocation(2); tt_u64_op(rend_cache_total_allocation, OP_EQ, SIZE_MAX); done: - (void)0; + if (log_level) + teardown_capture_of_logs(log_level); } static void diff --git a/src/test/test_shared_random.c b/src/test/test_shared_random.c index ead8d0311e..8210ba2dcd 100644 --- a/src/test/test_shared_random.c +++ b/src/test/test_shared_random.c @@ -530,8 +530,8 @@ test_vote(void *arg) HEX_DIGEST_LEN); tt_mem_op(digest, ==, our_commit->rsa_identity, sizeof(digest)); tt_str_op(smartlist_get(tokens, 4), OP_EQ, our_commit->encoded_commit); - tt_str_op(smartlist_get(tokens, 5), OP_EQ, our_commit->encoded_reveal); - + tt_str_op(smartlist_get(tokens, 5), OP_EQ, our_commit->encoded_reveal) +; /* Finally, does this vote line creates a valid commit object? */ smartlist_t *args = smartlist_new(); smartlist_add(args, smartlist_get(tokens, 1)); diff --git a/src/test/test_tortls.c b/src/test/test_tortls.c index 9115823f31..d2f256a197 100644 --- a/src/test/test_tortls.c +++ b/src/test/test_tortls.c @@ -1817,7 +1817,7 @@ test_tortls_server_info_callback(void *ignored) tor_tls_t *tls; SSL_CTX *ctx; SSL *ssl; - int previous_log = setup_capture_of_logs(LOG_WARN); + int previous_log = 0; SSL_library_init(); SSL_load_error_strings(); @@ -1831,20 +1831,23 @@ test_tortls_server_info_callback(void *ignored) tls->magic = TOR_TLS_MAGIC; tls->ssl = ssl; + previous_log = setup_full_capture_of_logs(LOG_WARN); SSL_set_state(ssl, SSL3_ST_SW_SRVR_HELLO_A); mock_clean_saved_logs(); tor_tls_server_info_callback(ssl, SSL_CB_ACCEPT_LOOP, 0); - expect_log_msg("Couldn't look up the tls for an SSL*. How odd!\n"); + expect_single_log_msg("Couldn't look up the tls for an SSL*. How odd!\n"); SSL_set_state(ssl, SSL3_ST_SW_SRVR_HELLO_B); mock_clean_saved_logs(); tor_tls_server_info_callback(ssl, SSL_CB_ACCEPT_LOOP, 0); - expect_log_msg("Couldn't look up the tls for an SSL*. How odd!\n"); + expect_single_log_msg("Couldn't look up the tls for an SSL*. How odd!\n"); SSL_set_state(ssl, 99); mock_clean_saved_logs(); tor_tls_server_info_callback(ssl, SSL_CB_ACCEPT_LOOP, 0); expect_no_log_entry(); + teardown_capture_of_logs(previous_log); + previous_log = 0; SSL_set_ex_data(tls->ssl, tor_tls_object_ex_data_index, tls); SSL_set_state(ssl, SSL3_ST_SW_SRVR_HELLO_B); @@ -1865,7 +1868,8 @@ test_tortls_server_info_callback(void *ignored) tt_int_op(tls->wasV2Handshake, OP_EQ, 0); done: - teardown_capture_of_logs(previous_log); + if (previous_log) + teardown_capture_of_logs(previous_log); SSL_free(ssl); SSL_CTX_free(ctx); tor_free(tls); @@ -2277,6 +2281,7 @@ test_tortls_finish_handshake(void *ignored) X509 *c1 = read_cert_from(validCertString); SESS_CERT_local *sess = NULL; + int log_level = 0; ctx = SSL_CTX_new(method); @@ -2289,9 +2294,14 @@ test_tortls_finish_handshake(void *ignored) tls->isServer = 1; tls->wasV2Handshake = 0; + log_level = setup_full_capture_of_logs(LOG_WARN); ret = tor_tls_finish_handshake(tls); tt_int_op(ret, OP_EQ, 0); tt_int_op(tls->wasV2Handshake, OP_EQ, 1); + expect_single_log_msg_containing("For some reason, wasV2Handshake didn't " + "get set."); + teardown_capture_of_logs(log_level); + log_level = 0; tls->wasV2Handshake = 1; ret = tor_tls_finish_handshake(tls); @@ -2330,6 +2340,8 @@ test_tortls_finish_handshake(void *ignored) tor_free(tls); SSL_CTX_free(ctx); tor_free(method); + if (log_level) + teardown_capture_of_logs(log_level); } #endif diff --git a/src/test/test_util_process.c b/src/test/test_util_process.c index 45c22ef47f..6add374c33 100644 --- a/src/test/test_util_process.c +++ b/src/test/test_util_process.c @@ -26,7 +26,7 @@ test_util_process_set_waitpid_callback(void *ignored) { (void)ignored; waitpid_callback_t *res1 = NULL, *res2 = NULL; - int previous_log = setup_capture_of_logs(LOG_WARN); + int previous_log = setup_full_capture_of_logs(LOG_WARN); pid_t pid = (pid_t)42; res1 = set_waitpid_callback(pid, temp_callback, NULL); @@ -34,7 +34,8 @@ test_util_process_set_waitpid_callback(void *ignored) res2 = set_waitpid_callback(pid, temp_callback, NULL); tt_assert(res2); - expect_log_msg("Replaced a waitpid monitor on pid 42. That should be " + expect_single_log_msg( + "Replaced a waitpid monitor on pid 42. That should be " "impossible.\n"); done: