torproject/tor
1
0
Fork 0
mirror of https://gitlab.torproject.org/tpo/core/tor.git synced 2024-12-06 19:41:15 +01:00
Code Issues Actions Packages Projects Releases Wiki Activity

Convert circuituse, command, config, connection, relay, router, test to new logging interface

Browse Source 
svn:r5308
This commit is contained in:
Nick Mathewson
2005-10-25 07:04:36 +00:00
parent 81dd50a942
commit 452f4cfa09
6 changed files with 281 additions and 255 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/or/circuituse.c
+60 -50
View File
@@ -10,6 +10,7 @@ const char circuituse_c_id[] = "$Id$";
* \brief Launch the right sort of circuits and attach streams to them.
**/
#define NEW_LOG_INTERFACE
#include "or.h"
/** Longest time to wait for a circuit before closing an AP connection */
@@ -83,7 +84,7 @@ circuit_is_acceptable(circuit_t *circ,
if (purpose == CIRCUIT_PURPOSE_C_GENERAL) {
if (!exitrouter) {
log_fn(LOG_DEBUG,"Not considering circuit with unknown router.");
debug(LD_CIRC,"Not considering circuit with unknown router.");
return 0; /* this circuit is screwed and doesn't know it yet,
* or is a rendezvous circuit. */
}
@@ -242,12 +243,14 @@ circuit_expire_building(time_t now)
victim->purpose == CIRCUIT_PURPOSE_C_INTRODUCE_ACK_WAIT) &&
victim->timestamp_dirty + MIN_SECONDS_BEFORE_EXPIRING_CIRC > now)) {
if (victim->n_conn)
log_fn(LOG_INFO,"Abandoning circ %s:%d:%d (state %d:%s, purpose %d)",
info(LD_CIRC,"Abandoning circ %s:%d:%d (state %d:%s, purpose %d)",
victim->n_conn->address, victim->n_port, victim->n_circ_id,
victim->state, circuit_state_to_string(victim->state), victim->purpose);
else
log_fn(LOG_INFO,"Abandoning circ %d (state %d:%s, purpose %d)", victim->n_circ_id,
victim->state, circuit_state_to_string(victim->state), victim->purpose);
info(LD_CIRC,"Abandoning circ %d (state %d:%s, purpose %d)",
victim->n_circ_id, victim->state,
circuit_state_to_string(victim->state), victim->purpose);
circuit_log_path(LOG_INFO,LD_CIRC,victim);
circuit_mark_for_close(victim);
}
@@ -267,11 +270,11 @@ circuit_remove_handled_ports(smartlist_t *needed_ports)
port = smartlist_get(needed_ports, i);
tor_assert(*port);
if (circuit_stream_is_being_handled(NULL, *port, 2)) {
// log_fn(LOG_DEBUG,"Port %d is already being handled; removing.", port);
// debug(LD_CIRC,"Port %d is already being handled; removing.", port);
smartlist_del(needed_ports, i--);
tor_free(port);
} else {
log_fn(LOG_DEBUG,"Port %d is not handled.", *port);
debug(LD_CIRC,"Port %d is not handled.", *port);
}
}
}
@@ -359,7 +362,7 @@ circuit_predict_and_launch_new(void)
* and no circuit is currently available that can handle it. */
if (!circuit_all_predicted_ports_handled(now, &port_needs_uptime,
&port_needs_capacity)) {
log_fn(LOG_INFO,"Have %d clean circs (%d internal), need another exit circ.",
info(LD_CIRC,"Have %d clean circs (%d internal), need another exit circ.",
num, num_internal);
circuit_launch_by_router(CIRCUIT_PURPOSE_C_GENERAL, NULL,
port_needs_uptime, port_needs_capacity, 0);
@@ -368,7 +371,7 @@ circuit_predict_and_launch_new(void)
/* Third, see if we need any more hidden service (server) circuits. */
if (num_rend_services() && num_uptime_internal < 3) {
log_fn(LOG_INFO,"Have %d clean circs (%d internal), need another internal circ for my hidden service.",
info(LD_CIRC,"Have %d clean circs (%d internal), need another internal circ for my hidden service.",
num, num_internal);
circuit_launch_by_router(CIRCUIT_PURPOSE_C_GENERAL, NULL,
1, 1, 1);
@@ -380,7 +383,7 @@ circuit_predict_and_launch_new(void)
&hidserv_needs_capacity) &&
((num_uptime_internal<2 && hidserv_needs_uptime) ||
num_internal<2)) {
log_fn(LOG_INFO,"Have %d clean circs (%d uptime-internal, %d internal),"
info(LD_CIRC,"Have %d clean circs (%d uptime-internal, %d internal),"
" need another hidserv circ.", num, num_uptime_internal, num_internal);
circuit_launch_by_router(CIRCUIT_PURPOSE_C_GENERAL, NULL,
hidserv_needs_uptime, hidserv_needs_capacity, 1);
@@ -482,7 +485,7 @@ circuit_detach_stream(circuit_t *circ, connection_t *conn)
return;
}
log_fn(LOG_ERR,"edge conn not in circuit's list?");
err(LD_BUG,"edge conn not in circuit's list?");
tor_assert(0); /* should never get here */
}
@@ -554,8 +557,8 @@ circuit_expire_old_circuits(void)
circ->timestamp_dirty + get_options()->MaxCircuitDirtiness < now &&
CIRCUIT_IS_ORIGIN(circ) &&
!circ->p_streams /* nothing attached */ ) {
log_fn(LOG_DEBUG,"Closing n_circ_id %d (dirty %d secs ago, purp %d)",circ->n_circ_id,
(int)(now - circ->timestamp_dirty), circ->purpose);
debug(LD_CIRC,"Closing n_circ_id %d (dirty %d secs ago, purp %d)",
circ->n_circ_id, (int)(now - circ->timestamp_dirty), circ->purpose);
/* (only general and purpose_c circs can get dirty) */
tor_assert(!circ->n_streams);
tor_assert(circ->purpose <= CIRCUIT_PURPOSE_C_REND_JOINED);
@@ -565,7 +568,7 @@ circuit_expire_old_circuits(void)
circ->purpose == CIRCUIT_PURPOSE_C_GENERAL) {
#define CIRCUIT_UNUSED_CIRC_TIMEOUT 3600 /* an hour */
if (circ->timestamp_created + CIRCUIT_UNUSED_CIRC_TIMEOUT < now) {
log_fn(LOG_DEBUG,"Closing circuit that has been unused for %d seconds.",
debug(LD_CIRC,"Closing circuit that has been unused for %d seconds.",
(int)(now - circ->timestamp_created));
circuit_mark_for_close(circ);
}
@@ -594,7 +597,7 @@ circuit_testing_failed(circuit_t *circ, int at_last_hop)
circuit_launch_by_router(CIRCUIT_PURPOSE_TESTING, me, 0, 1, 1);
else
#endif
log_fn(LOG_INFO,"Our testing circuit (to see if your ORPort is reachable) has failed. I'll try again later.");
info(LD_GENERAL,"Our testing circuit (to see if your ORPort is reachable) has failed. I'll try again later.");
}
/** The circuit <b>circ</b> has just become open. Take the next
@@ -633,7 +636,7 @@ circuit_has_opened(circuit_t *circ)
circuit_testing_opened(circ);
break;
default:
log_fn(LOG_ERR,"unhandled purpose %d",circ->purpose);
err(LD_BUG,"unhandled purpose %d",circ->purpose);
tor_assert(0);
}
}
@@ -694,9 +697,10 @@ circuit_build_failed(circuit_t *circ)
/* at Bob, connecting to rend point */
/* Don't increment failure count, since Alice may have picked
* the rendezvous point maliciously */
log_fn(LOG_INFO,"Couldn't connect to Alice's chosen rend point %s (%s hop failed).",
build_state_get_exit_nickname(circ->build_state),
failed_at_last_hop?"last":"non-last");
info(LD_REND,
"Couldn't connect to Alice's chosen rend point %s (%s hop failed).",
build_state_get_exit_nickname(circ->build_state),
failed_at_last_hop?"last":"non-last");
rend_service_relaunch_rendezvous(circ);
break;
default:
@@ -746,7 +750,7 @@ circuit_launch_by_extend_info(uint8_t purpose, extend_info_t *info,
circuit_t *circ;
if (!has_fetched_directory) {
log_fn(LOG_DEBUG,"Haven't fetched directory yet; canceling circuit launch.");
debug(LD_CIRC,"Haven't fetched directory yet; canceling circuit launch.");
return NULL;
}
@@ -755,7 +759,7 @@ circuit_launch_by_extend_info(uint8_t purpose, extend_info_t *info,
/* see if there are appropriate circs available to cannibalize. */
if ((circ = circuit_get_clean_open(CIRCUIT_PURPOSE_C_GENERAL, need_uptime,
need_capacity, internal))) {
log_fn(LOG_INFO,"Cannibalizing circ '%s' for purpose %d",
info(LD_CIRC,"Cannibalizing circ '%s' for purpose %d",
build_state_get_exit_nickname(circ->build_state), purpose);
circ->purpose = purpose;
/* reset the birth date of this circ, else expire_building
@@ -776,8 +780,7 @@ circuit_launch_by_extend_info(uint8_t purpose, extend_info_t *info,
return NULL;
break;
default:
log_fn(LOG_WARN,"Bug: unexpected purpose %d when cannibalizing a general circ.",
purpose);
warn(LD_BUG, "Bug: unexpected purpose %d when cannibalizing a general circ.", purpose);
tor_fragile_assert();
return NULL;
}
@@ -808,7 +811,8 @@ circuit_launch_by_nickname(uint8_t purpose, const char *exit_nickname,
if (exit_nickname) {
router = router_get_by_nickname(exit_nickname, 1);
if (!router) {
log_fn(LOG_WARN, "No such OR as '%s'", exit_nickname);
/*XXXXNM domain? */
warn(LD_GENERAL, "No such OR as '%s'", exit_nickname);
return NULL;
}
}
@@ -823,7 +827,7 @@ static void
circuit_increment_failure_count(void)
{
++n_circuit_failures;
log_fn(LOG_DEBUG,"n_circuit_failures now %d.",n_circuit_failures);
debug(LD_CIRC,"n_circuit_failures now %d.",n_circuit_failures);
}
/** Reset the failure count for opening general circuits. This means
@@ -869,7 +873,7 @@ circuit_get_open_circ_or_launch(connection_t *conn,
if (!has_fetched_directory) {
if (!connection_get_by_type(CONN_TYPE_DIR)) {
log(LOG_NOTICE,"Application request when we're believed to be offline. Optimistically trying again.");
notice(LD_APP|LD_DIR,"Application request when we're believed to be offline. Optimistically trying directory fetches again.");
router_reset_status_download_failures();
router_reset_descriptor_download_failures();
update_networkstatus_downloads(time(NULL));
@@ -895,7 +899,8 @@ circuit_get_open_circ_or_launch(connection_t *conn,
addr = ntohl(in.s_addr);
if (router_exit_policy_all_routers_reject(addr, conn->socks_request->port,
need_uptime)) {
log(LOG_NOTICE,"No Tor server exists that allows exit to %s:%d. Rejecting.",
/* LD_GENERAL? LD_APP? ???? NM */
notice(LD_CIRC,"No Tor server exists that allows exit to %s:%d. Rejecting.",
safe_str(conn->socks_request->address), conn->socks_request->port);
return -1;
}
@@ -912,14 +917,14 @@ circuit_get_open_circ_or_launch(connection_t *conn,
/* need to pick an intro point */
extend_info = rend_client_get_random_intro(conn->rend_query);
if (!extend_info) {
log_fn(LOG_INFO,"No intro points for '%s': refetching service descriptor.",
safe_str(conn->rend_query));
info(LD_REND,"No intro points for '%s': refetching service descriptor.",
safe_str(conn->rend_query));
rend_client_refetch_renddesc(conn->rend_query);
conn->state = AP_CONN_STATE_RENDDESC_WAIT;
return 0;
}
log_fn(LOG_INFO,"Chose %s as intro point for %s.",
extend_info->nickname, safe_str(conn->rend_query));
info(LD_REND,"Chose %s as intro point for %s.",
extend_info->nickname, safe_str(conn->rend_query));
}
/* If we have specified a particular exit node for our
@@ -929,7 +934,8 @@ circuit_get_open_circ_or_launch(connection_t *conn,
if (conn->chosen_exit_name) {
routerinfo_t *r;
if (!(r = router_get_by_nickname(conn->chosen_exit_name, 1))) {
log_fn(LOG_NOTICE,"Requested exit point '%s' is not known. Closing.",
/*XXXX NM domain? */
notice(LD_CIRC,"Requested exit point '%s' is not known. Closing.",
conn->chosen_exit_name);
return -1;
}
@@ -963,8 +969,9 @@ circuit_get_open_circ_or_launch(connection_t *conn,
}
}
if (!circ)
log_fn(LOG_INFO,"No safe circuit (purpose %d) ready for edge connection; delaying.",
desired_circuit_purpose);
info(LD_APP,
"No safe circuit (purpose %d) ready for edge connection; delaying.",
desired_circuit_purpose);
*circp = circ;
return 0;
}
@@ -977,7 +984,7 @@ static void
link_apconn_to_circ(connection_t *apconn, circuit_t *circ)
{
/* add it into the linked list of streams on this circuit */
log_fn(LOG_DEBUG,"attaching new conn to circ. n_circ_id %d.", circ->n_circ_id);
debug(LD_APP|LD_CIRC,"attaching new conn to circ. n_circ_id %d.", circ->n_circ_id);
apconn->timestamp_lastread = time(NULL); /* reset it, so we can measure circ timeouts */
apconn->next_stream = circ->p_streams;
apconn->on_circuit = circ;
@@ -1093,8 +1100,9 @@ connection_ap_handshake_attach_circuit(connection_t *conn)
conn_age = time(NULL) - conn->timestamp_created;
if (conn_age > CONN_AP_MAX_ATTACH_DELAY) {
log(LOG_NOTICE,"Tried for %d seconds to get a connection to %s:%d. Giving up.",
conn_age, safe_str(conn->socks_request->address), conn->socks_request->port);
notice(LD_APP,"Tried for %d seconds to get a connection to %s:%d. Giving up.",
conn_age, safe_str(conn->socks_request->address),
conn->socks_request->port);
return -1;
}
@@ -1104,12 +1112,12 @@ connection_ap_handshake_attach_circuit(connection_t *conn)
if (conn->chosen_exit_name) {
routerinfo_t *router = router_get_by_nickname(conn->chosen_exit_name, 1);
if (!router) {
log_fn(LOG_WARN,"Requested exit point '%s' is not known. Closing.",
warn(LD_APP,"Requested exit point '%s' is not known. Closing.",
conn->chosen_exit_name);
return -1;
}
if (!connection_ap_can_use_exit(conn, router)) {
log_fn(LOG_WARN, "Requested exit point '%s' would refuse request. Closing.",
warn(LD_APP, "Requested exit point '%s' would refuse request. Closing.",
conn->chosen_exit_name);
return -1;
}
@@ -1120,10 +1128,10 @@ connection_ap_handshake_attach_circuit(connection_t *conn)
if (retval < 1)
return retval;
log_fn(LOG_DEBUG,"Attaching apconn to circ %d (stream %d sec old).",
debug(LD_APP|LD_CIRC,"Attaching apconn to circ %d (stream %d sec old).",
circ->n_circ_id, conn_age);
/* here, print the circ's path. so people can figure out which circs are sucking. */
circuit_log_path(LOG_INFO,LD_APP,circ);
circuit_log_path(LOG_INFO,LD_APP|LD_CIRC,circ);
/* We have found a suitable circuit for our conn. Hurray. */
return connection_ap_handshake_attach_chosen_circuit(conn, circ);
@@ -1141,8 +1149,9 @@ connection_ap_handshake_attach_circuit(connection_t *conn)
if (retval > 0) {
tor_assert(rendcirc);
/* one is already established, attach */
log_fn(LOG_INFO,"rend joined circ %d already here. attaching. (stream %d sec old)",
rendcirc->n_circ_id, conn_age);
info(LD_REND,
"rend joined circ %d already here. attaching. (stream %d sec old)",
rendcirc->n_circ_id, 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 tradeoffs between linkability and
@@ -1156,7 +1165,7 @@ connection_ap_handshake_attach_circuit(connection_t *conn)
}
if (rendcirc && rendcirc->purpose == CIRCUIT_PURPOSE_C_REND_READY_INTRO_ACKED) {
log_fn(LOG_INFO,"pending-join circ %d already here, with intro ack. Stalling. (stream %d sec old)", rendcirc->n_circ_id, conn_age);
info(LD_REND,"pending-join circ %d already here, with intro ack. Stalling. (stream %d sec old)", rendcirc->n_circ_id, conn_age);
return 0;
}
@@ -1167,20 +1176,21 @@ connection_ap_handshake_attach_circuit(connection_t *conn)
if (retval > 0) {
/* one has already sent the intro. keep waiting. */
tor_assert(introcirc);
log_fn(LOG_INFO,"Intro circ %d present and awaiting ack (rend %d). Stalling. (stream %d sec old)",
introcirc->n_circ_id, rendcirc ? rendcirc->n_circ_id : 0, conn_age);
info(LD_REND,
"Intro circ %d present and awaiting ack (rend %d). Stalling. (stream %d sec old)",
introcirc->n_circ_id, rendcirc ? rendcirc->n_circ_id : 0, conn_age);
return 0;
}
/* now rendcirc and introcirc are each either undefined or not finished */
if (rendcirc && introcirc && rendcirc->purpose == CIRCUIT_PURPOSE_C_REND_READY) {
log_fn(LOG_INFO,"ready rend circ %d already here (no intro-ack yet on intro %d). (stream %d sec old)",
info(LD_REND,"ready rend circ %d already here (no intro-ack yet on intro %d). (stream %d sec old)",
rendcirc->n_circ_id, introcirc->n_circ_id, conn_age);
tor_assert(introcirc->purpose == CIRCUIT_PURPOSE_C_INTRODUCING);
if (introcirc->state == CIRCUIT_STATE_OPEN) {
log_fn(LOG_INFO,"found open intro circ %d (rend %d); sending introduction. (stream %d sec old)",
info(LD_REND,"found open intro circ %d (rend %d); sending introduction. (stream %d sec old)",
introcirc->n_circ_id, rendcirc->n_circ_id, conn_age);
if (rend_client_send_introduction(introcirc, rendcirc) < 0) {
return -1;
@@ -1193,9 +1203,9 @@ connection_ap_handshake_attach_circuit(connection_t *conn)
}
}
log_fn(LOG_INFO,"Intro (%d) and rend (%d) circs are not both ready. Stalling conn. (%d sec old)",
introcirc ? introcirc->n_circ_id : 0,
rendcirc ? rendcirc->n_circ_id : 0, conn_age);
info(LD_REND, "Intro (%d) and rend (%d) circs are not both ready. Stalling conn. (%d sec old)",
introcirc ? introcirc->n_circ_id : 0,
rendcirc ? rendcirc->n_circ_id : 0, conn_age);
return 0;
}
}
src/or/command.c
+30 -28
View File
@@ -16,6 +16,7 @@ const char command_c_id[] = "$Id$";
* connection_or_process_cells_from_inbuf() in connection_or.c
*/
#define NEW_LOG_INTERFACE
#include "or.h"
/** Keep statistics about how many of each type of cell we've received. */
@@ -51,10 +52,10 @@ command_time_process_cell(cell_t *cell, connection_t *conn, int *time,
time_passed = tv_udiff(&start, &end) ;
if (time_passed > 10000) { /* more than 10ms */
log_fn(LOG_DEBUG,"That call just took %ld ms.",time_passed/1000);
debug(LD_OR,"That call just took %ld ms.",time_passed/1000);
}
if (time_passed < 0) {
log_fn(LOG_INFO,"That call took us back in time!");
info(LD_GENERAL,"That call took us back in time!");
time_passed = 0;
}
*time += time_passed;
@@ -81,7 +82,7 @@ command_process_cell(cell_t *cell, connection_t *conn)
if (now > current_second) { /* the second has rolled over */
/* print stats */
log(LOG_INFO,"At end of second: %d creates (%d ms), %d createds (%d ms), %d relays (%d ms), %d destroys (%d ms)",
info(LD_OR,"At end of second: %d creates (%d ms), %d createds (%d ms), %d relays (%d ms), %d destroys (%d ms)",
num_create, create_time/1000,
num_created, created_time/1000,
num_relay, relay_time/1000,
@@ -144,7 +145,7 @@ command_process_cell(cell_t *cell, connection_t *conn)
#endif
break;
default:
log_fn(LOG_PROTOCOL_WARN,
log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL,
"Cell of unknown type (%d) received. Dropping.", cell->command);
break;
}
@@ -161,7 +162,7 @@ command_process_create_cell(cell_t *cell, connection_t *conn)
circuit_t *circ;
if (we_are_hibernating()) {
log_fn(LOG_INFO,"Received create cell but we're shutting down. Sending back destroy.");
info(LD_OR,"Received create cell but we're shutting down. Sending back destroy.");
connection_send_destroy(cell->circ_id, conn);
return;
}
@@ -173,11 +174,11 @@ command_process_create_cell(cell_t *cell, connection_t *conn)
* half to use based on nickname, and we now use identity keys.
*/
if ((cell->circ_id & (1<<15)) && conn->circ_id_type == CIRC_ID_TYPE_HIGHER) {
log_fn(LOG_INFO, "Got a high circuit ID from %s (%d); switching to low circuit IDs.",
info(LD_OR, "Got a high circuit ID from %s (%d); switching to low circuit IDs.",
conn->nickname ? conn->nickname : "client", conn->s);
conn->circ_id_type = CIRC_ID_TYPE_LOWER;
} else if (!(cell->circ_id & (1<<15)) && conn->circ_id_type == CIRC_ID_TYPE_LOWER) {
log_fn(LOG_INFO, "Got a low circuit ID from %s (%d); switching to high circuit IDs.",
info(LD_OR, "Got a low circuit ID from %s (%d); switching to high circuit IDs.",
conn->nickname ? conn->nickname : "client", conn->s);
conn->circ_id_type = CIRC_ID_TYPE_HIGHER;
}
@@ -186,11 +187,11 @@ command_process_create_cell(cell_t *cell, connection_t *conn)
if (circ) {
routerinfo_t *router = router_get_by_digest(conn->identity_digest);
log_fn(LOG_PROTOCOL_WARN,
log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL,
"received CREATE cell (circID %d) for known circ. Dropping (age %d).",
cell->circ_id, (int)(time(NULL) - conn->timestamp_created));
if (router)
log_fn(LOG_PROTOCOL_WARN,
log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL,
"Details: nickname '%s', platform '%s'.",
router->nickname, router->platform);
return;
@@ -204,22 +205,22 @@ command_process_create_cell(cell_t *cell, connection_t *conn)
/* hand it off to the cpuworkers, and then return */
if (assign_to_cpuworker(NULL, CPUWORKER_TASK_ONION, circ) < 0) {
log_fn(LOG_WARN,"Failed to hand off onionskin. Closing.");
warn(LD_GENERAL,"Failed to hand off onionskin. Closing.");
circuit_mark_for_close(circ);
return;
}
log_fn(LOG_DEBUG,"success: handed off onionskin.");
debug(LD_OR,"success: handed off onionskin.");
} else {
char keys[CPATH_KEY_MATERIAL_LEN];
char reply[DIGEST_LEN*2];
tor_assert(cell->command == CELL_CREATE_FAST);
if (fast_server_handshake(cell->payload, reply, keys, sizeof(keys))<0) {
log_fn(LOG_WARN,"Failed to generate key material. Closing.");
warn(LD_OR,"Failed to generate key material. Closing.");
circuit_mark_for_close(circ);
return;
}
if (onionskin_answer(circ, CELL_CREATED_FAST, reply, keys)<0) {
log_fn(LOG_WARN,"Failed to reply to CREATE_FAST cell. Closing.");
warn(LD_OR,"Failed to reply to CREATE_FAST cell. Closing.");
circuit_mark_for_close(circ);
return;
}
@@ -241,31 +242,32 @@ command_process_created_cell(cell_t *cell, connection_t *conn)
circ = circuit_get_by_circid_orconn(cell->circ_id, conn);
if (!circ) {
log_fn(LOG_INFO,"(circID %d) unknown circ (probably got a destroy earlier). Dropping.", cell->circ_id);
info(LD_OR,"(circID %d) unknown circ (probably got a destroy earlier). Dropping.", cell->circ_id);
return;
}
if (circ->n_circ_id != cell->circ_id) {
log_fn(LOG_PROTOCOL_WARN,"got created cell from OPward? Closing.");
log_fn(LOG_PROTOCOL_WARN,LD_PROTOCOL,
"got created cell from OPward? Closing.");
circuit_mark_for_close(circ);
return;
}
if (CIRCUIT_IS_ORIGIN(circ)) { /* we're the OP. Handshake this. */
log_fn(LOG_DEBUG,"at OP. Finishing handshake.");
debug(LD_OR,"at OP. Finishing handshake.");
if (circuit_finish_handshake(circ, cell->command, cell->payload) < 0) {
log_fn(LOG_WARN,"circuit_finish_handshake failed.");
warn(LD_OR,"circuit_finish_handshake failed.");
circuit_mark_for_close(circ);
return;
}
log_fn(LOG_DEBUG,"Moving to next skin.");
debug(LD_OR,"Moving to next skin.");
if (circuit_send_next_onion_skin(circ) < 0) {
log_fn(LOG_INFO,"circuit_send_next_onion_skin failed.");
info(LD_OR,"circuit_send_next_onion_skin failed.");
circuit_mark_for_close(circ); /* XXX push this circuit_close lower */
return;
}
} else { /* pack it into an extended relay cell, and send it. */
log_fn(LOG_DEBUG,"Converting created cell to extended relay cell, sending.");
debug(LD_OR,"Converting created cell to extended relay cell, sending.");
connection_edge_send_command(NULL, circ, RELAY_COMMAND_EXTENDED,
cell->payload, ONIONSKIN_REPLY_LEN, NULL);
}
@@ -283,26 +285,26 @@ command_process_relay_cell(cell_t *cell, connection_t *conn)
circ = circuit_get_by_circid_orconn(cell->circ_id, conn);
if (!circ) {
log_fn(LOG_DEBUG,"unknown circuit %d on connection from %s:%d. Dropping.",
cell->circ_id, conn->address, conn->port);
debug(LD_OR,"unknown circuit %d on connection from %s:%d. Dropping.",
cell->circ_id, conn->address, conn->port);
return;
}
if (circ->state == CIRCUIT_STATE_ONIONSKIN_PENDING) {
log_fn(LOG_PROTOCOL_WARN,"circuit in create_wait. Closing.");
log_fn(LOG_PROTOCOL_WARN,LD_PROTOCOL,"circuit in create_wait. Closing.");
circuit_mark_for_close(circ);
return;
}
if (cell->circ_id == circ->p_circ_id) { /* it's an outgoing cell */
if (circuit_receive_relay_cell(cell, circ, CELL_DIRECTION_OUT) < 0) {
log_fn(LOG_PROTOCOL_WARN,"circuit_receive_relay_cell (forward) failed. Closing.");
log_fn(LOG_PROTOCOL_WARN,LD_PROTOCOL,"circuit_receive_relay_cell (forward) failed. Closing.");
circuit_mark_for_close(circ);
return;
}
} else { /* it's an ingoing cell */
if (circuit_receive_relay_cell(cell, circ, CELL_DIRECTION_IN) < 0) {
log_fn(LOG_PROTOCOL_WARN,"circuit_receive_relay_cell (backward) failed. Closing.");
log_fn(LOG_PROTOCOL_WARN,LD_PROTOCOL,"circuit_receive_relay_cell (backward) failed. Closing.");
circuit_mark_for_close(circ);
return;
}
@@ -330,12 +332,12 @@ command_process_destroy_cell(cell_t *cell, connection_t *conn)
circ = circuit_get_by_circid_orconn(cell->circ_id, conn);
if (!circ) {
log_fn(LOG_INFO,"unknown circuit %d on connection from %s:%d. Dropping.",
info(LD_OR,"unknown circuit %d on connection from %s:%d. Dropping.",
cell->circ_id, conn->address, conn->port);
return;
}
log_fn(LOG_DEBUG,"Received for circID %d.",cell->circ_id);
debug(LD_OR,"Received for circID %d.",cell->circ_id);
if (circ->state == CIRCUIT_STATE_ONIONSKIN_PENDING) {
onion_pending_remove(circ);
}
@@ -349,7 +351,7 @@ command_process_destroy_cell(cell_t *cell, connection_t *conn)
if (CIRCUIT_IS_ORIGIN(circ)) {
circuit_mark_for_close(circ);
} else {
log_fn(LOG_DEBUG, "Delivering 'truncated' back.");
debug(LD_OR, "Delivering 'truncated' back.");
connection_edge_send_command(NULL, circ, RELAY_COMMAND_TRUNCATED,
NULL, 0, NULL);
}
src/or/connection.c
+67 -64
View File
@@ -11,6 +11,7 @@ const char connection_c_id[] = "$Id$";
* on connections.
**/
#define NEW_LOG_INTERFACE
#include "or.h"
static connection_t *connection_create_listener(const char *listenaddress,
@@ -51,7 +52,7 @@ conn_type_to_string(int type)
case CONN_TYPE_CONTROL_LISTENER: return "Control listener";
case CONN_TYPE_CONTROL: return "Control";
default:
log_fn(LOG_WARN, "Bug: unknown connection type %d", type);
warn(LD_BUG, "Bug: unknown connection type %d", type);
tor_snprintf(buf, sizeof(buf), "unknown [%d]", type);
return buf;
}
@@ -134,7 +135,7 @@ conn_state_to_string(int type, int state)
break;
}
log_fn(LOG_WARN, "Bug: unknown connection state %d (type %d)", state, type);
warn(LD_BUG, "Bug: unknown connection state %d (type %d)", state, type);
tor_snprintf(buf, sizeof(buf),
"unknown state [%d] on unknown [%s] connection",
state, conn_type_to_string(type));
@@ -191,12 +192,12 @@ connection_unregister(connection_t *conn)
{
if (conn->read_event) {
if (event_del(conn->read_event))
log_fn(LOG_WARN, "Error removing read event for %d", conn->s);
warn(LD_BUG, "Error removing read event for %d", conn->s);
tor_free(conn->read_event);
}
if (conn->write_event) {
if (event_del(conn->write_event))
log_fn(LOG_WARN, "Error removing write event for %d", conn->s);
warn(LD_BUG, "Error removing write event for %d", conn->s);
tor_free(conn->write_event);
}
}
@@ -234,7 +235,7 @@ _connection_free(connection_t *conn)
tor_free(conn->requested_resource);
if (conn->s >= 0) {
log_fn(LOG_DEBUG,"closing fd %d.",conn->s);
debug(LD_NET,"closing fd %d.",conn->s);
tor_close_socket(conn->s);
}
@@ -312,7 +313,7 @@ connection_about_to_close_connection(connection_t *conn)
if (CONN_IS_EDGE(conn)) {
if (!conn->has_sent_end) {
log_fn(LOG_WARN,"Harmless bug: Edge connection (marked at %s:%d) hasn't sent end yet?", conn->marked_for_close_file, conn->marked_for_close);
warn(LD_BUG,"Harmless bug: Edge connection (marked at %s:%d) hasn't sent end yet?", conn->marked_for_close_file, conn->marked_for_close);
tor_fragile_assert();
}
}
@@ -356,7 +357,7 @@ connection_about_to_close_connection(connection_t *conn)
if (conn->socks_request->has_finished == 0) {
/* since conn gets removed right after this function finishes,
* there's no point trying to send back a reply at this point. */
log_fn(LOG_WARN,"Bug: Closing stream (marked at %s:%d) without sending back a socks reply.",
warn(LD_BUG,"Bug: Closing stream (marked at %s:%d) without sending back a socks reply.",
conn->marked_for_close_file, conn->marked_for_close);
} else {
control_event_stream_status(conn, STREAM_EVENT_CLOSED);
@@ -387,12 +388,12 @@ connection_close_immediate(connection_t *conn)
{
assert_connection_ok(conn,0);
if (conn->s < 0) {
log_fn(LOG_WARN,"Bug: Attempt to close already-closed connection.");
err(LD_BUG,"Bug: Attempt to close already-closed connection.");
tor_fragile_assert();
return;
}
if (conn->outbuf_flushlen) {
log_fn(LOG_INFO,"fd %d, type %s, state %s, %d bytes on outbuf.",
info(LD_NET,"fd %d, type %s, state %s, %d bytes on outbuf.",
conn->s, conn_type_to_string(conn->type),
conn_state_to_string(conn->type, conn->state),
(int)conn->outbuf_flushlen);
@@ -418,7 +419,7 @@ _connection_mark_for_close(connection_t *conn, int line, const char *file)
tor_assert(file);
if (conn->marked_for_close) {
log(LOG_WARN, "Duplicate call to connection_mark_for_close at %s:%d"
log(LOG_WARN,LD_BUG,"Duplicate call to connection_mark_for_close at %s:%d"
" (first at %s:%d)", file, line, conn->marked_for_close_file,
conn->marked_for_close);
tor_fragile_assert();
@@ -464,7 +465,8 @@ connection_expire_held_open(void)
severity = LOG_INFO;
else
severity = LOG_NOTICE;
log_fn(severity, "Giving up on marked_for_close conn that's been flushing for 15s (fd %d, type %s, state %s).",
log_fn(severity, LD_NET,
"Giving up on marked_for_close conn that's been flushing for 15s (fd %d, type %s, state %s).",
conn->s, conn_type_to_string(conn->type),
conn_state_to_string(conn->type, conn->state));
conn->hold_open_until_flushed = 0;
@@ -496,7 +498,7 @@ connection_create_listener(const char *listenaddress, uint16_t listenport,
memset(&listenaddr,0,sizeof(struct sockaddr_in));
if (parse_addr_port(listenaddress, &address, &addr, &usePort)<0) {
log_fn(LOG_WARN, "Error parsing/resolving ListenAddress %s",listenaddress);
warn(LD_CONFIG, "Error parsing/resolving ListenAddress %s",listenaddress);
return NULL;
}
@@ -506,15 +508,15 @@ connection_create_listener(const char *listenaddress, uint16_t listenport,
listenaddr.sin_family = AF_INET;
listenaddr.sin_port = htons((uint16_t) usePort);
log_fn(LOG_NOTICE, "Opening %s on %s:%d",
notice(LD_NET, "Opening %s on %s:%d",
conn_type_to_string(type), address, usePort);
s = socket(PF_INET,SOCK_STREAM,IPPROTO_TCP);
if (s < 0) {
log_fn(LOG_WARN,"Socket creation failed.");
warn(LD_NET,"Socket creation failed.");
goto err;
} else if (!SOCKET_IS_POLLABLE(s)) {
log_fn(LOG_WARN,"Too many connections; can't create pollable listener.");
warn(LD_NET,"Too many connections; can't create pollable listener.");
tor_close_socket(s);
goto err;
}
@@ -528,13 +530,13 @@ connection_create_listener(const char *listenaddress, uint16_t listenport,
#endif
if (bind(s,(struct sockaddr *)&listenaddr,sizeof(listenaddr)) < 0) {
log_fn(LOG_WARN, "Could not bind to %s:%u: %s", address, usePort,
warn(LD_NET, "Could not bind to %s:%u: %s", address, usePort,
tor_socket_strerror(tor_socket_errno(s)));
goto err;
}
if (listen(s,SOMAXCONN) < 0) {
log_fn(LOG_WARN, "Could not listen on %s:%u: %s", address, usePort,
warn(LD_NET, "Could not listen on %s:%u: %s", address, usePort,
tor_socket_strerror(tor_socket_errno(s)));
goto err;
}
@@ -548,12 +550,12 @@ connection_create_listener(const char *listenaddress, uint16_t listenport,
conn->port = usePort;
if (connection_add(conn) < 0) { /* no space, forget it */
log_fn(LOG_WARN,"connection_add failed. Giving up.");
warn(LD_NET,"connection_add failed. Giving up.");
connection_free(conn);
goto err;
}
log_fn(LOG_DEBUG,"%s listening on port %u.",conn_type_to_string(type), usePort);
debug(LD_NET,"%s listening on port %u.",conn_type_to_string(type), usePort);
conn->state = LISTENER_STATE_READY;
connection_start_reading(conn);
@@ -574,17 +576,17 @@ check_sockaddr_in(struct sockaddr *sa, int len, int level)
struct sockaddr_in *sin=(struct sockaddr_in*)sa;
if (len != sizeof(struct sockaddr_in)) {
log_fn(level, "Length of address not as expected: %d vs %d",
log_fn(level, LD_NET, "Length of address not as expected: %d vs %d",
len,(int)sizeof(struct sockaddr_in));
ok = 0;
}
if (sa->sa_family != AF_INET) {
log_fn(level, "Family of address not as expected: %d vs %d",
log_fn(level, LD_NET, "Family of address not as expected: %d vs %d",
sa->sa_family, AF_INET);
ok = 0;
}
if (sin->sin_addr.s_addr == 0 || sin->sin_port == 0) {
log_fn(level, "Address for new connection has address/port equal to zero.");
log_fn(level, LD_NET, "Address for new connection has address/port equal to zero.");
ok = 0;
}
return ok ? 0 : -1;
@@ -613,7 +615,7 @@ connection_handle_listener_read(connection_t *conn, int new_type)
int e;
if (news>=0) {
/* Too many conns to poll. */
log_fn(LOG_WARN,"Too many connections; couldn't accept connection.");
warn(LD_NET,"Too many connections; couldn't accept connection.");
tor_close_socket(news);
return 0;
}
@@ -621,29 +623,29 @@ connection_handle_listener_read(connection_t *conn, int new_type)
if (ERRNO_IS_ACCEPT_EAGAIN(e)) {
return 0; /* he hung up before we could accept(). that's fine. */
} else if (ERRNO_IS_ACCEPT_RESOURCE_LIMIT(e)) {
log_fn(LOG_NOTICE,"accept failed: %s. Dropping incoming connection.",
notice(LD_NET,"accept failed: %s. Dropping incoming connection.",
tor_socket_strerror(e));
return 0;
}
/* else there was a real error. */
log_fn(LOG_WARN,"accept() failed: %s. Closing listener.",
warn(LD_NET,"accept() failed: %s. Closing listener.",
tor_socket_strerror(e));
connection_mark_for_close(conn);
return -1;
}
log(LOG_DEBUG,"Connection accepted on socket %d (child of fd %d).",news, conn->s);
debug(LD_NET,"Connection accepted on socket %d (child of fd %d).",news,conn->s);
set_socket_nonblocking(news);
if (check_sockaddr_in((struct sockaddr*)addrbuf, remotelen, LOG_INFO)<0) {
log_fn(LOG_INFO, "accept() returned a strange address; trying getsockname().");
info(LD_NET, "accept() returned a strange address; trying getsockname().");
remotelen=256;
memset(addrbuf, 0, sizeof(addrbuf));
if (getsockname(news, (struct sockaddr*)addrbuf, &remotelen)<0) {
log_fn(LOG_WARN, "getsockname() failed.");
warn(LD_NET, "getsockname() failed.");
} else {
if (check_sockaddr_in((struct sockaddr*)addrbuf, remotelen, LOG_WARN)<0) {
log_fn(LOG_WARN,"Something's wrong with this conn. Closing it.");
warn(LD_NET,"Something's wrong with this conn. Closing it.");
tor_close_socket(news);
return 0;
}
@@ -656,7 +658,7 @@ connection_handle_listener_read(connection_t *conn, int new_type)
/* check sockspolicy to see if we should accept it */
if (socks_policy_permits_address(ntohl(remote.sin_addr.s_addr)) == 0) {
tor_inet_ntoa(&remote.sin_addr, tmpbuf, sizeof(tmpbuf));
log_fn(LOG_NOTICE,"Denying socks connection from untrusted address %s.",
notice(LD_APP,"Denying socks connection from untrusted address %s.",
tmpbuf);
tor_close_socket(news);
return 0;
@@ -666,7 +668,7 @@ connection_handle_listener_read(connection_t *conn, int new_type)
/* check dirpolicy to see if we should accept it */
if (dir_policy_permits_address(ntohl(remote.sin_addr.s_addr)) == 0) {
tor_inet_ntoa(&remote.sin_addr, tmpbuf, sizeof(tmpbuf));
log_fn(LOG_NOTICE,"Denying dir connection from address %s.",
notice(LD_DIRSERV,"Denying dir connection from address %s.",
tmpbuf);
tor_close_socket(news);
return 0;
@@ -736,11 +738,11 @@ connection_connect(connection_t *conn, char *address,
s = socket(PF_INET,SOCK_STREAM,IPPROTO_TCP);
if (s < 0) {
log_fn(LOG_WARN,"Error creating network socket: %s",
warn(LD_NET,"Error creating network socket: %s",
tor_socket_strerror(tor_socket_errno(-1)));
return -1;
} else if (!SOCKET_IS_POLLABLE(s)) {
log_fn(LOG_WARN,
warn(LD_NET,
"Too many connections; can't create pollable connection to %s",
safe_str(address));
tor_close_socket(s);
@@ -754,11 +756,11 @@ connection_connect(connection_t *conn, char *address,
ext_addr.sin_family = AF_INET;
ext_addr.sin_port = 0;
if (!tor_inet_aton(options->OutboundBindAddress, &ext_addr.sin_addr)) {
log_fn(LOG_WARN,"Outbound bind address '%s' didn't parse. Ignoring.",
warn(LD_CONFIG,"Outbound bind address '%s' didn't parse. Ignoring.",
options->OutboundBindAddress);
} else {
if (bind(s, (struct sockaddr*)&ext_addr, sizeof(ext_addr)) < 0) {
log_fn(LOG_WARN,"Error binding network socket: %s",
warn(LD_NET,"Error binding network socket: %s",
tor_socket_strerror(tor_socket_errno(s)));
return -1;
}
@@ -772,13 +774,13 @@ connection_connect(connection_t *conn, char *address,
dest_addr.sin_port = htons(port);
dest_addr.sin_addr.s_addr = htonl(addr);
log_fn(LOG_DEBUG,"Connecting to %s:%u.",safe_str(address),port);
debug(LD_NET,"Connecting to %s:%u.",safe_str(address),port);
if (connect(s,(struct sockaddr *)&dest_addr,sizeof(dest_addr)) < 0) {
int e = tor_socket_errno(s);
if (!ERRNO_IS_CONN_EINPROGRESS(e)) {
/* yuck. kill it. */
log_fn(LOG_INFO,"Connect() to %s:%u failed: %s",safe_str(address),port,
info(LD_NET,"connect() to %s:%u failed: %s",safe_str(address),port,
tor_socket_strerror(e));
tor_close_socket(s);
return -1;
@@ -791,7 +793,7 @@ connection_connect(connection_t *conn, char *address,
client_check_address_changed(s);
/* it succeeded. we're connected. */
log_fn(inprogress?LOG_DEBUG:LOG_INFO,
log_fn(inprogress?LOG_DEBUG:LOG_INFO, LD_NET,
"Connection to %s:%u %s (sock %d).",safe_str(address),port,
inprogress?"in progress":"established",s);
conn->s = s;
@@ -854,7 +856,7 @@ retry_listeners(int type, config_line_t *cfg,
if (force) {
/* It's a listener, and we're relaunching all listeners of this
* type. Close this one. */
log_fn(LOG_NOTICE, "Closing %s on %s:%d",
log_fn(LOG_NOTICE, LD_NET, "Closing %s on %s:%d",
conn_type_to_string(type), conn->address, conn->port);
connection_close_immediate(conn);
connection_mark_for_close(conn);
@@ -879,7 +881,7 @@ retry_listeners(int type, config_line_t *cfg,
});
if (! line) {
/* This one isn't configured. Close it. */
log_fn(LOG_NOTICE, "Closing %s on %s:%d",
notice(LD_NET, "Closing %s on %s:%d",
conn_type_to_string(type), conn->address, conn->port);
if (replaced_conns) {
smartlist_add(replaced_conns, conn);
@@ -889,7 +891,7 @@ retry_listeners(int type, config_line_t *cfg,
}
} else {
/* It's configured; we don't need to launch it. */
log_fn(LOG_DEBUG, "Already have %s on %s:%d",
debug(LD_NET, "Already have %s on %s:%d",
conn_type_to_string(type), conn->address, conn->port);
smartlist_remove(launch, line);
if (free_launch_elts)
@@ -997,7 +999,7 @@ static void
connection_consider_empty_buckets(connection_t *conn)
{
if (global_read_bucket <= 0) {
LOG_FN_CONN(conn, (LOG_DEBUG,"global bucket exhausted. Pausing."));
LOG_FN_CONN(conn, (LOG_DEBUG,LD_NET,"global bucket exhausted. Pausing."));
conn->wants_to_read = 1;
connection_stop_reading(conn);
return;
@@ -1005,7 +1007,7 @@ connection_consider_empty_buckets(connection_t *conn)
if (connection_speaks_cells(conn) &&
conn->state == OR_CONN_STATE_OPEN &&
conn->receiver_bucket <= 0) {
LOG_FN_CONN(conn, (LOG_DEBUG,"receiver bucket exhausted. Pausing."));
LOG_FN_CONN(conn, (LOG_DEBUG,LD_NET,"receiver bucket exhausted. Pausing."));
conn->wants_to_read = 1;
connection_stop_reading(conn);
}
@@ -1033,11 +1035,11 @@ connection_bucket_refill(struct timeval *now)
/* refill the global buckets */
if (global_read_bucket < (int)options->BandwidthBurst) {
global_read_bucket += (int)options->BandwidthRate;
log_fn(LOG_DEBUG,"global_read_bucket now %d.", global_read_bucket);
debug(LD_NET,"global_read_bucket now %d.", global_read_bucket);
}
if (global_write_bucket < (int)options->BandwidthBurst) {
global_write_bucket += (int)options->BandwidthRate;
log_fn(LOG_DEBUG,"global_write_bucket now %d.", global_write_bucket);
debug(LD_NET,"global_write_bucket now %d.", global_write_bucket);
}
/* refill the per-connection buckets */
@@ -1058,7 +1060,7 @@ connection_bucket_refill(struct timeval *now)
conn->state != OR_CONN_STATE_OPEN ||
conn->receiver_bucket > 0)) {
/* and either a non-cell conn or a cell conn with non-empty bucket */
LOG_FN_CONN(conn, (LOG_DEBUG,"waking up conn (fd %d)",conn->s));
LOG_FN_CONN(conn, (LOG_DEBUG,LD_NET,"waking up conn (fd %d)",conn->s));
conn->wants_to_read = 0;
connection_start_reading(conn);
if (conn->wants_to_write == 1) {
@@ -1197,7 +1199,7 @@ connection_read_to_buf(connection_t *conn, int *max_to_read)
return connection_tls_continue_handshake(conn);
}
log_fn(LOG_DEBUG,"%d: starting, inbuf_datalen %d (%d pending in tls object). at_most %d.",
debug(LD_NET,"%d: starting, inbuf_datalen %d (%d pending in tls object). at_most %d.",
conn->s,(int)buf_datalen(conn->inbuf),tor_tls_get_pending_bytes(conn->tls), at_most);
/* else open, or closing */
@@ -1205,11 +1207,11 @@ connection_read_to_buf(connection_t *conn, int *max_to_read)
switch (result) {
case TOR_TLS_CLOSE:
log_fn(LOG_INFO,"TLS connection closed on read. Closing. (Nickname %s, address %s",
info(LD_NET,"TLS connection closed on read. Closing. (Nickname %s, address %s",
conn->nickname ? conn->nickname : "not set", conn->address);
return -1;
case TOR_TLS_ERROR:
log_fn(LOG_DEBUG,"tls error. breaking (nickname %s, address %s).",
info(LD_NET,"tls error. breaking (nickname %s, address %s).",
conn->nickname ? conn->nickname : "not set", conn->address);
return -1;
case TOR_TLS_WANTWRITE:
@@ -1229,7 +1231,7 @@ connection_read_to_buf(connection_t *conn, int *max_to_read)
* believing that SSL bytes are the same as TCP bytes anyway. */
int r2 = read_to_buf_tls(conn->tls, pending, conn->inbuf);
if (r2<0) {
log_fn(LOG_WARN, "Bug: apparently, reading pending bytes can fail.");
warn(LD_BUG, "Bug: apparently, reading pending bytes can fail.");
return -1;
} else {
result += r2;
@@ -1328,7 +1330,7 @@ connection_handle_write(connection_t *conn)
/* Sometimes, "writable" means "connected". */
if (connection_state_is_connecting(conn)) {
if (getsockopt(conn->s, SOL_SOCKET, SO_ERROR, (void*)&e, &len) < 0) {
log_fn(LOG_WARN,"getsockopt() syscall failed?! Please report to tor-ops.");
warn(LD_BUG,"getsockopt() syscall failed?! Please report to tor-ops.");
if (CONN_IS_EDGE(conn))
connection_edge_end_errno(conn, conn->cpath_layer);
connection_mark_for_close(conn);
@@ -1337,7 +1339,7 @@ connection_handle_write(connection_t *conn)
if (e) {
/* some sort of error, but maybe just inprogress still */
if (!ERRNO_IS_CONN_EINPROGRESS(e)) {
log_fn(LOG_INFO,"in-progress connect failed. Removing.");
info(LD_NET,"in-progress connect failed. Removing.");
if (CONN_IS_EDGE(conn))
connection_edge_end_errno(conn, conn->cpath_layer);
@@ -1374,18 +1376,18 @@ connection_handle_write(connection_t *conn)
switch (result) {
case TOR_TLS_ERROR:
case TOR_TLS_CLOSE:
log_fn(LOG_INFO,result==TOR_TLS_ERROR?
info(LD_NET,result==TOR_TLS_ERROR?
"tls error. breaking.":"TLS connection closed on flush");
connection_close_immediate(conn); /* Don't flush; connection is dead. */
connection_mark_for_close(conn);
return -1;
case TOR_TLS_WANTWRITE:
log_fn(LOG_DEBUG,"wanted write.");
debug(LD_NET,"wanted write.");
/* we're already writing */
return 0;
case TOR_TLS_WANTREAD:
/* Make sure to avoid a loop if the receive buckets are empty. */
log_fn(LOG_DEBUG,"wanted read.");
debug(LD_NET,"wanted read.");
if (!connection_is_reading(conn)) {
connection_stop_writing(conn);
conn->wants_to_write = 1;
@@ -1482,10 +1484,10 @@ connection_write_to_buf(const char *string, size_t len, connection_t *conn)
if (CONN_IS_EDGE(conn)) {
/* if it failed, it means we have our package/delivery windows set
wrong compared to our max outbuf size. close the whole circuit. */
log_fn(LOG_WARN,"write_to_buf failed. Closing circuit (fd %d).", conn->s);
warn(LD_NET,"write_to_buf failed. Closing circuit (fd %d).", conn->s);
circuit_mark_for_close(circuit_get_by_edge_conn(conn));
} else {
log_fn(LOG_WARN,"write_to_buf failed. Closing connection (fd %d).", conn->s);
warn(LD_NET,"write_to_buf failed. Closing connection (fd %d).", conn->s);
connection_mark_for_close(conn);
}
return;
@@ -1745,6 +1747,7 @@ connection_state_is_connecting(connection_t *conn)
*
* Return 0.
*/
/*XXXX Why isn't this in connection_or.c?*/
int
connection_send_destroy(uint16_t circ_id, connection_t *conn)
{
@@ -1756,7 +1759,7 @@ connection_send_destroy(uint16_t circ_id, connection_t *conn)
memset(&cell, 0, sizeof(cell_t));
cell.circ_id = circ_id;
cell.command = CELL_DESTROY;
log_fn(LOG_DEBUG,"Sending destroy (circID %d).", circ_id);
debug(LD_OR,"Sending destroy (circID %d).", circ_id);
connection_or_write_cell_to_buf(&cell, conn);
return 0;
}
@@ -1802,7 +1805,7 @@ client_check_address_changed(int sock)
if (getsockname(sock, (struct sockaddr*)&out_addr, &out_addr_len)<0) {
int e = tor_socket_errno(sock);
log_fn(LOG_WARN, "getsockname() failed: %s", tor_socket_strerror(e));
warn(LD_NET, "getsockname() failed: %s", tor_socket_strerror(e));
return;
}
@@ -1825,7 +1828,7 @@ client_check_address_changed(int sock)
} else {
/* The interface changed. We're a client, so we need to regenerate our
* keys. First, reset the state. */
log_fn(LOG_NOTICE, "Our IP has changed. Rotating keys...");
notice(LD_NET, "Our IP has changed. Rotating keys...");
last_interface_ip = iface_ip;
SMARTLIST_FOREACH(outgoing_addrs, void*, ip, tor_free(ip));
smartlist_clear(outgoing_addrs);
@@ -1861,7 +1864,7 @@ connection_process_inbuf(connection_t *conn, int package_partial)
case CONN_TYPE_CONTROL:
return connection_control_process_inbuf(conn);
default:
log_fn(LOG_WARN,"Bug: got unexpected conn type %d.", conn->type);
err(LD_BUG,"Bug: got unexpected conn type %d.", conn->type);
tor_fragile_assert();
return -1;
}
@@ -1895,7 +1898,7 @@ connection_finished_flushing(connection_t *conn)
case CONN_TYPE_CONTROL:
return connection_control_finished_flushing(conn);
default:
log_fn(LOG_WARN,"Bug: got unexpected conn type %d.", conn->type);
err(LD_BUG,"Bug: got unexpected conn type %d.", conn->type);
tor_fragile_assert();
return -1;
}
@@ -1920,7 +1923,7 @@ connection_finished_connecting(connection_t *conn)
case CONN_TYPE_DIR:
return connection_dir_finished_connecting(conn);
default:
log_fn(LOG_WARN,"Bug: got unexpected conn type %d.", conn->type);
err(LD_BUG,"Bug: got unexpected conn type %d.", conn->type);
tor_fragile_assert();
return -1;
}
@@ -1945,7 +1948,7 @@ connection_reached_eof(connection_t *conn)
case CONN_TYPE_CONTROL:
return connection_control_reached_eof(conn);
default:
log_fn(LOG_WARN,"Bug: got unexpected conn type %d.", conn->type);
err(LD_BUG,"Bug: got unexpected conn type %d.", conn->type);
tor_fragile_assert();
return -1;
}
src/or/relay.c
+101 -93
View File
@@ -11,6 +11,7 @@ const char relay_c_id[] = "$Id$";
* receiving from circuits.
**/
#define NEW_LOG_INTERFACE
#include "or.h"
static int relay_crypt(circuit_t *circ, cell_t *cell, int cell_direction,
@@ -116,7 +117,7 @@ relay_crypt_one_payload(crypto_cipher_env_t *cipher, char *in,
if (( encrypt_mode && crypto_cipher_encrypt(cipher, out, in, CELL_PAYLOAD_SIZE)) ||
(!encrypt_mode && crypto_cipher_decrypt(cipher, out, in, CELL_PAYLOAD_SIZE))) {
log_fn(LOG_WARN,"Error during relay encryption");
warn(LD_BUG,"Error during relay encryption");
return -1;
}
memcpy(in,out,CELL_PAYLOAD_SIZE);
@@ -147,7 +148,7 @@ circuit_receive_relay_cell(cell_t *cell, circuit_t *circ, int cell_direction)
return 0;
if (relay_crypt(circ, cell, cell_direction, &layer_hint, &recognized) < 0) {
log_fn(LOG_WARN,"relay crypt failed. Dropping connection.");
warn(LD_BUG,"relay crypt failed. Dropping connection.");
return -1;
}
@@ -155,17 +156,18 @@ circuit_receive_relay_cell(cell_t *cell, circuit_t *circ, int cell_direction)
conn = relay_lookup_conn(circ, cell, cell_direction);
if (cell_direction == CELL_DIRECTION_OUT) {
++stats_n_relay_cells_delivered;
log_fn(LOG_DEBUG,"Sending away from origin.");
debug(LD_OR,"Sending away from origin.");
if (connection_edge_process_relay_cell(cell, circ, conn, NULL) < 0) {
log_fn(LOG_PROTOCOL_WARN,"connection_edge_process_relay_cell (away from origin) failed.");
log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL,
"connection_edge_process_relay_cell (away from origin) failed.");
return -1;
}
}
if (cell_direction == CELL_DIRECTION_IN) {
++stats_n_relay_cells_delivered;
log_fn(LOG_DEBUG,"Sending to origin.");
debug(LD_OR,"Sending to origin.");
if (connection_edge_process_relay_cell(cell, circ, conn, layer_hint) < 0) {
log_fn(LOG_WARN,"connection_edge_process_relay_cell (at origin) failed.");
warn(LD_OR,"connection_edge_process_relay_cell (at origin) failed.");
return -1;
}
}
@@ -187,17 +189,17 @@ circuit_receive_relay_cell(cell_t *cell, circuit_t *circ, int cell_direction)
tor_assert(circ->rend_splice->purpose == CIRCUIT_PURPOSE_REND_ESTABLISHED);
cell->circ_id = circ->rend_splice->p_circ_id;
if (circuit_receive_relay_cell(cell, circ->rend_splice, CELL_DIRECTION_IN)<0) {
log_fn(LOG_WARN, "Error relaying cell across rendezvous; closing circuits");
warn(LD_REND, "Error relaying cell across rendezvous; closing circuits");
circuit_mark_for_close(circ); /* XXXX Do this here, or just return -1? */
return -1;
}
return 0;
}
log_fn(LOG_PROTOCOL_WARN,"Didn't recognize cell, but circ stops here! Closing circ.");
log_fn(LOG_PROTOCOL_WARN,LD_PROTOCOL,"Didn't recognize cell, but circ stops here! Closing circ.");
return -1;
}
log_fn(LOG_DEBUG,"Passing on unrecognized cell.");
debug(LD_OR,"Passing on unrecognized cell.");
++stats_n_relay_cells_relayed;
connection_or_write_cell_to_buf(cell, conn);
return 0;
@@ -240,7 +242,7 @@ relay_crypt(circuit_t *circ, cell_t *cell, int cell_direction,
tor_assert(circ->cpath);
thishop = circ->cpath;
if (thishop->state != CPATH_STATE_OPEN) {
log_fn(LOG_WARN,"Relay cell before first created cell? Closing.");
log_fn(LOG_PROTOCOL_WARN,LD_PROTOCOL,"Relay cell before first created cell? Closing.");
return -1;
}
do { /* Remember: cpath is in forward order, that is, first hop first. */
@@ -261,7 +263,7 @@ relay_crypt(circuit_t *circ, cell_t *cell, int cell_direction,
thishop = thishop->next;
} while (thishop != circ->cpath && thishop->state == CPATH_STATE_OPEN);
log_fn(LOG_WARN,"in-cell at OP not recognized. Closing.");
warn(LD_OR,"in-cell at OP not recognized. Closing.");
return -1;
} else { /* we're in the middle. Just one crypt. */
if (relay_crypt_one_payload(circ->p_crypto, cell->payload, 1) < 0)
@@ -301,7 +303,7 @@ circuit_package_relay_cell(cell_t *cell, circuit_t *circ,
if (cell_direction == CELL_DIRECTION_OUT) {
conn = circ->n_conn;
if (!conn) {
log_fn(LOG_WARN,"outgoing relay cell has n_conn==NULL. Dropping.");
warn(LD_BUG,"outgoing relay cell has n_conn==NULL. Dropping.");
return 0; /* just drop it */
}
relay_set_digest(layer_hint->f_digest, cell);
@@ -310,8 +312,8 @@ circuit_package_relay_cell(cell_t *cell, circuit_t *circ,
/* moving from farthest to nearest hop */
do {
tor_assert(thishop);
log_fn(LOG_DEBUG,"crypting a layer of the relay cell.");
/* XXXX RD This is a bug, right? */
debug(LD_OR,"crypting a layer of the relay cell.");
if (relay_crypt_one_payload(thishop->f_crypto, cell->payload, 1) < 0) {
return -1;
}
@@ -322,7 +324,8 @@ circuit_package_relay_cell(cell_t *cell, circuit_t *circ,
} else { /* incoming cell */
conn = circ->p_conn;
if (!conn) {
log_fn(LOG_WARN,"incoming relay cell has p_conn==NULL. Dropping.");
/* XXXX RD This is a bug, right? */
warn(LD_BUG,"incoming relay cell has p_conn==NULL. Dropping.");
return 0; /* just drop it */
}
relay_set_digest(circ->p_digest, cell);
@@ -354,7 +357,7 @@ relay_lookup_conn(circuit_t *circ, cell_t *cell, int cell_direction)
for (tmpconn = circ->n_streams; tmpconn; tmpconn=tmpconn->next_stream) {
if (rh.stream_id == tmpconn->stream_id && !tmpconn->marked_for_close) {
log_fn(LOG_DEBUG,"found conn for stream %d.", rh.stream_id);
debug(LD_EXIT,"found conn for stream %d.", rh.stream_id);
if (cell_direction == CELL_DIRECTION_OUT ||
connection_edge_is_rendezvous_stream(tmpconn))
return tmpconn;
@@ -362,13 +365,13 @@ relay_lookup_conn(circuit_t *circ, cell_t *cell, int cell_direction)
}
for (tmpconn = circ->p_streams; tmpconn; tmpconn=tmpconn->next_stream) {
if (rh.stream_id == tmpconn->stream_id && !tmpconn->marked_for_close) {
log_fn(LOG_DEBUG,"found conn for stream %d.", rh.stream_id);
debug(LD_APP,"found conn for stream %d.", rh.stream_id);
return tmpconn;
}
}
for (tmpconn = circ->resolving_streams; tmpconn; tmpconn=tmpconn->next_stream) {
if (rh.stream_id == tmpconn->stream_id && !tmpconn->marked_for_close) {
log_fn(LOG_DEBUG,"found conn for stream %d.", rh.stream_id);
debug(LD_EXIT,"found conn for stream %d.", rh.stream_id);
return tmpconn;
}
}
@@ -423,17 +426,18 @@ connection_edge_send_command(connection_t *fromconn, circuit_t *circ,
int cell_direction;
if (fromconn && fromconn->marked_for_close) {
log_fn(LOG_WARN,"Bug: called on conn that's already marked for close at %s:%d.",
warn(LD_BUG,"Bug: called on conn that's already marked for close at %s:%d.",
fromconn->marked_for_close_file, fromconn->marked_for_close);
return 0;
}
if (!circ) {
log_fn(LOG_INFO,"no circ. Closing conn.");
tor_assert(fromconn);
if (fromconn->type == CONN_TYPE_AP) {
info(LD_APP,"no circ. Closing conn.");
connection_mark_unattached_ap(fromconn, END_STREAM_REASON_INTERNAL);
} else {
info(LD_EXIT,"no circ. Closing conn.");
fromconn->has_sent_end = 1; /* no circ to send to */
connection_mark_for_close(fromconn);
}
@@ -461,11 +465,11 @@ connection_edge_send_command(connection_t *fromconn, circuit_t *circ,
memcpy(cell.payload+RELAY_HEADER_SIZE, payload, payload_len);
}
log_fn(LOG_DEBUG,"delivering %d cell %s.", relay_command,
debug(LD_OR,"delivering %d cell %s.", relay_command,
cell_direction == CELL_DIRECTION_OUT ? "forward" : "backward");
if (circuit_package_relay_cell(&cell, circ, cell_direction, cpath_layer) < 0) {
log_fn(LOG_WARN,"circuit_package_relay_cell failed. Closing.");
warn(LD_BUG,"circuit_package_relay_cell failed. Closing.");
circuit_mark_for_close(circ);
return -1;
}
@@ -481,7 +485,7 @@ connection_edge_end_reason_str(int reason)
{
switch (reason) {
case -1:
log_fn(LOG_WARN,"End cell arrived with length 0. Should be at least 1.");
warn(LD_PROTOCOL,"End cell arrived with length 0. Should be at least 1.");
return "MALFORMED";
case END_STREAM_REASON_MISC: return "misc error";
case END_STREAM_REASON_RESOLVEFAILED: return "resolve failed";
@@ -496,7 +500,7 @@ connection_edge_end_reason_str(int reason)
case END_STREAM_REASON_CONNRESET: return "connection reset";
case END_STREAM_REASON_TORPROTOCOL: return "Tor protocol error";
default:
log_fn(LOG_WARN,"Reason for ending (%d) not recognized.",reason);
warn(LD_PROTOCOL,"Reason for ending (%d) not recognized.",reason);
return "unknown";
}
}
@@ -540,7 +544,7 @@ connection_edge_end_reason_socks5_response(int reason)
case END_STREAM_REASON_NET_UNREACHABLE:
return SOCKS5_NET_UNREACHABLE;
default:
log_fn(LOG_WARN,"Reason for ending (%d) not recognized.",reason);
warn(LD_PROTOCOL,"Reason for ending (%d) not recognized.",reason);
return SOCKS5_GENERAL_ERROR;
}
}
@@ -590,8 +594,8 @@ errno_to_end_reason(int e)
E_CASE(EMFILE):
return END_STREAM_REASON_RESOURCELIMIT;
default:
log_fn(LOG_INFO, "Didn't recognize errno %d (%s); telling the OP that we are ending a stream for 'misc' reason.",
e, tor_socket_strerror(e));
info(LD_EXIT, "Didn't recognize errno %d (%s); telling the OP that we are ending a stream for 'misc' reason.",
e, tor_socket_strerror(e));
return END_STREAM_REASON_MISC;
}
}
@@ -627,13 +631,13 @@ connection_edge_process_end_not_open(
if (rh->length > 0 && edge_reason_is_retriable(reason)) {
if (conn->type != CONN_TYPE_AP) {
log_fn(LOG_WARN,"Got an end because of %s, but we're not an AP. Closing.",
warn(LD_PROTOCOL,"Got an end because of %s, but we're not an AP. Closing.",
connection_edge_end_reason_str(reason));
return -1;
}
log_fn(LOG_INFO,"Address '%s' refused due to '%s'. Considering retrying.",
safe_str(conn->socks_request->address),
connection_edge_end_reason_str(reason));
info(LD_APP,"Address '%s' refused due to '%s'. Considering retrying.",
safe_str(conn->socks_request->address),
connection_edge_end_reason_str(reason));
exitrouter =
router_get_by_digest(circ->build_state->chosen_exit->identity_digest);
switch (reason) {
@@ -642,7 +646,7 @@ connection_edge_process_end_not_open(
uint32_t addr = ntohl(get_uint32(cell->payload+RELAY_HEADER_SIZE+1));
int ttl;
if (!addr) {
log_fn(LOG_INFO,"Address '%s' resolved to 0.0.0.0. Closing,",
info(LD_APP,"Address '%s' resolved to 0.0.0.0. Closing,",
safe_str(conn->socks_request->address));
connection_mark_unattached_ap(conn, END_STREAM_REASON_TORPROTOCOL);
return 0;
@@ -659,7 +663,7 @@ connection_edge_process_end_not_open(
(rh->length < 5 ||
(tor_inet_aton(conn->socks_request->address, &in) &&
!conn->chosen_exit_name))) {
log_fn(LOG_NOTICE,"Exitrouter '%s' seems to be more restrictive than its exit policy. Not using this router as exit for now.", exitrouter->nickname);
notice(LD_APP,"Exitrouter '%s' seems to be more restrictive than its exit policy. Not using this router as exit for now.", exitrouter->nickname);
addr_policy_free(exitrouter->exit_policy);
exitrouter->exit_policy =
router_parse_addr_policy_from_string("reject *:*", -1);
@@ -684,7 +688,7 @@ connection_edge_process_end_not_open(
return 0;
/* else, conn will get closed below */
} else {
log_fn(LOG_NOTICE,"Have tried resolving address '%s' at %d different places. Giving up.",
notice(LD_APP,"Have tried resolving address '%s' at %d different places. Giving up.",
safe_str(conn->socks_request->address), MAX_RESOLVE_FAILURES);
/* clear the failures, so it will have a full try next time */
client_dns_clear_failures(conn->socks_request->address);
@@ -702,10 +706,10 @@ connection_edge_process_end_not_open(
/* else, will close below */
break;
} /* end switch */
log_fn(LOG_INFO,"Giving up on retrying; conn can't be handled.");
info(LD_APP,"Giving up on retrying; conn can't be handled.");
}
log_fn(LOG_INFO,"Edge got end (%s) before we're connected. Marking for close.",
info(LD_APP,"Edge got end (%s) before we're connected. Marking for close.",
connection_edge_end_reason_str(rh->length > 0 ? reason : -1));
if (conn->type == CONN_TYPE_AP) {
circuit_log_path(LOG_INFO,LD_APP,circ);
@@ -734,18 +738,18 @@ connection_edge_process_relay_cell_not_open(
if (conn->type == CONN_TYPE_AP && rh->command == RELAY_COMMAND_CONNECTED) {
if (conn->state != AP_CONN_STATE_CONNECT_WAIT) {
log_fn(LOG_WARN,"Got 'connected' while not in state connect_wait. Dropping.");
warn(LD_APP,"Got 'connected' while not in state connect_wait. Dropping.");
return 0;
}
// log_fn(LOG_INFO,"Connected! Notifying application.");
conn->state = AP_CONN_STATE_OPEN;
log_fn(LOG_INFO,"'connected' received after %d seconds.",
info(LD_APP,"'connected' received after %d seconds.",
(int)(time(NULL) - conn->timestamp_lastread));
if (rh->length >= 4) {
uint32_t addr = ntohl(get_uint32(cell->payload+RELAY_HEADER_SIZE));
int ttl;
if (!addr) {
log_fn(LOG_INFO,"...but it claims the IP address was 0.0.0.0. Closing.");
info(LD_APP,"...but it claims the IP address was 0.0.0.0. Closing.");
connection_edge_end(conn, END_STREAM_REASON_TORPROTOCOL, conn->cpath_layer);
connection_mark_unattached_ap(conn, END_STREAM_REASON_TORPROTOCOL);
return 0;
@@ -771,13 +775,13 @@ connection_edge_process_relay_cell_not_open(
int ttl;
int answer_len;
if (conn->state != AP_CONN_STATE_RESOLVE_WAIT) {
log_fn(LOG_WARN,"Got a 'resolved' cell while not in state resolve_wait. Dropping.");
warn(LD_APP,"Got a 'resolved' cell while not in state resolve_wait. Dropping.");
return 0;
}
tor_assert(conn->socks_request->command == SOCKS_COMMAND_RESOLVE);
answer_len = cell->payload[RELAY_HEADER_SIZE+1];
if (rh->length < 2 || answer_len+2>rh->length) {
log_fn(LOG_WARN, "Dropping malformed 'resolved' cell");
warn(LD_PROTOCOL, "Dropping malformed 'resolved' cell");
connection_mark_unattached_ap(conn, END_STREAM_REASON_TORPROTOCOL);
return 0;
}
@@ -794,8 +798,9 @@ connection_edge_process_relay_cell_not_open(
return 0;
}
log_fn(LOG_WARN,"Got an unexpected relay command %d, in state %d (%s). Closing.",
rh->command, conn->state, conn_state_to_string(conn->type, conn->state));
warn(LD_PROTOCOL,
"Got an unexpected relay command %d, in state %d (%s). Closing.",
rh->command, conn->state, conn_state_to_string(conn->type, conn->state));
connection_edge_end(conn, END_STREAM_REASON_TORPROTOCOL, conn->cpath_layer);
connection_mark_for_close(conn);
return -1;
@@ -817,6 +822,7 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ,
{
static int num_seen=0;
relay_header_t rh;
unsigned domain = layer_hint?LD_APP:LD_EXIT;
tor_assert(cell);
tor_assert(circ);
@@ -824,10 +830,10 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ,
relay_header_unpack(&rh, cell->payload);
// log_fn(LOG_DEBUG,"command %d stream %d", rh.command, rh.stream_id);
num_seen++;
log_fn(LOG_DEBUG,"Now seen %d relay cells here.", num_seen);
debug(domain, "Now seen %d relay cells here.", num_seen);
if (rh.length > RELAY_PAYLOAD_SIZE) {
log_fn(LOG_WARN, "Relay cell length field too long. Closing circuit.");
warn(LD_PROTOCOL, "Relay cell length field too long. Closing circuit.");
return -1;
}
@@ -840,16 +846,16 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ,
switch (rh.command) {
case RELAY_COMMAND_DROP:
log_fn(LOG_INFO,"Got a relay-level padding cell. Dropping.");
info(domain,"Got a relay-level padding cell. Dropping.");
return 0;
case RELAY_COMMAND_BEGIN:
if (layer_hint &&
circ->purpose != CIRCUIT_PURPOSE_S_REND_JOINED) {
log_fn(LOG_WARN,"relay begin request unsupported at AP. Dropping.");
warn(LD_APP,"relay begin request unsupported at AP. Dropping.");
return 0;
}
if (conn) {
log_fn(LOG_WARN,"begin cell for known stream. Dropping.");
warn(domain,"begin cell for known stream. Dropping.");
return 0;
}
connection_exit_begin_conn(cell, circ);
@@ -858,25 +864,25 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ,
++stats_n_data_cells_received;
if (( layer_hint && --layer_hint->deliver_window < 0) ||
(!layer_hint && --circ->deliver_window < 0)) {
log_fn(LOG_PROTOCOL_WARN,
log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL,
"(relay data) circ deliver_window below 0. Killing.");
connection_edge_end(conn, END_STREAM_REASON_TORPROTOCOL,
conn->cpath_layer);
connection_mark_for_close(conn);
return -1;
}
log_fn(LOG_DEBUG,"circ deliver_window now %d.", layer_hint ?
debug(domain,"circ deliver_window now %d.", layer_hint ?
layer_hint->deliver_window : circ->deliver_window);
circuit_consider_sending_sendme(circ, layer_hint);
if (!conn) {
log_fn(LOG_INFO,"data cell dropped, unknown stream.");
info(domain,"data cell dropped, unknown stream.");
return 0;
}
if (--conn->deliver_window < 0) { /* is it below 0 after decrement? */
log_fn(LOG_PROTOCOL_WARN,
log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL,
"(relay data) conn deliver_window below 0. Killing.");
return -1; /* somebody's breaking protocol. kill the whole circuit. */
}
@@ -888,19 +894,19 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ,
return 0;
case RELAY_COMMAND_END:
if (!conn) {
log_fn(LOG_INFO,"end cell (%s) dropped, unknown stream.",
info(domain,"end cell (%s) dropped, unknown stream.",
connection_edge_end_reason_str(rh.length > 0 ?
*(char *)(cell->payload+RELAY_HEADER_SIZE) : -1));
return 0;
}
/* XXX add to this log_fn the exit node's nickname? */
log_fn(LOG_INFO,"%d: end cell (%s) for stream %d. Removing stream.",
conn->s,
connection_edge_end_reason_str(rh.length > 0 ?
info(domain,"%d: end cell (%s) for stream %d. Removing stream.",
conn->s,
connection_edge_end_reason_str(rh.length > 0 ?
*(char *)(cell->payload+RELAY_HEADER_SIZE) : -1),
conn->stream_id);
conn->stream_id);
if (conn->socks_request && !conn->socks_request->has_finished)
log_fn(LOG_WARN,"Bug: open stream hasn't sent socks answer yet? Closing.");
warn(LD_BUG,"Bug: open stream hasn't sent socks answer yet? Closing.");
#ifdef HALF_OPEN
conn->done_sending = 1;
shutdown(conn->s, 1); /* XXX check return; refactor NM */
@@ -923,71 +929,71 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ,
return 0;
case RELAY_COMMAND_EXTEND:
if (conn) {
log_fn(LOG_WARN,"'extend' for non-zero stream. Dropping.");
warn(domain,"'extend' for non-zero stream. Dropping.");
return 0;
}
return circuit_extend(cell, circ);
case RELAY_COMMAND_EXTENDED:
if (!layer_hint) {
log_fn(LOG_WARN,"'extended' unsupported at non-origin. Dropping.");
warn(LD_PROTOCOL,"'extended' unsupported at non-origin. Dropping.");
return 0;
}
log_fn(LOG_DEBUG,"Got an extended cell! Yay.");
debug(domain,"Got an extended cell! Yay.");
if (circuit_finish_handshake(circ, CELL_CREATED,
cell->payload+RELAY_HEADER_SIZE) < 0) {
log_fn(LOG_WARN,"circuit_finish_handshake failed.");
warn(domain,"circuit_finish_handshake failed.");
return -1;
}
if (circuit_send_next_onion_skin(circ)<0) {
log_fn(LOG_INFO,"circuit_send_next_onion_skin() failed.");
info(domain,"circuit_send_next_onion_skin() failed.");
return -1;
}
return 0;
case RELAY_COMMAND_TRUNCATE:
if (layer_hint) {
log_fn(LOG_WARN,"'truncate' unsupported at origin. Dropping.");
warn(LD_APP,"'truncate' unsupported at origin. Dropping.");
return 0;
}
if (circ->n_conn) {
connection_send_destroy(circ->n_circ_id, circ->n_conn);
circuit_set_circid_orconn(circ, 0, NULL, N_CONN_CHANGED);
}
log_fn(LOG_DEBUG, "Processed 'truncate', replying.");
debug(LD_EXIT, "Processed 'truncate', replying.");
connection_edge_send_command(NULL, circ, RELAY_COMMAND_TRUNCATED,
NULL, 0, NULL);
return 0;
case RELAY_COMMAND_TRUNCATED:
if (!layer_hint) {
log_fn(LOG_WARN,"'truncated' unsupported at non-origin. Dropping.");
warn(LD_EXIT,"'truncated' unsupported at non-origin. Dropping.");
return 0;
}
circuit_truncated(circ, layer_hint);
return 0;
case RELAY_COMMAND_CONNECTED:
if (conn) {
log_fn(LOG_PROTOCOL_WARN,
log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL,
"'connected' unsupported while open. Closing circ.");
return -1;
}
log_fn(LOG_INFO,"'connected' received, no conn attached anymore. Ignoring.");
info(domain,"'connected' received, no conn attached anymore. Ignoring.");
return 0;
case RELAY_COMMAND_SENDME:
if (!conn) {
if (layer_hint) {
layer_hint->package_window += CIRCWINDOW_INCREMENT;
log_fn(LOG_DEBUG,"circ-level sendme at origin, packagewindow %d.",
debug(LD_APP,"circ-level sendme at origin, packagewindow %d.",
layer_hint->package_window);
circuit_resume_edge_reading(circ, layer_hint);
} else {
circ->package_window += CIRCWINDOW_INCREMENT;
log_fn(LOG_DEBUG,"circ-level sendme at non-origin, packagewindow %d.",
debug(LD_APP,"circ-level sendme at non-origin, packagewindow %d.",
circ->package_window);
circuit_resume_edge_reading(circ, layer_hint);
}
return 0;
}
conn->package_window += STREAMWINDOW_INCREMENT;
log_fn(LOG_DEBUG,"stream-level sendme, packagewindow now %d.", conn->package_window);
debug(domain,"stream-level sendme, packagewindow now %d.", conn->package_window);
connection_start_reading(conn);
/* handle whatever might still be on the inbuf */
if (connection_edge_package_raw_inbuf(conn, 1) < 0) {
@@ -998,13 +1004,13 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ,
return 0;
case RELAY_COMMAND_RESOLVE:
if (layer_hint) {
log_fn(LOG_WARN,"resolve request unsupported at AP; dropping.");
warn(LD_APP,"resolve request unsupported at AP; dropping.");
return 0;
} else if (conn) {
log_fn(LOG_WARN, "resolve request for known stream; dropping.");
warn(domain, "resolve request for known stream; dropping.");
return 0;
} else if (circ->purpose != CIRCUIT_PURPOSE_OR) {
log_fn(LOG_WARN, "resolve request on circ with purpose %d; dropping",
warn(domain, "resolve request on circ with purpose %d; dropping",
circ->purpose);
return 0;
}
@@ -1012,10 +1018,10 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ,
return 0;
case RELAY_COMMAND_RESOLVED:
if (conn) {
log_fn(LOG_WARN,"'resolved' unsupported while open. Closing circ.");
warn(domain,"'resolved' unsupported while open. Closing circ.");
return -1;
}
log_fn(LOG_INFO,"'resolved' received, no conn attached anymore. Ignoring.");
info(domain,"'resolved' received, no conn attached anymore. Ignoring.");
return 0;
case RELAY_COMMAND_ESTABLISH_INTRO:
case RELAY_COMMAND_ESTABLISH_RENDEZVOUS:
@@ -1030,7 +1036,7 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ,
cell->payload+RELAY_HEADER_SIZE);
return 0;
}
log_fn(LOG_WARN,"unknown relay command %d.",rh.command);
warn(LD_PROTOCOL,"unknown relay command %d.",rh.command);
return -1;
}
@@ -1052,11 +1058,12 @@ connection_edge_package_raw_inbuf(connection_t *conn, int package_partial)
size_t amount_to_process, length;
char payload[CELL_PAYLOAD_SIZE];
circuit_t *circ;
unsigned domain = conn->cpath_layer ? LD_APP : LD_EXIT;
tor_assert(conn);
tor_assert(!connection_speaks_cells(conn));
if (conn->marked_for_close) {
log_fn(LOG_WARN,"Bug: called on conn that's already marked for close at %s:%d.",
warn(LD_BUG,"Bug: called on conn that's already marked for close at %s:%d.",
conn->marked_for_close_file, conn->marked_for_close);
return 0;
}
@@ -1065,7 +1072,7 @@ repeat_connection_edge_package_raw_inbuf:
circ = circuit_get_by_edge_conn(conn);
if (!circ) {
log_fn(LOG_INFO,"conn has no circuit! Closing.");
info(domain,"conn has no circuit! Closing.");
return -1;
}
@@ -1073,7 +1080,7 @@ repeat_connection_edge_package_raw_inbuf:
return 0;
if (conn->package_window <= 0) {
log_fn(LOG_INFO,"called with package_window %d. Skipping.", conn->package_window);
info(domain,"called with package_window %d. Skipping.", conn->package_window);
connection_stop_reading(conn);
return 0;
}
@@ -1096,7 +1103,7 @@ repeat_connection_edge_package_raw_inbuf:
connection_fetch_from_buf(payload, length, conn);
log_fn(LOG_DEBUG,"(%d) Packaging %d bytes (%d waiting).", conn->s,
debug(domain,"(%d) Packaging %d bytes (%d waiting).", conn->s,
(int)length, (int)buf_datalen(conn->inbuf));
if (connection_edge_send_command(conn, circ, RELAY_COMMAND_DATA,
@@ -1114,11 +1121,11 @@ repeat_connection_edge_package_raw_inbuf:
if (--conn->package_window <= 0) { /* is it 0 after decrement? */
connection_stop_reading(conn);
log_fn(LOG_DEBUG,"conn->package_window reached 0.");
debug(domain,"conn->package_window reached 0.");
circuit_consider_stop_edge_reading(circ, conn->cpath_layer);
return 0; /* don't process the inbuf any more */
}
log_fn(LOG_DEBUG,"conn->package_window is now %d",conn->package_window);
debug(domain,"conn->package_window is now %d",conn->package_window);
/* handle more if there's more, or return 0 if there isn't */
goto repeat_connection_edge_package_raw_inbuf;
@@ -1142,16 +1149,16 @@ connection_edge_consider_sending_sendme(connection_t *conn)
if (!circ) {
/* this can legitimately happen if the destroy has already
* arrived and torn down the circuit */
log_fn(LOG_INFO,"No circuit associated with conn. Skipping.");
info(LD_APP,"No circuit associated with conn. Skipping.");
return;
}
while (conn->deliver_window < STREAMWINDOW_START - STREAMWINDOW_INCREMENT) {
log_fn(LOG_DEBUG,"Outbuf %d, Queueing stream sendme.", (int)conn->outbuf_flushlen);
debug(conn->cpath_layer?LD_APP:LD_EXIT,"Outbuf %d, Queueing stream sendme.", (int)conn->outbuf_flushlen);
conn->deliver_window += STREAMWINDOW_INCREMENT;
if (connection_edge_send_command(conn, circ, RELAY_COMMAND_SENDME,
NULL, 0, conn->cpath_layer) < 0) {
log_fn(LOG_WARN,"connection_edge_send_command failed. Returning.");
warn(LD_APP,"connection_edge_send_command failed. Returning.");
return; /* the circuit's closed, don't continue */
}
}
@@ -1166,7 +1173,7 @@ static void
circuit_resume_edge_reading(circuit_t *circ, crypt_path_t *layer_hint)
{
log_fn(LOG_DEBUG,"resuming");
debug(layer_hint?LD_APP:LD_EXIT,"resuming");
/* have to check both n_streams and p_streams, to handle rendezvous */
if (circuit_resume_edge_reading_helper(circ->n_streams, circ, layer_hint) >= 0)
@@ -1215,11 +1222,12 @@ static int
circuit_consider_stop_edge_reading(circuit_t *circ, crypt_path_t *layer_hint)
{
connection_t *conn = NULL;
unsigned domain = conn->cpath_layer ? LD_APP : LD_EXIT;
if (!layer_hint) {
log_fn(LOG_DEBUG,"considering circ->package_window %d", circ->package_window);
debug(domain,"considering circ->package_window %d", circ->package_window);
if (circ->package_window <= 0) {
log_fn(LOG_DEBUG,"yes, not-at-origin. stopped.");
debug(domain,"yes, not-at-origin. stopped.");
for (conn = circ->n_streams; conn; conn=conn->next_stream)
connection_stop_reading(conn);
return 1;
@@ -1227,9 +1235,9 @@ circuit_consider_stop_edge_reading(circuit_t *circ, crypt_path_t *layer_hint)
return 0;
}
/* else, layer hint is defined, use it */
log_fn(LOG_DEBUG,"considering layer_hint->package_window %d", layer_hint->package_window);
debug(domain,"considering layer_hint->package_window %d", layer_hint->package_window);
if (layer_hint->package_window <= 0) {
log_fn(LOG_DEBUG,"yes, at-origin. stopped.");
debug(domain,"yes, at-origin. stopped.");
for (conn = circ->n_streams; conn; conn=conn->next_stream)
if (conn->cpath_layer == layer_hint)
connection_stop_reading(conn);
@@ -1254,14 +1262,14 @@ circuit_consider_sending_sendme(circuit_t *circ, crypt_path_t *layer_hint)
// layer_hint ? "defined" : "null");
while ((layer_hint ? layer_hint->deliver_window : circ->deliver_window) <
CIRCWINDOW_START - CIRCWINDOW_INCREMENT) {
log_fn(LOG_DEBUG,"Queueing circuit sendme.");
debug(LD_CIRC,"Queueing circuit sendme.");
if (layer_hint)
layer_hint->deliver_window += CIRCWINDOW_INCREMENT;
else
circ->deliver_window += CIRCWINDOW_INCREMENT;
if (connection_edge_send_command(NULL, circ, RELAY_COMMAND_SENDME,
NULL, 0, layer_hint) < 0) {
log_fn(LOG_WARN,"connection_edge_send_command failed. Circuit's closed.");
warn(LD_CIRC,"connection_edge_send_command failed. Circuit's closed.");
return; /* the circuit's closed, don't continue */
}
}
src/or/router.c
+22 -20
View File
@@ -136,11 +136,11 @@ rotate_onion_key(void)
tor_snprintf(fname_prev,sizeof(fname_prev),
"%s/keys/secret_onion_key.old",get_options()->DataDirectory);
if (!(prkey = crypto_new_pk_env())) {
err("Error creating crypto environment.");
err(LD_GENERAL,"Error creating crypto environment.");
goto error;
}
if (crypto_pk_generate_key(prkey)) {
err("Error generating onion key");
err(LD_BUG,"Error generating onion key");
goto error;
}
if (file_status(fname) == FN_FILE) {
@@ -148,7 +148,7 @@ rotate_onion_key(void)
goto error;
}
if (crypto_pk_write_private_key_to_filename(prkey, fname)) {
err("Couldn't write generated key to \"%s\".", fname);
err(LD_FS,"Couldn't write generated key to \"%s\".", fname);
goto error;
}
info(LD_GENERAL, "Rotating onion key");
@@ -196,34 +196,34 @@ init_key_from_file(const char *fname)
FILE *file = NULL;
if (!(prkey = crypto_new_pk_env())) {
err("Error creating crypto environment.");
err(LD_GENERAL,"Error creating crypto environment.");
goto error;
}
switch (file_status(fname)) {
case FN_DIR:
case FN_ERROR:
err("Can't read key from \"%s\"", fname);
err(LD_FS,"Can't read key from \"%s\"", fname);
goto error;
case FN_NOENT:
info(LD_GENERAL, "No key found in \"%s\"; generating fresh key.", fname);
if (crypto_pk_generate_key(prkey)) {
err("Error generating onion key");
err(LD_GENERAL,"Error generating onion key");
goto error;
}
if (crypto_pk_check_key(prkey) <= 0) {
err("Generated key seems invalid");
err(LD_GENERAL,"Generated key seems invalid");
goto error;
}
info(LD_GENERAL, "Generated key seems valid");
if (crypto_pk_write_private_key_to_filename(prkey, fname)) {
err("Couldn't write generated key to \"%s\".", fname);
err(LD_FS,"Couldn't write generated key to \"%s\".", fname);
goto error;
}
return prkey;
case FN_FILE:
if (crypto_pk_read_private_key_from_filename(prkey, fname)) {
err("Error loading private key.");
err(LD_GENERAL,"Error loading private key.");
goto error;
}
return prkey;
@@ -274,7 +274,7 @@ init_keys(void)
if (tor_tls_context_new(get_identity_key(), 1,
options->Nickname ? options->Nickname : "client",
MAX_SSL_KEY_LIFETIME) < 0) {
err("Error creating TLS context for OP.");
err(LD_GENERAL,"Error creating TLS context for OP.");
return -1;
}
return 0;
@@ -315,25 +315,25 @@ init_keys(void)
/* 3. Initialize link key and TLS context. */
if (tor_tls_context_new(get_identity_key(), 1, options->Nickname,
MAX_SSL_KEY_LIFETIME) < 0) {
err("Error initializing TLS context");
err(LD_GENERAL,"Error initializing TLS context");
return -1;
}
/* 4. Dump router descriptor to 'router.desc' */
/* Must be called after keys are initialized. */
mydesc = router_get_my_descriptor();
if (!mydesc) {
err("Error initializing descriptor.");
err(LD_GENERAL,"Error initializing descriptor.");
return -1;
}
if (authdir_mode(options)) {
const char *m;
/* We need to add our own fingerprint so it gets recognized. */
if (dirserv_add_own_fingerprint(options->Nickname, get_identity_key())) {
err("Error adding own fingerprint to approved set");
err(LD_GENERAL,"Error adding own fingerprint to approved set");
return -1;
}
if (dirserv_add_descriptor(mydesc, &m) < 0) {
err("Unable to add own descriptor to directory: %s",
err(LD_GENERAL,"Unable to add own descriptor to directory: %s",
m?m:"<unknown error>");
return -1;
}
@@ -348,24 +348,26 @@ init_keys(void)
tor_snprintf(keydir,sizeof(keydir),"%s/fingerprint", datadir);
info(LD_GENERAL,"Dumping fingerprint to \"%s\"...",keydir);
if (crypto_pk_get_fingerprint(get_identity_key(), fingerprint, 1)<0) {
err("Error computing fingerprint");
err(LD_GENERAL,"Error computing fingerprint");
return -1;
}
tor_assert(strlen(options->Nickname) <= MAX_NICKNAME_LEN);
if (tor_snprintf(fingerprint_line, sizeof(fingerprint_line),
"%s %s\n",options->Nickname, fingerprint) < 0) {
err("Error writing fingerprint line");
err(LD_GENERAL,"Error writing fingerprint line");
return -1;
}
if (write_str_to_file(keydir, fingerprint_line, 0))
if (write_str_to_file(keydir, fingerprint_line, 0)) {
err(LD_FS, "Error writing fingerprint line to file");
return -1;
}
if (!authdir_mode(options))
return 0;
/* 6. [authdirserver only] load approved-routers file */
tor_snprintf(keydir,sizeof(keydir),"%s/approved-routers", datadir);
info(LD_DIRSERV,"Loading approved fingerprints from \"%s\"...",keydir);
if (dirserv_parse_fingerprint_file(keydir) < 0) {
err("Error loading fingerprints");
err(LD_GENERAL,"Error loading fingerprints");
return -1;
}
/* 6b. [authdirserver only] add own key to approved directories. */
@@ -1008,7 +1010,7 @@ router_dump_router_to_string(char *s, size_t maxlen, routerinfo_t *router,
/* record our fingerprint, so we can include it in the descriptor */
if (crypto_pk_get_fingerprint(router->identity_pkey, fingerprint, 1)<0) {
err("Error computing fingerprint");
err(LD_BUG,"Error computing fingerprint");
return -1;
}
@@ -1157,7 +1159,7 @@ router_dump_router_to_string(char *s, size_t maxlen, routerinfo_t *router,
cp = s_tmp = s_dup = tor_strdup(s);
ri_tmp = router_parse_entry_from_string(cp, NULL);
if (!ri_tmp) {
err("We just generated a router descriptor we can't parse: <<%s>>", s);
err(LD_BUG,"We just generated a router descriptor we can't parse: <<%s>>", s);
return -1;
}
tor_free(s_dup);
src/or/test.c
+1
View File
@@ -22,6 +22,7 @@ const char test_c_id[] = "$Id$";
#include <dirent.h>
#endif
#define NEW_LOG_INTERFACE
#include "or.h"
#include "../common/test.h"
#include "../common/torgzip.h"