diff options
Diffstat (limited to 'src')
-rw-r--r-- | src/core/mainloop/connection.c | 6 | ||||
-rw-r--r-- | src/core/or/channel.c | 2 | ||||
-rw-r--r-- | src/core/or/channel.h | 3 | ||||
-rw-r--r-- | src/core/or/channeltls.c | 7 | ||||
-rw-r--r-- | src/core/or/or_circuit_st.h | 4 | ||||
-rw-r--r-- | src/core/or/status.c | 41 | ||||
-rw-r--r-- | src/core/or/status.h | 1 | ||||
-rw-r--r-- | src/feature/client/bridges.c | 6 | ||||
-rw-r--r-- | src/feature/client/entrynodes.c | 6 | ||||
-rw-r--r-- | src/feature/hs/hs_dos.c | 5 | ||||
-rw-r--r-- | src/feature/hs/hs_intropoint.c | 5 | ||||
-rw-r--r-- | src/feature/relay/circuitbuild_relay.c | 24 | ||||
-rw-r--r-- | src/feature/relay/router.c | 25 | ||||
-rw-r--r-- | src/feature/relay/router.h | 1 | ||||
-rw-r--r-- | src/lib/log/ratelim.c | 12 | ||||
-rw-r--r-- | src/lib/log/ratelim.h | 8 | ||||
-rw-r--r-- | src/test/test_logging.c | 6 | ||||
-rw-r--r-- | src/test/test_status.c | 341 |
18 files changed, 208 insertions, 295 deletions
diff --git a/src/core/mainloop/connection.c b/src/core/mainloop/connection.c index 7f4c6a5f48..82886ccd0b 100644 --- a/src/core/mainloop/connection.c +++ b/src/core/mainloop/connection.c @@ -82,6 +82,7 @@ #include "core/or/policies.h" #include "core/or/reasons.h" #include "core/or/relay.h" +#include "core/or/status.h" #include "core/or/crypt_path.h" #include "core/proto/proto_haproxy.h" #include "core/proto/proto_http.h" @@ -2042,6 +2043,9 @@ connection_handle_listener_read(connection_t *conn, int new_type) connection_mark_for_close(newconn); return 0; } + + note_connection(true /* inbound */, conn->socket_family); + return 0; } @@ -2213,6 +2217,8 @@ connection_connect_sockaddr,(connection_t *conn, } } + note_connection(false /* outbound */, conn->socket_family); + /* it succeeded. we're connected. */ log_fn(inprogress ? LOG_DEBUG : LOG_INFO, LD_NET, "Connection to socket %s (sock "TOR_SOCKET_T_FORMAT").", diff --git a/src/core/or/channel.c b/src/core/or/channel.c index 91f083ec00..d082174dc8 100644 --- a/src/core/or/channel.c +++ b/src/core/or/channel.c @@ -871,6 +871,8 @@ channel_init(channel_t *chan) /* Channel is not in the scheduler heap. */ chan->sched_heap_idx = -1; + + tor_addr_make_unspec(&chan->addr_according_to_peer); } /** diff --git a/src/core/or/channel.h b/src/core/or/channel.h index 10b80aa7d5..606b0730b8 100644 --- a/src/core/or/channel.h +++ b/src/core/or/channel.h @@ -236,6 +236,9 @@ struct channel_t { /** The handle to this channel (to free on canceled timers) */ struct channel_handle_t *timer_handle; + /** If not UNSPEC, the address that the peer says we have. */ + tor_addr_t addr_according_to_peer; + /** * These two fields specify the minimum and maximum negotiated timeout * values for inactivity (send or receive) before we decide to pad a diff --git a/src/core/or/channeltls.c b/src/core/or/channeltls.c index 51b772728e..a0debf8d22 100644 --- a/src/core/or/channeltls.c +++ b/src/core/or/channeltls.c @@ -1856,6 +1856,13 @@ channel_tls_process_netinfo_cell(cell_t *cell, channel_tls_t *chan) } } + if (me) { + /* We have a descriptor, so we are a relay: record the address that the + * other side said we had. */ + tor_addr_copy(&TLS_CHAN_TO_BASE(chan)->addr_according_to_peer, + &my_apparent_addr); + } + n_other_addrs = netinfo_cell_get_n_my_addrs(netinfo_cell); for (uint8_t i = 0; i < n_other_addrs; i++) { /* Consider all the other addresses; if any matches, this connection is diff --git a/src/core/or/or_circuit_st.h b/src/core/or/or_circuit_st.h index 9bfe999728..4e17b1c143 100644 --- a/src/core/or/or_circuit_st.h +++ b/src/core/or/or_circuit_st.h @@ -75,6 +75,10 @@ struct or_circuit_t { /** If set, the DoS defenses are enabled on this circuit meaning that the * introduce2_bucket is initialized and used. */ unsigned int introduce2_dos_defense_enabled : 1; + /** If set, the DoS defenses were explicitly enabled through the + * ESTABLISH_INTRO cell extension. If unset, the consensus is used to learn + * if the defenses can be enabled or not. */ + unsigned int introduce2_dos_defense_explicit : 1; /** INTRODUCE2 cell bucket controlling how much can go on this circuit. Only * used if this is a service introduction circuit at the intro point diff --git a/src/core/or/status.c b/src/core/or/status.c index ed8448883c..00a88a3178 100644 --- a/src/core/or/status.c +++ b/src/core/or/status.c @@ -113,6 +113,41 @@ log_onion_service_stats(void) hs_stats_get_n_rendezvous_launches()); } +/** + * @name connection counts for heartbeat + * + * Tracks incoming and outgoing connections on IPv4/IPv6, for heartbeat + * logs. + **/ +/**@{*/ +static unsigned n_incoming_ipv4; +static unsigned n_incoming_ipv6; +static unsigned n_outgoing_ipv4; +static unsigned n_outgoing_ipv6; +/**@}*/ + +/** + * Note that a connection has arrived or has been made, for use in the + * heartbeat message. + **/ +void +note_connection(bool inbound, int family) +{ + if (family == AF_INET) { + if (inbound) { + ++n_incoming_ipv4; + } else { + ++n_outgoing_ipv4; + } + } else if (family == AF_INET6) { + if (inbound) { + ++n_incoming_ipv6; + } else { + ++n_outgoing_ipv6; + } + } +} + /** Log a "heartbeat" message describing Tor's status and history so that the * user can know that there is indeed a running Tor. Return 0 on success and * -1 on failure. */ @@ -143,8 +178,12 @@ log_heartbeat(time_t now) bw_sent = bytes_to_usage(get_bytes_written()); log_fn(LOG_NOTICE, LD_HEARTBEAT, "Heartbeat: Tor's uptime is %s, with %d " - "circuits open. I've sent %s and received %s.%s", + "circuits open. I've sent %s and received %s. I've received %u " + "connections on IPv4 and %u on IPv6. I've made %u connections " + "with IPv4 and %u with IPv6.%s", uptime, count_circuits(), bw_sent, bw_rcvd, + n_incoming_ipv4, n_incoming_ipv6, + n_outgoing_ipv4, n_outgoing_ipv6, hibernating?" We are currently hibernating.":""); dirclient_dump_total_dls(); diff --git a/src/core/or/status.h b/src/core/or/status.h index 639f8cdf51..271e0dbc9a 100644 --- a/src/core/or/status.h +++ b/src/core/or/status.h @@ -11,6 +11,7 @@ #include "lib/testsupport/testsupport.h" +void note_connection(bool inbound, int family); int log_heartbeat(time_t now); #ifdef STATUS_PRIVATE diff --git a/src/feature/client/bridges.c b/src/feature/client/bridges.c index cc17e8fa67..59f79219cf 100644 --- a/src/feature/client/bridges.c +++ b/src/feature/client/bridges.c @@ -249,8 +249,8 @@ get_configured_bridge_by_exact_addr_port_digest(const tor_addr_t *addr, * address/port matches only. */ int addr_is_a_configured_bridge(const tor_addr_t *addr, - uint16_t port, - const char *digest) + uint16_t port, + const char *digest) { tor_assert(addr); return get_configured_bridge_by_addr_port_digest(addr, port, digest) ? 1 : 0; @@ -596,7 +596,7 @@ find_transport_name_by_bridge_addrport(const tor_addr_t *addr, uint16_t port) */ int get_transport_by_bridge_addrport(const tor_addr_t *addr, uint16_t port, - const transport_t **transport) + const transport_t **transport) { *transport = NULL; if (!bridge_list) diff --git a/src/feature/client/entrynodes.c b/src/feature/client/entrynodes.c index c51958acec..2104a622da 100644 --- a/src/feature/client/entrynodes.c +++ b/src/feature/client/entrynodes.c @@ -3139,9 +3139,9 @@ entry_guard_parse_from_state(const char *s) guard->sampled_idx = guard->confirmed_idx; } else { - log_warn(LD_GUARD, "The state file seems to be into a status that could" - " yield to weird entry node selection: we're missing both a" - " sampled_idx and a confirmed_idx."); + log_info(LD_GUARD, "The state file seems to be into a status that could" + " yield to weird entry node selection: we're missing both a" + " sampled_idx and a confirmed_idx."); guard->sampled_idx = invalid_sampled_idx++; } diff --git a/src/feature/hs/hs_dos.c b/src/feature/hs/hs_dos.c index 1f7415a280..04c2bfbb89 100644 --- a/src/feature/hs/hs_dos.c +++ b/src/feature/hs/hs_dos.c @@ -93,6 +93,11 @@ update_intro_circuits(void) smartlist_t *intro_circs = hs_circuitmap_get_all_intro_circ_relay_side(); SMARTLIST_FOREACH_BEGIN(intro_circs, circuit_t *, circ) { + /* Ignore circuit if the defenses were set explicitly through the + * ESTABLISH_INTRO cell DoS extension. */ + if (TO_OR_CIRCUIT(circ)->introduce2_dos_defense_explicit) { + continue; + } /* Defenses might have been enabled or disabled. */ TO_OR_CIRCUIT(circ)->introduce2_dos_defense_enabled = consensus_param_introduce_defense_enabled; diff --git a/src/feature/hs/hs_intropoint.c b/src/feature/hs/hs_intropoint.c index e282d1f1bd..69d60f21c3 100644 --- a/src/feature/hs/hs_intropoint.c +++ b/src/feature/hs/hs_intropoint.c @@ -285,6 +285,11 @@ handle_establish_intro_cell_dos_extension( } } + /* At this point, the extension is valid so any values out of it implies + * that it was set explicitly and thus flag the circuit that it should not + * look at the consensus for that reason for the defenses' values. */ + circ->introduce2_dos_defense_explicit = 1; + /* A value of 0 is valid in the sense that we accept it but we still disable * the defenses so return false. */ if (intro2_rate_per_sec == 0 || intro2_burst_per_sec == 0) { diff --git a/src/feature/relay/circuitbuild_relay.c b/src/feature/relay/circuitbuild_relay.c index ad20e143be..64f3c341ae 100644 --- a/src/feature/relay/circuitbuild_relay.c +++ b/src/feature/relay/circuitbuild_relay.c @@ -588,13 +588,23 @@ onionskin_answer(struct or_circuit_t *circ, if ((!channel_is_local(circ->p_chan) || get_options()->ExtendAllowPrivateAddresses) && !channel_is_outgoing(circ->p_chan)) { - /* record that we could process create cells from a non-local conn - * that we didn't initiate; presumably this means that create cells - * can reach us too. */ - tor_addr_t remote_addr; - if (channel_get_addr_if_possible(circ->p_chan, &remote_addr)) { - int family = tor_addr_family(&remote_addr); - router_orport_found_reachable(family); + /* Okay, it's a create cell from a non-local connection + * that we didn't initiate. Presumably this means that create cells + * can reach us too. But what address can they reach us on? */ + const tor_addr_t *my_supposed_addr = &circ->p_chan->addr_according_to_peer; + if (router_addr_is_my_published_addr(my_supposed_addr)) { + /* Great, this create cell came on connection where the peer says + * that the our address is an address we're actually advertising! + * That should mean that we're reachable. But before we finally + * declare ourselves reachable, make sure that the address listed + * by the peer is the same family as the peer is actually using. + */ + tor_addr_t remote_addr; + int family = tor_addr_family(my_supposed_addr); + if (channel_get_addr_if_possible(circ->p_chan, &remote_addr) && + tor_addr_family(&remote_addr) == family) { + router_orport_found_reachable(family); + } } } diff --git a/src/feature/relay/router.c b/src/feature/relay/router.c index 9bf0e7026f..11847a2616 100644 --- a/src/feature/relay/router.c +++ b/src/feature/relay/router.c @@ -1729,6 +1729,31 @@ router_is_me(const routerinfo_t *router) return router_digest_is_me(router->cache_info.identity_digest); } +/** + * Return true if we are a server, and if @a addr is an address we are + * currently publishing (or trying to publish) in our descriptor. + * Return false otherwise. + **/ +bool +router_addr_is_my_published_addr(const tor_addr_t *addr) +{ + IF_BUG_ONCE(!addr) + return false; + + const routerinfo_t *me = router_get_my_routerinfo(); + if (!me) + return false; + + switch (tor_addr_family(addr)) { + case AF_INET: + return tor_addr_eq(addr, &me->ipv4_addr); + case AF_INET6: + return tor_addr_eq(addr, &me->ipv6_addr); + default: + return false; + } +} + /** Return a routerinfo for this OR, rebuilding a fresh one if * necessary. Return NULL on error, or if called on an OP. */ MOCK_IMPL(const routerinfo_t *, diff --git a/src/feature/relay/router.h b/src/feature/relay/router.h index 89b4a479a4..f71ada8eb7 100644 --- a/src/feature/relay/router.h +++ b/src/feature/relay/router.h @@ -100,6 +100,7 @@ int router_digest_is_me(const char *digest); const uint8_t *router_get_my_id_digest(void); int router_extrainfo_digest_is_me(const char *digest); int router_is_me(const routerinfo_t *router); +bool router_addr_is_my_published_addr(const tor_addr_t *addr); int router_build_fresh_descriptor(routerinfo_t **r, extrainfo_t **e); int router_rebuild_descriptor(int force); char *router_dump_router_to_string(routerinfo_t *router, diff --git a/src/lib/log/ratelim.c b/src/lib/log/ratelim.c index ac401fb398..8dfaee3384 100644 --- a/src/lib/log/ratelim.c +++ b/src/lib/log/ratelim.c @@ -11,6 +11,7 @@ #include "lib/log/ratelim.h" #include "lib/malloc/malloc.h" #include "lib/string/printf.h" +#include "lib/intmath/muldiv.h" /** If the rate-limiter <b>lim</b> is ready at <b>now</b>, return the number * of calls to rate_limit_is_ready (including this one!) since the last time @@ -42,19 +43,24 @@ rate_limit_log(ratelim_t *lim, time_t now) { int n; if ((n = rate_limit_is_ready(lim, now))) { + time_t started_limiting = lim->started_limiting; + lim->started_limiting = 0; if (n == 1) { return tor_strdup(""); } else { char *cp=NULL; const char *opt_over = (n >= RATELIM_TOOMANY) ? "over " : ""; - /* XXXX this is not exactly correct: the messages could have occurred - * any time between the old value of lim->allowed and now. */ + unsigned difference = (unsigned)(now - started_limiting); + difference = round_to_next_multiple_of(difference, 60); tor_asprintf(&cp, " [%s%d similar message(s) suppressed in last %d seconds]", - opt_over, n-1, lim->rate); + opt_over, n-1, (int)difference); return cp; } } else { + if (lim->started_limiting == 0) { + lim->started_limiting = now; + } return NULL; } } diff --git a/src/lib/log/ratelim.h b/src/lib/log/ratelim.h index e9b55d40dc..9e202028cf 100644 --- a/src/lib/log/ratelim.h +++ b/src/lib/log/ratelim.h @@ -40,13 +40,19 @@ </pre> */ typedef struct ratelim_t { + /** How many seconds must elapse between log messages? */ int rate; + /** When did this limiter last allow a message to appear? */ time_t last_allowed; + /** When did this limiter start suppressing messages? */ + time_t started_limiting; + /** How many messages has this limiter suppressed since it last allowed + * one to appear? */ int n_calls_since_last_time; } ratelim_t; #ifndef COCCI -#define RATELIM_INIT(r) { (r), 0, 0 } +#define RATELIM_INIT(r) { (r), 0, 0, 0 } #endif #define RATELIM_TOOMANY (16*1000*1000) diff --git a/src/test/test_logging.c b/src/test/test_logging.c index e09f7a21cd..58d0f24bd3 100644 --- a/src/test/test_logging.c +++ b/src/test/test_logging.c @@ -160,6 +160,7 @@ test_ratelim(void *arg) tor_free(msg); int i; + time_t first_suppressed_at = now + 60; for (i = 0; i < 9; ++i) { now += 60; /* one minute has passed. */ msg = rate_limit_log(&ten_min, now); @@ -167,12 +168,15 @@ test_ratelim(void *arg) tt_int_op(ten_min.last_allowed, OP_EQ, start); tt_int_op(ten_min.n_calls_since_last_time, OP_EQ, i + 1); } + tt_i64_op(ten_min.started_limiting, OP_EQ, first_suppressed_at); now += 240; /* Okay, we can be done. */ msg = rate_limit_log(&ten_min, now); tt_ptr_op(msg, OP_NE, NULL); tt_str_op(msg, OP_EQ, - " [9 similar message(s) suppressed in last 600 seconds]"); + " [9 similar message(s) suppressed in last 720 seconds]"); + tt_i64_op(now, OP_EQ, first_suppressed_at + 720); + done: tor_free(msg); } diff --git a/src/test/test_status.c b/src/test/test_status.c index 82afe0fd2a..b938b86326 100644 --- a/src/test/test_status.c +++ b/src/test/test_status.c @@ -26,6 +26,7 @@ #include "feature/nodelist/nodelist.h" #include "app/config/statefile.h" #include "lib/tls/tortls.h" +#include "test/log_test_helpers.h" #include "core/or/origin_circuit_st.h" #include "app/config/or_state_st.h" @@ -308,10 +309,6 @@ static int status_hb_not_in_consensus_public_server_mode( static const routerinfo_t *status_hb_not_in_consensus_get_my_routerinfo(void); static const node_t * status_hb_not_in_consensus_node_get_by_id( const char *identity_digest); -static void status_hb_not_in_consensus_logv( - int severity, log_domain_mask_t domain, const char *funcname, - const char *suffix, const char *format, va_list ap); -static int status_hb_not_in_consensus_logv_called = 0; static int status_hb_not_in_consensus_server_mode(const or_options_t *options); static routerinfo_t *mock_routerinfo; @@ -332,8 +329,6 @@ test_status_hb_not_in_consensus(void *arg) status_hb_not_in_consensus_get_my_routerinfo); MOCK(node_get_by_id, status_hb_not_in_consensus_node_get_by_id); - MOCK(logv, - status_hb_not_in_consensus_logv); MOCK(server_mode, status_hb_not_in_consensus_server_mode); @@ -344,18 +339,38 @@ test_status_hb_not_in_consensus(void *arg) onion_handshakes_assigned[ONION_HANDSHAKE_TYPE_NTOR] = 1; expected = 0; + setup_capture_of_logs(LOG_INFO); actual = log_heartbeat(0); - tt_int_op(actual, OP_EQ, expected); - tt_int_op(status_hb_not_in_consensus_logv_called, OP_EQ, 6); - done: + expect_log_msg("Heartbeat: It seems like we are " + "not in the cached consensus.\n"); + expect_log_msg("Heartbeat: Tor's uptime is 0:00 hours, " + "with 0 circuits open. " + "I've sent 0 kB and received 0 kB. " + "I've received 0 connections on IPv4 and 0 on IPv6. " + "I've made 0 connections with IPv4 and 0 with IPv6.\n"); + expect_log_msg("Average packaged cell fullness: 100.000%. " + "TLS write overhead: 0%\n"); + expect_log_msg("Circuit handshake stats since last time: 1/1 TAP, " + "1/1 NTor.\n"); + expect_log_msg("Since startup we initiated 0 and received 0 v1 " + "connections; initiated 0 and received 0 v2 connections; " + "initiated 0 and received 0 v3 connections; " + "initiated 0 and received 0 v4 connections; " + "initiated 0 and received 0 v5 connections.\n"); + expect_log_msg("DoS mitigation since startup: 0 circuits killed with " + "too many cells. [cc not enabled] [conn not enabled] " + "0 INTRODUCE2 rejected.\n"); + tt_int_op(mock_saved_log_n_entries(), OP_EQ, 6); + + done: + teardown_capture_of_logs(); UNMOCK(tls_get_write_overhead_ratio); UNMOCK(we_are_hibernating); UNMOCK(public_server_mode); UNMOCK(router_get_my_routerinfo); UNMOCK(node_get_by_id); - UNMOCK(logv); UNMOCK(server_mode); tor_free(mock_routerinfo); } @@ -396,76 +411,6 @@ status_hb_not_in_consensus_node_get_by_id(const char *identity_digest) return NULL; } -static void -status_hb_not_in_consensus_logv(int severity, log_domain_mask_t domain, - const char *funcname, const char *suffix, const char *format, va_list ap) -{ - switch (status_hb_not_in_consensus_logv_called) - { - case 0: - tt_int_op(severity, OP_EQ, LOG_NOTICE); - tt_u64_op(domain, OP_EQ, LD_HEARTBEAT); - tt_ptr_op(strstr(funcname, "log_heartbeat"), OP_NE, NULL); - tt_ptr_op(suffix, OP_EQ, NULL); - tt_str_op(format, OP_EQ, - "Heartbeat: It seems like we are not in the cached consensus."); - break; - case 1: - tt_int_op(severity, OP_EQ, LOG_NOTICE); - tt_u64_op(domain, OP_EQ, LD_HEARTBEAT); - tt_ptr_op(strstr(funcname, "log_heartbeat"), OP_NE, NULL); - tt_ptr_op(suffix, OP_EQ, NULL); - tt_str_op(format, OP_EQ, - "Heartbeat: Tor's uptime is %s, with %d circuits open. " - "I've sent %s and received %s.%s"); - tt_str_op(va_arg(ap, char *), OP_EQ, "0:00 hours"); /* uptime */ - tt_int_op(va_arg(ap, int), OP_EQ, 0); /* count_circuits() */ - tt_str_op(va_arg(ap, char *), OP_EQ, "0 kB"); /* bw_sent */ - tt_str_op(va_arg(ap, char *), OP_EQ, "0 kB"); /* bw_rcvd */ - tt_str_op(va_arg(ap, char *), OP_EQ, ""); /* hibernating */ - break; - case 2: - tt_int_op(severity, OP_EQ, LOG_INFO); - break; - case 3: - tt_int_op(severity, OP_EQ, LOG_NOTICE); - tt_u64_op(domain, OP_EQ, LD_HEARTBEAT); - tt_ptr_op(strstr(funcname, "rep_hist_log_circuit_handshake_stats"), - OP_NE, NULL); - tt_ptr_op(suffix, OP_EQ, NULL); - tt_str_op(format, OP_EQ, - "Circuit handshake stats since last time: %d/%d TAP, %d/%d NTor."); - tt_int_op(va_arg(ap, int), OP_EQ, 1); /* handshakes assigned (TAP) */ - tt_int_op(va_arg(ap, int), OP_EQ, 1); /* handshakes requested (TAP) */ - tt_int_op(va_arg(ap, int), OP_EQ, 1); /* handshakes assigned (NTOR) */ - tt_int_op(va_arg(ap, int), OP_EQ, 1); /* handshakes requested (NTOR) */ - break; - case 4: - tt_int_op(severity, OP_EQ, LOG_NOTICE); - tt_u64_op(domain, OP_EQ, LD_HEARTBEAT); - tt_ptr_op(strstr(funcname, "rep_hist_log_link_protocol_counts"), - OP_NE, NULL); - break; - case 5: - tt_int_op(severity, OP_EQ, LOG_NOTICE); - tt_u64_op(domain, OP_EQ, LD_HEARTBEAT); - tt_str_op(format, OP_EQ, "DoS mitigation since startup:%s%s%s%s%s"); - tt_str_op(va_arg(ap, char *), OP_EQ, - " 0 circuits killed with too many cells."); - tt_str_op(va_arg(ap, char *), OP_EQ, " [cc not enabled]"); - tt_str_op(va_arg(ap, char *), OP_EQ, " [conn not enabled]"); - tt_str_op(va_arg(ap, char *), OP_EQ, ""); - tt_str_op(va_arg(ap, char *), OP_EQ, " 0 INTRODUCE2 rejected."); - break; - default: - tt_abort_msg("unexpected call to logv()"); // TODO: prettyprint args - break; - } - - done: - status_hb_not_in_consensus_logv_called++; -} - static int status_hb_not_in_consensus_server_mode(const or_options_t *options) { @@ -485,14 +430,8 @@ static int status_hb_simple_public_server_mode(const or_options_t *options); static long status_hb_simple_get_uptime(void); static uint64_t status_hb_simple_get_bytes_read(void); static uint64_t status_hb_simple_get_bytes_written(void); -static void status_hb_simple_logv(int severity, log_domain_mask_t domain, - const char *funcname, const char *suffix, - const char *format, va_list ap); -ATTR_UNUSED static int status_hb_simple_logv_called = 0; static int status_hb_simple_server_mode(const or_options_t *options); -static int status_hb_simple_n_msgs = 0; - static void test_status_hb_simple(void *arg) { @@ -511,27 +450,32 @@ test_status_hb_simple(void *arg) status_hb_simple_get_bytes_read); MOCK(get_bytes_written, status_hb_simple_get_bytes_written); - MOCK(logv, - status_hb_simple_logv); MOCK(server_mode, status_hb_simple_server_mode); log_global_min_severity_ = LOG_DEBUG; + setup_capture_of_logs(LOG_INFO); expected = 0; actual = log_heartbeat(0); tt_int_op(actual, OP_EQ, expected); - tt_int_op(status_hb_simple_n_msgs, OP_EQ, 1); + + expect_log_msg("Heartbeat: Tor's uptime is 0:00 hours, " + "with 0 circuits open. " + "I've sent 0 kB and received 0 kB. " + "I've received 0 connections on IPv4 and 0 on IPv6. " + "I've made 0 connections with IPv4 and 0 with IPv6. " + "We are currently hibernating.\n"); done: + teardown_capture_of_logs(); UNMOCK(tls_get_write_overhead_ratio); UNMOCK(we_are_hibernating); UNMOCK(public_server_mode); UNMOCK(get_uptime); UNMOCK(get_bytes_read); UNMOCK(get_bytes_written); - UNMOCK(logv); UNMOCK(server_mode); } @@ -573,32 +517,6 @@ status_hb_simple_get_bytes_written(void) return 0; } -static void -status_hb_simple_logv(int severity, log_domain_mask_t domain, - const char *funcname, - const char *suffix, const char *format, va_list ap) -{ - if (severity == LOG_INFO) - return; - ++status_hb_simple_n_msgs; - - tt_int_op(severity, OP_EQ, LOG_NOTICE); - tt_u64_op(domain, OP_EQ, LD_HEARTBEAT); - tt_ptr_op(strstr(funcname, "log_heartbeat"), OP_NE, NULL); - tt_ptr_op(suffix, OP_EQ, NULL); - tt_str_op(format, OP_EQ, - "Heartbeat: Tor's uptime is %s, with %d circuits open. " - "I've sent %s and received %s.%s"); - tt_str_op(va_arg(ap, char *), OP_EQ, "0:00 hours"); /* uptime */ - tt_int_op(va_arg(ap, int), OP_EQ, 0); /* count_circuits() */ - tt_str_op(va_arg(ap, char *), OP_EQ, "0 kB"); /* bw_sent */ - tt_str_op(va_arg(ap, char *), OP_EQ, "0 kB"); /* bw_rcvd */ - tt_str_op(va_arg(ap, char *), OP_EQ, " We are currently hibernating."); - - done: - ; -} - static int status_hb_simple_server_mode(const or_options_t *options) { @@ -620,11 +538,6 @@ static int status_hb_calls_log_accounting_public_server_mode( static long status_hb_calls_log_accounting_get_uptime(void); static uint64_t status_hb_calls_log_accounting_get_bytes_read(void); static uint64_t status_hb_calls_log_accounting_get_bytes_written(void); -static void status_hb_calls_log_accounting_logv( - int severity, log_domain_mask_t domain, - const char *funcname, const char *suffix, - const char *format, va_list ap); -static int status_hb_calls_log_accounting_logv_called = 0; static int status_hb_calls_log_accounting_server_mode( const or_options_t *options); static or_state_t * status_hb_calls_log_accounting_get_or_state(void); @@ -653,8 +566,6 @@ test_status_hb_calls_log_accounting(void *arg) status_hb_calls_log_accounting_get_bytes_read); MOCK(get_bytes_written, status_hb_calls_log_accounting_get_bytes_written); - MOCK(logv, - status_hb_calls_log_accounting_logv); MOCK(server_mode, status_hb_calls_log_accounting_server_mode); MOCK(get_or_state, @@ -666,20 +577,31 @@ test_status_hb_calls_log_accounting(void *arg) log_global_min_severity_ = LOG_DEBUG; + setup_capture_of_logs(LOG_NOTICE); expected = 0; actual = log_heartbeat(0); tt_int_op(actual, OP_EQ, expected); - tt_int_op(status_hb_calls_log_accounting_logv_called, OP_EQ, 3); + + expect_log_msg("Heartbeat: Tor's uptime is 0:00 hours, " + "with 0 circuits open. " + "I've sent 0 kB and received 0 kB. " + "I've received 0 connections on IPv4 and 0 on IPv6. " + "I've made 0 connections with IPv4 and 0 with IPv6.\n"); + + expect_log_msg_containing("Heartbeat: Accounting enabled. Sent: 0 kB, " + "Received: 0 kB, Used: 0 kB / 0 kB, Rule: max. " + "The current accounting interval ends on "); + tt_int_op(mock_saved_log_n_entries(), OP_EQ, 2); done: + teardown_capture_of_logs(); UNMOCK(tls_get_write_overhead_ratio); UNMOCK(we_are_hibernating); UNMOCK(public_server_mode); UNMOCK(get_uptime); UNMOCK(get_bytes_read); UNMOCK(get_bytes_written); - UNMOCK(logv); UNMOCK(server_mode); UNMOCK(accounting_is_enabled); UNMOCK(accounting_get_end_time); @@ -725,58 +647,6 @@ status_hb_calls_log_accounting_get_bytes_written(void) return 0; } -static void -status_hb_calls_log_accounting_logv(int severity, log_domain_mask_t domain, - const char *funcname, const char *suffix, const char *format, va_list ap) -{ - switch (status_hb_calls_log_accounting_logv_called) - { - case 0: - tt_int_op(severity, OP_EQ, LOG_NOTICE); - tt_u64_op(domain, OP_EQ, LD_HEARTBEAT); - tt_ptr_op(strstr(funcname, "log_heartbeat"), OP_NE, NULL); - tt_ptr_op(suffix, OP_EQ, NULL); - tt_str_op(format, OP_EQ, - "Heartbeat: Tor's uptime is %s, with %d circuits open. " - "I've sent %s and received %s.%s"); - tt_str_op(va_arg(ap, char *), OP_EQ, "0:00 hours"); /* uptime */ - tt_int_op(va_arg(ap, int), OP_EQ, 0); /* count_circuits() */ - tt_str_op(va_arg(ap, char *), OP_EQ, "0 kB"); /* bw_sent */ - tt_str_op(va_arg(ap, char *), OP_EQ, "0 kB"); /* bw_rcvd */ - tt_str_op(va_arg(ap, char *), OP_EQ, ""); /* hibernating */ - break; - case 1: - tt_int_op(severity, OP_EQ, LOG_NOTICE); - tt_u64_op(domain, OP_EQ, LD_HEARTBEAT); - tt_ptr_op(strstr(funcname, "log_accounting"), OP_NE, NULL); - tt_ptr_op(suffix, OP_EQ, NULL); - tt_str_op(format, OP_EQ, - "Heartbeat: Accounting enabled. Sent: %s, Received: %s, Used: %s / " - "%s, Rule: %s. The current accounting interval ends on %s, in %s."); - tt_str_op(va_arg(ap, char *), OP_EQ, "0 kB"); /* acc_sent */ - tt_str_op(va_arg(ap, char *), OP_EQ, "0 kB"); /* acc_rcvd */ - tt_str_op(va_arg(ap, char *), OP_EQ, "0 kB"); /* acc_used */ - tt_str_op(va_arg(ap, char *), OP_EQ, "0 kB"); /* acc_max */ - tt_str_op(va_arg(ap, char *), OP_EQ, "max"); /* acc_rule */ - /* format_local_iso_time uses local tz, so we can't just compare - * the string against a constant */ - char datetime[ISO_TIME_LEN+1]; - format_local_iso_time(datetime, 60); - tt_str_op(va_arg(ap, char *), OP_EQ, datetime); /* end_buf */ - tt_str_op(va_arg(ap, char *), OP_EQ, "0:01 hours"); /* remaining */ - break; - case 2: - tt_int_op(severity, OP_EQ, LOG_INFO); - break; - default: - tt_abort_msg("unexpected call to logv()"); // TODO: prettyprint args - break; - } - - done: - status_hb_calls_log_accounting_logv_called++; -} - static int status_hb_calls_log_accounting_server_mode(const or_options_t *options) { @@ -826,11 +696,6 @@ static int status_hb_packaged_cell_fullness_public_server_mode( static long status_hb_packaged_cell_fullness_get_uptime(void); static uint64_t status_hb_packaged_cell_fullness_get_bytes_read(void); static uint64_t status_hb_packaged_cell_fullness_get_bytes_written(void); -static void status_hb_packaged_cell_fullness_logv( - int severity, log_domain_mask_t domain, - const char *funcname, const char *suffix, - const char *format, va_list ap); -static int status_hb_packaged_cell_fullness_logv_called = 0; static int status_hb_packaged_cell_fullness_server_mode( const or_options_t *options); static int status_hb_packaged_cell_fullness_accounting_is_enabled( @@ -854,8 +719,6 @@ test_status_hb_packaged_cell_fullness(void *arg) status_hb_packaged_cell_fullness_get_bytes_read); MOCK(get_bytes_written, status_hb_packaged_cell_fullness_get_bytes_written); - MOCK(logv, - status_hb_packaged_cell_fullness_logv); MOCK(server_mode, status_hb_packaged_cell_fullness_server_mode); MOCK(accounting_is_enabled, @@ -865,12 +728,20 @@ test_status_hb_packaged_cell_fullness(void *arg) stats_n_data_bytes_packaged = RELAY_PAYLOAD_SIZE; stats_n_data_cells_packaged = 2; expected = 0; + setup_capture_of_logs(LOG_INFO); actual = log_heartbeat(0); tt_int_op(actual, OP_EQ, expected); - tt_int_op(status_hb_packaged_cell_fullness_logv_called, OP_EQ, 2); + expect_log_msg("Heartbeat: Tor's uptime is 0:00 hours, " + "with 0 circuits open. " + "I've sent 0 kB and received 0 kB. " + "I've received 0 connections on IPv4 and 0 on IPv6. " + "I've made 0 connections with IPv4 and 0 with IPv6.\n"); + expect_log_msg("Average packaged cell fullness: 50.000%. " + "TLS write overhead: 0%\n"); done: + teardown_capture_of_logs(); stats_n_data_bytes_packaged = 0; stats_n_data_cells_packaged = 0; UNMOCK(tls_get_write_overhead_ratio); @@ -879,7 +750,6 @@ test_status_hb_packaged_cell_fullness(void *arg) UNMOCK(get_uptime); UNMOCK(get_bytes_read); UNMOCK(get_bytes_written); - UNMOCK(logv); UNMOCK(server_mode); UNMOCK(accounting_is_enabled); } @@ -923,47 +793,6 @@ status_hb_packaged_cell_fullness_get_bytes_written(void) return 0; } -static void -status_hb_packaged_cell_fullness_logv(int severity, - log_domain_mask_t domain, const char *funcname, - const char *suffix, const char *format, va_list ap) -{ - switch (status_hb_packaged_cell_fullness_logv_called) - { - case 0: - tt_int_op(severity, OP_EQ, LOG_NOTICE); - tt_u64_op(domain, OP_EQ, LD_HEARTBEAT); - tt_ptr_op(strstr(funcname, "log_heartbeat"), OP_NE, NULL); - tt_ptr_op(suffix, OP_EQ, NULL); - tt_str_op(format, OP_EQ, - "Heartbeat: Tor's uptime is %s, with %d circuits open. " - "I've sent %s and received %s.%s"); - tt_str_op(va_arg(ap, char *), OP_EQ, "0:00 hours"); /* uptime */ - tt_int_op(va_arg(ap, int), OP_EQ, 0); /* count_circuits() */ - tt_str_op(va_arg(ap, char *), OP_EQ, "0 kB"); /* bw_sent */ - tt_str_op(va_arg(ap, char *), OP_EQ, "0 kB"); /* bw_rcvd */ - tt_str_op(va_arg(ap, char *), OP_EQ, ""); /* hibernating */ - break; - case 1: - tt_int_op(severity, OP_EQ, LOG_NOTICE); - tt_u64_op(domain, OP_EQ, LD_HEARTBEAT); - tt_ptr_op(strstr(funcname, "log_heartbeat"), OP_NE, NULL); - tt_ptr_op(suffix, OP_EQ, NULL); - tt_str_op(format, OP_EQ, - "Average packaged cell fullness: %2.3f%%. " - "TLS write overhead: %.f%%"); - tt_double_op(fabs(va_arg(ap, double) - 50.0), OP_LE, DBL_EPSILON); - tt_double_op(fabs(va_arg(ap, double) - 0.0), OP_LE, DBL_EPSILON); - break; - default: - tt_abort_msg("unexpected call to logv()"); // TODO: prettyprint args - break; - } - - done: - status_hb_packaged_cell_fullness_logv_called++; -} - static int status_hb_packaged_cell_fullness_server_mode(const or_options_t *options) { @@ -993,11 +822,6 @@ static int status_hb_tls_write_overhead_public_server_mode( static long status_hb_tls_write_overhead_get_uptime(void); static uint64_t status_hb_tls_write_overhead_get_bytes_read(void); static uint64_t status_hb_tls_write_overhead_get_bytes_written(void); -static void status_hb_tls_write_overhead_logv( - int severity, log_domain_mask_t domain, - const char *funcname, const char *suffix, - const char *format, va_list ap); -static int status_hb_tls_write_overhead_logv_called = 0; static int status_hb_tls_write_overhead_server_mode( const or_options_t *options); static int status_hb_tls_write_overhead_accounting_is_enabled( @@ -1021,8 +845,6 @@ test_status_hb_tls_write_overhead(void *arg) status_hb_tls_write_overhead_get_bytes_read); MOCK(get_bytes_written, status_hb_tls_write_overhead_get_bytes_written); - MOCK(logv, - status_hb_tls_write_overhead_logv); MOCK(server_mode, status_hb_tls_write_overhead_server_mode); MOCK(accounting_is_enabled, @@ -1031,19 +853,26 @@ test_status_hb_tls_write_overhead(void *arg) log_global_min_severity_ = LOG_DEBUG; expected = 0; + setup_capture_of_logs(LOG_NOTICE); actual = log_heartbeat(0); tt_int_op(actual, OP_EQ, expected); - tt_int_op(status_hb_tls_write_overhead_logv_called, OP_EQ, 2); + expect_log_msg("Heartbeat: Tor's uptime is 0:00 hours, " + "with 0 circuits open. " + "I've sent 0 kB and received 0 kB. " + "I've received 0 connections on IPv4 and 0 on IPv6. " + "I've made 0 connections with IPv4 and 0 with IPv6.\n"); + expect_log_msg("Average packaged cell fullness: 100.000%. " + "TLS write overhead: 100%\n"); done: + teardown_capture_of_logs(); UNMOCK(tls_get_write_overhead_ratio); UNMOCK(we_are_hibernating); UNMOCK(public_server_mode); UNMOCK(get_uptime); UNMOCK(get_bytes_read); UNMOCK(get_bytes_written); - UNMOCK(logv); UNMOCK(server_mode); UNMOCK(accounting_is_enabled); } @@ -1086,46 +915,6 @@ status_hb_tls_write_overhead_get_bytes_written(void) return 0; } -static void -status_hb_tls_write_overhead_logv(int severity, log_domain_mask_t domain, - const char *funcname, const char *suffix, const char *format, va_list ap) -{ - switch (status_hb_tls_write_overhead_logv_called) - { - case 0: - tt_int_op(severity, OP_EQ, LOG_NOTICE); - tt_u64_op(domain, OP_EQ, LD_HEARTBEAT); - tt_ptr_op(strstr(funcname, "log_heartbeat"), OP_NE, NULL); - tt_ptr_op(suffix, OP_EQ, NULL); - tt_str_op(format, OP_EQ, - "Heartbeat: Tor's uptime is %s, with %d circuits open. " - "I've sent %s and received %s.%s"); - tt_str_op(va_arg(ap, char *), OP_EQ, "0:00 hours"); /* uptime */ - tt_int_op(va_arg(ap, int), OP_EQ, 0); /* count_circuits() */ - tt_str_op(va_arg(ap, char *), OP_EQ, "0 kB"); /* bw_sent */ - tt_str_op(va_arg(ap, char *), OP_EQ, "0 kB"); /* bw_rcvd */ - tt_str_op(va_arg(ap, char *), OP_EQ, ""); /* hibernating */ - break; - case 1: - tt_int_op(severity, OP_EQ, LOG_NOTICE); - tt_u64_op(domain, OP_EQ, LD_HEARTBEAT); - tt_ptr_op(strstr(funcname, "log_heartbeat"), OP_NE, NULL); - tt_ptr_op(suffix, OP_EQ, NULL); - tt_str_op(format, OP_EQ, - "Average packaged cell fullness: %2.3f%%. " - "TLS write overhead: %.f%%"); - tt_int_op(fabs(va_arg(ap, double) - 100.0) <= DBL_EPSILON, OP_EQ, 1); - tt_double_op(fabs(va_arg(ap, double) - 100.0), OP_LE, DBL_EPSILON); - break; - default: - tt_abort_msg("unexpected call to logv()"); // TODO: prettyprint args - break; - } - - done: - status_hb_tls_write_overhead_logv_called++; -} - static int status_hb_tls_write_overhead_server_mode(const or_options_t *options) { |