[tor-commits] [tor/master] heartbeat: Log the number of circuits killed because too many cells

[nickm at torproject.org]

commit 93ff1870ba153332ab695e53d906da6a14a8097c
Author: David Goulet <dgoulet at torproject.org>
Date:   Tue Apr 17 08:38:34 2018 -0400

    heartbeat: Log the number of circuits killed because too many cells
    
    We recently merged a circuit cell queue size safeguard. This commit adds the
    number of killed circuits that have reached the limit to the DoS heartbeat. It
    now looks like this:
    
      [notice] DoS mitigation since startup: 0 circuits killed with too many
      cells. 0 circuits rejected, 0 marked addresses. 0 connections closed. 0
      single hop clients refused.
    
    Second thing that this patch does. It makes tor always print the DoS
    mitigation heartbeat line (for a relay) even though no DoS mitigation have
    been enabled. The reason is because we now kill circuits that have too many
    cells regardless on if it is enabled or not but also it will give the operator
    a chance to learn what is enabled with the heartbeat instead of suddenly
    appearing when it is enabled by let say the consensus.
    
    Fixes #25824
    
    Signed-off-by: David Goulet <dgoulet at torproject.org>
---
 src/or/dos.c           | 15 +++++++++------
 src/or/relay.c         |  4 ++++
 src/or/relay.h         |  1 +
 src/test/test_status.c | 12 +++++++++++-
 4 files changed, 25 insertions(+), 7 deletions(-)

diff --git a/src/or/dos.c b/src/or/dos.c
index 4d1797eec..2cb347058 100644
--- a/src/or/dos.c
+++ b/src/or/dos.c
@@ -15,6 +15,7 @@
 #include "main.h"
 #include "networkstatus.h"
 #include "nodelist.h"
+#include "relay.h"
 #include "router.h"
 
 #include "dos.h"
@@ -622,10 +623,12 @@ dos_log_heartbeat(void)
   char *conn_msg = NULL;
   char *cc_msg = NULL;
   char *single_hop_client_msg = NULL;
+  char *circ_stats_msg = NULL;
 
-  if (!dos_is_enabled()) {
-    goto end;
-  }
+  /* Stats number coming from relay.c append_cell_to_circuit_queue(). */
+  tor_asprintf(&circ_stats_msg,
+               " %" PRIu64 " circuits killed with too many cells.",
+               stats_n_circ_max_cell_reached);
 
   if (dos_cc_enabled) {
     tor_asprintf(&cc_msg,
@@ -647,7 +650,8 @@ dos_log_heartbeat(void)
   }
 
   log_notice(LD_HEARTBEAT,
-             "DoS mitigation since startup:%s%s%s",
+             "DoS mitigation since startup:%s%s%s%s",
+             circ_stats_msg,
              (cc_msg != NULL) ? cc_msg : " [cc not enabled]",
              (conn_msg != NULL) ? conn_msg : " [conn not enabled]",
              (single_hop_client_msg != NULL) ? single_hop_client_msg : "");
@@ -655,8 +659,7 @@ dos_log_heartbeat(void)
   tor_free(conn_msg);
   tor_free(cc_msg);
   tor_free(single_hop_client_msg);
-
- end:
+  tor_free(circ_stats_msg);
   return;
 }
 
diff --git a/src/or/relay.c b/src/or/relay.c
index 5a3c43e05..b3571d6cd 100644
--- a/src/or/relay.c
+++ b/src/or/relay.c
@@ -115,6 +115,9 @@ uint64_t stats_n_relay_cells_relayed = 0;
  * hop?
  */
 uint64_t stats_n_relay_cells_delivered = 0;
+/** Stats: how many circuits have we closed due to the cell queue limit being
+ * reached (see append_cell_to_circuit_queue()) */
+uint64_t stats_n_circ_max_cell_reached = 0;
 
 /** Used to tell which stream to read from first on a circuit. */
 static tor_weak_rng_t stream_choice_rng = TOR_WEAK_RNG_INIT;
@@ -3041,6 +3044,7 @@ append_cell_to_circuit_queue(circuit_t *circ, channel_t *chan,
            (exitward) ? "Outbound" : "Inbound", queue->n,
            max_circuit_cell_queue_size);
     circuit_mark_for_close(circ, END_CIRC_REASON_RESOURCELIMIT);
+    stats_n_circ_max_cell_reached++;
     return;
   }
 
diff --git a/src/or/relay.h b/src/or/relay.h
index c9281c5ea..e96639170 100644
--- a/src/or/relay.h
+++ b/src/or/relay.h
@@ -14,6 +14,7 @@
 
 extern uint64_t stats_n_relay_cells_relayed;
 extern uint64_t stats_n_relay_cells_delivered;
+extern uint64_t stats_n_circ_max_cell_reached;
 
 void relay_consensus_has_changed(const networkstatus_t *ns);
 int circuit_receive_relay_cell(cell_t *cell, circuit_t *circ,
diff --git a/src/test/test_status.c b/src/test/test_status.c
index 50ea203e4..b4ca17891 100644
--- a/src/test/test_status.c
+++ b/src/test/test_status.c
@@ -340,7 +340,7 @@ NS(test_main)(void *arg)
   actual = log_heartbeat(0);
 
   tt_int_op(actual, OP_EQ, expected);
-  tt_int_op(CALLED(logv), OP_EQ, 5);
+  tt_int_op(CALLED(logv), OP_EQ, 6);
 
   done:
     NS_UNMOCK(tls_get_write_overhead_ratio);
@@ -439,6 +439,16 @@ NS(logv)(int severity, log_domain_mask_t domain,
       tt_ptr_op(strstr(funcname, "rep_hist_log_link_protocol_counts"),
                 OP_NE, NULL);
       break;
+    case 5:
+      tt_int_op(severity, OP_EQ, LOG_NOTICE);
+      tt_int_op(domain, OP_EQ, LD_HEARTBEAT);
+      tt_str_op(format, OP_EQ, "DoS mitigation since startup:%s%s%s%s");
+      tt_str_op(va_arg(ap, char *), OP_EQ,
+                " 0 circuits killed with too many cells.");
+      tt_str_op(va_arg(ap, char *), OP_EQ, " [cc not enabled]");
+      tt_str_op(va_arg(ap, char *), OP_EQ, " [conn not enabled]");
+      tt_str_op(va_arg(ap, char *), OP_EQ, "");
+      break;
     default:
       tt_abort_msg("unexpected call to logv()");  // TODO: prettyprint args
       break;