r12074@catbus: nickm | 2007-03-04 15:11:43 -0500

Make all LD_BUG log messsages get prefixed with "Bug: ".  Remove manually-generated "Bug: "s from log-messages.  (Apparently, we remembered to add them about 40% of the time.)


svn:r9733
This commit is contained in:
Nick Mathewson 2007-03-04 20:11:46 +00:00
parent 654924dfdf
commit 7fcceb2c25
21 changed files with 65 additions and 56 deletions

View File

@ -3,6 +3,10 @@ Changes in version 0.2.0.1-alpha - 2007-??-??
- Make autoconf search for libevent and openssl consistently.
- Update deprecated macros in configure.in
o Minor features (logging):
- Always prepend "Bug: " to any log message about a bug.
Changes in version 0.1.2.10-rc - 2007-03-??
o Major bugfixes (Windows):
- Do not load the NT services library functions (which may not exist)

View File

@ -424,7 +424,7 @@ Future version:
- when we hit a funny error from a dir request (eg 403 forbidden),
but tor is working and happy otherwise, and we haven't seen many
such errors recently, then don't warn about it.
- LD_BUG log messages could prepend "Bug: " automatically, so we don't
o LD_BUG log messages could prepend "Bug: " automatically, so we don't
have to try to remember to.
- More consistent error checking in router_parse_entry_from_string().
I can say "banana" as my bandwidthcapacity, and it won't even squeak.

View File

