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.
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;
{
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;
evaluate:
now = curlx_now();
ongoing = inconclusive = 0;
- more_possible = TRUE;
/* check if a running baller connects now */
i = -1;
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, "
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;
}
/* 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;
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;
}
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) {
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;
}
}
"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",
"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));
+ }
}
}
}
{ &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
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);
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;
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, ...) \
#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, ...) \
#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
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 && \
(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 */
#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 */
caller, ps->n, timeout_count);
break;
}
- CURL_TRC_M_TIMEOUTS(data);
+ CURL_TRC_EASY_TIMERS(data);
}
if(expect_sockets && !ps->n && data->multi &&
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);
}
long *timeout_ms)
{
static const struct curltime tv_zero = {0, 0};
+ struct Curl_easy *data = NULL;
if(multi->dead) {
*timeout_ms = 0;
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;
*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;
}
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.
}
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);
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;
size_t n;
struct Curl_llist *timeoutlist = &data->state.timeoutlist;
+ (void)nowp;
node = &data->state.expires[eid];
/* copy the timestamp and id */
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;
}
/* 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.
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));
}
/*
* 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");
}
/*
###########################################################################
#
import logging
+import re
import pytest
from testenv import Env, CurlClient
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()}'
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')
projects / thirdparty / curl.git / commitdiff
