Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: Use monotonic time for timeouts #284

Merged
merged 8 commits into from
Jun 17, 2020
Merged
Show file tree
Hide file tree
Changes from 2 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 6 additions & 2 deletions src/sentry_core.c
Original file line number Diff line number Diff line change
Expand Up @@ -126,8 +126,12 @@ sentry_shutdown(void)
// TODO: make this configurable
// Ideally, it should default to 2s as per
// https://docs.sentry.io/error-reporting/configuration/?platform=rust#shutdown-timeout
// but we hit that timeout in our own integration tests, so rather
// increase it to 5s, as it was before.
// but we hit that timeout in our own integration tests on windows,
// because the *first* `WinHttpSendRequest` consistently takes
// exactly 2000ms in local testing, with subsequent requests being
// essentially instant.
// So increase this to 5s, which is enough to pass integration
// tests on windows.
if (!sentry__transport_shutdown(options->transport, 5000)) {
SENTRY_DEBUG("transport did not shut down cleanly");
}
Expand Down
6 changes: 3 additions & 3 deletions src/sentry_ratelimiter.c
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,7 @@ sentry__rate_limiter_update_from_header(
return false;
}
retry_after *= 1000;
retry_after += sentry__msec_time();
retry_after += sentry__monotonic_time();

if (!sentry__slice_consume_if(&slice, ':')) {
return false;
Expand Down Expand Up @@ -77,14 +77,14 @@ sentry__rate_limiter_update_from_http_retry_after(
uint64_t eta = 60;
sentry__slice_consume_uint64(&slice, &eta);
rl->disabled_until[SENTRY_RL_CATEGORY_ANY]
= sentry__msec_time() + eta * 1000;
= sentry__monotonic_time() + eta * 1000;
return true;
}

bool
sentry__rate_limiter_is_disabled(const sentry_rate_limiter_t *rl, int category)
{
uint64_t now = sentry__msec_time();
uint64_t now = sentry__monotonic_time();
return rl->disabled_until[SENTRY_RL_CATEGORY_ANY] > now
|| rl->disabled_until[category] > now;
}
Expand Down
5 changes: 2 additions & 3 deletions src/sentry_sync.c
Original file line number Diff line number Diff line change
Expand Up @@ -128,8 +128,7 @@ sentry__bgworker_shutdown(sentry_bgworker_t *bgw, uint64_t timeout)
/* submit a task to shut down the queue */
sentry__bgworker_submit(bgw, shutdown_task, NULL, bgw);

/* TODO: this is dangerous and should be monotonic time */
uint64_t started = sentry__msec_time();
uint64_t started = sentry__monotonic_time();
while (true) {
sentry__mutex_lock(&bgw->task_lock);
bool done = bgw->task_count == 0 && !bgw->running;
Expand All @@ -142,7 +141,7 @@ sentry__bgworker_shutdown(sentry_bgworker_t *bgw, uint64_t timeout)
sentry__cond_wait_timeout(
&bgw->done_signal, &bgw->done_signal_lock, 250);
sentry__mutex_unlock(&bgw->done_signal_lock);
uint64_t now = sentry__msec_time();
uint64_t now = sentry__monotonic_time();
if (now > started && now - started > timeout) {
return 1;
}
Expand Down
20 changes: 20 additions & 0 deletions src/sentry_utils.h
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@
# include <winnt.h>
#else
# include <sys/time.h>
# include <time.h>
#endif

/**
Expand Down Expand Up @@ -108,6 +109,25 @@ sentry__msec_time(void)
#endif
}

/**
* Returns a monotonic millisecond resolution time.
*
* This should be used for timeouts and similar.
* For timestamps, use `sentry__msec_time` instead.
*/
static inline uint64_t
sentry__monotonic_time(void)
{
#ifdef SENTRY_PLATFORM_WINDOWS
Swatinem marked this conversation as resolved.
Show resolved Hide resolved
return GetTickCount64();
#else
struct timespec tv;
return (clock_gettime(CLOCK_MONOTONIC, &tv) == 0)
? (uint64_t)tv.tv_sec * 1000 + tv.tv_nsec / 1000000
: 0;
#endif
}

/**
* Formats a timestamp (milliseconds since epoch) into ISO8601 format.
*/
Expand Down
5 changes: 5 additions & 0 deletions src/transports/sentry_transport_winhttp.c
Original file line number Diff line number Diff line change
Expand Up @@ -120,6 +120,8 @@ task_exec_func(void *data)
struct task_state *ts = data;
winhttp_transport_state_t *state = ts->transport_state;

uint64_t started = sentry__monotonic_time();

sentry_prepared_http_request_t *req
= sentry__prepare_http_request(ts->envelope, state->rl);
if (!req) {
Expand Down Expand Up @@ -226,6 +228,9 @@ task_exec_func(void *data)
sentry_free(url);
sentry_free(headers);
sentry__prepared_http_request_free(req);

uint64_t now = sentry__monotonic_time();
SENTRY_TRACEF("request handled in %llums", now - started);
}

static void
Expand Down
2 changes: 1 addition & 1 deletion tests/unit/test_ratelimiter.c
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,7 @@

SENTRY_TEST(rate_limit_parsing)
{
uint64_t now = sentry__msec_time();
uint64_t now = sentry__monotonic_time();
sentry_rate_limiter_t *rl = sentry__rate_limiter_new();
TEST_CHECK(sentry__rate_limiter_update_from_header(
rl, "120:error:project, 60:session:foo, 30::bar, 120:invalid:invalid"));
Expand Down