@ -96,7 +96,7 @@ static void close_log(logfile_t *victim);
* <b>buf_len</b> character buffer in <b>buf</b>.
*/
static INLINE size_t
_log_prefix(char *buf, size_t buf_len, int severity)
_log_prefix(char *buf, size_t buf_len, int severity, uint32_t domain)
{
time_t t;
struct timeval now;
@ -144,7 +144,7 @@ log_tor_version(logfile_t *lf, int reset)
/* We are resetting, but we aren't at the start of the file; no
* need to log again. */
return 0;
n = _log_prefix(buf, sizeof(buf), LOG_NOTICE);
n = _log_prefix(buf, sizeof(buf), LOG_NOTICE, LD_GENERAL);
tor_snprintf(buf+n, sizeof(buf)-n,
"Tor %s opening %slog file.\n", VERSION, is_new?"new ":"");
if (fputs(buf, lf->file) == EOF ||
@ -170,7 +170,7 @@ format_msg(char *buf, size_t buf_len,
tor_assert(buf_len >= 2); /* prevent integer underflow */
buf_len -= 2; /* subtract 2 characters so we have room for \n\0 */
n = _log_prefix(buf, buf_len, severity);
n = _log_prefix(buf, buf_len, severity, domain);
end_of_prefix = buf+n;
if (funcname && should_log_function_name(domain, severity)) {
@ -181,6 +181,11 @@ format_msg(char *buf, size_t buf_len,
n += r;
}
if (domain == LD_BUG && buf_len-n > 6) {
memcpy(buf+n, "Bug: ", 6);
n += 5;
}
r = tor_vsnprintf(buf+n,buf_len-n,format,ap);
if (r < 0) {
/* The message was too long; overwrite the end of the buffer with

View File

@ -1242,7 +1242,7 @@ write_str_to_file(const char *fname, const char *str, int bin)
#ifdef MS_WINDOWS
if (!bin && strchr(str, '\r')) {
log_warn(LD_BUG,
"Bug: we're writing a text string that already contains a CR.");
"We're writing a text string that already contains a CR.");
}
#endif
return write_bytes_to_file(fname, str, strlen(str), bin);

View File

@ -73,7 +73,7 @@ get_unique_circ_id_by_conn(or_connection_t *conn)
tor_assert(conn);
if (conn->circ_id_type == CIRC_ID_TYPE_NEITHER) {
log_warn(LD_BUG, "Bug: Trying to pick a circuit ID for a connection from "
log_warn(LD_BUG, "Trying to pick a circuit ID for a connection from "
"a client with no identity.");
return 0;
}
@ -803,12 +803,12 @@ circuit_init_cpath_crypto(crypt_path_t *cpath, const char *key_data,
if (!(cpath->f_crypto =
crypto_create_init_cipher(key_data+(2*DIGEST_LEN),1))) {
log_warn(LD_BUG,"Bug: forward cipher initialization failed.");
log_warn(LD_BUG,"Forward cipher initialization failed.");
return -1;
}
if (!(cpath->b_crypto =
crypto_create_init_cipher(key_data+(2*DIGEST_LEN)+CIPHER_KEY_LEN,0))) {
log_warn(LD_BUG,"Bug: backward cipher initialization failed.");
log_warn(LD_BUG,"Backward cipher initialization failed.");
return -1;
}
@ -1342,7 +1342,7 @@ choose_good_exit_server(uint8_t purpose, routerlist_t *dir,
NULL, need_uptime, need_capacity, 0,
options->_AllowInvalid & ALLOW_INVALID_RENDEZVOUS, 0, 0);
}
log_warn(LD_BUG,"Bug: unhandled purpose %d", purpose);
log_warn(LD_BUG,"Unhandled purpose %d", purpose);
tor_fragile_assert();
return NULL;
}

View File

@ -279,7 +279,7 @@ circuit_state_to_string(int state)
case CIRCUIT_STATE_OR_WAIT: return "connecting to server";
case CIRCUIT_STATE_OPEN: return "open";
default:
log_warn(LD_BUG, "Bug: unknown circuit state %d", state);
log_warn(LD_BUG, "Unknown circuit state %d", state);
tor_snprintf(buf, sizeof(buf), "unknown state [%d]", state);
return buf;
}

View File

@ -849,7 +849,7 @@ circuit_launch_by_extend_info(uint8_t purpose, int onehop_tunnel,
break;
default:
log_warn(LD_BUG,
"Bug: unexpected purpose %d when cannibalizing a circ.",
"unexpected purpose %d when cannibalizing a circ.",
purpose);
tor_fragile_assert();
return NULL;

View File

@ -890,7 +890,7 @@ options_act(or_options_t *old_options)
for (cl = options->DirServers; cl; cl = cl->next) {
if (parse_dir_server_line(cl->value, 0)<0) {
log_err(LD_BUG,
"Bug: Previously validated DirServer line could not be added!");
"Previously validated DirServer line could not be added!");
return -1;
}
}
@ -900,7 +900,7 @@ options_act(or_options_t *old_options)
if (running_tor && rend_config_services(options, 0)<0) {
log_err(LD_BUG,
"Bug: Previously validated hidden services line could not be added!");
"Previously validated hidden services line could not be added!");
return -1;
}
@ -1561,7 +1561,7 @@ get_assigned_option(config_format_t *fmt, or_options_t *options,
default:
tor_free(result->key);
tor_free(result);
log_warn(LD_BUG,"Bug: unknown type %d for known key '%s'",
log_warn(LD_BUG,"Unknown type %d for known key '%s'",
var->type, key);
return NULL;
}
@ -2106,7 +2106,7 @@ options_dup(config_format_t *fmt, or_options_t *old)
if (line) {
char *msg = NULL;
if (config_assign(fmt, newopts, line, 0, 0, &msg) < 0) {
log_err(LD_BUG, "Bug: config_get_assigned_option() generated "
log_err(LD_BUG, "Config_get_assigned_option() generated "
"something we couldn't config_assign(): %s", msg);
tor_free(msg);
tor_assert(0);

View File

@ -56,7 +56,7 @@ conn_type_to_string(int type)
case CONN_TYPE_CONTROL_LISTENER: return "Control listener";
case CONN_TYPE_CONTROL: return "Control";
default:
log_warn(LD_BUG, "Bug: unknown connection type %d", type);
log_warn(LD_BUG, "unknown connection type %d", type);
tor_snprintf(buf, sizeof(buf), "unknown [%d]", type);
return buf;
}
@ -142,7 +142,7 @@ conn_state_to_string(int type, int state)
break;
}
log_warn(LD_BUG, "Bug: unknown connection state %d (type %d)", state, type);
log_warn(LD_BUG, "unknown connection state %d (type %d)", state, type);
tor_snprintf(buf, sizeof(buf),
"unknown state [%d] on unknown [%s] connection",
state, conn_type_to_string(type));
@ -408,7 +408,7 @@ connection_about_to_close_connection(connection_t *conn)
if (CONN_IS_EDGE(conn)) {
if (!conn->edge_has_sent_end) {
log_warn(LD_BUG, "Harmless bug: Edge connection (marked at %s:%d) "
log_warn(LD_BUG, "(Harmless.) Edge connection (marked at %s:%d) "
"hasn't sent end yet?",
conn->marked_for_close_file, conn->marked_for_close);
tor_fragile_assert();
@ -472,12 +472,12 @@ connection_about_to_close_connection(connection_t *conn)
if (edge_conn->socks_request->has_finished == 0) {
/* since conn gets removed right after this function finishes,
* there's no point trying to send back a reply at this point. */
log_warn(LD_BUG,"Bug: Closing stream (marked at %s:%d) without sending"
log_warn(LD_BUG,"Closing stream (marked at %s:%d) without sending"
" back a socks reply.",
conn->marked_for_close_file, conn->marked_for_close);
}
if (!edge_conn->end_reason) {
log_warn(LD_BUG,"Bug: Closing stream (marked at %s:%d) without having"
log_warn(LD_BUG,"Closing stream (marked at %s:%d) without having"
" set end_reason.",
conn->marked_for_close_file, conn->marked_for_close);
}
@ -516,7 +516,7 @@ connection_close_immediate(connection_t *conn)
{
assert_connection_ok(conn,0);
if (conn->s < 0) {
log_err(LD_BUG,"Bug: Attempt to close already-closed connection.");
log_err(LD_BUG,"Attempt to close already-closed connection.");
tor_fragile_assert();
return;
}
@ -1543,7 +1543,7 @@ connection_read_to_buf(connection_t *conn, int *max_to_read)
* believing that SSL bytes are the same as TCP bytes anyway. */
int r2 = read_to_buf_tls(or_conn->tls, pending, conn->inbuf);
if (r2<0) {
log_warn(LD_BUG, "Bug: apparently, reading pending bytes can fail.");
log_warn(LD_BUG, "apparently, reading pending bytes can fail.");
return -1;
} else {
result += r2;
@ -1896,7 +1896,7 @@ _connection_write_to_buf_impl(const char *string, size_t len,
if (connection_handle_write(conn, 0) < 0) {
if (!conn->marked_for_close) {
/* this connection is broken. remove it. */
log_warn(LD_BUG, "Bug: unhandled error on write for "
log_warn(LD_BUG, "unhandled error on write for "
"conn (type %d, fd %d); removing",
conn->type, conn->s);
tor_fragile_assert();
@ -2253,7 +2253,7 @@ connection_process_inbuf(connection_t *conn, int package_partial)
case CONN_TYPE_CONTROL:
return connection_control_process_inbuf(TO_CONTROL_CONN(conn));
default:
log_err(LD_BUG,"Bug: got unexpected conn type %d.", conn->type);
log_err(LD_BUG,"got unexpected conn type %d.", conn->type);
tor_fragile_assert();
return -1;
}
@ -2300,7 +2300,7 @@ connection_finished_flushing(connection_t *conn)
case CONN_TYPE_CONTROL:
return connection_control_finished_flushing(TO_CONTROL_CONN(conn));
default:
log_err(LD_BUG,"Bug: got unexpected conn type %d.", conn->type);
log_err(LD_BUG,"got unexpected conn type %d.", conn->type);
tor_fragile_assert();
return -1;
}
@ -2325,7 +2325,7 @@ connection_finished_connecting(connection_t *conn)
case CONN_TYPE_DIR:
return connection_dir_finished_connecting(TO_DIR_CONN(conn));
default:
log_err(LD_BUG,"Bug: got unexpected conn type %d.", conn->type);
log_err(LD_BUG,"got unexpected conn type %d.", conn->type);
tor_fragile_assert();
return -1;
}
@ -2350,7 +2350,7 @@ connection_reached_eof(connection_t *conn)
case CONN_TYPE_CONTROL:
return connection_control_reached_eof(TO_CONTROL_CONN(conn));
default:
log_err(LD_BUG,"Bug: got unexpected conn type %d.", conn->type);
log_err(LD_BUG,"got unexpected conn type %d.", conn->type);
tor_fragile_assert();
return -1;
}

View File

@ -52,7 +52,7 @@ _connection_mark_unattached_ap(edge_connection_t *conn, int endreason,
if (!conn->socks_request->has_finished) {
if (endreason & END_STREAM_REASON_FLAG_ALREADY_SOCKS_REPLIED)
log_warn(LD_BUG,
"Bug: stream (marked at %s:%d) sending two socks replies?",
"stream (marked at %s:%d) sending two socks replies?",
file, line);
if (SOCKS_COMMAND_IS_CONNECT(conn->socks_request->command))
@ -138,7 +138,7 @@ connection_edge_process_inbuf(edge_connection_t *conn, int package_partial)
conn_state_to_string(conn->_base.type, conn->_base.state));
return 0;
}
log_warn(LD_BUG,"Bug: Got unexpected state %d. Closing.",conn->_base.state);
log_warn(LD_BUG,"Got unexpected state %d. Closing.",conn->_base.state);
tor_fragile_assert();
connection_edge_end(conn, END_STREAM_REASON_INTERNAL, conn->cpath_layer);
connection_mark_for_close(TO_CONN(conn));
@ -190,7 +190,7 @@ connection_edge_end(edge_connection_t *conn, char reason,
circuit_t *circ;
if (conn->_base.edge_has_sent_end) {
log_warn(LD_BUG,"Harmless bug: Calling connection_edge_end (reason %d) "
log_warn(LD_BUG,"(Harmless.) Calling connection_edge_end (reason %d) "
"on an already ended stream?", reason);
tor_fragile_assert();
return -1;
@ -198,7 +198,7 @@ connection_edge_end(edge_connection_t *conn, char reason,
if (conn->_base.marked_for_close) {
log_warn(LD_BUG,
"Bug: called on conn that's already marked for close at %s:%d.",
"called on conn that's already marked for close at %s:%d.",
conn->_base.marked_for_close_file, conn->_base.marked_for_close);
return 0;
}
@ -269,7 +269,7 @@ connection_edge_finished_flushing(edge_connection_t *conn)
connection_stop_writing(TO_CONN(conn));
return 0;
default:
log_warn(LD_BUG,"BUG: called in unexpected state %d.",conn->_base.state);
log_warn(LD_BUG, "Called in unexpected state %d.",conn->_base.state);
tor_fragile_assert();
return -1;
}
@ -1384,7 +1384,7 @@ connection_ap_handshake_rewrite_and_attach(edge_connection_t *conn,
/* see if we already have it cached */
r = rend_cache_lookup_entry(conn->rend_query, -1, &entry);
if (r<0) {
log_warn(LD_BUG,"Bug: Invalid service name '%s'",
log_warn(LD_BUG,"Invalid service name '%s'",
safe_str(conn->rend_query));
connection_mark_unattached_ap(conn, END_STREAM_REASON_TORPROTOCOL);
return -1;
@ -2038,7 +2038,7 @@ connection_ap_handshake_socks_reply(edge_connection_t *conn, char *reply,
endreason);
if (conn->socks_request->has_finished) {
log_warn(LD_BUG, "Harmless bug: duplicate calls to "
log_warn(LD_BUG, "(Harmless.) duplicate calls to "
"connection_ap_handshake_socks_reply.");
return;
}
@ -2390,7 +2390,7 @@ connection_exit_connect(edge_connection_t *edge_conn)
conn->state = EXIT_CONN_STATE_OPEN;
if (connection_wants_to_flush(conn)) {
/* in case there are any queued data cells */
log_warn(LD_BUG,"Bug: newly connected conn had data waiting!");
log_warn(LD_BUG,"newly connected conn had data waiting!");
// connection_start_writing(conn);
}
connection_watch_events(conn, EV_READ);

View File

@ -37,7 +37,7 @@ connection_or_remove_from_identity_map(or_connection_t *conn)
tmp = digestmap_get(orconn_identity_map, conn->identity_digest);
if (!tmp) {
if (!tor_digest_is_zero(conn->identity_digest)) {
log_warn(LD_BUG, "Bug: Didn't find connection on identity map when "
log_warn(LD_BUG, "Didn't find connection on identity map when "
"trying to remove it.");
}
return;
@ -267,7 +267,7 @@ connection_or_finished_flushing(or_connection_t *conn)
connection_stop_writing(TO_CONN(conn));
break;
default:
log_err(LD_BUG,"BUG: called in unexpected state %d.", conn->_base.state);
log_err(LD_BUG,"Called in unexpected state %d.", conn->_base.state);
tor_fragile_assert();
return -1;
}

View File

@ -425,7 +425,7 @@ cull_wedged_cpuworkers(void)
conn->state == CPUWORKER_STATE_BUSY_ONION &&
conn->timestamp_lastwritten + CPUWORKER_BUSY_TIMEOUT < now) {
log_notice(LD_BUG,
"Bug: closing wedged cpuworker. Can somebody find the bug?");
"closing wedged cpuworker. Can somebody find the bug?");
num_cpuworkers_busy--;
num_cpuworkers--;
connection_mark_for_close(conn);

View File

@ -597,7 +597,7 @@ directory_send_command(dir_connection_t *conn,
if (strlen(proxystring) + strlen(url) >= 4096) {
log_warn(LD_BUG,
"Bug: squid does not like URLs longer than 4095 bytes, this "
"Squid does not like URLs longer than 4095 bytes, this "
"one is %d bytes long: %s%s",
(int)(strlen(proxystring) + strlen(url)), proxystring, url);
}
@ -1362,7 +1362,7 @@ write_http_status_line(dir_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_warn(LD_BUG,"Bug: status line too long.");
log_warn(LD_BUG,"status line too long.");
return;
}
connection_write_to_buf(buf, strlen(buf), TO_CONN(conn));
@ -1966,7 +1966,7 @@ connection_dir_finished_flushing(dir_connection_t *conn)
connection_mark_for_close(TO_CONN(conn));
return 0;
default:
log_warn(LD_BUG,"Bug: called in unexpected state %d.",
log_warn(LD_BUG,"called in unexpected state %d.",
conn->_base.state);
tor_fragile_assert();
return -1;

View File

@ -848,7 +848,7 @@ dns_cancel_pending_resolve(const char *address)
if (!resolve->pending_connections) {
/* XXX this should never trigger, but sometimes it does */
log_warn(LD_BUG,
"Bug: Address %s is pending but has no pending connections!",
"Address %s is pending but has no pending connections!",
escaped_safe_str(address));
tor_fragile_assert();
return;
@ -1165,7 +1165,7 @@ connection_dns_process_inbuf(connection_t *conn)
if (conn->state != DNSWORKER_STATE_BUSY && buf_datalen(conn->inbuf)) {
log_warn(LD_BUG,
"Bug: read data (%d bytes) from an idle dns worker (fd %d, "
"read data (%d bytes) from an idle dns worker (fd %d, "
"address %s). Please report.", (int)buf_datalen(conn->inbuf),
conn->s, escaped_safe_str(conn->address));
tor_fragile_assert();
@ -1680,7 +1680,7 @@ launch_resolve(edge_connection_t *exitconn, or_circuit_t *circ)
: DNS_QUERY_NO_SEARCH;
/* What? Nameservers not configured? Sounds like a bug. */
if (!nameservers_configured) {
log_warn(LD_EXIT, "Harmless bug: nameservers not configured, but resolve "
log_warn(LD_EXIT, "(Harmless.) Nameservers not configured, but resolve "
"launched. Configuring.");
if (configure_nameservers(1) < 0)
return -1;

View File

@ -422,7 +422,7 @@ conn_read_callback(int fd, short event, void *_conn)
if (connection_handle_read(conn) < 0) {
if (!conn->marked_for_close) {
#ifndef MS_WINDOWS
log_warn(LD_BUG,"Bug: unhandled error on read for %s connection "
log_warn(LD_BUG,"Unhandled error on read for %s connection "
"(fd %d); removing",
conn_type_to_string(conn->type), conn->s);
tor_fragile_assert();
@ -456,7 +456,7 @@ conn_write_callback(int fd, short events, void *_conn)
if (!conn->marked_for_close) {
/* this connection is broken. remove it. */
log_fn(LOG_WARN,LD_BUG,
"Bug: unhandled error on write for %s connection (fd %d); removing",
"unhandled error on write for %s connection (fd %d); removing",
conn_type_to_string(conn->type), conn->s);
tor_fragile_assert();
if (CONN_IS_EDGE(conn)) {

View File

@ -520,7 +520,7 @@ connection_edge_send_command(edge_connection_t *fromconn, circuit_t *circ,
if (fromconn && fromconn->_base.marked_for_close) {
log_warn(LD_BUG,
"Bug: called on conn that's already marked for close at %s:%d.",
"called on conn that's already marked for close at %s:%d.",
fromconn->_base.marked_for_close_file,
fromconn->_base.marked_for_close);
return 0;
@ -1064,7 +1064,7 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ,
conn->stream_id);
if (conn->socks_request && !conn->socks_request->has_finished)
log_warn(LD_BUG,
"Bug: open stream hasn't sent socks answer yet? Closing.");
"open stream hasn't sent socks answer yet? Closing.");
/* We just *got* an end; no reason to send one. */
conn->_base.edge_has_sent_end = 1;
if (!conn->end_reason)
@ -1234,7 +1234,7 @@ connection_edge_package_raw_inbuf(edge_connection_t *conn, int package_partial)
if (conn->_base.marked_for_close) {
log_warn(LD_BUG,
"Bug: called on conn that's already marked for close at %s:%d.",
"called on conn that's already marked for close at %s:%d.",
conn->_base.marked_for_close_file, conn->_base.marked_for_close);
return 0;
}

View File

@ -280,7 +280,7 @@ rend_client_remove_intro_point(extend_info_t *failed_intro, const char *query)
r = rend_cache_lookup_entry(query, -1, &ent);
if (r<0) {
log_warn(LD_BUG, "Bug: malformed service ID %s.", escaped_safe_str(query));
log_warn(LD_BUG, "Malformed service ID %s.", escaped_safe_str(query));
return -1;
}
if (r==0) {

View File

@ -359,7 +359,7 @@ rend_service_load_keys(void)
return -1;
}
if (crypto_pk_get_digest(s->private_key, s->pk_digest)<0) {
log_warn(LD_BUG, "Bug: Couldn't compute hash of public key.");
log_warn(LD_BUG, "Couldn't compute hash of public key.");
return -1;
}
if (strlcpy(fname,s->directory,sizeof(fname)) >= sizeof(fname) ||

View File

@ -944,7 +944,7 @@ router_rebuild_descriptor(int force)
ri->cache_info.signed_descriptor_body = tor_malloc(8192);
if (router_dump_router_to_string(ri->cache_info.signed_descriptor_body, 8192,
ri, get_identity_key())<0) {
log_warn(LD_BUG, "Bug: Couldn't generate router descriptor.");
log_warn(LD_BUG, "Couldn't generate router descriptor.");
return -1;
}
ri->cache_info.signed_descriptor_len =

View File

@ -287,7 +287,7 @@ router_rebuild_store(int force)
sized_chunk_t *c;
const char *body = signed_descriptor_get_body(sd);
if (!body) {
log_warn(LD_BUG, "Bug! No descriptor available for router.");
log_warn(LD_BUG, "No descriptor available for router.");
goto done;
}
c = tor_malloc(sizeof(sized_chunk_t));
@ -4061,7 +4061,7 @@ update_router_descriptor_cache_downloads(time_t now)
continue;
if (router_get_by_descriptor_digest(rs->descriptor_digest)) {
log_warn(LD_BUG,
"Bug: We have a router descriptor, but need_to_mirror=1.");
"We have a router descriptor, but need_to_mirror=1.");
rs->need_to_mirror = 0;
continue;
}

View File

@ -1806,7 +1806,7 @@ tor_version_as_new_as(const char *platform, const char *cutoff)
tor_assert(platform);
if (tor_version_parse(cutoff, &cutoff_version)<0) {
log_warn(LD_DIR,"Bug: cutoff version '%s' unparseable.",cutoff);
log_warn(LD_BUG,"cutoff version '%s' unparseable.",cutoff);
return 0;
}
if (strcmpstart(platform,"Tor ")) /* nonstandard Tor; be safe and say yes */