From 049f6c01310006e9c30fedd46ecda44b7d1d5570 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Tue, 25 Oct 2005 17:52:14 +0000 Subject: Switch remaining files to new log interface. svn:r5315 --- src/common/log.h | 2 + src/or/dirserv.c | 134 ++++++++++++++++++++++++++++------------------------- src/or/dns.c | 84 +++++++++++++++++---------------- src/or/hibernate.c | 75 +++++++++++++++--------------- 4 files changed, 155 insertions(+), 140 deletions(-) (limited to 'src') diff --git a/src/common/log.h b/src/common/log.h index ac0c5b76bb..11a959b6d7 100644 --- a/src/common/log.h +++ b/src/common/log.h @@ -87,6 +87,8 @@ /** Generic edge-connection functionality. */ #define LD_EDGE (1u<<16) #define LD_EXIT LD_EDGE +/** Bandwidth accounting. */ +#define LD_ACCT (1u<<17) typedef void (*log_callback)(int severity, unsigned int domain, const char *msg); diff --git a/src/or/dirserv.c b/src/or/dirserv.c index 077f06b10f..5a13b151c7 100644 --- a/src/or/dirserv.c +++ b/src/or/dirserv.c @@ -4,6 +4,7 @@ /* $Id$ */ const char dirserv_c_id[] = "$Id$"; +#define NEW_LOG_INTERFACE #include "or.h" /** @@ -135,7 +136,7 @@ dirserv_add_own_fingerprint(const char *nickname, crypto_pk_env_t *pk) { char fp[FINGERPRINT_LEN+1]; if (crypto_pk_get_fingerprint(pk, fp, 0)<0) { - log_fn(LOG_ERR, "Error computing fingerprint"); + err(LD_BUG, "Error computing fingerprint"); return -1; } if (!fingerprint_list) @@ -161,13 +162,13 @@ dirserv_parse_fingerprint_file(const char *fname) cf = read_file_to_str(fname, 0); if (!cf) { - log_fn(LOG_WARN, "Cannot open fingerprint file %s", fname); + warn(LD_FS, "Cannot open fingerprint file %s", fname); return -1; } result = config_get_lines(cf, &front); tor_free(cf); if (result < 0) { - log_fn(LOG_WARN, "Error reading from fingerprint file"); + warn(LD_CONFIG, "Error reading from fingerprint file"); return -1; } @@ -176,31 +177,34 @@ dirserv_parse_fingerprint_file(const char *fname) for (list=front; list; list=list->next) { nickname = list->key; fingerprint = list->value; if (strlen(nickname) > MAX_NICKNAME_LEN) { - log(LOG_NOTICE, "Nickname '%s' too long in fingerprint file. Skipping.", nickname); + notice(LD_CONFIG, + "Nickname '%s' too long in fingerprint file. Skipping.", nickname); continue; } if (!is_legal_nickname(nickname) && strcasecmp(nickname, "!reject") && strcasecmp(nickname, "!invalid")) { - log(LOG_NOTICE, "Invalid nickname '%s' in fingerprint file. Skipping.", nickname); + notice(LD_CONFIG, + "Invalid nickname '%s' in fingerprint file. Skipping.", nickname); continue; } if (strlen(fingerprint) != FINGERPRINT_LEN || !crypto_pk_check_fingerprint_syntax(fingerprint)) { - log_fn(LOG_NOTICE, "Invalid fingerprint (nickname '%s', fingerprint %s). Skipping.", + notice(LD_CONFIG, + "Invalid fingerprint (nickname '%s', fingerprint %s). Skipping.", nickname, fingerprint); continue; } if (0==strcasecmp(nickname, DEFAULT_CLIENT_NICKNAME)) { /* If you approved an OR called "client", then clients who use * the default nickname could all be rejected. That's no good. */ - log(LOG_NOTICE, + notice(LD_CONFIG, "Authorizing a nickname '%s' would break many clients; skipping.", DEFAULT_CLIENT_NICKNAME); continue; } if (add_fingerprint_to_dir(nickname, fingerprint, fingerprint_list_new) != 0) - log(LOG_NOTICE, "Duplicate nickname '%s'.", nickname); + notice(LD_CONFIG, "Duplicate nickname '%s'.", nickname); } config_free_lines(front); @@ -228,11 +232,11 @@ dirserv_router_get_status(const routerinfo_t *router, const char **msg) fingerprint_list = smartlist_create(); if (crypto_pk_get_fingerprint(router->identity_pkey, fp, 0)) { - log_fn(LOG_WARN,"Error computing fingerprint"); + warn(LD_BUG,"Error computing fingerprint"); return -1; } - log_fn(LOG_DEBUG, "%d fingerprints known.", smartlist_len(fingerprint_list)); + debug(LD_DIRSERV, "%d fingerprints known.", smartlist_len(fingerprint_list)); SMARTLIST_FOREACH(fingerprint_list, fingerprint_entry_t *, ent, { if (!strcasecmp(fp,ent->fingerprint)) @@ -260,32 +264,32 @@ dirserv_router_get_status(const routerinfo_t *router, const char **msg) router->addr, router->or_port, authdir_invalid_policy); if (rej == ADDR_POLICY_PROBABLY_REJECTED || rej == ADDR_POLICY_REJECTED) { - log_fn(LOG_INFO, "Rejecting '%s' because of address %s", - router->nickname, router->address); + info(LD_DIRSERV, "Rejecting '%s' because of address %s", + router->nickname, router->address); if (msg) *msg = "Authdir is rejecting routers in this range."; return FP_REJECT; } if (inv == ADDR_POLICY_PROBABLY_REJECTED || inv == ADDR_POLICY_REJECTED) { - log_fn(LOG_INFO, "Not marking '%s' valid because of address %s", - router->nickname, router->address); + info(LD_DIRSERV, "Not marking '%s' valid because of address %s", + router->nickname, router->address); return FP_INVALID; } if (tor_version_as_new_as(router->platform,"0.1.0.2-rc")) return FP_VALID; else return FP_INVALID; - log_fn(LOG_INFO,"No fingerprint found for '%s'",router->nickname); + info(LD_DIRSERV,"No fingerprint found for '%s'",router->nickname); return 0; } if (0==strcasecmp(nn_ent->fingerprint, fp)) { - log_fn(LOG_DEBUG,"Good fingerprint for '%s'",router->nickname); + debug(LD_DIRSERV,"Good fingerprint for '%s'",router->nickname); return FP_NAMED; /* Right fingerprint. */ } else { - log_fn(LOG_WARN,"Mismatched fingerprint for '%s': expected '%s' got '%s'. ContactInfo '%s', platform '%s'.)", - router->nickname, nn_ent->fingerprint, fp, - router->contact_info ? router->contact_info : "", - router->platform ? router->platform : ""); + warn(LD_DIRSERV,"Mismatched fingerprint for '%s': expected '%s' got '%s'. ContactInfo '%s', platform '%s'.)", + router->nickname, nn_ent->fingerprint, fp, + router->contact_info ? router->contact_info : "", + router->platform ? router->platform : ""); if (msg) *msg = "Rejected: There is already a verified server with this nickname and a different fingerprint."; return FP_REJECT; /* Wrong fingerprint. */ @@ -342,13 +346,14 @@ dirserv_router_has_valid_address(routerinfo_t *ri) if (get_options()->DirAllowPrivateAddresses) return 0; /* whatever it is, we're fine with it */ if (!tor_inet_aton(ri->address, &iaddr)) { - log_fn(LOG_INFO,"Router '%s' published non-IP address '%s'. Refusing.", - ri->nickname, ri->address); + info(LD_DIRSERV,"Router '%s' published non-IP address '%s'. Refusing.", + ri->nickname, ri->address); return -1; } if (is_internal_IP(ntohl(iaddr.s_addr))) { - log_fn(LOG_INFO,"Router '%s' published internal IP address '%s'. Refusing.", - ri->nickname, ri->address); + info(LD_DIRSERV, + "Router '%s' published internal IP address '%s'. Refusing.", + ri->nickname, ri->address); return -1; /* it's a private IP, we should reject it */ } return 0; @@ -373,7 +378,7 @@ authdir_wants_to_reject_router(routerinfo_t *ri, /* Is there too much clock skew? */ now = time(NULL); if (ri->published_on > now+ROUTER_ALLOW_SKEW) { - log_fn(LOG_NOTICE, "Publication time for nickname '%s' is too far (%d minutes) in the future; possible clock skew. Not adding (ContactInfo '%s', platform '%s').", + notice(LD_DIRSERV, "Publication time for nickname '%s' is too far (%d minutes) in the future; possible clock skew. Not adding (ContactInfo '%s', platform '%s').", ri->nickname, (int)((ri->published_on-now)/60), ri->contact_info ? ri->contact_info : "", ri->platform ? ri->platform : ""); @@ -381,7 +386,7 @@ authdir_wants_to_reject_router(routerinfo_t *ri, return -1; } if (ri->published_on < now-ROUTER_MAX_AGE) { - log_fn(LOG_NOTICE, "Publication time for router with nickname '%s' is too far (%d minutes) in the past. Not adding (ContactInfo '%s', platform '%s').", + notice(LD_DIRSERV, "Publication time for router with nickname '%s' is too far (%d minutes) in the past. Not adding (ContactInfo '%s', platform '%s').", ri->nickname, (int)((now-ri->published_on)/60), ri->contact_info ? ri->contact_info : "", ri->platform ? ri->platform : ""); @@ -389,7 +394,7 @@ authdir_wants_to_reject_router(routerinfo_t *ri, return -1; } if (dirserv_router_has_valid_address(ri) < 0) { - log_fn(LOG_NOTICE, "Router with nickname '%s' has invalid address '%s'. Not adding (ContactInfo '%s', platform '%s').", + notice(LD_DIRSERV, "Router with nickname '%s' has invalid address '%s'. Not adding (ContactInfo '%s', platform '%s').", ri->nickname, ri->address, ri->contact_info ? ri->contact_info : "", ri->platform ? ri->platform : ""); @@ -436,7 +441,7 @@ dirserv_add_descriptor(const char *desc, const char **msg) /* Check: is the descriptor syntactically valid? */ ri = router_parse_entry_from_string(desc, NULL); if (!ri) { - log(LOG_WARN, "Couldn't parse descriptor"); + warn(LD_DIRSERV, "Couldn't parse uploaded server descriptor"); *msg = "Rejected: Couldn't parse server descriptor."; return -2; } @@ -447,9 +452,9 @@ dirserv_add_descriptor(const char *desc, const char **msg) ri_old = router_get_by_digest(ri->identity_digest); if (ri_old && ri_old->published_on < ri->published_on && router_differences_are_cosmetic(ri_old, ri)) { - log_fn(LOG_INFO, - "Not replacing descriptor from '%s'; differences are cosmetic.", - ri->nickname); + info(LD_DIRSERV, + "Not replacing descriptor from '%s'; differences are cosmetic.", + ri->nickname); *msg = "Not replacing router descriptor; no information has changed since the last one with this identity."; return 0; } @@ -485,7 +490,7 @@ directory_remove_invalid(void) router_status_t r = dirserv_router_get_status(ent, &msg); switch (r) { case FP_REJECT: - log(LOG_INFO, "Router '%s' is now rejected: %s", + info(LD_DIRSERV, "Router '%s' is now rejected: %s", ent->nickname, msg?msg:""); routerlist_remove(rl, ent, i--); routerinfo_free(ent); @@ -493,14 +498,15 @@ directory_remove_invalid(void) break; case FP_NAMED: if (!ent->is_verified || !ent->is_named) { - log(LOG_INFO, "Router '%s' is now verified and named.", ent->nickname); + info(LD_DIRSERV, + "Router '%s' is now verified and named.", ent->nickname); ent->is_verified = ent->is_named = 1; changed = 1; } break; case FP_VALID: if (!ent->is_verified || ent->is_named) { - log(LOG_INFO, "Router '%s' is now verified.", ent->nickname); + info(LD_DIRSERV, "Router '%s' is now verified.", ent->nickname); ent->is_verified = 1; ent->is_named = 0; changed = 1; @@ -508,7 +514,8 @@ directory_remove_invalid(void) break; case FP_INVALID: if (ent->is_verified || ent->is_named) { - log(LOG_INFO, "Router '%s' is no longer verified.", ent->nickname); + info(LD_DIRSERV, + "Router '%s' is no longer verified.", ent->nickname); ent->is_verified = ent->is_named = 0; changed = 1; } @@ -745,7 +752,7 @@ dirserv_dump_directory_to_string(char **dir_out, if (crypto_pk_write_public_key_to_string(private_key,&identity_pkey, &identity_pkey_len)<0) { - log_fn(LOG_WARN,"write identity_pkey to string failed!"); + warn(LD_BUG,"write identity_pkey to string failed!"); return -1; } @@ -800,7 +807,7 @@ dirserv_dump_directory_to_string(char **dir_out, goto truncated; if (router_get_dir_hash(buf,digest)) { - log_fn(LOG_WARN,"couldn't compute digest"); + warn(LD_BUG,"couldn't compute digest"); tor_free(buf); return -1; } @@ -812,7 +819,7 @@ dirserv_dump_directory_to_string(char **dir_out, *dir_out = buf; return 0; truncated: - log_fn(LOG_WARN,"tried to exceed string length."); + warn(LD_BUG,"tried to exceed string length."); tor_free(buf); return -1; } @@ -840,21 +847,21 @@ set_cached_dir(cached_dir_t *d, char *directory, time_t when) { time_t now = time(NULL); if (when<=d->published) { - log_fn(LOG_INFO, "Ignoring old directory; not caching."); + info(LD_DIRSERV, "Ignoring old directory; not caching."); tor_free(directory); } else if (when>=now+ROUTER_MAX_AGE) { - log_fn(LOG_INFO, "Ignoring future directory; not caching."); + info(LD_DIRSERV, "Ignoring future directory; not caching."); tor_free(directory); } else { /* if (when>d->published && whendir); d->dir = directory; d->dir_len = strlen(directory); tor_free(d->dir_z); if (tor_gzip_compress(&(d->dir_z), &(d->dir_z_len), d->dir, d->dir_len, ZLIB_METHOD)) { - log_fn(LOG_WARN,"Error compressing cached directory"); + warn(LD_BUG,"Error compressing cached directory"); } d->published = when; } @@ -943,11 +950,11 @@ dirserv_pick_cached_dir_obj(cached_dir_t *cache_src, if (regenerate != NULL) { if (dirty && dirty + DIR_REGEN_SLACK_TIME < time(NULL)) { if (regenerate()) { - log_fn(LOG_ERR, "Couldn't generate %s?", name); + err(LD_BUG, "Couldn't generate %s?", name); exit(1); } } else { - log_fn(LOG_INFO, "The %s is still clean; reusing.", name); + info(LD_DIRSERV, "The %s is still clean; reusing.", name); } } return auth_src ? auth_src : cache_src; @@ -1011,13 +1018,13 @@ dirserv_regenerate_directory(void) if (dirserv_dump_directory_to_string(&new_directory, get_identity_key())) { - log(LOG_WARN, "Error creating directory."); + warn(LD_BUG, "Error creating directory."); tor_free(new_directory); return -1; } set_cached_dir(&the_directory, new_directory, time(NULL)); - log_fn(LOG_INFO,"New directory (size %d) has been built.",(int)the_directory.dir_len); - log_fn(LOG_DEBUG,"New directory (size %d):\n%s",(int)the_directory.dir_len, + info(LD_DIRSERV,"New directory (size %d) has been built.",(int)the_directory.dir_len); + debug(LD_DIRSERV,"New directory (size %d):\n%s",(int)the_directory.dir_len, the_directory.dir); the_directory_is_dirty = 0; @@ -1051,7 +1058,7 @@ generate_runningrouters(void) } if (crypto_pk_write_public_key_to_string(private_key,&identity_pkey, &identity_pkey_len)<0) { - log_fn(LOG_WARN,"write identity_pkey to string failed!"); + warn(LD_BUG,"write identity_pkey to string failed!"); goto err; } format_iso_time(published, time(NULL)); @@ -1068,7 +1075,7 @@ generate_runningrouters(void) tor_free(router_status); tor_free(identity_pkey); if (router_get_runningrouters_hash(s,digest)) { - log_fn(LOG_WARN,"couldn't compute digest"); + warn(LD_BUG,"couldn't compute digest"); goto err; } if (router_append_dirobj_signature(s, len, digest, private_key)<0) @@ -1162,7 +1169,7 @@ generate_v2_networkstatus(void) const char *contact; if (resolve_my_address(options, &addr, &hostname)<0) { - log_fn(LOG_WARN, "Couldn't resolve my hostname"); + warn(LD_NET, "Couldn't resolve my hostname"); goto done; } in.s_addr = htonl(addr); @@ -1175,12 +1182,12 @@ generate_v2_networkstatus(void) if (crypto_pk_write_public_key_to_string(private_key, &identity_pkey, &identity_pkey_len)<0) { - log_fn(LOG_WARN,"Writing public key to string failed."); + warn(LD_BUG,"Writing public key to string failed."); goto done; } if (crypto_pk_get_fingerprint(private_key, fingerprint, 0)<0) { - log_fn(LOG_ERR, "Error computing fingerprint"); + err(LD_BUG, "Error computing fingerprint"); goto done; } @@ -1254,25 +1261,25 @@ generate_v2_networkstatus(void) f_stable?" Stable":"", f_running?" Running":"", f_valid?" Valid":"")<0) { - log_fn(LOG_WARN, "Unable to print router status."); + warn(LD_BUG, "Unable to print router status."); goto done; - } + } outp += strlen(outp); }); if (tor_snprintf(outp, endp-outp, "directory-signature %s\n", get_options()->Nickname)<0) { - log_fn(LOG_WARN, "Unable to write signature line."); + warn(LD_BUG, "Unable to write signature line."); goto done; } if (router_get_networkstatus_v2_hash(status, digest)<0) { - log_fn(LOG_WARN, "Unable to hash network status"); + warn(LD_BUG, "Unable to hash network status"); goto done; } if (router_append_dirobj_signature(outp,endp-outp,digest,private_key)<0) { - log_fn(LOG_WARN, "Unable to sign router status."); + warn(LD_BUG, "Unable to sign router status."); goto done; } @@ -1320,7 +1327,7 @@ dirserv_get_networkstatus_v2(smartlist_t *result, if (d) smartlist_add(result, d); else - log_fn(LOG_WARN,"Unable to generate an authoritative network status."); + warn(LD_BUG,"Unable to generate an authoritative network status."); } } else if (!strcmp(key, "all")) { digestmap_iter_t *iter = digestmap_iter_init(cached_v2_networkstatus); @@ -1332,7 +1339,8 @@ dirserv_get_networkstatus_v2(smartlist_t *result, iter = digestmap_iter_next(cached_v2_networkstatus, iter); } if (smartlist_len(result) == 0) - log_fn(LOG_WARN, "Client requested 'all' network status objects; we have none."); + warn(LD_DIRSERV, + "Client requested 'all' network status objects; we have none."); } else if (!strcmpstart(key, "fp/")) { smartlist_t *digests = smartlist_create(); dir_split_resource_into_fingerprints(key+3, digests, NULL, 1); @@ -1351,7 +1359,7 @@ dirserv_get_networkstatus_v2(smartlist_t *result, } else { char hexbuf[HEX_DIGEST_LEN+1]; base16_encode(hexbuf, sizeof(hexbuf), cp, DIGEST_LEN); - log_fn(LOG_INFO, "Don't know about any network status with fingerprint '%s'", hexbuf); + info(LD_DIRSERV, "Don't know about any network status with fingerprint '%s'", hexbuf); } tor_free(cp); }); @@ -1460,11 +1468,11 @@ dirserv_orconn_tls_done(const char *address, if (!ri->is_verified) { /* We have a router at the same address! */ if (strcasecmp(ri->nickname, nickname_rcvd)) { - log_fn(LOG_NOTICE, "Dropping descriptor: nickname '%s' does not match nickname '%s' in cert from %s:%d", + notice(LD_DIRSERV, "Dropping descriptor: nickname '%s' does not match nickname '%s' in cert from %s:%d", ri->nickname, nickname_rcvd, address, or_port); drop = 1; } else if (memcmp(ri->identity_digest, digest_rcvd, DIGEST_LEN)) { - log_fn(LOG_NOTICE, "Dropping descriptor: identity key does not match key in cert from %s:%d", + notice(LD_DIRSERV, "Dropping descriptor: identity key does not match key in cert from %s:%d", address, or_port); drop = 1; } @@ -1474,7 +1482,7 @@ dirserv_orconn_tls_done(const char *address, routerinfo_free(ri); directory_set_dirty(); } else { /* correct nickname and digest. mark this router reachable! */ - log_fn(LOG_INFO,"Found router %s to be reachable. Yay.", ri->nickname); + info(LD_DIRSERV,"Found router %s to be reachable. Yay.", ri->nickname); ri->last_reachable = time(NULL); ri->num_unreachable_notifications = 0; } diff --git a/src/or/dns.c b/src/or/dns.c index 87815c312e..2cd64acc70 100644 --- a/src/or/dns.c +++ b/src/or/dns.c @@ -17,6 +17,7 @@ const char dns_c_id[] = "$Id$"; * them becomes more commonly available. */ +#define NEW_LOG_INTERFACE #include "or.h" #include "tree.h" @@ -149,14 +150,14 @@ purge_expired_resolves(uint32_t now) */ while (oldest_cached_resolve && (oldest_cached_resolve->expire < now)) { resolve = oldest_cached_resolve; - log(LOG_DEBUG,"Forgetting old cached resolve (address %s, expires %lu)", + debug(LD_EXIT,"Forgetting old cached resolve (address %s, expires %lu)", safe_str(resolve->address), (unsigned long)resolve->expire); if (resolve->state == CACHE_STATE_PENDING) { - log_fn(LOG_WARN,"Bug: Expiring a dns resolve ('%s') that's still pending. Forgot to cull it?", safe_str(resolve->address)); + debug(LD_EXIT,"Bug: Expiring a dns resolve ('%s') that's still pending. Forgot to cull it?", safe_str(resolve->address)); tor_fragile_assert(); } if (resolve->pending_connections) { - log_fn(LOG_WARN, "Closing pending connections on expiring DNS resolve!"); + debug(LD_EXIT, "Closing pending connections on expiring DNS resolve!"); tor_fragile_assert(); while (resolve->pending_connections) { pend = resolve->pending_connections; @@ -283,19 +284,19 @@ dns_resolve(connection_t *exitconn) pending_connection->conn = exitconn; pending_connection->next = resolve->pending_connections; resolve->pending_connections = pending_connection; - log_fn(LOG_DEBUG,"Connection (fd %d) waiting for pending DNS resolve of '%s'", + debug(LD_EXIT,"Connection (fd %d) waiting for pending DNS resolve of '%s'", exitconn->s, safe_str(exitconn->address)); exitconn->state = EXIT_CONN_STATE_RESOLVING; return 0; case CACHE_STATE_VALID: exitconn->addr = resolve->addr; - log_fn(LOG_DEBUG,"Connection (fd %d) found cached answer for '%s'", + debug(LD_EXIT,"Connection (fd %d) found cached answer for '%s'", exitconn->s, safe_str(exitconn->address)); if (exitconn->purpose == EXIT_PURPOSE_RESOLVE) send_resolved_cell(exitconn, RESOLVED_TYPE_IPV4); return 1; case CACHE_STATE_FAILED: - log_fn(LOG_DEBUG,"Connection (fd %d) found cached error for '%s'", + debug(LD_EXIT,"Connection (fd %d) found cached error for '%s'", exitconn->s, safe_str(exitconn->address)); if (exitconn->purpose == EXIT_PURPOSE_RESOLVE) send_resolved_cell(exitconn, RESOLVED_TYPE_ERROR); @@ -344,14 +345,15 @@ assign_to_dnsworker(connection_t *exitconn) dnsconn = connection_get_by_type_state(CONN_TYPE_DNSWORKER, DNSWORKER_STATE_IDLE); if (!dnsconn) { - log_fn(LOG_WARN,"no idle dns workers. Failing."); + warn(LD_EXIT,"no idle dns workers. Failing."); if (exitconn->purpose == EXIT_PURPOSE_RESOLVE) send_resolved_cell(exitconn, RESOLVED_TYPE_ERROR_TRANSIENT); goto err; } - log_fn(LOG_DEBUG, "Connection (fd %d) needs to resolve '%s'; assigning to DNSWorker (fd %d)", - exitconn->s, safe_str(exitconn->address), dnsconn->s); + debug(LD_EXIT, + "Connection (fd %d) needs to resolve '%s'; assigning to DNSWorker (fd %d)", + exitconn->s, safe_str(exitconn->address), dnsconn->s); tor_free(dnsconn->address); dnsconn->address = tor_strdup(exitconn->address); @@ -384,7 +386,8 @@ connection_dns_remove(connection_t *conn) resolve = SPLAY_FIND(cache_tree, &cache_root, &search); if (!resolve) { - log_fn(LOG_NOTICE,"Address '%s' is not pending. Dropping.", safe_str(conn->address)); + /* XXXX RD This *is* a bug, right? -NM */ + notice(LD_BUG,"Address '%s' is not pending. Dropping.", safe_str(conn->address)); return; } @@ -396,7 +399,7 @@ connection_dns_remove(connection_t *conn) if (pend->conn == conn) { resolve->pending_connections = pend->next; tor_free(pend); - log_fn(LOG_DEBUG, "First connection (fd %d) no longer waiting for resolve of '%s'", + debug(LD_EXIT, "First connection (fd %d) no longer waiting for resolve of '%s'", conn->s, safe_str(conn->address)); return; } else { @@ -405,7 +408,7 @@ connection_dns_remove(connection_t *conn) victim = pend->next; pend->next = victim->next; tor_free(victim); - log_fn(LOG_DEBUG, "Connection (fd %d) no longer waiting for resolve of '%s'", + debug(LD_EXIT, "Connection (fd %d) no longer waiting for resolve of '%s'", conn->s, safe_str(conn->address)); return; /* more are pending */ } @@ -467,13 +470,14 @@ dns_cancel_pending_resolve(char *address) resolve = SPLAY_FIND(cache_tree, &cache_root, &search); if (!resolve) { - log_fn(LOG_NOTICE,"Address '%s' is not pending. Dropping.", safe_str(address)); + /* XXXX RD This *is* a bug, right? -NM */ + notice(LD_BUG,"Address '%s' is not pending. Dropping.", safe_str(address)); return; } if (!resolve->pending_connections) { /* XXX this should never trigger, but sometimes it does */ - log_fn(LOG_WARN,"Bug: Address '%s' is pending but has no pending connections!", + warn(LD_BUG,"Bug: Address '%s' is pending but has no pending connections!", safe_str(address)); tor_fragile_assert(); return; @@ -481,8 +485,8 @@ dns_cancel_pending_resolve(char *address) tor_assert(resolve->pending_connections); /* mark all pending connections to fail */ - log_fn(LOG_DEBUG, "Failing all connections waiting on DNS resolve of '%s'", - safe_str(address)); + debug(LD_EXIT, "Failing all connections waiting on DNS resolve of '%s'", + safe_str(address)); while (resolve->pending_connections) { pend = resolve->pending_connections; pend->conn->state = EXIT_CONN_STATE_RESOLVEFAILED; @@ -551,8 +555,8 @@ dns_found_answer(char *address, uint32_t addr, char outcome) resolve = SPLAY_FIND(cache_tree, &cache_root, &search); if (!resolve) { - log_fn(LOG_INFO,"Resolved unasked address '%s'; caching anyway.", - safe_str(address)); + info(LD_EXIT,"Resolved unasked address '%s'; caching anyway.", + safe_str(address)); resolve = tor_malloc_zero(sizeof(cached_resolve_t)); resolve->state = (outcome == DNS_RESOLVE_SUCCEEDED) ? CACHE_STATE_VALID : CACHE_STATE_FAILED; @@ -565,7 +569,7 @@ dns_found_answer(char *address, uint32_t addr, char outcome) if (resolve->state != CACHE_STATE_PENDING) { /* XXXX Maybe update addr? or check addr for consistency? Or let * VALID replace FAILED? */ - log_fn(LOG_NOTICE, "Resolved '%s' which was already resolved; ignoring", + notice(LD_EXIT, "Resolved '%s' which was already resolved; ignoring", safe_str(address)); tor_assert(resolve->pending_connections == NULL); return; @@ -656,7 +660,7 @@ connection_dns_finished_flushing(connection_t *conn) int connection_dns_reached_eof(connection_t *conn) { - log_fn(LOG_WARN,"Read eof. Worker died unexpectedly."); + warn(LD_EXIT,"Read eof. Worker died unexpectedly."); if (conn->state == DNSWORKER_STATE_BUSY) { /* don't cancel the resolve here -- it would be cancelled in * connection_about_to_close_connection(), since conn is still @@ -682,8 +686,8 @@ connection_dns_process_inbuf(connection_t *conn) tor_assert(conn->type == CONN_TYPE_DNSWORKER); if (conn->state != DNSWORKER_STATE_BUSY && buf_datalen(conn->inbuf)) { - log_fn(LOG_WARN,"Bug: read data (%d bytes) from an idle dns worker (fd %d, address '%s'). Please report.", - (int)buf_datalen(conn->inbuf), conn->s, safe_str(conn->address)); + warn(LD_BUG,"Bug: read data (%d bytes) from an idle dns worker (fd %d, address '%s'). Please report.", + (int)buf_datalen(conn->inbuf), conn->s, safe_str(conn->address)); tor_fragile_assert(); /* Pull it off the buffer anyway, or it will just stay there. @@ -692,7 +696,7 @@ connection_dns_process_inbuf(connection_t *conn) while (buf_datalen(conn->inbuf)) { connection_fetch_from_buf(&success,1,conn); connection_fetch_from_buf((char *)&addr,sizeof(uint32_t),conn); - log_fn(LOG_WARN,"Discarding idle dns answer (success %d, addr %d.)", + warn(LD_EXIT,"Discarding idle dns answer (success %d, addr %d.)", success, addr); // XXX safe_str } return 0; @@ -705,8 +709,8 @@ connection_dns_process_inbuf(connection_t *conn) connection_fetch_from_buf(&success,1,conn); connection_fetch_from_buf((char *)&addr,sizeof(uint32_t),conn); - log_fn(LOG_DEBUG, "DNSWorker (fd %d) returned answer for '%s'", - conn->s, safe_str(conn->address)); + debug(LD_EXIT, "DNSWorker (fd %d) returned answer for '%s'", + conn->s, safe_str(conn->address)); tor_assert(success >= DNS_RESOLVE_FAILED_TRANSIENT); tor_assert(success <= DNS_RESOLVE_SUCCEEDED); @@ -784,17 +788,17 @@ dnsworker_main(void *data) if ((r = recv(fd, &address_len, 1, 0)) != 1) { if (r == 0) { - log_fn(LOG_INFO,"DNS worker exiting because Tor process closed connection (either pruned idle dnsworker or died)."); + info(LD_EXIT,"DNS worker exiting because Tor process closed connection (either pruned idle dnsworker or died)."); } else { - log_fn(LOG_INFO,"DNS worker exiting 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_EXIT,"DNS worker exiting because of error on connection to Tor process."); + info(LD_EXIT,"(Error on %d was %s)", fd, tor_socket_strerror(tor_socket_errno(fd))); } tor_close_socket(fd); spawn_exit(); } if (address_len && read_all(fd, address, address_len, 1) != address_len) { - log_fn(LOG_ERR,"read hostname failed. Child exiting."); + err(LD_BUG,"read hostname failed. Child exiting."); tor_close_socket(fd); spawn_exit(); } @@ -807,21 +811,21 @@ dnsworker_main(void *data) switch (result) { case 1: /* XXX result can never be 1, because we set it to -1 above on error */ - log_fn(LOG_INFO,"Could not resolve dest addr %s (transient).",safe_str(address)); + info(LD_NET,"Could not resolve dest addr %s (transient).",safe_str(address)); answer[0] = DNS_RESOLVE_FAILED_TRANSIENT; break; case -1: - log_fn(LOG_INFO,"Could not resolve dest addr %s (permanent).",safe_str(address)); + info(LD_NET,"Could not resolve dest addr %s (permanent).",safe_str(address)); answer[0] = DNS_RESOLVE_FAILED_PERMANENT; break; case 0: - log_fn(LOG_INFO,"Resolved address '%s'.",safe_str(address)); + info(LD_NET,"Resolved address '%s'.",safe_str(address)); answer[0] = DNS_RESOLVE_SUCCEEDED; break; } set_uint32(answer+1, ip); if (write_all(fd, answer, 5, 1) != 5) { - log_fn(LOG_ERR,"writing answer failed. Child exiting."); + err(LD_NET,"writing answer failed. Child exiting."); tor_close_socket(fd); spawn_exit(); } @@ -841,7 +845,7 @@ spawn_dnsworker(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; } @@ -850,7 +854,7 @@ spawn_dnsworker(void) fd = fdarray[0]; /* We copy this out here, since dnsworker_main may free fdarray */ spawn_func(dnsworker_main, (void*)fdarray); - log_fn(LOG_DEBUG,"just spawned a worker."); + debug(LD_EXIT,"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); @@ -865,7 +869,7 @@ spawn_dnsworker(void) conn->address = tor_strdup(""); 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; } @@ -903,8 +907,8 @@ spawn_enough_dnsworkers(void) DNSWORKER_STATE_BUSY); tor_assert(dnsconn); - log_fn(LOG_WARN, "%d DNS workers are spawned; all are busy. Killing one.", - MAX_DNSWORKERS); + warn(LD_EXIT, "%d DNS workers are spawned; all are busy. Killing one.", + MAX_DNSWORKERS); connection_mark_for_close(dnsconn); num_dnsworkers_busy--; @@ -918,7 +922,7 @@ spawn_enough_dnsworkers(void) while (num_dnsworkers < num_dnsworkers_needed) { if (spawn_dnsworker() < 0) { - log_fn(LOG_WARN,"Spawn failed. Will try again later."); + warn(LD_EXIT,"Spawn failed. Will try again later."); return -1; } num_dnsworkers++; @@ -927,7 +931,7 @@ spawn_enough_dnsworkers(void) while (num_dnsworkers > num_dnsworkers_busy+MAX_IDLE_DNSWORKERS) { /* too many idle? */ /* cull excess workers */ - log_fn(LOG_INFO,"%d of %d dnsworkers are idle. Killing one.", + info(LD_EXIT,"%d of %d dnsworkers are idle. Killing one.", num_dnsworkers-num_dnsworkers_busy, num_dnsworkers); dnsconn = connection_get_by_type_state(CONN_TYPE_DNSWORKER, DNSWORKER_STATE_IDLE); tor_assert(dnsconn); diff --git a/src/or/hibernate.c b/src/or/hibernate.c index cf7cacc3f4..337b16b9db 100644 --- a/src/or/hibernate.c +++ b/src/or/hibernate.c @@ -22,6 +22,7 @@ hibernating, phase 2: - close all OR/AP/exit conns) */ +#define NEW_LOG_INTERFACE #include "or.h" #define HIBERNATE_STATE_LIVE 1 @@ -128,7 +129,7 @@ accounting_parse_options(or_options_t *options, int validate_only) smartlist_split_string(items, v, NULL, SPLIT_SKIP_SPACE|SPLIT_IGNORE_BLANK,0); if (smartlist_len(items)<2) { - log_fn(LOG_WARN, "Too few arguments to AccountingStart"); + warn(LD_CONFIG, "Too few arguments to AccountingStart"); goto err; } s = smartlist_get(items,0); @@ -139,7 +140,7 @@ accounting_parse_options(or_options_t *options, int validate_only) } else if (0==strcasecmp(s, "day")) { unit = UNIT_DAY; } else { - log_fn(LOG_WARN, "Unrecognized accounting unit '%s': only 'month', 'week', and 'day' are supported.", s); + warn(LD_CONFIG, "Unrecognized accounting unit '%s': only 'month', 'week', and 'day' are supported.", s); goto err; } @@ -147,14 +148,14 @@ accounting_parse_options(or_options_t *options, int validate_only) case UNIT_WEEK: d = tor_parse_long(smartlist_get(items,1), 10, 1, 7, &ok, NULL); if (!ok) { - log_fn(LOG_WARN, "Weekly accounting must start begin on a day between 1(Monday) and 7 (Sunday)"); + warn(LD_CONFIG, "Weekly accounting must start begin on a day between 1(Monday) and 7 (Sunday)"); goto err; } break; case UNIT_MONTH: d = tor_parse_long(smartlist_get(items,1), 10, 1, 28, &ok, NULL); if (!ok) { - log_fn(LOG_WARN, "Monthly accounting must start begin on a day between 1 and 28"); + warn(LD_CONFIG, "Monthly accounting must start begin on a day between 1 and 28"); goto err; } break; @@ -167,27 +168,27 @@ accounting_parse_options(or_options_t *options, int validate_only) idx = unit==UNIT_DAY?1:2; if (smartlist_len(items) != (idx+1)) { - log_fn(LOG_WARN, "Accounting unit '%s' requires %d arguments", + warn(LD_CONFIG,"Accounting unit '%s' requires %d arguments", s, idx+1); goto err; } s = smartlist_get(items, idx); h = tor_parse_long(s, 10, 0, 23, &ok, &cp); if (!ok) { - log_fn(LOG_WARN, "Accounting start time not parseable: bad hour."); + warn(LD_CONFIG,"Accounting start time not parseable: bad hour."); goto err; } if (!cp || *cp!=':') { - log_fn(LOG_WARN,"Accounting start time not parseable: not in HH:MM format"); + warn(LD_CONFIG,"Accounting start time not parseable: not in HH:MM format"); goto err; } m = tor_parse_long(cp+1, 10, 0, 59, &ok, &cp); if (!ok) { - log_fn(LOG_WARN, "Accounting start time not parseable: bad minute"); + warn(LD_CONFIG, "Accounting start time not parseable: bad minute"); goto err; } if (!cp || *cp!='\0') { - log_fn(LOG_WARN,"Accounting start time not parseable: not in HH:MM format"); + warn(LD_CONFIG,"Accounting start time not parseable: not in HH:MM format"); goto err; } @@ -321,15 +322,15 @@ configure_accounting(time_t now) start_of_accounting_period_after(interval_start_time) <= now) { /* We didn't have recorded usage, or we don't have recorded usage * for this interval. Start a new interval. */ - log_fn(LOG_INFO, "Starting new accounting interval."); + info(LD_ACCT, "Starting new accounting interval."); reset_accounting(now); } else if (interval_start_time == start_of_accounting_period_containing(interval_start_time)) { - log_fn(LOG_INFO, "Continuing accounting interval."); + info(LD_ACCT, "Continuing accounting interval."); /* We are in the interval we thought we were in. Do nothing.*/ interval_end_time = start_of_accounting_period_after(interval_start_time); } else { - log_fn(LOG_WARN, "Mismatched accounting interval; starting a fresh one."); + warn(LD_ACCT, "Mismatched accounting interval; starting a fresh one."); reset_accounting(now); } accounting_set_wakeup_time(); @@ -370,7 +371,7 @@ update_expected_bandwidth(void) static void reset_accounting(time_t now) { - log_fn(LOG_INFO, "Starting new accounting interval."); + info(LD_ACCT, "Starting new accounting interval."); update_expected_bandwidth(); interval_start_time = start_of_accounting_period_containing(now); interval_end_time = start_of_accounting_period_after(interval_start_time); @@ -413,7 +414,7 @@ accounting_run_housekeeping(time_t now) } if (time_to_record_bandwidth_usage(now)) { if (accounting_record_bandwidth_usage(now)) { - log_fn(LOG_ERR, "Couldn't record bandwidth usage to disk; exiting."); + err(LD_FS, "Couldn't record bandwidth usage to disk; exiting."); /* This can fail when we're out of fd's, causing a crash. * The current answer is to reserve 32 more than we need, in * set_max_file_descriptors(). */ @@ -436,7 +437,7 @@ accounting_set_wakeup_time(void) if (! identity_key_is_set()) { if (init_keys() < 0) { - log_fn(LOG_ERR, "Error initializing keys"); + err(LD_BUG, "Error initializing keys"); tor_assert(0); } } @@ -458,7 +459,7 @@ accounting_set_wakeup_time(void) time_to_exhaust_bw = 24*60*60; interval_wakeup_time = interval_start_time; - log_fn(LOG_NOTICE, "Configured hibernation. This interval begins at %s " + notice(LD_ACCT, "Configured hibernation. This interval begins at %s " "and ends at %s. We have no prior estimate for bandwidth, so " "we will start out awake and hibernate when we exhaust our quota.", buf1, buf2); @@ -500,7 +501,7 @@ accounting_set_wakeup_time(void) down_timetype); + info(LD_NET,"Closing listener type %d", conn->type); connection_mark_for_close(conn); } @@ -685,7 +686,7 @@ hibernate_begin(int new_state, time_t now) /* XXX upload rendezvous service descriptors with no intro points */ if (new_state == HIBERNATE_STATE_EXITING) { - log(LOG_NOTICE,"Interrupt: will shut down in %d seconds. Interrupt again to exit now.", options->ShutdownWaitLength); + notice(LD_GENERAL,"Interrupt: will shut down in %d seconds. Interrupt again to exit now.", options->ShutdownWaitLength); hibernate_end_time = time(NULL) + options->ShutdownWaitLength; } else { /* soft limit reached */ hibernate_end_time = interval_end_time; @@ -703,7 +704,7 @@ hibernate_end(int new_state) hibernate_state == HIBERNATE_STATE_DORMANT); /* listeners will be relaunched in run_scheduled_events() in main.c */ - log_fn(LOG_NOTICE,"Hibernation period ended. Resuming normal activity."); + notice(LD_ACCT,"Hibernation period ended. Resuming normal activity."); hibernate_state = new_state; hibernate_end_time = 0; /* no longer hibernating */ @@ -738,7 +739,7 @@ hibernate_go_dormant(time_t now) else hibernate_begin(HIBERNATE_STATE_DORMANT, now); - log_fn(LOG_NOTICE,"Going dormant. Blowing away remaining connections."); + notice(LD_ACCT,"Going dormant. Blowing away remaining connections."); /* Close all OR/AP/exit conns. Leave dir conns because we still want * to be able to upload server descriptors so people know we're still @@ -751,7 +752,7 @@ hibernate_go_dormant(time_t now) if (CONN_IS_EDGE(conn)) connection_edge_end(conn, END_STREAM_REASON_HIBERNATING, conn->cpath_layer); - log_fn(LOG_INFO,"Closing conn type %d", conn->type); + info(LD_NET,"Closing conn type %d", conn->type); if (conn->type == CONN_TYPE_AP) /* send socks failure if needed */ connection_mark_unattached_ap(conn, END_STREAM_REASON_HIBERNATING); else @@ -780,10 +781,10 @@ hibernate_end_time_elapsed(time_t now) format_iso_time(buf,interval_wakeup_time); if (hibernate_state != HIBERNATE_STATE_DORMANT) { /* We weren't sleeping before; we should sleep now. */ - log_fn(LOG_NOTICE, "Accounting period ended. Commencing hibernation until %s GMT",buf); + notice(LD_ACCT, "Accounting period ended. Commencing hibernation until %s GMT",buf); hibernate_go_dormant(now); } else { - log_fn(LOG_NOTICE, "Accounting period ended. This period, we will hibernate until %s GMT",buf); + notice(LD_ACCT, "Accounting period ended. This period, we will hibernate until %s GMT",buf); } } } @@ -802,7 +803,7 @@ consider_hibernation(time_t now) if (hibernate_state == HIBERNATE_STATE_EXITING) { tor_assert(hibernate_end_time); if (hibernate_end_time <= now) { - log(LOG_NOTICE,"Clean shutdown finished. Exiting."); + notice(LD_GENERAL, "Clean shutdown finished. Exiting."); tor_cleanup(); exit(0); } @@ -825,11 +826,11 @@ consider_hibernation(time_t now) * go dormant. */ if (hibernate_state == HIBERNATE_STATE_LIVE) { if (hibernate_soft_limit_reached()) { - log_fn(LOG_NOTICE,"Bandwidth soft limit reached; commencing hibernation."); + notice(LD_ACCT,"Bandwidth soft limit reached; commencing hibernation."); hibernate_begin(HIBERNATE_STATE_LOWBANDWIDTH, now); } else if (accounting_enabled && now < interval_wakeup_time) { format_iso_time(buf,interval_wakeup_time); - log_fn(LOG_NOTICE, "Commencing hibernation. We will wake up at %s GMT",buf); + notice(LD_ACCT,"Commencing hibernation. We will wake up at %s GMT",buf); hibernate_go_dormant(now); } } -- cgit v1.2.3-54-g00ecf