romenskiy2012/curl
1
0
Fork 0
mirror of https://github.com/curl/curl.git synced 2026-08-25 23:23:31 +03:00
Code Issues Projects Releases Packages Wiki Activity

connect: fix time_connect and time_appconnect timer statistics

Browse source 
- time_connect was not updated when the overall connection failed,
  e.g. when SSL verification was unsuccessful, refs #10670
- rework gather those values to interrogate involved filters,
  also from all eyeballing attempts, to report the maximum of
  those values.
- added 3 test cases in test_06 to check reported values on
  successful, partially failed and totally failed connections.

Reported-by: Master Inspire
Fixes #10670
Closes #10671
This commit is contained in:
Stefan Eissing 2023-03-03 17:54:44 +01:00 • committed by Daniel Stenberg
parent 93eefa6ba1
commit 257416023d
No known key found for this signature in database
GPG key ID: 5CC908FDB71E12C2
10 changed files with 224 additions and 57 deletions
Download patch file Download diff file Expand all files Collapse all files

51
lib/cf-https-connect.c
View file

@ -376,6 +376,55 @@ static bool cf_hc_data_pending(struct Curl_cfilter *cf,
|| cf_hc_baller_data_pending(&ctx->h21_baller, data);
}
static struct curltime get_max_baller_time(struct Curl_cfilter *cf,
struct Curl_easy *data,
int query)
{
struct cf_hc_ctx *ctx = cf->ctx;
struct Curl_cfilter *cfb;
struct curltime t, tmax;
memset(&tmax, 0, sizeof(tmax));
memset(&t, 0, sizeof(t));
cfb = ctx->h21_baller.enabled? ctx->h21_baller.cf : NULL;
if(cfb && !cfb->cft->query(cfb, data, query, NULL, &t)) {
if((t.tv_sec || t.tv_usec) && Curl_timediff_us(t, tmax) > 0)
tmax = t;
}
memset(&t, 0, sizeof(t));
cfb = ctx->h3_baller.enabled? ctx->h3_baller.cf : NULL;
if(cfb && !cfb->cft->query(cfb, data, query, NULL, &t)) {
if((t.tv_sec || t.tv_usec) && Curl_timediff_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)
{
if(!cf->connected) {
switch(query) {
case CF_QUERY_TIMER_CONNECT: {
struct curltime *when = pres2;
*when = get_max_baller_time(cf, data, CF_QUERY_TIMER_CONNECT);
return CURLE_OK;
}
case CF_QUERY_TIMER_APPCONNECT: {
struct curltime *when = pres2;
*when = get_max_baller_time(cf, data, CF_QUERY_TIMER_APPCONNECT);
return CURLE_OK;
}
default:
break;
}
}
return cf->next?
cf->next->cft->query(cf->next, data, query, pres1, pres2) :
CURLE_UNKNOWN_OPTION;
}
static void cf_hc_close(struct Curl_cfilter *cf, struct Curl_easy *data)
{
DEBUGF(LOG_CF(data, cf, "close"));
@ -413,7 +462,7 @@ struct Curl_cftype Curl_cft_http_connect = {
Curl_cf_def_cntrl,
Curl_cf_def_conn_is_alive,
Curl_cf_def_conn_keep_alive,
Curl_cf_def_query,
cf_hc_query,
};
static CURLcode cf_hc_create(struct Curl_cfilter **pcf,

34
lib/cf-socket.c
View file

@ -1441,22 +1441,6 @@ static CURLcode cf_socket_cntrl(struct Curl_cfilter *cf,
case CF_CTRL_CONN_INFO_UPDATE:
cf_socket_active(cf, data);
break;
case CF_CTRL_CONN_REPORT_STATS:
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) {
Curl_pgrsTimeWas(data, TIMER_CONNECT, ctx->first_byte_at);
break;
}
/* FALLTHROUGH */
default:
Curl_pgrsTimeWas(data, TIMER_CONNECT, ctx->connected_at);
break;
}
break;
case CF_CTRL_DATA_SETUP:
Curl_persistconninfo(data, cf->conn, ctx->l_ip, ctx->l_port);
break;
@ -1517,6 +1501,24 @@ 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;
}
default:
break;
}

25
lib/cfilters.c
View file

@ -370,9 +370,12 @@ CURLcode Curl_conn_connect(struct Curl_easy *data,
result = cf->cft->connect(cf, data, blocking, done);
if(!result && *done) {
Curl_conn_ev_update_info(data, data->conn);
Curl_conn_ev_report_stats(data, data->conn);
Curl_conn_report_connect_stats(data, data->conn);
data->conn->keepalive = Curl_now();
}
else if(result) {
Curl_conn_report_connect_stats(data, data->conn);
}
}
return result;
@ -608,10 +611,24 @@ void Curl_conn_ev_update_info(struct Curl_easy *data,
cf_cntrl_all(conn, data, TRUE, CF_CTRL_CONN_INFO_UPDATE, 0, NULL);
}
void Curl_conn_ev_report_stats(struct Curl_easy *data,
struct connectdata *conn)
void Curl_conn_report_connect_stats(struct Curl_easy *data,
struct connectdata *conn)
{
cf_cntrl_all(conn, data, TRUE, CF_CTRL_CONN_REPORT_STATS, 0, NULL);
struct Curl_cfilter *cf = conn->cfilter[FIRSTSOCKET];
if(cf) {
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);
}
}
bool Curl_conn_is_alive(struct Curl_easy *data, struct connectdata *conn)

