From 7449865fe3919f21ea2f4291eaebb8ff0e134c63 Mon Sep 17 00:00:00 2001 From: Richard Whitehouse Date: Thu, 30 Nov 2017 16:56:53 +0000 Subject: [PATCH 1/4] Alter timeout ordering with connections - Check whether a connection has succeded before checking whether it's timed out. This means if we've connected quickly, but subsequently been descheduled, we allow the connection to succeed. Note, if we timeout, but between checking the timeout, and connecting to the server the connection succeeds, we will allow it to go ahead. This is viewed as an acceptable trade off. - Add additional failf logging around failed connection attempts to propogate the cause up to the caller. --- lib/connect.c | 31 +++++++++------ lib/multi.c | 108 +++++++++++++++++++++++++++++++------------------- lib/url.c | 7 +++- 3 files changed, 92 insertions(+), 54 deletions(-) diff --git a/lib/connect.c b/lib/connect.c index d9317f3783c8f2..22cd1c08ff6d87 100644 --- a/lib/connect.c +++ b/lib/connect.c @@ -872,15 +872,6 @@ CURLcode Curl_is_connected(struct Curl_easy *data, now = Curl_now(); - /* figure out how long time we have left to connect */ - allow = Curl_timeleft(data, &now, TRUE); - - if(allow < 0) { - /* time-out, bail out, go home */ - failf(data, "Connection time-out"); - return CURLE_OPERATION_TIMEDOUT; - } - if(SOCKS_STATE(conn->cnnct.state)) { /* still doing SOCKS */ result = connect_SOCKS(data, sockindex, connected); @@ -1006,6 +997,21 @@ CURLcode Curl_is_connected(struct Curl_easy *data, } } + /* + * Now that we've checked whether we are connected, check whether we've + * already timed out. + * + * First figure out how long time we have left to connect */ + + allow = Curl_timeleft(data, &now, TRUE); + + if(allow < 0) { + /* time-out, bail out, go home */ + failf(data, "Connection timeout after %ld ms", + Curl_timediff(now, data->progress.t_startsingle)); + return CURLE_OPERATION_TIMEDOUT; + } + if(result && (conn->tempsock[0] == CURL_SOCKET_BAD) && (conn->tempsock[1] == CURL_SOCKET_BAD)) { @@ -1031,9 +1037,10 @@ CURLcode Curl_is_connected(struct Curl_easy *data, else hostname = conn->host.name; - failf(data, "Failed to connect to %s port %ld: %s", - hostname, conn->port, - Curl_strerror(error, buffer, sizeof(buffer))); + failf(data, "Failed to connect to %s port %ld after %ld ms: %s", + hostname, conn->port, + Curl_timediff(now, data->progress.t_startsingle), + Curl_strerror(error, buffer, sizeof(buffer))); Curl_quic_disconnect(data, conn, 0); Curl_quic_disconnect(data, conn, 1); diff --git a/lib/multi.c b/lib/multi.c index 1b3e261c682a47..dc858df3ca5db0 100644 --- a/lib/multi.c +++ b/lib/multi.c @@ -1539,6 +1539,58 @@ static CURLcode multi_do_more(struct Curl_easy *data, int *complete) return result; } +/* + * Check whether a timeout occurred, and handle it if it did + */ +static bool multi_handle_timeout(struct Curl_easy *data, + struct curltime *now, + bool *stream_error, + CURLcode *result, + bool connect_timeout) +{ + timediff_t timeout_ms; + timeout_ms = Curl_timeleft(data, now, connect_timeout); + + if(timeout_ms < 0) { + /* Handle timed out */ + if(data->mstate == MSTATE_RESOLVING) + failf(data, "Resolving timed out after %" CURL_FORMAT_TIMEDIFF_T + " milliseconds", + Curl_timediff(*now, data->progress.t_startsingle)); + else if(data->mstate == MSTATE_CONNECTING) + failf(data, "Connection timed out after %" CURL_FORMAT_TIMEDIFF_T + " milliseconds", + Curl_timediff(*now, data->progress.t_startsingle)); + else { + struct SingleRequest *k = &data->req; + if(k->size != -1) { + failf(data, "Operation timed out after %" CURL_FORMAT_TIMEDIFF_T + " milliseconds with %" CURL_FORMAT_CURL_OFF_T " out of %" + CURL_FORMAT_CURL_OFF_T " bytes received", + Curl_timediff(*now, data->progress.t_startsingle), + k->bytecount, k->size); + } + else { + failf(data, "Operation timed out after %" CURL_FORMAT_TIMEDIFF_T + " milliseconds with %" CURL_FORMAT_CURL_OFF_T + " bytes received", + Curl_timediff(*now, data->progress.t_startsingle), + k->bytecount); + } + } + + /* Force connection closed if the connection has indeed been used */ + if(data->mstate > MSTATE_DO) { + streamclose(data->conn, "Disconnected with pending data"); + *stream_error = TRUE; + } + *result = CURLE_OPERATION_TIMEDOUT; + (void)multi_done(data, *result, TRUE); + } + + return (timeout_ms < 0); +} + /* * We are doing protocol-specific connecting and this is being called over and * over from the multi interface until the connection phase is done on @@ -1670,7 +1722,6 @@ static CURLMcode multi_runsingle(struct Curl_multi *multi, bool done = FALSE; CURLMcode rc; CURLcode result = CURLE_OK; - timediff_t timeout_ms; timediff_t recv_timeout_ms; timediff_t send_timeout_ms; int control; @@ -1700,47 +1751,13 @@ static CURLMcode multi_runsingle(struct Curl_multi *multi, if(data->conn && (data->mstate >= MSTATE_CONNECT) && (data->mstate < MSTATE_COMPLETED)) { + /* We defer handling the connection timeout to later, to see if the + * connection has actually succeeded. + * See https://github.com/Metaswitch/curl/pull/2 for original changes */ + /* we need to wait for the connect state as only then is the start time stored, but we must not check already completed handles */ - timeout_ms = Curl_timeleft(data, nowp, - (data->mstate <= MSTATE_DO)? - TRUE:FALSE); - - if(timeout_ms < 0) { - /* Handle timed out */ - if(data->mstate == MSTATE_RESOLVING) - failf(data, "Resolving timed out after %" CURL_FORMAT_TIMEDIFF_T - " milliseconds", - Curl_timediff(*nowp, data->progress.t_startsingle)); - else if(data->mstate == MSTATE_CONNECTING) - failf(data, "Connection timed out after %" CURL_FORMAT_TIMEDIFF_T - " milliseconds", - Curl_timediff(*nowp, data->progress.t_startsingle)); - else { - struct SingleRequest *k = &data->req; - if(k->size != -1) { - failf(data, "Operation timed out after %" CURL_FORMAT_TIMEDIFF_T - " milliseconds with %" CURL_FORMAT_CURL_OFF_T " out of %" - CURL_FORMAT_CURL_OFF_T " bytes received", - Curl_timediff(*nowp, data->progress.t_startsingle), - k->bytecount, k->size); - } - else { - failf(data, "Operation timed out after %" CURL_FORMAT_TIMEDIFF_T - " milliseconds with %" CURL_FORMAT_CURL_OFF_T - " bytes received", - Curl_timediff(*nowp, data->progress.t_startsingle), - k->bytecount); - } - } - - /* Force connection closed if the connection has indeed been used */ - if(data->mstate > MSTATE_DO) { - streamclose(data->conn, "Disconnected with pending data"); - stream_error = TRUE; - } - result = CURLE_OPERATION_TIMEDOUT; - (void)multi_done(data, result, TRUE); + if(multi_handle_timeout(data, nowp, &stream_error, &result, FALSE)) { /* Skip the statemachine and go directly to error handling section. */ goto statemachine_end; } @@ -2418,6 +2435,17 @@ static CURLMcode multi_runsingle(struct Curl_multi *multi, default: return CURLM_INTERNAL_ERROR; } + + if(data->conn && + data->mstate >= MSTATE_CONNECT && + data->mstate <= MSTATE_DO && + rc != CURLM_CALL_MULTI_PERFORM && + multi_ischanged(multi, false)) { + /* We now handle stream timeouts if and only if this will be the last + * loop iteration */ + multi_handle_timeout(data, nowp, &stream_error, &result, TRUE); + } + statemachine_end: if(data->mstate < MSTATE_COMPLETED) { diff --git a/lib/url.c b/lib/url.c index edcdf54b1a07e1..290698386e3b4d 100644 --- a/lib/url.c +++ b/lib/url.c @@ -3355,9 +3355,12 @@ static CURLcode resolve_server(struct Curl_easy *data, if(rc == CURLRESOLV_PENDING) *async = TRUE; - else if(rc == CURLRESOLV_TIMEDOUT) + else if(rc == CURLRESOLV_TIMEDOUT) { + failf(data, "Failed to resolve host '%s' with timeout after %ld ms", + connhost->dispname, + Curl_timediff(Curl_now(), data->progress.t_startsingle)); result = CURLE_OPERATION_TIMEDOUT; - + } else if(!hostaddr) { failf(data, "Could not resolve host: %s", connhost->dispname); result = CURLE_COULDNT_RESOLVE_HOST; From 9b50e55fc2d250c213985381a0ab6bf468f84a23 Mon Sep 17 00:00:00 2001 From: Martin Howarth Date: Fri, 18 Jun 2021 13:05:26 +0100 Subject: [PATCH 2/4] Calculate time left when reducing per-connection timeouts as well --- lib/connect.c | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/connect.c b/lib/connect.c index 22cd1c08ff6d87..18d3d84f5259a0 100644 --- a/lib/connect.c +++ b/lib/connect.c @@ -985,6 +985,7 @@ CURLcode Curl_is_connected(struct Curl_easy *data, Curl_strerror(error, buffer, sizeof(buffer))); #endif + allow = Curl_timeleft(data, &now, TRUE); conn->timeoutms_per_addr[i] = conn->tempaddr[i]->ai_next == NULL ? allow : allow / 2; ainext(conn, i, TRUE); From 2a8c04bdfeeec6e7f6328cf6eb8099fec7a41522 Mon Sep 17 00:00:00 2001 From: Martin Howarth Date: Mon, 21 Jun 2021 14:45:00 +0100 Subject: [PATCH 3/4] Fix timeout check and improve comments. --- lib/multi.c | 17 ++++++++++++----- 1 file changed, 12 insertions(+), 5 deletions(-) diff --git a/lib/multi.c b/lib/multi.c index dc858df3ca5db0..90af8e53c97682 100644 --- a/lib/multi.c +++ b/lib/multi.c @@ -1751,9 +1751,12 @@ static CURLMcode multi_runsingle(struct Curl_multi *multi, if(data->conn && (data->mstate >= MSTATE_CONNECT) && (data->mstate < MSTATE_COMPLETED)) { - /* We defer handling the connection timeout to later, to see if the - * connection has actually succeeded. - * See https://github.com/Metaswitch/curl/pull/2 for original changes */ + /* Check for overall operation timeout here but defer handling the + * connection timeout to later, to allow for a connection to be set up + * in the window since we last checked timeout. This prevents us + * tearing down a completed connection in the case where we were slow + * to check the timeout (e.g. process descheduled during this loop). + * We set connect_timeout=FALSE to do this.*/ /* we need to wait for the connect state as only then is the start time stored, but we must not check already completed handles */ @@ -2440,9 +2443,13 @@ static CURLMcode multi_runsingle(struct Curl_multi *multi, data->mstate >= MSTATE_CONNECT && data->mstate <= MSTATE_DO && rc != CURLM_CALL_MULTI_PERFORM && - multi_ischanged(multi, false)) { + !multi_ischanged(multi, false)) { /* We now handle stream timeouts if and only if this will be the last - * loop iteration */ + * loop iteration. We only check this on the last iteration to ensure + * that if we know we have additional work to do immediately + * (i.e. CURLM_CALL_MULTI_PERFORM == TRUE) then we should do that before + * declaring the connection timed out as we may almost have a completed + * connection. */ multi_handle_timeout(data, nowp, &stream_error, &result, TRUE); } From 74527e43541c75a0431618c31e99a89688a6fa3e Mon Sep 17 00:00:00 2001 From: Martin Howarth Date: Mon, 21 Jun 2021 15:41:40 +0100 Subject: [PATCH 4/4] Don't check timeouts in DO state --- lib/multi.c | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/lib/multi.c b/lib/multi.c index 90af8e53c97682..34a4cde9a83803 100644 --- a/lib/multi.c +++ b/lib/multi.c @@ -1751,12 +1751,12 @@ static CURLMcode multi_runsingle(struct Curl_multi *multi, if(data->conn && (data->mstate >= MSTATE_CONNECT) && (data->mstate < MSTATE_COMPLETED)) { - /* Check for overall operation timeout here but defer handling the + /* Check for overall operation timeout here but defer handling the * connection timeout to later, to allow for a connection to be set up - * in the window since we last checked timeout. This prevents us + * in the window since we last checked timeout. This prevents us * tearing down a completed connection in the case where we were slow * to check the timeout (e.g. process descheduled during this loop). - * We set connect_timeout=FALSE to do this.*/ + * We set connect_timeout=FALSE to do this. */ /* we need to wait for the connect state as only then is the start time stored, but we must not check already completed handles */ @@ -2441,7 +2441,7 @@ static CURLMcode multi_runsingle(struct Curl_multi *multi, if(data->conn && data->mstate >= MSTATE_CONNECT && - data->mstate <= MSTATE_DO && + data->mstate < MSTATE_DO && rc != CURLM_CALL_MULTI_PERFORM && !multi_ischanged(multi, false)) { /* We now handle stream timeouts if and only if this will be the last