Merge remote-tracking branch 'mike/bug31356+logs-rebased2' into bug31356_final

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.

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
+

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

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;

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";
 }
 

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`

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

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"
         )
     }

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