clean up some log messages and severities

still plenty more left to clean


svn:r1158
This commit is contained in:
Roger Dingledine 2004-02-28 07:01:22 +00:00
parent a24b6e6d4f
commit dd632e697e
6 changed files with 63 additions and 63 deletions

View File

@ -419,7 +419,6 @@ int fetch_from_buf_socks(buf_t *buf, socks_request_t *req) {
if(req->socks_version != 5) { /* we need to negotiate a method */
unsigned char nummethods = (unsigned char)*(buf->mem+1);
assert(!req->socks_version);
log_fn(LOG_DEBUG,"socks5: learning offered methods");
if(buf->datalen < 2+nummethods)
return 0;
if(!nummethods || !memchr(buf->mem+2, 0, nummethods)) {
@ -443,7 +442,7 @@ int fetch_from_buf_socks(buf_t *buf, socks_request_t *req) {
if(buf->datalen < 8) /* basic info plus >=2 for addr plus 2 for port */
return 0; /* not yet */
if(*(buf->mem+1) != 1) { /* not a connect? we don't support it. */
log_fn(LOG_WARN,"socks5: command %d not '1'.",*(buf->mem+1));
log_fn(LOG_WARN,"socks5: command %d not '1'. Rejecting.",*(buf->mem+1));
return -1;
}
switch(*(buf->mem+3)) { /* address type */
@ -455,7 +454,7 @@ int fetch_from_buf_socks(buf_t *buf, socks_request_t *req) {
in.s_addr = htonl(destip);
tmpbuf = inet_ntoa(in);
if(strlen(tmpbuf)+1 > MAX_SOCKS_ADDR_LEN) {
log_fn(LOG_WARN,"socks5 IP takes %d bytes, which doesn't fit in %d",
log_fn(LOG_WARN,"socks5 IP takes %d bytes, which doesn't fit in %d. Rejecting.",
(int)strlen(tmpbuf)+1,(int)MAX_SOCKS_ADDR_LEN);
return -1;
}
@ -469,7 +468,7 @@ int fetch_from_buf_socks(buf_t *buf, socks_request_t *req) {
if(buf->datalen < 7+len) /* addr/port there? */
return 0; /* not yet */
if(len+1 > MAX_SOCKS_ADDR_LEN) {
log_fn(LOG_WARN,"socks5 hostname is %d bytes, which doesn't fit in %d",
log_fn(LOG_WARN,"socks5 hostname is %d bytes, which doesn't fit in %d. Rejecting.",
len+1,MAX_SOCKS_ADDR_LEN);
return -1;
}
@ -479,7 +478,7 @@ int fetch_from_buf_socks(buf_t *buf, socks_request_t *req) {
buf_remove_from_front(buf, 5+len+2);
return 1;
default: /* unsupported */
log_fn(LOG_WARN,"socks5: unsupported address type %d",*(buf->mem+3));
log_fn(LOG_WARN,"socks5: unsupported address type %d. Rejecting.",*(buf->mem+3));
return -1;
}
assert(0);
@ -490,14 +489,14 @@ int fetch_from_buf_socks(buf_t *buf, socks_request_t *req) {
return 0; /* not yet */
if(*(buf->mem+1) != 1) { /* not a connect? we don't support it. */
log_fn(LOG_WARN,"socks4: command %d not '1'.",*(buf->mem+1));
log_fn(LOG_WARN,"socks4: command %d not '1'. Rejecting.",*(buf->mem+1));
return -1;
}
req->port = ntohs(*(uint16_t*)(buf->mem+2));
destip = ntohl(*(uint32_t*)(buf->mem+4));
if(!req->port || !destip) {
log_fn(LOG_WARN,"socks4: Port or DestIP is zero.");
log_fn(LOG_WARN,"socks4: Port or DestIP is zero. Rejecting.");
return -1;
}
if(destip >> 8) {
@ -505,7 +504,7 @@ int fetch_from_buf_socks(buf_t *buf, socks_request_t *req) {
in.s_addr = htonl(destip);
tmpbuf = inet_ntoa(in);
if(strlen(tmpbuf)+1 > MAX_SOCKS_ADDR_LEN) {
log_fn(LOG_WARN,"socks4 addr (%d bytes) too long.",
log_fn(LOG_WARN,"socks4 addr (%d bytes) too long. Rejecting.",
(int)strlen(tmpbuf));
return -1;
}
@ -515,7 +514,7 @@ int fetch_from_buf_socks(buf_t *buf, socks_request_t *req) {
next = memchr(buf->mem+SOCKS4_NETWORK_LEN, 0, buf->datalen);
if(!next) {
log_fn(LOG_DEBUG,"Username not here yet.");
log_fn(LOG_DEBUG,"socks4: Username not here yet.");
return 0;
}
@ -523,15 +522,15 @@ int fetch_from_buf_socks(buf_t *buf, socks_request_t *req) {
if(socks4_prot == socks4a) {
next = memchr(startaddr, 0, buf->mem+buf->datalen-startaddr);
if(!next) {
log_fn(LOG_DEBUG,"Destaddr not here yet.");
log_fn(LOG_DEBUG,"socks4: Destaddr not here yet.");
return 0;
}
if(MAX_SOCKS_ADDR_LEN <= next-startaddr) {
log_fn(LOG_WARN,"Destaddr too long.");
log_fn(LOG_WARN,"socks4: Destaddr too long. Rejecting.");
return -1;
}
}
log_fn(LOG_DEBUG,"Everything is here. Success.");
log_fn(LOG_DEBUG,"socks4: Everything is here. Success.");
strcpy(req->address, socks4_prot == socks4 ? tmpbuf : startaddr);
/* XXX on very old netscapes (socks4) the next line triggers an
* assert, because next-buf->mem+1 is greater than buf->datalen.

View File

@ -323,8 +323,8 @@ static void relay_set_digest(crypto_digest_env_t *digest, cell_t *cell) {
crypto_digest_add_bytes(digest, cell->payload, CELL_PAYLOAD_SIZE);
crypto_digest_get_digest(digest, integrity, 4);
log_fn(LOG_DEBUG,"Putting digest of %u %u %u %u into relay cell.",
integrity[0], integrity[1], integrity[2], integrity[3]);
// log_fn(LOG_DEBUG,"Putting digest of %u %u %u %u into relay cell.",
// integrity[0], integrity[1], integrity[2], integrity[3]);
relay_header_unpack(&rh, cell->payload);
memcpy(rh.integrity, integrity, 4);
relay_header_pack(cell->payload, &rh);
@ -346,15 +346,15 @@ static int relay_digest_matches(crypto_digest_env_t *digest, cell_t *cell) {
memset(rh.integrity, 0, 4);
relay_header_pack(cell->payload, &rh);
log_fn(LOG_DEBUG,"Reading digest of %u %u %u %u from relay cell.",
received_integrity[0], received_integrity[1],
received_integrity[2], received_integrity[3]);
// log_fn(LOG_DEBUG,"Reading digest of %u %u %u %u from relay cell.",
// received_integrity[0], received_integrity[1],
// received_integrity[2], received_integrity[3]);
crypto_digest_add_bytes(digest, cell->payload, CELL_PAYLOAD_SIZE);
crypto_digest_get_digest(digest, calculated_integrity, 4);
if(memcmp(received_integrity, calculated_integrity, 4)) {
log_fn(LOG_INFO,"Recognized=0 but bad digest. Not recognizing.");
// log_fn(LOG_INFO,"Recognized=0 but bad digest. Not recognizing.");
// (%d vs %d).", received_integrity, calculated_integrity);
/* restore digest to its old form */
crypto_digest_assign(digest, backup_digest);
@ -374,7 +374,7 @@ static int relay_crypt_one_payload(crypto_cipher_env_t *cipher, char *in,
relay_header_t rh;
relay_header_unpack(&rh, in);
log_fn(LOG_DEBUG,"before crypt: %d",rh.recognized);
// log_fn(LOG_DEBUG,"before crypt: %d",rh.recognized);
if(( encrypt_mode && crypto_cipher_encrypt(cipher, in, CELL_PAYLOAD_SIZE, out)) ||
(!encrypt_mode && crypto_cipher_decrypt(cipher, in, CELL_PAYLOAD_SIZE, out))) {
log_fn(LOG_WARN,"Error during crypt: %s", crypto_perror());
@ -382,7 +382,7 @@ static int relay_crypt_one_payload(crypto_cipher_env_t *cipher, char *in,
}
memcpy(in,out,CELL_PAYLOAD_SIZE);
relay_header_unpack(&rh, in);
log_fn(LOG_DEBUG,"after crypt: %d",rh.recognized);
// log_fn(LOG_DEBUG,"after crypt: %d",rh.recognized);
return 0;
}
@ -438,7 +438,7 @@ int circuit_receive_relay_cell(cell_t *cell, circuit_t *circ,
}
if(!conn) {
log_fn(LOG_WARN,"Didn't recognize cell, but circ stops here! Dropping.");
log_fn(LOG_WARN,"Didn't recognize cell, but circ stops here! Closing circ.");
return -1;
}
@ -462,7 +462,7 @@ static int relay_crypt(circuit_t *circ, cell_t *cell, char cell_direction,
We'll want to do layered crypts. */
thishop = circ->cpath;
if(thishop->state != CPATH_STATE_OPEN) {
log_fn(LOG_WARN,"Relay cell before first created cell?");
log_fn(LOG_WARN,"Relay cell before first created cell? Closing.");
return -1;
}
do { /* Remember: cpath is in forward order, that is, first hop first. */
@ -483,12 +483,12 @@ static int relay_crypt(circuit_t *circ, cell_t *cell, char cell_direction,
thishop = thishop->next;
} while(thishop != circ->cpath && thishop->state == CPATH_STATE_OPEN);
log_fn(LOG_WARN,"in-cell at OP not recognized. Dropping.");
return 0;
log_fn(LOG_WARN,"in-cell at OP not recognized. Closing.");
return -1;
} else { /* we're in the middle. Just one crypt. */
if(relay_crypt_one_payload(circ->p_crypto, cell->payload, 1) < 0)
return -1;
log_fn(LOG_DEBUG,"Skipping recognized check, because we're not the OP.");
// log_fn(LOG_DEBUG,"Skipping recognized check, because we're not the OP.");
}
} else /* cell_direction == CELL_DIRECTION_OUT */ {
/* we're in the middle. Just one crypt. */
@ -510,10 +510,8 @@ static int relay_crypt(circuit_t *circ, cell_t *cell, char cell_direction,
/*
package a relay cell:
- if from AP: encrypt it to the right conn if 'recognized' doesn't
conflict, else insert dummies first as appropriate
- if from exit: encrypt it
- connection_or_write_cell_to_buf to the right conn
1) encrypt it to the right conn
2) connection_or_write_cell_to_buf to the right conn
*/
int
circuit_package_relay_cell(cell_t *cell, circuit_t *circ,
@ -526,7 +524,7 @@ circuit_package_relay_cell(cell_t *cell, circuit_t *circ,
if(cell_direction == CELL_DIRECTION_OUT) {
conn = circ->n_conn;
if(!conn) {
log_fn(LOG_INFO,"outgoing relay cell has n_conn==NULL. Dropping.");
log_fn(LOG_WARN,"outgoing relay cell has n_conn==NULL. Dropping.");
return 0; /* just drop it */
}
relay_set_digest(layer_hint->f_digest, cell);
@ -547,7 +545,7 @@ circuit_package_relay_cell(cell_t *cell, circuit_t *circ,
} else { /* incoming cell */
conn = circ->p_conn;
if(!conn) {
log_fn(LOG_INFO,"incoming relay cell has p_conn==NULL. Dropping.");
log_fn(LOG_WARN,"incoming relay cell has p_conn==NULL. Dropping.");
return 0; /* just drop it */
}
relay_set_digest(circ->p_digest, cell);
@ -580,7 +578,7 @@ relay_lookup_conn(circuit_t *circ, cell_t *cell, int cell_direction)
log_fn(LOG_DEBUG,"found conn for stream %d.", rh.stream_id);
return tmpconn;
}
log_fn(LOG_DEBUG,"considered stream %d, not it.",tmpconn->stream_id);
// log_fn(LOG_DEBUG,"considered stream %d, not it.",tmpconn->stream_id);
}
return NULL; /* probably a begin relay cell */
}
@ -645,7 +643,7 @@ void circuit_consider_sending_sendme(circuit_t *circ, int edge_type, crypt_path_
circ->deliver_window += CIRCWINDOW_INCREMENT;
if(connection_edge_send_command(NULL, circ, RELAY_COMMAND_SENDME,
NULL, 0, layer_hint) < 0) {
log_fn(LOG_WARN,"connection_edge_send_command failed. Returning.");
log_fn(LOG_WARN,"connection_edge_send_command failed. Circuit's closed.");
return; /* the circuit's closed, don't continue */
}
}
@ -942,7 +940,7 @@ void circuit_n_conn_open(connection_t *or_conn) {
log_fn(LOG_INFO,"send_next_onion_skin failed; circuit marked for closing.");
circuit_close(circ);
continue;
/* XXX could this be bad, eg if next_onion_skin failed because conn died? */
/* XXX could this be bad, eg if next_onion_skin failed because conn died? */
}
}
}
@ -1038,11 +1036,11 @@ int circuit_extend(cell_t *cell, circuit_t *circ) {
n_conn = connection_twin_get_by_addr_port(circ->n_addr,circ->n_port);
if(!n_conn || n_conn->type != CONN_TYPE_OR) {
/* i've disabled making connections through OPs, but it's definitely
* possible here. I'm not sure if it would be a bug or a feature. -RD
*/
/* note also that this will close circuits where the onion has the same
* router twice in a row in the path. i think that's ok. -RD
/* I've disabled making connections through OPs, but it's definitely
* possible here. I'm not sure if it would be a bug or a feature.
*
* Note also that this will close circuits where the onion has the same
* router twice in a row in the path. I think that's ok.
*/
struct in_addr in;
in.s_addr = htonl(circ->n_addr);
@ -1060,7 +1058,7 @@ int circuit_extend(cell_t *cell, circuit_t *circ) {
circ_id_type = decide_circ_id_type(options.Nickname, n_conn->nickname);
log_fn(LOG_DEBUG,"circ_id_type = %u.",circ_id_type);
// log_fn(LOG_DEBUG,"circ_id_type = %u.",circ_id_type);
circ->n_circ_id = get_unique_circ_id_by_conn(circ->n_conn, circ_id_type);
if(!circ->n_circ_id) {
log_fn(LOG_WARN,"failed to get unique circID.");
@ -1108,7 +1106,7 @@ int circuit_finish_handshake(circuit_t *circ, char *reply) {
crypto_dh_free(hop->handshake_state); /* don't need it anymore */
hop->handshake_state = NULL;
log_fn(LOG_INFO,"hop init digest forward %u, backward %u.",
log_fn(LOG_DEBUG,"hop init digest forward %u, backward %u.",
(unsigned)*(uint32_t*)keys, (unsigned)*(uint32_t*)(keys+20));
hop->f_digest = crypto_new_digest_env(CRYPTO_SHA1_DIGEST);
crypto_digest_add_bytes(hop->f_digest, keys, 20);
@ -1130,7 +1128,7 @@ int circuit_finish_handshake(circuit_t *circ, char *reply) {
hop->state = CPATH_STATE_OPEN;
log_fn(LOG_INFO,"finished");
circuit_log_path(LOG_WARN,circ);
circuit_log_path(LOG_INFO,circ);
return 0;
}

View File

@ -32,7 +32,7 @@ static void command_time_process_cell(cell_t *cell, connection_t *conn,
tor_gettimeofday(&end);
time_passed = tv_udiff(&start, &end) ;
if (time_passed > 5000) { /* more than 5ms */
if (time_passed > 10000) { /* more than 10ms */
log_fn(LOG_INFO,"That call just took %ld ms.",time_passed/1000);
}
*time += time_passed;
@ -112,7 +112,7 @@ static void command_process_create_cell(cell_t *cell, connection_t *conn) {
circuit_close(circ);
return;
}
log_fn(LOG_INFO,"success: handed off onionskin.");
log_fn(LOG_DEBUG,"success: handed off onionskin.");
}
static void command_process_created_cell(cell_t *cell, connection_t *conn) {
@ -145,7 +145,7 @@ static void command_process_created_cell(cell_t *cell, connection_t *conn) {
return;
}
} else { /* pack it into an extended relay cell, and send it. */
log_fn(LOG_INFO,"Converting created cell to extended relay cell, sending.");
log_fn(LOG_DEBUG,"Converting created cell to extended relay cell, sending.");
connection_edge_send_command(NULL, circ, RELAY_COMMAND_EXTENDED,
cell->payload, ONIONSKIN_REPLY_LEN, NULL);
}

View File

@ -441,6 +441,7 @@ int getconfig(int argc, char **argv, or_options_t *options) {
if(!cf) {
if(using_default_torrc == 1) {
log(LOG_WARN, "Configuration file '%s' not found. Using defaults.",fname);
/* XXX change this WARN to INFO once we start using this feature */
if(config_assign_default(options) < 0)
return -1;
} else {

View File

@ -407,8 +407,8 @@ int connection_handle_read(connection_t *conn) {
if(connection_read_to_buf(conn) < 0) {
if(conn->type == CONN_TYPE_DIR &&
(conn->state == DIR_CONN_STATE_CONNECTING_FETCH ||
conn->state == DIR_CONN_STATE_CONNECTING_UPLOAD)) {
(conn->state == DIR_CONN_STATE_CONNECTING_FETCH ||
conn->state == DIR_CONN_STATE_CONNECTING_UPLOAD)) {
/* it's a directory server and connecting failed: forget about this router */
/* XXX I suspect pollerr may make Windows not get to this point. :( */
router_mark_as_down(conn->nickname);
@ -512,10 +512,7 @@ int connection_outbuf_too_full(connection_t *conn) {
/* return -1 if you want to break the conn, else return 0 */
int connection_handle_write(connection_t *conn) {
if(connection_is_listener(conn)) {
log_fn(LOG_WARN,"Got a listener socket. Can't happen!");
return -1;
}
assert(!connection_is_listener(conn));
conn->timestamp_lastwritten = time(NULL);
@ -631,7 +628,7 @@ connection_t *connection_twin_get_by_addr_port(uint32_t addr, uint16_t port) {
/* first check if it's there exactly */
conn = connection_exact_get_by_addr_port(addr,port);
if(conn && connection_state_is_open(conn)) {
log(LOG_INFO,"connection_twin_get_by_addr_port(): Found exact match.");
log(LOG_DEBUG,"connection_twin_get_by_addr_port(): Found exact match.");
return conn;
}
@ -647,7 +644,7 @@ connection_t *connection_twin_get_by_addr_port(uint32_t addr, uint16_t port) {
assert(conn);
if(connection_state_is_open(conn) &&
!crypto_pk_cmp_keys(conn->onion_pkey, router->onion_pkey)) {
log(LOG_INFO,"connection_twin_get_by_addr_port(): Found twin (%s).",conn->address);
log(LOG_DEBUG,"connection_twin_get_by_addr_port(): Found twin (%s).",conn->address);
return conn;
}
}
@ -808,7 +805,7 @@ void assert_connection_ok(connection_t *conn, time_t now)
{
assert(conn);
assert(conn->magic == CONNECTION_MAGIC);
return;
return; /* XXX !!! */
assert(conn->type >= _CONN_TYPE_MIN);
assert(conn->type <= _CONN_TYPE_MAX);

View File

@ -145,7 +145,7 @@ int connection_edge_send_command(connection_t *fromconn, circuit_t *circ, int re
int cell_direction;
if(!circ) {
log_fn(LOG_WARN,"no circ. Closing.");
log_fn(LOG_WARN,"no circ. Closing conn.");
assert(fromconn);
connection_mark_for_close(fromconn, 0);
return -1;
@ -212,15 +212,15 @@ int connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ, connection
log_fn(LOG_WARN,"Got 'connected' while not in state connecting. Dropping.");
return 0;
}
log_fn(LOG_INFO,"Connected! Notifying application.");
// log_fn(LOG_INFO,"Connected! Notifying application.");
conn->state = AP_CONN_STATE_OPEN;
if (rh.length >= 4) {
addr = ntohl(*(uint32_t*)(cell->payload + RELAY_HEADER_SIZE));
client_dns_set_entry(conn->socks_request->address, addr);
}
log_fn(LOG_WARN,"'connected' received after %d seconds.",
log_fn(LOG_INFO,"'connected' received after %d seconds.",
(int)(time(NULL) - conn->timestamp_lastread));
circuit_log_path(LOG_WARN,circ);
circuit_log_path(LOG_INFO,circ);
if(connection_ap_handshake_socks_reply(conn, NULL, 0, 1) < 0) {
log_fn(LOG_INFO,"Writing to socks-speaking application failed. Closing.");
connection_mark_for_close(conn, END_STREAM_REASON_MISC);
@ -357,8 +357,12 @@ int connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ, connection
circuit_truncated(circ, layer_hint);
return 0;
case RELAY_COMMAND_CONNECTED:
log_fn(LOG_WARN,"'connected' unsupported while open. Closing.");
return -1;
if(conn) {
log_fn(LOG_WARN,"'connected' unsupported while open. Closing conn.");
return -1;
}
log_fn(LOG_INFO,"'connected' received, no conn attached anymore. Ignoring.");
return 0;
case RELAY_COMMAND_SENDME:
if(!conn) {
if(edge_type == EDGE_AP) {
@ -562,7 +566,7 @@ void connection_ap_attach_pending(void)
conn->state != AP_CONN_STATE_CIRCUIT_WAIT)
continue;
if(connection_ap_handshake_attach_circuit(conn) < 0) {
/* it will never work */
/* -1 means it will never work */
/* Don't send end; there is no 'other end' of the stream */
connection_mark_for_close(conn,0);
}
@ -661,7 +665,7 @@ static int connection_ap_handshake_attach_circuit_helper(connection_t *conn) {
log_fn(LOG_INFO,"No safe circuit ready for edge connection; delaying.");
addr = client_dns_lookup_entry(conn->socks_request->address);
if(router_exit_policy_all_routers_reject(addr, conn->socks_request->port)) {
log_fn(LOG_WARN,"No node exists that will handle exit to %s:%d. Rejecting.",
log_fn(LOG_WARN,"No Tor server exists that allows exit to %s:%d. Rejecting.",
conn->socks_request->address, conn->socks_request->port);
return -1;
}
@ -672,7 +676,7 @@ static int connection_ap_handshake_attach_circuit_helper(connection_t *conn) {
connection_start_reading(conn);
/* here, print the circ's path. so people can figure out which circs are sucking. */
circuit_log_path(LOG_WARN,circ);
circuit_log_path(LOG_INFO,circ);
if(!circ->timestamp_dirty)
circ->timestamp_dirty = time(NULL);
@ -980,6 +984,7 @@ static uint32_t client_dns_lookup_entry(const char *address)
return ent->addr;
}
}
static void client_dns_set_entry(const char *address, uint32_t val)
{
struct client_dns_entry *ent;