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

@@ -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);