From f74916a98f97c7e80e46400e921d54466285d1fb Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Wed, 31 Aug 2016 12:51:22 -0400 Subject: [PATCH 1/7] setup_capture_of_logs: no longer suppress log messages Previously setup_capture_of_logs would prevent log messages from going to the console entirely. That's a problem, since sometimes log messages are bugs! Now setup_capture_of_logs() acts sensibly. If you really do need to keep a message from going to the console entirely, there is setup_full_capture_of_logs(). But only use that if you're prepared to make sure that there are no extraneous messages generated at all. --- src/common/log.c | 5 +++++ src/common/torlog.h | 5 +++++ src/test/log_test_helpers.c | 16 +++++++++++++++- src/test/log_test_helpers.h | 5 +++++ 4 files changed, 30 insertions(+), 1 deletion(-) diff --git a/src/common/log.c b/src/common/log.c index cb62a37e52..71b67906b7 100644 --- a/src/common/log.c +++ b/src/common/log.c @@ -534,6 +534,11 @@ tor_log(int severity, log_domain_mask_t domain, const char *format, ...) if (severity > log_global_min_severity_) return; va_start(ap,format); +#ifdef TOR_UNIT_TESTS + if (domain & LD_NO_MOCK) + logv__real(severity, domain, NULL, NULL, format, ap); + else +#endif logv(severity, domain, NULL, NULL, format, ap); va_end(ap); } diff --git a/src/common/torlog.h b/src/common/torlog.h index 80f37e0e48..6732a42741 100644 --- a/src/common/torlog.h +++ b/src/common/torlog.h @@ -109,6 +109,11 @@ * would. Used as a flag, not a log domain. */ #define LD_NOFUNCNAME (1u<<30) +#ifdef TOR_UNIT_TESTS +/** This log message should not be intercepted by mock_saving_logv */ +#define LD_NO_MOCK (1u<<29) +#endif + /** Mask of zero or more log domains, OR'd together. */ typedef uint32_t log_domain_mask_t; diff --git a/src/test/log_test_helpers.c b/src/test/log_test_helpers.c index 1828689d1d..8b67c39bca 100644 --- a/src/test/log_test_helpers.c +++ b/src/test/log_test_helpers.c @@ -6,6 +6,16 @@ static smartlist_t *saved_logs = NULL; +static int echo_to_real_logs = 1; + +int +setup_full_capture_of_logs(int new_level) +{ + int result = setup_capture_of_logs(new_level); + echo_to_real_logs = 0; + return result; +} + int setup_capture_of_logs(int new_level) { @@ -14,6 +24,7 @@ setup_capture_of_logs(int new_level) mock_clean_saved_logs(); saved_logs = smartlist_new(); MOCK(logv, mock_saving_logv); + echo_to_real_logs = 1; return previous_log; } @@ -108,7 +119,6 @@ mock_saving_logv(int severity, log_domain_mask_t domain, const char *funcname, const char *suffix, const char *format, va_list ap) { - (void)domain; char *buf = tor_malloc_zero(10240); int n; n = tor_vsnprintf(buf,10240,format,ap); @@ -127,5 +137,9 @@ mock_saving_logv(int severity, log_domain_mask_t domain, if (!saved_logs) saved_logs = smartlist_new(); smartlist_add(saved_logs, e); + + if (echo_to_real_logs) { + tor_log(severity, domain|LD_NO_MOCK, "%s", e->generated_msg); + } } diff --git a/src/test/log_test_helpers.h b/src/test/log_test_helpers.h index d767453a6e..2cb76b2767 100644 --- a/src/test/log_test_helpers.h +++ b/src/test/log_test_helpers.h @@ -22,6 +22,7 @@ void mock_saving_logv(int severity, log_domain_mask_t domain, void mock_clean_saved_logs(void); const smartlist_t *mock_saved_logs(void); int setup_capture_of_logs(int new_level); +int setup_full_capture_of_logs(int new_level); void teardown_capture_of_logs(int prev); int mock_saved_log_has_message(const char *msg); @@ -33,6 +34,10 @@ int mock_saved_log_has_entry(void); tt_assert_msg(mock_saved_log_has_message(str), \ "expected log to contain " # str); +#define expect_log_msg_containing(str) \ + tt_assert_msg(mock_saved_log_has_message_containing(str), \ + "expected log to contain " # str); + #define expect_no_log_msg(str) \ tt_assert_msg(!mock_saved_log_has_message(str), \ "expected log to not contain " # str); From d5614b2102d3d9c6deb7190f77106ab7c0ef78ad Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Wed, 31 Aug 2016 12:53:18 -0400 Subject: [PATCH 2/7] Use setup_full_capture_of_logs() where appropriate. --- src/test/test_address.c | 5 ++++- src/test/test_compat_libevent.c | 12 +++++++++++- src/test/test_util.c | 4 +++- 3 files changed, 18 insertions(+), 3 deletions(-) diff --git a/src/test/test_address.c b/src/test/test_address.c index b4638f0702..e984beab46 100644 --- a/src/test/test_address.c +++ b/src/test/test_address.c @@ -824,9 +824,12 @@ test_address_get_if_addrs6_list_no_internal(void *arg) (void)arg; /* We might drop a log_err */ - int prev_level = setup_capture_of_logs(LOG_ERR); + int prev_level = setup_full_capture_of_logs(LOG_ERR); results = get_interface_address6_list(LOG_ERR, AF_INET6, 0); tt_int_op(smartlist_len(mock_saved_logs()), OP_LE, 1); + if (smartlist_len(mock_saved_logs()) == 1) { + expect_log_msg_containing("connect() failed"); + } teardown_capture_of_logs(prev_level); tt_assert(results != NULL); diff --git a/src/test/test_compat_libevent.c b/src/test/test_compat_libevent.c index f13eb81124..5e14be5b33 100644 --- a/src/test/test_compat_libevent.c +++ b/src/test/test_compat_libevent.c @@ -20,31 +20,36 @@ static void test_compat_libevent_logging_callback(void *ignored) { (void)ignored; - int previous_log = setup_capture_of_logs(LOG_DEBUG); + int previous_log = setup_full_capture_of_logs(LOG_DEBUG); libevent_logging_callback(_EVENT_LOG_DEBUG, "hello world"); expect_log_msg("Message from libevent: hello world\n"); expect_log_severity(LOG_DEBUG); + tt_int_op(smartlist_len(mock_saved_logs()), OP_EQ, 1); mock_clean_saved_logs(); libevent_logging_callback(_EVENT_LOG_MSG, "hello world another time"); expect_log_msg("Message from libevent: hello world another time\n"); expect_log_severity(LOG_INFO); + tt_int_op(smartlist_len(mock_saved_logs()), OP_EQ, 1); mock_clean_saved_logs(); libevent_logging_callback(_EVENT_LOG_WARN, "hello world a third time"); expect_log_msg("Warning from libevent: hello world a third time\n"); expect_log_severity(LOG_WARN); + tt_int_op(smartlist_len(mock_saved_logs()), OP_EQ, 1); mock_clean_saved_logs(); libevent_logging_callback(_EVENT_LOG_ERR, "hello world a fourth time"); expect_log_msg("Error from libevent: hello world a fourth time\n"); expect_log_severity(LOG_ERR); + tt_int_op(smartlist_len(mock_saved_logs()), OP_EQ, 1); mock_clean_saved_logs(); libevent_logging_callback(42, "hello world a fifth time"); expect_log_msg("Message [42] from libevent: hello world a fifth time\n"); expect_log_severity(LOG_WARN); + tt_int_op(smartlist_len(mock_saved_logs()), OP_EQ, 1); mock_clean_saved_logs(); libevent_logging_callback(_EVENT_LOG_DEBUG, @@ -75,21 +80,26 @@ test_compat_libevent_logging_callback(void *ignored) "012345678901234567890123456789" "012345678901234567890123456789\n"); expect_log_severity(LOG_DEBUG); + tt_int_op(smartlist_len(mock_saved_logs()), OP_EQ, 1); mock_clean_saved_logs(); libevent_logging_callback(42, "xxx\n"); expect_log_msg("Message [42] from libevent: xxx\n"); expect_log_severity(LOG_WARN); + tt_int_op(smartlist_len(mock_saved_logs()), OP_EQ, 1); suppress_libevent_log_msg("something"); mock_clean_saved_logs(); libevent_logging_callback(_EVENT_LOG_MSG, "hello there"); expect_log_msg("Message from libevent: hello there\n"); expect_log_severity(LOG_INFO); + tt_int_op(smartlist_len(mock_saved_logs()), OP_EQ, 1); mock_clean_saved_logs(); libevent_logging_callback(_EVENT_LOG_MSG, "hello there something else"); expect_no_log_msg("hello there something else"); + if (mock_saved_logs()) + tt_int_op(smartlist_len(mock_saved_logs()), OP_EQ, 0); // No way of verifying the result of this, it seems =/ configure_libevent_logging(); diff --git a/src/test/test_util.c b/src/test/test_util.c index 5432b2ccc4..061398cb84 100644 --- a/src/test/test_util.c +++ b/src/test/test_util.c @@ -5254,9 +5254,11 @@ test_util_pwdb(void *arg) tt_assert(found); tor_free(dir); - prev_level = setup_capture_of_logs(LOG_ERR); /* We should do a LOG_ERR */ + /* We should do a LOG_ERR */ + prev_level = setup_full_capture_of_logs(LOG_ERR); dir = get_user_homedir(badname); tt_assert(dir == NULL); + expect_log_msg_containing("not found"); tt_int_op(smartlist_len(mock_saved_logs()), OP_EQ, 1); teardown_capture_of_logs(prev_level); prev_level = -100; From 2df6cdc9f94f59c332bf3a00787320a98678bf4e Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Wed, 31 Aug 2016 13:03:59 -0400 Subject: [PATCH 3/7] Document and clean log_test_helpers.c a bit In addition to documentation, this commit makes a function static, and removes a weird single-point-of-return-ism, and notes a thing I should fix. --- src/test/log_test_helpers.c | 64 +++++++++++++++++++++++++++++++++---- src/test/log_test_helpers.h | 7 ++-- 2 files changed, 60 insertions(+), 11 deletions(-) diff --git a/src/test/log_test_helpers.c b/src/test/log_test_helpers.c index 8b67c39bca..d6982ae0c9 100644 --- a/src/test/log_test_helpers.c +++ b/src/test/log_test_helpers.c @@ -4,10 +4,32 @@ #include "torlog.h" #include "log_test_helpers.h" +/** + * \file log_test_helpers.c + * \brief Code to check for expected log messages during testing. + */ + +static void mock_saving_logv(int severity, log_domain_mask_t domain, + const char *funcname, const char *suffix, + const char *format, va_list ap) + CHECK_PRINTF(5, 0); + +/** + * Smartlist of all the logs we've received since we last set up + * log capture. + */ static smartlist_t *saved_logs = NULL; +/** Boolean: should we also send messages to the test-runner? */ static int echo_to_real_logs = 1; +/** + * As setup_capture_of_logs, but do not relay log messages into the main + * logging system. + * + * Avoid using this function; use setup_capture_of_logs() instead if you + * can. If you must use this function, then make sure you detect any + * unexpected log messages, and treat them as test failures. */ int setup_full_capture_of_logs(int new_level) { @@ -16,10 +38,19 @@ setup_full_capture_of_logs(int new_level) return result; } +/** + * Temporarily capture all the messages logged at severity new_level or + * higher. Return the previous log level; you'll need to pass it into + * teardown_capture_of_logs(). + * + * This function does not prevent messages from being sent to the main + * logging system. + */ int setup_capture_of_logs(int new_level) { int previous_log = log_global_min_severity_; + /* XXXX This can suppress, if logging is turned up high. Will fix. -NM*/ log_global_min_severity_ = new_level; mock_clean_saved_logs(); saved_logs = smartlist_new(); @@ -28,6 +59,9 @@ setup_capture_of_logs(int new_level) return previous_log; } +/** + * Undo setup_capture_of_logs(). + */ void teardown_capture_of_logs(int prev) { @@ -36,6 +70,9 @@ teardown_capture_of_logs(int prev) mock_clean_saved_logs(); } +/** + * Clear all messages in mock_saved_logs() + */ void mock_clean_saved_logs(void) { @@ -47,29 +84,41 @@ mock_clean_saved_logs(void) saved_logs = NULL; } +/** + * Return a list of all the messages captured since the last + * setup_[full_]capture_of_logs() call. Each log call is recorded as a + * mock_saved_log_entry_t. + */ const smartlist_t * mock_saved_logs(void) { return saved_logs; } +/** + * Return true iff there is a message recorded by log capture + * that is exactly equal to msg + */ int mock_saved_log_has_message(const char *msg) { - int has_msg = 0; if (saved_logs) { SMARTLIST_FOREACH(saved_logs, mock_saved_log_entry_t *, m, { if (msg && m->generated_msg && !strcmp(msg, m->generated_msg)) { - has_msg = 1; + return 1; } }); } - return has_msg; + return 0; } +/** + * Return true iff there is a message recorded by log capture + * that contains msg as a substring. + */ int mock_saved_log_has_message_containing(const char *msg) { @@ -87,7 +136,7 @@ mock_saved_log_has_message_containing(const char *msg) } -/* Do the saved logs have any messages with severity? */ +/** Return true iff the saved logs have any messages with severity */ int mock_saved_log_has_severity(int severity) { @@ -104,7 +153,7 @@ mock_saved_log_has_severity(int severity) return has_sev; } -/* Do the saved logs have any messages? */ +/** Return true iff the the saved logs have at lease one message */ int mock_saved_log_has_entry(void) { @@ -114,7 +163,10 @@ mock_saved_log_has_entry(void) return 0; } -void +/* Replacement for logv: record the log message, and (maybe) send it + * into the logging system again. + */ +static void mock_saving_logv(int severity, log_domain_mask_t domain, const char *funcname, const char *suffix, const char *format, va_list ap) diff --git a/src/test/log_test_helpers.h b/src/test/log_test_helpers.h index 2cb76b2767..039c7ae1eb 100644 --- a/src/test/log_test_helpers.h +++ b/src/test/log_test_helpers.h @@ -6,19 +6,16 @@ #ifndef TOR_LOG_TEST_HELPERS_H #define TOR_LOG_TEST_HELPERS_H +/** An element of mock_saved_logs(); records the log element that we + * received. */ typedef struct mock_saved_log_entry_t { int severity; const char *funcname; const char *suffix; const char *format; char *generated_msg; - struct mock_saved_log_entry_t *next; } mock_saved_log_entry_t; -void mock_saving_logv(int severity, log_domain_mask_t domain, - const char *funcname, const char *suffix, - const char *format, va_list ap) - CHECK_PRINTF(5, 0); void mock_clean_saved_logs(void); const smartlist_t *mock_saved_logs(void); int setup_capture_of_logs(int new_level); From 871b711f1016d0394ca1aae84cdfa267d213eb45 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Wed, 31 Aug 2016 13:12:36 -0400 Subject: [PATCH 4/7] Work even harder not to suppress logging messages unless we mean to. --- src/test/log_test_helpers.c | 33 ++++++++++++++++++++++++--------- 1 file changed, 24 insertions(+), 9 deletions(-) diff --git a/src/test/log_test_helpers.c b/src/test/log_test_helpers.c index d6982ae0c9..2c99da8583 100644 --- a/src/test/log_test_helpers.c +++ b/src/test/log_test_helpers.c @@ -23,6 +23,9 @@ static smartlist_t *saved_logs = NULL; /** Boolean: should we also send messages to the test-runner? */ static int echo_to_real_logs = 1; +/** Record logs at this level or more severe */ +static int record_logs_at_level = LOG_ERR; + /** * As setup_capture_of_logs, but do not relay log messages into the main * logging system. @@ -50,8 +53,15 @@ int setup_capture_of_logs(int new_level) { int previous_log = log_global_min_severity_; - /* XXXX This can suppress, if logging is turned up high. Will fix. -NM*/ - log_global_min_severity_ = new_level; + + /* Only change the log_global_min_severity_ if we're making things _more_ + * verbose. Otherwise we could prevent real log messages that the test- + * runner wanted. + */ + if (log_global_min_severity_ < new_level) + log_global_min_severity_ = new_level; + + record_logs_at_level = new_level; mock_clean_saved_logs(); saved_logs = smartlist_new(); MOCK(logv, mock_saving_logv); @@ -178,6 +188,18 @@ mock_saving_logv(int severity, log_domain_mask_t domain, buf[n]='\n'; buf[n+1]='\0'; + if (echo_to_real_logs) { + tor_log(severity, domain|LD_NO_MOCK, "%s", buf); + } + + if (severity > record_logs_at_level) { + tor_free(buf); + return; + } + + if (!saved_logs) + saved_logs = smartlist_new(); + mock_saved_log_entry_t *e = tor_malloc_zero(sizeof(mock_saved_log_entry_t)); e->severity = severity; e->funcname = funcname; @@ -186,12 +208,5 @@ mock_saving_logv(int severity, log_domain_mask_t domain, e->generated_msg = tor_strdup(buf); tor_free(buf); - if (!saved_logs) - saved_logs = smartlist_new(); smartlist_add(saved_logs, e); - - if (echo_to_real_logs) { - tor_log(severity, domain|LD_NO_MOCK, "%s", e->generated_msg); - } } - From 69dce0903187abc0a48606884c88588d276086d7 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Wed, 31 Aug 2016 13:18:13 -0400 Subject: [PATCH 5/7] Do not call tor_tls_server_info_callback(NULL) from tests. This isn't valid behavior, and it causes a crash when you run the unit tests at --debug. I've added an IF_BUG_ONCE() check for this case. --- src/common/tortls.c | 4 ++++ src/test/test_tortls.c | 2 -- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/src/common/tortls.c b/src/common/tortls.c index a62efb5575..23889be259 100644 --- a/src/common/tortls.c +++ b/src/common/tortls.c @@ -1489,6 +1489,10 @@ tor_tls_server_info_callback(const SSL *ssl, int type, int val) tor_tls_t *tls; (void) val; + IF_BUG_ONCE(ssl == NULL) { + return; // LCOV_EXCL_LINE + } + tor_tls_debug_state_callback(ssl, type, val); if (type != SSL_CB_ACCEPT_LOOP) diff --git a/src/test/test_tortls.c b/src/test/test_tortls.c index 3a048fb1f0..9115823f31 100644 --- a/src/test/test_tortls.c +++ b/src/test/test_tortls.c @@ -1831,8 +1831,6 @@ test_tortls_server_info_callback(void *ignored) tls->magic = TOR_TLS_MAGIC; tls->ssl = ssl; - tor_tls_server_info_callback(NULL, 0, 0); - 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); From 273290d4fee31857d689ef5286e44dd268a9bd65 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Wed, 31 Aug 2016 13:22:07 -0400 Subject: [PATCH 6/7] Always log [bug] warnings from the unit tests. We should consider them bugs. If they are happening intentionally, we should use the log_test_helpers code to capture and suppress them. But having them off-by-default has potential to cause programming errors. --- src/test/testing_common.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/test/testing_common.c b/src/test/testing_common.c index ea9366305c..e3fe87cb43 100644 --- a/src/test/testing_common.c +++ b/src/test/testing_common.c @@ -272,6 +272,8 @@ main(int c, const char **v) log_severity_list_t s; memset(&s, 0, sizeof(s)); set_log_severity_config(loglevel, LOG_ERR, &s); + /* ALWAYS log bug warnings. */ + s.masks[LOG_WARN-LOG_ERR] |= LD_BUG; add_stream_log(&s, "", fileno(stdout)); } From 05c2db3f0bec9fe2e41ea62fbb6e5bd8ac755da4 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Wed, 31 Aug 2016 13:35:46 -0400 Subject: [PATCH 7/7] Changes file for log test improvements --- changes/bug19999_prep | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) create mode 100644 changes/bug19999_prep diff --git a/changes/bug19999_prep b/changes/bug19999_prep new file mode 100644 index 0000000000..e8bb4a571b --- /dev/null +++ b/changes/bug19999_prep @@ -0,0 +1,20 @@ + o Minor features (unit tests): + - The unit tests now log all warning messages with the "BUG" flag. + Previously, they only logged errors by default. This change will + help us make our testing code more correct, and make sure that + we only hit this code when we mean to. This is preparatory work + for ticket 19999. + - Our unit testing code that captures log messages no longer prevents + them from being written out if the user asked for them (by passing + --debug or --info or or --notice --warn to the "test" binary). This + change will prevent us from missing unexpected log messages simply + because we were looking for others. Related to ticket 19999. + - Our link-handshake unit tests now check, that when invalid + handshakes fail, they fail with the error messages we + expected. + + o Minor bugfixes (unit tests): + - The tor_tls_server_info_callback unit test no longer crashes when + debug-level logging is turned on. Fixes bug 20041; bugfix on + 0.2.8.1-alpha. +