From: Stefan Eissing Date: Fri, 3 Mar 2023 16:54:44 +0000 (+0100) Subject: connect: fix time_connect and time_appconnect timer statistics X-Git-Tag: curl-8_0_0~91 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=257416023d179f84ab77a53406156871453e280f;p=thirdparty%2Fcurl.git connect: fix time_connect and time_appconnect timer statistics - 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 --- diff --git a/lib/cf-https-connect.c b/lib/cf-https-connect.c index 72cdd10518..ed70ad05f9 100644 --- a/lib/cf-https-connect.c +++ b/lib/cf-https-connect.c @@ -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, diff --git a/lib/cf-socket.c b/lib/cf-socket.c index f523b13325..006c22d2cd 100644 --- a/lib/cf-socket.c +++ b/lib/cf-socket.c @@ -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; } diff --git a/lib/cfilters.c b/lib/cfilters.c index 2af0dd8288..c9932afcd1 100644 --- a/lib/cfilters.c +++ b/lib/cfilters.c @@ -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) diff --git a/lib/cfilters.h b/lib/cfilters.h index 94dc53f813..b70770350d 100644 --- a/lib/cfilters.h +++ b/lib/cfilters.h @@ -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. diff --git a/lib/connect.c b/lib/connect.c index b88351a2aa..10d0c11ae9 100644 --- a/lib/connect.c +++ b/lib/connect.c @@ -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; } diff --git a/lib/vquic/curl_msh3.c b/lib/vquic/curl_msh3.c index 1930703418..a74f7ceaa7 100644 --- a/lib/vquic/curl_msh3.c +++ b/lib/vquic/curl_msh3.c @@ -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; } diff --git a/lib/vquic/curl_ngtcp2.c b/lib/vquic/curl_ngtcp2.c index 58cf129f34..7296792856 100644 --- a/lib/vquic/curl_ngtcp2.c +++ b/lib/vquic/curl_ngtcp2.c @@ -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; } diff --git a/lib/vquic/curl_quiche.c b/lib/vquic/curl_quiche.c index c3c3b91e0f..6df9b85a10 100644 --- a/lib/vquic/curl_quiche.c +++ b/lib/vquic/curl_quiche.c @@ -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; } diff --git a/lib/vtls/vtls.c b/lib/vtls/vtls.c index 0fb3d43f41..108ac68d15 100644 --- a/lib/vtls/vtls.c +++ b/lib/vtls/vtls.c @@ -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 = { diff --git a/tests/http/test_06_eyeballs.py b/tests/http/test_06_eyeballs.py index 627ed3cea9..9b439fc049 100644 --- a/tests/http/test_06_eyeballs.py +++ b/tests/http/test_06_eyeballs.py @@ -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 +