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.

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;

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) */
-

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

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

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