Merge branch 'log_test_improvements'

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.
+

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

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;
 

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)

src/test/log_test_helpers.c

@@ -4,19 +4,74 @@
 #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;
+
+/** 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.
+ *
+ * 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)
+{
+  int result = setup_capture_of_logs(new_level);
+  echo_to_real_logs = 0;
+  return result;
+}
+
+/**
+ * Temporarily capture all the messages logged at severity <b>new_level</b> 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_;
-  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);
+  echo_to_real_logs = 1;
   return previous_log;
 }
 
+/**
+ * Undo setup_capture_of_logs().
+ */
 void
 teardown_capture_of_logs(int prev)
 {
@@ -25,6 +80,9 @@ teardown_capture_of_logs(int prev)
   mock_clean_saved_logs();
 }
 
+/**
+ * Clear all messages in mock_saved_logs()
+ */
 void
 mock_clean_saved_logs(void)
 {
@@ -36,29 +94,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 <b>msg</b>
+ */
 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 <b>msg</b> as a substring.
+ */
 int
 mock_saved_log_has_message_containing(const char *msg)
 {
@@ -76,7 +146,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 <b>severity</b> */
 int
 mock_saved_log_has_severity(int severity)
 {
@@ -93,7 +163,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)
 {
@@ -103,12 +173,14 @@ 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)
 {
-  (void)domain;
   char *buf = tor_malloc_zero(10240);
   int n;
   n = tor_vsnprintf(buf,10240,format,ap);
@@ -116,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;
@@ -124,8 +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);
 }
-

src/test/log_test_helpers.h

@@ -6,22 +6,20 @@
 #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);
+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 +31,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);

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

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

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

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;

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