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. diff --git a/scripts/maint/practracker/exceptions.txt b/scripts/maint/practracker/exceptions.txt index 8e4618a72a..a6f10a99a6 100644 --- a/scripts/maint/practracker/exceptions.txt +++ b/scripts/maint/practracker/exceptions.txt @@ -283,3 +283,4 @@ problem function-size /src/tools/tor-gencert.c:parse_commandline() 111 problem function-size /src/tools/tor-resolve.c:build_socks5_resolve_request() 102 problem function-size /src/tools/tor-resolve.c:do_resolve() 171 problem function-size /src/tools/tor-resolve.c:main() 112 + diff --git a/src/core/or/circuitpadding.c b/src/core/or/circuitpadding.c index 9ccad87449..d7f6b04f39 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); } /** @@ -1206,7 +1215,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; } @@ -1417,7 +1428,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; } @@ -1457,7 +1470,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) { @@ -1481,7 +1496,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) { @@ -1512,6 +1529,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 @@ -1527,7 +1550,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 @@ -1593,7 +1615,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, @@ -2129,7 +2153,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; @@ -2714,8 +2741,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"); @@ -2792,8 +2820,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, @@ -2856,7 +2885,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; } @@ -2923,21 +2953,24 @@ 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!"); + log_fn(LOG_PROTOCOL_WARN, LD_CIRC, + "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, @@ -2951,7 +2984,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); 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.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/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/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" ) } diff --git a/src/test/test_circuitpadding.c b/src/test/test_circuitpadding.c index 915f086615..934ddb0208 100644 --- a/src/test/test_circuitpadding.c +++ b/src/test/test_circuitpadding.c @@ -92,10 +92,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