commit ccd16caeacd3cec84f6a2c419bfc9a4500506d55 Author: Mike Perry mikeperry-git@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);