August 2019 - tor-commits - lists.torproject.org

[tor/maint-0.4.1] Bug 30992: Demote logline of wronghop padding to protocol warn.
by nickm＠torproject.org 19 Aug '19

19 Aug '19

commit f6bc9d7c7eff9d50e5499007ea3a742b259e6ff9 Author: Mike Perry <mikeperry-git(a)torproject.org> Date: Thu Aug 8 12:24:31 2019 -0500 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 392dc5333..cdebda33f 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;

1 0

[tor/maint-0.4.1] Additional circpad diagnostic logs
by nickm＠torproject.org 19 Aug '19

19 Aug '19

commit ccd16caeacd3cec84f6a2c419bfc9a4500506d55 Author: Mike Perry <mikeperry-git(a)torproject.org> Date: Mon Aug 12 13:40:54 2019 -0500 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 c4670bbc2..392dc5333 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);

1 0

[tor/maint-0.4.1] Bug 31356: Bump protover for new padding machines
by nickm＠torproject.org 19 Aug '19

19 Aug '19

commit b14bb12e39d3ccb95a9e5d9cf3eda8428c129520 Author: Mike Perry <mikeperry-git(a)torproject.org> Date: Thu Aug 8 12:49:33 2019 -0500 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 e12919f0a..ccd33fabf 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 f7d9d6d15..7a76fcdd9 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" ) }

1 0

[tor/maint-0.4.1] Bug 31356: Add changes file.
by nickm＠torproject.org 19 Aug '19

19 Aug '19

commit 02c89c955d60d1135aa231ce8ebc431af732f560 Author: Mike Perry <mikeperry-git(a)torproject.org> Date: Thu Aug 8 13:59:49 2019 -0500 Bug 31356: Add changes file. Also document the other log changes in this branch. --- changes/bug31356_and_logs | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/changes/bug31356_and_logs b/changes/bug31356_and_logs new file mode 100644 index 000000000..fb5307cb6 --- /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.

1 0

[tor/maint-0.4.1] Bug 31356: Propogate protover padding support to circpad
by nickm＠torproject.org 19 Aug '19

19 Aug '19

commit b2821b72bc4e228934b5187ae5015230e7cbd26b Author: Mike Perry <mikeperry-git(a)torproject.org> Date: Mon Aug 12 13:15:31 2019 -0500 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 cdebda33f..a62cdcf9e 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 db6d08958..ab258629a 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 d8e541735..af45a31ae 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 2a572d470..06417bb4e 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 236f4a192..25f8fd311 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

1 0

[tor/maint-0.4.1] Practracker
by nickm＠torproject.org 19 Aug '19

19 Aug '19

commit 6deba34fee9b3ea99771db4fec562a776ff1ed4d Author: Mike Perry <mikeperry-git(a)torproject.org> Date: Mon Aug 12 13:40:29 2019 -0500 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 9073f2f1d..726dc9c3e 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 +

1 0

[tor/master] Bug 31356: Bump protover for new padding machines
by nickm＠torproject.org 19 Aug '19

19 Aug '19

commit b14bb12e39d3ccb95a9e5d9cf3eda8428c129520 Author: Mike Perry <mikeperry-git(a)torproject.org> Date: Thu Aug 8 12:49:33 2019 -0500 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 e12919f0a..ccd33fabf 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 f7d9d6d15..7a76fcdd9 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" ) }

1 0

[tor/master] Bug 30992: Demote logline of wronghop padding to protocol warn.
by nickm＠torproject.org 19 Aug '19

19 Aug '19

commit f6bc9d7c7eff9d50e5499007ea3a742b259e6ff9 Author: Mike Perry <mikeperry-git(a)torproject.org> Date: Thu Aug 8 12:24:31 2019 -0500 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 392dc5333..cdebda33f 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;

1 0

[tor/maint-0.4.1] Merge remote-tracking branch 'tor-github/pr/1230' into maint-0.4.1
by nickm＠torproject.org 19 Aug '19

19 Aug '19

commit 6a89b0104970037893536f3336a1ec982da13dc6 Merge: bba64c988 6deba34fe Author: Nick Mathewson <nickm(a)torproject.org> Date: Mon Aug 19 11:11:32 2019 -0400 Merge remote-tracking branch 'tor-github/pr/1230' into maint-0.4.1 changes/bug31356_and_logs | 11 +++++ scripts/maint/practracker/exceptions.txt | 3 ++ src/core/or/circuitpadding.c | 81 +++++++++++++++++++++++--------- src/core/or/or.h | 4 +- src/core/or/protover.c | 2 +- src/core/or/protover.h | 2 + src/core/or/versions.c | 5 +- src/rust/protover/protover.rs | 4 +- src/test/test_circuitpadding.c | 4 +- 9 files changed, 84 insertions(+), 32 deletions(-)

1 0

[tor/master] Additional circpad diagnostic logs
by nickm＠torproject.org 19 Aug '19

19 Aug '19

commit ccd16caeacd3cec84f6a2c419bfc9a4500506d55 Author: Mike Perry <mikeperry-git(a)torproject.org> Date: Mon Aug 12 13:40:54 2019 -0500 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 c4670bbc2..392dc5333 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);

1 0