Use monotime_coarse for transfer times and padding times

Using absolute_msec requires a 64-bit division operation every time
we calculate it, which gets expensive on 32-bit architectures.
Instead, just use the lazy "monotime_coarse_get()" operation, and
don't convert to milliseconds until we absolutely must.

In this case, it seemed fine to use a full monotime_coarse_t rather
than a truncated "stamp" as we did to solve this problem for the
timerstamps in buf_t and packed_cell_t: There are vastly more cells
and buffer chunks than there are channels, and using 16 bytes per
channel in the worst case is not a big deal.

There are still more millisecond operations here than strictly
necessary; let's see any divisions show up in profiles.
This commit is contained in:
Nick Mathewson 2017-12-13 09:34:20 -05:00
parent dd6dec2665
commit 219c969d7b
6 changed files with 118 additions and 81 deletions

4
changes/bug24613 Normal file
View File

@ -0,0 +1,4 @@
o Minor features (performance, 32-bit):
- Improve performance on 32-bit systems by avoiding 64-bit division
to calculate the current timestamp in milliseconds for channel
padding computations. Implements ticket 24613.

View File

@ -3241,12 +3241,12 @@ channel_timestamp_active(channel_t *chan)
time_t now = time(NULL); time_t now = time(NULL);
tor_assert(chan); tor_assert(chan);
chan->timestamp_xfer_ms = monotime_coarse_absolute_msec(); monotime_coarse_get(&chan->timestamp_xfer);
chan->timestamp_active = now; chan->timestamp_active = now;
/* Clear any potential netflow padding timer. We're active */ /* Clear any potential netflow padding timer. We're active */
chan->next_padding_time_ms = 0; monotime_coarse_zero(&chan->next_padding_time);
} }
/** /**
@ -3311,13 +3311,13 @@ channel_timestamp_recv(channel_t *chan)
{ {
time_t now = time(NULL); time_t now = time(NULL);
tor_assert(chan); tor_assert(chan);
chan->timestamp_xfer_ms = monotime_coarse_absolute_msec(); monotime_coarse_get(&chan->timestamp_xfer);
chan->timestamp_active = now; chan->timestamp_active = now;
chan->timestamp_recv = now; chan->timestamp_recv = now;
/* Clear any potential netflow padding timer. We're active */ /* Clear any potential netflow padding timer. We're active */
chan->next_padding_time_ms = 0; monotime_coarse_zero(&chan->next_padding_time);
} }
/** /**
@ -3332,13 +3332,13 @@ channel_timestamp_xmit(channel_t *chan)
time_t now = time(NULL); time_t now = time(NULL);
tor_assert(chan); tor_assert(chan);
chan->timestamp_xfer_ms = monotime_coarse_absolute_msec(); monotime_coarse_get(&chan->timestamp_xfer);
chan->timestamp_active = now; chan->timestamp_active = now;
chan->timestamp_xmit = now; chan->timestamp_xmit = now;
/* Clear any potential netflow padding timer. We're active */ /* Clear any potential netflow padding timer. We're active */
chan->next_padding_time_ms = 0; monotime_coarse_zero(&chan->next_padding_time);
} }
/*************************************************************** /***************************************************************

View File

@ -88,10 +88,9 @@ struct channel_s {
* Used to decide what channels to pad, and when. */ * Used to decide what channels to pad, and when. */
channel_usage_info_t channel_usage; channel_usage_info_t channel_usage;
/** When should we send a cell for netflow padding, in absolute /** When should we send a cell for netflow padding? 0 means no padding is
* milliseconds since monotime system start. 0 means no padding * scheduled. */
* is scheduled. */ monotime_coarse_t next_padding_time;
uint64_t next_padding_time_ms;
/** The callback pointer for the padding callbacks */ /** The callback pointer for the padding callbacks */
tor_timer_t *padding_timer; tor_timer_t *padding_timer;
@ -158,7 +157,7 @@ struct channel_s {
time_t timestamp_active; /* Any activity */ time_t timestamp_active; /* Any activity */
/** /**
* This is a high-resolution monotonic timestamp that marks when we * This is a monotonic timestamp that marks when we
* believe the channel has actually sent or received data to/from * believe the channel has actually sent or received data to/from
* the wire. Right now, it is used to determine when we should send * the wire. Right now, it is used to determine when we should send
* a padding cell for channelpadding. * a padding cell for channelpadding.
@ -167,7 +166,7 @@ struct channel_s {
* accurately reflect actual network data transfer? Or might this be * accurately reflect actual network data transfer? Or might this be
* very wrong wrt when bytes actually go on the wire? * very wrong wrt when bytes actually go on the wire?
*/ */
uint64_t timestamp_xfer_ms; monotime_coarse_t timestamp_xfer;
/* Methods implemented by the lower layer */ /* Methods implemented by the lower layer */

View File

@ -23,7 +23,8 @@
#include <event2/event.h> #include <event2/event.h>
#include "rendservice.h" #include "rendservice.h"
STATIC int channelpadding_get_netflow_inactive_timeout_ms(const channel_t *); STATIC int32_t channelpadding_get_netflow_inactive_timeout_ms(
const channel_t *);
STATIC int channelpadding_send_disable_command(channel_t *); STATIC int channelpadding_send_disable_command(channel_t *);
STATIC int64_t channelpadding_compute_time_until_pad_for_netflow(channel_t *); STATIC int64_t channelpadding_compute_time_until_pad_for_netflow(channel_t *);
@ -165,7 +166,7 @@ channelpadding_new_consensus_params(networkstatus_t *ns)
* Returns the next timeout period (in milliseconds) after which we should * Returns the next timeout period (in milliseconds) after which we should
* send a padding packet, or 0 if padding is disabled. * send a padding packet, or 0 if padding is disabled.
*/ */
STATIC int STATIC int32_t
channelpadding_get_netflow_inactive_timeout_ms(const channel_t *chan) channelpadding_get_netflow_inactive_timeout_ms(const channel_t *chan)
{ {
int low_timeout = consensus_nf_ito_low; int low_timeout = consensus_nf_ito_low;
@ -377,15 +378,16 @@ channelpadding_send_padding_cell_for_callback(channel_t *chan)
chan->pending_padding_callback = 0; chan->pending_padding_callback = 0;
if (!chan->next_padding_time_ms || if (monotime_coarse_is_zero(&chan->next_padding_time) ||
chan->has_queued_writes(chan)) { chan->has_queued_writes(chan)) {
/* We must have been active before the timer fired */ /* We must have been active before the timer fired */
chan->next_padding_time_ms = 0; monotime_coarse_zero(&chan->next_padding_time);
return; return;
} }
{ {
uint64_t now = monotime_coarse_absolute_msec(); monotime_coarse_t now;
monotime_coarse_get(&now);
log_fn(LOG_INFO,LD_OR, log_fn(LOG_INFO,LD_OR,
"Sending netflow keepalive on "U64_FORMAT" to %s (%s) after " "Sending netflow keepalive on "U64_FORMAT" to %s (%s) after "
@ -393,12 +395,13 @@ channelpadding_send_padding_cell_for_callback(channel_t *chan)
U64_PRINTF_ARG(chan->global_identifier), U64_PRINTF_ARG(chan->global_identifier),
safe_str_client(chan->get_remote_descr(chan, 0)), safe_str_client(chan->get_remote_descr(chan, 0)),
safe_str_client(hex_str(chan->identity_digest, DIGEST_LEN)), safe_str_client(hex_str(chan->identity_digest, DIGEST_LEN)),
U64_PRINTF_ARG(now - chan->timestamp_xfer_ms), I64_PRINTF_ARG(monotime_coarse_diff_msec(&chan->timestamp_xfer,&now)),
U64_PRINTF_ARG(now - chan->next_padding_time_ms)); I64_PRINTF_ARG(
monotime_coarse_diff_msec(&chan->next_padding_time,&now)));
} }
/* Clear the timer */ /* Clear the timer */
chan->next_padding_time_ms = 0; monotime_coarse_zero(&chan->next_padding_time);
/* Send the padding cell. This will cause the channel to get a /* Send the padding cell. This will cause the channel to get a
* fresh timestamp_active */ * fresh timestamp_active */
@ -500,38 +503,42 @@ channelpadding_schedule_padding(channel_t *chan, int in_ms)
STATIC int64_t STATIC int64_t
channelpadding_compute_time_until_pad_for_netflow(channel_t *chan) channelpadding_compute_time_until_pad_for_netflow(channel_t *chan)
{ {
uint64_t long_now = monotime_coarse_absolute_msec(); monotime_coarse_t now;
monotime_coarse_get(&now);
if (!chan->next_padding_time_ms) { if (monotime_coarse_is_zero(&chan->next_padding_time)) {
/* If the below line or crypto_rand_int() shows up on a profile, /* If the below line or crypto_rand_int() shows up on a profile,
* we can avoid getting a timeout until we're at least nf_ito_lo * we can avoid getting a timeout until we're at least nf_ito_lo
* from a timeout window. That will prevent us from setting timers * from a timeout window. That will prevent us from setting timers
* on connections that were active up to 1.5 seconds ago. * on connections that were active up to 1.5 seconds ago.
* Idle connections should only call this once every 5.5s on average * Idle connections should only call this once every 5.5s on average
* though, so that might be a micro-optimization for little gain. */ * though, so that might be a micro-optimization for little gain. */
int64_t padding_timeout = int32_t padding_timeout =
channelpadding_get_netflow_inactive_timeout_ms(chan); channelpadding_get_netflow_inactive_timeout_ms(chan);
if (!padding_timeout) if (!padding_timeout)
return CHANNELPADDING_TIME_DISABLED; return CHANNELPADDING_TIME_DISABLED;
chan->next_padding_time_ms = padding_timeout monotime_coarse_add_msec(&chan->next_padding_time,
+ chan->timestamp_xfer_ms; &chan->timestamp_xfer,
padding_timeout);
} }
const int64_t ms_till_pad =
monotime_coarse_diff_msec(&now, &chan->next_padding_time);
/* If the next padding time is beyond the maximum possible consensus value, /* If the next padding time is beyond the maximum possible consensus value,
* then this indicates a clock jump, so just send padding now. This is * then this indicates a clock jump, so just send padding now. This is
* better than using monotonic time because we want to avoid the situation * better than using monotonic time because we want to avoid the situation
* where we wait around forever for monotonic time to move forward after * where we wait around forever for monotonic time to move forward after
* a clock jump far into the past. * a clock jump far into the past.
*/ */
if (chan->next_padding_time_ms > long_now + if (ms_till_pad > DFLT_NETFLOW_INACTIVE_KEEPALIVE_MAX) {
DFLT_NETFLOW_INACTIVE_KEEPALIVE_MAX) {
tor_fragile_assert(); tor_fragile_assert();
log_warn(LD_BUG, log_warn(LD_BUG,
"Channel padding timeout scheduled "I64_FORMAT"ms in the future. " "Channel padding timeout scheduled "I64_FORMAT"ms in the future. "
"Did the monotonic clock just jump?", "Did the monotonic clock just jump?",
I64_PRINTF_ARG(chan->next_padding_time_ms - long_now)); I64_PRINTF_ARG(ms_till_pad));
return 0; /* Clock jumped: Send padding now */ return 0; /* Clock jumped: Send padding now */
} }
@ -540,11 +547,8 @@ channelpadding_compute_time_until_pad_for_netflow(channel_t *chan)
from now which we should send padding, so we can schedule a callback from now which we should send padding, so we can schedule a callback
then. then.
*/ */
if (long_now + if (ms_till_pad < (TOR_HOUSEKEEPING_CALLBACK_MSEC +
(TOR_HOUSEKEEPING_CALLBACK_MSEC + TOR_HOUSEKEEPING_CALLBACK_SLACK_MSEC) TOR_HOUSEKEEPING_CALLBACK_SLACK_MSEC)) {
>= chan->next_padding_time_ms) {
int64_t ms_until_pad_for_netflow = chan->next_padding_time_ms -
long_now;
/* If the padding time is in the past, that means that libevent delayed /* If the padding time is in the past, that means that libevent delayed
* calling the once-per-second callback due to other work taking too long. * calling the once-per-second callback due to other work taking too long.
* See https://bugs.torproject.org/22212 and * See https://bugs.torproject.org/22212 and
@ -554,16 +558,16 @@ channelpadding_compute_time_until_pad_for_netflow(channel_t *chan)
* and allowed a router to emit a netflow frame, just so we don't forget * and allowed a router to emit a netflow frame, just so we don't forget
* about it entirely.. */ * about it entirely.. */
#define NETFLOW_MISSED_WINDOW (150000 - DFLT_NETFLOW_INACTIVE_KEEPALIVE_HIGH) #define NETFLOW_MISSED_WINDOW (150000 - DFLT_NETFLOW_INACTIVE_KEEPALIVE_HIGH)
if (ms_until_pad_for_netflow < 0) { if (ms_till_pad < 0) {
int severity = (ms_until_pad_for_netflow < -NETFLOW_MISSED_WINDOW) int severity = (ms_till_pad < -NETFLOW_MISSED_WINDOW)
? LOG_NOTICE : LOG_INFO; ? LOG_NOTICE : LOG_INFO;
log_fn(severity, LD_OR, log_fn(severity, LD_OR,
"Channel padding timeout scheduled "I64_FORMAT"ms in the past. ", "Channel padding timeout scheduled "I64_FORMAT"ms in the past. ",
I64_PRINTF_ARG(-ms_until_pad_for_netflow)); I64_PRINTF_ARG(-ms_till_pad));
return 0; /* Clock jumped: Send padding now */ return 0; /* Clock jumped: Send padding now */
} }
return ms_until_pad_for_netflow; return ms_till_pad;
} }
return CHANNELPADDING_TIME_LATER; return CHANNELPADDING_TIME_LATER;
} }

View File

@ -703,7 +703,7 @@ test_channel_inbound_cell(void *arg)
old_count = test_chan_fixed_cells_recved; old_count = test_chan_fixed_cells_recved;
channel_process_cell(chan, cell); channel_process_cell(chan, cell);
tt_int_op(test_chan_fixed_cells_recved, OP_EQ, old_count); tt_int_op(test_chan_fixed_cells_recved, OP_EQ, old_count);
tt_u64_op(chan->timestamp_xfer_ms, OP_EQ, 0); tt_assert(monotime_coarse_is_zero(&chan->timestamp_xfer));
tt_u64_op(chan->timestamp_active, OP_EQ, 0); tt_u64_op(chan->timestamp_active, OP_EQ, 0);
tt_u64_op(chan->timestamp_recv, OP_EQ, 0); tt_u64_op(chan->timestamp_recv, OP_EQ, 0);
@ -716,10 +716,10 @@ test_channel_inbound_cell(void *arg)
channel_process_cell(chan, cell); channel_process_cell(chan, cell);
tt_int_op(test_chan_fixed_cells_recved, OP_EQ, old_count + 1); tt_int_op(test_chan_fixed_cells_recved, OP_EQ, old_count + 1);
/* We should have a series of timestamp set. */ /* We should have a series of timestamp set. */
tt_u64_op(chan->timestamp_xfer_ms, OP_NE, 0); tt_assert(!monotime_coarse_is_zero(&chan->timestamp_xfer));
tt_u64_op(chan->timestamp_active, OP_NE, 0); tt_u64_op(chan->timestamp_active, OP_NE, 0);
tt_u64_op(chan->timestamp_recv, OP_NE, 0); tt_u64_op(chan->timestamp_recv, OP_NE, 0);
tt_u64_op(chan->next_padding_time_ms, OP_EQ, 0); tt_assert(monotime_is_zero(&chan->next_padding_time));
tt_u64_op(chan->n_cells_recved, OP_EQ, 1); tt_u64_op(chan->n_cells_recved, OP_EQ, 1);
tt_u64_op(chan->n_bytes_recved, OP_EQ, get_cell_network_size(0)); tt_u64_op(chan->n_bytes_recved, OP_EQ, get_cell_network_size(0));

View File

@ -279,7 +279,6 @@ test_channelpadding_timers(void *arg)
{ {
channelpadding_decision_t decision; channelpadding_decision_t decision;
channel_t *chans[CHANNELS_TO_TEST]; channel_t *chans[CHANNELS_TO_TEST];
int64_t new_time;
(void)arg; (void)arg;
tor_libevent_postfork(); tor_libevent_postfork();
@ -289,8 +288,9 @@ test_channelpadding_timers(void *arg)
monotime_init(); monotime_init();
monotime_enable_test_mocking(); monotime_enable_test_mocking();
monotime_set_mock_time_nsec(1); uint64_t nsec_mock = 1;
monotime_coarse_set_mock_time_nsec(1); monotime_set_mock_time_nsec(nsec_mock);
monotime_coarse_set_mock_time_nsec(nsec_mock);
timers_initialize(); timers_initialize();
channelpadding_new_consensus_params(NULL); channelpadding_new_consensus_params(NULL);
@ -304,11 +304,14 @@ test_channelpadding_timers(void *arg)
tried_to_write_cell = 0; tried_to_write_cell = 0;
int i = 0; int i = 0;
monotime_coarse_t now;
monotime_coarse_get(&now);
/* This loop fills our timerslot array with timers of increasing time /* This loop fills our timerslot array with timers of increasing time
* until they fire */ * until they fire */
for (; i < CHANNELPADDING_MAX_TIMERS; i++) { for (; i < CHANNELPADDING_MAX_TIMERS; i++) {
chans[i]->next_padding_time_ms = monotime_coarse_absolute_msec() monotime_coarse_add_msec(&chans[i]->next_padding_time,
+ 10 + i*4; &now, 10 + i*4);
decision = channelpadding_decide_to_pad_channel(chans[i]); decision = channelpadding_decide_to_pad_channel(chans[i]);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED);
tt_assert(chans[i]->pending_padding_callback); tt_assert(chans[i]->pending_padding_callback);
@ -318,7 +321,8 @@ test_channelpadding_timers(void *arg)
/* This loop should add timers to the first position in the timerslot /* This loop should add timers to the first position in the timerslot
* array, since its timeout is before all other timers. */ * array, since its timeout is before all other timers. */
for (; i < CHANNELS_TO_TEST/3; i++) { for (; i < CHANNELS_TO_TEST/3; i++) {
chans[i]->next_padding_time_ms = monotime_coarse_absolute_msec() + 1; monotime_coarse_add_msec(&chans[i]->next_padding_time,
&now, 1);
decision = channelpadding_decide_to_pad_channel(chans[i]); decision = channelpadding_decide_to_pad_channel(chans[i]);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED);
tt_assert(chans[i]->pending_padding_callback); tt_assert(chans[i]->pending_padding_callback);
@ -329,8 +333,8 @@ test_channelpadding_timers(void *arg)
* pseudorandom pattern. It ensures that the lists can grow with multiple * pseudorandom pattern. It ensures that the lists can grow with multiple
* timers in them. */ * timers in them. */
for (; i < CHANNELS_TO_TEST/2; i++) { for (; i < CHANNELS_TO_TEST/2; i++) {
chans[i]->next_padding_time_ms = monotime_coarse_absolute_msec() + 10 + monotime_coarse_add_msec(&chans[i]->next_padding_time,
i*3 % CHANNELPADDING_MAX_TIMERS; &now, 10 + i*3 % CHANNELPADDING_MAX_TIMERS);
decision = channelpadding_decide_to_pad_channel(chans[i]); decision = channelpadding_decide_to_pad_channel(chans[i]);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED);
tt_assert(chans[i]->pending_padding_callback); tt_assert(chans[i]->pending_padding_callback);
@ -340,8 +344,8 @@ test_channelpadding_timers(void *arg)
/* This loop should add timers to the last position in the timerslot /* This loop should add timers to the last position in the timerslot
* array, since its timeout is after all other timers. */ * array, since its timeout is after all other timers. */
for (; i < CHANNELS_TO_TEST; i++) { for (; i < CHANNELS_TO_TEST; i++) {
chans[i]->next_padding_time_ms = monotime_coarse_absolute_msec() + 500 + monotime_coarse_add_msec(&chans[i]->next_padding_time,
i % CHANNELPADDING_MAX_TIMERS; &now, 500 + i % CHANNELPADDING_MAX_TIMERS);
decision = channelpadding_decide_to_pad_channel(chans[i]); decision = channelpadding_decide_to_pad_channel(chans[i]);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED);
tt_assert(chans[i]->pending_padding_callback); tt_assert(chans[i]->pending_padding_callback);
@ -349,9 +353,9 @@ test_channelpadding_timers(void *arg)
} }
// Wait for the timers and then kill the event loop. // Wait for the timers and then kill the event loop.
new_time = (monotime_coarse_absolute_msec()+1001)*NSEC_PER_MSEC; nsec_mock += 1001 * NSEC_PER_MSEC;
monotime_coarse_set_mock_time_nsec(new_time); monotime_coarse_set_mock_time_nsec(nsec_mock);
monotime_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(nsec_mock);
timers_run_pending(); timers_run_pending();
tt_int_op(tried_to_write_cell, OP_EQ, CHANNELS_TO_TEST); tt_int_op(tried_to_write_cell, OP_EQ, CHANNELS_TO_TEST);
@ -388,6 +392,7 @@ test_channelpadding_killonehop(void *arg)
monotime_enable_test_mocking(); monotime_enable_test_mocking();
monotime_set_mock_time_nsec(1); monotime_set_mock_time_nsec(1);
monotime_coarse_set_mock_time_nsec(1); monotime_coarse_set_mock_time_nsec(1);
new_time = 1;
timers_initialize(); timers_initialize();
setup_mock_consensus(); setup_mock_consensus();
@ -401,9 +406,12 @@ test_channelpadding_killonehop(void *arg)
smartlist_clear(current_md_consensus->net_params); smartlist_clear(current_md_consensus->net_params);
channelpadding_new_consensus_params(current_md_consensus); channelpadding_new_consensus_params(current_md_consensus);
monotime_coarse_t now;
monotime_coarse_get(&now);
tried_to_write_cell = 0; tried_to_write_cell = 0;
get_options_mutable()->Tor2webMode = 1; get_options_mutable()->Tor2webMode = 1;
client_relay3->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; monotime_coarse_add_msec(&client_relay3->next_padding_time, &now, 100);
decision = channelpadding_decide_to_pad_channel(client_relay3); decision = channelpadding_decide_to_pad_channel(client_relay3);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED);
tt_assert(client_relay3->pending_padding_callback); tt_assert(client_relay3->pending_padding_callback);
@ -413,9 +421,10 @@ test_channelpadding_killonehop(void *arg)
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_ALREADY_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_ALREADY_SCHEDULED);
// Wait for the timer // Wait for the timer
new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; new_time += 101*NSEC_PER_MSEC;
monotime_coarse_set_mock_time_nsec(new_time); monotime_coarse_set_mock_time_nsec(new_time);
monotime_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time);
monotime_coarse_get(&now);
timers_run_pending(); timers_run_pending();
tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_int_op(tried_to_write_cell, OP_EQ, 1);
tt_assert(!client_relay3->pending_padding_callback); tt_assert(!client_relay3->pending_padding_callback);
@ -427,7 +436,7 @@ test_channelpadding_killonehop(void *arg)
// Before the client tries to pad, the relay will still pad: // Before the client tries to pad, the relay will still pad:
tried_to_write_cell = 0; tried_to_write_cell = 0;
relay3_client->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; monotime_coarse_add_msec(&relay3_client->next_padding_time, &now, 100);
get_options_mutable()->ORPort_set = 1; get_options_mutable()->ORPort_set = 1;
get_options_mutable()->Tor2webMode = 0; get_options_mutable()->Tor2webMode = 0;
decision = channelpadding_decide_to_pad_channel(relay3_client); decision = channelpadding_decide_to_pad_channel(relay3_client);
@ -435,9 +444,10 @@ test_channelpadding_killonehop(void *arg)
tt_assert(relay3_client->pending_padding_callback); tt_assert(relay3_client->pending_padding_callback);
// Wait for the timer // Wait for the timer
new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; new_time += 101*NSEC_PER_MSEC;
monotime_coarse_set_mock_time_nsec(new_time); monotime_coarse_set_mock_time_nsec(new_time);
monotime_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time);
monotime_coarse_get(&now);
timers_run_pending(); timers_run_pending();
tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_int_op(tried_to_write_cell, OP_EQ, 1);
tt_assert(!client_relay3->pending_padding_callback); tt_assert(!client_relay3->pending_padding_callback);
@ -474,7 +484,8 @@ test_channelpadding_killonehop(void *arg)
get_options_mutable()->ORPort_set = 0; get_options_mutable()->ORPort_set = 0;
get_options_mutable()->HiddenServiceSingleHopMode = 1; get_options_mutable()->HiddenServiceSingleHopMode = 1;
get_options_mutable()->HiddenServiceNonAnonymousMode = 1; get_options_mutable()->HiddenServiceNonAnonymousMode = 1;
client_relay3->next_padding_time_ms = monotime_coarse_absolute_msec() + 100;
monotime_coarse_add_msec(&client_relay3->next_padding_time, &now, 100);
decision = channelpadding_decide_to_pad_channel(client_relay3); decision = channelpadding_decide_to_pad_channel(client_relay3);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED);
tt_assert(client_relay3->pending_padding_callback); tt_assert(client_relay3->pending_padding_callback);
@ -484,9 +495,10 @@ test_channelpadding_killonehop(void *arg)
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_ALREADY_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_ALREADY_SCHEDULED);
// Wait for the timer // Wait for the timer
new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; new_time += 101 * NSEC_PER_MSEC;
monotime_coarse_set_mock_time_nsec(new_time); monotime_coarse_set_mock_time_nsec(new_time);
monotime_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time);
monotime_coarse_get(&now);
timers_run_pending(); timers_run_pending();
tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_int_op(tried_to_write_cell, OP_EQ, 1);
tt_assert(!client_relay3->pending_padding_callback); tt_assert(!client_relay3->pending_padding_callback);
@ -498,7 +510,7 @@ test_channelpadding_killonehop(void *arg)
// Before the client tries to pad, the relay will still pad: // Before the client tries to pad, the relay will still pad:
tried_to_write_cell = 0; tried_to_write_cell = 0;
relay3_client->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; monotime_coarse_add_msec(&relay3_client->next_padding_time, &now, 100);
get_options_mutable()->ORPort_set = 1; get_options_mutable()->ORPort_set = 1;
get_options_mutable()->HiddenServiceSingleHopMode = 0; get_options_mutable()->HiddenServiceSingleHopMode = 0;
get_options_mutable()->HiddenServiceNonAnonymousMode = 0; get_options_mutable()->HiddenServiceNonAnonymousMode = 0;
@ -507,9 +519,10 @@ test_channelpadding_killonehop(void *arg)
tt_assert(relay3_client->pending_padding_callback); tt_assert(relay3_client->pending_padding_callback);
// Wait for the timer // Wait for the timer
new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; new_time += 101 * NSEC_PER_MSEC;
monotime_coarse_set_mock_time_nsec(new_time); monotime_coarse_set_mock_time_nsec(new_time);
monotime_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time);
monotime_coarse_get(&now);
timers_run_pending(); timers_run_pending();
tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_int_op(tried_to_write_cell, OP_EQ, 1);
tt_assert(!client_relay3->pending_padding_callback); tt_assert(!client_relay3->pending_padding_callback);
@ -573,6 +586,9 @@ test_channelpadding_consensus(void *arg)
monotime_enable_test_mocking(); monotime_enable_test_mocking();
monotime_set_mock_time_nsec(1); monotime_set_mock_time_nsec(1);
monotime_coarse_set_mock_time_nsec(1); monotime_coarse_set_mock_time_nsec(1);
new_time = 1;
monotime_coarse_t now;
monotime_coarse_get(&now);
timers_initialize(); timers_initialize();
if (!connection_array) if (!connection_array)
@ -586,7 +602,7 @@ test_channelpadding_consensus(void *arg)
/* Test 1: Padding can be completely disabled via consensus */ /* Test 1: Padding can be completely disabled via consensus */
tried_to_write_cell = 0; tried_to_write_cell = 0;
chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; monotime_coarse_add_msec(&chan->next_padding_time, &now, 100);
decision = channelpadding_decide_to_pad_channel(chan); decision = channelpadding_decide_to_pad_channel(chan);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED);
tt_assert(chan->pending_padding_callback); tt_assert(chan->pending_padding_callback);
@ -596,9 +612,10 @@ test_channelpadding_consensus(void *arg)
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_ALREADY_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_ALREADY_SCHEDULED);
// Wait for the timer // Wait for the timer
new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; new_time += 101*NSEC_PER_MSEC;
monotime_coarse_set_mock_time_nsec(new_time); monotime_coarse_set_mock_time_nsec(new_time);
monotime_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time);
monotime_coarse_get(&now);
timers_run_pending(); timers_run_pending();
tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_int_op(tried_to_write_cell, OP_EQ, 1);
tt_assert(!chan->pending_padding_callback); tt_assert(!chan->pending_padding_callback);
@ -628,7 +645,7 @@ test_channelpadding_consensus(void *arg)
tt_i64_op(val, OP_EQ, 0); tt_i64_op(val, OP_EQ, 0);
val = channelpadding_compute_time_until_pad_for_netflow(chan); val = channelpadding_compute_time_until_pad_for_netflow(chan);
tt_i64_op(val, OP_EQ, -2); tt_i64_op(val, OP_EQ, -2);
tt_assert(!chan->next_padding_time_ms); tt_assert(monotime_coarse_is_zero(&chan->next_padding_time));
smartlist_clear(current_md_consensus->net_params); smartlist_clear(current_md_consensus->net_params);
@ -641,7 +658,7 @@ test_channelpadding_consensus(void *arg)
channelpadding_new_consensus_params(current_md_consensus); channelpadding_new_consensus_params(current_md_consensus);
tried_to_write_cell = 0; tried_to_write_cell = 0;
chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; monotime_coarse_add_msec(&chan->next_padding_time, &now, 100);
decision = channelpadding_decide_to_pad_channel(chan); decision = channelpadding_decide_to_pad_channel(chan);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED);
tt_assert(chan->pending_padding_callback); tt_assert(chan->pending_padding_callback);
@ -653,9 +670,10 @@ test_channelpadding_consensus(void *arg)
tt_i64_op(val, OP_LE, 200); tt_i64_op(val, OP_LE, 200);
// Wait for the timer // Wait for the timer
new_time = (monotime_coarse_absolute_msec()+201)*NSEC_PER_MSEC; new_time += 201*NSEC_PER_MSEC;
monotime_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time);
monotime_coarse_set_mock_time_nsec(new_time); monotime_coarse_set_mock_time_nsec(new_time);
monotime_coarse_get(&now);
timers_run_pending(); timers_run_pending();
tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_int_op(tried_to_write_cell, OP_EQ, 1);
tt_assert(!chan->pending_padding_callback); tt_assert(!chan->pending_padding_callback);
@ -944,6 +962,9 @@ test_channelpadding_decide_to_pad_channel(void *arg)
monotime_enable_test_mocking(); monotime_enable_test_mocking();
monotime_set_mock_time_nsec(1); monotime_set_mock_time_nsec(1);
monotime_coarse_set_mock_time_nsec(1); monotime_coarse_set_mock_time_nsec(1);
new_time = 1;
monotime_coarse_t now;
monotime_coarse_get(&now);
timers_initialize(); timers_initialize();
setup_full_capture_of_logs(LOG_WARN); setup_full_capture_of_logs(LOG_WARN);
channelpadding_new_consensus_params(NULL); channelpadding_new_consensus_params(NULL);
@ -960,7 +981,7 @@ test_channelpadding_decide_to_pad_channel(void *arg)
/* Test case #2a: > 1.1s until timeout */ /* Test case #2a: > 1.1s until timeout */
tried_to_write_cell = 0; tried_to_write_cell = 0;
chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 1200; monotime_coarse_add_msec(&chan->next_padding_time, &now, 1200);
decision = channelpadding_decide_to_pad_channel(chan); decision = channelpadding_decide_to_pad_channel(chan);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADLATER); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADLATER);
tt_assert(!chan->pending_padding_callback); tt_assert(!chan->pending_padding_callback);
@ -968,23 +989,27 @@ test_channelpadding_decide_to_pad_channel(void *arg)
/* Test case #2b: >= 1.0s until timeout */ /* Test case #2b: >= 1.0s until timeout */
tried_to_write_cell = 0; tried_to_write_cell = 0;
chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 1000; monotime_coarse_add_msec(&chan->next_padding_time, &now, 1000);
decision = channelpadding_decide_to_pad_channel(chan); decision = channelpadding_decide_to_pad_channel(chan);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED);
tt_assert(chan->pending_padding_callback); tt_assert(chan->pending_padding_callback);
tt_int_op(tried_to_write_cell, OP_EQ, 0); tt_int_op(tried_to_write_cell, OP_EQ, 0);
// Set up a timer for the <0 case below.
monotime_coarse_t now_minus_100s;
monotime_coarse_add_msec(&now_minus_100s, &now, 900);
// Wait for the timer from case #2b // Wait for the timer from case #2b
new_time = (monotime_coarse_absolute_msec() + 1000)*NSEC_PER_MSEC; new_time += 1000*NSEC_PER_MSEC;
monotime_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time);
monotime_coarse_set_mock_time_nsec(new_time); monotime_coarse_set_mock_time_nsec(new_time);
monotime_coarse_get(&now);
timers_run_pending(); timers_run_pending();
tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_int_op(tried_to_write_cell, OP_EQ, 1);
tt_assert(!chan->pending_padding_callback); tt_assert(!chan->pending_padding_callback);
/* Test case #2c: > 0.1s until timeout */ /* Test case #2c: > 0.1s until timeout */
tried_to_write_cell = 0; tried_to_write_cell = 0;
chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; monotime_coarse_add_msec(&chan->next_padding_time, &now, 100);
decision = channelpadding_decide_to_pad_channel(chan); decision = channelpadding_decide_to_pad_channel(chan);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED);
tt_assert(chan->pending_padding_callback); tt_assert(chan->pending_padding_callback);
@ -995,16 +1020,17 @@ test_channelpadding_decide_to_pad_channel(void *arg)
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_ALREADY_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_ALREADY_SCHEDULED);
// Wait for the timer // Wait for the timer
new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; new_time += 101*NSEC_PER_MSEC;
monotime_coarse_set_mock_time_nsec(new_time); monotime_coarse_set_mock_time_nsec(new_time);
monotime_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time);
monotime_coarse_get(&now);
timers_run_pending(); timers_run_pending();
tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_int_op(tried_to_write_cell, OP_EQ, 1);
tt_assert(!chan->pending_padding_callback); tt_assert(!chan->pending_padding_callback);
/* Test case #2e: 0s until timeout */ /* Test case #2e: 0s until timeout */
tried_to_write_cell = 0; tried_to_write_cell = 0;
chan->next_padding_time_ms = monotime_coarse_absolute_msec(); monotime_coarse_add_msec(&chan->next_padding_time, &now, 0);
decision = channelpadding_decide_to_pad_channel(chan); decision = channelpadding_decide_to_pad_channel(chan);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SENT); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SENT);
tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_int_op(tried_to_write_cell, OP_EQ, 1);
@ -1012,7 +1038,7 @@ test_channelpadding_decide_to_pad_channel(void *arg)
/* Test case #2f: <0s until timeout */ /* Test case #2f: <0s until timeout */
tried_to_write_cell = 0; tried_to_write_cell = 0;
chan->next_padding_time_ms = monotime_coarse_absolute_msec() - 100; monotime_coarse_add_msec(&chan->next_padding_time, &now_minus_100s, 0);
decision = channelpadding_decide_to_pad_channel(chan); decision = channelpadding_decide_to_pad_channel(chan);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SENT); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SENT);
tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_int_op(tried_to_write_cell, OP_EQ, 1);
@ -1020,7 +1046,7 @@ test_channelpadding_decide_to_pad_channel(void *arg)
/* Test case #3: Channel that sends a packet while timeout is scheduled */ /* Test case #3: Channel that sends a packet while timeout is scheduled */
tried_to_write_cell = 0; tried_to_write_cell = 0;
chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; monotime_coarse_add_msec(&chan->next_padding_time, &now, 100);
decision = channelpadding_decide_to_pad_channel(chan); decision = channelpadding_decide_to_pad_channel(chan);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED);
tt_int_op(tried_to_write_cell, OP_EQ, 0); tt_int_op(tried_to_write_cell, OP_EQ, 0);
@ -1031,9 +1057,10 @@ test_channelpadding_decide_to_pad_channel(void *arg)
// We don't expect any timer callbacks here. Make a dummy one to be sure. // We don't expect any timer callbacks here. Make a dummy one to be sure.
// Wait for the timer // Wait for the timer
new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; new_time += 101*NSEC_PER_MSEC;
monotime_coarse_set_mock_time_nsec(new_time); monotime_coarse_set_mock_time_nsec(new_time);
monotime_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time);
monotime_coarse_get(&now);
timers_run_pending(); timers_run_pending();
tt_int_op(tried_to_write_cell, OP_EQ, 0); tt_int_op(tried_to_write_cell, OP_EQ, 0);
@ -1041,7 +1068,7 @@ test_channelpadding_decide_to_pad_channel(void *arg)
/* Test case #4: Channel that closes while a timeout is scheduled */ /* Test case #4: Channel that closes while a timeout is scheduled */
tried_to_write_cell = 0; tried_to_write_cell = 0;
chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; monotime_coarse_add_msec(&chan->next_padding_time, &now, 100);
decision = channelpadding_decide_to_pad_channel(chan); decision = channelpadding_decide_to_pad_channel(chan);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED);
tt_int_op(tried_to_write_cell, OP_EQ, 0); tt_int_op(tried_to_write_cell, OP_EQ, 0);
@ -1051,9 +1078,10 @@ test_channelpadding_decide_to_pad_channel(void *arg)
chan->state = CHANNEL_STATE_MAINT; chan->state = CHANNEL_STATE_MAINT;
// We don't expect any timer callbacks here. Make a dummy one to be sure. // We don't expect any timer callbacks here. Make a dummy one to be sure.
new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; new_time += 101*NSEC_PER_MSEC;
monotime_coarse_set_mock_time_nsec(new_time); monotime_coarse_set_mock_time_nsec(new_time);
monotime_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time);
monotime_coarse_get(&now);
timers_run_pending(); timers_run_pending();
tt_int_op(tried_to_write_cell, OP_EQ, 0); tt_int_op(tried_to_write_cell, OP_EQ, 0);
@ -1062,16 +1090,17 @@ test_channelpadding_decide_to_pad_channel(void *arg)
/* Test case #5: Make sure previous test case didn't break everything */ /* Test case #5: Make sure previous test case didn't break everything */
tried_to_write_cell = 0; tried_to_write_cell = 0;
chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; monotime_coarse_add_msec(&chan->next_padding_time, &now, 100);
decision = channelpadding_decide_to_pad_channel(chan); decision = channelpadding_decide_to_pad_channel(chan);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED);
tt_assert(chan->pending_padding_callback); tt_assert(chan->pending_padding_callback);
tt_int_op(tried_to_write_cell, OP_EQ, 0); tt_int_op(tried_to_write_cell, OP_EQ, 0);
// Wait for the timer // Wait for the timer
new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; new_time += 101*NSEC_PER_MSEC;
monotime_coarse_set_mock_time_nsec(new_time); monotime_coarse_set_mock_time_nsec(new_time);
monotime_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time);
monotime_coarse_get(&now);
timers_run_pending(); timers_run_pending();
tt_int_op(tried_to_write_cell, OP_EQ, 1); tt_int_op(tried_to_write_cell, OP_EQ, 1);
@ -1090,7 +1119,7 @@ test_channelpadding_decide_to_pad_channel(void *arg)
* It must be last. * It must be last.
*/ */
tried_to_write_cell = 0; tried_to_write_cell = 0;
chan->next_padding_time_ms = monotime_coarse_absolute_msec() + 100; monotime_coarse_add_msec(&chan->next_padding_time, &now, 100);
decision = channelpadding_decide_to_pad_channel(chan); decision = channelpadding_decide_to_pad_channel(chan);
tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED); tt_int_op(decision, OP_EQ, CHANNELPADDING_PADDING_SCHEDULED);
tt_int_op(tried_to_write_cell, OP_EQ, 0); tt_int_op(tried_to_write_cell, OP_EQ, 0);
@ -1100,9 +1129,10 @@ test_channelpadding_decide_to_pad_channel(void *arg)
free_fake_channeltls((channel_tls_t*)chan); free_fake_channeltls((channel_tls_t*)chan);
// We don't expect any timer callbacks here. Make a dummy one to be sure. // We don't expect any timer callbacks here. Make a dummy one to be sure.
new_time = (monotime_coarse_absolute_msec()+101)*NSEC_PER_MSEC; new_time = 101*NSEC_PER_MSEC;
monotime_coarse_set_mock_time_nsec(new_time); monotime_coarse_set_mock_time_nsec(new_time);
monotime_set_mock_time_nsec(new_time); monotime_set_mock_time_nsec(new_time);
monotime_coarse_get(&now);
timers_run_pending(); timers_run_pending();
tt_int_op(tried_to_write_cell, OP_EQ, 0); tt_int_op(tried_to_write_cell, OP_EQ, 0);