http3/ngtcp2: shorten handshake, trace cleanup

- shorten handshake timing by delayed x509 store load (OpenSSL)
  as we do for HTTP/2
- cleanup of trace output, align with HTTP/2 output

Closes #11609

diff --git a/lib/vquic/curl_ngtcp2.c b/lib/vquic/curl_ngtcp2.c
index f58b685f6c66b4f7aa3b427aa2793bb0dfae99d5..f07cd8fbc8eaad76e6ab949388642b0f0a23de38 100644 (file)
--- a/lib/vquic/curl_ngtcp2.c
+++ b/lib/vquic/curl_ngtcp2.c
@@ -162,6 +162,9 @@ struct cf_ngtcp2_ctx {
   size_t max_stream_window;          /* max flow window for one stream */
   int qlogfd;
   BIT(got_first_byte);               /* if first byte was received */
+#ifdef USE_OPENSSL
+  BIT(x509_store_setup);             /* if x509 store has been set up */
+#endif
 };
 
 /* How to access `call_data` from a cf_ngtcp2 filter */
@@ -225,7 +228,6 @@ static CURLcode h3_data_setup(struct Curl_cfilter *cf,
   stream->recv_buf_nonflow = 0;
 
   H3_STREAM_LCTX(data) = stream;
-  CURL_TRC_CF(data, cf, "data setup");
   return CURLE_OK;
 }
 
@@ -235,7 +237,7 @@ static void h3_data_done(struct Curl_cfilter *cf, struct Curl_easy *data)
 
   (void)cf;
   if(stream) {
-    CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] easy handle is done", stream->id);
+    CURL_TRC_CF(data, cf, "[%"PRId64"] easy handle is done", stream->id);
     Curl_bufq_free(&stream->sendbuf);
     Curl_bufq_free(&stream->recvbuf);
     free(stream);
@@ -439,10 +441,6 @@ static CURLcode quic_ssl_ctx(SSL_CTX **pssl_ctx,
     SSL_CTX_set_keylog_callback(ssl_ctx, keylog_callback);
   }
 
-  result = Curl_ssl_setup_x509_store(cf, data, ssl_ctx);
-  if(result)
-    goto out;
-
   /* OpenSSL always tries to verify the peer, this only says whether it should
    * fail to connect if the verification fails, or if it should continue
    * anyway. In the latter case the result of the verification is checked with
@@ -727,7 +725,7 @@ static void report_consumed_data(struct Curl_cfilter *cf,
     }
   }
   if(consumed > 0) {
-    CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] consumed %zu DATA bytes",
+    CURL_TRC_CF(data, cf, "[%" PRId64 "] ACK %zu bytes of DATA",
                 stream->id, consumed);
     ngtcp2_conn_extend_max_stream_offset(ctx->qconn, stream->id,
                                          consumed);
@@ -750,7 +748,7 @@ static int cb_recv_stream_data(ngtcp2_conn *tconn, uint32_t flags,
 
   nconsumed =
     nghttp3_conn_read_stream(ctx->h3conn, stream_id, buf, buflen, fin);
-  CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read_stream(len=%zu) -> %zd",
+  CURL_TRC_CF(data, cf, "[%" PRId64 "] read_stream(len=%zu) -> %zd",
               stream_id, buflen, nconsumed);
   if(nconsumed < 0) {
     ngtcp2_ccerr_set_application_error(
@@ -809,7 +807,7 @@ static int cb_stream_close(ngtcp2_conn *tconn, uint32_t flags,
 
   rv = nghttp3_conn_close_stream(ctx->h3conn, stream3_id,
                                  app_error_code);
-  CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] quic close(err=%"
+  CURL_TRC_CF(data, cf, "[%" PRId64 "] quic close(err=%"
               PRIu64 ") -> %d", stream3_id, app_error_code, rv);
   if(rv) {
     ngtcp2_ccerr_set_application_error(
@@ -834,7 +832,7 @@ static int cb_stream_reset(ngtcp2_conn *tconn, int64_t stream_id,
   (void)data;
 
   rv = nghttp3_conn_shutdown_stream_read(ctx->h3conn, stream_id);
-  CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] reset -> %d", stream_id, rv);
+  CURL_TRC_CF(data, cf, "[%" PRId64 "] reset -> %d", stream_id, rv);
   if(rv) {
     return NGTCP2_ERR_CALLBACK_FAILURE;
   }
@@ -1092,20 +1090,21 @@ static int cb_h3_stream_close(nghttp3_conn *conn, int64_t stream_id,
   struct h3_stream_ctx *stream = H3_STREAM_CTX(data);
   (void)conn;
   (void)stream_id;
-  (void)app_error_code;
-  (void)cf;
 
   /* we might be called by nghttp3 after we already cleaned up */
   if(!stream)
     return 0;
 