10
lib/cfilters.h
View file

@ -109,8 +109,6 @@ typedef CURLcode Curl_cft_conn_keep_alive(struct Curl_cfilter *cf,
#define CF_CTRL_DATA_DONE_SEND 8 /* 0 NULL ignored */
/* update conn info at connection and data */
#define CF_CTRL_CONN_INFO_UPDATE (256+0) /* 0 NULL ignored */
/* report conn statistics (timers) for connection and data */
#define CF_CTRL_CONN_REPORT_STATS (256+1) /* 0 NULL ignored */
/**
* Handle event/control for the filter.
@ -138,6 +136,8 @@ typedef CURLcode Curl_cft_cntrl(struct Curl_cfilter *cf,
#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 */
/**
* Query the cfilter for properties. Filters ignorant of a query will
@ -435,10 +435,10 @@ void Curl_conn_ev_update_info(struct Curl_easy *data,
struct connectdata *conn);
/**
* Inform connection filters to report statistics.
* Update connection statistics
*/
void Curl_conn_ev_report_stats(struct Curl_easy *data,
struct connectdata *conn);
void Curl_conn_report_connect_stats(struct Curl_easy *data,
struct connectdata *conn);
/**
* Check if FIRSTSOCKET's cfilter chain deems connection alive.

33
lib/connect.c
View file

@ -957,6 +957,28 @@ static bool cf_he_data_pending(struct Curl_cfilter *cf,
return FALSE;
}
static struct curltime get_max_baller_time(struct Curl_cfilter *cf,
struct Curl_easy *data,
int query)
{
struct cf_he_ctx *ctx = cf->ctx;
struct curltime t, tmax;
size_t i;
memset(&tmax, 0, sizeof(tmax));
for(i = 0; i < sizeof(ctx->baller)/sizeof(ctx->baller[0]); i++) {
struct eyeballer *baller = ctx->baller[i];
memset(&t, 0, sizeof(t));
if(baller && baller->cf &&
!baller->cf->cft->query(baller->cf, data, query, NULL, &t)) {
if((t.tv_sec || t.tv_usec) && Curl_timediff_us(t, tmax) > 0)
tmax = t;
}
}
return tmax;
}
static CURLcode cf_he_query(struct Curl_cfilter *cf,
struct Curl_easy *data,
int query, int *pres1, void *pres2)
@ -984,7 +1006,16 @@ static CURLcode cf_he_query(struct Curl_cfilter *cf,
DEBUGF(LOG_CF(data, cf, "query connect reply: %dms", *pres1));
return CURLE_OK;
}
case CF_QUERY_TIMER_CONNECT: {
struct curltime *when = pres2;
*when = get_max_baller_time(cf, data, CF_QUERY_TIMER_CONNECT);
return CURLE_OK;
}
case CF_QUERY_TIMER_APPCONNECT: {
struct curltime *when = pres2;
*when = get_max_baller_time(cf, data, CF_QUERY_TIMER_APPCONNECT);
return CURLE_OK;
}
default:
break;
}

19
lib/vquic/curl_msh3.c
View file

@ -548,7 +548,6 @@ static CURLcode cf_msh3_data_event(struct Curl_cfilter *cf,
struct Curl_easy *data,
int event, int arg1, void *arg2)
{
struct cf_msh3_ctx *ctx = cf->ctx;
struct HTTP *stream = data->req.p.http;
CURLcode result = CURLE_OK;
@ -579,11 +578,6 @@ static CURLcode cf_msh3_data_event(struct Curl_cfilter *cf,
DEBUGF(LOG_CF(data, cf, "req: update info"));
cf_msh3_active(cf, data);
break;
case CF_CTRL_CONN_REPORT_STATS:
if(cf->sockindex == FIRSTSOCKET)
Curl_pgrsTimeWas(data, TIMER_APPCONNECT, ctx->handshake_at);
break;
default:
break;
}
@ -753,6 +747,19 @@ static CURLcode cf_msh3_query(struct Curl_cfilter *cf,
*pres1 = 100;
return CURLE_OK;
}
case CF_QUERY_TIMER_CONNECT: {
struct curltime *when = pres2;
/* we do not know when the first byte arrived */
if(cf->connected)
*when = ctx->handshake_at;
return CURLE_OK;
}
case CF_QUERY_TIMER_APPCONNECT: {
struct curltime *when = pres2;
if(cf->connected)
*when = ctx->handshake_at;
return CURLE_OK;
}
default:
break;
}

