send clientStartTime for query-request

lib/client_int.h

@@ -35,6 +35,7 @@
 #define URL_PARAM_REQEST_GUID "request_guid="
 #define URL_PARAM_RETRY_COUNT "retryCount="
 #define URL_PARAM_RETRY_REASON "retryReason="
+#define URL_PARAM_CLIENT_START_TIME "clientStartTime="
 
 #define CLIENT_APP_ID_KEY "CLIENT_APP_ID"
 #define CLIENT_APP_VERSION_KEY "CLIENT_APP_VERSION"

lib/connection.c

@@ -13,9 +13,16 @@
 #include "authenticator.h"
 #include "curl_desc_pool.h"
 
+#ifdef _WIN32
+#include <time.h>
+#else
+#include <sys/time.h>
+#endif
+
 #define curl_easier_escape(curl, string) curl_easy_escape(curl, string, 0)
 #define QUERYCODE_LEN 7
 #define REQUEST_GUID_KEY_SIZE 13
+#define EPOCH_OFFSET 116444736000000000LL
 
 /*
  * Debug functions from curl example. Should update at somepoint, and possibly remove from header since these are private functions
@@ -1097,7 +1104,7 @@ uint32 STDCALL retry_ctx_next_sleep(RETRY_CONTEXT *retry_ctx) {
     retry_ctx->sleep_time = get_next_sleep_with_jitter(retry_ctx->djb, retry_ctx->sleep_time, retry_ctx->retry_count);
 
     // limit the sleep time within retry timeout
-    uint32 time_elapsed = time(NULL) - retry_ctx->start_time;
+    uint32 time_elapsed = time(NULL) - (retry_ctx->start_time / 1000);
     if (time_elapsed >= retry_ctx->retry_timeout)
     {
       // retry timeout is checked before calling retry_ctx_next_sleep
@@ -1169,6 +1176,11 @@ sf_bool STDCALL retry_ctx_update_url(RETRY_CONTEXT *retry_ctx,
       retry_ctx->retry_reason = 0;
     }
 
+    // add client start time in milliseconds
+    SPRINT_TO_BUFFER(retry_context_ptr, "%s", URL_PARAM_CLIENT_START_TIME);
+    SPRINT_TO_BUFFER(retry_context_ptr, "%llu", retry_ctx->start_time);
+    SPRINT_TO_BUFFER(retry_context_ptr, "%s", URL_PARAM_DELIM);
+
     // add request guid after retry context
     request_guid_ptr = retry_context_ptr;
 
@@ -1340,3 +1352,19 @@ int8 get_login_retry_count(SF_CONNECT *sf)
 {
   return (int8)get_less_one(sf->retry_on_connect_count, sf->retry_count);
 }
+
+uint64_t get_current_time_millis()
+{
+#if defined(__linux__) || defined(__APPLE__)
+    struct timeval tv;
+    gettimeofday(&tv, NULL);
+    return ((uint64_t)tv.tv_sec * 1000) + (tv.tv_usec / 1000);
+#else // Windows
+    FILETIME ft;
+    ULARGE_INTEGER ui;
+    GetSystemTimeAsFileTime(&ft);
+    ui.LowPart = ft.dwLowDateTime;
+    ui.HighPart = ft.dwHighDateTime;
+    return (ui.QuadPart - EPOCH_OFFSET) / 10000;
+#endif
+}

lib/connection.h

@@ -137,7 +137,7 @@ typedef struct RETRY_CONTEXT {
     // Decorrelate Jitter is used to determine sleep time
     DECORRELATE_JITTER_BACKOFF *djb;
     // start time to track on retry timeout
-    time_t start_time;
+    uint64 start_time;
 } RETRY_CONTEXT;
 
 typedef struct SF_HEADER {
@@ -618,6 +618,11 @@ int8 get_login_retry_count(SF_CONNECT *sf);
 */
 int64 get_retry_timeout(SF_CONNECT *sf);
 
