From: Stefan Eissing Date: Mon, 29 Sep 2025 14:38:55 +0000 (+0200) Subject: ip-happy: do not set unnecessary timeout X-Git-Tag: rc-8_17_0-2~308 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=b02238975768d0bcbf8c7ef00eaaee3ec379f4ff;p=thirdparty%2Fcurl.git ip-happy: do not set unnecessary timeout When attempts on all addresses have been started, do no longer set any EXPIRE_HAPPY_EYEBALLS timeouts. Fixes #18767 Reported-by: Johannes Schindelin Closes #18768 --- diff --git a/docs/libcurl/curl_global_trace.md b/docs/libcurl/curl_global_trace.md index 4a21bdc455..0459eab674 100644 --- a/docs/libcurl/curl_global_trace.md +++ b/docs/libcurl/curl_global_trace.md @@ -138,6 +138,10 @@ Tracing of SSL Session handling, e.g. caching/import/export. Tracing of SMTP operations when this protocol is enabled in your build. +## `timer` + +Tracing of timers set for transfers. + ## `write` Traces writing of download data, received from the server, to the application. diff --git a/lib/cf-ip-happy.c b/lib/cf-ip-happy.c index 897b968114..47560889d4 100644 --- a/lib/cf-ip-happy.c +++ b/lib/cf-ip-happy.c @@ -153,12 +153,17 @@ static const struct Curl_addrinfo *cf_ai_iter_next(struct cf_ai_iter *iter) return iter->last; } -#ifdef USE_IPV6 -static bool cf_ai_iter_done(struct cf_ai_iter *iter) +static bool cf_ai_iter_has_more(struct cf_ai_iter *iter) { - return (iter->n >= 0) && !iter->last; + const struct Curl_addrinfo *addr = iter->last ? iter->last->ai_next : + ((iter->n < 0) ? iter->head : NULL); + while(addr) { + if(addr->ai_family == iter->ai_family) + return TRUE; + addr = addr->ai_next; + } + return FALSE; } -#endif struct cf_ip_attempt { struct cf_ip_attempt *next; @@ -353,7 +358,7 @@ static CURLcode cf_ip_ballers_run(struct cf_ip_ballers *bs, { CURLcode result = CURLE_OK; struct cf_ip_attempt *a = NULL, **panchor; - bool do_more, more_possible; + bool do_more; struct curltime now; timediff_t next_expire_ms; int i, inconclusive, ongoing; @@ -364,7 +369,6 @@ static CURLcode cf_ip_ballers_run(struct cf_ip_ballers *bs, evaluate: now = curlx_now(); ongoing = inconclusive = 0; - more_possible = TRUE; /* check if a running baller connects now */ i = -1; @@ -404,7 +408,13 @@ evaluate: do_more = TRUE; } else { - do_more = (curlx_timediff(now, bs->last_attempt_started) >= + bool more_possible = cf_ai_iter_has_more(&bs->addr_iter); +#ifdef USE_IPV6 + if(!more_possible) + more_possible = cf_ai_iter_has_more(&bs->ipv6_iter); +#endif + do_more = more_possible && + (curlx_timediff(now, bs->last_attempt_started) >= bs->attempt_delay_ms); if(do_more) CURL_TRC_CF(data, cf, "happy eyeballs timeout expired, " @@ -418,7 +428,7 @@ evaluate: int ai_family = 0; #ifdef USE_IPV6 if((bs->last_attempt_ai_family == AF_INET) || - cf_ai_iter_done(&bs->addr_iter)) { + !cf_ai_iter_has_more(&bs->addr_iter)) { addr = cf_ai_iter_next(&bs->ipv6_iter); ai_family = bs->ipv6_iter.ai_family; } @@ -472,11 +482,8 @@ evaluate: /* attempt timeout for restart has not expired yet */ goto out; } - else if(ongoing) { + else if(!ongoing) { /* no more addresses, no inconclusive attempts */ - more_possible = FALSE; - } - else { CURL_TRC_CF(data, cf, "no more attempts to try"); result = CURLE_COULDNT_CONNECT; i = 0; @@ -490,21 +497,34 @@ evaluate: out: if(!result) { + bool more_possible; + /* when do we need to be called again? */ next_expire_ms = Curl_timeleft(data, &now, TRUE); + if(next_expire_ms <= 0) { + failf(data, "Connection timeout after %" FMT_OFF_T " ms", + curlx_timediff(now, data->progress.t_startsingle)); + return CURLE_OPERATION_TIMEDOUT; + } + + more_possible = cf_ai_iter_has_more(&bs->addr_iter); +#ifdef USE_IPV6 + if(!more_possible) + more_possible = cf_ai_iter_has_more(&bs->ipv6_iter); +#endif if(more_possible) { timediff_t expire_ms, elapsed_ms; elapsed_ms = curlx_timediff(now, bs->last_attempt_started); expire_ms = CURLMAX(bs->attempt_delay_ms - elapsed_ms, 0); next_expire_ms = CURLMIN(next_expire_ms, expire_ms); + if(next_expire_ms <= 0) { + CURL_TRC_CF(data, cf, "HAPPY_EYBALLS timeout due, re-evaluate"); + goto evaluate; + } + CURL_TRC_CF(data, cf, "next HAPPY_EYBALLS timeout in %" FMT_TIMEDIFF_T + "ms", next_expire_ms); + Curl_expire(data, next_expire_ms, EXPIRE_HAPPY_EYEBALLS); } - - if(next_expire_ms <= 0) { - failf(data, "Connection timeout after %" FMT_OFF_T " ms", - curlx_timediff(now, data->progress.t_startsingle)); - return CURLE_OPERATION_TIMEDOUT; - } - Curl_expire(data, next_expire_ms, EXPIRE_HAPPY_EYEBALLS); } return result; } diff --git a/lib/cf-socket.c b/lib/cf-socket.c index cdd496a5e1..3d1f5e7529 100644 --- a/lib/cf-socket.c +++ b/lib/cf-socket.c @@ -1329,7 +1329,8 @@ static CURLcode cf_tcp_connect(struct Curl_cfilter *cf, rc = SOCKET_WRITABLE(ctx->sock, 0); if(rc == 0) { /* no connection yet */ - CURL_TRC_CF(data, cf, "not connected yet"); + CURL_TRC_CF(data, cf, "not connected yet on fd=%" FMT_SOCKET_T, + ctx->sock); return CURLE_OK; } else if(rc == CURL_CSELECT_OUT || cf->conn->bits.tcp_fastopen) { @@ -1339,7 +1340,7 @@ static CURLcode cf_tcp_connect(struct Curl_cfilter *cf, set_local_ip(cf, data); *done = TRUE; cf->connected = TRUE; - CURL_TRC_CF(data, cf, "connected"); + CURL_TRC_CF(data, cf, "connected on fd=%" FMT_SOCKET_T, ctx->sock); return CURLE_OK; } } diff --git a/lib/curl_trc.c b/lib/curl_trc.c index 9426adcede..27dc2b3b44 100644 --- a/lib/curl_trc.c +++ b/lib/curl_trc.c @@ -272,6 +272,10 @@ struct curl_trc_feat Curl_trc_feat_dns = { "DNS", CURL_LOG_LVL_NONE, }; +struct curl_trc_feat Curl_trc_feat_timer = { + "TIMER", + CURL_LOG_LVL_NONE, +}; static const char * const Curl_trc_timer_names[]={ "100_TIMEOUT", @@ -291,24 +295,36 @@ static const char * const Curl_trc_timer_names[]={ "SHUTDOWN", }; -const char *Curl_trc_timer_name(int tid) +static const char *trc_timer_name(int tid) { if((tid >= 0) && ((size_t)tid < CURL_ARRAYSIZE(Curl_trc_timer_names))) return Curl_trc_timer_names[(size_t)tid]; return "UNKNOWN?"; } -void Curl_trc_multi_timeouts(struct Curl_easy *data) +void Curl_trc_timer(struct Curl_easy *data, int tid, const char *fmt, ...) { - struct Curl_llist_node *e = Curl_llist_head(&data->state.timeoutlist); - if(e) { - struct curltime now = curlx_now(); - while(e) { - struct time_node *n = Curl_node_elem(e); - e = Curl_node_next(e); - CURL_TRC_M(data, "[TIMEOUT] %s expires in %" FMT_TIMEDIFF_T "ns", - CURL_TIMER_NAME(n->eid), - curlx_timediff_us(n->time, now)); + DEBUGASSERT(!strchr(fmt, '\n')); + if(Curl_trc_ft_is_verbose(data, &Curl_trc_feat_timer)) { + const char *tname = trc_timer_name(tid); + va_list ap; + va_start(ap, fmt); + trc_infof(data, &Curl_trc_feat_timer, tname, 0, fmt, ap); + va_end(ap); + } +} +void Curl_trc_easy_timers(struct Curl_easy *data) +{ + if(CURL_TRC_TIMER_is_verbose(data)) { + struct Curl_llist_node *e = Curl_llist_head(&data->state.timeoutlist); + if(e) { + struct curltime now = curlx_now(); + while(e) { + struct time_node *n = Curl_node_elem(e); + e = Curl_node_next(e); + CURL_TRC_TIMER(data, n->eid, "expires in %" FMT_TIMEDIFF_T "ns", + curlx_timediff_us(n->time, now)); + } } } } @@ -476,6 +492,7 @@ static struct trc_feat_def trc_feats[] = { { &Curl_trc_feat_read, TRC_CT_NONE }, { &Curl_trc_feat_write, TRC_CT_NONE }, { &Curl_trc_feat_dns, TRC_CT_NETWORK }, + { &Curl_trc_feat_timer, TRC_CT_NETWORK }, #ifndef CURL_DISABLE_FTP { &Curl_trc_feat_ftp, TRC_CT_PROTOCOL }, #endif diff --git a/lib/curl_trc.h b/lib/curl_trc.h index 37a373e4a6..1a3f8f374e 100644 --- a/lib/curl_trc.h +++ b/lib/curl_trc.h @@ -86,7 +86,7 @@ void Curl_trc_multi(struct Curl_easy *data, const char *fmt, ...) CURL_PRINTF(2, 3); const char *Curl_trc_mstate_name(int state); const char *Curl_trc_timer_name(int tid); -void Curl_trc_multi_timeouts(struct Curl_easy *data); +void Curl_trc_easy_timers(struct Curl_easy *data); void Curl_trc_write(struct Curl_easy *data, const char *fmt, ...) CURL_PRINTF(2, 3); @@ -94,6 +94,8 @@ void Curl_trc_read(struct Curl_easy *data, const char *fmt, ...) CURL_PRINTF(2, 3); void Curl_trc_dns(struct Curl_easy *data, const char *fmt, ...) CURL_PRINTF(2, 3); +void Curl_trc_timer(struct Curl_easy *data, int tid, + const char *fmt, ...) CURL_PRINTF(3, 4); struct curl_trc_feat { const char *name; @@ -125,6 +127,8 @@ void Curl_trc_ws(struct Curl_easy *data, Curl_trc_ft_is_verbose(data, &Curl_trc_feat_multi) #define CURL_TRC_DNS_is_verbose(data) \ Curl_trc_ft_is_verbose(data, &Curl_trc_feat_dns) +#define CURL_TRC_TIMER_is_verbose(data) \ + Curl_trc_ft_is_verbose(data, &Curl_trc_feat_timer) #if defined(CURL_HAVE_C99) && !defined(CURL_DISABLE_VERBOSE_STRINGS) #define infof(data, ...) \ @@ -145,6 +149,9 @@ void Curl_trc_ws(struct Curl_easy *data, #define CURL_TRC_DNS(data, ...) \ do { if(CURL_TRC_DNS_is_verbose(data)) \ Curl_trc_dns(data, __VA_ARGS__); } while(0) +#define CURL_TRC_TIMER(data, tid, ...) \ + do { if(CURL_TRC_TIMER_is_verbose(data)) \ + Curl_trc_timer(data, tid, __VA_ARGS__); } while(0) #ifndef CURL_DISABLE_FTP #define CURL_TRC_FTP(data, ...) \ @@ -175,6 +182,7 @@ void Curl_trc_ws(struct Curl_easy *data, #define CURL_TRC_WRITE Curl_trc_write #define CURL_TRC_READ Curl_trc_read #define CURL_TRC_DNS Curl_trc_dns +#define CURL_TRC_TIMER Curl_trc_timer #ifndef CURL_DISABLE_FTP #define CURL_TRC_FTP Curl_trc_ftp @@ -198,6 +206,7 @@ extern struct curl_trc_feat Curl_trc_feat_multi; extern struct curl_trc_feat Curl_trc_feat_read; extern struct curl_trc_feat Curl_trc_feat_write; extern struct curl_trc_feat Curl_trc_feat_dns; +extern struct curl_trc_feat Curl_trc_feat_timer; #define Curl_trc_is_verbose(data) \ ((data) && (data)->set.verbose && \ @@ -210,10 +219,9 @@ extern struct curl_trc_feat Curl_trc_feat_dns; (Curl_trc_is_verbose(data) && \ (ft)->log_level >= CURL_LOG_LVL_INFO) #define CURL_MSTATE_NAME(s) Curl_trc_mstate_name((int)(s)) -#define CURL_TIMER_NAME(t) Curl_trc_timer_name((int)(t)) -#define CURL_TRC_M_TIMEOUTS(data) \ - do { if(CURL_TRC_M_is_verbose(data)) \ - Curl_trc_multi_timeouts(data); } while(0) +#define CURL_TRC_EASY_TIMERS(data) \ + do { if(CURL_TRC_TIMER_is_verbose(data)) \ + Curl_trc_easy_timers(data); } while(0) #else /* CURL_DISABLE_VERBOSE_STRINGS */ /* All informational messages are not compiled in for size savings */ @@ -222,8 +230,7 @@ extern struct curl_trc_feat Curl_trc_feat_dns; #define Curl_trc_cf_is_verbose(x,y) (FALSE) #define Curl_trc_ft_is_verbose(x,y) (FALSE) #define CURL_MSTATE_NAME(x) ((void)(x), "-") -#define CURL_TIMER_NAME(x) ((void)(x), "-") -#define CURL_TRC_M_TIMEOUTS(x) Curl_nop_stmt +#define CURL_TRC_EASY_TIMERS(x) Curl_nop_stmt #endif /* !CURL_DISABLE_VERBOSE_STRINGS */ diff --git a/lib/multi.c b/lib/multi.c index 442956f844..ae38f5f443 100644 --- a/lib/multi.c +++ b/lib/multi.c @@ -1135,7 +1135,7 @@ CURLMcode Curl_multi_pollset(struct Curl_easy *data, caller, ps->n, timeout_count); break; } - CURL_TRC_M_TIMEOUTS(data); + CURL_TRC_EASY_TIMERS(data); } if(expect_sockets && !ps->n && data->multi && @@ -3050,7 +3050,13 @@ static void multi_mark_expired_as_dirty(struct multi_run_ctx *mrc) data = Curl_splayget(t); /* assign this for next loop */ if(!data) continue; - + if(CURL_TRC_TIMER_is_verbose(data)) { + struct Curl_llist_node *e = Curl_llist_head(&data->state.timeoutlist); + if(e) { + struct time_node *n = Curl_node_elem(e); + CURL_TRC_TIMER(data, n->eid, "has expired"); + } + } (void)add_next_timeout(mrc->now, multi, data); Curl_multi_mark_dirty(data); } @@ -3323,6 +3329,7 @@ static CURLMcode multi_timeout(struct Curl_multi *multi, long *timeout_ms) { static const struct curltime tv_zero = {0, 0}; + struct Curl_easy *data = NULL; if(multi->dead) { *timeout_ms = 0; @@ -3350,14 +3357,14 @@ static CURLMcode multi_timeout(struct Curl_multi *multi, curlx_timediff_us(multi->timetree->key, now) > 0) { /* some time left before expiration */ timediff_t diff = curlx_timediff_ceil(multi->timetree->key, now); + data = Curl_splayget(multi->timetree); /* this should be safe even on 32-bit archs, as we do not use that overly long timeouts */ *timeout_ms = (long)diff; } else { if(multi->timetree) { - struct Curl_easy *data = Curl_splayget(multi->timetree); - CURL_TRC_M(data, "multi_timeout() says this has expired"); + data = Curl_splayget(multi->timetree); } /* 0 means immediately */ *timeout_ms = 0; @@ -3368,6 +3375,16 @@ static CURLMcode multi_timeout(struct Curl_multi *multi, *timeout_ms = -1; } + if(data && CURL_TRC_TIMER_is_verbose(data)) { + struct Curl_llist_node *e = + Curl_llist_head(&data->state.timeoutlist); + if(e) { + struct time_node *n = Curl_node_elem(e); + CURL_TRC_TIMER(data, n->eid, "gives multi timeout in %ldms", + *timeout_ms); + } + } + return CURLM_OK; } @@ -3387,8 +3404,6 @@ CURLMcode curl_multi_timeout(CURLM *m, return multi_timeout(multi, &expire_time, timeout_ms); } -#define DEBUG_UPDATE_TIMER 0 - /* * Tell the application it should update its timers, if it subscribes to the * update timer callback. @@ -3407,47 +3422,34 @@ CURLMcode Curl_update_timer(struct Curl_multi *multi) } if(timeout_ms < 0 && multi->last_timeout_ms < 0) { -#if DEBUG_UPDATE_TIMER - fprintf(stderr, "Curl_update_timer(), still no timeout, no change\n"); -#endif + /* nothing to do */ } else if(timeout_ms < 0) { /* there is no timeout now but there was one previously */ -#if DEBUG_UPDATE_TIMER - fprintf(stderr, "Curl_update_timer(), remove timeout, " - " last_timeout=%ldms\n", multi->last_timeout_ms); -#endif + CURL_TRC_M(multi->admin, "[TIMER] clear"); timeout_ms = -1; /* normalize */ set_value = TRUE; } else if(multi->last_timeout_ms < 0) { -#if DEBUG_UPDATE_TIMER - fprintf(stderr, "Curl_update_timer(), had no timeout, set now\n"); -#endif + CURL_TRC_M(multi->admin, "[TIMER] set %ldms, none before", + timeout_ms); set_value = TRUE; } else if(curlx_timediff_us(multi->last_expire_ts, expire_ts)) { /* We had a timeout before and have one now, the absolute timestamp * differs. The relative timeout_ms may be the same, but the starting * point differs. Let the application restart its timer. */ -#if DEBUG_UPDATE_TIMER - fprintf(stderr, "Curl_update_timer(), expire timestamp changed\n"); -#endif + CURL_TRC_M(multi->admin, "[TIMER] set %ldms, replace previous", + timeout_ms); set_value = TRUE; } else { /* We have same expire time as previously. Our relative 'timeout_ms' * may be different now, but the application has the timer running * and we do not to tell it to start this again. */ -#if DEBUG_UPDATE_TIMER - fprintf(stderr, "Curl_update_timer(), same expire timestamp, no change\n"); -#endif } if(set_value) { -#if DEBUG_UPDATE_TIMER - fprintf(stderr, "Curl_update_timer(), set timeout %ldms\n", timeout_ms); -#endif multi->last_expire_ts = expire_ts; multi->last_timeout_ms = timeout_ms; set_in_callback(multi, TRUE); @@ -3491,7 +3493,8 @@ multi_deltimeout(struct Curl_easy *data, expire_id eid) static CURLMcode multi_addtimeout(struct Curl_easy *data, struct curltime *stamp, - expire_id eid) + expire_id eid, + const struct curltime *nowp) { struct Curl_llist_node *e; struct time_node *node; @@ -3499,6 +3502,7 @@ multi_addtimeout(struct Curl_easy *data, size_t n; struct Curl_llist *timeoutlist = &data->state.timeoutlist; + (void)nowp; node = &data->state.expires[eid]; /* copy the timestamp and id */ @@ -3521,6 +3525,8 @@ multi_addtimeout(struct Curl_easy *data, this is the first timeout on the list */ Curl_llist_insert_next(timeoutlist, prev, node, &node->list); + CURL_TRC_TIMER(data, eid, "set for %" FMT_TIMEDIFF_T "ns", + curlx_timediff_us(node->time, *nowp)); return CURLM_OK; } @@ -3553,7 +3559,7 @@ void Curl_expire_ex(struct Curl_easy *data, /* Add it to the timer list. It must stay in the list until it has expired in case we need to recompute the minimum timer later. */ - multi_addtimeout(data, &set, id); + multi_addtimeout(data, &set, id, nowp); if(curr_expire->tv_sec || curr_expire->tv_usec) { /* This means that the struct is added as a node in the splay tree. @@ -3582,9 +3588,6 @@ void Curl_expire_ex(struct Curl_easy *data, Curl_splayset(&data->state.timenode, data); multi->timetree = Curl_splayinsert(*curr_expire, multi->timetree, &data->state.timenode); - if(data->id >= 0) - CURL_TRC_M(data, "[TIMEOUT] set %s to expire in %" FMT_TIMEDIFF_T "ns", - CURL_TIMER_NAME(id), curlx_timediff_us(set, *nowp)); } /* @@ -3610,12 +3613,11 @@ void Curl_expire(struct Curl_easy *data, timediff_t milli, expire_id id) * Removes the expire timer. Marks it as done. * */ -void Curl_expire_done(struct Curl_easy *data, expire_id id) +void Curl_expire_done(struct Curl_easy *data, expire_id eid) { /* remove the timer, if there */ - multi_deltimeout(data, id); - if(data->id >= 0) - CURL_TRC_M(data, "[TIMEOUT] cleared %s", CURL_TIMER_NAME(id)); + multi_deltimeout(data, eid); + CURL_TRC_TIMER(data, eid, "cleared"); } /* diff --git a/tests/http/test_06_eyeballs.py b/tests/http/test_06_eyeballs.py index 038721fbf9..d05eb3c7da 100644 --- a/tests/http/test_06_eyeballs.py +++ b/tests/http/test_06_eyeballs.py @@ -25,6 +25,7 @@ ########################################################################### # import logging +import re import pytest from testenv import Env, CurlClient @@ -100,3 +101,34 @@ class TestEyeballs: r.check_response(count=1, http_status=None, exitcode=False) assert r.stats[0]['time_connect'] == 0 # no one should have listened assert r.stats[0]['time_appconnect'] == 0 # did not happen either + + # check timers when trying 3 unresponsive addresses + @pytest.mark.skipif(condition=not Env.curl_has_feature('IPv6'), + reason='curl lacks ipv6 support') + def test_06_13_timers(self, env: Env): + curl = CurlClient(env=env) + # ipv6 0100::/64 is supposed to go into the void (rfc6666) + r = curl.http_download(urls=['https://xxx.invalid/'], extra_args=[ + '--resolve', 'xxx.invalid:443:0100::1,0100::2,0100::3', + '--connect-timeout', '1', + '--happy-eyeballs-timeout-ms', '123', + '--trace-config', 'timer,happy-eyeballs,tcp' + ]) + r.check_response(count=1, http_status=None, exitcode=False) + assert r.stats[0]['time_connect'] == 0 # no one connected + # check that we indeed started attempts on all 3 addresses + tcp_attempts = [line for line in r.trace_lines + if re.match(r'.*Trying \[100::[123]]:443', line)] + assert len(tcp_attempts) == 3, f'fond: {"".join(tcp_attempts)}\n{r.dump_logs()}' + # if the 0100::/64 really goes into the void, we should see 2 HAPPY_EYEBALLS + # timeouts being set here + failed_attempts = [line for line in r.trace_lines + if re.match(r'.*checked connect attempts: 0 ongoing', line)] + if len(failed_attempts): + # github CI fails right away with "Network is unreachable", slackers... + assert len(failed_attempts) == 3, f'found: {"".join(failed_attempts)}\n{r.dump_logs()}' + else: + # no immediately failed attempts, as should be + he_timers_set = [line for line in r.trace_lines + if re.match(r'.*\[TIMER] \[HAPPY_EYEBALLS] set for', line)] + assert len(he_timers_set) == 2, f'found: {"".join(he_timers_set)}\n{r.dump_logs()}' diff --git a/tests/http/testenv/curl.py b/tests/http/testenv/curl.py index 7c3f6e72d9..f8e7b12a26 100644 --- a/tests/http/testenv/curl.py +++ b/tests/http/testenv/curl.py @@ -895,6 +895,9 @@ class CurlClient: if not isinstance(urls, list): urls = [urls] + if options is not None and '--resolve' in options: + force_resolve = False + args = [self._curl, "-s", "--path-as-is"] if 'CURL_TEST_EVENT' in os.environ: args.append('--test-event')