[Author Prev][Author Next][Thread Prev][Thread Next][Author Index][Thread Index]
[tor-commits] [tor/release-0.4.1] Additional circpad diagnostic logs
commit ccd16caeacd3cec84f6a2c419bfc9a4500506d55
Author: Mike Perry <mikeperry-git@xxxxxxxxxxxxxx>
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);
_______________________________________________
tor-commits mailing list
tor-commits@xxxxxxxxxxxxxxxxxxxx
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-commits