+/*
+* Get current time since epoch in milliseconds
+*/
+uint64_t get_current_time_millis();
+
 #ifdef __cplusplus
 }
 #endif

lib/http_perform.c

@@ -186,7 +186,7 @@ sf_bool STDCALL http_perform(CURL *curl,
             network_timeout,
             djb.base,      // time to sleep
             &djb,    // Decorrelate jitter
-            time(NULL)
+            get_current_time_millis() // start time
     };
     time_t elapsedRetryTime = time(NULL);
     RAW_JSON_BUFFER buffer = {NULL, 0};

tests/test_unit_retry_context.c

@@ -13,6 +13,7 @@
 #define URL_NON_QUERY_WITH_GUID "http://snowflake.com/other-path?request_guid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx"
 #define URL_NO_GUID "http://snowflake.com/other-path"
 #define GUID_LENGTH strlen("request_guid=xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx")
+#define CLIENT_START_TIME_LENGTH strlen("clientStartTime=xxxxxxxxxxxxx&")
 
 #define URL_LOGIN "http://snowflake.com/session/v1/login-request"
 #define URL_TOKEN "http://snowflake.com/session/token-request"
@@ -52,6 +53,7 @@ void test_update_other_url_with_guid(void **unused) {
   assert_int_equal(strlen(urlbuf), strlen(URL_NON_QUERY_WITH_GUID));
   assert_null(strstr(urlbuf, URL_PARAM_RETRY_COUNT));
   assert_null(strstr(urlbuf, URL_PARAM_RETRY_REASON));
+  assert_null(strstr(urlbuf, URL_PARAM_CLIENT_START_TIME));
   char* guid_ptr = strstr(urlbuf, URL_PARAM_REQEST_GUID);
   assert_non_null(guid_ptr);
   assert_int_equal(strlen(guid_ptr), GUID_LENGTH);
@@ -67,9 +69,11 @@ void test_update_query_url_with_retry_reason_disabled(void **unused) {
     429,    // retry reason
     0,      // network_timeout
     1,      // time to sleep
-    NULL    // Decorrelate jitter
+    NULL,   // Decorrelate jitter
+    get_current_time_millis() // start time
   };
 
+  sf_fprintf(stderr, "== Debug: current time in millis: %llu\n", retry_ctx.start_time);
   sf_bool ret = retry_ctx_update_url(&retry_ctx, urlbuf, SF_BOOLEAN_FALSE);
   assert_int_equal(ret, SF_BOOLEAN_TRUE);
 
@@ -79,6 +83,12 @@ void test_update_query_url_with_retry_reason_disabled(void **unused) {
   assert_int_equal(strlen(guid_ptr), GUID_LENGTH);
   *guid_ptr = '\0';
 
+  // should have client start time added
+  char* starttime_ptr = strstr(urlbuf, URL_PARAM_CLIENT_START_TIME);
+  assert_non_null(starttime_ptr);
+  assert_int_equal(strlen(starttime_ptr), CLIENT_START_TIME_LENGTH);
+  *starttime_ptr = '\0';
+
   // should not have retry reason added
   char* retryreason_ptr = strstr(urlbuf, URL_PARAM_RETRY_REASON);
   assert_null(retryreason_ptr);
@@ -95,6 +105,7 @@ void test_update_query_url_with_retry_reason_disabled(void **unused) {
   // recover the updated URL for testing next retry
   *guid_ptr = 'r';
   *retrycount_ptr = 'r';
+  *starttime_ptr = 'c';
   retry_ctx.retry_count = 2;
   retry_ctx.retry_reason = 503;
 
@@ -107,6 +118,12 @@ void test_update_query_url_with_retry_reason_disabled(void **unused) {
   assert_int_equal(strlen(guid_ptr), GUID_LENGTH);
   *guid_ptr = '\0';
 
+  // should have client start time added
+  starttime_ptr = strstr(urlbuf, URL_PARAM_CLIENT_START_TIME);
+  assert_non_null(starttime_ptr);
+  assert_int_equal(strlen(starttime_ptr), CLIENT_START_TIME_LENGTH);
+  *starttime_ptr = '\0';
+
   // should not have retry reason added
   retryreason_ptr = strstr(urlbuf, URL_PARAM_RETRY_REASON);
   assert_null(retryreason_ptr);
@@ -129,9 +146,10 @@ void test_update_query_url_with_retry_reason_enabled(void **unused) {
     429,    // retry reason
     0,      // network_timeout
     1,      // time to sleep
-    NULL    // Decorrelate jitter
+    NULL,    // Decorrelate jitter
+    get_current_time_millis() // start time
   };
-
+  sf_fprintf(stderr, "== Debug: current time in millis: %llu\n", retry_ctx.start_time);
   sf_bool ret = retry_ctx_update_url(&retry_ctx, urlbuf, SF_BOOLEAN_TRUE);
   assert_int_equal(ret, SF_BOOLEAN_TRUE);
 
@@ -141,6 +159,12 @@ void test_update_query_url_with_retry_reason_enabled(void **unused) {
   assert_int_equal(strlen(guid_ptr), GUID_LENGTH);
   *guid_ptr = '\0';
 
+  // should have client start time added
+  char* starttime_ptr = strstr(urlbuf, URL_PARAM_CLIENT_START_TIME);
+  assert_non_null(starttime_ptr);
+  assert_int_equal(strlen(starttime_ptr), CLIENT_START_TIME_LENGTH);
+  *starttime_ptr = '\0';
+
   // should have retry count/reason added
   char* retrycount_ptr = strstr(urlbuf, URL_PARAM_RETRY_COUNT);
   assert_non_null(retrycount_ptr);
@@ -153,6 +177,7 @@ void test_update_query_url_with_retry_reason_enabled(void **unused) {
   // recover the updated URL for testing next retry
   *guid_ptr = 'r';
   *retrycount_ptr = 'r';
+  *starttime_ptr = 'c';
   retry_ctx.retry_count = 2;
   retry_ctx.retry_reason = 503;
 
@@ -165,6 +190,12 @@ void test_update_query_url_with_retry_reason_enabled(void **unused) {
   assert_int_equal(strlen(guid_ptr), GUID_LENGTH);
   *guid_ptr = '\0';
 
+  // should have client start time added
+  starttime_ptr = strstr(urlbuf, URL_PARAM_CLIENT_START_TIME);
+  assert_non_null(starttime_ptr);
+  assert_int_equal(strlen(starttime_ptr), CLIENT_START_TIME_LENGTH);
+  *starttime_ptr = '\0';
+
   // should have retry count/reason updated
   retrycount_ptr = strstr(urlbuf, URL_PARAM_RETRY_COUNT);
   assert_non_null(retrycount_ptr);
@@ -186,9 +217,10 @@ void test_new_retry_strategy(void **unused) {
     SF_RETRY_TIMEOUT,
     djb.base,      // time to sleep
     &djb,    // Decorrelate jitter
-    time(NULL)
+    get_current_time_millis() // start time
   };
 
+  sf_fprintf(stderr, "== Debug: current time in millis: %llu\n", curl_retry_ctx.start_time);
   uint32 error_codes[SF_MAX_RETRY] = {429, 503, 403, 408, 400, 538, 525};
   uint32 backoff = SF_BACKOFF_BASE;
   uint32 next_sleep_in_secs = 0;
@@ -202,7 +234,7 @@ void test_new_retry_strategy(void **unused) {
     assert_int_equal(is_retryable_http_code(error_codes[retry_count]), SF_BOOLEAN_TRUE);
     next_sleep_in_secs = retry_ctx_next_sleep(&curl_retry_ctx);
     // change the start time to mock the time elapsed
-    curl_retry_ctx.start_time -= next_sleep_in_secs;
+    curl_retry_ctx.start_time -= next_sleep_in_secs * 1000;
     total_backoff += next_sleep_in_secs;
 
     if (total_backoff + next_sleep_in_secs >= SF_LOGIN_TIMEOUT)