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@torproject.org>

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()) {
+  /* Stats number coming from relay.c append_cell_to_circuit_queue(). */
-    goto end;
+  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);
-
+  tor_free(circ_stats_msg);
- end:
   return;
 }
 

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

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,

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;