quic: improve connect error message, debugging info, fix false connect report

- ECONNECTREFUSED has not its own fail message in quic filters
- Debug logging in connect eyballing improved
- Fix bug in ngtcp2/quiche that could lead to false success reporting.

Reported-by: Divy Le Ray

Fixes #10245
Closes #10248
This commit is contained in:
Stefan Eissing 2023-01-06 12:33:34 +01:00 committed by Daniel Stenberg
parent 0ef2926881
commit 1c5d8acf79
No known key found for this signature in database
GPG Key ID: 5CC908FDB71E12C2
5 changed files with 64 additions and 38 deletions

View File

@ -1555,10 +1555,14 @@ CURLcode Curl_cf_socket_peek(struct Curl_cfilter *cf,
if(Curl_cf_is_socket(cf) && cf->ctx) {
struct cf_socket_ctx *ctx = cf->ctx;
*psock = ctx->sock;
*paddr = &ctx->addr;
*premote_ip_str = ctx->r_ip;
*premote_port = ctx->r_port;
if(psock)
*psock = ctx->sock;
if(paddr)
*paddr = &ctx->addr;
if(premote_ip_str)
*premote_ip_str = ctx->r_ip;
if(premote_port)
*premote_port = ctx->r_port;
return CURLE_OK;
}
return CURLE_FAILED_INIT;

View File

@ -166,6 +166,10 @@ bool Curl_cf_is_socket(struct Curl_cfilter *cf);
/**
* Peek at the socket and remote ip/port the socket filter is using.
* The filter owns all returned values.
* @param psock pointer to hold socket descriptor or NULL
* @param paddr pointer to hold addr reference or NULL
* @param premote_ip_str pointer to hold remote addr as string or NULL
* @param premote_port pointer to hold remote port number or NULL
* Returns error if the filter is of invalid type.
*/
CURLcode Curl_cf_socket_peek(struct Curl_cfilter *cf,

View File

@ -352,6 +352,7 @@ void Curl_conncontrol(struct connectdata *conn,
* provided method `cf_create` and running setup/connect on it.
*/
struct eyeballer {
const char *name;
const struct Curl_addrinfo *addr; /* List of addresses to try, not owned */
int ai_family; /* matching address family only */
cf_ip_connect_create *cf_create; /* for creating cf */
@ -379,7 +380,7 @@ struct cf_he_ctx {
cf_ip_connect_create *cf_create;
const struct Curl_dns_entry *remotehost;
cf_connect_state state;
struct eyeballer *baller[5];
struct eyeballer *baller[2];
struct eyeballer *winner;
struct curltime started;
};
@ -400,6 +401,8 @@ static CURLcode eyeballer_new(struct eyeballer **pballer,
if(!baller)
return CURLE_OUT_OF_MEMORY;
baller->name = ((ai_family == AF_INET)? "ipv4" : (
(ai_family == AF_INET6)? "ipv6" : "ip"));
baller->cf_create = cf_create;
baller->addr = addr;
baller->ai_family = ai_family;
@ -458,8 +461,6 @@ static void baller_initiate(struct Curl_cfilter *cf,
if(result)
goto out;
CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer created %s"),
baller->cf->cft->name));
/* the new filter might have sub-filters */
for(wcf = baller->cf; wcf; wcf = wcf->next) {
wcf->conn = cf->conn;
@ -472,7 +473,7 @@ static void baller_initiate(struct Curl_cfilter *cf,
out:
if(result) {
CF_DEBUGF(infof(data, "eyeballer failed"));
CF_DEBUGF(infof(data, "eyeballer[%s] failed", baller->name));
baller_close(baller, data);
}
if(cf_prev)
@ -546,8 +547,8 @@ static CURLcode baller_connect(struct Curl_cfilter *cf,
baller->is_done = TRUE;
}
else if(Curl_timediff(*now, ctx->started) >= baller->timeoutms) {
infof(data, "After %" CURL_FORMAT_TIMEDIFF_T
"ms connect time, move on!", baller->timeoutms);
infof(data, "%s connect timeout after %" CURL_FORMAT_TIMEDIFF_T
"ms, move on!", baller->name, baller->timeoutms);
#if defined(ETIMEDOUT)
baller->error = ETIMEDOUT;
#endif
@ -592,13 +593,12 @@ evaluate:
continue;
if(!baller->has_started) {
CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%d] not started yet"), i));
++not_started;
continue;
}
baller->result = baller_connect(cf, data, baller, &now, connected);
CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%d] connect -> %d, "
"connected=%d"), i, baller->result, *connected));
CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%s] connect -> %d, "
"connected=%d"), baller->name, baller->result, *connected));
if(!baller->result) {
if(*connected) {
@ -619,11 +619,14 @@ evaluate:
}
allow = Curl_timeleft(data, &now, TRUE);
baller->timeoutms = baller->addr->ai_next == NULL ? allow : allow / 2;
CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%d] starting"), i));
baller_start_next(cf, data, baller);
if(!baller->is_done) {
if(baller->is_done) {
CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%s] done"), baller->name));
}
else {
/* next attempt was started */
CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%d] started"), i));
CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%s] trying next"),
baller->name));
++ongoing;
}
}
@ -655,10 +658,14 @@ evaluate:
* its start delay_ms have expired */
if((baller->primary && baller->primary->is_done) ||
Curl_timediff(now, ctx->started) >= baller->delay_ms) {
CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%d] starting"), i));
baller_start(cf, data, baller);
if(!baller->is_done) {
CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%d] has started"), i));
if(baller->is_done) {
CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%s] done"),
baller->name));
}
else {
CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%s] starting"),
baller->name));
++ongoing;
++added;
}
@ -679,8 +686,9 @@ evaluate:
result = CURLE_COULDNT_CONNECT;
for(i = 0; i < sizeof(ctx->baller)/sizeof(ctx->baller[0]); i++) {
struct eyeballer *baller = ctx->baller[i];
CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%d] assess started=%d, "
"result=%d"), i, baller->has_started, baller->result));
CF_DEBUGF(infof(data, CFMSG(cf, "eyeballer[%s] assess started=%d, "
"result=%d"),
baller->name, baller->has_started, baller->result));
if(baller && baller->has_started && baller->result) {
result = baller->result;
break;
@ -887,6 +895,7 @@ static CURLcode cf_he_connect(struct Curl_cfilter *cf,
if(!result && *done) {
DEBUGASSERT(ctx->winner);
DEBUGASSERT(ctx->winner->cf);
DEBUGASSERT(ctx->winner->cf->connected);
/* we have a winner. Install and activate it.
* close/free all others. */
ctx->state = SCFST_DONE;
@ -953,7 +962,7 @@ static void cf_he_destroy(struct Curl_cfilter *cf, struct Curl_easy *data)
CF_DEBUGF(infof(data, CFMSG(cf, "destroy")));
if(ctx) {
cf_he_close(cf, data);
cf_he_ctx_clear(cf, data);
}
/* release any resources held in state */
Curl_safefree(ctx);
@ -1189,11 +1198,8 @@ static void cf_setup_destroy(struct Curl_cfilter *cf, struct Curl_easy *data)
{
struct cf_setup_ctx *ctx = cf->ctx;
(void)data;
CF_DEBUGF(infof(data, CFMSG(cf, "destroy")));
if(ctx) {
cf_setup_close(cf, data);
}
/* release any resources held in state */
Curl_safefree(ctx);
}

View File

@ -1169,6 +1169,10 @@ static ssize_t cf_ngtcp2_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
struct cf_ngtcp2_ctx *ctx = cf->ctx;
struct HTTP *stream = data->req.p.http;
DEBUGASSERT(cf->connected);
DEBUGASSERT(ctx);
DEBUGASSERT(ctx->qconn);
DEBUGASSERT(ctx->h3conn);
*err = CURLE_OK;
if(!stream->memlen) {
@ -1442,6 +1446,10 @@ static ssize_t cf_ngtcp2_send(struct Curl_cfilter *cf, struct Curl_easy *data,
ssize_t sent = 0;
struct HTTP *stream = data->req.p.http;
DEBUGASSERT(cf->connected);
DEBUGASSERT(ctx);
DEBUGASSERT(ctx->qconn);
DEBUGASSERT(ctx->h3conn);
*err = CURLE_OK;
if(stream->closed) {
@ -1576,8 +1584,16 @@ static CURLcode cf_process_ingress(struct Curl_cfilter *cf,
if(recvd == -1) {
if(SOCKERRNO == EAGAIN || SOCKERRNO == EWOULDBLOCK)
break;
failf(data, "ngtcp2: recvfrom() unexpectedly returned %zd", recvd);
if(SOCKERRNO == ECONNREFUSED) {
const char *r_ip;
int r_port;
Curl_cf_socket_peek(cf->next, NULL, NULL, &r_ip, &r_port);
failf(data, "ngtcp2: connection to %s port %u refused",
r_ip, r_port);
return CURLE_COULDNT_CONNECT;
}
failf(data, "ngtcp2: recvfrom() unexpectedly returned %zd (errno=%d)",
recvd, SOCKERRNO);
return CURLE_RECV_ERROR;
}
@ -2273,13 +2289,13 @@ static CURLcode cf_ngtcp2_connect(struct Curl_cfilter *cf,
return result;
}
*done = FALSE;
if(!ctx->qconn) {
result = cf_connect_start(cf, data);
if(result)
goto out;
}
*done = FALSE;
result = cf_process_ingress(cf, data);
if(result)
goto out;
@ -2301,12 +2317,10 @@ static CURLcode cf_ngtcp2_connect(struct Curl_cfilter *cf,
out:
#ifndef CURL_DISABLE_VERBOSE_STRINGS
if(result && result != CURLE_AGAIN) {
const struct Curl_sockaddr_ex *sockaddr;
const char *r_ip;
int r_port;
result = Curl_cf_socket_peek(cf->next, &ctx->sockfd,
&sockaddr, &r_ip, &r_port);
Curl_cf_socket_peek(cf->next, NULL, NULL, &r_ip, &r_port);
infof(data, "connect to %s port %u failed: %s",
r_ip, r_port, curl_easy_strerror(result));
}
@ -2364,7 +2378,7 @@ CURLcode Curl_cf_ngtcp2_create(struct Curl_cfilter **pcf,
const struct Curl_addrinfo *ai)
{
struct cf_ngtcp2_ctx *ctx = NULL;
struct Curl_cfilter *cf = NULL, *udp_cf;
struct Curl_cfilter *cf = NULL, *udp_cf = NULL;
CURLcode result;
(void)data;

View File

@ -961,13 +961,13 @@ static CURLcode cf_quiche_connect(struct Curl_cfilter *cf,
return result;
}
*done = FALSE;
if(!ctx->qconn) {
result = cf_connect_start(cf, data);
if(result)
goto out;
}
*done = FALSE;
result = cf_process_ingress(cf, data);
if(result)
goto out;
@ -990,12 +990,10 @@ static CURLcode cf_quiche_connect(struct Curl_cfilter *cf,
out:
#ifndef CURL_DISABLE_VERBOSE_STRINGS
if(result && result != CURLE_AGAIN) {
const struct Curl_sockaddr_ex *sockaddr;
const char *r_ip;
int r_port;
result = Curl_cf_socket_peek(cf->next, &ctx->sockfd,
&sockaddr, &r_ip, &r_port);
Curl_cf_socket_peek(cf->next, NULL, NULL, &r_ip, &r_port);
infof(data, "connect to %s port %u failed: %s",
r_ip, r_port, curl_easy_strerror(result));
}
@ -1094,7 +1092,7 @@ CURLcode Curl_cf_quiche_create(struct Curl_cfilter **pcf,
const struct Curl_addrinfo *ai)
{
struct cf_quiche_ctx *ctx = NULL;
struct Curl_cfilter *cf = NULL, *udp_cf;
struct Curl_cfilter *cf = NULL, *udp_cf = NULL;
CURLcode result;
(void)data;