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

Jump to bottom

HTTP request timeout with CURLMOPT_MAX_TOTAL_CONNECTIONS set low #6744

Closed
bagder opened this issue Mar 14, 2021 · 6 comments · Fixed by #6745
Closed

HTTP request timeout with CURLMOPT_MAX_TOTAL_CONNECTIONS set low #6744

bagder opened this issue Mar 14, 2021 · 6 comments · Fixed by #6745
Assignees
@bagder
Labels
HTTP performance

Comments

@bagder
Copy link
Member

bagder commented Mar 14, 2021

(Issue filed on behalf of Andrei Bica)

I've managed to produce this behavior by using a modified multi-poll.c example (see below) which makes 10 HTTP requests to "example.org:8200", set CURLOPT_TIMEOUT_MS to 1000 for each request and
CURLMOPT_MAX_TOTAL_CONNECTIONS to 1 for the multi handle.

I've used iptables to drop all packets going to URL address:

iptables -A OUTPUT -p tcp --destination-port 8200 -j DROP

I would expect the runtime to be around 1000 ms (the value of CURLOPT_TIMEOUT_MS), but instead I get a runtime of about 7000 ms.

#include <stdio.h>
#include <string.h>

/* somewhat unix-specific */
#include <sys/time.h>
#include <unistd.h>

/* curl stuff */
#include <curl/curl.h>

#define COUNT 10
#define URL "example.org:8200"

int main(void)
{
  CURL *http_handles[COUNT];
  CURLM *multi_handle;
  int still_running = 1; /* keep number of running handles */

  curl_global_init(CURL_GLOBAL_DEFAULT);

  multi_handle = curl_multi_init();
  curl_multi_setopt(multi_handle, CURLMOPT_MAX_TOTAL_CONNECTIONS, 1l);

  for (int i = 0 ; i < COUNT ; i++) {
    http_handles[i] = curl_easy_init();
    curl_easy_setopt(http_handles[i], CURLOPT_URL, URL);
    curl_easy_setopt(http_handles[i], CURLOPT_TIMEOUT_MS, 1000l);
    curl_multi_add_handle(multi_handle, http_handles[i]);
  }

  while(still_running) {
    CURLMcode mc; /* curl_multi_poll() return code */
    int numfds;

    /* we start some action by calling perform right away */
    mc = curl_multi_perform(multi_handle, &still_running);

    if(still_running)
      /* wait for activity, timeout or "nothing" */
      mc = curl_multi_poll(multi_handle, NULL, 0, 100, &numfds);

    if(mc != CURLM_OK) {
      fprintf(stderr, "curl_multi_wait() failed, code %d.\n", mc);
      break;
    }
  }

  for (int i = 0 ; i < COUNT ; i++) {
    curl_multi_remove_handle(multi_handle, http_handles[i]);
    curl_easy_cleanup(http_handles[i]);
  }

  curl_multi_cleanup(multi_handle);
  curl_global_cleanup();

  return 0;
}

operating system

Linux
@bagder
Copy link
Member Author

bagder commented Mar 14, 2021

Why this happens:

When a connection is moved from the PENDING state (waiting for a connection) it is moved to CONNECT state and the TIMER_STARTSINGLE time stamp is set (again).

Curl_timeleft() is the function that checks how long time a handle has left until timed out, and "during connect" it will check if the time since TIMER_STARTSINGLE until now is larger than the timeout (or the CURLOPT_CONNECTTIMEOUT if that is set).

This has the effect that with CURLOPT_TIMEOUT set to 1000ms, it will allow each handle 1000ms to connect after having been moved to CONNECT and when it fails, it will move in the next handle that then also will wait...

I haven't yet really figured out exactly how I think this should be fixed...

@jay
Copy link
Member

jay commented Mar 15, 2021

This has the effect that with CURLOPT_TIMEOUT set to 1000ms, it will allow each handle 1000ms to connect after having been moved to CONNECT and when it fails, it will move in the next handle that then also will wait...

I haven't yet really figured out exactly how I think this should be fixed...

He set an option that limits the number of connections. I don't see the bug, what am I missing?

@bagder
Copy link
Member Author

bagder commented Mar 15, 2021

He set an option that limits the number of connections

That's why the queued transfers are in the PENDING state.

I don't see the bug, what am I missing?

CURLOPT_TIMEOUT is documented to be the max time a transfer is allowed to spend while in the report some of them takes much longer time to get cancelled. I didn't reproduce (yet) but I read the code and it is obvious it can happen as I explained above.

@jay
Copy link
Member

jay commented Mar 15, 2021

They take 1000ms to get canceled just not including queue time, and that's the rub, if I understand you correctly.

@bagder
Copy link
Member Author

bagder commented Mar 15, 2021

Basically, yes. Which isn't how it is supposed to work. CURLOPT_TIMEOUT is meant to include the queue time. The maximum time allowed for a transfer to be "in operation" no matter in which internal state the transfer is or isn't in or transitions through.

I have a local fix I think is decent and very simple. I'll only test it out a little bit more first...

bagder added a commit that referenced this issue Mar 15, 2021
@bagder
Curl_timeleft: check both timeouts even during connect
768cac9 
The duration of a connect and the total transfer are calculated from two
different time-stamps. It can end up with the total timeout triggering
before the connect timeout expires and we should make sure to
acknowledge whichever timeout that is reached first.

This is especially notable when a transfer first sits in PENDING, as
that time is counted in the total time but the connect timeout is based
on the time since the handle changed to the CONNECT state.

Fixes #6744
Reported-by: Andrei Bica
@bagder bagder mentioned this issue Mar 15, 2021
Merged
bagder added a commit that referenced this issue Mar 16, 2021
@bagder
Curl_timeleft: check both timeouts during connect
a8e27f1 
The duration of a connect and the total transfer are calculated from two
different time-stamps. It can end up with the total timeout triggering
before the connect timeout expires and we should make sure to
acknowledge whichever timeout that is reached first.

This is especially notable when a transfer first sits in PENDING, as
that time is counted in the total time but the connect timeout is based
on the time since the handle changed to the CONNECT state.

The CONNECTTIMEOUT is per connect attempt. The TIMEOUT is for the entire
operation.

Fixes #6744
Reported-by: Andrei Bica
@bagder bagder self-assigned this Mar 16, 2021
@bagder bagder closed this as completed in e8e7ef3 Mar 17, 2021
@mezzatto
Copy link

mezzatto commented Jun 8, 2021

Should https://github.com/curl/curl/blob/master/tests/unit/unit1303.c have been updated to reflect this change?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@bagder bagder

Labels
HTTP performance
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Curl_timeleft: check both timeouts even during connect curl/curl
3 participants
@bagder @mezzatto @jay