[tor-commits] [tor/main] Move "Didn't recognize cell, but circ stops here" into heartbeat.
ahf at torproject.org
ahf at torproject.org
Wed Oct 20 18:39:52 UTC 2021
commit bcc953307b571df5b640f9fbc299b93c74d3847f
Author: Nick Mathewson <nickm at torproject.org>
Date: Tue Oct 19 15:16:49 2021 -0400
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.
---
changes/bug40400_part3 | 7 +++++++
src/core/or/circuitlist.c | 7 +++++++
src/core/or/or_circuit_st.h | 5 ++++-
src/core/or/relay.c | 13 +++++++++++--
src/core/or/status.c | 43 +++++++++++++++++++++++++++++++++++++++++++
src/core/or/status.h | 3 +++
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
More information about the tor-commits
mailing list