]> git.ipfire.org Git - thirdparty/curl.git/commitdiff
connect: fix time_connect and time_appconnect timer statistics
authorStefan Eissing <stefan@eissing.org>
Fri, 3 Mar 2023 16:54:44 +0000 (17:54 +0100)
committerDaniel Stenberg <daniel@haxx.se>
Mon, 6 Mar 2023 19:16:43 +0000 (20:16 +0100)
- 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

lib/cf-https-connect.c
lib/cf-socket.c
lib/cfilters.c
lib/cfilters.h
lib/connect.c
lib/vquic/curl_msh3.c
lib/vquic/curl_ngtcp2.c
lib/vquic/curl_quiche.c
lib/vtls/vtls.c
tests/http/test_06_eyeballs.py

index 72cdd10518fe5306a3f0313379ca4e9374a23f8c..ed70ad05f9397ffe481972a49352e4f7ce8ac326 100644 (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,
index f523b1332568f6699111ff27fec51c7d8b17adad..006c22d2cd9a22bffb3e4277873acd14aa2c5f98 100644 (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;
   }
index 2af0dd8288c29b738b2346eb3a96ab26998cf288..c9932afcd18a1505f25e6e957dcd2e9add7f57de 100644 (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)
index 94dc53f813baf988dd4c7b5bac3301531791e3b8..b70770350de5632d6764346b941cac965a05b4fa 100644 (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.
index b88351a2aa571478db61b1c52983d6ff8b14792a..10d0c11ae990eca2e28d4aa9ca4f2257015c8bb2 100644 (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;
     }
index 193070341806070d2f8eaf4ac5f8e9ff56cbef76..a74f7ceaa71ef90dbfa435ce78573a5444dfc45d 100644 (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;
   }
index 58cf129f34ec2320d0cc4e811df6d0ace91d3573..72967928563cd26192ef30e4dfbb40c4ada41910 100644 (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;
   }
index c3c3b91e0f5f4f141eacf41c99855e49ef0df9aa..6df9b85a106747e75ace56f99fbcea6b89f65e8f 100644 (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;
   }
index 0fb3d43f418412ceab850afcb5f942d66c1d4a0a..108ac68d15262e14495a70994de27cadabc24431 100644 (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 = {
index 627ed3cea9b56d9f2a70a8f4b9af330722bdc176..9b439fc0490ceb8caa0cb123b812aaf3618b4619 100644 (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
+