From 1a23e54880a7b4b2337005f03097aede1ac04aa5 Mon Sep 17 00:00:00 2001 From: Joyce <115662568+sfc-gh-ext-simba-jl@users.noreply.github.com> Date: Tue, 24 Sep 2024 10:16:42 -0700 Subject: [PATCH] SNOW-80092: Send clientStartTime with each /queries/v1/query-request (#746) Send clientStartTime (current time in milliseconds since epoch) with each /queries/v1/query-request --- cpp/util/SnowflakeCommon.cpp | 5 +++++ lib/client_int.h | 1 + lib/connection.c | 9 ++++++-- lib/connection.h | 7 +++++- lib/http_perform.c | 2 +- tests/test_unit_retry_context.c | 39 ++++++++++++++++++++++++++++----- 6 files changed, 54 insertions(+), 9 deletions(-) diff --git a/cpp/util/SnowflakeCommon.cpp b/cpp/util/SnowflakeCommon.cpp index e4c0b743a1..b12642b6c4 100644 --- a/cpp/util/SnowflakeCommon.cpp +++ b/cpp/util/SnowflakeCommon.cpp @@ -137,5 +137,10 @@ void STDCALL sf_memory_error_handler() exit(EXIT_FAILURE); } +uint64 sf_get_current_time_millis() +{ + return std::chrono::duration_cast(std::chrono::system_clock::now().time_since_epoch()).count(); +} + } diff --git a/lib/client_int.h b/lib/client_int.h index 66c4ea36f9..ed6b46c5a2 100644 --- a/lib/client_int.h +++ b/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" diff --git a/lib/connection.c b/lib/connection.c index 5176607223..64f9578c83 100644 --- a/lib/connection.c +++ b/lib/connection.c @@ -1097,7 +1097,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 +1169,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; @@ -1339,4 +1344,4 @@ int64 get_retry_timeout(SF_CONNECT *sf) int8 get_login_retry_count(SF_CONNECT *sf) { return (int8)get_less_one(sf->retry_on_connect_count, sf->retry_count); -} +} \ No newline at end of file diff --git a/lib/connection.h b/lib/connection.h index d27cf9d6b9..af56504750 100644 --- a/lib/connection.h +++ b/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 sf_get_current_time_millis(); + #ifdef __cplusplus } #endif diff --git a/lib/http_perform.c b/lib/http_perform.c index 292427b38b..3ae2d19aa5 100644 --- a/lib/http_perform.c +++ b/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) + sf_get_current_time_millis() // start time }; time_t elapsedRetryTime = time(NULL); RAW_JSON_BUFFER buffer = {NULL, 0}; diff --git a/tests/test_unit_retry_context.c b/tests/test_unit_retry_context.c index e1c8dacb15..db38544358 100644 --- a/tests/test_unit_retry_context.c +++ b/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,7 +69,8 @@ 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 + sf_get_current_time_millis() // start time }; sf_bool ret = retry_ctx_update_url(&retry_ctx, urlbuf, SF_BOOLEAN_FALSE); @@ -79,6 +82,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 +104,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 +117,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 +145,9 @@ 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 + sf_get_current_time_millis() // start time }; - sf_bool ret = retry_ctx_update_url(&retry_ctx, urlbuf, SF_BOOLEAN_TRUE); assert_int_equal(ret, SF_BOOLEAN_TRUE); @@ -141,6 +157,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 +175,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 +188,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,7 +215,7 @@ void test_new_retry_strategy(void **unused) { SF_RETRY_TIMEOUT, djb.base, // time to sleep &djb, // Decorrelate jitter - time(NULL) + sf_get_current_time_millis() // start time }; uint32 error_codes[SF_MAX_RETRY] = {429, 503, 403, 408, 400, 538, 525}; @@ -202,7 +231,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)