diff options
| -rw-r--r-- | src/or/circuituse.c | 110 | ||||
| -rw-r--r-- | src/or/command.c | 58 | ||||
| -rw-r--r-- | src/or/connection.c | 131 | ||||
| -rw-r--r-- | src/or/relay.c | 194 | ||||
| -rw-r--r-- | src/or/router.c | 42 | ||||
| -rw-r--r-- | src/or/test.c | 1 |
6 files changed, 281 insertions, 255 deletions
diff --git a/src/or/circuituse.c b/src/or/circuituse.c index 98f5febd52..8c98d7e302 100644 --- a/src/or/circuituse.c +++ b/src/or/circuituse.c @@ -10,6 +10,7 @@ const char circuituse_c_id[] = "$Id$"; * \brief Launch the right sort of circuits and attach streams to them. **/ +#define NEW_LOG_INTERFACE #include "or.h" /** Longest time to wait for a circuit before closing an AP connection */ @@ -83,7 +84,7 @@ circuit_is_acceptable(circuit_t *circ, if (purpose == CIRCUIT_PURPOSE_C_GENERAL) { if (!exitrouter) { - log_fn(LOG_DEBUG,"Not considering circuit with unknown router."); + debug(LD_CIRC,"Not considering circuit with unknown router."); return 0; /* this circuit is screwed and doesn't know it yet, * or is a rendezvous circuit. */ } @@ -242,12 +243,14 @@ circuit_expire_building(time_t now) victim->purpose == CIRCUIT_PURPOSE_C_INTRODUCE_ACK_WAIT) && victim->timestamp_dirty + MIN_SECONDS_BEFORE_EXPIRING_CIRC > now)) { if (victim->n_conn) - log_fn(LOG_INFO,"Abandoning circ %s:%d:%d (state %d:%s, purpose %d)", + info(LD_CIRC,"Abandoning circ %s:%d:%d (state %d:%s, purpose %d)", victim->n_conn->address, victim->n_port, victim->n_circ_id, victim->state, circuit_state_to_string(victim->state), victim->purpose); else - log_fn(LOG_INFO,"Abandoning circ %d (state %d:%s, purpose %d)", victim->n_circ_id, - victim->state, circuit_state_to_string(victim->state), victim->purpose); + info(LD_CIRC,"Abandoning circ %d (state %d:%s, purpose %d)", + victim->n_circ_id, victim->state, + circuit_state_to_string(victim->state), victim->purpose); + circuit_log_path(LOG_INFO,LD_CIRC,victim); circuit_mark_for_close(victim); } @@ -267,11 +270,11 @@ circuit_remove_handled_ports(smartlist_t *needed_ports) port = smartlist_get(needed_ports, i); tor_assert(*port); if (circuit_stream_is_being_handled(NULL, *port, 2)) { -// log_fn(LOG_DEBUG,"Port %d is already being handled; removing.", port); +// debug(LD_CIRC,"Port %d is already being handled; removing.", port); smartlist_del(needed_ports, i--); tor_free(port); } else { - log_fn(LOG_DEBUG,"Port %d is not handled.", *port); + debug(LD_CIRC,"Port %d is not handled.", *port); } } } @@ -359,7 +362,7 @@ circuit_predict_and_launch_new(void) * and no circuit is currently available that can handle it. */ if (!circuit_all_predicted_ports_handled(now, &port_needs_uptime, &port_needs_capacity)) { - log_fn(LOG_INFO,"Have %d clean circs (%d internal), need another exit circ.", + info(LD_CIRC,"Have %d clean circs (%d internal), need another exit circ.", num, num_internal); circuit_launch_by_router(CIRCUIT_PURPOSE_C_GENERAL, NULL, port_needs_uptime, port_needs_capacity, 0); @@ -368,7 +371,7 @@ circuit_predict_and_launch_new(void) /* Third, see if we need any more hidden service (server) circuits. */ if (num_rend_services() && num_uptime_internal < 3) { - log_fn(LOG_INFO,"Have %d clean circs (%d internal), need another internal circ for my hidden service.", + info(LD_CIRC,"Have %d clean circs (%d internal), need another internal circ for my hidden service.", num, num_internal); circuit_launch_by_router(CIRCUIT_PURPOSE_C_GENERAL, NULL, 1, 1, 1); @@ -380,7 +383,7 @@ circuit_predict_and_launch_new(void) &hidserv_needs_capacity) && ((num_uptime_internal<2 && hidserv_needs_uptime) || num_internal<2)) { - log_fn(LOG_INFO,"Have %d clean circs (%d uptime-internal, %d internal)," + info(LD_CIRC,"Have %d clean circs (%d uptime-internal, %d internal)," " need another hidserv circ.", num, num_uptime_internal, num_internal); circuit_launch_by_router(CIRCUIT_PURPOSE_C_GENERAL, NULL, hidserv_needs_uptime, hidserv_needs_capacity, 1); @@ -482,7 +485,7 @@ circuit_detach_stream(circuit_t *circ, connection_t *conn) return; } - log_fn(LOG_ERR,"edge conn not in circuit's list?"); + err(LD_BUG,"edge conn not in circuit's list?"); tor_assert(0); /* should never get here */ } @@ -554,8 +557,8 @@ circuit_expire_old_circuits(void) circ->timestamp_dirty + get_options()->MaxCircuitDirtiness < now && CIRCUIT_IS_ORIGIN(circ) && !circ->p_streams /* nothing attached */ ) { - log_fn(LOG_DEBUG,"Closing n_circ_id %d (dirty %d secs ago, purp %d)",circ->n_circ_id, - (int)(now - circ->timestamp_dirty), circ->purpose); + debug(LD_CIRC,"Closing n_circ_id %d (dirty %d secs ago, purp %d)", + circ->n_circ_id, (int)(now - circ->timestamp_dirty), circ->purpose); /* (only general and purpose_c circs can get dirty) */ tor_assert(!circ->n_streams); tor_assert(circ->purpose <= CIRCUIT_PURPOSE_C_REND_JOINED); @@ -565,7 +568,7 @@ circuit_expire_old_circuits(void) circ->purpose == CIRCUIT_PURPOSE_C_GENERAL) { #define CIRCUIT_UNUSED_CIRC_TIMEOUT 3600 /* an hour */ if (circ->timestamp_created + CIRCUIT_UNUSED_CIRC_TIMEOUT < now) { - log_fn(LOG_DEBUG,"Closing circuit that has been unused for %d seconds.", + debug(LD_CIRC,"Closing circuit that has been unused for %d seconds.", (int)(now - circ->timestamp_created)); circuit_mark_for_close(circ); } @@ -594,7 +597,7 @@ circuit_testing_failed(circuit_t *circ, int at_last_hop) circuit_launch_by_router(CIRCUIT_PURPOSE_TESTING, me, 0, 1, 1); else #endif - log_fn(LOG_INFO,"Our testing circuit (to see if your ORPort is reachable) has failed. I'll try again later."); + info(LD_GENERAL,"Our testing circuit (to see if your ORPort is reachable) has failed. I'll try again later."); } /** The circuit <b>circ</b> has just become open. Take the next @@ -633,7 +636,7 @@ circuit_has_opened(circuit_t *circ) circuit_testing_opened(circ); break; default: - log_fn(LOG_ERR,"unhandled purpose %d",circ->purpose); + err(LD_BUG,"unhandled purpose %d",circ->purpose); tor_assert(0); } } @@ -694,9 +697,10 @@ circuit_build_failed(circuit_t *circ) /* at Bob, connecting to rend point */ /* Don't increment failure count, since Alice may have picked * the rendezvous point maliciously */ - log_fn(LOG_INFO,"Couldn't connect to Alice's chosen rend point %s (%s hop failed).", - build_state_get_exit_nickname(circ->build_state), - failed_at_last_hop?"last":"non-last"); + info(LD_REND, + "Couldn't connect to Alice's chosen rend point %s (%s hop failed).", + build_state_get_exit_nickname(circ->build_state), + failed_at_last_hop?"last":"non-last"); rend_service_relaunch_rendezvous(circ); break; default: @@ -746,7 +750,7 @@ circuit_launch_by_extend_info(uint8_t purpose, extend_info_t *info, circuit_t *circ; if (!has_fetched_directory) { - log_fn(LOG_DEBUG,"Haven't fetched directory yet; canceling circuit launch."); + debug(LD_CIRC,"Haven't fetched directory yet; canceling circuit launch."); return NULL; } @@ -755,7 +759,7 @@ circuit_launch_by_extend_info(uint8_t purpose, extend_info_t *info, /* see if there are appropriate circs available to cannibalize. */ if ((circ = circuit_get_clean_open(CIRCUIT_PURPOSE_C_GENERAL, need_uptime, need_capacity, internal))) { - log_fn(LOG_INFO,"Cannibalizing circ '%s' for purpose %d", + info(LD_CIRC,"Cannibalizing circ '%s' for purpose %d", build_state_get_exit_nickname(circ->build_state), purpose); circ->purpose = purpose; /* reset the birth date of this circ, else expire_building @@ -776,8 +780,7 @@ circuit_launch_by_extend_info(uint8_t purpose, extend_info_t *info, return NULL; break; default: - log_fn(LOG_WARN,"Bug: unexpected purpose %d when cannibalizing a general circ.", - purpose); + warn(LD_BUG, "Bug: unexpected purpose %d when cannibalizing a general circ.", purpose); tor_fragile_assert(); return NULL; } @@ -808,7 +811,8 @@ circuit_launch_by_nickname(uint8_t purpose, const char *exit_nickname, if (exit_nickname) { router = router_get_by_nickname(exit_nickname, 1); if (!router) { - log_fn(LOG_WARN, "No such OR as '%s'", exit_nickname); + /*XXXXNM domain? */ + warn(LD_GENERAL, "No such OR as '%s'", exit_nickname); return NULL; } } @@ -823,7 +827,7 @@ static void circuit_increment_failure_count(void) { ++n_circuit_failures; - log_fn(LOG_DEBUG,"n_circuit_failures now %d.",n_circuit_failures); + debug(LD_CIRC,"n_circuit_failures now %d.",n_circuit_failures); } /** Reset the failure count for opening general circuits. This means @@ -869,7 +873,7 @@ circuit_get_open_circ_or_launch(connection_t *conn, if (!has_fetched_directory) { if (!connection_get_by_type(CONN_TYPE_DIR)) { - log(LOG_NOTICE,"Application request when we're believed to be offline. Optimistically trying again."); + notice(LD_APP|LD_DIR,"Application request when we're believed to be offline. Optimistically trying directory fetches again."); router_reset_status_download_failures(); router_reset_descriptor_download_failures(); update_networkstatus_downloads(time(NULL)); @@ -895,7 +899,8 @@ circuit_get_open_circ_or_launch(connection_t *conn, addr = ntohl(in.s_addr); if (router_exit_policy_all_routers_reject(addr, conn->socks_request->port, need_uptime)) { - log(LOG_NOTICE,"No Tor server exists that allows exit to %s:%d. Rejecting.", + /* LD_GENERAL? LD_APP? ???? NM */ + notice(LD_CIRC,"No Tor server exists that allows exit to %s:%d. Rejecting.", safe_str(conn->socks_request->address), conn->socks_request->port); return -1; } @@ -912,14 +917,14 @@ circuit_get_open_circ_or_launch(connection_t *conn, /* need to pick an intro point */ extend_info = rend_client_get_random_intro(conn->rend_query); if (!extend_info) { - log_fn(LOG_INFO,"No intro points for '%s': refetching service descriptor.", - safe_str(conn->rend_query)); + info(LD_REND,"No intro points for '%s': refetching service descriptor.", + safe_str(conn->rend_query)); rend_client_refetch_renddesc(conn->rend_query); conn->state = AP_CONN_STATE_RENDDESC_WAIT; return 0; } - log_fn(LOG_INFO,"Chose %s as intro point for %s.", - extend_info->nickname, safe_str(conn->rend_query)); + info(LD_REND,"Chose %s as intro point for %s.", + extend_info->nickname, safe_str(conn->rend_query)); } /* If we have specified a particular exit node for our @@ -929,7 +934,8 @@ circuit_get_open_circ_or_launch(connection_t *conn, if (conn->chosen_exit_name) { routerinfo_t *r; if (!(r = router_get_by_nickname(conn->chosen_exit_name, 1))) { - log_fn(LOG_NOTICE,"Requested exit point '%s' is not known. Closing.", + /*XXXX NM domain? */ + notice(LD_CIRC,"Requested exit point '%s' is not known. Closing.", conn->chosen_exit_name); return -1; } @@ -963,8 +969,9 @@ circuit_get_open_circ_or_launch(connection_t *conn, } } if (!circ) - log_fn(LOG_INFO,"No safe circuit (purpose %d) ready for edge connection; delaying.", - desired_circuit_purpose); + info(LD_APP, + "No safe circuit (purpose %d) ready for edge connection; delaying.", + desired_circuit_purpose); *circp = circ; return 0; } @@ -977,7 +984,7 @@ static void link_apconn_to_circ(connection_t *apconn, circuit_t *circ) { /* add it into the linked list of streams on this circuit */ - log_fn(LOG_DEBUG,"attaching new conn to circ. n_circ_id %d.", circ->n_circ_id); + debug(LD_APP|LD_CIRC,"attaching new conn to circ. n_circ_id %d.", circ->n_circ_id); apconn->timestamp_lastread = time(NULL); /* reset it, so we can measure circ timeouts */ apconn->next_stream = circ->p_streams; apconn->on_circuit = circ; @@ -1093,8 +1100,9 @@ connection_ap_handshake_attach_circuit(connection_t *conn) conn_age = time(NULL) - conn->timestamp_created; if (conn_age > CONN_AP_MAX_ATTACH_DELAY) { - log(LOG_NOTICE,"Tried for %d seconds to get a connection to %s:%d. Giving up.", - conn_age, safe_str(conn->socks_request->address), conn->socks_request->port); + notice(LD_APP,"Tried for %d seconds to get a connection to %s:%d. Giving up.", + conn_age, safe_str(conn->socks_request->address), + conn->socks_request->port); return -1; } @@ -1104,12 +1112,12 @@ connection_ap_handshake_attach_circuit(connection_t *conn) if (conn->chosen_exit_name) { routerinfo_t *router = router_get_by_nickname(conn->chosen_exit_name, 1); if (!router) { - log_fn(LOG_WARN,"Requested exit point '%s' is not known. Closing.", + warn(LD_APP,"Requested exit point '%s' is not known. Closing.", conn->chosen_exit_name); return -1; } if (!connection_ap_can_use_exit(conn, router)) { - log_fn(LOG_WARN, "Requested exit point '%s' would refuse request. Closing.", + warn(LD_APP, "Requested exit point '%s' would refuse request. Closing.", conn->chosen_exit_name); return -1; } @@ -1120,10 +1128,10 @@ connection_ap_handshake_attach_circuit(connection_t *conn) if (retval < 1) return retval; - log_fn(LOG_DEBUG,"Attaching apconn to circ %d (stream %d sec old).", + debug(LD_APP|LD_CIRC,"Attaching apconn to circ %d (stream %d sec old).", circ->n_circ_id, conn_age); /* here, print the circ's path. so people can figure out which circs are sucking. */ - circuit_log_path(LOG_INFO,LD_APP,circ); + circuit_log_path(LOG_INFO,LD_APP|LD_CIRC,circ); /* We have found a suitable circuit for our conn. Hurray. */ return connection_ap_handshake_attach_chosen_circuit(conn, circ); @@ -1141,8 +1149,9 @@ connection_ap_handshake_attach_circuit(connection_t *conn) if (retval > 0) { tor_assert(rendcirc); /* one is already established, attach */ - log_fn(LOG_INFO,"rend joined circ %d already here. attaching. (stream %d sec old)", - rendcirc->n_circ_id, conn_age); + info(LD_REND, + "rend joined circ %d already here. attaching. (stream %d sec old)", + rendcirc->n_circ_id, conn_age); /* Mark rendezvous circuits as 'newly dirty' every time you use * them, since the process of rebuilding a rendezvous circ is so * expensive. There is a tradeoffs between linkability and @@ -1156,7 +1165,7 @@ connection_ap_handshake_attach_circuit(connection_t *conn) } if (rendcirc && rendcirc->purpose == CIRCUIT_PURPOSE_C_REND_READY_INTRO_ACKED) { - log_fn(LOG_INFO,"pending-join circ %d already here, with intro ack. Stalling. (stream %d sec old)", rendcirc->n_circ_id, conn_age); + info(LD_REND,"pending-join circ %d already here, with intro ack. Stalling. (stream %d sec old)", rendcirc->n_circ_id, conn_age); return 0; } @@ -1167,20 +1176,21 @@ connection_ap_handshake_attach_circuit(connection_t *conn) if (retval > 0) { /* one has already sent the intro. keep waiting. */ tor_assert(introcirc); - log_fn(LOG_INFO,"Intro circ %d present and awaiting ack (rend %d). Stalling. (stream %d sec old)", - introcirc->n_circ_id, rendcirc ? rendcirc->n_circ_id : 0, conn_age); + info(LD_REND, + "Intro circ %d present and awaiting ack (rend %d). Stalling. (stream %d sec old)", + introcirc->n_circ_id, rendcirc ? rendcirc->n_circ_id : 0, conn_age); return 0; } /* now rendcirc and introcirc are each either undefined or not finished */ if (rendcirc && introcirc && rendcirc->purpose == CIRCUIT_PURPOSE_C_REND_READY) { - log_fn(LOG_INFO,"ready rend circ %d already here (no intro-ack yet on intro %d). (stream %d sec old)", + info(LD_REND,"ready rend circ %d already here (no intro-ack yet on intro %d). (stream %d sec old)", rendcirc->n_circ_id, introcirc->n_circ_id, conn_age); tor_assert(introcirc->purpose == CIRCUIT_PURPOSE_C_INTRODUCING); if (introcirc->state == CIRCUIT_STATE_OPEN) { - log_fn(LOG_INFO,"found open intro circ %d (rend %d); sending introduction. (stream %d sec old)", + info(LD_REND,"found open intro circ %d (rend %d); sending introduction. (stream %d sec old)", introcirc->n_circ_id, rendcirc->n_circ_id, conn_age); if (rend_client_send_introduction(introcirc, rendcirc) < 0) { return -1; @@ -1193,9 +1203,9 @@ connection_ap_handshake_attach_circuit(connection_t *conn) } } - log_fn(LOG_INFO,"Intro (%d) and rend (%d) circs are not both ready. Stalling conn. (%d sec old)", - introcirc ? introcirc->n_circ_id : 0, - rendcirc ? rendcirc->n_circ_id : 0, conn_age); + info(LD_REND, "Intro (%d) and rend (%d) circs are not both ready. Stalling conn. (%d sec old)", + introcirc ? introcirc->n_circ_id : 0, + rendcirc ? rendcirc->n_circ_id : 0, conn_age); return 0; } } diff --git a/src/or/command.c b/src/or/command.c index 72bcaf5578..63d067ae65 100644 --- a/src/or/command.c +++ b/src/or/command.c @@ -16,6 +16,7 @@ const char command_c_id[] = "$Id$"; * connection_or_process_cells_from_inbuf() in connection_or.c */ +#define NEW_LOG_INTERFACE #include "or.h" /** Keep statistics about how many of each type of cell we've received. */ @@ -51,10 +52,10 @@ command_time_process_cell(cell_t *cell, connection_t *conn, int *time, time_passed = tv_udiff(&start, &end) ; if (time_passed > 10000) { /* more than 10ms */ - log_fn(LOG_DEBUG,"That call just took %ld ms.",time_passed/1000); + debug(LD_OR,"That call just took %ld ms.",time_passed/1000); } if (time_passed < 0) { - log_fn(LOG_INFO,"That call took us back in time!"); + info(LD_GENERAL,"That call took us back in time!"); time_passed = 0; } *time += time_passed; @@ -81,7 +82,7 @@ command_process_cell(cell_t *cell, connection_t *conn) if (now > current_second) { /* the second has rolled over */ /* print stats */ - log(LOG_INFO,"At end of second: %d creates (%d ms), %d createds (%d ms), %d relays (%d ms), %d destroys (%d ms)", + info(LD_OR,"At end of second: %d creates (%d ms), %d createds (%d ms), %d relays (%d ms), %d destroys (%d ms)", num_create, create_time/1000, num_created, created_time/1000, num_relay, relay_time/1000, @@ -144,7 +145,7 @@ command_process_cell(cell_t *cell, connection_t *conn) #endif break; default: - log_fn(LOG_PROTOCOL_WARN, + log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL, "Cell of unknown type (%d) received. Dropping.", cell->command); break; } @@ -161,7 +162,7 @@ command_process_create_cell(cell_t *cell, connection_t *conn) circuit_t *circ; if (we_are_hibernating()) { - log_fn(LOG_INFO,"Received create cell but we're shutting down. Sending back destroy."); + info(LD_OR,"Received create cell but we're shutting down. Sending back destroy."); connection_send_destroy(cell->circ_id, conn); return; } @@ -173,11 +174,11 @@ command_process_create_cell(cell_t *cell, connection_t *conn) * half to use based on nickname, and we now use identity keys. */ if ((cell->circ_id & (1<<15)) && conn->circ_id_type == CIRC_ID_TYPE_HIGHER) { - log_fn(LOG_INFO, "Got a high circuit ID from %s (%d); switching to low circuit IDs.", + info(LD_OR, "Got a high circuit ID from %s (%d); switching to low circuit IDs.", conn->nickname ? conn->nickname : "client", conn->s); conn->circ_id_type = CIRC_ID_TYPE_LOWER; } else if (!(cell->circ_id & (1<<15)) && conn->circ_id_type == CIRC_ID_TYPE_LOWER) { - log_fn(LOG_INFO, "Got a low circuit ID from %s (%d); switching to high circuit IDs.", + info(LD_OR, "Got a low circuit ID from %s (%d); switching to high circuit IDs.", conn->nickname ? conn->nickname : "client", conn->s); conn->circ_id_type = CIRC_ID_TYPE_HIGHER; } @@ -186,11 +187,11 @@ command_process_create_cell(cell_t *cell, connection_t *conn) if (circ) { routerinfo_t *router = router_get_by_digest(conn->identity_digest); - log_fn(LOG_PROTOCOL_WARN, + log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL, "received CREATE cell (circID %d) for known circ. Dropping (age %d).", cell->circ_id, (int)(time(NULL) - conn->timestamp_created)); if (router) - log_fn(LOG_PROTOCOL_WARN, + log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL, "Details: nickname '%s', platform '%s'.", router->nickname, router->platform); return; @@ -204,22 +205,22 @@ command_process_create_cell(cell_t *cell, connection_t *conn) /* hand it off to the cpuworkers, and then return */ if (assign_to_cpuworker(NULL, CPUWORKER_TASK_ONION, circ) < 0) { - log_fn(LOG_WARN,"Failed to hand off onionskin. Closing."); + warn(LD_GENERAL,"Failed to hand off onionskin. Closing."); circuit_mark_for_close(circ); return; } - log_fn(LOG_DEBUG,"success: handed off onionskin."); + debug(LD_OR,"success: handed off onionskin."); } else { char keys[CPATH_KEY_MATERIAL_LEN]; char reply[DIGEST_LEN*2]; tor_assert(cell->command == CELL_CREATE_FAST); if (fast_server_handshake(cell->payload, reply, keys, sizeof(keys))<0) { - log_fn(LOG_WARN,"Failed to generate key material. Closing."); + warn(LD_OR,"Failed to generate key material. Closing."); circuit_mark_for_close(circ); return; } if (onionskin_answer(circ, CELL_CREATED_FAST, reply, keys)<0) { - log_fn(LOG_WARN,"Failed to reply to CREATE_FAST cell. Closing."); + warn(LD_OR,"Failed to reply to CREATE_FAST cell. Closing."); circuit_mark_for_close(circ); return; } @@ -241,31 +242,32 @@ command_process_created_cell(cell_t *cell, connection_t *conn) circ = circuit_get_by_circid_orconn(cell->circ_id, conn); if (!circ) { - log_fn(LOG_INFO,"(circID %d) unknown circ (probably got a destroy earlier). Dropping.", cell->circ_id); + info(LD_OR,"(circID %d) unknown circ (probably got a destroy earlier). Dropping.", cell->circ_id); return; } if (circ->n_circ_id != cell->circ_id) { - log_fn(LOG_PROTOCOL_WARN,"got created cell from OPward? Closing."); + log_fn(LOG_PROTOCOL_WARN,LD_PROTOCOL, + "got created cell from OPward? Closing."); circuit_mark_for_close(circ); return; } if (CIRCUIT_IS_ORIGIN(circ)) { /* we're the OP. Handshake this. */ - log_fn(LOG_DEBUG,"at OP. Finishing handshake."); + debug(LD_OR,"at OP. Finishing handshake."); if (circuit_finish_handshake(circ, cell->command, cell->payload) < 0) { - log_fn(LOG_WARN,"circuit_finish_handshake failed."); + warn(LD_OR,"circuit_finish_handshake failed."); circuit_mark_for_close(circ); return; } - log_fn(LOG_DEBUG,"Moving to next skin."); + debug(LD_OR,"Moving to next skin."); if (circuit_send_next_onion_skin(circ) < 0) { - log_fn(LOG_INFO,"circuit_send_next_onion_skin failed."); + info(LD_OR,"circuit_send_next_onion_skin failed."); circuit_mark_for_close(circ); /* XXX push this circuit_close lower */ return; } } else { /* pack it into an extended relay cell, and send it. */ - log_fn(LOG_DEBUG,"Converting created cell to extended relay cell, sending."); + debug(LD_OR,"Converting created cell to extended relay cell, sending."); connection_edge_send_command(NULL, circ, RELAY_COMMAND_EXTENDED, cell->payload, ONIONSKIN_REPLY_LEN, NULL); } @@ -283,26 +285,26 @@ command_process_relay_cell(cell_t *cell, connection_t *conn) circ = circuit_get_by_circid_orconn(cell->circ_id, conn); if (!circ) { - log_fn(LOG_DEBUG,"unknown circuit %d on connection from %s:%d. Dropping.", - cell->circ_id, conn->address, conn->port); + debug(LD_OR,"unknown circuit %d on connection from %s:%d. Dropping.", + cell->circ_id, conn->address, conn->port); return; } if (circ->state == CIRCUIT_STATE_ONIONSKIN_PENDING) { - log_fn(LOG_PROTOCOL_WARN,"circuit in create_wait. Closing."); + log_fn(LOG_PROTOCOL_WARN,LD_PROTOCOL,"circuit in create_wait. Closing."); circuit_mark_for_close(circ); return; } if (cell->circ_id == circ->p_circ_id) { /* it's an outgoing cell */ if (circuit_receive_relay_cell(cell, circ, CELL_DIRECTION_OUT) < 0) { - log_fn(LOG_PROTOCOL_WARN,"circuit_receive_relay_cell (forward) failed. Closing."); + log_fn(LOG_PROTOCOL_WARN,LD_PROTOCOL,"circuit_receive_relay_cell (forward) failed. Closing."); circuit_mark_for_close(circ); return; } } else { /* it's an ingoing cell */ if (circuit_receive_relay_cell(cell, circ, CELL_DIRECTION_IN) < 0) { - log_fn(LOG_PROTOCOL_WARN,"circuit_receive_relay_cell (backward) failed. Closing."); + log_fn(LOG_PROTOCOL_WARN,LD_PROTOCOL,"circuit_receive_relay_cell (backward) failed. Closing."); circuit_mark_for_close(circ); return; } @@ -330,12 +332,12 @@ command_process_destroy_cell(cell_t *cell, connection_t *conn) circ = circuit_get_by_circid_orconn(cell->circ_id, conn); if (!circ) { - log_fn(LOG_INFO,"unknown circuit %d on connection from %s:%d. Dropping.", + info(LD_OR,"unknown circuit %d on connection from %s:%d. Dropping.", cell->circ_id, conn->address, conn->port); return; } - log_fn(LOG_DEBUG,"Received for circID %d.",cell->circ_id); + debug(LD_OR,"Received for circID %d.",cell->circ_id); if (circ->state == CIRCUIT_STATE_ONIONSKIN_PENDING) { onion_pending_remove(circ); } @@ -349,7 +351,7 @@ command_process_destroy_cell(cell_t *cell, connection_t *conn) if (CIRCUIT_IS_ORIGIN(circ)) { circuit_mark_for_close(circ); } else { - log_fn(LOG_DEBUG, "Delivering 'truncated' back."); + debug(LD_OR, "Delivering 'truncated' back."); connection_edge_send_command(NULL, circ, RELAY_COMMAND_TRUNCATED, NULL, 0, NULL); } diff --git a/src/or/connection.c b/src/or/connection.c index 6845fa72f9..257efbbb12 100644 --- a/src/or/connection.c +++ b/src/or/connection.c @@ -11,6 +11,7 @@ const char connection_c_id[] = "$Id$"; * on connections. **/ +#define NEW_LOG_INTERFACE #include "or.h" static connection_t *connection_create_listener(const char *listenaddress, @@ -51,7 +52,7 @@ conn_type_to_string(int type) case CONN_TYPE_CONTROL_LISTENER: return "Control listener"; case CONN_TYPE_CONTROL: return "Control"; default: - log_fn(LOG_WARN, "Bug: unknown connection type %d", type); + warn(LD_BUG, "Bug: unknown connection type %d", type); tor_snprintf(buf, sizeof(buf), "unknown [%d]", type); return buf; } @@ -134,7 +135,7 @@ conn_state_to_string(int type, int state) break; } - log_fn(LOG_WARN, "Bug: unknown connection state %d (type %d)", state, type); + warn(LD_BUG, "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)); @@ -191,12 +192,12 @@ connection_unregister(connection_t *conn) { if (conn->read_event) { if (event_del(conn->read_event)) - log_fn(LOG_WARN, "Error removing read event for %d", conn->s); + warn(LD_BUG, "Error removing read event for %d", conn->s); tor_free(conn->read_event); } if (conn->write_event) { if (event_del(conn->write_event)) - log_fn(LOG_WARN, "Error removing write event for %d", conn->s); + warn(LD_BUG, "Error removing write event for %d", conn->s); tor_free(conn->write_event); } } @@ -234,7 +235,7 @@ _connection_free(connection_t *conn) tor_free(conn->requested_resource); if (conn->s >= 0) { - log_fn(LOG_DEBUG,"closing fd %d.",conn->s); + debug(LD_NET,"closing fd %d.",conn->s); tor_close_socket(conn->s); } @@ -312,7 +313,7 @@ connection_about_to_close_connection(connection_t *conn) if (CONN_IS_EDGE(conn)) { if (!conn->has_sent_end) { - log_fn(LOG_WARN,"Harmless bug: Edge connection (marked at %s:%d) hasn't sent end yet?", conn->marked_for_close_file, conn->marked_for_close); + warn(LD_BUG,"Harmless bug: Edge connection (marked at %s:%d) hasn't sent end yet?", conn->marked_for_close_file, conn->marked_for_close); tor_fragile_assert(); } } @@ -356,7 +357,7 @@ connection_about_to_close_connection(connection_t *conn) if (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_fn(LOG_WARN,"Bug: Closing stream (marked at %s:%d) without sending back a socks reply.", + warn(LD_BUG,"Bug: Closing stream (marked at %s:%d) without sending back a socks reply.", conn->marked_for_close_file, conn->marked_for_close); } else { control_event_stream_status(conn, STREAM_EVENT_CLOSED); @@ -387,12 +388,12 @@ connection_close_immediate(connection_t *conn) { assert_connection_ok(conn,0); if (conn->s < 0) { - log_fn(LOG_WARN,"Bug: Attempt to close already-closed connection."); + err(LD_BUG,"Bug: Attempt to close already-closed connection."); tor_fragile_assert(); return; } if (conn->outbuf_flushlen) { - log_fn(LOG_INFO,"fd %d, type %s, state %s, %d bytes on outbuf.", + info(LD_NET,"fd %d, type %s, state %s, %d bytes on outbuf.", conn->s, conn_type_to_string(conn->type), conn_state_to_string(conn->type, conn->state), (int)conn->outbuf_flushlen); @@ -418,7 +419,7 @@ _connection_mark_for_close(connection_t *conn, int line, const char *file) tor_assert(file); if (conn->marked_for_close) { - log(LOG_WARN, "Duplicate call to connection_mark_for_close at %s:%d" + log(LOG_WARN,LD_BUG,"Duplicate call to connection_mark_for_close at %s:%d" " (first at %s:%d)", file, line, conn->marked_for_close_file, conn->marked_for_close); tor_fragile_assert(); @@ -464,7 +465,8 @@ connection_expire_held_open(void) severity = LOG_INFO; else severity = LOG_NOTICE; - log_fn(severity, "Giving up on marked_for_close conn that's been flushing for 15s (fd %d, type %s, state %s).", + log_fn(severity, LD_NET, + "Giving up on marked_for_close conn that's been flushing for 15s (fd %d, type %s, state %s).", conn->s, conn_type_to_string(conn->type), conn_state_to_string(conn->type, conn->state)); conn->hold_open_until_flushed = 0; @@ -496,7 +498,7 @@ connection_create_listener(const char *listenaddress, uint16_t listenport, memset(&listenaddr,0,sizeof(struct sockaddr_in)); if (parse_addr_port(listenaddress, &address, &addr, &usePort)<0) { - log_fn(LOG_WARN, "Error parsing/resolving ListenAddress %s",listenaddress); + warn(LD_CONFIG, "Error parsing/resolving ListenAddress %s",listenaddress); return NULL; } @@ -506,15 +508,15 @@ connection_create_listener(const char *listenaddress, uint16_t listenport, listenaddr.sin_family = AF_INET; listenaddr.sin_port = htons((uint16_t) usePort); - log_fn(LOG_NOTICE, "Opening %s on %s:%d", + notice(LD_NET, "Opening %s on %s:%d", conn_type_to_string(type), address, usePort); s = socket(PF_INET,SOCK_STREAM,IPPROTO_TCP); if (s < 0) { - log_fn(LOG_WARN,"Socket creation failed."); + warn(LD_NET,"Socket creation failed."); goto err; } else if (!SOCKET_IS_POLLABLE(s)) { - log_fn(LOG_WARN,"Too many connections; can't create pollable listener."); + warn(LD_NET,"Too many connections; can't create pollable listener."); tor_close_socket(s); goto err; } @@ -528,13 +530,13 @@ connection_create_listener(const char *listenaddress, uint16_t listenport, #endif if (bind(s,(struct sockaddr *)&listenaddr,sizeof(listenaddr)) < 0) { - log_fn(LOG_WARN, "Could not bind to %s:%u: %s", address, usePort, + warn(LD_NET, "Could not bind to %s:%u: %s", address, usePort, tor_socket_strerror(tor_socket_errno(s))); goto err; } if (listen(s,SOMAXCONN) < 0) { - log_fn(LOG_WARN, "Could not listen on %s:%u: %s", address, usePort, + warn(LD_NET, "Could not listen on %s:%u: %s", address, usePort, tor_socket_strerror(tor_socket_errno(s))); goto err; } @@ -548,12 +550,12 @@ connection_create_listener(const char *listenaddress, uint16_t listenport, conn->port = usePort; 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); goto err; } - log_fn(LOG_DEBUG,"%s listening on port %u.",conn_type_to_string(type), usePort); + debug(LD_NET,"%s listening on port %u.",conn_type_to_string(type), usePort); conn->state = LISTENER_STATE_READY; connection_start_reading(conn); @@ -574,17 +576,17 @@ check_sockaddr_in(struct sockaddr *sa, int len, int level) struct sockaddr_in *sin=(struct sockaddr_in*)sa; if (len != sizeof(struct sockaddr_in)) { - log_fn(level, "Length of address not as expected: %d vs %d", + log_fn(level, LD_NET, "Length of address not as expected: %d vs %d", len,(int)sizeof(struct sockaddr_in)); ok = 0; } if (sa->sa_family != AF_INET) { - log_fn(level, "Family of address not as expected: %d vs %d", + log_fn(level, LD_NET, "Family of address not as expected: %d vs %d", sa->sa_family, AF_INET); ok = 0; } if (sin->sin_addr.s_addr == 0 || sin->sin_port == 0) { - log_fn(level, "Address for new connection has address/port equal to zero."); + log_fn(level, LD_NET, "Address for new connection has address/port equal to zero."); ok = 0; } return ok ? 0 : -1; @@ -613,7 +615,7 @@ connection_handle_listener_read(connection_t *conn, int new_type) int e; if (news>=0) { /* Too many conns to poll. */ - log_fn(LOG_WARN,"Too many connections; couldn't accept connection."); + warn(LD_NET,"Too many connections; couldn't accept connection."); tor_close_socket(news); return 0; } @@ -621,29 +623,29 @@ connection_handle_listener_read(connection_t *conn, int new_type) if (ERRNO_IS_ACCEPT_EAGAIN(e)) { return 0; /* he hung up before we could accept(). that's fine. */ } else if (ERRNO_IS_ACCEPT_RESOURCE_LIMIT(e)) { - log_fn(LOG_NOTICE,"accept failed: %s. Dropping incoming connection.", + notice(LD_NET,"accept failed: %s. Dropping incoming connection.", tor_socket_strerror(e)); return 0; } /* else there was a real error. */ - log_fn(LOG_WARN,"accept() failed: %s. Closing listener.", + warn(LD_NET,"accept() failed: %s. Closing listener.", tor_socket_strerror(e)); connection_mark_for_close(conn); return -1; } - log(LOG_DEBUG,"Connection accepted on socket %d (child of fd %d).",news, conn->s); + debug(LD_NET,"Connection accepted on socket %d (child of fd %d).",news,conn->s); set_socket_nonblocking(news); if (check_sockaddr_in((struct sockaddr*)addrbuf, remotelen, LOG_INFO)<0) { - log_fn(LOG_INFO, "accept() returned a strange address; trying getsockname()."); + info(LD_NET, "accept() returned a strange address; trying getsockname()."); remotelen=256; memset(addrbuf, 0, sizeof(addrbuf)); if (getsockname(news, (struct sockaddr*)addrbuf, &remotelen)<0) { - log_fn(LOG_WARN, "getsockname() failed."); + warn(LD_NET, "getsockname() failed."); } else { if (check_sockaddr_in((struct sockaddr*)addrbuf, remotelen, LOG_WARN)<0) { - log_fn(LOG_WARN,"Something's wrong with this conn. Closing it."); + warn(LD_NET,"Something's wrong with this conn. Closing it."); tor_close_socket(news); return 0; } @@ -656,7 +658,7 @@ connection_handle_listener_read(connection_t *conn, int new_type) /* check sockspolicy to see if we should accept it */ if (socks_policy_permits_address(ntohl(remote.sin_addr.s_addr)) == 0) { tor_inet_ntoa(&remote.sin_addr, tmpbuf, sizeof(tmpbuf)); - log_fn(LOG_NOTICE,"Denying socks connection from untrusted address %s.", + notice(LD_APP,"Denying socks connection from untrusted address %s.", tmpbuf); tor_close_socket(news); return 0; @@ -666,7 +668,7 @@ connection_handle_listener_read(connection_t *conn, int new_type) /* check dirpolicy to see if we should accept it */ if (dir_policy_permits_address(ntohl(remote.sin_addr.s_addr)) == 0) { tor_inet_ntoa(&remote.sin_addr, tmpbuf, sizeof(tmpbuf)); - log_fn(LOG_NOTICE,"Denying dir connection from address %s.", + notice(LD_DIRSERV,"Denying dir connection from address %s.", tmpbuf); tor_close_socket(news); return 0; @@ -736,11 +738,11 @@ connection_connect(connection_t *conn, char *address, s = socket(PF_INET,SOCK_STREAM,IPPROTO_TCP); if (s < 0) { - log_fn(LOG_WARN,"Error creating network socket: %s", + warn(LD_NET,"Error creating network socket: %s", tor_socket_strerror(tor_socket_errno(-1))); return -1; } else if (!SOCKET_IS_POLLABLE(s)) { - log_fn(LOG_WARN, + warn(LD_NET, "Too many connections; can't create pollable connection to %s", safe_str(address)); tor_close_socket(s); @@ -754,11 +756,11 @@ connection_connect(connection_t *conn, char *address, ext_addr.sin_family = AF_INET; ext_addr.sin_port = 0; if (!tor_inet_aton(options->OutboundBindAddress, &ext_addr.sin_addr)) { - log_fn(LOG_WARN,"Outbound bind address '%s' didn't parse. Ignoring.", + warn(LD_CONFIG,"Outbound bind address '%s' didn't parse. Ignoring.", options->OutboundBindAddress); } else { if (bind(s, (struct sockaddr*)&ext_addr, sizeof(ext_addr)) < 0) { - log_fn(LOG_WARN,"Error binding network socket: %s", + warn(LD_NET,"Error binding network socket: %s", tor_socket_strerror(tor_socket_errno(s))); return -1; } @@ -772,13 +774,13 @@ connection_connect(connection_t *conn, char *address, dest_addr.sin_port = htons(port); dest_addr.sin_addr.s_addr = htonl(addr); - log_fn(LOG_DEBUG,"Connecting to %s:%u.",safe_str(address),port); + debug(LD_NET,"Connecting to %s:%u.",safe_str(address),port); if (connect(s,(struct sockaddr *)&dest_addr,sizeof(dest_addr)) < 0) { int e = tor_socket_errno(s); if (!ERRNO_IS_CONN_EINPROGRESS(e)) { /* yuck. kill it. */ - log_fn(LOG_INFO,"Connect() to %s:%u failed: %s",safe_str(address),port, + info(LD_NET,"connect() to %s:%u failed: %s",safe_str(address),port, tor_socket_strerror(e)); tor_close_socket(s); return -1; @@ -791,7 +793,7 @@ connection_connect(connection_t *conn, char *address, client_check_address_changed(s); /* it succeeded. we're connected. */ - log_fn(inprogress?LOG_DEBUG:LOG_INFO, + log_fn(inprogress?LOG_DEBUG:LOG_INFO, LD_NET, "Connection to %s:%u %s (sock %d).",safe_str(address),port, inprogress?"in progress":"established",s); conn->s = s; @@ -854,7 +856,7 @@ retry_listeners(int type, config_line_t *cfg, if (force) { /* It's a listener, and we're relaunching all listeners of this * type. Close this one. */ - log_fn(LOG_NOTICE, "Closing %s on %s:%d", + log_fn(LOG_NOTICE, LD_NET, "Closing %s on %s:%d", conn_type_to_string(type), conn->address, conn->port); connection_close_immediate(conn); connection_mark_for_close(conn); @@ -879,7 +881,7 @@ retry_listeners(int type, config_line_t *cfg, }); if (! line) { /* This one isn't configured. Close it. */ - log_fn(LOG_NOTICE, "Closing %s on %s:%d", + notice(LD_NET, "Closing %s on %s:%d", conn_type_to_string(type), conn->address, conn->port); if (replaced_conns) { smartlist_add(replaced_conns, conn); @@ -889,7 +891,7 @@ retry_listeners(int type, config_line_t *cfg, } } else { /* It's configured; we don't need to launch it. */ - log_fn(LOG_DEBUG, "Already have %s on %s:%d", + debug(LD_NET, "Already have %s on %s:%d", conn_type_to_string(type), conn->address, conn->port); smartlist_remove(launch, line); if (free_launch_elts) @@ -997,7 +999,7 @@ static void connection_consider_empty_buckets(connection_t *conn) { if (global_read_bucket <= 0) { - LOG_FN_CONN(conn, (LOG_DEBUG,"global bucket exhausted. Pausing.")); + LOG_FN_CONN(conn, (LOG_DEBUG,LD_NET,"global bucket exhausted. Pausing.")); conn->wants_to_read = 1; connection_stop_reading(conn); return; @@ -1005,7 +1007,7 @@ connection_consider_empty_buckets(connection_t *conn) if (connection_speaks_cells(conn) && conn->state == OR_CONN_STATE_OPEN && conn->receiver_bucket <= 0) { - LOG_FN_CONN(conn, (LOG_DEBUG,"receiver bucket exhausted. Pausing.")); + LOG_FN_CONN(conn, (LOG_DEBUG,LD_NET,"receiver bucket exhausted. Pausing.")); conn->wants_to_read = 1; connection_stop_reading(conn); } @@ -1033,11 +1035,11 @@ connection_bucket_refill(struct timeval *now) /* refill the global buckets */ if (global_read_bucket < (int)options->BandwidthBurst) { global_read_bucket += (int)options->BandwidthRate; - log_fn(LOG_DEBUG,"global_read_bucket now %d.", global_read_bucket); + debug(LD_NET,"global_read_bucket now %d.", global_read_bucket); } if (global_write_bucket < (int)options->BandwidthBurst) { global_write_bucket += (int)options->BandwidthRate; - log_fn(LOG_DEBUG,"global_write_bucket now %d.", global_write_bucket); + debug(LD_NET,"global_write_bucket now %d.", global_write_bucket); } /* refill the per-connection buckets */ @@ -1058,7 +1060,7 @@ connection_bucket_refill(struct timeval *now) conn->state != OR_CONN_STATE_OPEN || conn->receiver_bucket > 0)) { /* and either a non-cell conn or a cell conn with non-empty bucket */ - LOG_FN_CONN(conn, (LOG_DEBUG,"waking up conn (fd %d)",conn->s)); + LOG_FN_CONN(conn, (LOG_DEBUG,LD_NET,"waking up conn (fd %d)",conn->s)); conn->wants_to_read = 0; connection_start_reading(conn); if (conn->wants_to_write == 1) { @@ -1197,7 +1199,7 @@ connection_read_to_buf(connection_t *conn, int *max_to_read) return connection_tls_continue_handshake(conn); } - log_fn(LOG_DEBUG,"%d: starting, inbuf_datalen %d (%d pending in tls object). at_most %d.", + debug(LD_NET,"%d: starting, inbuf_datalen %d (%d pending in tls object). at_most %d.", conn->s,(int)buf_datalen(conn->inbuf),tor_tls_get_pending_bytes(conn->tls), at_most); /* else open, or closing */ @@ -1205,11 +1207,11 @@ connection_read_to_buf(connection_t *conn, int *max_to_read) switch (result) { case TOR_TLS_CLOSE: - log_fn(LOG_INFO,"TLS connection closed on read. Closing. (Nickname %s, address %s", + info(LD_NET,"TLS connection closed on read. Closing. (Nickname %s, address %s", conn->nickname ? conn->nickname : "not set", conn->address); return -1; case TOR_TLS_ERROR: - log_fn(LOG_DEBUG,"tls error. breaking (nickname %s, address %s).", + info(LD_NET,"tls error. breaking (nickname %s, address %s).", conn->nickname ? conn->nickname : "not set", conn->address); return -1; case TOR_TLS_WANTWRITE: @@ -1229,7 +1231,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(conn->tls, pending, conn->inbuf); if (r2<0) { - log_fn(LOG_WARN, "Bug: apparently, reading pending bytes can fail."); + warn(LD_BUG, "Bug: apparently, reading pending bytes can fail."); return -1; } else { result += r2; @@ -1328,7 +1330,7 @@ connection_handle_write(connection_t *conn) /* Sometimes, "writable" means "connected". */ if (connection_state_is_connecting(conn)) { if (getsockopt(conn->s, SOL_SOCKET, SO_ERROR, (void*)&e, &len) < 0) { - log_fn(LOG_WARN,"getsockopt() syscall failed?! Please report to tor-ops."); + warn(LD_BUG,"getsockopt() syscall failed?! Please report to tor-ops."); if (CONN_IS_EDGE(conn)) connection_edge_end_errno(conn, conn->cpath_layer); connection_mark_for_close(conn); @@ -1337,7 +1339,7 @@ connection_handle_write(connection_t *conn) if (e) { /* some sort of error, but maybe just inprogress still */ if (!ERRNO_IS_CONN_EINPROGRESS(e)) { - log_fn(LOG_INFO,"in-progress connect failed. Removing."); + info(LD_NET,"in-progress connect failed. Removing."); if (CONN_IS_EDGE(conn)) connection_edge_end_errno(conn, conn->cpath_layer); @@ -1374,18 +1376,18 @@ connection_handle_write(connection_t *conn) switch (result) { case TOR_TLS_ERROR: case TOR_TLS_CLOSE: - log_fn(LOG_INFO,result==TOR_TLS_ERROR? + info(LD_NET,result==TOR_TLS_ERROR? "tls error. breaking.":"TLS connection closed on flush"); connection_close_immediate(conn); /* Don't flush; connection is dead. */ connection_mark_for_close(conn); return -1; case TOR_TLS_WANTWRITE: - log_fn(LOG_DEBUG,"wanted write."); + debug(LD_NET,"wanted write."); /* we're already writing */ return 0; case TOR_TLS_WANTREAD: /* Make sure to avoid a loop if the receive buckets are empty. */ - log_fn(LOG_DEBUG,"wanted read."); + debug(LD_NET,"wanted read."); if (!connection_is_reading(conn)) { connection_stop_writing(conn); conn->wants_to_write = 1; @@ -1482,10 +1484,10 @@ connection_write_to_buf(const char *string, size_t len, connection_t *conn) if (CONN_IS_EDGE(conn)) { /* if it failed, it means we have our package/delivery windows set wrong compared to our max outbuf size. close the whole circuit. */ - log_fn(LOG_WARN,"write_to_buf failed. Closing circuit (fd %d).", conn->s); + warn(LD_NET,"write_to_buf failed. Closing circuit (fd %d).", conn->s); circuit_mark_for_close(circuit_get_by_edge_conn(conn)); } else { - log_fn(LOG_WARN,"write_to_buf failed. Closing connection (fd %d).", conn->s); + warn(LD_NET,"write_to_buf failed. Closing connection (fd %d).", conn->s); connection_mark_for_close(conn); } return; @@ -1745,6 +1747,7 @@ connection_state_is_connecting(connection_t *conn) * * Return 0. */ +/*XXXX Why isn't this in connection_or.c?*/ int connection_send_destroy(uint16_t circ_id, connection_t *conn) { @@ -1756,7 +1759,7 @@ connection_send_destroy(uint16_t circ_id, connection_t *conn) memset(&cell, 0, sizeof(cell_t)); cell.circ_id = circ_id; cell.command = CELL_DESTROY; - log_fn(LOG_DEBUG,"Sending destroy (circID %d).", circ_id); + debug(LD_OR,"Sending destroy (circID %d).", circ_id); connection_or_write_cell_to_buf(&cell, conn); return 0; } @@ -1802,7 +1805,7 @@ client_check_address_changed(int sock) if (getsockname(sock, (struct sockaddr*)&out_addr, &out_addr_len)<0) { int e = tor_socket_errno(sock); - log_fn(LOG_WARN, "getsockname() failed: %s", tor_socket_strerror(e)); + warn(LD_NET, "getsockname() failed: %s", tor_socket_strerror(e)); return; } @@ -1825,7 +1828,7 @@ client_check_address_changed(int sock) } else { /* The interface changed. We're a client, so we need to regenerate our * keys. First, reset the state. */ - log_fn(LOG_NOTICE, "Our IP has changed. Rotating keys..."); + notice(LD_NET, "Our IP has changed. Rotating keys..."); last_interface_ip = iface_ip; SMARTLIST_FOREACH(outgoing_addrs, void*, ip, tor_free(ip)); smartlist_clear(outgoing_addrs); @@ -1861,7 +1864,7 @@ connection_process_inbuf(connection_t *conn, int package_partial) case CONN_TYPE_CONTROL: return connection_control_process_inbuf(conn); default: - log_fn(LOG_WARN,"Bug: got unexpected conn type %d.", conn->type); + err(LD_BUG,"Bug: got unexpected conn type %d.", conn->type); tor_fragile_assert(); return -1; } @@ -1895,7 +1898,7 @@ connection_finished_flushing(connection_t *conn) case CONN_TYPE_CONTROL: return connection_control_finished_flushing(conn); default: - log_fn(LOG_WARN,"Bug: got unexpected conn type %d.", conn->type); + err(LD_BUG,"Bug: got unexpected conn type %d.", conn->type); tor_fragile_assert(); return -1; } @@ -1920,7 +1923,7 @@ connection_finished_connecting(connection_t *conn) case CONN_TYPE_DIR: return connection_dir_finished_connecting(conn); default: - log_fn(LOG_WARN,"Bug: got unexpected conn type %d.", conn->type); + err(LD_BUG,"Bug: got unexpected conn type %d.", conn->type); tor_fragile_assert(); return -1; } @@ -1945,7 +1948,7 @@ connection_reached_eof(connection_t *conn) case CONN_TYPE_CONTROL: return connection_control_reached_eof(conn); default: - log_fn(LOG_WARN,"Bug: got unexpected conn type %d.", conn->type); + err(LD_BUG,"Bug: got unexpected conn type %d.", conn->type); tor_fragile_assert(); return -1; } diff --git a/src/or/relay.c b/src/or/relay.c index d336ed2518..a352d9efbb 100644 --- a/src/or/relay.c +++ b/src/or/relay.c @@ -11,6 +11,7 @@ const char relay_c_id[] = "$Id$"; * receiving from circuits. **/ +#define NEW_LOG_INTERFACE #include "or.h" static int relay_crypt(circuit_t *circ, cell_t *cell, int cell_direction, @@ -116,7 +117,7 @@ relay_crypt_one_payload(crypto_cipher_env_t *cipher, char *in, if (( encrypt_mode && crypto_cipher_encrypt(cipher, out, in, CELL_PAYLOAD_SIZE)) || (!encrypt_mode && crypto_cipher_decrypt(cipher, out, in, CELL_PAYLOAD_SIZE))) { - log_fn(LOG_WARN,"Error during relay encryption"); + warn(LD_BUG,"Error during relay encryption"); return -1; } memcpy(in,out,CELL_PAYLOAD_SIZE); @@ -147,7 +148,7 @@ circuit_receive_relay_cell(cell_t *cell, circuit_t *circ, int cell_direction) return 0; if (relay_crypt(circ, cell, cell_direction, &layer_hint, &recognized) < 0) { - log_fn(LOG_WARN,"relay crypt failed. Dropping connection."); + warn(LD_BUG,"relay crypt failed. Dropping connection."); return -1; } @@ -155,17 +156,18 @@ circuit_receive_relay_cell(cell_t *cell, circuit_t *circ, int cell_direction) conn = relay_lookup_conn(circ, cell, cell_direction); if (cell_direction == CELL_DIRECTION_OUT) { ++stats_n_relay_cells_delivered; - log_fn(LOG_DEBUG,"Sending away from origin."); + debug(LD_OR,"Sending away from origin."); if (connection_edge_process_relay_cell(cell, circ, conn, NULL) < 0) { - log_fn(LOG_PROTOCOL_WARN,"connection_edge_process_relay_cell (away from origin) failed."); + log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL, + "connection_edge_process_relay_cell (away from origin) failed."); return -1; } } if (cell_direction == CELL_DIRECTION_IN) { ++stats_n_relay_cells_delivered; - log_fn(LOG_DEBUG,"Sending to origin."); + debug(LD_OR,"Sending to origin."); if (connection_edge_process_relay_cell(cell, circ, conn, layer_hint) < 0) { - log_fn(LOG_WARN,"connection_edge_process_relay_cell (at origin) failed."); + warn(LD_OR,"connection_edge_process_relay_cell (at origin) failed."); return -1; } } @@ -187,17 +189,17 @@ circuit_receive_relay_cell(cell_t *cell, circuit_t *circ, int cell_direction) tor_assert(circ->rend_splice->purpose == CIRCUIT_PURPOSE_REND_ESTABLISHED); cell->circ_id = circ->rend_splice->p_circ_id; if (circuit_receive_relay_cell(cell, circ->rend_splice, CELL_DIRECTION_IN)<0) { - log_fn(LOG_WARN, "Error relaying cell across rendezvous; closing circuits"); + warn(LD_REND, "Error relaying cell across rendezvous; closing circuits"); circuit_mark_for_close(circ); /* XXXX Do this here, or just return -1? */ return -1; } return 0; } - log_fn(LOG_PROTOCOL_WARN,"Didn't recognize cell, but circ stops here! Closing circ."); + log_fn(LOG_PROTOCOL_WARN,LD_PROTOCOL,"Didn't recognize cell, but circ stops here! Closing circ."); return -1; } - log_fn(LOG_DEBUG,"Passing on unrecognized cell."); + debug(LD_OR,"Passing on unrecognized cell."); ++stats_n_relay_cells_relayed; connection_or_write_cell_to_buf(cell, conn); return 0; @@ -240,7 +242,7 @@ relay_crypt(circuit_t *circ, cell_t *cell, int cell_direction, tor_assert(circ->cpath); thishop = circ->cpath; if (thishop->state != CPATH_STATE_OPEN) { - log_fn(LOG_WARN,"Relay cell before first created cell? Closing."); + log_fn(LOG_PROTOCOL_WARN,LD_PROTOCOL,"Relay cell before first created cell? Closing."); return -1; } do { /* Remember: cpath is in forward order, that is, first hop first. */ @@ -261,7 +263,7 @@ relay_crypt(circuit_t *circ, cell_t *cell, int cell_direction, thishop = thishop->next; } while (thishop != circ->cpath && thishop->state == CPATH_STATE_OPEN); - log_fn(LOG_WARN,"in-cell at OP not recognized. Closing."); + warn(LD_OR,"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) @@ -301,7 +303,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_WARN,"outgoing relay cell has n_conn==NULL. Dropping."); + warn(LD_BUG,"outgoing relay cell has n_conn==NULL. Dropping."); return 0; /* just drop it */ } relay_set_digest(layer_hint->f_digest, cell); @@ -310,8 +312,8 @@ circuit_package_relay_cell(cell_t *cell, circuit_t *circ, /* moving from farthest to nearest hop */ do { tor_assert(thishop); - - log_fn(LOG_DEBUG,"crypting a layer of the relay cell."); + /* XXXX RD This is a bug, right? */ + debug(LD_OR,"crypting a layer of the relay cell."); if (relay_crypt_one_payload(thishop->f_crypto, cell->payload, 1) < 0) { return -1; } @@ -322,7 +324,8 @@ circuit_package_relay_cell(cell_t *cell, circuit_t *circ, } else { /* incoming cell */ conn = circ->p_conn; if (!conn) { - log_fn(LOG_WARN,"incoming relay cell has p_conn==NULL. Dropping."); + /* XXXX RD This is a bug, right? */ + warn(LD_BUG,"incoming relay cell has p_conn==NULL. Dropping."); return 0; /* just drop it */ } relay_set_digest(circ->p_digest, cell); @@ -354,7 +357,7 @@ relay_lookup_conn(circuit_t *circ, cell_t *cell, int cell_direction) for (tmpconn = circ->n_streams; tmpconn; tmpconn=tmpconn->next_stream) { if (rh.stream_id == tmpconn->stream_id && !tmpconn->marked_for_close) { - log_fn(LOG_DEBUG,"found conn for stream %d.", rh.stream_id); + debug(LD_EXIT,"found conn for stream %d.", rh.stream_id); if (cell_direction == CELL_DIRECTION_OUT || connection_edge_is_rendezvous_stream(tmpconn)) return tmpconn; @@ -362,13 +365,13 @@ relay_lookup_conn(circuit_t *circ, cell_t *cell, int cell_direction) } for (tmpconn = circ->p_streams; tmpconn; tmpconn=tmpconn->next_stream) { if (rh.stream_id == tmpconn->stream_id && !tmpconn->marked_for_close) { - log_fn(LOG_DEBUG,"found conn for stream %d.", rh.stream_id); + debug(LD_APP,"found conn for stream %d.", rh.stream_id); return tmpconn; } } for (tmpconn = circ->resolving_streams; tmpconn; tmpconn=tmpconn->next_stream) { if (rh.stream_id == tmpconn->stream_id && !tmpconn->marked_for_close) { - log_fn(LOG_DEBUG,"found conn for stream %d.", rh.stream_id); + debug(LD_EXIT,"found conn for stream %d.", rh.stream_id); return tmpconn; } } @@ -423,17 +426,18 @@ connection_edge_send_command(connection_t *fromconn, circuit_t *circ, int cell_direction; if (fromconn && fromconn->marked_for_close) { - log_fn(LOG_WARN,"Bug: called on conn that's already marked for close at %s:%d.", + warn(LD_BUG,"Bug: called on conn that's already marked for close at %s:%d.", fromconn->marked_for_close_file, fromconn->marked_for_close); return 0; } if (!circ) { - log_fn(LOG_INFO,"no circ. Closing conn."); tor_assert(fromconn); if (fromconn->type == CONN_TYPE_AP) { + info(LD_APP,"no circ. Closing conn."); connection_mark_unattached_ap(fromconn, END_STREAM_REASON_INTERNAL); } else { + info(LD_EXIT,"no circ. Closing conn."); fromconn->has_sent_end = 1; /* no circ to send to */ connection_mark_for_close(fromconn); } @@ -461,11 +465,11 @@ connection_edge_send_command(connection_t *fromconn, circuit_t *circ, memcpy(cell.payload+RELAY_HEADER_SIZE, payload, payload_len); } - log_fn(LOG_DEBUG,"delivering %d cell %s.", relay_command, + debug(LD_OR,"delivering %d cell %s.", relay_command, cell_direction == CELL_DIRECTION_OUT ? "forward" : "backward"); if (circuit_package_relay_cell(&cell, circ, cell_direction, cpath_layer) < 0) { - log_fn(LOG_WARN,"circuit_package_relay_cell failed. Closing."); + warn(LD_BUG,"circuit_package_relay_cell failed. Closing."); circuit_mark_for_close(circ); return -1; } @@ -481,7 +485,7 @@ connection_edge_end_reason_str(int reason) { switch (reason) { case -1: - log_fn(LOG_WARN,"End cell arrived with length 0. Should be at least 1."); + warn(LD_PROTOCOL,"End cell arrived with length 0. Should be at least 1."); return "MALFORMED"; case END_STREAM_REASON_MISC: return "misc error"; case END_STREAM_REASON_RESOLVEFAILED: return "resolve failed"; @@ -496,7 +500,7 @@ connection_edge_end_reason_str(int reason) case END_STREAM_REASON_CONNRESET: return "connection reset"; case END_STREAM_REASON_TORPROTOCOL: return "Tor protocol error"; default: - log_fn(LOG_WARN,"Reason for ending (%d) not recognized.",reason); + warn(LD_PROTOCOL,"Reason for ending (%d) not recognized.",reason); return "unknown"; } } @@ -540,7 +544,7 @@ connection_edge_end_reason_socks5_response(int reason) case END_STREAM_REASON_NET_UNREACHABLE: return SOCKS5_NET_UNREACHABLE; default: - log_fn(LOG_WARN,"Reason for ending (%d) not recognized.",reason); + warn(LD_PROTOCOL,"Reason for ending (%d) not recognized.",reason); return SOCKS5_GENERAL_ERROR; } } @@ -590,8 +594,8 @@ errno_to_end_reason(int e) E_CASE(EMFILE): return END_STREAM_REASON_RESOURCELIMIT; default: - log_fn(LOG_INFO, "Didn't recognize errno %d (%s); telling the OP that we are ending a stream for 'misc' reason.", - e, tor_socket_strerror(e)); + info(LD_EXIT, "Didn't recognize errno %d (%s); telling the OP that we are ending a stream for 'misc' reason.", + e, tor_socket_strerror(e)); return END_STREAM_REASON_MISC; } } @@ -627,13 +631,13 @@ connection_edge_process_end_not_open( if (rh->length > 0 && edge_reason_is_retriable(reason)) { if (conn->type != CONN_TYPE_AP) { - log_fn(LOG_WARN,"Got an end because of %s, but we're not an AP. Closing.", + warn(LD_PROTOCOL,"Got an end because of %s, but we're not an AP. Closing.", connection_edge_end_reason_str(reason)); return -1; } - log_fn(LOG_INFO,"Address '%s' refused due to '%s'. Considering retrying.", - safe_str(conn->socks_request->address), - connection_edge_end_reason_str(reason)); + info(LD_APP,"Address '%s' refused due to '%s'. Considering retrying.", + safe_str(conn->socks_request->address), + connection_edge_end_reason_str(reason)); exitrouter = router_get_by_digest(circ->build_state->chosen_exit->identity_digest); switch (reason) { @@ -642,7 +646,7 @@ connection_edge_process_end_not_open( uint32_t addr = ntohl(get_uint32(cell->payload+RELAY_HEADER_SIZE+1)); int ttl; if (!addr) { - log_fn(LOG_INFO,"Address '%s' resolved to 0.0.0.0. Closing,", + info(LD_APP,"Address '%s' resolved to 0.0.0.0. Closing,", safe_str(conn->socks_request->address)); connection_mark_unattached_ap(conn, END_STREAM_REASON_TORPROTOCOL); return 0; @@ -659,7 +663,7 @@ connection_edge_process_end_not_open( (rh->length < 5 || (tor_inet_aton(conn->socks_request->address, &in) && !conn->chosen_exit_name))) { - log_fn(LOG_NOTICE,"Exitrouter '%s' seems to be more restrictive than its exit policy. Not using this router as exit for now.", exitrouter->nickname); + notice(LD_APP,"Exitrouter '%s' seems to be more restrictive than its exit policy. Not using this router as exit for now.", exitrouter->nickname); addr_policy_free(exitrouter->exit_policy); exitrouter->exit_policy = router_parse_addr_policy_from_string("reject *:*", -1); @@ -684,7 +688,7 @@ connection_edge_process_end_not_open( return 0; /* else, conn will get closed below */ } else { - log_fn(LOG_NOTICE,"Have tried resolving address '%s' at %d different places. Giving up.", + notice(LD_APP,"Have tried resolving address '%s' at %d different places. Giving up.", safe_str(conn->socks_request->address), MAX_RESOLVE_FAILURES); /* clear the failures, so it will have a full try next time */ client_dns_clear_failures(conn->socks_request->address); @@ -702,10 +706,10 @@ connection_edge_process_end_not_open( /* else, will close below */ break; } /* end switch */ - log_fn(LOG_INFO,"Giving up on retrying; conn can't be handled."); + info(LD_APP,"Giving up on retrying; conn can't be handled."); } - log_fn(LOG_INFO,"Edge got end (%s) before we're connected. Marking for close.", + info(LD_APP,"Edge got end (%s) before we're connected. Marking for close.", connection_edge_end_reason_str(rh->length > 0 ? reason : -1)); if (conn->type == CONN_TYPE_AP) { circuit_log_path(LOG_INFO,LD_APP,circ); @@ -734,18 +738,18 @@ connection_edge_process_relay_cell_not_open( if (conn->type == CONN_TYPE_AP && rh->command == RELAY_COMMAND_CONNECTED) { if (conn->state != AP_CONN_STATE_CONNECT_WAIT) { - log_fn(LOG_WARN,"Got 'connected' while not in state connect_wait. Dropping."); + warn(LD_APP,"Got 'connected' while not in state connect_wait. Dropping."); return 0; } // log_fn(LOG_INFO,"Connected! Notifying application."); conn->state = AP_CONN_STATE_OPEN; - log_fn(LOG_INFO,"'connected' received after %d seconds.", + info(LD_APP,"'connected' received after %d seconds.", (int)(time(NULL) - conn->timestamp_lastread)); if (rh->length >= 4) { uint32_t addr = ntohl(get_uint32(cell->payload+RELAY_HEADER_SIZE)); int ttl; if (!addr) { - log_fn(LOG_INFO,"...but it claims the IP address was 0.0.0.0. Closing."); + info(LD_APP,"...but it claims the IP address was 0.0.0.0. Closing."); connection_edge_end(conn, END_STREAM_REASON_TORPROTOCOL, conn->cpath_layer); connection_mark_unattached_ap(conn, END_STREAM_REASON_TORPROTOCOL); return 0; @@ -771,13 +775,13 @@ connection_edge_process_relay_cell_not_open( int ttl; int answer_len; if (conn->state != AP_CONN_STATE_RESOLVE_WAIT) { - log_fn(LOG_WARN,"Got a 'resolved' cell while not in state resolve_wait. Dropping."); + warn(LD_APP,"Got a 'resolved' cell while not in state resolve_wait. Dropping."); return 0; } tor_assert(conn->socks_request->command == SOCKS_COMMAND_RESOLVE); answer_len = cell->payload[RELAY_HEADER_SIZE+1]; if (rh->length < 2 || answer_len+2>rh->length) { - log_fn(LOG_WARN, "Dropping malformed 'resolved' cell"); + warn(LD_PROTOCOL, "Dropping malformed 'resolved' cell"); connection_mark_unattached_ap(conn, END_STREAM_REASON_TORPROTOCOL); return 0; } @@ -794,8 +798,9 @@ connection_edge_process_relay_cell_not_open( return 0; } - log_fn(LOG_WARN,"Got an unexpected relay command %d, in state %d (%s). Closing.", - rh->command, conn->state, conn_state_to_string(conn->type, conn->state)); + warn(LD_PROTOCOL, + "Got an unexpected relay command %d, in state %d (%s). Closing.", + rh->command, conn->state, conn_state_to_string(conn->type, conn->state)); connection_edge_end(conn, END_STREAM_REASON_TORPROTOCOL, conn->cpath_layer); connection_mark_for_close(conn); return -1; @@ -817,6 +822,7 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ, { static int num_seen=0; relay_header_t rh; + unsigned domain = layer_hint?LD_APP:LD_EXIT; tor_assert(cell); tor_assert(circ); @@ -824,10 +830,10 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ, relay_header_unpack(&rh, cell->payload); // log_fn(LOG_DEBUG,"command %d stream %d", rh.command, rh.stream_id); num_seen++; - log_fn(LOG_DEBUG,"Now seen %d relay cells here.", num_seen); + debug(domain, "Now seen %d relay cells here.", num_seen); if (rh.length > RELAY_PAYLOAD_SIZE) { - log_fn(LOG_WARN, "Relay cell length field too long. Closing circuit."); + warn(LD_PROTOCOL, "Relay cell length field too long. Closing circuit."); return -1; } @@ -840,16 +846,16 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ, switch (rh.command) { case RELAY_COMMAND_DROP: - log_fn(LOG_INFO,"Got a relay-level padding cell. Dropping."); + info(domain,"Got a relay-level padding cell. Dropping."); return 0; case RELAY_COMMAND_BEGIN: if (layer_hint && circ->purpose != CIRCUIT_PURPOSE_S_REND_JOINED) { - log_fn(LOG_WARN,"relay begin request unsupported at AP. Dropping."); + warn(LD_APP,"relay begin request unsupported at AP. Dropping."); return 0; } if (conn) { - log_fn(LOG_WARN,"begin cell for known stream. Dropping."); + warn(domain,"begin cell for known stream. Dropping."); return 0; } connection_exit_begin_conn(cell, circ); @@ -858,25 +864,25 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ, ++stats_n_data_cells_received; if (( layer_hint && --layer_hint->deliver_window < 0) || (!layer_hint && --circ->deliver_window < 0)) { - log_fn(LOG_PROTOCOL_WARN, + log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL, "(relay data) circ deliver_window below 0. Killing."); connection_edge_end(conn, END_STREAM_REASON_TORPROTOCOL, conn->cpath_layer); connection_mark_for_close(conn); return -1; } - log_fn(LOG_DEBUG,"circ deliver_window now %d.", layer_hint ? + debug(domain,"circ deliver_window now %d.", layer_hint ? layer_hint->deliver_window : circ->deliver_window); circuit_consider_sending_sendme(circ, layer_hint); if (!conn) { - log_fn(LOG_INFO,"data cell dropped, unknown stream."); + info(domain,"data cell dropped, unknown stream."); return 0; } if (--conn->deliver_window < 0) { /* is it below 0 after decrement? */ - log_fn(LOG_PROTOCOL_WARN, + log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL, "(relay data) conn deliver_window below 0. Killing."); return -1; /* somebody's breaking protocol. kill the whole circuit. */ } @@ -888,19 +894,19 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ, return 0; case RELAY_COMMAND_END: if (!conn) { - log_fn(LOG_INFO,"end cell (%s) dropped, unknown stream.", + info(domain,"end cell (%s) dropped, unknown stream.", connection_edge_end_reason_str(rh.length > 0 ? *(char *)(cell->payload+RELAY_HEADER_SIZE) : -1)); return 0; } /* XXX add to this log_fn the exit node's nickname? */ - log_fn(LOG_INFO,"%d: end cell (%s) for stream %d. Removing stream.", - conn->s, - connection_edge_end_reason_str(rh.length > 0 ? + info(domain,"%d: end cell (%s) for stream %d. Removing stream.", + conn->s, + connection_edge_end_reason_str(rh.length > 0 ? *(char *)(cell->payload+RELAY_HEADER_SIZE) : -1), - conn->stream_id); + conn->stream_id); if (conn->socks_request && !conn->socks_request->has_finished) - log_fn(LOG_WARN,"Bug: open stream hasn't sent socks answer yet? Closing."); + warn(LD_BUG,"Bug: open stream hasn't sent socks answer yet? Closing."); #ifdef HALF_OPEN conn->done_sending = 1; shutdown(conn->s, 1); /* XXX check return; refactor NM */ @@ -923,71 +929,71 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ, return 0; case RELAY_COMMAND_EXTEND: if (conn) { - log_fn(LOG_WARN,"'extend' for non-zero stream. Dropping."); + warn(domain,"'extend' for non-zero stream. Dropping."); return 0; } return circuit_extend(cell, circ); case RELAY_COMMAND_EXTENDED: if (!layer_hint) { - log_fn(LOG_WARN,"'extended' unsupported at non-origin. Dropping."); + warn(LD_PROTOCOL,"'extended' unsupported at non-origin. Dropping."); return 0; } - log_fn(LOG_DEBUG,"Got an extended cell! Yay."); + debug(domain,"Got an extended cell! Yay."); if (circuit_finish_handshake(circ, CELL_CREATED, cell->payload+RELAY_HEADER_SIZE) < 0) { - log_fn(LOG_WARN,"circuit_finish_handshake failed."); + warn(domain,"circuit_finish_handshake failed."); return -1; } if (circuit_send_next_onion_skin(circ)<0) { - log_fn(LOG_INFO,"circuit_send_next_onion_skin() failed."); + info(domain,"circuit_send_next_onion_skin() failed."); return -1; } return 0; case RELAY_COMMAND_TRUNCATE: if (layer_hint) { - log_fn(LOG_WARN,"'truncate' unsupported at origin. Dropping."); + warn(LD_APP,"'truncate' unsupported at origin. Dropping."); return 0; } if (circ->n_conn) { connection_send_destroy(circ->n_circ_id, circ->n_conn); circuit_set_circid_orconn(circ, 0, NULL, N_CONN_CHANGED); } - log_fn(LOG_DEBUG, "Processed 'truncate', replying."); + debug(LD_EXIT, "Processed 'truncate', replying."); connection_edge_send_command(NULL, circ, RELAY_COMMAND_TRUNCATED, NULL, 0, NULL); return 0; case RELAY_COMMAND_TRUNCATED: if (!layer_hint) { - log_fn(LOG_WARN,"'truncated' unsupported at non-origin. Dropping."); + warn(LD_EXIT,"'truncated' unsupported at non-origin. Dropping."); return 0; } circuit_truncated(circ, layer_hint); return 0; case RELAY_COMMAND_CONNECTED: if (conn) { - log_fn(LOG_PROTOCOL_WARN, + log_fn(LOG_PROTOCOL_WARN, LD_PROTOCOL, "'connected' unsupported while open. Closing circ."); return -1; } - log_fn(LOG_INFO,"'connected' received, no conn attached anymore. Ignoring."); + info(domain,"'connected' received, no conn attached anymore. Ignoring."); return 0; case RELAY_COMMAND_SENDME: if (!conn) { if (layer_hint) { layer_hint->package_window += CIRCWINDOW_INCREMENT; - log_fn(LOG_DEBUG,"circ-level sendme at origin, packagewindow %d.", + debug(LD_APP,"circ-level sendme at origin, packagewindow %d.", layer_hint->package_window); circuit_resume_edge_reading(circ, layer_hint); } else { circ->package_window += CIRCWINDOW_INCREMENT; - log_fn(LOG_DEBUG,"circ-level sendme at non-origin, packagewindow %d.", + debug(LD_APP,"circ-level sendme at non-origin, packagewindow %d.", circ->package_window); circuit_resume_edge_reading(circ, layer_hint); } return 0; } conn->package_window += STREAMWINDOW_INCREMENT; - log_fn(LOG_DEBUG,"stream-level sendme, packagewindow now %d.", conn->package_window); + debug(domain,"stream-level sendme, packagewindow now %d.", conn->package_window); connection_start_reading(conn); /* handle whatever might still be on the inbuf */ if (connection_edge_package_raw_inbuf(conn, 1) < 0) { @@ -998,13 +1004,13 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ, return 0; case RELAY_COMMAND_RESOLVE: if (layer_hint) { - log_fn(LOG_WARN,"resolve request unsupported at AP; dropping."); + warn(LD_APP,"resolve request unsupported at AP; dropping."); return 0; } else if (conn) { - log_fn(LOG_WARN, "resolve request for known stream; dropping."); + warn(domain, "resolve request for known stream; dropping."); return 0; } else if (circ->purpose != CIRCUIT_PURPOSE_OR) { - log_fn(LOG_WARN, "resolve request on circ with purpose %d; dropping", + warn(domain, "resolve request on circ with purpose %d; dropping", circ->purpose); return 0; } @@ -1012,10 +1018,10 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ, return 0; case RELAY_COMMAND_RESOLVED: if (conn) { - log_fn(LOG_WARN,"'resolved' unsupported while open. Closing circ."); + warn(domain,"'resolved' unsupported while open. Closing circ."); return -1; } - log_fn(LOG_INFO,"'resolved' received, no conn attached anymore. Ignoring."); + info(domain,"'resolved' received, no conn attached anymore. Ignoring."); return 0; case RELAY_COMMAND_ESTABLISH_INTRO: case RELAY_COMMAND_ESTABLISH_RENDEZVOUS: @@ -1030,7 +1036,7 @@ connection_edge_process_relay_cell(cell_t *cell, circuit_t *circ, cell->payload+RELAY_HEADER_SIZE); return 0; } - log_fn(LOG_WARN,"unknown relay command %d.",rh.command); + warn(LD_PROTOCOL,"unknown relay command %d.",rh.command); return -1; } @@ -1052,11 +1058,12 @@ connection_edge_package_raw_inbuf(connection_t *conn, int package_partial) size_t amount_to_process, length; char payload[CELL_PAYLOAD_SIZE]; circuit_t *circ; + unsigned domain = conn->cpath_layer ? LD_APP : LD_EXIT; tor_assert(conn); tor_assert(!connection_speaks_cells(conn)); if (conn->marked_for_close) { - log_fn(LOG_WARN,"Bug: called on conn that's already marked for close at %s:%d.", + warn(LD_BUG,"Bug: called on conn that's already marked for close at %s:%d.", conn->marked_for_close_file, conn->marked_for_close); return 0; } @@ -1065,7 +1072,7 @@ repeat_connection_edge_package_raw_inbuf: circ = circuit_get_by_edge_conn(conn); if (!circ) { - log_fn(LOG_INFO,"conn has no circuit! Closing."); + info(domain,"conn has no circuit! Closing."); return -1; } @@ -1073,7 +1080,7 @@ repeat_connection_edge_package_raw_inbuf: return 0; if (conn->package_window <= 0) { - log_fn(LOG_INFO,"called with package_window %d. Skipping.", conn->package_window); + info(domain,"called with package_window %d. Skipping.", conn->package_window); connection_stop_reading(conn); return 0; } @@ -1096,7 +1103,7 @@ repeat_connection_edge_package_raw_inbuf: connection_fetch_from_buf(payload, length, conn); - log_fn(LOG_DEBUG,"(%d) Packaging %d bytes (%d waiting).", conn->s, + debug(domain,"(%d) Packaging %d bytes (%d waiting).", conn->s, (int)length, (int)buf_datalen(conn->inbuf)); if (connection_edge_send_command(conn, circ, RELAY_COMMAND_DATA, @@ -1114,11 +1121,11 @@ repeat_connection_edge_package_raw_inbuf: if (--conn->package_window <= 0) { /* is it 0 after decrement? */ connection_stop_reading(conn); - log_fn(LOG_DEBUG,"conn->package_window reached 0."); + debug(domain,"conn->package_window reached 0."); circuit_consider_stop_edge_reading(circ, conn->cpath_layer); return 0; /* don't process the inbuf any more */ } - log_fn(LOG_DEBUG,"conn->package_window is now %d",conn->package_window); + debug(domain,"conn->package_window is now %d",conn->package_window); /* handle more if there's more, or return 0 if there isn't */ goto repeat_connection_edge_package_raw_inbuf; @@ -1142,16 +1149,16 @@ connection_edge_consider_sending_sendme(connection_t *conn) if (!circ) { /* this can legitimately happen if the destroy has already * arrived and torn down the circuit */ - log_fn(LOG_INFO,"No circuit associated with conn. Skipping."); + info(LD_APP,"No circuit associated with conn. Skipping."); return; } while (conn->deliver_window < STREAMWINDOW_START - STREAMWINDOW_INCREMENT) { - log_fn(LOG_DEBUG,"Outbuf %d, Queueing stream sendme.", (int)conn->outbuf_flushlen); + debug(conn->cpath_layer?LD_APP:LD_EXIT,"Outbuf %d, Queueing stream sendme.", (int)conn->outbuf_flushlen); conn->deliver_window += STREAMWINDOW_INCREMENT; if (connection_edge_send_command(conn, circ, RELAY_COMMAND_SENDME, NULL, 0, conn->cpath_layer) < 0) { - log_fn(LOG_WARN,"connection_edge_send_command failed. Returning."); + warn(LD_APP,"connection_edge_send_command failed. Returning."); return; /* the circuit's closed, don't continue */ } } @@ -1166,7 +1173,7 @@ static void circuit_resume_edge_reading(circuit_t *circ, crypt_path_t *layer_hint) { - log_fn(LOG_DEBUG,"resuming"); + debug(layer_hint?LD_APP:LD_EXIT,"resuming"); /* have to check both n_streams and p_streams, to handle rendezvous */ if (circuit_resume_edge_reading_helper(circ->n_streams, circ, layer_hint) >= 0) @@ -1215,11 +1222,12 @@ static int circuit_consider_stop_edge_reading(circuit_t *circ, crypt_path_t *layer_hint) { connection_t *conn = NULL; + unsigned domain = conn->cpath_layer ? LD_APP : LD_EXIT; if (!layer_hint) { - log_fn(LOG_DEBUG,"considering circ->package_window %d", circ->package_window); + debug(domain,"considering circ->package_window %d", circ->package_window); if (circ->package_window <= 0) { - log_fn(LOG_DEBUG,"yes, not-at-origin. stopped."); + debug(domain,"yes, not-at-origin. stopped."); for (conn = circ->n_streams; conn; conn=conn->next_stream) connection_stop_reading(conn); return 1; @@ -1227,9 +1235,9 @@ circuit_consider_stop_edge_reading(circuit_t *circ, crypt_path_t *layer_hint) return 0; } /* else, layer hint is defined, use it */ - log_fn(LOG_DEBUG,"considering layer_hint->package_window %d", layer_hint->package_window); + debug(domain,"considering layer_hint->package_window %d", layer_hint->package_window); if (layer_hint->package_window <= 0) { - log_fn(LOG_DEBUG,"yes, at-origin. stopped."); + debug(domain,"yes, at-origin. stopped."); for (conn = circ->n_streams; conn; conn=conn->next_stream) if (conn->cpath_layer == layer_hint) connection_stop_reading(conn); @@ -1254,14 +1262,14 @@ circuit_consider_sending_sendme(circuit_t *circ, crypt_path_t *layer_hint) // layer_hint ? "defined" : "null"); while ((layer_hint ? layer_hint->deliver_window : circ->deliver_window) < CIRCWINDOW_START - CIRCWINDOW_INCREMENT) { - log_fn(LOG_DEBUG,"Queueing circuit sendme."); + debug(LD_CIRC,"Queueing circuit sendme."); if (layer_hint) layer_hint->deliver_window += CIRCWINDOW_INCREMENT; else 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. Circuit's closed."); + warn(LD_CIRC,"connection_edge_send_command failed. Circuit's closed."); return; /* the circuit's closed, don't continue */ } } diff --git a/src/or/router.c b/src/or/router.c index 7e824a0193..3531d9024f 100644 --- a/src/or/router.c +++ b/src/or/router.c @@ -136,11 +136,11 @@ rotate_onion_key(void) tor_snprintf(fname_prev,sizeof(fname_prev), "%s/keys/secret_onion_key.old",get_options()->DataDirectory); if (!(prkey = crypto_new_pk_env())) { - err("Error creating crypto environment."); + err(LD_GENERAL,"Error creating crypto environment."); goto error; } if (crypto_pk_generate_key(prkey)) { - err("Error generating onion key"); + err(LD_BUG,"Error generating onion key"); goto error; } if (file_status(fname) == FN_FILE) { @@ -148,7 +148,7 @@ rotate_onion_key(void) goto error; } if (crypto_pk_write_private_key_to_filename(prkey, fname)) { - err("Couldn't write generated key to \"%s\".", fname); + err(LD_FS,"Couldn't write generated key to \"%s\".", fname); goto error; } info(LD_GENERAL, "Rotating onion key"); @@ -196,34 +196,34 @@ init_key_from_file(const char *fname) FILE *file = NULL; if (!(prkey = crypto_new_pk_env())) { - err("Error creating crypto environment."); + err(LD_GENERAL,"Error creating crypto environment."); goto error; } switch (file_status(fname)) { case FN_DIR: case FN_ERROR: - err("Can't read key from \"%s\"", fname); + err(LD_FS,"Can't read key from \"%s\"", fname); goto error; case FN_NOENT: info(LD_GENERAL, "No key found in \"%s\"; generating fresh key.", fname); if (crypto_pk_generate_key(prkey)) { - err("Error generating onion key"); + err(LD_GENERAL,"Error generating onion key"); goto error; } if (crypto_pk_check_key(prkey) <= 0) { - err("Generated key seems invalid"); + err(LD_GENERAL,"Generated key seems invalid"); goto error; } info(LD_GENERAL, "Generated key seems valid"); if (crypto_pk_write_private_key_to_filename(prkey, fname)) { - err("Couldn't write generated key to \"%s\".", fname); + err(LD_FS,"Couldn't write generated key to \"%s\".", fname); goto error; } return prkey; case FN_FILE: if (crypto_pk_read_private_key_from_filename(prkey, fname)) { - err("Error loading private key."); + err(LD_GENERAL,"Error loading private key."); goto error; } return prkey; @@ -274,7 +274,7 @@ init_keys(void) if (tor_tls_context_new(get_identity_key(), 1, options->Nickname ? options->Nickname : "client", MAX_SSL_KEY_LIFETIME) < 0) { - err("Error creating TLS context for OP."); + err(LD_GENERAL,"Error creating TLS context for OP."); return -1; } return 0; @@ -315,25 +315,25 @@ init_keys(void) /* 3. Initialize link key and TLS context. */ if (tor_tls_context_new(get_identity_key(), 1, options->Nickname, MAX_SSL_KEY_LIFETIME) < 0) { - err("Error initializing TLS context"); + err(LD_GENERAL,"Error initializing TLS context"); return -1; } /* 4. Dump router descriptor to 'router.desc' */ /* Must be called after keys are initialized. */ mydesc = router_get_my_descriptor(); if (!mydesc) { - err("Error initializing descriptor."); + err(LD_GENERAL,"Error initializing descriptor."); return -1; } if (authdir_mode(options)) { const char *m; /* We need to add our own fingerprint so it gets recognized. */ if (dirserv_add_own_fingerprint(options->Nickname, get_identity_key())) { - err("Error adding own fingerprint to approved set"); + err(LD_GENERAL,"Error adding own fingerprint to approved set"); return -1; } if (dirserv_add_descriptor(mydesc, &m) < 0) { - err("Unable to add own descriptor to directory: %s", + err(LD_GENERAL,"Unable to add own descriptor to directory: %s", m?m:"<unknown error>"); return -1; } @@ -348,24 +348,26 @@ init_keys(void) tor_snprintf(keydir,sizeof(keydir),"%s/fingerprint", datadir); info(LD_GENERAL,"Dumping fingerprint to \"%s\"...",keydir); if (crypto_pk_get_fingerprint(get_identity_key(), fingerprint, 1)<0) { - err("Error computing fingerprint"); + err(LD_GENERAL,"Error computing fingerprint"); return -1; } tor_assert(strlen(options->Nickname) <= MAX_NICKNAME_LEN); if (tor_snprintf(fingerprint_line, sizeof(fingerprint_line), "%s %s\n",options->Nickname, fingerprint) < 0) { - err("Error writing fingerprint line"); + err(LD_GENERAL,"Error writing fingerprint line"); return -1; } - if (write_str_to_file(keydir, fingerprint_line, 0)) + if (write_str_to_file(keydir, fingerprint_line, 0)) { + err(LD_FS, "Error writing fingerprint line to file"); return -1; + } if (!authdir_mode(options)) return 0; /* 6. [authdirserver only] load approved-routers file */ tor_snprintf(keydir,sizeof(keydir),"%s/approved-routers", datadir); info(LD_DIRSERV,"Loading approved fingerprints from \"%s\"...",keydir); if (dirserv_parse_fingerprint_file(keydir) < 0) { - err("Error loading fingerprints"); + err(LD_GENERAL,"Error loading fingerprints"); return -1; } /* 6b. [authdirserver only] add own key to approved directories. */ @@ -1008,7 +1010,7 @@ router_dump_router_to_string(char *s, size_t maxlen, routerinfo_t *router, /* record our fingerprint, so we can include it in the descriptor */ if (crypto_pk_get_fingerprint(router->identity_pkey, fingerprint, 1)<0) { - err("Error computing fingerprint"); + err(LD_BUG,"Error computing fingerprint"); return -1; } @@ -1157,7 +1159,7 @@ router_dump_router_to_string(char *s, size_t maxlen, routerinfo_t *router, cp = s_tmp = s_dup = tor_strdup(s); ri_tmp = router_parse_entry_from_string(cp, NULL); if (!ri_tmp) { - err("We just generated a router descriptor we can't parse: <<%s>>", s); + err(LD_BUG,"We just generated a router descriptor we can't parse: <<%s>>", s); return -1; } tor_free(s_dup); diff --git a/src/or/test.c b/src/or/test.c index 918278b9cf..d9018e7fc6 100644 --- a/src/or/test.c +++ b/src/or/test.c @@ -22,6 +22,7 @@ const char test_c_id[] = "$Id$"; #include <dirent.h> #endif +#define NEW_LOG_INTERFACE #include "or.h" #include "../common/test.h" #include "../common/torgzip.h" |