mirrors/tor
1
0
Fork 0
mirror of https://gitlab.torproject.org/tpo/core/tor.git synced 2025-02-25 07:07:52 +01:00
Code Issues Projects Releases Wiki Activity

Change more files to new loggin interface. 3 left.

Browse source 
svn:r5310
This commit is contained in:
Nick Mathewson 2005-10-25 08:20:10 +00:00
parent 932106f54c
commit e7e170a59e
5 changed files with 276 additions and 268 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

5
src/common/log.h
View file

@ -84,8 +84,9 @@
#define LD_DIRSERV (1u<<14)
/** Onion routing protocol. */
#define LD_OR (1u<<15)
/** Connections leaving Tor, other exit stuff. */
#define LD_EXIT (1u<<16)
/** Generic edge-connection functionality. */
#define LD_EDGE (1u<<16)
#define LD_EXIT LD_EDGE
typedef void (*log_callback)(int severity, unsigned int domain, const char *msg);

150
src/or/connection_edge.c
View file

@ -10,6 +10,7 @@ const char connection_edge_c_id[] = "$Id$";
* \brief Handle edge streams.
**/
#define NEW_LOG_INTERFACE
#include "or.h"
#include "tree.h"
@ -41,8 +42,8 @@ _connection_mark_unattached_ap(connection_t *conn, int endreason,
connection_edge_end_reason_socks5_response(endreason);
if (endreason == END_STREAM_REASON_ALREADY_SOCKS_REPLIED)
log_fn(LOG_WARN,"Bug: stream (marked at %s:%d) sending two socks replies?",
file, line);
warn(LD_BUG,"Bug: stream (marked at %s:%d) sending two socks replies?",
file, line);
if (conn->socks_request->command == SOCKS_COMMAND_CONNECT)
connection_ap_handshake_socks_reply(conn, NULL, 0, socksreason);
@ -77,7 +78,7 @@ connection_edge_reached_eof(connection_t *conn)
/* it still has stuff to process. don't let it die yet. */
return 0;
}
log_fn(LOG_INFO,"conn (fd %d) reached eof. Closing.", conn->s);
info(LD_EDGE,"conn (fd %d) reached eof. Closing.", conn->s);
if (!conn->marked_for_close) {
/* only mark it if not already marked. it's possible to
* get the 'end' right around when the client hangs up on us. */
@ -126,11 +127,11 @@ connection_edge_process_inbuf(connection_t *conn, int package_partial)
case AP_CONN_STATE_CONNECT_WAIT:
case AP_CONN_STATE_RESOLVE_WAIT:
case AP_CONN_STATE_CONTROLLER_WAIT:
log_fn(LOG_INFO,"data from edge while in '%s' state. Leaving it on buffer.",
info(LD_EDGE,"data from edge while in '%s' state. Leaving it on buffer.",
conn_state_to_string(conn->type, conn->state));
return 0;
}
log_fn(LOG_WARN,"Bug: Got unexpected state %d. Closing.",conn->state);
warn(LD_BUG,"Bug: Got unexpected state %d. Closing.",conn->state);
tor_fragile_assert();
connection_edge_end(conn, END_STREAM_REASON_INTERNAL, conn->cpath_layer);
connection_mark_for_close(conn);
@ -146,8 +147,8 @@ connection_edge_destroy(uint16_t circ_id, connection_t *conn)
tor_assert(CONN_IS_EDGE(conn));
if (!conn->marked_for_close) {
log_fn(LOG_INFO,"CircID %d: At an edge. Marking connection for close.",
circ_id);
info(LD_EDGE,
"CircID %d: At an edge. Marking connection for close.", circ_id);
if (conn->type == CONN_TYPE_AP) {
connection_mark_unattached_ap(conn, END_STREAM_REASON_DESTROY);
} else {
@ -177,13 +178,13 @@ connection_edge_end(connection_t *conn, char reason, crypt_path_t *cpath_layer)
circuit_t *circ;
if (conn->has_sent_end) {
log_fn(LOG_WARN,"Harmless bug: Calling connection_edge_end (reason %d) on an already ended stream?", reason);
warn(LD_BUG,"Harmless bug: Calling connection_edge_end (reason %d) on an already ended stream?", reason);
tor_fragile_assert();
return -1;
}
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;
}
@ -198,11 +199,11 @@ connection_edge_end(connection_t *conn, char reason, crypt_path_t *cpath_layer)
circ = circuit_get_by_edge_conn(conn);
if (circ && !circ->marked_for_close) {
log_fn(LOG_DEBUG,"Marking conn (fd %d) and sending end.",conn->s);
debug(LD_EDGE,"Marking conn (fd %d) and sending end.",conn->s);
connection_edge_send_command(conn, circ, RELAY_COMMAND_END,
payload, payload_len, cpath_layer);
} else {
log_fn(LOG_DEBUG,"Marking conn (fd %d); no circ to send end.",conn->s);
debug(LD_EDGE,"Marking conn (fd %d); no circ to send end.",conn->s);
}
conn->has_sent_end = 1;
@ -252,7 +253,7 @@ connection_edge_finished_flushing(connection_t *conn)
connection_stop_writing(conn);
return 0;
default:
log_fn(LOG_WARN,"BUG: called in unexpected state %d.", conn->state);
warn(LD_BUG,"BUG: called in unexpected state %d.", conn->state);
tor_fragile_assert();
return -1;
}
@ -274,7 +275,7 @@ connection_edge_finished_connecting(connection_t *conn)
in.s_addr = htonl(conn->addr);
tor_inet_ntoa(&in,valbuf,sizeof(valbuf));
log_fn(LOG_INFO,"Exit connection to %s:%u (%s) established.",
info(LD_EXIT,"Exit connection to %s:%u (%s) established.",
safe_str(conn->address),conn->port,safe_str(valbuf));
conn->state = EXIT_CONN_STATE_OPEN;
@ -327,7 +328,7 @@ connection_ap_expire_beginning(void)
continue;
if (conn->state == AP_CONN_STATE_CONTROLLER_WAIT) {
if (now - conn->timestamp_lastread >= 120) {
log_fn(LOG_NOTICE, "Closing unattached stream.");
notice(LD_APP, "Closing unattached stream.");
connection_mark_unattached_ap(conn, END_STREAM_REASON_TIMEOUT);
}
continue;
@ -340,14 +341,14 @@ connection_ap_expire_beginning(void)
continue;
circ = circuit_get_by_edge_conn(conn);
if (!circ) { /* it's vanished? */
log_fn(LOG_INFO,"Conn is waiting (address %s), but lost its circ.",
info(LD_APP,"Conn is waiting (address %s), but lost its circ.",
safe_str(conn->socks_request->address));
connection_mark_unattached_ap(conn, END_STREAM_REASON_TIMEOUT);
continue;
}
if (circ->purpose == CIRCUIT_PURPOSE_C_REND_JOINED) {
if (now - conn->timestamp_lastread > 45) {
log_fn(LOG_NOTICE,"Rend stream is %d seconds late. Giving up on address '%s'.",
notice(LD_REND,"Rend stream is %d seconds late. Giving up on address '%s'.",
(int)(now - conn->timestamp_lastread),
safe_str(conn->socks_request->address));
connection_edge_end(conn, END_STREAM_REASON_TIMEOUT, conn->cpath_layer);
@ -356,7 +357,7 @@ connection_ap_expire_beginning(void)
continue;
}
tor_assert(circ->purpose == CIRCUIT_PURPOSE_C_GENERAL);
log_fn(LOG_NOTICE,"Stream is %d seconds late on address '%s'. Retrying.",
notice(LD_APP,"Stream is %d seconds late on address '%s'. Retrying.",
(int)(now - conn->timestamp_lastread),
safe_str(conn->socks_request->address));
circuit_log_path(LOG_NOTICE, LD_APP, circ);
@ -582,11 +583,11 @@ addressmap_rewrite(char *address, size_t maxlen)
if (!ent || !ent->new_address)
return; /* done, no rewrite needed */
log_fn(LOG_INFO, "Addressmap: rewriting '%s' to '%s'",
safe_str(address), safe_str(ent->new_address));
info(LD_APP, "Addressmap: rewriting '%s' to '%s'",
safe_str(address), safe_str(ent->new_address));
strlcpy(address, ent->new_address, maxlen);
}
log_fn(LOG_WARN,"Loop detected: we've rewritten '%s' 16 times! Using it as-is.",
warn(LD_CONFIG,"Loop detected: we've rewritten '%s' 16 times! Using it as-is.",
safe_str(address));
/* it's fine to rewrite a rewrite, but don't loop forever */
}
@ -629,7 +630,7 @@ addressmap_register(const char *address, char *new_address, time_t expires)
strmap_set(addressmap, address, ent);
} else if (ent->new_address) { /* we need to clean up the old mapping. */
if (expires > 1) {
log_fn(LOG_INFO,"Temporary addressmap ('%s' to '%s') not performed, since it's already mapped to '%s'",
info(LD_APP,"Temporary addressmap ('%s' to '%s') not performed, since it's already mapped to '%s'",
safe_str(address), safe_str(new_address), safe_str(ent->new_address));
tor_free(new_address);
return;
@ -647,8 +648,8 @@ addressmap_register(const char *address, char *new_address, time_t expires)
ent->expires = expires==2 ? 1 : expires;
ent->num_resolve_failures = 0;
log_fn(LOG_INFO, "Addressmap: (re)mapped '%s' to '%s'",
safe_str(address), safe_str(ent->new_address));
info(LD_CONFIG, "Addressmap: (re)mapped '%s' to '%s'",
safe_str(address), safe_str(ent->new_address));
control_event_address_mapped(address, ent->new_address, expires);
}
@ -666,7 +667,7 @@ client_dns_incr_failures(const char *address)
strmap_set(addressmap,address,ent);
}
++ent->num_resolve_failures;
log_fn(LOG_INFO,"Address %s now has %d resolve failures.",
info(LD_APP, "Address %s now has %d resolve failures.",
safe_str(address), ent->num_resolve_failures);
return ent->num_resolve_failures;
}
@ -791,8 +792,7 @@ addressmap_get_virtual_address(int type)
}
return tor_strdup(buf);
} else {
log_fn(LOG_WARN, "Called with unsupported address type (%d)",
type);
warn(LD_BUG, "Called with unsupported address type (%d)", type);
return NULL;
}
}
@ -830,9 +830,9 @@ addressmap_register_virtual_address(int type, char *new_address)
tor_free(new_address);
return tor_strdup(*addrp);
} else
log_fn(LOG_WARN, "Internal confusion: I thought that '%s' was mapped to by '%s', but '%s' really maps to '%s'. This is a harmless bug.",
safe_str(new_address), safe_str(*addrp), safe_str(*addrp),
ent?safe_str(ent->new_address):"(nothing)");
warn(LD_BUG, "Internal confusion: I thought that '%s' was mapped to by '%s', but '%s' really maps to '%s'. This is a harmless bug.",
safe_str(new_address), safe_str(*addrp), safe_str(*addrp),
ent?safe_str(ent->new_address):"(nothing)");
}
tor_free(*addrp);
@ -933,7 +933,7 @@ connection_ap_handshake_process_socks(connection_t *conn)
tor_assert(conn->socks_request);
socks = conn->socks_request;
log_fn(LOG_DEBUG,"entered.");
debug(LD_APP,"entered.");
sockshere = fetch_from_buf_socks(conn->inbuf, socks);
if (sockshere == 0) {
@ -941,16 +941,16 @@ connection_ap_handshake_process_socks(connection_t *conn)
connection_write_to_buf(socks->reply, socks->replylen, conn);
socks->replylen = 0; /* zero it out so we can do another round of negotiation */
} else {
log_fn(LOG_DEBUG,"socks handshake not all here yet.");
debug(LD_APP,"socks handshake not all here yet.");
}
return 0;
} else if (sockshere == -1) {
if (socks->replylen) { /* we should send reply back */
log_fn(LOG_DEBUG,"reply is already set for us. Using it.");
debug(LD_APP,"reply is already set for us. Using it.");
connection_ap_handshake_socks_reply(conn, socks->reply, socks->replylen,
SOCKS5_GENERAL_ERROR);
} else {
log_fn(LOG_WARN,"Fetching socks handshake failed. Closing.");
warn(LD_APP,"Fetching socks handshake failed. Closing.");
connection_ap_handshake_socks_reply(conn, NULL, 0, SOCKS5_GENERAL_ERROR);
}
connection_mark_unattached_ap(conn, END_STREAM_REASON_ALREADY_SOCKS_REPLIED);
@ -958,7 +958,7 @@ connection_ap_handshake_process_socks(connection_t *conn)
} /* else socks handshake is done, continue processing */
tor_strlower(socks->address); /* normalize it */
log_fn(LOG_DEBUG,"Client asked for %s:%d", safe_str(socks->address),
debug(LD_APP,"Client asked for %s:%d", safe_str(socks->address),
socks->port);
/* For address map controls, remap the address */
@ -971,7 +971,7 @@ connection_ap_handshake_process_socks(connection_t *conn)
* the address through tor; that's likely to fail, and may leak
* information.
*/
log_fn(LOG_WARN,"Missing mapping for virtual address '%s'. Refusing.",
warn(LD_APP,"Missing mapping for virtual address '%s'. Refusing.",
socks->address); /* don't safe_str() this yet. */
connection_mark_unattached_ap(conn, END_STREAM_REASON_INTERNAL);
return -1;
@ -983,7 +983,7 @@ connection_ap_handshake_process_socks(connection_t *conn)
addresstype = parse_extended_hostname(socks->address);
if (tor_should_handle_stream && addresstype == BAD_HOSTNAME) {
log_fn(LOG_WARN, "Invalid hostname %s; rejecting", socks->address);
warn(LD_APP, "Invalid hostname %s; rejecting", socks->address);
connection_mark_unattached_ap(conn, END_STREAM_REASON_TORPROTOCOL);
return -1;
}
@ -997,8 +997,8 @@ connection_ap_handshake_process_socks(connection_t *conn)
conn->chosen_exit_name = tor_strdup(s+1);
*s = 0;
} else {
log_fn(LOG_WARN,"Malformed exit address '%s.exit'. Refusing.",
safe_str(socks->address));
warn(LD_APP,"Malformed exit address '%s.exit'. Refusing.",
safe_str(socks->address));
connection_mark_unattached_ap(conn, END_STREAM_REASON_TORPROTOCOL);
return -1;
}
@ -1011,9 +1011,9 @@ connection_ap_handshake_process_socks(connection_t *conn)
in.s_addr = htonl(r->addr);
strlcpy(socks->address, inet_ntoa(in), sizeof(socks->address));
} else if (tor_should_handle_stream) {
log_fn(LOG_WARN,
"Unrecognized server in exit address '%s.exit'. Refusing.",
safe_str(socks->address));
warn(LD_APP,
"Unrecognized server in exit address '%s.exit'. Refusing.",
safe_str(socks->address));
connection_mark_unattached_ap(conn, END_STREAM_REASON_TORPROTOCOL);
return -1;
}
@ -1025,7 +1025,7 @@ connection_ap_handshake_process_socks(connection_t *conn)
if (tor_should_handle_stream &&
address_is_invalid_destination(socks->address)) {
log_fn(LOG_WARN,"Destination '%s' seems to be an invalid hostname. Failing.",
warn(LD_APP,"Destination '%s' seems to be an invalid hostname. Failing.",
safe_str(socks->address));
connection_mark_unattached_ap(conn, END_STREAM_REASON_TORPROTOCOL);
return -1;
@ -1036,7 +1036,7 @@ connection_ap_handshake_process_socks(connection_t *conn)
struct in_addr in;
/* Reply to resolves immediately if we can. */
if (strlen(socks->address) > RELAY_PAYLOAD_SIZE) {
log_fn(LOG_WARN,"Address to be resolved is too large. Failing.");
warn(LD_APP,"Address to be resolved is too large. Failing.");
connection_ap_handshake_socks_resolved(conn,RESOLVED_TYPE_ERROR,0,NULL,-1);
connection_mark_unattached_ap(conn, END_STREAM_REASON_ALREADY_SOCKS_REPLIED);
return -1;
@ -1052,7 +1052,7 @@ connection_ap_handshake_process_socks(connection_t *conn)
control_event_stream_status(conn, STREAM_EVENT_NEW_RESOLVE);
} else { /* socks->command == SOCKS_COMMAND_CONNECT */
if (socks->port == 0) {
log_fn(LOG_NOTICE,"Application asked to connect to port 0. Refusing.");
notice(LD_APP,"Application asked to connect to port 0. Refusing.");
connection_mark_unattached_ap(conn, END_STREAM_REASON_TORPROTOCOL);
return -1;
}
@ -1062,7 +1062,7 @@ connection_ap_handshake_process_socks(connection_t *conn)
routerinfo_t *r =
router_find_exact_exit_enclave(socks->address, socks->port);
if (r) {
log_fn(LOG_INFO,"Redirecting address %s to exit at enclave router %s",
info(LD_APP,"Redirecting address %s to exit at enclave router %s",
safe_str(socks->address), r->nickname);
/* use the hex digest, not nickname, in case there are two
routers with this nickname */
@ -1092,26 +1092,26 @@ connection_ap_handshake_process_socks(connection_t *conn)
if (socks->command == SOCKS_COMMAND_RESOLVE) {
/* if it's a resolve request, fail it right now, rather than
* building all the circuits and then realizing it won't work. */
log_fn(LOG_WARN,"Resolve requests to hidden services not allowed. Failing.");
warn(LD_APP,"Resolve requests to hidden services not allowed. Failing.");
connection_ap_handshake_socks_resolved(conn,RESOLVED_TYPE_ERROR,0,NULL,-1);
connection_mark_unattached_ap(conn, END_STREAM_REASON_ALREADY_SOCKS_REPLIED);
return -1;
}
strlcpy(conn->rend_query, socks->address, sizeof(conn->rend_query));
log_fn(LOG_INFO,"Got a hidden service request for ID '%s'",
info(LD_REND,"Got a hidden service request for ID '%s'",
safe_str(conn->rend_query));
/* see if we already have it cached */
r = rend_cache_lookup_entry(conn->rend_query, -1, &entry);
if (r<0) {
log_fn(LOG_WARN,"Invalid service descriptor %s",
warn(LD_REND,"Invalid service descriptor %s",
safe_str(conn->rend_query));
connection_mark_unattached_ap(conn, END_STREAM_REASON_TORPROTOCOL);
return -1;
}
if (r==0) {
conn->state = AP_CONN_STATE_RENDDESC_WAIT;
log_fn(LOG_INFO, "Unknown descriptor %s. Fetching.",
info(LD_REND, "Unknown descriptor %s. Fetching.",
safe_str(conn->rend_query));
rend_client_refetch_renddesc(conn->rend_query);
return 0;
@ -1120,7 +1120,7 @@ connection_ap_handshake_process_socks(connection_t *conn)
#define NUM_SECONDS_BEFORE_REFETCH (60*15)
if (time(NULL) - entry->received < NUM_SECONDS_BEFORE_REFETCH) {
conn->state = AP_CONN_STATE_CIRCUIT_WAIT;
log_fn(LOG_INFO, "Descriptor is here and fresh enough. Great.");
info(LD_REND, "Descriptor is here and fresh enough. Great.");
if (connection_ap_handshake_attach_circuit(conn) < 0) {
connection_mark_unattached_ap(conn, END_STREAM_REASON_CANT_ATTACH);
return -1;
@ -1128,8 +1128,8 @@ connection_ap_handshake_process_socks(connection_t *conn)
return 0;
} else {
conn->state = AP_CONN_STATE_RENDDESC_WAIT;
log_fn(LOG_INFO, "Stale descriptor %s. Refetching.",
safe_str(conn->rend_query));
info(LD_REND, "Stale descriptor %s. Refetching.",
safe_str(conn->rend_query));
rend_client_refetch_renddesc(conn->rend_query);
return 0;
}
@ -1152,7 +1152,7 @@ again:
test_stream_id = circ->next_stream_id++;
if (++attempts > 1<<16) {
/* Make sure we don't loop forever if all stream_id's are used. */
log_fn(LOG_WARN,"No unused stream IDs. Failing.");
warn(LD_APP,"No unused stream IDs. Failing.");
return 0;
}
if (test_stream_id == 0)
@ -1191,7 +1191,7 @@ connection_ap_handshake_send_begin(connection_t *ap_conn, circuit_t *circ)
ap_conn->socks_request->port);
payload_len = strlen(payload)+1;
log_fn(LOG_DEBUG,"Sending relay cell to begin stream %d.",ap_conn->stream_id);
debug(LD_APP,"Sending relay cell to begin stream %d.",ap_conn->stream_id);
if (connection_edge_send_command(ap_conn, circ, RELAY_COMMAND_BEGIN,
payload, payload_len, ap_conn->cpath_layer) < 0)
@ -1200,8 +1200,8 @@ connection_ap_handshake_send_begin(connection_t *ap_conn, circuit_t *circ)
ap_conn->package_window = STREAMWINDOW_START;
ap_conn->deliver_window = STREAMWINDOW_START;
ap_conn->state = AP_CONN_STATE_CONNECT_WAIT;
log_fn(LOG_INFO,"Address/port sent, ap socket %d, n_circ_id %d",
ap_conn->s, circ->n_circ_id);
info(LD_APP,"Address/port sent, ap socket %d, n_circ_id %d",
ap_conn->s, circ->n_circ_id);
control_event_stream_status(ap_conn, STREAM_EVENT_SENT_CONNECT);
return 0;
}
@ -1234,14 +1234,14 @@ connection_ap_handshake_send_resolve(connection_t *ap_conn, circuit_t *circ)
payload_len = strlen(string_addr)+1;
tor_assert(payload_len <= RELAY_PAYLOAD_SIZE);
log_fn(LOG_DEBUG,"Sending relay cell to begin stream %d.",ap_conn->stream_id);
debug(LD_APP,"Sending relay cell to begin stream %d.",ap_conn->stream_id);
if (connection_edge_send_command(ap_conn, circ, RELAY_COMMAND_RESOLVE,
string_addr, payload_len, ap_conn->cpath_layer) < 0)
return -1; /* circuit is closed, don't continue */
ap_conn->state = AP_CONN_STATE_RESOLVE_WAIT;
log_fn(LOG_INFO,"Address sent for resolve, ap socket %d, n_circ_id %d",
info(LD_APP,"Address sent for resolve, ap socket %d, n_circ_id %d",
ap_conn->s, circ->n_circ_id);
control_event_stream_status(ap_conn, STREAM_EVENT_SENT_RESOLVE);
return 0;
@ -1260,10 +1260,10 @@ connection_ap_make_bridge(char *address, uint16_t port)
connection_t *conn;
int err;
log_fn(LOG_INFO,"Making AP bridge to %s:%d ...",safe_str(address),port);
info(LD_APP,"Making AP bridge to %s:%d ...",safe_str(address),port);
if ((err = tor_socketpair(AF_UNIX, SOCK_STREAM, 0, fd)) < 0) {
log(LOG_WARN,"Couldn't construct socketpair (%s). Network down? Delaying.",
warn(LD_NET,"Couldn't construct socketpair (%s). Network down? Delaying.",
tor_socket_strerror(-err));
return -1;
}
@ -1304,7 +1304,7 @@ connection_ap_make_bridge(char *address, uint16_t port)
return -1;
}
log_fn(LOG_INFO,"... AP bridge created and connected.");
info(LD_APP,"... AP bridge created and connected.");
return fd[1];
}
@ -1391,7 +1391,7 @@ connection_ap_handshake_socks_reply(connection_t *conn, char *reply,
status==SOCKS5_SUCCEEDED ? STREAM_EVENT_SUCCEEDED : STREAM_EVENT_FAILED);
if (conn->socks_request->has_finished) {
log_fn(LOG_WARN, "Harmless bug: duplicate calls to connection_ap_handshake_socks_reply.");
warn(LD_BUG, "Harmless bug: duplicate calls to connection_ap_handshake_socks_reply.");
return;
}
if (replylen) { /* we already have a reply in mind */
@ -1453,20 +1453,20 @@ connection_exit_begin_conn(cell_t *cell, circuit_t *circ)
*/
if (!memchr(cell->payload+RELAY_HEADER_SIZE, 0, rh.length)) {
log_fn(LOG_WARN,"relay begin cell has no \\0. Dropping.");
warn(LD_PROTOCOL,"relay begin cell has no \\0. Dropping.");
return 0;
}
if (parse_addr_port(cell->payload+RELAY_HEADER_SIZE,&address,NULL,&port)<0) {
log_fn(LOG_WARN,"Unable to parse addr:port in relay begin cell. Dropping.");
warn(LD_PROTOCOL,"Unable to parse addr:port in relay begin cell. Dropping.");
return 0;
}
if (port==0) {
log_fn(LOG_WARN,"Missing port in relay begin cell. Dropping.");
warn(LD_PROTOCOL,"Missing port in relay begin cell. Dropping.");
tor_free(address);
return 0;
}
log_fn(LOG_DEBUG,"Creating new exit connection.");
debug(LD_EXIT,"Creating new exit connection.");
n_stream = connection_new(CONN_TYPE_EXIT);
n_stream->purpose = EXIT_PURPOSE_CONNECT;
@ -1477,7 +1477,7 @@ connection_exit_begin_conn(cell_t *cell, circuit_t *circ)
n_stream->deliver_window = STREAMWINDOW_START;
if (circ->purpose == CIRCUIT_PURPOSE_S_REND_JOINED) {
log_fn(LOG_DEBUG,"begin is for rendezvous. configuring stream.");
debug(LD_REND,"begin is for rendezvous. configuring stream.");
n_stream->address = tor_strdup("(rendezvous)");
n_stream->state = EXIT_CONN_STATE_CONNECTING;
strlcpy(n_stream->rend_query, circ->rend_query,
@ -1485,7 +1485,7 @@ connection_exit_begin_conn(cell_t *cell, circuit_t *circ)
tor_assert(connection_edge_is_rendezvous_stream(n_stream));
assert_circuit_ok(circ);
if (rend_service_set_connection_addr_port(n_stream, circ) < 0) {
log_fn(LOG_INFO,"Didn't find rendezvous service (port %d)",n_stream->port);
info(LD_REND,"Didn't find rendezvous service (port %d)",n_stream->port);
connection_edge_end(n_stream, END_STREAM_REASON_EXITPOLICY, n_stream->cpath_layer);
connection_free(n_stream);
circuit_mark_for_close(circ); /* knock the whole thing down, somebody screwed up */
@ -1493,7 +1493,7 @@ connection_exit_begin_conn(cell_t *cell, circuit_t *circ)
return 0;
}
assert_circuit_ok(circ);
log_fn(LOG_DEBUG,"Finished assigning addr/port");
debug(LD_REND,"Finished assigning addr/port");
n_stream->cpath_layer = circ->cpath->prev; /* link it */
/* add it into the linked list of n_streams on this circuit */
@ -1605,7 +1605,7 @@ connection_exit_connect(connection_t *conn)
if (!connection_edge_is_rendezvous_stream(conn) &&
router_compare_to_my_exit_policy(conn)) {
log_fn(LOG_INFO,"%s:%d failed exit policy. Closing.",
info(LD_EXIT,"%s:%d failed exit policy. Closing.",
safe_str(conn->address), conn->port);
connection_edge_end(conn, END_STREAM_REASON_EXITPOLICY, conn->cpath_layer);
circuit_detach_stream(circuit_get_by_edge_conn(conn), conn);
@ -1627,7 +1627,7 @@ connection_exit_connect(connection_t *conn)
port = r->port_dest;
in.s_addr = htonl(addr);
tor_inet_ntoa(&in, tmpbuf, sizeof(tmpbuf));
log_fn(LOG_DEBUG, "Redirecting connection from %s:%d to %s:%d",
debug(LD_EXIT, "Redirecting connection from %s:%d to %s:%d",
safe_str(conn->address), conn->port, safe_str(tmpbuf), port);
}
break;
@ -1635,7 +1635,7 @@ connection_exit_connect(connection_t *conn)
});
}
log_fn(LOG_DEBUG,"about to try connecting");
debug(LD_EXIT,"about to try connecting");
switch (connection_connect(conn, conn->address, addr, port)) {
case -1:
connection_edge_end_errno(conn, conn->cpath_layer);
@ -1654,7 +1654,7 @@ connection_exit_connect(connection_t *conn)
conn->state = EXIT_CONN_STATE_OPEN;
if (connection_wants_to_flush(conn)) { /* in case there are any queued data cells */
log_fn(LOG_WARN,"Bug: newly connected conn had data waiting!");
warn(LD_BUG,"Bug: newly connected conn had data waiting!");
// connection_start_writing(conn);
}
connection_watch_events(conn, EV_READ);
@ -1714,7 +1714,7 @@ connection_ap_can_use_exit(connection_t *conn, routerinfo_t *exit)
if (conn->chosen_exit_name) {
if (router_get_by_nickname(conn->chosen_exit_name, 1) != exit) {
/* doesn't match */
log_fn(LOG_DEBUG,"Requested node '%s', considering node '%s'. No.",
debug(LD_APP,"Requested node '%s', considering node '%s'. No.",
conn->chosen_exit_name, exit->nickname);
return 0;
}
@ -1780,7 +1780,7 @@ socks_policy_permits_address(uint32_t addr)
return 0;
else if (a==ADDR_POLICY_ACCEPTED)
return 1;
log_fn(LOG_WARN, "Bug: Got unexpected 'maybe' answer from socks policy");
warn(LD_BUG, "Bug: Got unexpected 'maybe' answer from socks policy");
return 0;
}

50
src/or/cpuworker.c
View file

@ -13,6 +13,7 @@ const char cpuworker_c_id[] = "$Id$";
* Right now, we only use this for processing onionskins.
**/
#define NEW_LOG_INTERFACE
#include "or.h"
/** The maximum number of cpuworker processes we will keep around. */
@ -83,7 +84,7 @@ tag_unpack(const char *tag, uint32_t *addr, uint16_t *port, uint16_t *circ_id)
in.s_addr = htonl(*addr);
tor_inet_ntoa(&in, addrbuf, sizeof(addrbuf));
log_fn(LOG_DEBUG,"onion was from %s:%d, circ_id %d.", addrbuf, *port, *circ_id);
debug(LD_OR,"onion was from %s:%d, circ_id %d.", addrbuf, *port, *circ_id);
}
/** Called when the onion key has changed and we need to spawn new
@ -109,12 +110,12 @@ cpuworkers_rotate(void)
int
connection_cpu_reached_eof(connection_t *conn)
{
log_fn(LOG_WARN,"Read eof. Worker died unexpectedly.");
warn(LD_GENERAL,"Read eof. Worker died unexpectedly.");
if (conn->state != CPUWORKER_STATE_IDLE) {
/* the circ associated with this cpuworker will have to wait until
* it gets culled in run_connection_housekeeping(), since we have
* no way to find out which circ it was. */
log_fn(LOG_WARN,"...and it left a circuit queued; abandoning circ.");
warn(LD_GENERAL,"...and it left a circuit queued; abandoning circ.");
num_cpuworkers_busy--;
}
num_cpuworkers--;
@ -163,22 +164,23 @@ connection_cpu_process_inbuf(connection_t *conn)
circ = circuit_get_by_circid_orconn(circ_id, p_conn);
if (success == 0) {
log_fn(LOG_DEBUG,"decoding onionskin failed. Closing.");
debug(LD_OR,"decoding onionskin failed. (Old key or bad sw.) Closing.");
if (circ)
circuit_mark_for_close(circ);
goto done_processing;
}
if (!circ) {
log_fn(LOG_INFO,"processed onion for a circ that's gone. Dropping.");
/*XXXX Why does this happen?*/
debug(LD_OR,"processed onion for a circ that's gone. Dropping.");
goto done_processing;
}
tor_assert(circ->p_conn);
if (onionskin_answer(circ, CELL_CREATED, buf+TAG_LEN, buf+TAG_LEN+ONIONSKIN_REPLY_LEN) < 0) {
log_fn(LOG_WARN,"onionskin_answer failed. Closing.");
warn(LD_OR,"onionskin_answer failed. Closing.");
circuit_mark_for_close(circ);
goto done_processing;
}
log_fn(LOG_DEBUG,"onionskin_answer succeeded. Yay.");
debug(LD_OR,"onionskin_answer succeeded. Yay.");
} else {
tor_assert(0); /* don't ask me to do handshakes yet */
}
@ -243,22 +245,22 @@ cpuworker_main(void *data)
if ((r = recv(fd, &question_type, 1, 0)) != 1) {
// log_fn(LOG_ERR,"read type failed. Exiting.");
if (r == 0) {
log_fn(LOG_INFO,"CPU worker exiting because Tor process closed connection (either rotated keys or died).");
info(LD_OR,"CPU worker exiting because Tor process closed connection (either rotated keys or died).");
} else {
log_fn(LOG_INFO,"CPU worker editing because of error on connection to Tor process.");
log_fn(LOG_INFO,"(Error on %d was %s)", fd, tor_socket_strerror(tor_socket_errno(fd)));
info(LD_OR,"CPU worker editing because of error on connection to Tor process.");
info(LD_OR,"(Error on %d was %s)", fd, tor_socket_strerror(tor_socket_errno(fd)));
}
goto end;
}
tor_assert(question_type == CPUWORKER_TASK_ONION);
if (read_all(fd, tag, TAG_LEN, 1) != TAG_LEN) {
log_fn(LOG_ERR,"read tag failed. Exiting.");
err(LD_BUG,"read tag failed. Exiting.");
goto end;
}
if (read_all(fd, question, ONIONSKIN_CHALLENGE_LEN, 1) != ONIONSKIN_CHALLENGE_LEN) {
log_fn(LOG_ERR,"read question failed. Exiting.");
info(LD_BUG,"read question failed. Exiting.");
goto end;
}
@ -266,21 +268,21 @@ cpuworker_main(void *data)
if (onion_skin_server_handshake(question, onion_key, last_onion_key,
reply_to_proxy, keys, CPATH_KEY_MATERIAL_LEN) < 0) {
/* failure */
log_fn(LOG_DEBUG,"onion_skin_server_handshake failed.");
debug(LD_OR,"onion_skin_server_handshake failed.");
memset(buf,0,LEN_ONION_RESPONSE); /* send all zeros for failure */
} else {
/* success */
log_fn(LOG_DEBUG,"onion_skin_server_handshake succeeded.");
debug(LD_OR,"onion_skin_server_handshake succeeded.");
buf[0] = 1; /* 1 means success */
memcpy(buf+1,tag,TAG_LEN);
memcpy(buf+1+TAG_LEN,reply_to_proxy,ONIONSKIN_REPLY_LEN);
memcpy(buf+1+TAG_LEN+ONIONSKIN_REPLY_LEN,keys,CPATH_KEY_MATERIAL_LEN);
}
if (write_all(fd, buf, LEN_ONION_RESPONSE, 1) != LEN_ONION_RESPONSE) {
log_fn(LOG_ERR,"writing response buf failed. Exiting.");
err(LD_BUG,"writing response buf failed. Exiting.");
goto end;
}
log_fn(LOG_DEBUG,"finished writing response.");
debug(LD_OR,"finished writing response.");
}
}
end:
@ -305,14 +307,14 @@ spawn_cpuworker(void)
fdarray = tor_malloc(sizeof(int)*2);
if ((err = tor_socketpair(AF_UNIX, SOCK_STREAM, 0, fdarray)) < 0) {
log(LOG_WARN, "Couldn't construct socketpair: %s", tor_socket_strerror(-err));
warn(LD_NET, "Couldn't construct socketpair: %s", tor_socket_strerror(-err));
tor_free(fdarray);
return -1;
}
fd = fdarray[0];
spawn_func(cpuworker_main, (void*)fdarray);
log_fn(LOG_DEBUG,"just spawned a worker.");
debug(LD_OR,"just spawned a worker.");
#ifndef TOR_IS_MULTITHREADED
tor_close_socket(fdarray[1]); /* we don't need the worker's side of the pipe */
tor_free(fdarray);
@ -327,7 +329,7 @@ spawn_cpuworker(void)
conn->address = tor_strdup("localhost");
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); /* this closes fd */
return -1;
}
@ -353,7 +355,7 @@ spawn_enough_cpuworkers(void)
while (num_cpuworkers < num_cpuworkers_needed) {
if (spawn_cpuworker() < 0) {
log_fn(LOG_WARN,"Spawn failed. Will try again later.");
warn(LD_GENERAL,"Spawn failed. Will try again later.");
return;
}
num_cpuworkers++;
@ -374,7 +376,7 @@ process_pending_task(connection_t *cpuworker)
if (!circ)
return;
if (assign_to_cpuworker(cpuworker, CPUWORKER_TASK_ONION, circ) < 0)
log_fn(LOG_WARN,"assign_to_cpuworker failed. Ignoring.");
warn(LD_OR,"assign_to_cpuworker failed. Ignoring.");
}
#define CPUWORKER_BUSY_TIMEOUT 3600 /* seconds */
@ -398,7 +400,7 @@ cull_wedged_cpuworkers(void)
conn->type == CONN_TYPE_CPUWORKER &&
conn->state == CPUWORKER_STATE_BUSY_ONION &&
conn->timestamp_lastwritten + CPUWORKER_BUSY_TIMEOUT < now) {
log_fn(LOG_NOTICE,"Bug: closing wedged cpuworker. Can somebody find the bug?");
notice(LD_BUG,"Bug: closing wedged cpuworker. Can somebody find the bug?");
num_cpuworkers_busy--;
num_cpuworkers--;
connection_mark_for_close(conn);
@ -428,7 +430,7 @@ assign_to_cpuworker(connection_t *cpuworker, uint8_t question_type,
circ = task;
if (num_cpuworkers_busy == num_cpuworkers) {
log_fn(LOG_DEBUG,"No idle cpuworkers. Queuing.");
debug(LD_OR,"No idle cpuworkers. Queuing.");
if (onion_pending_add(circ) < 0)
return -1;
return 0;
@ -440,7 +442,7 @@ assign_to_cpuworker(connection_t *cpuworker, uint8_t question_type,
tor_assert(cpuworker);
if (!circ->p_conn) {
log_fn(LOG_INFO,"circ->p_conn gone. Failing circ.");
info(LD_OR,"circ->p_conn gone. Failing circ.");
return -1;
}
tag_pack(tag, circ->p_conn->addr, circ->p_conn->port, circ->p_circ_id);

160
src/or/directory.c
View file

@ -4,6 +4,7 @@
/* $Id$ */
const char directory_c_id[] = "$Id$";
#define NEW_LOG_INTERFACE
#include "or.h"
/**
@ -105,7 +106,7 @@ dir_policy_permits_address(uint32_t addr)
return 0;
else if (a==ADDR_POLICY_ACCEPTED)
return 1;
log_fn(LOG_WARN, "Bug: got unexpected 'maybe' answer from dir policy");
warn(LD_BUG, "Bug: got unexpected 'maybe' answer from dir policy");
return 0;
}
@ -204,8 +205,8 @@ directory_get_from_dirserver(uint8_t purpose, const char *resource,
which = "network status";
else // if (purpose == DIR_PURPOSE_FETCH_NETWORKSTATUS)
which = "server descriptors";
log_fn(LOG_INFO,
"No router found for %s; falling back to dirserver list",which);
info(LD_DIR,
"No router found for %s; falling back to dirserver list",which);
ds = router_pick_trusteddirserver(1, 1, fascistfirewall,
retry_if_no_servers);
}
@ -223,7 +224,8 @@ directory_get_from_dirserver(uint8_t purpose, const char *resource,
directory_initiate_command_trusted_dir(ds, purpose, !directconn,
resource, NULL, 0);
else {
log_fn(LOG_NOTICE,"No running dirservers known. Will try again later. (purpose %d)",
notice(LD_DIR,
"No running dirservers known. Will try again later. (purpose %d)",
purpose);
if (directconn) {
/* remember we tried them all and failed. */
@ -279,16 +281,16 @@ connection_dir_request_failed(connection_t *conn)
router_mark_as_down(conn->identity_digest); /* don't try him again */
if (conn->purpose == DIR_PURPOSE_FETCH_DIR ||
conn->purpose == DIR_PURPOSE_FETCH_RUNNING_LIST) {
log_fn(LOG_INFO, "Giving up on directory server at '%s:%d'; retrying",
info(LD_DIR, "Giving up on directory server at '%s:%d'; retrying",
conn->address, conn->port);
directory_get_from_dirserver(conn->purpose, NULL,
0 /* don't retry_if_no_servers */);
} else if (conn->purpose == DIR_PURPOSE_FETCH_NETWORKSTATUS) {
log_fn(LOG_INFO, "Giving up on directory server at '%s'; retrying",
info(LD_DIR, "Giving up on directory server at '%s'; retrying",
conn->address);
connection_dir_download_networkstatus_failed(conn);
} else if (conn->purpose == DIR_PURPOSE_FETCH_SERVERDESC) {
log_fn(LOG_INFO, "Giving up on directory server at '%s'; retrying",
info(LD_DIR, "Giving up on directory server at '%s'; retrying",
conn->address);
connection_dir_download_routerdesc_failed(conn);
}
@ -357,28 +359,28 @@ directory_initiate_command(const char *address, uint32_t addr,
switch (purpose) {
case DIR_PURPOSE_FETCH_DIR:
log_fn(LOG_DEBUG,"initiating directory fetch");
debug(LD_DIR,"initiating directory fetch");
break;
case DIR_PURPOSE_FETCH_RENDDESC:
log_fn(LOG_DEBUG,"initiating hidden-service descriptor fetch");
debug(LD_DIR,"initiating hidden-service descriptor fetch");
break;
case DIR_PURPOSE_UPLOAD_DIR:
log_fn(LOG_DEBUG,"initiating server descriptor upload");
debug(LD_OR,"initiating server descriptor upload");
break;
case DIR_PURPOSE_UPLOAD_RENDDESC:
log_fn(LOG_DEBUG,"initiating hidden-service descriptor upload");
debug(LD_REND,"initiating hidden-service descriptor upload");
break;
case DIR_PURPOSE_FETCH_RUNNING_LIST:
log_fn(LOG_DEBUG,"initiating running-routers fetch");
debug(LD_DIR,"initiating running-routers fetch");
break;
case DIR_PURPOSE_FETCH_NETWORKSTATUS:
log_fn(LOG_DEBUG,"initiating network-status fetch");
debug(LD_DIR,"initiating network-status fetch");
break;
case DIR_PURPOSE_FETCH_SERVERDESC:
log_fn(LOG_DEBUG,"initiating server descriptor fetch");
debug(LD_DIR,"initiating server descriptor fetch");
break;
default:
log_fn(LOG_ERR, "Unrecognized directory connection purpose.");
err(LD_BUG, "Unrecognized directory connection purpose.");
tor_assert(0);
}
@ -426,7 +428,7 @@ directory_initiate_command(const char *address, uint32_t addr,
*/
conn->s = connection_ap_make_bridge(conn->address, conn->port);
if (conn->s < 0) {
log_fn(LOG_WARN,"Making AP bridge to dirserver failed.");
warn(LD_NET,"Making AP bridge to dirserver failed.");
connection_mark_for_close(conn);
return;
}
@ -479,7 +481,7 @@ directory_send_command(connection_t *conn, const char *platform,
if (authenticator) {
base64_authenticator = alloc_http_authenticator(authenticator);
if (!base64_authenticator)
log_fn(LOG_WARN, "Encoding http authenticator failed");
warn(LD_BUG, "Encoding http authenticator failed");
}
if (base64_authenticator) {
tor_snprintf(proxyauthstring, sizeof(proxyauthstring),
@ -498,7 +500,7 @@ directory_send_command(connection_t *conn, const char *platform,
case DIR_PURPOSE_FETCH_DIR:
tor_assert(!resource);
tor_assert(!payload);
log_fn(LOG_DEBUG, "Asking for compressed directory from server running %s",
debug(LD_DIR, "Asking for compressed directory from server running %s",
platform?platform:"<unknown version>");
httpcommand = "GET";
url = tor_strdup("/tor/dir.z");
@ -603,7 +605,7 @@ parse_http_url(char *headers, char **url)
if (s-tmp >= 3 && !strcmpstart(tmp,"://")) {
tmp = strchr(tmp+3, '/');
if (tmp && tmp < s) {
log_fn(LOG_DEBUG,"Skipping over 'http[s]://hostname' string");
debug(LD_DIR,"Skipping over 'http[s]://hostname' string");
start = tmp;
}
}
@ -700,7 +702,7 @@ parse_http_response(const char *headers, int *code, time_t *date,
if (sscanf(headers, "HTTP/1.%d %d", &n1, &n2) < 2 ||
(n1 != 0 && n1 != 1) ||
(n2 < 100 || n2 >= 600)) {
log_fn(LOG_WARN,"Failed to parse header '%s'",headers);
warn(LD_HTTP,"Failed to parse header '%s'",headers);
return -1;
}
*code = n2;
@ -747,7 +749,7 @@ parse_http_response(const char *headers, int *code, time_t *date,
} else if (!strcmp(enc, "gzip") || !strcmp(enc, "x-gzip")) {
*compression = GZIP_METHOD;
} else {
log_fn(LOG_INFO, "Unrecognized content encoding: '%s'. Trying to deal.", enc);
info(LD_HTTP, "Unrecognized content encoding: '%s'. Trying to deal.", enc);
*compression = -1;
}
}
@ -813,38 +815,39 @@ connection_dir_client_reached_eof(connection_t *conn)
&body, &body_len, MAX_DIR_SIZE,
allow_partial)) {
case -1: /* overflow */
log_fn(LOG_WARN,"'fetch' response too large (server '%s:%d'). Closing.", conn->address, conn->port);
warn(LD_BUG,"'fetch' response too large (server '%s:%d'). Closing.", conn->address, conn->port);
return -1;
case 0:
log_fn(LOG_INFO,"'fetch' response not all here, but we're at eof. Closing.");
info(LD_HTTP,"'fetch' response not all here, but we're at eof. Closing.");
return -1;
/* case 1, fall through */
}
if (parse_http_response(headers, &status_code, &date_header,
&compression, &reason) < 0) {
log_fn(LOG_WARN,"Unparseable headers (server '%s:%d'). Closing.", conn->address, conn->port);
warn(LD_HTTP,"Unparseable headers (server '%s:%d'). Closing.", conn->address, conn->port);
tor_free(body); tor_free(headers);
return -1;
}
if (!reason) reason = tor_strdup("[no reason given]");
log_fn(LOG_DEBUG,
"Received response from directory server '%s:%d': %d \"%s\"",
conn->address, conn->port, status_code, reason);
debug(LD_DIR,
"Received response from directory server '%s:%d': %d \"%s\"",
conn->address, conn->port, status_code, reason);
if (date_header > 0) {
now = time(NULL);
delta = now-date_header;
if (abs(delta)>ALLOW_DIRECTORY_TIME_SKEW) {
log_fn(router_digest_is_trusted_dir(conn->identity_digest) ? LOG_WARN : LOG_INFO,
LD_HTTP,
"Received directory with skewed time (server '%s:%d'): we are %d minutes %s, or the directory is %d minutes %s.",
conn->address, conn->port,
abs(delta)/60, delta>0 ? "ahead" : "behind",
abs(delta)/60, delta>0 ? "behind" : "ahead");
skewed = 1; /* don't check the recommended-versions line */
} else {
log_fn(LOG_DEBUG, "Time on received directory is within tolerance; we are %d seconds skewed. (That's okay.)", delta);
debug(LD_HTTP, "Time on received directory is within tolerance; we are %d seconds skewed. (That's okay.)", delta);
}
}
@ -873,7 +876,7 @@ connection_dir_client_reached_eof(connection_t *conn)
else
description2 = "uncompressed";
log_fn(LOG_INFO, "HTTP body from server '%s:%d' was labeled %s, "
info(LD_HTTP, "HTTP body from server '%s:%d' was labeled %s, "
"but it seems to be %s.%s",
conn->address, conn->port, description1, description2,
(compression>0 && guessed>0)?" Trying both.":"");
@ -890,8 +893,8 @@ connection_dir_client_reached_eof(connection_t *conn)
/* If we're pretty sure that we have a compressed directory, and
* we didn't manage to uncompress it, then warn and bail. */
if (!plausible && !new_body) {
log_fn(LOG_WARN, "Unable to decompress HTTP body (server '%s:%d').",
conn->address, conn->port);
warn(LD_HTTP, "Unable to decompress HTTP body (server '%s:%d').",
conn->address, conn->port);
tor_free(body); tor_free(headers); tor_free(reason);
return -1;
}
@ -904,36 +907,36 @@ connection_dir_client_reached_eof(connection_t *conn)
if (conn->purpose == DIR_PURPOSE_FETCH_DIR) {
/* fetch/process the directory to learn about new routers. */
log_fn(LOG_INFO,"Received directory (size %d) from server '%s:%d'",
info(LD_DIR,"Received directory (size %d) from server '%s:%d'",
(int)body_len, conn->address, conn->port);
if (status_code == 503 || body_len == 0) {
log_fn(LOG_INFO,"Empty directory; status %d (\"%s\") Ignoring.",
info(LD_DIR,"Empty directory; status %d (\"%s\") Ignoring.",
status_code, reason);
tor_free(body); tor_free(headers); tor_free(reason);
return -1;
}
if (status_code != 200) {
log_fn(LOG_WARN,"Received http status code %d (\"%s\") from server '%s:%d'. I'll try again soon.",
warn(LD_DIR,"Received http status code %d (\"%s\") from server '%s:%d'. I'll try again soon.",
status_code, reason, conn->address, conn->port);
tor_free(body); tor_free(headers); tor_free(reason);
return -1;
}
if (router_parse_directory(body) < 0) {
log_fn(LOG_NOTICE,"I failed to parse the directory I fetched from '%s:%d'. Ignoring.", conn->address, conn->port);
notice(LD_DIR,"I failed to parse the directory I fetched from '%s:%d'. Ignoring.", conn->address, conn->port);
}
}
if (conn->purpose == DIR_PURPOSE_FETCH_RUNNING_LIST) {
/* just update our list of running routers, if this list is new info */
log_fn(LOG_INFO,"Received running-routers list (size %d)", (int)body_len);
info(LD_DIR,"Received running-routers list (size %d)", (int)body_len);
if (status_code != 200) {
log_fn(LOG_WARN,"Received http status code %d (\"%s\") from server '%s:%d'. I'll try again soon.",
warn(LD_DIR,"Received http status code %d (\"%s\") from server '%s:%d'. I'll try again soon.",
status_code, reason, conn->address, conn->port);
tor_free(body); tor_free(headers); tor_free(reason);
return -1;
}
if (router_parse_runningrouters(body)<0) {
log_fn(LOG_WARN,"Bad running-routers from server '%s:%d'. I'll try again soon.",
warn(LD_DIR,"Bad running-routers from server '%s:%d'. I'll try again soon.",
conn->address, conn->port);
tor_free(body); tor_free(headers); tor_free(reason);
return -1;
@ -943,9 +946,9 @@ connection_dir_client_reached_eof(connection_t *conn)
if (conn->purpose == DIR_PURPOSE_FETCH_NETWORKSTATUS) {
smartlist_t *which = NULL;
char *cp;
log_fn(LOG_INFO,"Received networkstatus objects (size %d) from server '%s:%d'",(int) body_len, conn->address, conn->port);
info(LD_DIR,"Received networkstatus objects (size %d) from server '%s:%d'",(int) body_len, conn->address, conn->port);
if (status_code != 200) {
log_fn(LOG_WARN,"Received http status code %d (\"%s\") from server '%s:%d' while fetching \"/tor/status/%s\". I'll try again soon.",
warn(LD_DIR,"Received http status code %d (\"%s\") from server '%s:%d' while fetching \"/tor/status/%s\". I'll try again soon.",
status_code, reason, conn->address, conn->port,
conn->requested_resource);
tor_free(body); tor_free(headers); tor_free(reason);
@ -987,7 +990,7 @@ connection_dir_client_reached_eof(connection_t *conn)
if (conn->purpose == DIR_PURPOSE_FETCH_SERVERDESC) {
smartlist_t *which = NULL;
int n_asked_for = 0;
log_fn(LOG_INFO,"Received server info (size %d) from server '%s:%d'",
info(LD_DIR,"Received server info (size %d) from server '%s:%d'",
(int)body_len, conn->address, conn->port);
if (conn->requested_resource &&
!strcmpstart(conn->requested_resource,"fp/")) {
@ -1001,7 +1004,7 @@ connection_dir_client_reached_eof(connection_t *conn)
(status_code == 400 && !strcmp(reason, "Servers unavailable."));
/* 404 means that it didn't have them; no big deal.
* Older (pre-0.1.1.8) servers said 400 Servers unavailable instead. */
log_fn(no_warn ? LOG_INFO : LOG_WARN,
log_fn(no_warn ? LOG_INFO : LOG_WARN, LD_DIR,
"Received http status code %d (\"%s\") from server '%s:%d' while fetching \"/tor/server/%s\". I'll try again soon.",
status_code, reason, conn->address, conn->port,
conn->requested_resource);
@ -1027,7 +1030,7 @@ connection_dir_client_reached_eof(connection_t *conn)
directory_info_has_arrived(time(NULL), 0);
}
if (which) { /* mark remaining ones as failed */
log_fn(LOG_INFO, "Received %d/%d routers requested from %s:%d",
info(LD_DIR, "Received %d/%d routers requested from %s:%d",
n_asked_for-smartlist_len(which), n_asked_for,
conn->address, (int)conn->port);
if (smartlist_len(which)) {
@ -1051,16 +1054,16 @@ connection_dir_client_reached_eof(connection_t *conn)
if (conn->purpose == DIR_PURPOSE_UPLOAD_DIR) {
switch (status_code) {
case 200:
log_fn(LOG_INFO,"eof (status 200) after uploading server descriptor: finished.");
info(LD_GENERAL,"eof (status 200) after uploading server descriptor: finished.");
break;
case 400:
log_fn(LOG_WARN,"http status 400 (\"%s\") response from dirserver '%s:%d'. Please correct.", reason, conn->address, conn->port);
warn(LD_GENERAL,"http status 400 (\"%s\") response from dirserver '%s:%d'. Please correct.", reason, conn->address, conn->port);
break;
case 403:
log_fn(LOG_WARN,"http status 403 (\"%s\") response from dirserver '%s:%d'. Is your clock skewed? Have you mailed us your key fingerprint? Are you using the right key? Are you using a private IP address? See http://tor.eff.org/doc/tor-doc-server.html", reason, conn->address, conn->port);
warn(LD_GENERAL,"http status 403 (\"%s\") response from dirserver '%s:%d'. Is your clock skewed? Have you mailed us your key fingerprint? Are you using the right key? Are you using a private IP address? See http://tor.eff.org/doc/tor-doc-server.html", reason, conn->address, conn->port);
break;
default:
log_fn(LOG_WARN,"http status %d (\"%s\") reason unexpected (server '%s:%d').", status_code, reason, conn->address, conn->port);
warn(LD_GENERAL,"http status %d (\"%s\") reason unexpected (server '%s:%d').", status_code, reason, conn->address, conn->port);
break;
}
/* return 0 in all cases, since we don't want to mark any
@ -1068,12 +1071,12 @@ connection_dir_client_reached_eof(connection_t *conn)
}
if (conn->purpose == DIR_PURPOSE_FETCH_RENDDESC) {
log_fn(LOG_INFO,"Received rendezvous descriptor (size %d, status %d (\"%s\"))",
info(LD_REND,"Received rendezvous descriptor (size %d, status %d (\"%s\"))",
(int)body_len, status_code, reason);
switch (status_code) {
case 200:
if (rend_cache_store(body, body_len) < 0) {
log_fn(LOG_WARN,"Failed to store rendezvous descriptor.");
warn(LD_REND,"Failed to store rendezvous descriptor.");
/* alice's ap_stream will notice when connection_mark_for_close
* cleans it up */
} else {
@ -1087,10 +1090,10 @@ connection_dir_client_reached_eof(connection_t *conn)
* connection_mark_for_close cleans it up. */
break;
case 400:
log_fn(LOG_WARN,"http status 400 (\"%s\"). Dirserver didn't like our rendezvous query?", reason);
warn(LD_REND,"http status 400 (\"%s\"). Dirserver didn't like our rendezvous query?", reason);
break;
default:
log_fn(LOG_WARN,"http status %d (\"%s\") response unexpected (server '%s:%d').", status_code, reason, conn->address, conn->port);
warn(LD_REND,"http status %d (\"%s\") response unexpected (server '%s:%d').", status_code, reason, conn->address, conn->port);
break;
}
}
@ -1098,13 +1101,13 @@ connection_dir_client_reached_eof(connection_t *conn)
if (conn->purpose == DIR_PURPOSE_UPLOAD_RENDDESC) {
switch (status_code) {
case 200:
log_fn(LOG_INFO,"Uploading rendezvous descriptor: finished with status 200 (\"%s\")", reason);
info(LD_REND,"Uploading rendezvous descriptor: finished with status 200 (\"%s\")", reason);
break;
case 400:
log_fn(LOG_WARN,"http status 400 (\"%s\") response from dirserver '%s:%d'. Malformed rendezvous descriptor?", reason, conn->address, conn->port);
warn(LD_REND,"http status 400 (\"%s\") response from dirserver '%s:%d'. Malformed rendezvous descriptor?", reason, conn->address, conn->port);
break;
default:
log_fn(LOG_WARN,"http status %d (\"%s\") response unexpected (server '%s:%d').", status_code, reason, conn->address, conn->port);
warn(LD_REND,"http status %d (\"%s\") response unexpected (server '%s:%d').", status_code, reason, conn->address, conn->port);
break;
}
}
@ -1118,12 +1121,12 @@ connection_dir_reached_eof(connection_t *conn)
{
int retval;
if (conn->state != DIR_CONN_STATE_CLIENT_READING) {
log_fn(LOG_INFO,"conn reached eof, not reading. Closing.");
info(LD_HTTP,"conn reached eof, not reading. Closing.");
/* This check is temporary; it's to let us know whether we should consider
* parsing partial serverdesc responses. */
if (conn->purpose == DIR_PURPOSE_FETCH_SERVERDESC &&
buf_datalen(conn->inbuf)>=(24*1024)) {
log_fn(LOG_NOTICE, "Directory connection closed early after downloading %d bytes of descriptors. If this happens often, please file a bug report.",
notice(LD_DIR, "Directory connection closed early after downloading %d bytes of descriptors. If this happens often, please file a bug report.",
(int)buf_datalen(conn->inbuf));
}
connection_close_immediate(conn); /* it was an error; give up on flushing */
@ -1164,7 +1167,7 @@ connection_dir_process_inbuf(connection_t *conn)
/* XXX for READ states, might want to make sure inbuf isn't too big */
log_fn(LOG_DEBUG,"Got data, not eof. Leaving on inbuf.");
debug(LD_HTTP,"Got data, not eof. Leaving on inbuf.");
return 0;
}
@ -1178,7 +1181,7 @@ write_http_status_line(connection_t *conn, int status,
char buf[256];
if (tor_snprintf(buf, sizeof(buf), "HTTP/1.0 %d %s\r\n\r\n",
status, reason_phrase) < 0) {
log_fn(LOG_WARN,"Bug: status line too long.");
warn(LD_BUG,"Bug: status line too long.");
return;
}
connection_write_to_buf(buf, strlen(buf), conn);
@ -1222,7 +1225,7 @@ directory_handle_command_get(connection_t *conn, char *headers,
char tmp[8192];
char date[RFC1123_TIME_LEN+1];
log_fn(LOG_DEBUG,"Received GET command.");
debug(LD_DIRSERV,"Received GET command.");
conn->state = DIR_CONN_STATE_SERVER_WRITING;
@ -1230,7 +1233,7 @@ directory_handle_command_get(connection_t *conn, char *headers,
write_http_status_line(conn, 400, "Bad request");
return 0;
}
log_fn(LOG_DEBUG,"rewritten url as '%s'.", url);
debug(LD_DIRSERV,"rewritten url as '%s'.", url);
if (!strcmp(url,"/tor/") || !strcmp(url,"/tor/dir.z")) { /* directory fetch */
int deflated = !strcmp(url,"/tor/dir.z");
@ -1239,7 +1242,7 @@ directory_handle_command_get(connection_t *conn, char *headers,
tor_free(url);
if (dlen == 0) {
log_fn(LOG_NOTICE,"Client asked for the mirrored directory, but we don't have a good one yet. Sending 503 Dir not available.");
notice(LD_DIRSERV,"Client asked for the mirrored directory, but we don't have a good one yet. Sending 503 Dir not available.");
write_http_status_line(conn, 503, "Directory unavailable");
/* try to get a new one now */
if (!already_fetching_directory(DIR_PURPOSE_FETCH_DIR))
@ -1247,8 +1250,8 @@ directory_handle_command_get(connection_t *conn, char *headers,
return 0;
}
log_fn(LOG_DEBUG,"Dumping %sdirectory to client.",
deflated?"deflated ":"");
debug(LD_DIRSERV,"Dumping %sdirectory to client.",
deflated?"deflated ":"");
format_rfc1123_time(date, time(NULL));
tor_snprintf(tmp, sizeof(tmp), "HTTP/1.0 200 OK\r\nDate: %s\r\nContent-Length: %d\r\nContent-Type: %s\r\nContent-Encoding: %s\r\n\r\n",
date,
@ -1440,7 +1443,7 @@ directory_handle_command_post(connection_t *conn, char *headers,
char *origin = NULL;
char *url = NULL;
log_fn(LOG_DEBUG,"Received POST command.");
debug(LD_DIRSERV,"Received POST command.");
conn->state = DIR_CONN_STATE_SERVER_WRITING;
@ -1455,7 +1458,7 @@ directory_handle_command_post(connection_t *conn, char *headers,
write_http_status_line(conn, 400, "Bad request");
return 0;
}
log_fn(LOG_DEBUG,"rewritten url as '%s'.", url);
debug(LD_DIRSERV,"rewritten url as '%s'.", url);
origin = http_get_origin(headers, conn);
if (!strcmp(url,"/tor/")) { /* server descriptor post */
@ -1468,7 +1471,7 @@ directory_handle_command_post(connection_t *conn, char *headers,
case -2:
case -1:
case 1:
log_fn(LOG_NOTICE,"Rejected descriptor from %s.", origin);
notice(LD_DIRSERV,"Rejected descriptor from %s.", origin);
/* malformed descriptor, or something wrong */
write_http_status_line(conn, 400, msg);
break;
@ -1518,22 +1521,23 @@ directory_handle_command(connection_t *conn)
&headers, MAX_HEADERS_SIZE,
&body, &body_len, MAX_BODY_SIZE, 0)) {
case -1: /* overflow */
log_fn(LOG_WARN,"Invalid input from address '%s'. Closing.", conn->address);
warn(LD_DIRSERV,
"Invalid input from address '%s'. Closing.", conn->address);
return -1;
case 0:
log_fn(LOG_DEBUG,"command not all here yet.");
debug(LD_DIRSERV,"command not all here yet.");
return 0;
/* case 1, fall through */
}
log_fn(LOG_DEBUG,"headers '%s', body '%s'.", headers, body);
debug(LD_DIRSERV,"headers '%s', body '%s'.", headers, body);
if (!strncasecmp(headers,"GET",3))
r = directory_handle_command_get(conn, headers, body, body_len);
else if (!strncasecmp(headers,"POST",4))
r = directory_handle_command_post(conn, headers, body, body_len);
else {
log_fn(LOG_WARN,"Got headers '%s' with unknown command. Closing.", headers);
warn(LD_PROTOCOL,"Got headers '%s' with unknown command. Closing.", headers);
r = -1;
}
@ -1553,16 +1557,16 @@ connection_dir_finished_flushing(connection_t *conn)
switch (conn->state) {
case DIR_CONN_STATE_CLIENT_SENDING:
log_fn(LOG_DEBUG,"client finished sending command.");
debug(LD_DIR,"client finished sending command.");
conn->state = DIR_CONN_STATE_CLIENT_READING;
connection_stop_writing(conn);
return 0;
case DIR_CONN_STATE_SERVER_WRITING:
log_fn(LOG_DEBUG,"Finished writing server response. Closing.");
debug(LD_DIRSERV,"Finished writing server response. Closing.");
connection_mark_for_close(conn);
return 0;
default:
log_fn(LOG_WARN,"Bug: called in unexpected state %d.", conn->state);
warn(LD_BUG,"Bug: called in unexpected state %d.", conn->state);
tor_fragile_assert();
return -1;
}
@ -1578,8 +1582,8 @@ connection_dir_finished_connecting(connection_t *conn)
tor_assert(conn->type == CONN_TYPE_DIR);
tor_assert(conn->state == DIR_CONN_STATE_CONNECTING);
log_fn(LOG_DEBUG,"Dir connection to router %s:%u established.",
conn->address,conn->port);
debug(LD_HTTP,"Dir connection to router %s:%u established.",
conn->address,conn->port);
conn->state = DIR_CONN_STATE_CLIENT_SENDING; /* start flushing conn */
return 0;
@ -1639,13 +1643,13 @@ dir_routerdesc_download_failed(smartlist_t *failed)
}
}
if (rs->next_attempt_at == 0)
log_fn(LOG_DEBUG, "%s failed %d time(s); I'll try again immediately.",
debug(LD_DIR, "%s failed %d time(s); I'll try again immediately.",
cp, (int)rs->n_download_failures);
else if (rs->next_attempt_at < TIME_MAX)
log_fn(LOG_DEBUG, "%s failed %d time(s); I'll try again in %d seconds.",
debug(LD_DIR, "%s failed %d time(s); I'll try again in %d seconds.",
cp, (int)rs->n_download_failures, (int)(rs->next_attempt_at-now));
else
log_fn(LOG_DEBUG, "%s failed %d time(s); Giving up for a while.",
debug(LD_DIR, "%s failed %d time(s); Giving up for a while.",
cp, (int)rs->n_download_failures);
});

179
src/or/main.c
View file

@ -11,6 +11,7 @@ const char main_c_id[] = "$Id$";
* connections, implements main loop, and drives scheduled events.
**/
#define NEW_LOG_INTERFACE
#include "or.h"
#ifdef USE_DMALLOC
#include <dmalloc.h>
@ -122,7 +123,7 @@ connection_add(connection_t *conn)
tor_assert(conn->s >= 0);
if (nfds >= get_options()->_ConnLimit-1) {
log_fn(LOG_WARN,"Failing because we have %d connections already. Please raise your ulimit -n.", nfds);
warn(LD_NET,"Failing because we have %d connections already. Please raise your ulimit -n.", nfds);
return -1;
}
@ -139,7 +140,7 @@ connection_add(connection_t *conn)
nfds++;
log_fn(LOG_DEBUG,"new conn type %s, socket %d, nfds %d.",
debug(LD_NET,"new conn type %s, socket %d, nfds %d.",
conn_type_to_string(conn->type), conn->s, nfds);
return 0;
@ -157,8 +158,8 @@ connection_remove(connection_t *conn)
tor_assert(conn);
tor_assert(nfds>0);
log_fn(LOG_DEBUG,"removing socket %d (type %s), nfds now %d",
conn->s, conn_type_to_string(conn->type), nfds-1);
debug(LD_NET,"removing socket %d (type %s), nfds now %d",
conn->s, conn_type_to_string(conn->type), nfds-1);
tor_assert(conn->poll_index >= 0);
current_index = conn->poll_index;
@ -260,9 +261,9 @@ connection_watch_events(connection_t *conn, short events)
}
if (r<0)
log_fn(LOG_WARN,
"Error from libevent setting read event state for %d to %swatched.",
conn->s, (events & EV_READ)?"":"un");
warn(LD_NET,
"Error from libevent setting read event state for %d to %swatched.",
conn->s, (events & EV_READ)?"":"un");
if (events & EV_WRITE) {
r = event_add(conn->write_event, NULL);
@ -271,9 +272,9 @@ connection_watch_events(connection_t *conn, short events)
}
if (r<0)
log_fn(LOG_WARN,
"Error from libevent setting read event state for %d to %swatched.",
conn->s, (events & EV_WRITE)?"":"un");
warn(LD_NET,
"Error from libevent setting read event state for %d to %swatched.",
conn->s, (events & EV_WRITE)?"":"un");
}
/** Return true iff <b>conn</b> is listening for read events. */
@ -292,10 +293,10 @@ connection_stop_reading(connection_t *conn)
tor_assert(conn);
tor_assert(conn->read_event);
log(LOG_DEBUG,"connection_stop_reading() called.");
debug(LD_NET,"connection_stop_reading() called.");
if (event_del(conn->read_event))
log_fn(LOG_WARN, "Error from libevent setting read event state for %d to unwatched.",
conn->s);
warn(LD_NET, "Error from libevent setting read event state for %d to unwatched.",
conn->s);
}
/** Tell the main loop to start notifying <b>conn</b> of any read events. */
@ -306,8 +307,8 @@ connection_start_reading(connection_t *conn)
tor_assert(conn->read_event);
if (event_add(conn->read_event, NULL))
log_fn(LOG_WARN, "Error from libevent setting read event state for %d to watched.",
conn->s);
warn(LD_NET, "Error from libevent setting read event state for %d to watched.",
conn->s);
}
/** Return true iff <b>conn</b> is listening for write events. */
@ -327,7 +328,7 @@ connection_stop_writing(connection_t *conn)
tor_assert(conn->write_event);
if (event_del(conn->write_event))
log_fn(LOG_WARN, "Error from libevent setting write event state for %d to unwatched.",
warn(LD_NET, "Error from libevent setting write event state for %d to unwatched.",
conn->s);
}
@ -340,7 +341,7 @@ connection_start_writing(connection_t *conn)
tor_assert(conn->write_event);
if (event_add(conn->write_event, NULL))
log_fn(LOG_WARN, "Error from libevent setting write event state for %d to watched.",
warn(LD_NET, "Error from libevent setting write event state for %d to watched.",
conn->s);
}
@ -367,14 +368,14 @@ conn_read_callback(int fd, short event, void *_conn)
{
connection_t *conn = _conn;
LOG_FN_CONN(conn, (LOG_DEBUG,"socket %d wants to read.",conn->s));
debug(LD_NET,"socket %d wants to read.",conn->s);
assert_connection_ok(conn, time(NULL));
if (connection_handle_read(conn) < 0) {
if (!conn->marked_for_close) {
#ifndef MS_WINDOWS
log_fn(LOG_WARN,"Bug: unhandled error on read for %s connection (fd %d); removing",
warn(LD_BUG,"Bug: unhandled error on read for %s connection (fd %d); removing",
conn_type_to_string(conn->type), conn->s);
tor_fragile_assert();
#endif
@ -396,14 +397,14 @@ conn_write_callback(int fd, short events, void *_conn)
{
connection_t *conn = _conn;
LOG_FN_CONN(conn, (LOG_DEBUG,"socket %d wants to write.",conn->s));
LOG_FN_CONN(conn, (LOG_DEBUG, LD_NET, "socket %d wants to write.",conn->s));
assert_connection_ok(conn, time(NULL));
if (connection_handle_write(conn) < 0) {
if (!conn->marked_for_close) {
/* this connection is broken. remove it. */
log_fn(LOG_WARN,"Bug: unhandled error on write for %s connection (fd %d); removing",
log_fn(LOG_WARN,LD_BUG,"Bug: unhandled error on write for %s connection (fd %d); removing",
conn_type_to_string(conn->type), conn->s);
tor_fragile_assert();
conn->has_sent_end = 1; /* otherwise we cry wolf about duplicate close */
@ -437,12 +438,12 @@ conn_close_if_marked(int i)
assert_connection_ok(conn, time(NULL));
assert_all_pending_dns_resolves_ok();
log_fn(LOG_DEBUG,"Cleaning up connection (fd %d).",conn->s);
debug(LD_NET,"Cleaning up connection (fd %d).",conn->s);
if (conn->s >= 0 && connection_wants_to_flush(conn)) {
/* -1 means it's an incomplete edge connection, or that the socket
* has already been closed as unflushable. */
if (!conn->hold_open_until_flushed)
log_fn(LOG_INFO,
info(LD_NET,
"Conn (addr %s, fd %d, type %s, state %d) marked, but wants to flush %d bytes. "
"(Marked at %s:%d)",
conn->address, conn->s, conn_type_to_string(conn->type), conn->state,
@ -458,7 +459,7 @@ conn_close_if_marked(int i)
if (retval >= 0 &&
conn->hold_open_until_flushed && connection_wants_to_flush(conn)) {
LOG_FN_CONN(conn,
(LOG_INFO,"Holding conn (fd %d) open for more flushing.",conn->s));
(LOG_INFO,LD_NET,"Holding conn (fd %d) open for more flushing.",conn->s));
/* XXX should we reset timestamp_lastwritten here? */
return 0;
}
@ -469,7 +470,7 @@ conn_close_if_marked(int i)
severity = LOG_INFO;
else
severity = LOG_NOTICE;
log_fn(severity, "Something wrong with your network connection? Conn (addr %s, fd %d, type %s, state %d) tried to write %d bytes but timed out. (Marked at %s:%d)",
log_fn(severity, LD_NET, "Something wrong with your network connection? Conn (addr %s, fd %d, type %s, state %d) tried to write %d bytes but timed out. (Marked at %s:%d)",
safe_str(conn->address), conn->s, conn_type_to_string(conn->type),
conn->state,
(int)buf_datalen(conn->outbuf), conn->marked_for_close_file,
@ -497,7 +498,7 @@ directory_all_unreachable(time_t now)
while ((conn = connection_get_by_type_state(CONN_TYPE_AP,
AP_CONN_STATE_CIRCUIT_WAIT))) {
log_fn(LOG_NOTICE,"Network down? Failing connection to '%s:%d'.",
notice(LD_NET,"Network down? Failing connection to '%s:%d'.",
safe_str(conn->socks_request->address), conn->socks_request->port);
connection_mark_unattached_ap(conn, END_STREAM_REASON_NET_UNREACHABLE);
}
@ -545,12 +546,12 @@ directory_info_has_arrived(time_t now, int from_cache)
or_options_t *options = get_options();
if (!router_have_minimum_dir_info()) {
log_fn(LOG_NOTICE, "I learned some more directory information, but not enough to build a circuit.");
notice(LD_DIR, "I learned some more directory information, but not enough to build a circuit.");
return;
}
if (!has_fetched_directory) {
log_fn(LOG_NOTICE, "We have enough directory information to build circuits.");
notice(LD_DIR, "We have enough directory information to build circuits.");
}
has_fetched_directory=1;
@ -581,13 +582,13 @@ run_connection_housekeeping(int i, time_t now)
if (conn->type == CONN_TYPE_DIR &&
!conn->marked_for_close &&
conn->timestamp_lastwritten + 5*60 < now) {
log_fn(LOG_INFO,"Expiring wedged directory conn (fd %d, purpose %d)",
info(LD_DIR,"Expiring wedged directory conn (fd %d, purpose %d)",
conn->s, conn->purpose);
/* This check is temporary; it's to let us know whether we should consider
* parsing partial serverdesc responses. */
if (conn->purpose == DIR_PURPOSE_FETCH_SERVERDESC &&
buf_datalen(conn->inbuf)>=1024) {
log_fn(LOG_INFO,"Trying to extract information from wedged server desc download.");
info(LD_DIR,"Trying to extract information from wedged server desc download.");
connection_dir_reached_eof(conn);
}
connection_mark_for_close(conn);
@ -600,33 +601,33 @@ run_connection_housekeeping(int i, time_t now)
now >= conn->timestamp_lastwritten + options->KeepalivePeriod) {
routerinfo_t *router = router_get_by_digest(conn->identity_digest);
if (!connection_state_is_open(conn)) {
log_fn(LOG_INFO,"Expiring non-open OR connection to fd %d (%s:%d).",
conn->s,conn->address, conn->port);
info(LD_OR,"Expiring non-open OR connection to fd %d (%s:%d).",
conn->s,conn->address, conn->port);
connection_mark_for_close(conn);
conn->hold_open_until_flushed = 1;
} else if (we_are_hibernating() && !circuit_get_by_conn(conn) &&
!buf_datalen(conn->outbuf)) {
log_fn(LOG_INFO,"Expiring non-used OR connection to fd %d (%s:%d) [Hibernating or exiting].",
info(LD_OR,"Expiring non-used OR connection to fd %d (%s:%d) [Hibernating or exiting].",
conn->s,conn->address, conn->port);
connection_mark_for_close(conn);
conn->hold_open_until_flushed = 1;
} else if (!clique_mode(options) && !circuit_get_by_conn(conn) &&
(!router || !server_mode(options) || !router_is_clique_mode(router))) {
log_fn(LOG_INFO,"Expiring non-used OR connection to fd %d (%s:%d) [Not in clique mode].",
info(LD_OR,"Expiring non-used OR connection to fd %d (%s:%d) [Not in clique mode].",
conn->s,conn->address, conn->port);
connection_mark_for_close(conn);
conn->hold_open_until_flushed = 1;
} else if (
now >= conn->timestamp_lastempty + options->KeepalivePeriod*10 &&
now >= conn->timestamp_lastwritten + options->KeepalivePeriod*10) {
log_fn(LOG_PROTOCOL_WARN,"Expiring stuck OR connection to fd %d (%s:%d). (%d bytes to flush; %d seconds since last write)",
log_fn(LOG_PROTOCOL_WARN,LD_PROTOCOL,"Expiring stuck OR connection to fd %d (%s:%d). (%d bytes to flush; %d seconds since last write)",
conn->s, conn->address, conn->port,
(int)buf_datalen(conn->outbuf),
(int)(now-conn->timestamp_lastwritten));
connection_mark_for_close(conn);
} else if (!buf_datalen(conn->outbuf)) {
/* either in clique mode, or we've got a circuit. send a padding cell. */
log_fn(LOG_DEBUG,"Sending keepalive to (%s:%d)",
log_fn(LOG_DEBUG,LD_OR,"Sending keepalive to (%s:%d)",
conn->address, conn->port);
memset(&cell,0,sizeof(cell_t));
cell.command = CELL_PADDING;
@ -664,11 +665,11 @@ run_scheduled_events(time_t now)
*/
if (server_mode(options) &&
get_onion_key_set_at()+MIN_ONION_KEY_LIFETIME < now) {
log_fn(LOG_INFO,"Rotating onion key.");
info(LD_GENERAL,"Rotating onion key.");
rotate_onion_key();
cpuworkers_rotate();
if (router_rebuild_descriptor(1)<0) {
log_fn(LOG_WARN, "Couldn't rebuild router descriptor");
warn(LD_BUG, "Couldn't rebuild router descriptor");
}
if (advertised_server_mode())
router_upload_dir_desc_to_dirservers(0);
@ -688,10 +689,10 @@ run_scheduled_events(time_t now)
if (!last_rotated_certificate)
last_rotated_certificate = now;
if (last_rotated_certificate+MAX_SSL_KEY_LIFETIME < now) {
log_fn(LOG_INFO,"Rotating tls context.");
info(LD_GENERAL,"Rotating tls context.");
if (tor_tls_context_new(get_identity_key(), 1, options->Nickname,
MAX_SSL_KEY_LIFETIME) < 0) {
log_fn(LOG_WARN, "Error reinitializing TLS context");
warn(LD_BUG, "Error reinitializing TLS context");
/* XXX is it a bug here, that we just keep going? */
}
last_rotated_certificate = now;
@ -893,10 +894,10 @@ second_elapsed_callback(int fd, short event, void *args)
/* every 20 minutes, check and complain if necessary */
routerinfo_t *me = router_get_my_routerinfo();
if (me && !check_whether_orport_reachable())
log(LOG_WARN,"Your server (%s:%d) has not managed to confirm that its ORPort is reachable. Please check your firewalls, ports, address, /etc/hosts file, etc.",
warn(LD_CONFIG,"Your server (%s:%d) has not managed to confirm that its ORPort is reachable. Please check your firewalls, ports, address, /etc/hosts file, etc.",
me->address, me->or_port);
if (me && !check_whether_dirport_reachable())
log(LOG_WARN,"Your server (%s:%d) has not managed to confirm that its DirPort is reachable. Please check your firewalls, ports, address, /etc/hosts file, etc.",
warn(LD_CONFIG,"Your server (%s:%d) has not managed to confirm that its DirPort is reachable. Please check your firewalls, ports, address, /etc/hosts file, etc.",
me->address, me->dir_port);
}
@ -918,8 +919,8 @@ second_elapsed_callback(int fd, short event, void *args)
#endif
if (evtimer_add(timeout_event, &one_second))
log_fn(LOG_ERR,
"Error from libevent when setting one-second timeout event");
err(LD_NET,
"Error from libevent when setting one-second timeout event");
}
/** Called when a possibly ignorable libevent error occurs; ensures that we
@ -929,7 +930,7 @@ static int
got_libevent_error(void)
{
if (++n_libevent_errors > 8) {
log_fn(LOG_ERR, "Too many libevent errors in one second; dying");
err(LD_NET, "Too many libevent errors in one second; dying");
return -1;
}
return 0;
@ -943,7 +944,7 @@ do_hup(void)
char keydir[512];
or_options_t *options = get_options();
log(LOG_NOTICE,"Received sighup. Reloading config.");
notice(LD_GENERAL,"Received sighup. Reloading config.");
has_completed_circuit=0;
if (accounting_is_enabled(options))
accounting_record_bandwidth_usage(time(NULL));
@ -954,16 +955,16 @@ do_hup(void)
/* first, reload config variables, in case they've changed */
/* no need to provide argc/v, they've been cached inside init_from_config */
if (options_init_from_torrc(0, NULL) < 0) {
log_fn(LOG_ERR,"Reading config failed--see warnings above. For usage, try -h.");
err(LD_CONFIG,"Reading config failed--see warnings above. For usage, try -h.");
return -1;
}
options = get_options(); /* they have changed now */
if (authdir_mode(options)) {
/* reload the approved-routers file */
tor_snprintf(keydir,sizeof(keydir),"%s/approved-routers", options->DataDirectory);
log_fn(LOG_INFO,"Reloading approved fingerprints from \"%s\"...",keydir);
info(LD_GENERAL,"Reloading approved fingerprints from \"%s\"...",keydir);
if (dirserv_parse_fingerprint_file(keydir) < 0) {
log_fn(LOG_NOTICE, "Error reloading fingerprints. Continuing with old list.");
info(LD_GENERAL, "Error reloading fingerprints. Continuing with old list.");
}
}
@ -992,7 +993,7 @@ do_hup(void)
if (descriptor) {
tor_snprintf(keydir,sizeof(keydir),"%s/router.desc",
options->DataDirectory);
log_fn(LOG_INFO,"Saving descriptor to \"%s\"...",keydir);
info(LD_OR,"Saving descriptor to \"%s\"...",keydir);
if (write_str_to_file(keydir, descriptor, 0)) {
return 0;
}
@ -1015,7 +1016,7 @@ do_main_loop(void)
* TLS context. */
if (! identity_key_is_set()) {
if (init_keys() < 0) {
log_fn(LOG_ERR,"Error initializing keys; exiting");
err(LD_GENERAL,"Error initializing keys; exiting");
return -1;
}
}
@ -1067,23 +1068,23 @@ do_main_loop(void)
/* let the program survive things like ^z */
if (e != EINTR && !ERRNO_IS_EINPROGRESS(e)) {
#ifdef HAVE_EVENT_GET_METHOD
log_fn(LOG_ERR,"libevent poll with %s failed: %s [%d]",
err(LD_NET,"libevent poll with %s failed: %s [%d]",
event_get_method(), tor_socket_strerror(e), e);
#else
log_fn(LOG_ERR,"libevent poll failed: %s [%d]",
err(LD_NET,"libevent poll failed: %s [%d]",
tor_socket_strerror(e), e);
#endif
return -1;
#ifndef MS_WINDOWS
} else if (e == EINVAL) {
log_fn(LOG_WARN, "EINVAL from libevent: should you upgrade libevent?");
warn(LD_NET, "EINVAL from libevent: should you upgrade libevent?");
if (got_libevent_error())
return -1;
#endif
} else {
if (ERRNO_IS_EINPROGRESS(e))
log_fn(LOG_WARN,"libevent poll returned EINPROGRESS? Please report.");
log_fn(LOG_DEBUG,"event poll interrupted.");
warn(LD_BUG,"libevent poll returned EINPROGRESS? Please report.");
debug(LD_NET,"event poll interrupted.");
/* You can't trust the results of this poll(). Go back to the
* top of the big for loop. */
continue;
@ -1141,13 +1142,13 @@ signal_callback(int fd, short events, void *arg)
switch (sig)
{
case SIGTERM:
log(LOG_ERR,"Catching signal TERM, exiting cleanly.");
err(LD_GENERAL,"Catching signal TERM, exiting cleanly.");
tor_cleanup();
exit(0);
break;
case SIGINT:
if (!server_mode(get_options())) { /* do it now */
log(LOG_NOTICE,"Interrupt: exiting cleanly.");
notice(LD_GENERAL,"Interrupt: exiting cleanly.");
tor_cleanup();
exit(0);
}
@ -1155,7 +1156,7 @@ signal_callback(int fd, short events, void *arg)
break;
#ifdef SIGPIPE
case SIGPIPE:
log(LOG_DEBUG,"Caught sigpipe. Ignoring.");
debug(LD_GENERAL,"Caught sigpipe. Ignoring.");
break;
#endif
case SIGUSR1:
@ -1164,11 +1165,11 @@ signal_callback(int fd, short events, void *arg)
break;
case SIGUSR2:
switch_logs_debug();
log(LOG_NOTICE,"Caught USR2, going to loglevel debug. Send HUP to change back.");
debug(LD_GENERAL,"Caught USR2, going to loglevel debug. Send HUP to change back.");
break;
case SIGHUP:
if (do_hup() < 0) {
log_fn(LOG_WARN,"Restart failed (config error?). Exiting.");
warn(LD_CONFIG,"Restart failed (config error?). Exiting.");
tor_cleanup();
exit(1);
}
@ -1192,10 +1193,10 @@ dumpmemusage(int severity)
extern uint64_t rephist_total_alloc;
extern uint32_t rephist_total_num;
log(severity, "In buffers: "U64_FORMAT" used/"U64_FORMAT" allocated (%d conns).",
log(severity, LD_GENERAL, "In buffers: "U64_FORMAT" used/"U64_FORMAT" allocated (%d conns).",
U64_PRINTF_ARG(buf_total_used), U64_PRINTF_ARG(buf_total_alloc),
nfds);
log(severity, "In rephist: "U64_FORMAT" used by %d Tors.",
log(severity, LD_GENERAL, "In rephist: "U64_FORMAT" used by %d Tors.",
U64_PRINTF_ARG(rephist_total_alloc), rephist_total_num);
}
@ -1209,27 +1210,27 @@ dumpstats(int severity)
time_t now = time(NULL);
time_t elapsed;
log(severity, "Dumping stats:");
log(severity, LD_GENERAL, "Dumping stats:");
for (i=0;i<nfds;i++) {
conn = connection_array[i];
log(severity, "Conn %d (socket %d) type %d (%s), state %d (%s), created %d secs ago",
log(severity, LD_GENERAL, "Conn %d (socket %d) type %d (%s), state %d (%s), created %d secs ago",
i, conn->s, conn->type, conn_type_to_string(conn->type),
conn->state, conn_state_to_string(conn->type, conn->state), (int)(now - conn->timestamp_created));
if (!connection_is_listener(conn)) {
log(severity,"Conn %d is to '%s:%d'.",i,safe_str(conn->address), conn->port);
log(severity,"Conn %d: %d bytes waiting on inbuf (len %d, last read %d secs ago)",i,
log(severity,LD_GENERAL,"Conn %d is to '%s:%d'.",i,safe_str(conn->address), conn->port);
log(severity,LD_GENERAL, "Conn %d: %d bytes waiting on inbuf (len %d, last read %d secs ago)",i,
(int)buf_datalen(conn->inbuf),
(int)buf_capacity(conn->inbuf),
(int)(now - conn->timestamp_lastread));
log(severity,"Conn %d: %d bytes waiting on outbuf (len %d, last written %d secs ago)",i,
log(severity,LD_GENERAL, "Conn %d: %d bytes waiting on outbuf (len %d, last written %d secs ago)",i,
(int)buf_datalen(conn->outbuf),
(int)buf_capacity(conn->outbuf),
(int)(now - conn->timestamp_lastwritten));
}
circuit_dump_by_conn(conn, severity); /* dump info about all the circuits using this conn */
}
log(severity,
log(severity, LD_NET,
"Cells processed: %10lu padding\n"
" %10lu create\n"
" %10lu created\n"
@ -1245,11 +1246,11 @@ dumpstats(int severity)
stats_n_relay_cells_delivered,
stats_n_destroy_cells_processed);
if (stats_n_data_cells_packaged)
log(severity,"Average packaged cell fullness: %2.3f%%",
log(severity,LD_NET,"Average packaged cell fullness: %2.3f%%",
100*(((double)stats_n_data_bytes_packaged) /
(stats_n_data_cells_packaged*RELAY_PAYLOAD_SIZE)) );
if (stats_n_data_cells_received)
log(severity,"Average delivered cell fullness: %2.3f%%",
log(severity,LD_NET,"Average delivered cell fullness: %2.3f%%",
100*(((double)stats_n_data_bytes_received) /
(stats_n_data_cells_received*RELAY_PAYLOAD_SIZE)) );
@ -1259,19 +1260,19 @@ dumpstats(int severity)
elapsed = 0;
if (elapsed) {
log(severity,
log(severity, LD_NET,
"Average bandwidth: "U64_FORMAT"/%d = %d bytes/sec reading",
U64_PRINTF_ARG(stats_n_bytes_read),
(int)elapsed,
(int) (stats_n_bytes_read/elapsed));
log(severity,
log(severity, LD_NET,
"Average bandwidth: "U64_FORMAT"/%d = %d bytes/sec writing",
U64_PRINTF_ARG(stats_n_bytes_written),
(int)elapsed,
(int) (stats_n_bytes_written/elapsed));
}
log(severity, "--------------- Dumping memory information:");
log(severity, LD_NET, "--------------- Dumping memory information:");
dumpmemusage(severity);
rep_hist_dump_stats(now,severity);
@ -1314,7 +1315,7 @@ handle_signals(int is_parent)
signal_set(&signal_events[i], signals[i], signal_callback,
(void*)(uintptr_t)signals[i]);
if (signal_add(&signal_events[i], NULL))
log_fn(LOG_WARN, "Error from libevent when adding event for signal %d",
warn(LD_BUG, "Error from libevent when adding event for signal %d",
signals[i]);
}
} else {
@ -1352,27 +1353,27 @@ tor_init(int argc, char *argv[])
/* give it somewhere to log to initially */
add_temp_log();
log(LOG_NOTICE,"Tor v%s. This is experimental software. Do not rely on it for strong anonymity.",VERSION);
log(LOG_NOTICE, LD_GENERAL, "Tor v%s. This is experimental software. Do not rely on it for strong anonymity.",VERSION);
if (network_init()<0) {
log_fn(LOG_ERR,"Error initializing network; exiting.");
err(LD_NET,"Error initializing network; exiting.");
return -1;
}
atexit(exit_function);
if (options_init_from_torrc(argc,argv) < 0) {
log_fn(LOG_ERR,"Reading config failed--see warnings above. For usage, try -h.");
err(LD_CONFIG,"Reading config failed--see warnings above. For usage, try -h.");
return -1;
}
#ifndef MS_WINDOWS
if (geteuid()==0)
log_fn(LOG_WARN,"You are running Tor as root. You don't need to, and you probably shouldn't.");
warn(LD_GENERAL,"You are running Tor as root. You don't need to, and you probably shouldn't.");
#endif
crypto_global_init(get_options()->HardwareAccel);
if (crypto_seed_rng()) {
log_fn(LOG_ERR, "Unable to seed random number generator. Exiting.");
err(LD_BUG, "Unable to seed random number generator. Exiting.");
return -1;
}
@ -1447,15 +1448,15 @@ do_list_fingerprint(void)
}
tor_assert(nickname);
if (init_keys() < 0) {
log_fn(LOG_ERR,"Error initializing keys; exiting");
err(LD_BUG,"Error initializing keys; exiting");
return;
}
if (!(k = get_identity_key())) {
log_fn(LOG_ERR,"Error: missing identity key.");
err(LD_GENERAL,"Error: missing identity key.");
return;
}
if (crypto_pk_get_fingerprint(k, buf, 1)<0) {
log_fn(LOG_ERR, "Error computing fingerprint");
warn(LD_BUG, "Error computing fingerprint");
return;
}
printf("%s %s\n", nickname, buf);
@ -1552,7 +1553,7 @@ nt_service_control(DWORD request)
switch (request) {
case SERVICE_CONTROL_STOP:
case SERVICE_CONTROL_SHUTDOWN:
log(LOG_ERR, "Got stop/shutdown request; shutting down cleanly.");
err(LD_GENERAL, "Got stop/shutdown request; shutting down cleanly.");
service_status.dwCurrentState = SERVICE_STOP_PENDING;
event_loopexit(&exit_now);
return;
@ -1588,7 +1589,7 @@ nt_service_body(int argc, char **argv)
}
}
else {
log_fn(LOG_ERR, "torrc is not in the current working directory. The Tor service will not start.");
err(LD_CONFIG, "torrc is not in the current working directory. The Tor service will not start.");
err = NT_SERVICE_ERROR_NO_TORRC;
}
@ -1641,7 +1642,7 @@ nt_service_main(void)
printf("Configuration was valid\n");
break;
default:
log_fn(LOG_ERR, "Illegal command number %d: internal error.", get_options()->command);
err(LD_CONFIG, "Illegal command number %d: internal error.", get_options()->command);
}
tor_cleanup();
}
@ -1960,7 +1961,7 @@ tor_main(int argc, char *argv[])
{
#ifdef USE_DMALLOC
int r = CRYPTO_set_mem_ex_functions(_tor_malloc, _tor_realloc, _tor_dmalloc_free);
log_fn(LOG_NOTICE, "r = %d", r);
notice(LD_CONFIG, "Set up damalloc; returned %d", r);
#endif
#ifdef MS_WINDOWS_SERVICE
backup_argv = argv;
@ -2008,8 +2009,8 @@ tor_main(int argc, char *argv[])
printf("Configuration was valid\n");
break;
default:
log_fn(LOG_ERR, "Illegal command number %d: internal error.",
get_options()->command);
warn(LD_BUG,"Illegal command number %d: internal error.",
get_options()->command);
}
tor_cleanup();
return -1;