-  CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] h3 close(err=%" PRId64 ")",
-              stream_id, app_error_code);
   stream->closed = TRUE;
   stream->error3 = app_error_code;
-  if(app_error_code == NGHTTP3_H3_INTERNAL_ERROR) {
+  if(stream->error3 != NGHTTP3_H3_NO_ERROR) {
     stream->reset = TRUE;
     stream->send_closed = TRUE;
+    CURL_TRC_CF(data, cf, "[%" PRId64 "] RESET: error %" PRId64,
+                stream->id, stream->error3);
+  }
+  else {
+    CURL_TRC_CF(data, cf, "[%" PRId64 "] CLOSED", stream->id);
   }
   h3_drain_stream(cf, data);
   return 0;
@@ -1152,12 +1151,22 @@ static int cb_h3_recv_data(nghttp3_conn *conn, int64_t stream3_id,
 {
   struct Curl_cfilter *cf = user_data;
   struct Curl_easy *data = stream_user_data;
+  struct h3_stream_ctx *stream = H3_STREAM_CTX(data);
   CURLcode result;
 
   (void)conn;
   (void)stream3_id;
 
+  if(!stream)
+    return NGHTTP3_ERR_CALLBACK_FAILURE;
+
   result = write_resp_raw(cf, data, buf, buflen, TRUE);
+  if(result) {
+    CURL_TRC_CF(data, cf, "[%" PRId64 "] DATA len=%zu, ERROR receiving %d",
+                stream->id, buflen, result);
+    return NGHTTP3_ERR_CALLBACK_FAILURE;
+  }
+  CURL_TRC_CF(data, cf, "[%" PRId64 "] DATA len=%zu", stream->id, buflen);
   h3_drain_stream(cf, data);
   return result? -1 : 0;
 }
@@ -1198,7 +1207,7 @@ static int cb_h3_end_headers(nghttp3_conn *conn, int64_t stream_id,
     return -1;
   }
 
-  CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] end_headers(status_code=%d",
+  CURL_TRC_CF(data, cf, "[%" PRId64 "] end_headers, status=%d",
               stream_id, stream->status_code);
   if(stream->status_code / 100 != 1) {
     stream->resp_hds_complete = TRUE;
@@ -1238,7 +1247,7 @@ static int cb_h3_recv_header(nghttp3_conn *conn, int64_t stream_id,
       return -1;
     ncopy = msnprintf(line, sizeof(line), "HTTP/3 %03d \r\n",
                       stream->status_code);
-    CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] status: %s", stream_id, line);
+    CURL_TRC_CF(data, cf, "[%" PRId64 "] status: %s", stream_id, line);
     result = write_resp_raw(cf, data, line, ncopy, FALSE);
     if(result) {
       return -1;
@@ -1246,7 +1255,7 @@ static int cb_h3_recv_header(nghttp3_conn *conn, int64_t stream_id,
   }
   else {
     /* store as an HTTP1-style header */
-    CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] header: %.*s: %.*s",
+    CURL_TRC_CF(data, cf, "[%" PRId64 "] header: %.*s: %.*s",
                 stream_id, (int)h3name.len, h3name.base,
                 (int)h3val.len, h3val.base);
     result = write_resp_raw(cf, data, h3name.base, h3name.len, FALSE);
@@ -1300,7 +1309,7 @@ static int cb_h3_reset_stream(nghttp3_conn *conn, int64_t stream_id,
 
   rv = ngtcp2_conn_shutdown_stream_write(ctx->qconn, 0, stream_id,
                                          app_error_code);
-  CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] reset -> %d", stream_id, rv);
+  CURL_TRC_CF(data, cf, "[%" PRId64 "] reset -> %d", stream_id, rv);
   if(rv && rv != NGTCP2_ERR_STREAM_NOT_FOUND) {
     return NGTCP2_ERR_CALLBACK_FAILURE;
   }
@@ -1397,35 +1406,17 @@ static ssize_t recv_closed_stream(struct Curl_cfilter *cf,
   if(stream->reset) {
     failf(data,
           "HTTP/3 stream %" PRId64 " reset by server", stream->id);
-    *err = CURLE_PARTIAL_FILE;
-    CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, was reset -> %d",
-                stream->id, *err);
+    *err = stream->resp_hds_complete? CURLE_PARTIAL_FILE : CURLE_HTTP3;
     goto out;
   }
-  else if(stream->error3 != NGHTTP3_H3_NO_ERROR) {
-    failf(data,
-          "HTTP/3 stream %" PRId64 " was not closed cleanly: "
-          "(err %"PRId64")", stream->id, stream->error3);
-    *err = CURLE_HTTP3;
-    CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed uncleanly"
-                " -> %d", stream->id, *err);
-    goto out;
-  }
-
-  if(!stream->resp_hds_complete) {
+  else if(!stream->resp_hds_complete) {
     failf(data,
           "HTTP/3 stream %" PRId64 " was closed cleanly, but before getting"
           " all response header fields, treated as error",
           stream->id);
     *err = CURLE_HTTP3;
-    CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed incomplete"
-                " -> %d", stream->id, *err);
     goto out;
   }
-  else {
-    CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed ok"
-                " -> %d", stream->id, *err);
-  }
   *err = CURLE_OK;
   nread = 0;
 
@@ -1462,10 +1453,11 @@ static ssize_t cf_ngtcp2_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
   if(!Curl_bufq_is_empty(&stream->recvbuf)) {
     nread = Curl_bufq_read(&stream->recvbuf,
                            (unsigned char *)buf, len, err);
-    CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) "
-                "-> %zd, %d", stream->id, len, nread, *err);
-    if(nread < 0)
+    if(nread < 0) {
+      CURL_TRC_CF(data, cf, "[%" PRId64 "] read recvbuf(len=%zu) "
+                  "-> %zd, %d", stream->id, len, nread, *err);
       goto out;
+    }
     report_consumed_data(cf, data, nread);
   }
 
