Regression (8.15 -> 8.17): CURLMOPT_MAX_HOST_CONNECTIONS causes PENDING handle timeouts under sustained HTTPS load

[juanbelonepic]

I did this

I'm doing requests for uploading ~2.4M small analytics events from a standalone tool as roughly 800 concurrent HTTPS POST requests to a single host (TLS 1.3, HTTP/1.1). Pool is constrained with:

• CURLMOPT_MAX_HOST_CONNECTIONS = 16
• CURLMOPT_MAX_TOTAL_CONNECTIONS = 256
• CURLMOPT_CONNECTTIMEOUT = 30s
• No CURLOPT_TIMEOUT
• Multi interface, repeated curl_multi_perform, one easy handle per request, added in a tight loop.

The easy handles are created via a CURLSH-shared DNS/connection pool on the multi handle, same config that has been in use for years.

I expected the following

All requests complete successfully (this is what happens with curl 8.15.0 : zero errors).

What goes wrong

About 49 out of ~800 requests fail with CURLE_OPERATION_TIMEDOUT after 30s. The info cache of every failing request is dominated by repeated "No more connections allowed to host" messages (~20-40 of them in a row), followed finally by a late TCP connect attempt that never completes within the remaining budget:

libcurl info message cache 0  (No more connections allowed to host)
libcurl info message cache 1  (No more connections allowed to host)
...
libcurl info message cache 18 (Hostname ___ was found in DNS cache)
libcurl info message cache 19 (  Trying IP:443...)
libcurl info message cache 20 (SSL reusing session with ALPN 'http/1.1')
libcurl info message cache 21 (ALPN: curl offers http/1.1)
libcurl info message cache 22 (TLSv1.3 (OUT), TLS handshake, Client hello (1):)
libcurl info message cache 23 (Connection timed out after 30000 milliseconds)
libcurl info message cache 24 (closing connection #815)

Each failing request spends the bulk of its 30s in MSTATE_PENDING waiting for a slot, gets woken late, and runs out of its connect-timeout budget mid-TLS handshake.

he same workload (same network, same host, same binary except the linked libcurl) produces 0 errors with libcurl 8.15.0.

Total connection IDs also differ: 8.17 reports connection numbers up to #815 (so MaxHost=16 isn't being effectively reused -> connections leave and come back). 8.15 creates a similar number of total connections, but never lets a PENDING handle hit the connect timeout.

Bisect / suspicion

Comparing the source:

• Curl_cpool_check_limits and the dest-limit switch case in create_conn_helper/url.c are effectively unchanged between 8.15 and 8.17.
• What changed in 8.16 (per release notes & source diff):
  • multi: process pending, one by one [90] - process_pending_handles now wakes only a single pending handle per call (present through master).
  • multi: replace remaining EXPIRE_RUN_NOW [67] -> move_pending_to_connect() now calls Curl_multi_mark_dirty(data) instead of Curl_expire(data, 0, EXPIRE_RUN_NOW). Previously the PENDING handle was re-queued via the splay tree for immediate retry; now it is only marked dirty and depends on a future process_pending_handles() call to be woken.
  • In 8.17 the happy-eyeballing code was extracted to cf-ip-happy.c and the connection filter lifecycle was reworked. This also coincides with "vtls: properly handle SSL shutdown timeout [433]" and schannel shutdown tweaks; I haven't isolated whether the connection-filter rework keeps CONN_INUSE true longer.
  • The end result is that under sustained saturation (all 16 live connections busy serving slow remote POSTs), some PENDING handles never get woken before their connect timeout expires.

Things I tried locally in 8.17 that did not fully fix it:

• Revert process_pending_handles to wake all pending handles (8.15 behavior).
• Reset TIMER_STARTSINGLE + re-schedule EXPIRE_CONNECTTIMEOUT inside move_pending_to_connect() so PENDING wait time doesn't count against the connect timeout.
• Schedule a 1s EXPIRE_CONNECTTIMEOUT retry when entering PENDING so the splay tree polls for a slot.
• Cap concurrent cf_ip_attempt entries in cf-ip-happy.c at 2 (to match 8.15's two-baller model).
• Move process_pending_handles(data->multi) in multi_done() to after Curl_cpool_do_locked(... multi_done_locked ...) so the slot is actually free when pending handles wake.

• None of those reliably eliminate the failures.

The only thing that reliably gives 0 errors is making Curl_cpool_check_limits return CPOOL_LIMIT_OK when the dest bundle is full (i.e. disabling MAX_HOST_CONNECTIONS). That implies the regression isn't about wake/timer semantics but about the real connection lifecycle under 8.17 - something keeps connections counting against dest_limit longer than 8.15 did.

How to reproduce (minimal)

1. Multi interface.
2. CURLMOPT_MAX_HOST_CONNECTIONS = 16, CURLMOPT_MAX_TOTAL_CONNECTIONS = 256.
3. CURLOPT_CONNECTTIMEOUT = 30, no CURLOPT_TIMEOUT.
4. Queue ~800 simultaneous HTTPS POSTs to the same remote host (small payload, e.g. 100 KB of JSON, against any real TLS server).
5. Repeatedly call curl_multi_perform until all requests complete.

Happy to put together a standalone C reproducer if that would help - the failure is fully deterministic on my setup with this pattern.

Related

• Multi performance regression 8.13.0 -> 8.14.1 #18017 (introduced the "one by one" pending wake change in 8.14, then adjusted in 8.16)
• Requests start failing after long running connections on 8.17 release #20105 (also 8.15 -> 8.17 connection failures)

curl/libcurl version

libcurl/8.17.0 (OpenSSL 1.1.1t, zlib 1.3, nghttp2 1.64.0, HTTP/2) Windows x64, static lib, built (tried with both debug enabled and disabled)

operating system

Windows 11 / Windows Server 2022 (reproduced on both dev machines).
HTTPS via Schannel not used here -> built with OpenSSL..

[bagder]

Do you still see the problem if you run your test case with curl from current git master?

[juanbelonepic]

Do you still see the problem if you run your test case with curl from current git master?

I would need to integrate latest with UE to test, I'd rather fix the issue in 8.17 if we can do that. Happy to bisect commits between 8.17 and master on lib/multi.c / lib/cf-ip-happy.c if you can point me at likely candidates, or put together a standalone C reproducer if that would help test on master.

[bagder]

If you make a reproducer I can certainly test that against master.

[icing]

We support here mainly the current version of the software and we do not make fixes for past releases, e.g. a curl 8.17.1. We need to reproduce in the current master to make sure the issue still is there and that we have it fixed in the next release.

To your report: since you have only connection timeout configured, it would seem that the connect for a new connection takes more than 30 seconds. That seems to match the part of the trace you listed. It may also be that there is/was a bug in calculating the connect timeout. Or it may be that the server did not respond for 30 seconds.

A reproducer would certainly help. Otherwise a trace with timestamps could clarify this.

[juanbelonepic]

I was wrong, I can't find a way to reproduce the issue purely in curl 8.17 :( , need to investigate our code base more sorry.
I've made a standalone reproducer but without UE in the loop can't repro the bug..., with only libcurl 8.17.0 that runs clean in 2-3 seconds. The UE binary using the same libcurl reliably fails ~25-49/800 requests with CURLE_OPERATION_TIMEDOUT.
So the regression exists but the trigger is UE-side something I haven't isolated. I'll keep digging on our side, probably by stubbing out subsystems in the UE HTTP module one at a time.
Thanks for your time.
Juan

[juanbelonepic]

Found the bug, the theory is that CURLOPT_RESOLVE pre-pins the IP for our datarouter url, curl skips DNS resolution, connections establish faster, the host-connection pool doesn't stay saturated, PENDING handles get their turn before the 30s and CURLOPT_CONNECTTIMEOUT fires.

• repro_pending_timeout.c:

#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <time.h>
#include <stdbool.h>
#ifdef _WIN32
# include <windows.h>
  typedef CRITICAL_SECTION repro_mutex_t;
# define MUTEX_INIT(m)    InitializeCriticalSection(&(m))
# define MUTEX_LOCK(m)    EnterCriticalSection(&(m))
# define MUTEX_UNLOCK(m)  LeaveCriticalSection(&(m))
# define MUTEX_DESTROY(m) DeleteCriticalSection(&(m))
  typedef HANDLE repro_thread_t;
#else
# include <pthread.h>
  typedef pthread_mutex_t repro_mutex_t;
# define MUTEX_INIT(m)    pthread_mutex_init(&(m), NULL)
# define MUTEX_LOCK(m)    pthread_mutex_lock(&(m))
# define MUTEX_UNLOCK(m)  pthread_mutex_unlock(&(m))
# define MUTEX_DESTROY(m) pthread_mutex_destroy(&(m))
  typedef pthread_t repro_thread_t;
#endif
#include <curl/curl.h>

/* Workload parameters - a bursty analytics-style upload */
#define TOTAL_EVENTS       400000      /* events the "app" will record */
#define PAYLOAD_TARGET_SIZE (100*1024) /* flush cache when this big */
#define MAX_HOST_CONN           16L
#define MAX_TOTAL_CONN         256L
#define CONNECT_TIMEOUT_S       30L
#define HTTP_TICK_MS             5      /* 200Hz like UE */
#define MAX_QUEUED_REQUESTS   4096
#define DEFAULT_URL \
  "https://httpbin.org/delay/1"

struct info_cache;
struct upload_body {
  char *buf;
  size_t len;
  size_t pos;
  struct info_cache *ic; /* per-request info cache */
};

struct queue {
  struct upload_body *items[MAX_QUEUED_REQUESTS];
  int head;
  int tail;
  repro_mutex_t lock;
  bool done_recording;
};

struct http_thread_arg {
  const char *url;
  const char *resolve_entry; /* argv[2]: "host:port:addr[,addr...]" for CURLOPT_RESOLVE, or NULL */
  struct queue *q;
  CURLSH *share;
  struct curl_slist *hdrs;
  struct curl_slist *resolve_list; /* shared CURLOPT_RESOLVE slist, or NULL */

  int succeeded;
  int failed;
  int timeout_msgs;
  int completed;
};

static void sleep_ms(int ms)
{
#ifdef _WIN32
  Sleep(ms);
#else
  struct timespec ts = { ms / 1000, (ms % 1000) * 1000 * 1000 };
  nanosleep(&ts, NULL);
#endif
}

static size_t sink_write(char *p, size_t s, size_t n, void *u)
{
  (void)p; (void)u;
  return s * n;
}

static size_t read_body(char *dst, size_t s, size_t n, void *u)
{
  struct upload_body *st = u;
  size_t want = s * n;
  size_t left = st->len - st->pos;
  size_t copy = want < left ? want : left;
  if(copy) {
    memcpy(dst, st->buf + st->pos, copy);
    st->pos += copy;
  }
  return copy;
}

/* Per-easy-handle "info message cache" like UE:
 *  - Ring buffer of N strings
 *  - Each CURLINFO_TEXT line is copied (malloc) and stored under a mutex
 *  - Older entries are freed when overwritten
 * This stresses the exact same code path UE's DEBUGFUNCTION hits. */
#define INFO_CACHE_SIZE 50
struct info_cache {
  repro_mutex_t lock;
  char *entries[INFO_CACHE_SIZE];
  int head;
};

static int debug_callback(CURL *handle, curl_infotype type,
                          char *data, size_t size, void *userp)
{
  struct info_cache *ic = userp;
  char *copy;
  (void)handle;
  if(type != CURLINFO_TEXT)
    return 0;
  /* allocate, copy, take lock, swap ring, free old, release lock */
  copy = malloc(size + 1);
  if(!copy) return 0;
  memcpy(copy, data, size);
  copy[size] = 0;
  MUTEX_LOCK(ic->lock);
  {
    char *old = ic->entries[ic->head];
    ic->entries[ic->head] = copy;
    ic->head = (ic->head + 1) % INFO_CACHE_SIZE;
    if(old) free(old);
  }
  MUTEX_UNLOCK(ic->lock);
  return 0;
}

static void info_cache_init(struct info_cache *ic)
{
  memset(ic, 0, sizeof(*ic));
  MUTEX_INIT(ic->lock);
}

static void info_cache_destroy(struct info_cache *ic)
{
  int i;
  for(i = 0; i < INFO_CACHE_SIZE; i++)
    if(ic->entries[i]) free(ic->entries[i]);
  MUTEX_DESTROY(ic->lock);
}

static int queue_push(struct queue *q, struct upload_body *b)
{
  int next;
  MUTEX_LOCK(q->lock);
  next = (q->tail + 1) % MAX_QUEUED_REQUESTS;
  while(next == q->head) {
    MUTEX_UNLOCK(q->lock);
    sleep_ms(1);
    MUTEX_LOCK(q->lock);
    next = (q->tail + 1) % MAX_QUEUED_REQUESTS;
  }
  q->items[q->tail] = b;
  q->tail = next;
  MUTEX_UNLOCK(q->lock);
  return 0;
}

static struct upload_body *queue_pop(struct queue *q)
{
  struct upload_body *b = NULL;
  MUTEX_LOCK(q->lock);
  if(q->head != q->tail) {
    b = q->items[q->head];
    q->head = (q->head + 1) % MAX_QUEUED_REQUESTS;
  }
  MUTEX_UNLOCK(q->lock);
  return b;
}

static int queue_empty(struct queue *q)
{
  int empty;
  MUTEX_LOCK(q->lock);
  empty = (q->head == q->tail);
  MUTEX_UNLOCK(q->lock);
  return empty;
}

/* HTTP thread: drains the queue, adds handles to multi, ticks at 200Hz */
#ifdef _WIN32
static DWORD WINAPI http_thread_fn(LPVOID arg)
#else
static void *http_thread_fn(void *arg)
#endif
{
  struct http_thread_arg *a = arg;
  CURLM *multi = curl_multi_init();
  curl_multi_setopt(multi, CURLMOPT_MAX_HOST_CONNECTIONS, MAX_HOST_CONN);
  curl_multi_setopt(multi, CURLMOPT_MAX_TOTAL_CONNECTIONS, MAX_TOTAL_CONN);

  int still_running = 0;

  for(;;) {
    /* Drain any queued bodies into new easy handles */
    for(;;) {
      struct upload_body *b = queue_pop(a->q);
      if(!b) break;
      CURL *e = curl_easy_init();
      /* per-request info cache + debug callback (matches UE) */
      b->ic = malloc(sizeof(*b->ic));
      info_cache_init(b->ic);
      curl_easy_setopt(e, CURLOPT_URL, a->url);
      curl_easy_setopt(e, CURLOPT_POST, 1L);
      curl_easy_setopt(e, CURLOPT_POSTFIELDS, NULL);
      curl_easy_setopt(e, CURLOPT_POSTFIELDSIZE, (long)b->len);
      curl_easy_setopt(e, CURLOPT_READFUNCTION, read_body);
      curl_easy_setopt(e, CURLOPT_READDATA, b);
      curl_easy_setopt(e, CURLOPT_HTTPHEADER, a->hdrs);
      curl_easy_setopt(e, CURLOPT_CONNECTTIMEOUT, CONNECT_TIMEOUT_S);
      curl_easy_setopt(e, CURLOPT_WRITEFUNCTION, sink_write);
      curl_easy_setopt(e, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_1_1);
      curl_easy_setopt(e, CURLOPT_FOLLOWLOCATION, 1L);
      curl_easy_setopt(e, CURLOPT_USE_SSL, CURLUSESSL_ALL);
      curl_easy_setopt(e, CURLOPT_BUFFERSIZE, 65536L);
      curl_easy_setopt(e, CURLOPT_NOSIGNAL, 1L);
      curl_easy_setopt(e, CURLOPT_SSL_VERIFYPEER, 0L);
      curl_easy_setopt(e, CURLOPT_SSL_VERIFYHOST, 0L);
      curl_easy_setopt(e, CURLOPT_SHARE, a->share);
      curl_easy_setopt(e, CURLOPT_VERBOSE, 1L);
      /* Probe variable: when resolve_entry is provided, pre-pin DNS via
         CURLOPT_RESOLVE. The failure mode is expected to disappear when this
         is set, because the front-of-burst handles no longer pay DNS
         resolution time while the PENDING queue counts down
         CURLOPT_CONNECTTIMEOUT. */
      if(a->resolve_list) {
        curl_easy_setopt(e, CURLOPT_RESOLVE, a->resolve_list);
      }
      curl_easy_setopt(e, CURLOPT_DEBUGFUNCTION, debug_callback);
      curl_easy_setopt(e, CURLOPT_DEBUGDATA, b->ic);
      curl_easy_setopt(e, CURLOPT_PRIVATE, b); /* so we can free it on done */
      curl_multi_add_handle(multi, e);
    }

    curl_multi_perform(multi, &still_running);
    sleep_ms(HTTP_TICK_MS);

    /* drain completions */
    int queued;
    for(;;) {
      CURLMsg *m = curl_multi_info_read(multi, &queued);
      if(!m) break;
      if(m->msg == CURLMSG_DONE) {
        struct upload_body *b = NULL;
        curl_easy_getinfo(m->easy_handle, CURLINFO_PRIVATE, &b);
        if(m->data.result == CURLE_OK)
          a->succeeded++;
        else {
          a->failed++;
          if(m->data.result == CURLE_OPERATION_TIMEDOUT) a->timeout_msgs++;
          fprintf(stderr, "req %d: %s\n",
                  a->completed, curl_easy_strerror(m->data.result));
        }
        a->completed++;
        curl_multi_remove_handle(multi, m->easy_handle);
        curl_easy_cleanup(m->easy_handle);
        if(b) {
          if(b->ic) { info_cache_destroy(b->ic); free(b->ic); }
          free(b->buf);
          free(b);
        }
      }
    }

    if(a->q->done_recording && queue_empty(a->q) && still_running == 0)
      break;
  }

  curl_multi_cleanup(multi);
#ifdef _WIN32
  return 0;
#else
  return NULL;
#endif
}

/* Match exactly: RecordEvent -> AddToCache -> when buffer
 * fills, QueueFlush (appends to FlushQueue). Main thread NEVER calls
 * FlushEvents in the loop. Only at session end, FlushEvents() drains
 * ALL queued payloads by calling ExecuteRequest -> HttpRequest->ProcessRequest
 * in a tight while loop with zero delay. That means all ~800 HTTP
 * requests get curl_multi_add_handle'd in a single burst from the main
 * thread BEFORE the HTTP thread gets a chance to drain them.
 *
 * In this repro: record_events pushes all bodies onto an internal stash,
 * then at the end, dumps them all into the shared queue in one shot.
 */
static void record_events(struct queue *q)
{
  char *cache = malloc(PAYLOAD_TARGET_SIZE * 2);
  size_t cache_len = 0;
  int i;
  /* internal stash - fills up as events are recorded, then bursted
   * onto the shared queue at the end (matches ET FlushQueue semantics) */
  struct upload_body **stash = malloc(sizeof(*stash) * MAX_QUEUED_REQUESTS);
  int stash_count = 0;

  cache_len = snprintf(cache, PAYLOAD_TARGET_SIZE * 2, "{\"Events\":[");

  for(i = 0; i < TOTAL_EVENTS; i++) {
    int n = snprintf(cache + cache_len, PAYLOAD_TARGET_SIZE * 2 - cache_len,
                     "%s{\"EventName\":\"Test.Event\","
                     "\"SchemaVersion\":1,"
                     "\"Name\":\"item_%08d\","
                     "\"A\":%d,\"B\":%d,\"C\":%d,\"D\":%d,\"E\":%d,"
                     "\"F\":true}",
                     (cache_len > 11 ? "," : ""),
                     i, (i * 13) % 65535, i * 512,
                     ((i * 13) % 65535) / 2, i % 11, i % 4);
    cache_len += n;

    if(cache_len >= PAYLOAD_TARGET_SIZE) {
      cache_len += snprintf(cache + cache_len,
                            PAYLOAD_TARGET_SIZE * 2 - cache_len, "]}");
      struct upload_body *b = malloc(sizeof(*b));
      b->buf = malloc(cache_len);
      memcpy(b->buf, cache, cache_len);
      b->len = cache_len;
      b->pos = 0;
      b->ic = NULL;
      /* stash locally, do NOT push to shared queue yet */
      if(stash_count < MAX_QUEUED_REQUESTS) {
        stash[stash_count++] = b;
      }
      cache_len = snprintf(cache, PAYLOAD_TARGET_SIZE * 2, "{\"Events\":[");
    }
  }

  if(cache_len > (size_t)strlen("{\"Events\":[")) {
    cache_len += snprintf(cache + cache_len,
                          PAYLOAD_TARGET_SIZE * 2 - cache_len, "]}");
    struct upload_body *b = malloc(sizeof(*b));
    b->buf = malloc(cache_len);
    memcpy(b->buf, cache, cache_len);
    b->len = cache_len;
    b->pos = 0;
    b->ic = NULL;
    if(stash_count < MAX_QUEUED_REQUESTS) {
      stash[stash_count++] = b;
    }
  }

  /* BURST: dump everything onto the shared queue at once. This is what
   * analytics's EndSession->FlushEvents does - tight while loop
   * calling FlushEventsOnce->ExecuteRequest->HttpRequest->ProcessRequest
   * for every queued payload with no ticking in between. */
  fprintf(stderr, "bursting %d payloads onto HTTP queue\n", stash_count);
  for(i = 0; i < stash_count; i++) {
    queue_push(q, stash[i]);
  }

  free(stash);
  free(cache);
}

int main(int argc, char **argv)
{
  /* Usage: repro [url] [resolve]
   *   url      - target HTTPS endpoint, default DEFAULT_URL
   *   resolve  - optional CURLOPT_RESOLVE entry "host:port:addr[,addr...]".
   *              When supplied, DNS is pre-pinned and the bug should NOT
   *              reproduce (control run). When omitted, curl resolves DNS
   *              normally and the bug SHOULD reproduce against an endpoint
   *              whose DNS/TLS handshake is slow enough from this network.
   *
   * The variable under test: whether the front-of-burst handles pay DNS/TLS
   * time while later handles sit in MSTATE_PENDING counting down
   * CURLOPT_CONNECTTIMEOUT.
   */
  const char *url = (argc > 1) ? argv[1] : DEFAULT_URL;
  const char *resolve_entry = (argc > 2) ? argv[2] : NULL;
  struct queue q;
  struct http_thread_arg arg;
  repro_thread_t http_thread;
  time_t t0, t1;

  curl_global_init(CURL_GLOBAL_DEFAULT);

  memset(&q, 0, sizeof(q));
  MUTEX_INIT(q.lock);

  memset(&arg, 0, sizeof(arg));
  arg.url = url;
  arg.resolve_entry = resolve_entry;
  arg.q = &q;
  arg.share = curl_share_init();
  curl_share_setopt(arg.share, CURLSHOPT_SHARE, CURL_LOCK_DATA_DNS);
  curl_share_setopt(arg.share, CURLSHOPT_SHARE, CURL_LOCK_DATA_COOKIE);
  curl_share_setopt(arg.share, CURLSHOPT_SHARE, CURL_LOCK_DATA_SSL_SESSION);
  arg.hdrs = curl_slist_append(NULL, "Content-Type: application/json");
  arg.resolve_list = resolve_entry ? curl_slist_append(NULL, resolve_entry) : NULL;

  fprintf(stderr, "url=%s\n", url);
  fprintf(stderr, "CURLOPT_RESOLVE=%s\n", resolve_entry ? resolve_entry : "(none, DNS resolution will happen)");

  t0 = time(NULL);

#ifdef _WIN32
  http_thread = CreateThread(NULL, 0, http_thread_fn, &arg, 0, NULL);
#else
  pthread_create(&http_thread, NULL, http_thread_fn, &arg);
#endif

  /* main thread records events; HTTP thread drains concurrently */
  record_events(&q);
  q.done_recording = true;

#ifdef _WIN32
  WaitForSingleObject(http_thread, INFINITE);
  CloseHandle(http_thread);
#else
  pthread_join(http_thread, NULL);
#endif
  t1 = time(NULL);

  curl_slist_free_all(arg.hdrs);
  if(arg.resolve_list)
    curl_slist_free_all(arg.resolve_list);
  curl_share_cleanup(arg.share);
  MUTEX_DESTROY(q.lock);
  curl_global_cleanup();

  printf("---\n");
  printf("completed=%d succeeded=%d failed=%d (CURLE_OPERATION_TIMEDOUT=%d)\n",
         arg.completed, arg.succeeded, arg.failed, arg.timeout_msgs);
  printf("elapsed=%lds\n", (long)(t1 - t0));
  printf("libcurl=%s\n", curl_version());

  return arg.failed ? 1 : 0;
}

This standalone C reproducer simulates an analytics-style flush: main thread records events into payloads, then bursts ~500 ~100KB JSON POSTs onto a shared queue; an HTTP thread drains the queue into a single CURLM at 200Hz.

Repro parameters (see top of file):
MAX_HOST_CONNECTIONS=16
MAX_TOTAL_CONNECTIONS=256
CONNECTTIMEOUT=30
HTTP_TICK_MS=5
DEFAULT_URL=https://httpbin.org/delay/1

Optional control run that pre-pins DNS via CURLOPT_RESOLVE (does not change the outcome meaningfully):
repro_pending_timeout.exe https://httpbin.org/delay/1 httpbin.org:443:3.220.42.21

What we think changed
Between 8.15 and 8.17 (likely in the 8.16 work around process_pending_handles / Curl_multi_mark_dirty), handles in STATE_PENDING appear to wait passively for process_pending_handles() to be invoked from another code path, rather than actively re-polling via the splay tree. When the pool is saturated by the first N connections, and those first N take meaningful wall-clock time to reach MSTATE_DO (TLS handshake against a normal public HTTPS endpoint is enough), the remaining handles' CURLOPT_CONNECTTIMEOUT counts down before they ever get a slot.

Questions

1. Is MSTATE_PENDING wait time intended to count against CURLOPT_CONNECTTIMEOUT in 8.17? In 8.15 it didn't.
2. Is process_pending_handles() expected to be called frequently enough to drain the PENDING bset under sustained pool saturation, or should PENDING handles re-schedule themselves in the splay tree?
3. Is there a recommended option / multi-handle setting to recover 8.15-like behavior without patching libcurl?

Thanks

[icing]

Questions

1. Is MSTATE_PENDING wait time intended to count against CURLOPT_CONNECTTIMEOUT in 8.17? In 8.15 it didn't.

It also does in 8.15. I just built that version, set a fixed limit of max host connections to 1 and ran:

> curl -o /dev/null https://curl.se/download/curl-8.19.0.tar.xz --limit-rate 48k --http1.1  --connect-timeout 1 -o /dev/null https://curl.se/download/curl-8.19.0.tar.xz --parallel

The second url times out after 1 second.

2. Is process_pending_handles() expected to be called frequently enough to drain the PENDING bset under sustained pool saturation, or should PENDING handles re-schedule themselves in the splay tree?

I hope it is. The question also is: are they fairly rescheduled. We currently try the first pending handle in the bitset and that may be unfair to handles that got assigned higher mid values. We should probably address that.

3. Is there a recommended option / multi-handle setting to recover 8.15-like behavior without patching libcurl?

Other than configuring a larger connect timeout, I can think of none.

[icing]

I just made #21412 which makes scheduling of pending transfers more fairly. The patch should apply pretty cleanly to 8.15 code as well, if you want to try it.

[juanbelonepic]

I just made #21412 which makes scheduling of pending transfers more fairly. The patch should apply pretty cleanly to 8.15 code as well, if you want to try it.

thanks @icing , I had to modify it a bit to make it works in 8.17 + UE:

static void move_pending_to_connect(struct Curl_multi *multi,
                                     struct Curl_easy *data)
 {
   DEBUGASSERT(data->mstate == MSTATE_PENDING);
+  /* reset the connect-timeout budget when a handle leaves
+     MSTATE_PENDING. curl 8.17 counts PENDING wait time against
+     CURLOPT_CONNECTTIMEOUT; without resetting here, a handle that spent
+     most of its 30s budget waiting for a connection slot has little or
+     no time left for the actual TCP/TLS connect. */
+  (void)Curl_pgrsTime(data, TIMER_STARTSINGLE);
+  if(data->set.connecttimeout)
+    Curl_expire(data, data->set.connecttimeout, EXPIRE_CONNECTTIMEOUT);
+
   /* Remove this node from the pending set, add into process set */
   Curl_uint_bset_remove(&multi->pending, data->mid);
   Curl_uint_bset_add(&multi->process, data->mid);
@@ -3755,20 +3812,43 @@
    We could consider an improvement where we store the queue reason and allow
    more pipewait rechecks than others.
 */
 static void process_pending_handles(struct Curl_multi *multi)
 {
-  unsigned int mid;
+  /* Upstream curl/curl#21412 (pending handles fairness): rotate through the
+     pending bitset starting from the mid that was last reactivated, so
+     transfers with higher mid values do not starve when the bitset is always
+     iterated from the start. */
+  unsigned int mid = (unsigned int)multi->last_pending_mid;
+
+  if(mid) {
+    while(Curl_uint_bset_next(&multi->pending, mid, &mid)) {
+      struct Curl_easy *data = Curl_multi_get_easy(multi, mid);
+      if(data) {
+        move_pending_to_connect(multi, data);
+        multi->last_pending_mid = (uint32_t)mid;
+        return;
+      }
+      /* transfer no longer known, should not happen */
+      Curl_uint_bset_remove(&multi->pending, mid);
+      DEBUGASSERT(0);
+    }
+    /* found no pending transfers with `mid` larger than `last_pending_mid`.
+     * Start at the beginning of the pending set again. */
+    multi->last_pending_mid = 0;
+  }
+
   if(Curl_uint_bset_first(&multi->pending, &mid)) {
     do {
       struct Curl_easy *data = Curl_multi_get_easy(multi, mid);
       if(data) {
         move_pending_to_connect(multi, data);
-        break;
+        multi->last_pending_mid = (uint32_t)mid;
+        return;
       }
       /* transfer no longer known, should not happen */
       Curl_uint_bset_remove(&multi->pending, mid);
       DEBUGASSERT(0);
     }
     while(Curl_uint_bset_next(&multi->pending, mid, &mid));
   }
 }

thank you!

[icing]

Does it solve your problem?

Just saw your first part: resetting the connect timeout is not what we do. You have your own curl now!

What I'd really like to know: does #21412 solve your problem without your additional timeout resetting? Otherwise, do you want to patch your own curl going forward forever?

[juanbelonepic]

Your #21412 does fix the standalone C reproducer I sent, yes.

I haven't re-run without your fix to double-check since I had both patches stacked, but as I was seeing 25-30% timeouts and with yours #21412 applied the repro drops to 0 failures against the same public endpoint.
So the PENDING-bitset fairness work is doing what it should.
The important update on my end was that while validating your patch I discovered our internal failing test had an additional cause I had been ignoring, our UE-side HTTP layer's debug callback was doing expensive per-buffer work (UE_LOG + a lock-protected activity-timer reset) synchronously inside the curl thread, thousands of times per burst upload. That was starving curl_multi_perform and producing the same CURLE_OPERATION_TIMEDOUT + "No more connections allowed to host" symptoms your PR addresses.

First we are going to try if this 2 part patch works, then we will need to come to a version that we dont need to patch so much, we save a patch file to apply per version but the idea is to keep the patches at minimum so we can go forward in versions as far as possible and without need to adapt too much code.