fix: Use monotonic time for timeouts (#284)

src/sentry_core.c

@@ -124,11 +124,8 @@ sentry_shutdown(void)
     if (options) {
         if (options->transport) {
             // 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.
-            if (!sentry__transport_shutdown(options->transport, 5000)) {
+            if (!sentry__transport_shutdown(
+                    options->transport, SENTRY_DEFAULT_SHUTDOWN_TIMEOUT)) {
                 SENTRY_DEBUG("transport did not shut down cleanly");
             }
         }

src/sentry_options.h

@@ -5,6 +5,10 @@
 
 #include "sentry_utils.h"
 
+// Defaults to 2s as per
+// https://docs.sentry.io/error-reporting/configuration/?platform=native#shutdown-timeout
+#define SENTRY_DEFAULT_SHUTDOWN_TIMEOUT 2000
+
 typedef struct sentry_path_s sentry_path_t;
 typedef struct sentry_run_s sentry_run_t;
 struct sentry_backend_s;

src/sentry_ratelimiter.c

@@ -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;
@@ -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;
 }

src/sentry_sync.c

@@ -133,8 +133,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;
@@ -147,7 +146,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;
         }

src/sentry_utils.h

@@ -7,6 +7,7 @@
 #    include <winnt.h>
 #else
 #    include <sys/time.h>
+#    include <time.h>
 #endif
 
 /**
@@ -108,6 +109,42 @@ 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
+    static LARGE_INTEGER qpc_frequency = { 0 };
+
+    if (!qpc_frequency.QuadPart) {
+        QueryPerformanceFrequency(&qpc_frequency);
+    }
+
+    // Fallback to GetTickCount() on QPC fail
+    if (!qpc_frequency.QuadPart) {
+#    if _WIN32_WINNT >= 0x0600
+        return GetTickCount64();
+#    else
+        return GetTickCount();
+#    endif
+    }
+
+    LARGE_INTEGER qpc_counter;
+    QueryPerformanceCounter(&qpc_counter);
+    return qpc_counter.QuadPart * 1000 / qpc_frequency.QuadPart;
+#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.
  */

src/transports/sentry_transport_winhttp.c

@@ -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) {
@@ -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

tests/__init__.py

@@ -13,14 +13,12 @@
 
 def make_dsn(httpserver, auth="uiaeosnrtdy", id=123456):
     url = urllib.parse.urlsplit(httpserver.url_for("/{}".format(id)))
+    # We explicitly use `127.0.0.1` here, because on Windows, `localhost` will
+    # first try `::1` (the ipv6 loopback), retry a couple times and give up
+    # after a timeout of 2 seconds, falling back to the ipv4 loopback instead.
+    host = url.netloc.replace("localhost", "127.0.0.1")
     return urllib.parse.urlunsplit(
-        (
-            url.scheme,
-            "{}@{}".format(auth, url.netloc),
-            url.path,
-            url.query,
-            url.fragment,
-        )
+        (url.scheme, "{}@{}".format(auth, host), url.path, url.query, url.fragment,)
     )
 
 

tests/unit/test_ratelimiter.c

@@ -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"));