@@ -1479,10 +1471,11 @@ static ssize_t cf_ngtcp2_recv(struct Curl_cfilter *cf, struct Curl_easy *data,
   if(nread < 0 && !Curl_bufq_is_empty(&stream->recvbuf)) {
     nread = Curl_bufq_read(&stream->recvbuf,
                            (unsigned char *)buf, len, err);
-    CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read recvbuf(len=%zu) "
-                "-> %zd, %d", stream->id, len, nread, *err);
-    if(nread < 0)
+    if(nread < 0) {
+      CURL_TRC_CF(data, cf, "[%" PRId64 "] read recvbuf(len=%zu) "
+                  "-> %zd, %d", stream->id, len, nread, *err);
       goto out;
+    }
     report_consumed_data(cf, data, nread);
   }
 
@@ -1510,7 +1503,7 @@ out:
       nread = -1;
     }
   }
-  CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv(len=%zu) -> %zd, %d",
+  CURL_TRC_CF(data, cf, "[%" PRId64 "] cf_recv(len=%zu) -> %zd, %d",
               stream? stream->id : -1, len, nread, *err);
   CF_DATA_RESTORE(cf, save);
   return nread;
@@ -1548,7 +1541,7 @@ static int cb_h3_acked_req_body(nghttp3_conn *conn, int64_t stream_id,
        (data->req.keepon & KEEP_SEND)) {
       data->req.keepon &= ~KEEP_SEND_HOLD;
       h3_drain_stream(cf, data);
-      CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] unpausing acks", stream_id);
+      CURL_TRC_CF(data, cf, "[%" PRId64 "] unpausing acks", stream_id);
     }
   }
   return 0;
@@ -1605,12 +1598,12 @@ cb_h3_read_req_body(nghttp3_conn *conn, int64_t stream_id,
   }
   else if(!nwritten) {
     /* Not EOF, and nothing to give, we signal WOULDBLOCK. */
-    CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read req body -> AGAIN",
+    CURL_TRC_CF(data, cf, "[%" PRId64 "] read req body -> AGAIN",
                 stream->id);
     return NGHTTP3_ERR_WOULDBLOCK;
   }
 
