filter: change time reporting

Replace the QUERY filter methods for connect and appconnect time with a
new control CF_CTRL_REPORT_STATS that is triggered when a connect ends
(successful or not).

Filters in the connection can then report their statistics. Socket and
TLS filters do this only once. Subsequent CF_CTRL_REPORT_STATS will do
nothing.

This prevents timers to be reported twice in STARTTLS scenarios.

Fixes #22587 (again)
Closes #22596
This commit is contained in:
Stefan Eissing 2026-08-15 17:14:41 +02:00 committed by Daniel Stenberg
parent a01a24deaf
commit 406edd036a
No known key found for this signature in database
GPG key ID: 5CC908FDB71E12C2
14 changed files with 187 additions and 149 deletions

View file

@ -652,26 +652,6 @@ static bool cf_hc_data_pending(struct Curl_cfilter *cf,
return FALSE;
}
static struct curltime cf_get_max_baller_time(struct Curl_cfilter *cf,
struct Curl_easy *data,
int query)
{
struct cf_hc_ctx *ctx = cf->ctx;
struct curltime t, tmax;
size_t i;
memset(&tmax, 0, sizeof(tmax));
for(i = 0; i < ctx->baller_count; i++) {
struct Curl_cfilter *cfb = ctx->ballers[i].cf;
memset(&t, 0, sizeof(t));
if(cfb && !cfb->cft->query(cfb, data, query, NULL, &t)) {
if((t.tv_sec || t.tv_usec) && curlx_ptimediff_us(&t, &tmax) > 0)
tmax = t;
}
}
return tmax;
}
static CURLcode cf_hc_query(struct Curl_cfilter *cf,
struct Curl_easy *data,
int query, int *pres1, void *pres2)
@ -681,16 +661,6 @@ static CURLcode cf_hc_query(struct Curl_cfilter *cf,
if(!cf->connected) {
switch(query) {
case CF_QUERY_TIMER_CONNECT: {
struct curltime *when = pres2;
*when = cf_get_max_baller_time(cf, data, CF_QUERY_TIMER_CONNECT);
return CURLE_OK;
}
case CF_QUERY_TIMER_APPCONNECT: {
struct curltime *when = pres2;
*when = cf_get_max_baller_time(cf, data, CF_QUERY_TIMER_APPCONNECT);
return CURLE_OK;
}
case CF_QUERY_NEED_FLUSH: {
for(i = 0; i < ctx->baller_count; i++)
if(cf_hc_baller_needs_flush(&ctx->ballers[i], data)) {
@ -717,12 +687,26 @@ static CURLcode cf_hc_cntrl(struct Curl_cfilter *cf,
size_t i;
if(!cf->connected) {
for(i = 0; i < ctx->baller_count; i++) {
result = cf_hc_baller_cntrl(&ctx->ballers[i], data, event, arg1, arg2);
if(result && (result != CURLE_AGAIN))
goto out;
switch(event) {
case CF_CTRL_REPORT_STATS:
for(i = 0; i < ctx->baller_count; i++) {
/* Make the first baller that connected at network level report */
if(Curl_conn_cf_is_ip_connected(ctx->ballers[i].cf, data)) {
Curl_conn_cf_cntrl(ctx->ballers[i].cf, data, TRUE,
event, arg1, arg2);
break;
}
}
break;
default:
for(i = 0; i < ctx->baller_count; i++) {
result = cf_hc_baller_cntrl(&ctx->ballers[i], data, event, arg1, arg2);
if(result && (result != CURLE_AGAIN))
goto out;
}
result = CURLE_OK;
break;
}
result = CURLE_OK;
}
out:
return result;

View file

@ -645,24 +645,6 @@ static bool cf_ip_ballers_pending(struct cf_ip_ballers *bs,
return FALSE;
}
static struct curltime cf_ip_ballers_max_time(struct cf_ip_ballers *bs,
struct Curl_easy *data,
int query)
{
struct curltime t, tmax;
struct cf_ip_attempt *a;
memset(&tmax, 0, sizeof(tmax));
for(a = bs->running; a; a = a->next) {
memset(&t, 0, sizeof(t));
if(a->cf && !a->cf->cft->query(a->cf, data, query, NULL, &t)) {
if((t.tv_sec || t.tv_usec) && curlx_ptimediff_us(&t, &tmax) > 0)
tmax = t;
}
}
return tmax;
}
static int cf_ip_ballers_min_reply_ms(struct cf_ip_ballers *bs,
struct Curl_easy *data)
{
@ -940,18 +922,6 @@ static CURLcode cf_ip_happy_query(struct Curl_cfilter *cf,
CURL_TRC_CF(data, cf, "query connect reply: %dms", *pres1);
return CURLE_OK;
}
case CF_QUERY_TIMER_CONNECT: {
struct curltime *when = pres2;
*when = cf_ip_ballers_max_time(&ctx->ballers, data,
CF_QUERY_TIMER_CONNECT);
return CURLE_OK;
}
case CF_QUERY_TIMER_APPCONNECT: {
struct curltime *when = pres2;
*when = cf_ip_ballers_max_time(&ctx->ballers, data,
CF_QUERY_TIMER_APPCONNECT);
return CURLE_OK;
}
default:
break;
}

View file

@ -988,6 +988,7 @@ struct cf_socket_ctx {
BIT(accepted); /* socket was accepted, not connected */
BIT(sock_connected); /* socket is "connected", e.g. in UDP */
BIT(active);
BIT(stats_reported);
};
static CURLcode cf_socket_ctx_init(struct cf_socket_ctx *ctx,
@ -1729,6 +1730,26 @@ static CURLcode cf_socket_cntrl(struct Curl_cfilter *cf,
case CF_CTRL_FORGET_SOCKET:
ctx->sock = CURL_SOCKET_BAD;
break;
case CF_CTRL_REPORT_STATS:
if(cf->connected && !ctx->stats_reported) {
struct curltime *ts = NULL;
switch(ctx->transport) {
case TRNSPRT_UDP:
case TRNSPRT_QUIC:
/* Since UDP connected sockets work different from TCP, we use the
* time of the first byte from the peer as the "connect" time. */
if(ctx->got_first_byte)
ts = &ctx->first_byte_at;
break;
default:
ts = &ctx->connected_at;
break;
}
if(ts) {
Curl_pgrsTimeWas(data, TIMER_CONNECT, *ts);
ctx->stats_reported = TRUE;
}
}
}
return CURLE_OK;
}
@ -1799,24 +1820,6 @@ static CURLcode cf_socket_query(struct Curl_cfilter *cf,
else
*pres1 = -1;
return CURLE_OK;
case CF_QUERY_TIMER_CONNECT: {
struct curltime *when = pres2;
switch(ctx->transport) {
case TRNSPRT_UDP:
case TRNSPRT_QUIC:
/* Since UDP connected sockets work different from TCP, we use the
* time of the first byte from the peer as the "connect" time. */
if(ctx->got_first_byte) {
*when = ctx->first_byte_at;
break;
}
FALLTHROUGH();
default:
*when = ctx->connected_at;
break;
}
return CURLE_OK;
}
case CF_QUERY_IP_INFO:
#ifdef USE_IPV6
*pres1 = (ctx->addr.family == AF_INET6);
@ -1825,6 +1828,12 @@ static CURLcode cf_socket_query(struct Curl_cfilter *cf,
#endif
*(struct ip_quadruple *)pres2 = ctx->ip;
return CURLE_OK;
case CF_QUERY_REALLY_CONNECTED:
if(cf->cft != &Curl_cft_udp)
*pres1 = cf->connected;
else
*pres1 = ctx->got_first_byte;
return CURLE_OK;
default:
break;
}

View file

@ -462,12 +462,32 @@ static CURLcode cf_cntrl_all(struct connectdata *conn,
return result;
}
bool Curl_conn_cf_is_ip_connected(struct Curl_cfilter *cf,
struct Curl_easy *data)
{
if(cf) {
int value = 0;
if(!cf->cft->query(cf, data, CF_QUERY_REALLY_CONNECTED, &value, NULL))
return !!value;
}
return FALSE;
}
void Curl_conn_cntrl_update_info(struct Curl_easy *data,
struct connectdata *conn)
{
cf_cntrl_all(conn, data, TRUE, CF_CTRL_CONN_INFO_UPDATE, 0, NULL);
}
void Curl_conn_cntrl_report_stats(struct Curl_easy *data,
struct connectdata *conn,
int sockindex)
{
if((unsigned)sockindex < CURL_ARRAYSIZE(conn->cfilter))
(void)Curl_conn_cf_cntrl(conn->cfilter[sockindex], data, TRUE,
CF_CTRL_REPORT_STATS, 0, NULL);
}
void Curl_conn_remove_setup_filters(struct Curl_easy *data,
int8_t sockindex)
{

View file

@ -121,6 +121,7 @@ typedef CURLcode Curl_cft_conn_keep_alive(struct Curl_cfilter *cf,
#define CF_CTRL_CONN_INFO_UPDATE (256 + 0) /* 0 NULL ignored */
#define CF_CTRL_FORGET_SOCKET (256 + 1) /* 0 NULL ignored */
#define CF_CTRL_FLUSH (256 + 2) /* 0 NULL first fail */
#define CF_CTRL_REPORT_STATS (256 + 3) /* 0 NULL ignored */
/**
* Handle event/control for the filter.
@ -156,13 +157,17 @@ typedef CURLcode Curl_cft_cntrl(struct Curl_cfilter *cf,
null-terminated string or NULL if none
selected/handshake not done. Implemented by filter
types CF_TYPE_SSL or CF_TYPE_IP_CONNECT.
* - CF_QUERY_REALLY_CONNECTED: implemented in socket filters to return
* if a reply from a server has really arrived. For
* non-UDP sockets this is TRUE when the socket became
* writable. For UDP sockets, this is TRUE when the
* first byte from the peer was received.
*/
/* query res1 res2 */
#define CF_QUERY_MAX_CONCURRENT 1 /* number - */
#define CF_QUERY_CONNECT_REPLY_MS 2 /* number - */
#define CF_QUERY_SOCKET 3 /* - curl_socket_t */
#define CF_QUERY_TIMER_CONNECT 4 /* - struct curltime */
#define CF_QUERY_TIMER_APPCONNECT 5 /* - struct curltime */
/* unused 4 + 5 */
#define CF_QUERY_STREAM_ERROR 6 /* error code - */
#define CF_QUERY_NEED_FLUSH 7 /* TRUE/FALSE - */
#define CF_QUERY_IP_INFO 8 /* TRUE/FALSE struct ip_quadruple */
@ -175,6 +180,7 @@ typedef CURLcode Curl_cft_cntrl(struct Curl_cfilter *cf,
#define CF_QUERY_SSL_CTX_INFO 13 /* - struct curl_tlssessioninfo * */
#define CF_QUERY_TRANSPORT 14 /* TRNSPRT_* - * */
#define CF_QUERY_ALPN_NEGOTIATED 15 /* - const char * */
#define CF_QUERY_REALLY_CONNECTED 16 /* TRUE/FALSE - */
/**
* Query the cfilter for properties. Filters ignorant of a query will
@ -343,6 +349,9 @@ CURLcode Curl_conn_cf_get_ip_info(struct Curl_cfilter *cf,
bool Curl_conn_cf_needs_flush(struct Curl_cfilter *cf,
struct Curl_easy *data);
bool Curl_conn_cf_is_ip_connected(struct Curl_cfilter *cf,
struct Curl_easy *data);
unsigned char Curl_conn_cf_get_transport(struct Curl_cfilter *cf,
struct Curl_easy *data);
@ -422,6 +431,10 @@ const char *Curl_conn_get_alpn_negotiated(struct Curl_easy *data,
void Curl_conn_cntrl_update_info(struct Curl_easy *data,
struct connectdata *conn);
void Curl_conn_cntrl_report_stats(struct Curl_easy *data,
struct connectdata *conn,
int sockindex);
void Curl_conn_remove_setup_filters(struct Curl_easy *data,
int8_t sockindex);

View file

@ -306,22 +306,11 @@ static CURLcode conn_connect_trace(struct Curl_easy *data,
/**
* Update connection statistics
*/
static void conn_report_connect_stats(struct Curl_cfilter *cf,
struct Curl_easy *data)
static void conn_report_stats(struct Curl_easy *data, int sockindex)
{
if(cf && (cf->sockindex == FIRSTSOCKET)) {
struct curltime connected;
struct curltime appconnected;
memset(&connected, 0, sizeof(connected));
cf->cft->query(cf, data, CF_QUERY_TIMER_CONNECT, NULL, &connected);
if(connected.tv_sec || connected.tv_usec)
Curl_pgrsTimeWas(data, TIMER_CONNECT, connected);
memset(&appconnected, 0, sizeof(appconnected));
cf->cft->query(cf, data, CF_QUERY_TIMER_APPCONNECT, NULL, &appconnected);
if(appconnected.tv_sec || appconnected.tv_usec)
Curl_pgrsTimeWas(data, TIMER_APPCONNECT, appconnected);
/* We do gather stats for the second socket...yet */
if(sockindex == FIRSTSOCKET) {
Curl_conn_cntrl_report_stats(data, data->conn, sockindex);
}
}
@ -384,7 +373,7 @@ CURLcode Curl_conn_connect(struct Curl_easy *data,
* persist information at the connection. E.g. cf-socket sets the
* socket and ip related information. */
Curl_conn_cntrl_update_info(data, data->conn);
conn_report_connect_stats(cf, data);
conn_report_stats(data, sockindex);
data->conn->lastupkeep = *Curl_pgrs_now(data);
VERBOSE(result = conn_connect_trace(data, cf));
VERBOSE(Curl_conn_trc_filters(data, sockindex, "connected"));
@ -396,7 +385,7 @@ CURLcode Curl_conn_connect(struct Curl_easy *data,
CURL_TRC_CF(data, cf, "Curl_conn_connect(), filter returned %d",
(int)result);
VERBOSE(Curl_conn_trc_filters(data, sockindex, "failed to connect"));
conn_report_connect_stats(cf, data);
conn_report_stats(data, sockindex);
goto out;
}

View file

@ -267,8 +267,11 @@ static int cb_ngtcp2_handshake_completed(ngtcp2_conn *tconn, void *user_data)
/* In case of earlydata, where we simulate being connected, update
* the handshake time when we really did connect */
if(ctx->use_earlydata)
if(ctx->use_earlydata && !ctx->stats_reported &&
!(cf->cft->flags & CF_TYPE_PROXY)) {
Curl_pgrsTimeWas(data, TIMER_APPCONNECT, ctx->handshake_at);
ctx->stats_reported = TRUE;
}
if(ctx->use_earlydata) {
#if defined(USE_OPENSSL) && defined(HAVE_OPENSSL_EARLYDATA)
ctx->earlydata_accepted =
@ -2008,4 +2011,65 @@ CURLcode Curl_cf_ngtcp2_h3_init_ctrls(struct cf_ngtcp2_ctx *ctx,
return CURLE_OK;
}
CURLcode Curl_cf_ngtcp2_cmn_query(struct Curl_cfilter *cf,
struct Curl_easy *data,
int query, int *pres1, void *pres2)
{
struct cf_ngtcp2_ctx *ctx = cf->ctx;
switch(query) {
case CF_QUERY_CONNECT_REPLY_MS:
if((ctx->q.sockfd != CURL_SOCKET_BAD) && ctx->q.got_first_byte) {
timediff_t ms = curlx_ptimediff_ms(&ctx->q.first_byte_at,
&ctx->started_at);
*pres1 = (ms < INT_MAX) ? (int)ms : INT_MAX;
return CURLE_OK;
}
break;
case CF_QUERY_REALLY_CONNECTED:
if(ctx->q.sockfd != CURL_SOCKET_BAD) {
*pres1 = ctx->q.got_first_byte;
return CURLE_OK;
}
break;
default:
break;
}
return cf->next ?
cf->next->cft->query(cf->next, data, query, pres1, pres2) :
CURLE_UNKNOWN_OPTION;
}
CURLcode Curl_cf_ngtcp2_cmn_cntrl(struct Curl_cfilter *cf,
struct Curl_easy *data,
int event, int arg1, void *arg2)
{
struct cf_ngtcp2_ctx *ctx = cf->ctx;
CURLcode result = CURLE_OK;
(void)arg1;
(void)arg2;
switch(event) {
case CF_CTRL_REPORT_STATS:
if(cf->connected && !ctx->stats_reported) {
if((cf->cft->flags & CF_TYPE_PROXY) &&
(ctx->q.sockfd != CURL_SOCKET_BAD) && ctx->q.got_first_byte) {
Curl_pgrsTimeWas(data, TIMER_CONNECT, ctx->q.first_byte_at);
ctx->stats_reported = TRUE;
}
else if(ctx->handshake_at.tv_sec || ctx->handshake_at.tv_usec) {
if(ctx->q.sockfd != CURL_SOCKET_BAD)
Curl_pgrsTimeWas(data, TIMER_CONNECT, ctx->q.first_byte_at);
Curl_pgrsTimeWas(data, TIMER_APPCONNECT, ctx->handshake_at);
ctx->stats_reported = TRUE;
}
}
break;
default:
break;
}
return result;
}
#endif /* !CURL_DISABLE_HTTP && USE_NGTCP2 && USE_NGHTTP3 */

View file

@ -142,6 +142,7 @@ struct cf_ngtcp2_ctx {
BIT(use_earlydata); /* Using 0RTT data */
BIT(earlydata_accepted); /* 0RTT was accepted by server */
BIT(shutdown_started); /* queued shutdown packets */
BIT(stats_reported); /* connect statistics reported */
};
/* How to access `call_data` from a cf_ngtcp2 filter */
@ -234,6 +235,14 @@ bool Curl_cf_ngtcp2_cmn_conn_is_alive(struct Curl_cfilter *cf,
struct Curl_easy *data,
bool *input_pending);
CURLcode Curl_cf_ngtcp2_cmn_query(struct Curl_cfilter *cf,
struct Curl_easy *data,
int query, int *pres1, void *pres2);
CURLcode Curl_cf_ngtcp2_cmn_cntrl(struct Curl_cfilter *cf,
struct Curl_easy *data,
int event, int arg1, void *arg2);
#endif /* !CURL_DISABLE_HTTP && USE_NGTCP2 && USE_NGHTTP3 */
#endif /* HEADER_CURL_VQUIC_CF_NGTCP2_CMN_H */

View file

@ -1229,7 +1229,7 @@ struct Curl_cftype Curl_cft_h3_proxy = {
Curl_cf_def_cntrl,
Curl_cf_ngtcp2_cmn_conn_is_alive,
Curl_cf_def_conn_keep_alive,
Curl_cf_def_query,
Curl_cf_ngtcp2_cmn_query,
};
CURLcode Curl_cf_ngtcp2_proxy_create(struct Curl_cfilter **pcf,

View file

@ -911,8 +911,6 @@ static CURLcode cf_ngtcp2_cntrl(struct Curl_cfilter *cf,
struct cf_call_data save;
CF_DATA_SAVE(save, cf, data);
(void)arg1;
(void)arg2;
switch(event) {
case CF_CTRL_DATA_SETUP:
break;
@ -939,6 +937,7 @@ static CURLcode cf_ngtcp2_cntrl(struct Curl_cfilter *cf,
}
break;
default:
result = Curl_cf_ngtcp2_cmn_cntrl(cf, data, event, arg1, arg2);
break;
}
CF_DATA_RESTORE(cf, save);
@ -1035,27 +1034,6 @@ static CURLcode cf_ngtcp2_query(struct Curl_cfilter *cf,
CF_DATA_RESTORE(cf, save);
return CURLE_OK;
}
case CF_QUERY_CONNECT_REPLY_MS:
if(ctx->q.got_first_byte) {
timediff_t ms = curlx_ptimediff_ms(&ctx->q.first_byte_at,
&ctx->started_at);
*pres1 = (ms < INT_MAX) ? (int)ms : INT_MAX;
}
else
*pres1 = -1;
return CURLE_OK;
case CF_QUERY_TIMER_CONNECT: {
struct curltime *when = pres2;
if(ctx->q.got_first_byte)
*when = ctx->q.first_byte_at;
return CURLE_OK;
}
case CF_QUERY_TIMER_APPCONNECT: {
struct curltime *when = pres2;
if(cf->connected)
*when = ctx->handshake_at;
return CURLE_OK;
}
case CF_QUERY_HTTP_VERSION:
*pres1 = 30;
return CURLE_OK;
@ -1076,9 +1054,7 @@ static CURLcode cf_ngtcp2_query(struct Curl_cfilter *cf,
default:
break;
}
return cf->next ?
cf->next->cft->query(cf->next, data, query, pres1, pres2) :
CURLE_UNKNOWN_OPTION;
return Curl_cf_ngtcp2_cmn_query(cf, data, query, pres1, pres2);
}
struct Curl_cftype Curl_cft_http3 = {

View file

@ -94,6 +94,7 @@ struct cf_quiche_ctx {
BIT(goaway); /* got GOAWAY from server */
BIT(x509_store_setup); /* if x509 store has been set up */
BIT(shutdown_started); /* queued shutdown packets */
BIT(stats_reported); /* connect statistics reported */
};
#ifdef DEBUG_QUICHE
@ -1254,6 +1255,14 @@ static CURLcode cf_quiche_cntrl(struct Curl_cfilter *cf,
Curl_conn_set_multiplex(cf->conn);
}
break;
case CF_CTRL_REPORT_STATS:
if(cf->connected && !ctx->stats_reported &&
(ctx->handshake_at.tv_sec || ctx->handshake_at.tv_usec)) {
Curl_pgrsTimeWas(data, TIMER_CONNECT, ctx->q.first_byte_at);
Curl_pgrsTimeWas(data, TIMER_APPCONNECT, ctx->handshake_at);
ctx->stats_reported = TRUE;
}
break;
default:
break;
}
@ -1550,18 +1559,6 @@ static CURLcode cf_quiche_query(struct Curl_cfilter *cf,
else
*pres1 = -1;
return CURLE_OK;
case CF_QUERY_TIMER_CONNECT: {
struct curltime *when = pres2;
if(ctx->q.got_first_byte)
*when = ctx->q.first_byte_at;
return CURLE_OK;
}
case CF_QUERY_TIMER_APPCONNECT: {
struct curltime *when = pres2;
if(cf->connected)
*when = ctx->handshake_at;
return CURLE_OK;
}
case CF_QUERY_HTTP_VERSION:
*pres1 = 30;
return CURLE_OK;

View file

@ -24,6 +24,7 @@
#include "curl_setup.h"
#include "urldata.h"
#include "vquic/vquic.h"
#include "vtls/vtls.h"
#include "curl_trc.h"

View file

@ -1064,7 +1064,10 @@ static CURLcode ssl_cf_connect_deferred(struct Curl_cfilter *cf,
result = ssl_cf_connect(cf, data, done);
if(!result && *done) {
Curl_pgrsTimeWas(data, TIMER_APPCONNECT, connssl->handshake_done);
if(!connssl->stats_reported && (cf->cft == &Curl_cft_ssl)) {
Curl_pgrsTimeWas(data, TIMER_APPCONNECT, connssl->handshake_done);
connssl->stats_reported = TRUE;
}
switch(connssl->earlydata_state) {
case ssl_earlydata_none:
break;
@ -1232,12 +1235,6 @@ static CURLcode ssl_cf_query(struct Curl_cfilter *cf,
struct ssl_connect_data *connssl = cf->ctx;
switch(query) {
case CF_QUERY_TIMER_APPCONNECT: {
struct curltime *when = pres2;
if(cf->connected && !Curl_ssl_cf_is_proxy(cf))
*when = connssl->handshake_done;
return CURLE_OK;
}
case CF_QUERY_SSL_INFO:
case CF_QUERY_SSL_CTX_INFO:
if(!Curl_ssl_cf_is_proxy(cf)) {
@ -1287,6 +1284,14 @@ static CURLcode ssl_cf_cntrl(struct Curl_cfilter *cf,
cf->conn->httpversion_seen = 30;
}
break;
case CF_CTRL_REPORT_STATS:
if(cf->connected && !connssl->stats_reported &&
(cf->cft == &Curl_cft_ssl) &&
(connssl->handshake_done.tv_sec || connssl->handshake_done.tv_usec)) {
Curl_pgrsTimeWas(data, TIMER_APPCONNECT, connssl->handshake_done);
connssl->stats_reported = TRUE;
}
break;
}
return CURLE_OK;
}

View file

@ -132,6 +132,7 @@ struct ssl_connect_data {
BIT(peer_closed); /* peer has closed connection */
BIT(prefs_checked); /* SSL preferences have been checked */
BIT(input_pending); /* data for SSL_read() may be available */
BIT(stats_reported); /* connect times have been reported */
};
/* Definitions for SSL Implementations */