Merge remote-tracking branch 'asn/ticket23645_032_01'

src/or/circuitlist.c

@@ -926,12 +926,16 @@ circuit_clear_testing_cell_stats(circuit_t *circ)
 STATIC void
 circuit_free(circuit_t *circ)
 {
+  circid_t n_circ_id = 0;
   void *mem;
   size_t memlen;
   int should_free = 1;
   if (!circ)
     return;
 
+  /* We keep a copy of this so we can log its value before it gets unset. */
+  n_circ_id = circ->n_circ_id;
+
   circuit_clear_testing_cell_stats(circ);
 
   if (CIRCUIT_IS_ORIGIN(circ)) {
@@ -1028,7 +1032,7 @@ circuit_free(circuit_t *circ)
   cell_queue_clear(&circ->n_chan_cells);
 
   log_info(LD_CIRC, "Circuit %u (id: %" PRIu32 ") has been freed.",
-           circ->n_circ_id,
+           n_circ_id,
            CIRCUIT_IS_ORIGIN(circ) ?
               TO_ORIGIN_CIRCUIT(circ)->global_identifier : 0);
 
@@ -1919,7 +1923,7 @@ circuit_mark_for_close_, (circuit_t *circ, int reason, int line,
   smartlist_add(circuits_pending_close, circ);
 
   log_info(LD_GENERAL, "Circuit %u (id: %" PRIu32 ") marked for close at "
-                       "%s:%d (orig reason: %u, new reason: %u)",
+                       "%s:%d (orig reason: %d, new reason: %d)",
            circ->n_circ_id,
            CIRCUIT_IS_ORIGIN(circ) ?
               TO_ORIGIN_CIRCUIT(circ)->global_identifier : 0,

src/or/circuituse.c

@@ -1904,8 +1904,9 @@ circuit_launch_by_extend_info(uint8_t purpose,
       uint8_t old_purpose = circ->base_.purpose;
       struct timeval old_timestamp_began = circ->base_.timestamp_began;
 
-      log_info(LD_CIRC,"Cannibalizing circ '%s' for purpose %d (%s)",
-               build_state_get_exit_nickname(circ->build_state), purpose,
+      log_info(LD_CIRC, "Cannibalizing circ %u (id: %" PRIu32 ") for "
+                        "purpose %d (%s)",
+               TO_CIRCUIT(circ)->n_circ_id, circ->global_identifier, purpose,
                circuit_purpose_to_string(purpose));
 
       if ((purpose == CIRCUIT_PURPOSE_S_CONNECT_REND ||
@@ -2694,9 +2695,10 @@ connection_ap_handshake_attach_circuit(entry_connection_t *conn)
       tor_assert(rendcirc);
       /* one is already established, attach */
       log_info(LD_REND,
-               "rend joined circ %u already here. attaching. "
-               "(stream %d sec old)",
-               (unsigned)rendcirc->base_.n_circ_id, conn_age);
+               "rend joined circ %u (id: %" PRIu32 ") already here. "
+               "Attaching. (stream %d sec old)",
+               (unsigned) TO_CIRCUIT(rendcirc)->n_circ_id,
+               rendcirc->global_identifier, conn_age);
       /* Mark rendezvous circuits as 'newly dirty' every time you use
        * them, since the process of rebuilding a rendezvous circ is so
        * expensive. There is a tradeoff between linkability and
@@ -2729,9 +2731,10 @@ connection_ap_handshake_attach_circuit(entry_connection_t *conn)
     if (rendcirc && (rendcirc->base_.purpose ==
                      CIRCUIT_PURPOSE_C_REND_READY_INTRO_ACKED)) {
       log_info(LD_REND,
-               "pending-join circ %u already here, with intro ack. "
-               "Stalling. (stream %d sec old)",
-               (unsigned)rendcirc->base_.n_circ_id, conn_age);
+               "pending-join circ %u (id: %" PRIu32 ") already here, with "
+               "intro ack. Stalling. (stream %d sec old)",
+               (unsigned) TO_CIRCUIT(rendcirc)->n_circ_id,
+               rendcirc->global_identifier, conn_age);
       return 0;
     }
 
@@ -2743,10 +2746,13 @@ connection_ap_handshake_attach_circuit(entry_connection_t *conn)
     if (retval > 0) {
       /* one has already sent the intro. keep waiting. */
       tor_assert(introcirc);
-      log_info(LD_REND, "Intro circ %u present and awaiting ack (rend %u). "
-               "Stalling. (stream %d sec old)",
-               (unsigned)introcirc->base_.n_circ_id,
-               rendcirc ? (unsigned)rendcirc->base_.n_circ_id : 0,
+      log_info(LD_REND, "Intro circ %u (id: %" PRIu32 ") present and "
+                        "awaiting ACK. Rend circuit %u (id: %" PRIu32 "). "
+                        "Stalling. (stream %d sec old)",
+               (unsigned) TO_CIRCUIT(introcirc)->n_circ_id,
+               introcirc->global_identifier,
+               rendcirc ? (unsigned) TO_CIRCUIT(rendcirc)->n_circ_id : 0,
+               rendcirc ? rendcirc->global_identifier : 0,
                conn_age);
       return 0;
     }
@@ -2756,19 +2762,24 @@ connection_ap_handshake_attach_circuit(entry_connection_t *conn)
     if (rendcirc && introcirc &&
         rendcirc->base_.purpose == CIRCUIT_PURPOSE_C_REND_READY) {
       log_info(LD_REND,
-               "ready rend circ %u already here (no intro-ack yet on "
-               "intro %u). (stream %d sec old)",
-               (unsigned)rendcirc->base_.n_circ_id,
-               (unsigned)introcirc->base_.n_circ_id, conn_age);
+               "ready rend circ %u (id: %" PRIu32 ") already here. No"
+               "intro-ack yet on intro %u (id: %" PRIu32 "). "
+               "(stream %d sec old)",
+               (unsigned) TO_CIRCUIT(rendcirc)->n_circ_id,
+               rendcirc->global_identifier,
+               (unsigned) TO_CIRCUIT(introcirc)->n_circ_id,
+               introcirc->global_identifier, conn_age);
 
       tor_assert(introcirc->base_.purpose == CIRCUIT_PURPOSE_C_INTRODUCING);
       if (introcirc->base_.state == CIRCUIT_STATE_OPEN) {
         int ret;
-        log_info(LD_REND,"found open intro circ %u (rend %u); sending "
-                 "introduction. (stream %d sec old)",
-                 (unsigned)introcirc->base_.n_circ_id,
-                 (unsigned)rendcirc->base_.n_circ_id,
-                 conn_age);
+        log_info(LD_REND, "Found open intro circ %u (id: %" PRIu32 "). "
+                          "Rend circuit %u (id: %" PRIu32 "); Sending "
+                          "introduction. (stream %d sec old)",
+                 (unsigned) TO_CIRCUIT(introcirc)->n_circ_id,
+                 introcirc->global_identifier,
+                 (unsigned) TO_CIRCUIT(rendcirc)->n_circ_id,
+                 rendcirc->global_identifier, conn_age);
         ret = hs_client_send_introduce1(introcirc, rendcirc);
         switch (ret) {
         case 0: /* success */
@@ -2792,10 +2803,13 @@ connection_ap_handshake_attach_circuit(entry_connection_t *conn)
       }
     }
 
-    log_info(LD_REND, "Intro (%u) and rend (%u) circs are not both ready. "
-             "Stalling conn. (%d sec old)",
-             introcirc ? (unsigned)introcirc->base_.n_circ_id : 0,
-             rendcirc ? (unsigned)rendcirc->base_.n_circ_id : 0, conn_age);
+    log_info(LD_REND, "Intro %u (id: %" PRIu32 ") and rend circuit %u "
+                      "(id: %" PRIu32 ") circuits are not both ready. "
+                      "Stalling conn. (%d sec old)",
+             introcirc ? (unsigned) TO_CIRCUIT(introcirc)->n_circ_id : 0,
+             introcirc ? introcirc->global_identifier : 0,
+             rendcirc ? (unsigned) TO_CIRCUIT(rendcirc)->n_circ_id : 0,
+             rendcirc ? rendcirc->global_identifier : 0, conn_age);
     return 0;
   }
 }

src/or/hs_service.c

@@ -1570,6 +1570,8 @@ pick_intro_point(unsigned int direct_conn, smartlist_t *exclude_nodes)
   if (ip == NULL) {
     goto err;
   }
+
+  log_info(LD_REND, "Picked intro point: %s", extend_info_describe(info));
   extend_info_free(info);
   return ip;
  err:
@@ -1725,11 +1727,12 @@ update_service_descriptor(hs_service_t *service,
                                                                  desc);
     if (num_new_intro_points != 0) {
       log_info(LD_REND, "Service %s just picked %u intro points and wanted "
-                        "%u. It currently has %d intro points. "
-                        "Launching ESTABLISH_INTRO circuit shortly.",
+                        "%u for %s descriptor. It currently has %d intro "
+                        "points. Launching ESTABLISH_INTRO circuit shortly.",
                safe_str_client(service->onion_address),
                num_new_intro_points,
                service->config.num_intro_points - num_intro_points,
+               (desc == service->desc_current) ? "current" : "next",
                num_intro_points);
       /* We'll build those introduction point into the descriptor once we have
        * confirmation that the circuits are opened and ready. However,
@@ -2046,7 +2049,7 @@ launch_intro_point_circuits(hs_service_t *service)
       /* Launch a circuit to the intro point. */
       ip->circuit_retries++;
       if (hs_circ_launch_intro_point(service, ip, ei) < 0) {
-        log_warn(LD_REND, "Unable to launch intro circuit to node %s "
+        log_info(LD_REND, "Unable to launch intro circuit to node %s "
                           "for service %s.",
                  safe_str_client(extend_info_describe(ei)),
                  safe_str_client(service->onion_address));

src/test/test_hs_service.c

@@ -1149,9 +1149,9 @@ test_build_update_descriptors(void *arg)
   tor_free(node->ri->onion_curve25519_pkey); /* Avoid memleak. */
   tor_free(node->ri->cache_info.signing_key_cert);
   crypto_pk_free(node->ri->onion_pkey);
-  expect_log_msg_containing("just picked 1 intro points and wanted 3. It "
-                            "currently has 0 intro points. Launching "
-                            "ESTABLISH_INTRO circuit shortly.");
+  expect_log_msg_containing("just picked 1 intro points and wanted 3 for next "
+                            "descriptor. It currently has 0 intro points. "
+                            "Launching ESTABLISH_INTRO circuit shortly.");
   teardown_capture_of_logs();
   tt_int_op(digest256map_size(service->desc_current->intro_points.map),
             OP_EQ, 1);