diff options
Diffstat (limited to 'src')
| -rw-r--r-- | src/common/log.h | 5 | ||||
| -rw-r--r-- | src/or/connection_edge.c | 150 | ||||
| -rw-r--r-- | src/or/cpuworker.c | 50 | ||||
| -rw-r--r-- | src/or/directory.c | 160 | ||||
| -rw-r--r-- | src/or/main.c | 179 |
5 files changed, 276 insertions, 268 deletions
diff --git a/src/common/log.h b/src/common/log.h index 0cd6dd442..7ca278b78 100644 --- a/src/common/log.h +++ b/src/common/log.h @@ -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); diff --git a/src/or/connection_edge.c b/src/or/connection_edge.c index abddbe2ba..b0620205d 100644 --- a/src/or/connection_edge.c +++ b/src/or/connection_edge.c @@ -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; } diff --git a/src/or/cpuworker.c b/src/or/cpuworker.c index a6ef430e6..a6bb9d932 100644 --- a/src/or/cpuworker.c +++ b/src/or/cpuworker.c @@ -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); diff --git a/src/or/directory.c b/src/or/directory.c index af6b9afc4..198b95f0c 100644 --- a/src/or/directory.c +++ b/src/or/directory.c @@ -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); }); diff --git a/src/or/main.c b/src/or/main.c index 572b29537..9966a825a 100644 --- a/src/or/main.c +++ b/src/or/main.c @@ -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; |