[or-cvs] clean up some log messages and severities
Roger Dingledine
arma at seul.org
Sat Feb 28 07:01:24 UTC 2004
Update of /home/or/cvsroot/src/or
In directory moria.mit.edu:/home2/arma/work/onion/cvs/src/or
Modified Files:
buffers.c circuit.c command.c config.c connection.c
connection_edge.c
Log Message:
clean up some log messages and severities
still plenty more left to clean
Index: buffers.c
===================================================================
RCS file: /home/or/cvsroot/src/or/buffers.c,v
retrieving revision 1.64
retrieving revision 1.65
diff -u -d -r1.64 -r1.65
--- buffers.c 28 Feb 2004 05:22:07 -0000 1.64
+++ buffers.c 28 Feb 2004 07:01:22 -0000 1.65
@@ -419,7 +419,6 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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.
Index: circuit.c
===================================================================
RCS file: /home/or/cvsroot/src/or/circuit.c,v
retrieving revision 1.141
retrieving revision 1.142
diff -u -d -r1.141 -r1.142
--- circuit.c 28 Feb 2004 04:48:46 -0000 1.141
+++ circuit.c 28 Feb 2004 07:01:22 -0000 1.142
@@ -323,8 +323,8 @@
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 @@
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 @@
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 @@
}
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 @@
}
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 @@
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 @@
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 @@
/*
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 @@
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 @@
} 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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
hop->state = CPATH_STATE_OPEN;
log_fn(LOG_INFO,"finished");
- circuit_log_path(LOG_WARN,circ);
+ circuit_log_path(LOG_INFO,circ);
return 0;
}
Index: command.c
===================================================================
RCS file: /home/or/cvsroot/src/or/command.c,v
retrieving revision 1.52
retrieving revision 1.53
diff -u -d -r1.52 -r1.53
--- command.c 23 Dec 2003 07:45:31 -0000 1.52
+++ command.c 28 Feb 2004 07:01:22 -0000 1.53
@@ -32,7 +32,7 @@
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 @@
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 @@
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);
}
Index: config.c
===================================================================
RCS file: /home/or/cvsroot/src/or/config.c,v
retrieving revision 1.85
retrieving revision 1.86
diff -u -d -r1.85 -r1.86
--- config.c 28 Feb 2004 05:09:37 -0000 1.85
+++ config.c 28 Feb 2004 07:01:22 -0000 1.86
@@ -441,6 +441,7 @@
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 {
Index: connection.c
===================================================================
RCS file: /home/or/cvsroot/src/or/connection.c,v
retrieving revision 1.159
retrieving revision 1.160
diff -u -d -r1.159 -r1.160
--- connection.c 28 Feb 2004 04:44:48 -0000 1.159
+++ connection.c 28 Feb 2004 07:01:22 -0000 1.160
@@ -407,8 +407,8 @@
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 @@
/* 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 @@
/* 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 @@
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 @@
{
assert(conn);
assert(conn->magic == CONNECTION_MAGIC);
- return;
+ return; /* XXX !!! */
assert(conn->type >= _CONN_TYPE_MIN);
assert(conn->type <= _CONN_TYPE_MAX);
Index: connection_edge.c
===================================================================
RCS file: /home/or/cvsroot/src/or/connection_edge.c,v
retrieving revision 1.99
retrieving revision 1.100
diff -u -d -r1.99 -r1.100
--- connection_edge.c 28 Feb 2004 04:44:48 -0000 1.99
+++ connection_edge.c 28 Feb 2004 07:01:22 -0000 1.100
@@ -145,7 +145,7 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
return ent->addr;
}
}
+
static void client_dns_set_entry(const char *address, uint32_t val)
{
struct client_dns_entry *ent;
More information about the tor-commits
mailing list