-  CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] read req body -> "
+  CURL_TRC_CF(data, cf, "[%" PRId64 "] read req body -> "
               "%d vecs%s with %zu (buffered=%zu, left=%"
               CURL_FORMAT_CURL_OFF_T ")",
               stream->id, (int)nvecs,
@@ -1728,9 +1721,15 @@ static ssize_t h3_stream_open(struct Curl_cfilter *cf,
     goto out;
   }
 
-  infof(data, "Using HTTP/3 Stream ID: %" PRId64, stream->id);
-  CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] opened for %s",
-              stream->id, data->state.url);
+  if(Curl_trc_is_verbose(data)) {
+    infof(data, "[HTTP/3] [%" PRId64 "] OPENED stream for %s",
+          stream->id, data->state.url);
+    for(i = 0; i < nheader; ++i) {
+      infof(data, "[HTTP/3] [%" PRId64 "] [%.*s: %.*s]", stream->id,
+            (int)nva[i].namelen, nva[i].name,
+            (int)nva[i].valuelen, nva[i].value);
+    }
+  }
 
 out:
   free(nva);
@@ -1768,6 +1767,7 @@ static ssize_t cf_ngtcp2_send(struct Curl_cfilter *cf, struct Curl_easy *data,
       CURL_TRC_CF(data, cf, "failed to open stream -> %d", *err);
       goto out;
     }
+    stream = H3_STREAM_CTX(data);
   }
   else if(stream->upload_blocked_len) {
     /* the data in `buf` has alread been submitted or added to the
@@ -1791,7 +1791,7 @@ static ssize_t cf_ngtcp2_send(struct Curl_cfilter *cf, struct Curl_easy *data,
   }
   else {
     sent = Curl_bufq_write(&stream->sendbuf, buf, len, err);
-    CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_send, add to "
+    CURL_TRC_CF(data, cf, "[%" PRId64 "] cf_send, add to "
                 "sendbuf(len=%zu) -> %zd, %d",
                 stream->id, len, sent, *err);
     if(sent < 0) {
@@ -1813,7 +1813,7 @@ static ssize_t cf_ngtcp2_send(struct Curl_cfilter *cf, struct Curl_easy *data,
      * "written" into our various internal connection buffers.
      * We put the stream upload on HOLD, until this gets ACKed. */
     stream->upload_blocked_len = sent;
-    CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_send(len=%zu), "
+    CURL_TRC_CF(data, cf, "[%" PRId64 "] cf_send(len=%zu), "
                 "%zu bytes in flight -> EGAIN", stream->id, len,
                 stream->sendbuf_len_in_flight);
     *err = CURLE_AGAIN;
@@ -1827,7 +1827,7 @@ out:
     *err = result;
     sent = -1;
   }
-  CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_send(len=%zu) -> %zd, %d",
+  CURL_TRC_CF(data, cf, "[%" PRId64 "] cf_send(len=%zu) -> %zd, %d",
               stream? stream->id : -1, len, sent, *err);
   CF_DATA_RESTORE(cf, save);
   return sent;
@@ -1946,6 +1946,15 @@ static CURLcode cf_progress_ingress(struct Curl_cfilter *cf,
     pktx->ts = timestamp();
   }
 
+#ifdef USE_OPENSSL
+  if(!ctx->x509_store_setup) {
+    result = Curl_ssl_setup_x509_store(cf, data, ctx->sslctx);
+    if(result)
+      return result;
+    ctx->x509_store_setup = TRUE;
+  }
+#endif
+
   for(i = 0; i < pkts_max; i += pkts_chunk) {
     pktx->pkt_count = 0;
     result = vquic_recv_packets(cf, data, &ctx->q, pkts_chunk,
@@ -2528,7 +2537,8 @@ out:
   if(!result && ctx->qconn) {
     result = check_and_set_expiry(cf, data, &pktx);
   }
-  CURL_TRC_CF(data, cf, "connect -> %d, done=%d", result, *done);
+  if(result || *done)
+    CURL_TRC_CF(data, cf, "connect -> %d, done=%d", result, *done);
   CF_DATA_RESTORE(cf, save);
   return result;
 }

diff --git a/lib/vquic/vquic.c b/lib/vquic/vquic.c
index 039a0124c65cc261b476514e2aef4688400a466a..a60165f91f98eb3da17f5fd7346fbfeee8197f03 100644 (file)
--- a/lib/vquic/vquic.c
+++ b/lib/vquic/vquic.c
@@ -363,8 +363,9 @@ static CURLcode recvmmsg_packets(struct Curl_cfilter *cf,
   }
 
 out:
-  CURL_TRC_CF(data, cf, "recvd %zu packets with %zu bytes -> %d",
-              pkts, total_nread, result);
+  if(total_nread || result)
+    CURL_TRC_CF(data, cf, "recvd %zu packets with %zu bytes -> %d",
+                pkts, total_nread, result);
   return result;
 }
 
