From ccd16caeacd3cec84f6a2c419bfc9a4500506d55 Mon Sep 17 00:00:00 2001 From: Mike Perry Date: Mon, 12 Aug 2019 13:40:54 -0500 Subject: [PATCH 1/6] Additional circpad diagnostic logs Also add controller circuit id to all relevant circpad loglines. This will make debugging any future issues like #30992 much easier. --- src/core/or/circuitpadding.c | 74 ++++++++++++++++++++++++++---------- 1 file changed, 54 insertions(+), 20 deletions(-) diff --git a/src/core/or/circuitpadding.c b/src/core/or/circuitpadding.c index c4670bbc2f..392dc53331 100644 --- a/src/core/or/circuitpadding.c +++ b/src/core/or/circuitpadding.c @@ -138,6 +138,11 @@ static void circpad_circuit_machineinfo_free_idx(circuit_t *circ, int idx) { if (circ->padding_info[idx]) { + log_fn(LOG_INFO,LD_CIRC, "Freeing padding info idx %d on circuit %u (%d)", + idx, CIRCUIT_IS_ORIGIN(circ) ? + TO_ORIGIN_CIRCUIT(circ)->global_identifier : 0, + circ->purpose); + tor_free(circ->padding_info[idx]->histogram); timer_free(circ->padding_info[idx]->padding_timer); tor_free(circ->padding_info[idx]); @@ -210,8 +215,9 @@ circpad_marked_circuit_for_padding(circuit_t *circ, int reason) } log_info(LD_CIRC, "Circuit %d is not marked for close because of a " - " pending padding machine.", CIRCUIT_IS_ORIGIN(circ) ? - TO_ORIGIN_CIRCUIT(circ)->global_identifier : 0); + "pending padding machine in index %d.", + CIRCUIT_IS_ORIGIN(circ) ? + TO_ORIGIN_CIRCUIT(circ)->global_identifier : 0, i); /* If the machine has had no network events at all within the * last circpad_delay_t timespan, it's in some deadlock state. @@ -222,10 +228,11 @@ circpad_marked_circuit_for_padding(circuit_t *circ, int reason) if (circ->padding_info[i]->last_cell_time_sec + (time_t)CIRCPAD_DELAY_MAX_SECS < approx_time()) { log_notice(LD_BUG, "Circuit %d was not marked for close because of a " - " pending padding machine for over an hour. Circuit is a %s", + "pending padding machine in index %d for over an hour. " + "Circuit is a %s", CIRCUIT_IS_ORIGIN(circ) ? TO_ORIGIN_CIRCUIT(circ)->global_identifier : 0, - circuit_purpose_to_string(circ->purpose)); + i, circuit_purpose_to_string(circ->purpose)); return 0; // abort timer reached; mark the circuit for close now } @@ -524,7 +531,9 @@ circpad_choose_state_length(circpad_machine_runtime_t *mi) mi->state_length = clamp_double_to_int64(length); - log_info(LD_CIRC, "State length sampled to %"PRIu64".", mi->state_length); + log_info(LD_CIRC, "State length sampled to %"PRIu64" for circuit %u", + mi->state_length, CIRCUIT_IS_ORIGIN(mi->on_circ) ? + TO_ORIGIN_CIRCUIT(mi->on_circ)->global_identifier : 0); } /** @@ -1198,7 +1207,9 @@ circpad_send_padding_cell_for_callback(circpad_machine_runtime_t *mi) /* Make sure circuit didn't close on us */ if (mi->on_circ->marked_for_close) { log_fn(LOG_INFO,LD_CIRC, - "Padding callback on a circuit marked for close. Ignoring."); + "Padding callback on circuit marked for close (%u). Ignoring.", + CIRCUIT_IS_ORIGIN(mi->on_circ) ? + TO_ORIGIN_CIRCUIT(mi->on_circ)->global_identifier : 0); return CIRCPAD_STATE_CHANGED; } @@ -1409,7 +1420,9 @@ circpad_machine_schedule_padding,(circpad_machine_runtime_t *mi)) // Don't pad in end (but also don't cancel any previously // scheduled padding either). if (mi->current_state == CIRCPAD_STATE_END) { - log_fn(LOG_INFO, LD_CIRC, "Padding end state"); + log_fn(LOG_INFO, LD_CIRC, "Padding end state on circuit %u", + CIRCUIT_IS_ORIGIN(mi->on_circ) ? + TO_ORIGIN_CIRCUIT(mi->on_circ)->global_identifier : 0); return CIRCPAD_STATE_UNCHANGED; } @@ -1449,7 +1462,9 @@ circpad_machine_schedule_padding,(circpad_machine_runtime_t *mi)) } else { mi->padding_scheduled_at_usec = 1; } - log_fn(LOG_INFO,LD_CIRC,"\tPadding in %u usec", in_usec); + log_fn(LOG_INFO,LD_CIRC,"\tPadding in %u usec on circuit %u", in_usec, + CIRCUIT_IS_ORIGIN(mi->on_circ) ? + TO_ORIGIN_CIRCUIT(mi->on_circ)->global_identifier : 0); // Don't schedule if we have infinite delay. if (in_usec == CIRCPAD_DELAY_INFINITE) { @@ -1473,7 +1488,9 @@ circpad_machine_schedule_padding,(circpad_machine_runtime_t *mi)) timeout.tv_sec = in_usec/TOR_USEC_PER_SEC; timeout.tv_usec = (in_usec%TOR_USEC_PER_SEC); - log_fn(LOG_INFO, LD_CIRC, "\tPadding in %u sec, %u usec", + log_fn(LOG_INFO, LD_CIRC, "\tPadding circuit %u in %u sec, %u usec", + CIRCUIT_IS_ORIGIN(mi->on_circ) ? + TO_ORIGIN_CIRCUIT(mi->on_circ)->global_identifier : 0, (unsigned)timeout.tv_sec, (unsigned)timeout.tv_usec); if (mi->padding_timer) { @@ -1504,6 +1521,12 @@ static void circpad_machine_spec_transitioned_to_end(circpad_machine_runtime_t *mi) { const circpad_machine_spec_t *machine = CIRCPAD_GET_MACHINE(mi); + circuit_t *on_circ = mi->on_circ; + + log_fn(LOG_INFO,LD_CIRC, "Padding machine in end state on circuit %u (%d)", + CIRCUIT_IS_ORIGIN(on_circ) ? + TO_ORIGIN_CIRCUIT(on_circ)->global_identifier : 0, + on_circ->purpose); /* * We allow machines to shut down and delete themselves as opposed @@ -1519,7 +1542,6 @@ circpad_machine_spec_transitioned_to_end(circpad_machine_runtime_t *mi) * here does. */ if (machine->should_negotiate_end) { - circuit_t *on_circ = mi->on_circ; if (machine->is_origin_side) { /* We free the machine info here so that we can be replaced * by a different machine. But we must leave the padding_machine @@ -1585,7 +1607,9 @@ circpad_machine_spec_transition,(circpad_machine_runtime_t *mi, * a transition to itself. All non-specified events are ignored. */ log_fn(LOG_INFO, LD_CIRC, - "Circpad machine %d transitioning from %u to %u", + "Circuit %u circpad machine %d transitioning from %u to %u", + CIRCUIT_IS_ORIGIN(mi->on_circ) ? + TO_ORIGIN_CIRCUIT(mi->on_circ)->global_identifier : 0, mi->machine_index, mi->current_state, s); /* If this is not the same state, switch and init tokens, @@ -2084,7 +2108,10 @@ circpad_add_matching_machines(origin_circuit_t *on_circ, if (circpad_negotiate_padding(on_circ, machine->machine_num, machine->target_hopnum, CIRCPAD_COMMAND_START) < 0) { - log_info(LD_CIRC, "Padding not negotiated. Cleaning machine"); + log_info(LD_CIRC, + "Padding not negotiated. Cleaning machine from circuit %u", + CIRCUIT_IS_ORIGIN(circ) ? + TO_ORIGIN_CIRCUIT(circ)->global_identifier : 0); circpad_circuit_machineinfo_free_idx(circ, i); circ->padding_machine[i] = NULL; on_circ->padding_negotiation_failed = 1; @@ -2747,8 +2774,9 @@ circpad_negotiate_padding(origin_circuit_t *circ, &type)) < 0) return -1; - log_fn(LOG_INFO,LD_CIRC, "Negotiating padding on circuit %u (%d)", - circ->global_identifier, TO_CIRCUIT(circ)->purpose); + log_fn(LOG_INFO,LD_CIRC, + "Negotiating padding on circuit %u (%d), command %d", + circ->global_identifier, TO_CIRCUIT(circ)->purpose, command); return circpad_send_command_to_hop(circ, target_hopnum, RELAY_COMMAND_PADDING_NEGOTIATE, @@ -2811,7 +2839,8 @@ circpad_handle_padding_negotiate(circuit_t *circ, cell_t *cell) if (CIRCUIT_IS_ORIGIN(circ)) { log_fn(LOG_PROTOCOL_WARN, LD_CIRC, - "Padding negotiate cell unsupported at origin."); + "Padding negotiate cell unsupported at origin (circuit %u)", + TO_ORIGIN_CIRCUIT(circ)->global_identifier); return -1; } @@ -2879,20 +2908,23 @@ circpad_handle_padding_negotiated(circuit_t *circ, cell_t *cell, /* Verify this came from the expected hop */ if (!circpad_padding_is_from_expected_hop(circ, layer_hint)) { log_fn(LOG_WARN, LD_CIRC, - "Padding negotiated cell from wrong hop!"); + "Padding negotiated cell from wrong hop on circuit %u", + TO_ORIGIN_CIRCUIT(circ)->global_identifier); return -1; } if (circpad_negotiated_parse(&negotiated, cell->payload+RELAY_HEADER_SIZE, CELL_PAYLOAD_SIZE-RELAY_HEADER_SIZE) < 0) { log_fn(LOG_PROTOCOL_WARN, LD_CIRC, - "Received malformed PADDING_NEGOTIATED cell; " - "dropping."); + "Received malformed PADDING_NEGOTIATED cell on circuit %u; " + "dropping.", TO_ORIGIN_CIRCUIT(circ)->global_identifier); return -1; } if (negotiated->command == CIRCPAD_COMMAND_STOP) { - log_info(LD_CIRC, "Received STOP command on PADDING_NEGOTIATED"); + log_info(LD_CIRC, + "Received STOP command on PADDING_NEGOTIATED for circuit %u", + TO_ORIGIN_CIRCUIT(circ)->global_identifier); /* There may not be a padding_info here if we shut down the * machine in circpad_shutdown_old_machines(). Or, if * circpad_add_matching_matchines() added a new machine, @@ -2906,7 +2938,9 @@ circpad_handle_padding_negotiated(circuit_t *circ, cell_t *cell, free_circ_machineinfos_with_machine_num(circ, negotiated->machine_type); TO_ORIGIN_CIRCUIT(circ)->padding_negotiation_failed = 1; log_fn(LOG_PROTOCOL_WARN, LD_CIRC, - "Middle node did not accept our padding request."); + "Middle node did not accept our padding request on circuit %u (%d)", + TO_ORIGIN_CIRCUIT(circ)->global_identifier, + circ->purpose); } circpad_negotiated_free(negotiated); From f6bc9d7c7eff9d50e5499007ea3a742b259e6ff9 Mon Sep 17 00:00:00 2001 From: Mike Perry Date: Thu, 8 Aug 2019 12:24:31 -0500 Subject: [PATCH 2/6] Bug 30992: Demote logline of wronghop padding to protocol warn. This can happen, it's not great, but it's not the worst thing in the world either. Deferring full fix for 0.4.2/later. --- src/core/or/circuitpadding.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/core/or/circuitpadding.c b/src/core/or/circuitpadding.c index 392dc53331..cdebda33f6 100644 --- a/src/core/or/circuitpadding.c +++ b/src/core/or/circuitpadding.c @@ -2907,7 +2907,7 @@ circpad_handle_padding_negotiated(circuit_t *circ, cell_t *cell, /* Verify this came from the expected hop */ if (!circpad_padding_is_from_expected_hop(circ, layer_hint)) { - log_fn(LOG_WARN, LD_CIRC, + log_fn(LOG_PROTOCOL_WARN, LD_CIRC, "Padding negotiated cell from wrong hop on circuit %u", TO_ORIGIN_CIRCUIT(circ)->global_identifier); return -1; From b14bb12e39d3ccb95a9e5d9cf3eda8428c129520 Mon Sep 17 00:00:00 2001 From: Mike Perry Date: Thu, 8 Aug 2019 12:49:33 -0500 Subject: [PATCH 3/6] Bug 31356: Bump protover for new padding machines By binding the protover numbering to specific padding machines, we can make our padding negotiation simpler. We probably should have done this in the first place. This has the side effect that earlier 0.4.1.x-alpha clients won't negotiate with 0.4.1.x-stable relays, and 0.4.1.x-stable clients won't negotiate with earlier 0.4.1.x-alpha relays (or 0.4.0.x relays). Since we don't support alphas after the stable is released, this is fine, so long as it gets in before the first stable of 0.4.1.x. --- src/core/or/protover.c | 2 +- src/rust/protover/protover.rs | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/core/or/protover.c b/src/core/or/protover.c index e12919f0a8..ccd33fabf7 100644 --- a/src/core/or/protover.c +++ b/src/core/or/protover.c @@ -402,7 +402,7 @@ protover_get_supported_protocols(void) #endif "Microdesc=1-2 " "Relay=1-2 " - "Padding=1 " + "Padding=2 " "FlowCtrl=1"; } diff --git a/src/rust/protover/protover.rs b/src/rust/protover/protover.rs index f7d9d6d15f..7a76fcdd94 100644 --- a/src/rust/protover/protover.rs +++ b/src/rust/protover/protover.rs @@ -168,7 +168,7 @@ pub(crate) fn get_supported_protocols_cstr() -> &'static CStr { LinkAuth=3 \ Microdesc=1-2 \ Relay=1-2 \ - Padding=1 \ + Padding=2 \ FlowCtrl=1" ) } else { @@ -183,7 +183,7 @@ pub(crate) fn get_supported_protocols_cstr() -> &'static CStr { LinkAuth=1,3 \ Microdesc=1-2 \ Relay=1-2 \ - Padding=1 \ + Padding=2 \ FlowCtrl=1" ) } From b2821b72bc4e228934b5187ae5015230e7cbd26b Mon Sep 17 00:00:00 2001 From: Mike Perry Date: Mon, 12 Aug 2019 13:15:31 -0500 Subject: [PATCH 4/6] Bug 31356: Propogate protover padding support to circpad --- src/core/or/circuitpadding.c | 5 +++-- src/core/or/or.h | 4 ++-- src/core/or/protover.h | 2 ++ src/core/or/versions.c | 5 +++-- src/test/test_circuitpadding.c | 4 ++-- 5 files changed, 12 insertions(+), 8 deletions(-) diff --git a/src/core/or/circuitpadding.c b/src/core/or/circuitpadding.c index cdebda33f6..a62cdcf9e6 100644 --- a/src/core/or/circuitpadding.c +++ b/src/core/or/circuitpadding.c @@ -2696,8 +2696,9 @@ circpad_node_supports_padding(const node_t *node) { if (node->rs) { log_fn(LOG_INFO, LD_CIRC, "Checking padding: %s", - node->rs->pv.supports_padding ? "supported" : "unsupported"); - return node->rs->pv.supports_padding; + node->rs->pv.supports_hs_setup_padding ? + "supported" : "unsupported"); + return node->rs->pv.supports_hs_setup_padding; } log_fn(LOG_INFO, LD_CIRC, "Empty routerstatus in padding check"); diff --git a/src/core/or/or.h b/src/core/or/or.h index db6d089582..ab258629a6 100644 --- a/src/core/or/or.h +++ b/src/core/or/or.h @@ -841,8 +841,8 @@ typedef struct protover_summary_flags_t { unsigned int supports_v3_rendezvous_point: 1; /** True iff this router has a protocol list that allows clients to - * negotiate link-level padding. Requires Padding>=1. */ - unsigned int supports_padding : 1; + * negotiate hs circuit setup padding. Requires Padding>=2. */ + unsigned int supports_hs_setup_padding : 1; } protover_summary_flags_t; typedef struct routerinfo_t routerinfo_t; diff --git a/src/core/or/protover.h b/src/core/or/protover.h index d8e541735f..af45a31aeb 100644 --- a/src/core/or/protover.h +++ b/src/core/or/protover.h @@ -28,6 +28,8 @@ struct smartlist_t; #define PROTOVER_HS_INTRO_V3 4 /** The protover version number that signifies HSv3 rendezvous point support */ #define PROTOVER_HS_RENDEZVOUS_POINT_V3 2 +/** The protover that signals support for HS circuit setup padding machines */ +#define PROTOVER_HS_SETUP_PADDING 2 /** List of recognized subprotocols. */ /// C_RUST_COUPLED: src/rust/protover/ffi.rs `translate_to_rust` diff --git a/src/core/or/versions.c b/src/core/or/versions.c index 2a572d4704..06417bb4eb 100644 --- a/src/core/or/versions.c +++ b/src/core/or/versions.c @@ -448,8 +448,9 @@ memoize_protover_summary(protover_summary_flags_t *out, out->supports_v3_rendezvous_point = protocol_list_supports_protocol(protocols, PRT_HSREND, PROTOVER_HS_RENDEZVOUS_POINT_V3); - out->supports_padding = - protocol_list_supports_protocol(protocols, PRT_PADDING, 1); + out->supports_hs_setup_padding = + protocol_list_supports_protocol(protocols, PRT_PADDING, + PROTOVER_HS_SETUP_PADDING); protover_summary_flags_t *new_cached = tor_memdup(out, sizeof(*out)); cached = strmap_set(protover_summary_map, protocols, new_cached); diff --git a/src/test/test_circuitpadding.c b/src/test/test_circuitpadding.c index 236f4a192d..25f8fd311b 100644 --- a/src/test/test_circuitpadding.c +++ b/src/test/test_circuitpadding.c @@ -90,10 +90,10 @@ static void nodes_init(void) { padding_node.rs = tor_malloc_zero(sizeof(routerstatus_t)); - padding_node.rs->pv.supports_padding = 1; + padding_node.rs->pv.supports_hs_setup_padding = 1; non_padding_node.rs = tor_malloc_zero(sizeof(routerstatus_t)); - non_padding_node.rs->pv.supports_padding = 0; + non_padding_node.rs->pv.supports_hs_setup_padding = 0; } static void From 02c89c955d60d1135aa231ce8ebc431af732f560 Mon Sep 17 00:00:00 2001 From: Mike Perry Date: Thu, 8 Aug 2019 13:59:49 -0500 Subject: [PATCH 5/6] Bug 31356: Add changes file. Also document the other log changes in this branch. --- changes/bug31356_and_logs | 11 +++++++++++ 1 file changed, 11 insertions(+) create mode 100644 changes/bug31356_and_logs diff --git a/changes/bug31356_and_logs b/changes/bug31356_and_logs new file mode 100644 index 0000000000..fb5307cb69 --- /dev/null +++ b/changes/bug31356_and_logs @@ -0,0 +1,11 @@ + o Minor bugfixes (circuit padding negotiation): + - Bump circuit padding protover to explicitly signify that the hs setup + machine support is finalized in 0.4.1.x-stable. This also means that + 0.4.1.x-alpha clients will not negotiate padding with 0.4.1.x-stable + relays, and 0.4.1.x-stable clients will not negotiate padding with + 0.4.1.x-alpha relays (or 0.4.0.x relays). Fixes bug 31356; + bugfix on 0.4.1.1-alpha. + o Minor features (circuit padding logging): + - Demote noisy client-side warn log to a protocol warning. Add additional + log messages and circuit id fields to help with fixing bug 30992 and any + other future issues. From 6deba34fee9b3ea99771db4fec562a776ff1ed4d Mon Sep 17 00:00:00 2001 From: Mike Perry Date: Mon, 12 Aug 2019 13:40:29 -0500 Subject: [PATCH 6/6] Practracker --- scripts/maint/practracker/exceptions.txt | 3 +++ 1 file changed, 3 insertions(+) diff --git a/scripts/maint/practracker/exceptions.txt b/scripts/maint/practracker/exceptions.txt index 9073f2f1dd..726dc9c3ef 100644 --- a/scripts/maint/practracker/exceptions.txt +++ b/scripts/maint/practracker/exceptions.txt @@ -87,7 +87,9 @@ problem function-size /src/core/or/circuitlist.c:circuit_about_to_free() 120 problem function-size /src/core/or/circuitlist.c:circuits_handle_oom() 117 problem function-size /src/core/or/circuitmux.c:circuitmux_set_policy() 110 problem function-size /src/core/or/circuitmux.c:circuitmux_attach_circuit() 114 +problem file-size /src/core/or/circuitpadding.c 3040 problem function-size /src/core/or/circuitpadding.c:circpad_machine_schedule_padding() 107 +problem function-size /src/core/or/circuitpadding.c:circpad_machine_schedule_padding() 113 problem function-size /src/core/or/circuitpadding_machines.c:circpad_machine_relay_hide_intro_circuits() 104 problem function-size /src/core/or/circuitpadding_machines.c:circpad_machine_client_hide_rend_circuits() 112 problem function-size /src/core/or/circuitstats.c:circuit_build_times_parse_state() 124 @@ -284,3 +286,4 @@ problem function-size /src/tools/tor-gencert.c:parse_commandline() 111 problem function-size /src/tools/tor-resolve.c:build_socks5_resolve_request() 104 problem function-size /src/tools/tor-resolve.c:do_resolve() 174 problem function-size /src/tools/tor-resolve.c:main() 112 +