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
This commit is contained in:
Stefan Eissing 2025-09-29 16:38:55 +02:00 committed by Daniel Stenberg
parent d8823e855c
commit b022389757
No known key found for this signature in database
GPG key ID: 5CC908FDB71E12C2
8 changed files with 160 additions and 74 deletions

View file

@ -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.

View file

@ -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(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) {
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);
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);
}
}
return result;
}

View file

@ -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;
}
}

View file

@ -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

View file

@ -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 */

View file

@ -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");
}
/*

View file

@ -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()}'

View file

@ -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')