@@ -428,8 +429,9 @@ static CURLcode recvmsg_packets(struct Curl_cfilter *cf,
   }
 
 out:
-  CURL_TRC_CF(data, cf, "recvd %zu packets with %zu bytes -> %d",
-              pkts, total_nread, result);
+  if(total_nread || result)
+    CURL_TRC_CF(data, cf, "recvd %zu packets with %zu bytes -> %d",
+                pkts, total_nread, result);
   return result;
 }
 
@@ -487,8 +489,9 @@ static CURLcode recvfrom_packets(struct Curl_cfilter *cf,
   }
 
 out:
-  CURL_TRC_CF(data, cf, "recvd %zu packets with %zu bytes -> %d",
-              pkts, total_nread, result);
+  if(total_nread || result)
+    CURL_TRC_CF(data, cf, "recvd %zu packets with %zu bytes -> %d",
+                pkts, total_nread, result);
   return result;
 }
 #endif /* !HAVE_SENDMMSG && !HAVE_SENDMSG */

diff --git a/tests/http/scorecard.py b/tests/http/scorecard.py
index fe56f43db32224739cfc32c778b081a995cdddce..ae466129c0aa8abfe12ed5faed0f75d27dc4f22c 100644 (file)
--- a/tests/http/scorecard.py
+++ b/tests/http/scorecard.py
@@ -33,7 +33,7 @@ import sys
 from statistics import mean
 from typing import Dict, Any, Optional, List
 
-from testenv import Env, Httpd, Nghttpx, CurlClient, Caddy, ExecResult
+from testenv import Env, Httpd, Nghttpx, CurlClient, Caddy, ExecResult, NghttpxFwd
 
 log = logging.getLogger(__name__)
 
@@ -67,33 +67,7 @@ class ScoreCard:
         sample_size = 5
         self.info(f'TLS Handshake\n')
         for authority in [
-            f'{self.env.authority_for(self.env.domain1, proto)}'
-        ]:
-            self.info('  localhost...')
-            c_samples = []
-            hs_samples = []
-            errors = []
-            for i in range(sample_size):
-                curl = CurlClient(env=self.env, silent=self._silent_curl)
-                url = f'https://{authority}/'
-                r = curl.http_download(urls=[url], alpn_proto=proto,
-                                       no_save=True)
-                if r.exit_code == 0 and len(r.stats) == 1:
-                    c_samples.append(r.stats[0]['time_connect'])
-                    hs_samples.append(r.stats[0]['time_appconnect'])
-                else:
-                    errors.append(f'exit={r.exit_code}')
-            props['localhost'] = {
-                'ipv4-connect': mean(c_samples),
-                'ipv4-handshake': mean(hs_samples),
-                'ipv4-errors': errors,
-                'ipv6-connect': 0,
-                'ipv6-handshake': 0,
-                'ipv6-errors': [],
-            }
-            self.info('ok.\n')
-        for authority in [
-            'curl.se', 'nghttp2.org',
+            'curl.se', 'google.com', 'cloudflare.com', 'nghttp2.org'
         ]:
             self.info(f'  {authority}...')
             props[authority] = {}
@@ -556,7 +530,7 @@ def main():
             httpd.clear_logs()
             assert httpd.start()
             if 'h3' == protocol:
-                nghttpx = Nghttpx(env=env)
+                nghttpx = NghttpxFwd(env=env)
                 nghttpx.clear_logs()
                 assert nghttpx.start()
         if test_caddy and env.caddy:

diff --git a/tests/http/test_05_errors.py b/tests/http/test_05_errors.py
index ecace5f4abd2d39c189152717f71b4260c25be1b..61579befc462d4389f899adbafde914a5438211e 100644 (file)
--- a/tests/http/test_05_errors.py
+++ b/tests/http/test_05_errors.py
@@ -65,7 +65,7 @@ class TestErrors:
         r.check_exit_code(False)
         invalid_stats = []
         for idx, s in enumerate(r.stats):
-            if 'exitcode' not in s or s['exitcode'] not in [18, 56, 92]:
+            if 'exitcode' not in s or s['exitcode'] not in [18, 56, 92, 95]:
                 invalid_stats.append(f'request {idx} exit with {s["exitcode"]}')
         assert len(invalid_stats) == 0, f'failed: {invalid_stats}'