Move "Didn't recognize cell, but circ stops here" into heartbeat.

When we looked, this was the third most frequent message at
PROTOCOL_WARN, and doesn't actually tell us what to do about it.
Now:
 * we just log it at info
 * we log it only once per circuit
 * we report, in the heartbeat, how many times it happens, how many
   cells it happens with per circuit, and how long these circuits
   have been alive (on average).

Fixes the final part of #40400.

6 files changed, 75 insertions, 3 deletions

diff --git a/changes/bug40400_part3 b/changes/bug40400_part3
new file mode 100644
index 0000000000..b78e800229
--- /dev/null
+++ b/changes/bug40400_part3
@@ -0,0 +1,7 @@
+  o Minor features (logging, heartbeat):
+    - When a relay receives a cell that isn't encrypted properly for
+      it, but the relay is the last hop on the circuit, the relay
+      now counts how many cells of this kind it receives, on how
+      many circuits, and reports this information in the log.
+      Previously, we'd log each cell at PROTOCOL_WARN level, which
+      is far too verbose to be useful. Fixes part of ticket 40400.
diff --git a/src/core/or/circuitlist.c b/src/core/or/circuitlist.c
index 88c4159294..4dbf4d4549 100644
--- a/src/core/or/circuitlist.c
+++ b/src/core/or/circuitlist.c
@@ -64,6 +64,7 @@
 #include "core/or/circuitpadding.h"
 #include "core/or/crypt_path.h"
 #include "core/or/extendinfo.h"
+#include "core/or/status.h"
 #include "core/or/trace_probes_circuit.h"
 #include "core/mainloop/connection.h"
 #include "app/config/config.h"
@@ -2346,6 +2347,12 @@ circuit_about_to_free(circuit_t *circ)
       circuitmux_detach_circuit(or_circ->p_chan->cmux, circ);
       circuit_set_p_circid_chan(or_circ, 0, NULL);
     }
+
+    if (or_circ->n_cells_discarded_at_end) {
+      time_t age = approx_time() - circ->timestamp_created.tv_sec;
+      note_circ_closed_for_unrecognized_cells(
+                      age, or_circ->n_cells_discarded_at_end);
+    }
   } else {
     origin_circuit_t *ocirc = TO_ORIGIN_CIRCUIT(circ);
     edge_connection_t *conn;
diff --git a/src/core/or/or_circuit_st.h b/src/core/or/or_circuit_st.h
index b8fbf9658e..11695ec301 100644
--- a/src/core/or/or_circuit_st.h
+++ b/src/core/or/or_circuit_st.h
@@ -52,6 +52,10 @@ struct or_circuit_t {
   /** Stores KH for the handshake. */
   char rend_circ_nonce[DIGEST_LEN];/* KH in tor-spec.txt */
 
+  /** Number of cells which we have discarded because of having no next hop,
+   * despite not recognizing the cell. */
+  uint32_t n_cells_discarded_at_end;
+
   /** How many more relay_early cells can we send on this circuit, according
    * to the specification? */
   unsigned int remaining_relay_early_cells : 4;
@@ -93,4 +97,3 @@ struct or_circuit_t {
 };
 
 #endif /* !defined(OR_CIRCUIT_ST_H) */
-
diff --git a/src/core/or/relay.c b/src/core/or/relay.c
index a2123f991c..68fddd1ae7 100644
--- a/src/core/or/relay.c
+++ b/src/core/or/relay.c
@@ -333,8 +333,17 @@ circuit_receive_relay_cell(cell_t *cell, circuit_t *circ,
       }
       return 0;
     }
-    log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL,
-           "Didn't recognize cell, but circ stops here! Closing circ.");
+    if (BUG(CIRCUIT_IS_ORIGIN(circ))) {
+      /* Should be impossible at this point. */
+      return -END_CIRC_REASON_TORPROTOCOL;
+    }
+    or_circuit_t *or_circ = TO_OR_CIRCUIT(circ);
+    if (++or_circ->n_cells_discarded_at_end == 1) {
+      time_t seconds_open = approx_time() - circ->timestamp_created.tv_sec;
+      log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL,
+             "Didn't recognize a cell, but circ stops here! Closing circuit. "
+             "It was created %ld seconds ago.", (long)seconds_open);
+    }
     return -END_CIRC_REASON_TORPROTOCOL;
   }
 
diff --git a/src/core/or/status.c b/src/core/or/status.c
index 9e7ae70535..1e599aafb3 100644
--- a/src/core/or/status.c
+++ b/src/core/or/status.c
@@ -147,6 +147,32 @@ note_connection(bool inbound, int family)
   }
 }
 
+/**
+ * @name Counters for unrecognized cells
+ *
+ * Track cells that we drop because they are unrecognized and we have
+ * nobody to send them to.
+ **/
+/**@{*/
+static unsigned n_circs_closed_for_unrecognized_cells;
+static uint64_t n_unrecognized_cells_discarded;
+static uint64_t n_secs_on_circs_with_unrecognized_cells;
+/**@}*/
+
+/**
+ * Note that a circuit has closed @a n_seconds after having been created,
+ * because of one or more unrecognized cells.  Also note the number of
+ * unrecognized cells @a n_cells.
+ */
+void
+note_circ_closed_for_unrecognized_cells(time_t n_seconds, uint32_t n_cells)
+{
+  ++n_circs_closed_for_unrecognized_cells;
+  n_unrecognized_cells_discarded += n_cells;
+  if (n_seconds >= 0)
+    n_secs_on_circs_with_unrecognized_cells += (uint64_t) n_seconds;
+}
+
 /** Log a "heartbeat" message describing Tor's status and history so that the
  * user can know that there is indeed a running Tor.  Return 0 on success and
  * -1 on failure. */
@@ -240,6 +266,23 @@ log_heartbeat(time_t now)
          (main_loop_idle_count));
   }
 
+  if (n_circs_closed_for_unrecognized_cells) {
+    double avg_time_alive = ((double) n_secs_on_circs_with_unrecognized_cells)
+      / n_circs_closed_for_unrecognized_cells;
+    double avg_cells = ((double) n_unrecognized_cells_discarded)
+      / n_circs_closed_for_unrecognized_cells;
+    log_fn(LOG_NOTICE, LD_HEARTBEAT,
+        "Since our last heartbeat, %u circuits were closed because of "
+        "unrecognized cells while we were the last hop. On average, each "
+        "one was alive for %lf seconds, and had %lf unrecognized cells.",
+        n_circs_closed_for_unrecognized_cells,
+        avg_time_alive,
+        avg_cells);
+    n_circs_closed_for_unrecognized_cells = 0;
+    n_unrecognized_cells_discarded = 0;
+    n_secs_on_circs_with_unrecognized_cells = 0;
+  }
+
   /** Now, if we are an HS service, log some stats about our usage */
   log_onion_service_stats();
 
diff --git a/src/core/or/status.h b/src/core/or/status.h
index 927df9a192..57e28002fc 100644
--- a/src/core/or/status.h
+++ b/src/core/or/status.h
@@ -12,6 +12,9 @@
 #include "lib/testsupport/testsupport.h"
 
 void note_connection(bool inbound, int family);
+void note_circ_closed_for_unrecognized_cells(time_t n_seconds,
+                                             uint32_t n_cells);
+
 int log_heartbeat(time_t now);
 
 #ifdef STATUS_PRIVATE