19
lib/vquic/curl_ngtcp2.c
View file

@ -2109,13 +2109,6 @@ static CURLcode cf_ngtcp2_data_event(struct Curl_cfilter *cf,
}
}
break;
case CF_CTRL_CONN_REPORT_STATS:
if(cf->sockindex == FIRSTSOCKET) {
if(ctx->got_first_byte)
Curl_pgrsTimeWas(data, TIMER_CONNECT, ctx->first_byte_at);
Curl_pgrsTimeWas(data, TIMER_APPCONNECT, ctx->handshake_at);
}
break;
default:
break;
}
@ -2431,6 +2424,18 @@ static CURLcode cf_ngtcp2_query(struct Curl_cfilter *cf,
else
*pres1 = -1;
return CURLE_OK;
case CF_QUERY_TIMER_CONNECT: {
struct curltime *when = pres2;
if(ctx->got_first_byte)
*when = ctx->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;
}
default:
break;
}

19
lib/vquic/curl_quiche.c
View file

@ -1016,13 +1016,6 @@ static CURLcode cf_quiche_data_event(struct Curl_cfilter *cf,
case CF_CTRL_DATA_IDLE:
/* anything to do? */
break;
case CF_CTRL_CONN_REPORT_STATS:
if(cf->sockindex == FIRSTSOCKET) {
if(ctx->got_first_byte)
Curl_pgrsTimeWas(data, TIMER_CONNECT, ctx->first_byte_at);
Curl_pgrsTimeWas(data, TIMER_APPCONNECT, ctx->handshake_at);
}
break;
default:
break;
}
@ -1346,6 +1339,18 @@ 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->got_first_byte)
*when = ctx->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;
}
default:
break;
}

28
lib/vtls/vtls.c
View file

