commit bcc953307b571df5b640f9fbc299b93c74d3847f Author: Nick Mathewson <nickm@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