From de54e143123ff37e2e1db09391ca32096b059b67 Mon Sep 17 00:00:00 2001 From: David Goulet Date: Mon, 25 Sep 2017 16:01:12 -0400 Subject: [PATCH 1/5] circuit: Closing reason are signed values Part of #23645 Signed-off-by: David Goulet --- src/or/circuitlist.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/or/circuitlist.c b/src/or/circuitlist.c index 9577573ec2..7fbf6e4488 100644 --- a/src/or/circuitlist.c +++ b/src/or/circuitlist.c @@ -1919,7 +1919,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, From fb4a82c485b694e080a1d86dde7be2ddbf512bc4 Mon Sep 17 00:00:00 2001 From: David Goulet Date: Mon, 25 Sep 2017 16:04:30 -0400 Subject: [PATCH 2/5] circuit: Keep a copy of n_circ_id for logging Prior to the log statement, the circuit n_circ_id value is zeroed so keep a copy so we can log it at the end. Part of #23645 Signed-off-by: David Goulet --- src/or/circuitlist.c | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/src/or/circuitlist.c b/src/or/circuitlist.c index 7fbf6e4488..65fcdaaddb 100644 --- a/src/or/circuitlist.c +++ b/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); From 767b1815e9c02b1ee45f1853b32878fb1bc806c7 Mon Sep 17 00:00:00 2001 From: David Goulet Date: Mon, 25 Sep 2017 16:08:11 -0400 Subject: [PATCH 3/5] circuit: Log circuit identifiers when cannibalizing This removes the "nickname" of the cannibalized circuit last hop as it is useless. It now logs the n_circ_id and global identifier so we can match it with other logging statement. Signed-off-by: David Goulet --- src/or/circuituse.c | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/or/circuituse.c b/src/or/circuituse.c index 343ce3bcf5..e2b21df016 100644 --- a/src/or/circuituse.c +++ b/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 || From 4190f602bd9edcd0f9f29458dda59e4d664a8b62 Mon Sep 17 00:00:00 2001 From: David Goulet Date: Mon, 25 Sep 2017 16:20:15 -0400 Subject: [PATCH 4/5] circuit: Log n_circ_id and global identifier of HS circuits So we can track them more easily in the logs and match any open/close/free with those identifiers. Part of #23645 Signed-off-by: David Goulet --- src/or/circuituse.c | 59 +++++++++++++++++++++++++++------------------ 1 file changed, 36 insertions(+), 23 deletions(-) diff --git a/src/or/circuituse.c b/src/or/circuituse.c index e2b21df016..62cc865f48 100644 --- a/src/or/circuituse.c +++ b/src/or/circuituse.c @@ -2695,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 @@ -2730,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; } @@ -2744,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; } @@ -2757,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 */ @@ -2793,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; } } From 648d5ea67e1bf362363f399c708bc3dcca5b26f6 Mon Sep 17 00:00:00 2001 From: David Goulet Date: Mon, 25 Sep 2017 16:31:43 -0400 Subject: [PATCH 5/5] hs: Improve logging Also demote a log message that can occur under natural causes (if the circuit subsystem is missing descriptors/consensus etc.). The HS subsystem will naturally retry to connect to intro points, so no need to make that log user-facing. --- src/or/hs_service.c | 9 ++++++--- src/test/test_hs_service.c | 6 +++--- 2 files changed, 9 insertions(+), 6 deletions(-) diff --git a/src/or/hs_service.c b/src/or/hs_service.c index 50c2317887..8c99f0747a 100644 --- a/src/or/hs_service.c +++ b/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)); diff --git a/src/test/test_hs_service.c b/src/test/test_hs_service.c index 859476b703..3557974ebc 100644 --- a/src/test/test_hs_service.c +++ b/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);