@ -1604,16 +1604,11 @@ static CURLcode ssl_cf_cntrl(struct Curl_cfilter *cf,
struct Curl_easy *data,
int event, int arg1, void *arg2)
{
struct ssl_connect_data *connssl = cf->ctx;
struct cf_call_data save;
(void)arg1;
(void)arg2;
switch(event) {
case CF_CTRL_CONN_REPORT_STATS:
if(cf->sockindex == FIRSTSOCKET && !Curl_ssl_cf_is_proxy(cf))
Curl_pgrsTimeWas(data, TIMER_APPCONNECT, connssl->handshake_done);
break;
case CF_CTRL_DATA_ATTACH:
if(Curl_ssl->attach_data) {
CF_DATA_SAVE(save, cf, data);
@ -1634,6 +1629,27 @@ static CURLcode ssl_cf_cntrl(struct Curl_cfilter *cf,
return CURLE_OK;
}
static CURLcode ssl_cf_query(struct Curl_cfilter *cf,
struct Curl_easy *data,
int query, int *pres1, void *pres2)
{
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;
}
default:
break;
}
return cf->next?
cf->next->cft->query(cf->next, data, query, pres1, pres2) :
CURLE_UNKNOWN_OPTION;
}
static bool cf_ssl_is_alive(struct Curl_cfilter *cf, struct Curl_easy *data)
{
struct cf_call_data save;
@ -1674,7 +1690,7 @@ struct Curl_cftype Curl_cft_ssl = {
ssl_cf_cntrl,
cf_ssl_is_alive,
Curl_cf_def_conn_keep_alive,
Curl_cf_def_query,
ssl_cf_query,
};
struct Curl_cftype Curl_cft_ssl_proxy = {

43
tests/http/test_06_eyeballs.py
View file

@ -37,10 +37,6 @@ log = logging.getLogger(__name__)
@pytest.mark.skipif(condition=Env.setup_incomplete(),
reason=f"missing: {Env.incomplete_reason()}")
@pytest.mark.skipif(condition=not Env.have_h3_server(),
reason=f"missing HTTP/3 server")
@pytest.mark.skipif(condition=not Env.have_h3_curl(),
reason=f"curl built without HTTP/3")
class TestEyeballs:
@pytest.fixture(autouse=True, scope='class')
@ -49,6 +45,7 @@ class TestEyeballs:
nghttpx.start_if_needed()
# download using only HTTP/3 on working server
@pytest.mark.skipif(condition=not Env.have_h3(), reason=f"missing HTTP/3 support")
def test_06_01_h3_only(self, env: Env, httpd, nghttpx, repeat):
curl = CurlClient(env=env)
urln = f'https://{env.authority_for(env.domain1, "h3")}/data.json'
@ -58,6 +55,7 @@ class TestEyeballs:
assert r.stats[0]['http_version'] == '3'
# download using only HTTP/3 on missing server
@pytest.mark.skipif(condition=not Env.have_h3(), reason=f"missing HTTP/3 support")
def test_06_02_h3_only(self, env: Env, httpd, nghttpx, repeat):
nghttpx.stop_if_running()
curl = CurlClient(env=env)
@ -66,6 +64,7 @@ class TestEyeballs:
assert r.exit_code == 7, f'{r}' # could not connect
# download using HTTP/3 on missing server with fallback on h2
@pytest.mark.skipif(condition=not Env.have_h3(), reason=f"missing HTTP/3 support")
def test_06_03_h3_fallback_h2(self, env: Env, httpd, nghttpx, repeat):
nghttpx.stop_if_running()
curl = CurlClient(env=env)
@ -76,6 +75,7 @@ class TestEyeballs:
assert r.stats[0]['http_version'] == '2'
# download using HTTP/3 on missing server with fallback on http/1.1
@pytest.mark.skipif(condition=not Env.have_h3(), reason=f"missing HTTP/3 support")
def test_06_04_h3_fallback_h1(self, env: Env, httpd, nghttpx, repeat):
nghttpx.stop_if_running()
curl = CurlClient(env=env)
@ -84,3 +84,38 @@ class TestEyeballs:
assert r.exit_code == 0, f'{r}'
r.check_stats(count=1, exp_status=200)
assert r.stats[0]['http_version'] == '1.1'
# make a successful https: transfer and observer the timer stats
def test_06_10_stats_success(self, env: Env, httpd, nghttpx, repeat):
curl = CurlClient(env=env)
urln = f'https://{env.authority_for(env.domain1, "h2")}/data.json'
r = curl.http_download(urls=[urln])
assert r.exit_code == 0, f'{r}'
r.check_stats(count=1, exp_status=200)
assert r.stats[0]['time_connect'] > 0.0
assert r.stats[0]['time_appconnect'] > 0.0
# make https: to a hostname that tcp connects, but will not verify
def test_06_11_stats_fail_verify(self, env: Env, httpd, nghttpx, repeat):
curl = CurlClient(env=env)
urln = f'https://not-valid.com:{env.https_port}/data.json'
r = curl.http_download(urls=[urln], extra_args=[
'--resolve', f'not-valid.com:{env.https_port}:127.0.0.1'
])
assert r.exit_code != 0, f'{r}'
r.check_stats(count=1, exp_status=0)
assert r.stats[0]['time_connect'] > 0.0 # was tcp connected
assert r.stats[0]['time_appconnect'] == 0 # but not SSL verified
# make https: to an invalid address
def test_06_12_stats_fail_tcp(self, env: Env, httpd, nghttpx, repeat):
curl = CurlClient(env=env)
urln = f'https://not-valid.com:1/data.json'
r = curl.http_download(urls=[urln], extra_args=[
'--resolve', f'not-valid.com:{1}:127.0.0.1'
])
assert r.exit_code != 0, f'{r}'
r.check_stats(count=1, exp_status=0)
assert r.stats[0]['time_connect'] == 0 # no one should have listened
assert r.stats[0]['time_appconnect'] == 0 # did not happen either