From: Stefan Eissing Date: Mon, 7 Aug 2023 11:50:14 +0000 (+0200) Subject: http3: quiche, handshake optimization, trace cleanup X-Git-Tag: curl-8_3_0~194 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=d7eafb1d558f92bfb70e231b11bb29c18e9ccaa4;p=thirdparty%2Fcurl.git http3: quiche, handshake optimization, trace cleanup - load x509 store after clienthello - cleanup of tracing Closes #11618 --- diff --git a/lib/vquic/curl_quiche.c b/lib/vquic/curl_quiche.c index c3c20eece2..9776de8992 100644 --- a/lib/vquic/curl_quiche.c +++ b/lib/vquic/curl_quiche.c @@ -88,54 +88,6 @@ static void keylog_callback(const SSL *ssl, const char *line) Curl_tls_keylog_write_line(line); } -static SSL_CTX *quic_ssl_ctx(struct Curl_easy *data) -{ - SSL_CTX *ssl_ctx = SSL_CTX_new(TLS_method()); - - SSL_CTX_set_alpn_protos(ssl_ctx, - (const uint8_t *)QUICHE_H3_APPLICATION_PROTOCOL, - sizeof(QUICHE_H3_APPLICATION_PROTOCOL) - 1); - - SSL_CTX_set_default_verify_paths(ssl_ctx); - - /* Open the file if a TLS or QUIC backend has not done this before. */ - Curl_tls_keylog_open(); - if(Curl_tls_keylog_enabled()) { - SSL_CTX_set_keylog_callback(ssl_ctx, keylog_callback); - } - - { - struct connectdata *conn = data->conn; - if(conn->ssl_config.verifypeer) { - const char * const ssl_cafile = conn->ssl_config.CAfile; - const char * const ssl_capath = conn->ssl_config.CApath; - if(ssl_cafile || ssl_capath) { - SSL_CTX_set_verify(ssl_ctx, SSL_VERIFY_PEER, NULL); - /* tell OpenSSL where to find CA certificates that are used to verify - the server's certificate. */ - if(!SSL_CTX_load_verify_locations(ssl_ctx, ssl_cafile, ssl_capath)) { - /* Fail if we insist on successfully verifying the server. */ - failf(data, "error setting certificate verify locations:" - " CAfile: %s CApath: %s", - ssl_cafile ? ssl_cafile : "none", - ssl_capath ? ssl_capath : "none"); - return NULL; - } - infof(data, " CAfile: %s", ssl_cafile ? ssl_cafile : "none"); - infof(data, " CApath: %s", ssl_capath ? ssl_capath : "none"); - } -#ifdef CURL_CA_FALLBACK - else { - /* verifying the peer without any CA certificates won't work so - use openssl's built-in default as fallback */ - SSL_CTX_set_default_verify_paths(ssl_ctx); - } -#endif - } - } - return ssl_ctx; -} - struct cf_quiche_ctx { struct cf_quic_ctx q; quiche_conn *qconn; @@ -154,6 +106,7 @@ struct cf_quiche_ctx { size_t sends_on_hold; /* # of streams with SEND_HOLD set */ BIT(goaway); /* got GOAWAY from server */ BIT(got_first_byte); /* if first byte was received */ + BIT(x509_store_setup); /* if x509 store has been set up */ }; #ifdef DEBUG_QUICHE @@ -181,6 +134,76 @@ static void cf_quiche_ctx_clear(struct cf_quiche_ctx *ctx) } } +static CURLcode quic_x509_store_setup(struct Curl_cfilter *cf, + struct Curl_easy *data) +{ + struct cf_quiche_ctx *ctx = cf->ctx; + + if(!ctx->x509_store_setup) { + if(cf->conn->ssl_config.verifypeer) { + const char * const ssl_cafile = cf->conn->ssl_config.CAfile; + const char * const ssl_capath = cf->conn->ssl_config.CApath; + if(ssl_cafile || ssl_capath) { + SSL_CTX_set_verify(ctx->sslctx, SSL_VERIFY_PEER, NULL); + /* tell OpenSSL where to find CA certificates that are used to verify + the server's certificate. */ + if(!SSL_CTX_load_verify_locations( + ctx->sslctx, ssl_cafile, ssl_capath)) { + /* Fail if we insist on successfully verifying the server. */ + failf(data, "error setting certificate verify locations:" + " CAfile: %s CApath: %s", + ssl_cafile ? ssl_cafile : "none", + ssl_capath ? ssl_capath : "none"); + return CURLE_SSL_CACERT_BADFILE; + } + infof(data, " CAfile: %s", ssl_cafile ? ssl_cafile : "none"); + infof(data, " CApath: %s", ssl_capath ? ssl_capath : "none"); + } +#ifdef CURL_CA_FALLBACK + else { + /* verifying the peer without any CA certificates won't work so + use openssl's built-in default as fallback */ + SSL_CTX_set_default_verify_paths(ssl_ctx); + } +#endif + } + ctx->x509_store_setup = TRUE; + } + return CURLE_OK; +} + +static CURLcode quic_ssl_setup(struct Curl_cfilter *cf, struct Curl_easy *data) +{ + struct cf_quiche_ctx *ctx = cf->ctx; + + (void)data; + DEBUGASSERT(!ctx->sslctx); + ctx->sslctx = SSL_CTX_new(TLS_method()); + if(!ctx->sslctx) + return CURLE_OUT_OF_MEMORY; + + SSL_CTX_set_alpn_protos(ctx->sslctx, + (const uint8_t *)QUICHE_H3_APPLICATION_PROTOCOL, + sizeof(QUICHE_H3_APPLICATION_PROTOCOL) - 1); + + SSL_CTX_set_default_verify_paths(ctx->sslctx); + + /* Open the file if a TLS or QUIC backend has not done this before. */ + Curl_tls_keylog_open(); + if(Curl_tls_keylog_enabled()) { + SSL_CTX_set_keylog_callback(ctx->sslctx, keylog_callback); + } + + ctx->ssl = SSL_new(ctx->sslctx); + if(!ctx->ssl) + return CURLE_QUIC_CONNECT_ERROR; + + SSL_set_app_data(ctx->ssl, cf); + SSL_set_tlsext_host_name(ctx->ssl, cf->conn->host.name); + + return CURLE_OK; +} + /** * All about the H3 internals of a stream */ @@ -217,7 +240,7 @@ static void stream_send_suspend(struct Curl_cfilter *cf, data->req.keepon |= KEEP_SEND_HOLD; ++ctx->sends_on_hold; if(H3_STREAM_ID(data) >= 0) - CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] suspend sending", + CURL_TRC_CF(data, cf, "[%"PRId64"] suspend sending", H3_STREAM_ID(data)); else CURL_TRC_CF(data, cf, "[%s] suspend sending", data->state.url); @@ -233,7 +256,7 @@ static void stream_send_resume(struct Curl_cfilter *cf, data->req.keepon &= ~KEEP_SEND_HOLD; --ctx->sends_on_hold; if(H3_STREAM_ID(data) >= 0) - CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] resume sending", + CURL_TRC_CF(data, cf, "[%"PRId64"] resume sending", H3_STREAM_ID(data)); else CURL_TRC_CF(data, cf, "[%s] resume sending", data->state.url); @@ -275,7 +298,6 @@ static CURLcode h3_data_setup(struct Curl_cfilter *cf, stream->id = -1; Curl_bufq_initp(&stream->recvbuf, &ctx->stream_bufcp, H3_STREAM_RECV_CHUNKS, BUFQ_OPT_SOFT_LIMIT); - CURL_TRC_CF(data, cf, "data setup"); return CURLE_OK; } @@ -286,7 +308,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); if(stream_send_is_suspended(data)) { data->req.keepon &= ~KEEP_SEND_HOLD; --ctx->sends_on_hold; @@ -376,8 +398,12 @@ static int cb_each_header(uint8_t *name, size_t name_len, struct stream_ctx *stream = H3_STREAM_CTX(x->data); CURLcode result; - (void)stream; + if(!stream) + return CURLE_OK; + if((name_len == 7) && !strncmp(HTTP_PSEUDO_STATUS, (char *)name, 7)) { + CURL_TRC_CF(x->data, x->cf, "[%" PRId64 "] status: %.*s", + stream->id, (int)value_len, value); result = write_resp_raw(x->cf, x->data, "HTTP/3 ", sizeof("HTTP/3 ") - 1); if(!result) result = write_resp_raw(x->cf, x->data, value, value_len); @@ -385,6 +411,9 @@ static int cb_each_header(uint8_t *name, size_t name_len, result = write_resp_raw(x->cf, x->data, " \r\n", 3); } else { + CURL_TRC_CF(x->data, x->cf, "[%" PRId64 "] header: %.*s: %.*s", + stream->id, (int)name_len, name, + (int)value_len, value); result = write_resp_raw(x->cf, x->data, name, name_len); if(!result) result = write_resp_raw(x->cf, x->data, ": ", 2); @@ -394,10 +423,8 @@ static int cb_each_header(uint8_t *name, size_t name_len, result = write_resp_raw(x->cf, x->data, "\r\n", 2); } if(result) { - CURL_TRC_CF(x->data, x->cf, - "[h3sid=%"PRId64"][HEADERS][%.*s: %.*s] error %d", - stream? stream->id : -1, (int)name_len, name, - (int)value_len, value, result); + CURL_TRC_CF(x->data, x->cf, "[%"PRId64"] on header error %d", + stream->id, result); } return result; } @@ -452,7 +479,7 @@ static CURLcode cf_recv_body(struct Curl_cfilter *cf, stream_resp_read, &cb_ctx, &result); if(nwritten < 0 && result != CURLE_AGAIN) { - CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] recv_body error %zd", + CURL_TRC_CF(data, cf, "[%"PRId64"] recv_body error %zd", stream->id, nwritten); failf(data, "Error %d in HTTP/3 response body for stream[%"PRId64"]", result, stream->id); @@ -511,7 +538,7 @@ static CURLcode h3_process_event(struct Curl_cfilter *cf, rc, stream3_id); return CURLE_RECV_ERROR; } - CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"][HEADERS]", stream3_id); + CURL_TRC_CF(data, cf, "[%"PRId64"] <- [HEADERS]", stream3_id); break; case QUICHE_H3_EVENT_DATA: @@ -521,7 +548,7 @@ static CURLcode h3_process_event(struct Curl_cfilter *cf, break; case QUICHE_H3_EVENT_RESET: - CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"][RESET]", stream3_id); + CURL_TRC_CF(data, cf, "[%"PRId64"] RESET", stream3_id); stream->closed = TRUE; stream->reset = TRUE; stream->send_closed = TRUE; @@ -529,7 +556,7 @@ static CURLcode h3_process_event(struct Curl_cfilter *cf, break; case QUICHE_H3_EVENT_FINISHED: - CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"][FINISHED]", stream3_id); + CURL_TRC_CF(data, cf, "[%"PRId64"] CLOSED", stream3_id); if(!stream->resp_hds_complete) { result = write_resp_raw(cf, data, "\r\n", 2); if(result) @@ -541,11 +568,11 @@ static CURLcode h3_process_event(struct Curl_cfilter *cf, break; case QUICHE_H3_EVENT_GOAWAY: - CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"][GOAWAY]", stream3_id); + CURL_TRC_CF(data, cf, "[%"PRId64"] <- [GOAWAY]", stream3_id); break; default: - CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] recv, unhandled event %d", + CURL_TRC_CF(data, cf, "[%"PRId64"] recv, unhandled event %d", stream3_id, quiche_h3_event_type(ev)); break; } @@ -568,23 +595,23 @@ static CURLcode cf_poll_events(struct Curl_cfilter *cf, break; } else if(stream3_id < 0) { - CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] error poll: %"PRId64, + CURL_TRC_CF(data, cf, "[%"PRId64"] error poll: %"PRId64, stream? stream->id : -1, stream3_id); return CURLE_HTTP3; } sdata = get_stream_easy(cf, data, stream3_id); if(!sdata) { - CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] discard event %s for " - "unknown [h3sid=%"PRId64"]", + CURL_TRC_CF(data, cf, "[%"PRId64"] discard event %s for " + "unknown [%"PRId64"]", stream? stream->id : -1, cf_ev_name(ev), stream3_id); } else { result = h3_process_event(cf, sdata, stream3_id, ev); drain_stream(cf, sdata); if(result) { - CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] error processing event %s " - "for [h3sid=%"PRId64"] -> %d", + CURL_TRC_CF(data, cf, "[%"PRId64"] error processing event %s " + "for [%"PRId64"] -> %d", stream? stream->id : -1, cf_ev_name(ev), stream3_id, result); if(data == sdata) { @@ -661,6 +688,10 @@ static CURLcode cf_process_ingress(struct Curl_cfilter *cf, CURLcode result; DEBUGASSERT(ctx->qconn); + result = quic_x509_store_setup(cf, data); + if(result) + return result; + rctx.cf = cf; rctx.data = data; rctx.pkts = 0; @@ -788,7 +819,7 @@ static ssize_t recv_closed_stream(struct Curl_cfilter *cf, failf(data, "HTTP/3 stream %" PRId64 " reset by server", stream->id); *err = stream->resp_got_header? CURLE_PARTIAL_FILE : CURLE_RECV_ERROR; - CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, was reset -> %d", + CURL_TRC_CF(data, cf, "[%" PRId64 "] cf_recv, was reset -> %d", stream->id, *err); } else if(!stream->resp_got_header) { @@ -798,14 +829,12 @@ static ssize_t recv_closed_stream(struct Curl_cfilter *cf, stream->id); /* *err = CURLE_PARTIAL_FILE; */ *err = CURLE_RECV_ERROR; - CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed incomplete" + CURL_TRC_CF(data, cf, "[%" PRId64 "] cf_recv, closed incomplete" " -> %d", stream->id, *err); } else { *err = CURLE_OK; nread = 0; - CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] cf_recv, closed ok" - " -> %d", stream->id, *err); } return nread; } @@ -826,7 +855,7 @@ static ssize_t cf_quiche_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) " + CURL_TRC_CF(data, cf, "[%" PRId64 "] read recvbuf(len=%zu) " "-> %zd, %d", stream->id, len, nread, *err); if(nread < 0) goto out; @@ -843,7 +872,7 @@ static ssize_t cf_quiche_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) " + CURL_TRC_CF(data, cf, "[%" PRId64 "] read recvbuf(len=%zu) " "-> %zd, %d", stream->id, len, nread, *err); if(nread < 0) goto out; @@ -877,7 +906,7 @@ out: } if(nread > 0) ctx->data_recvd += nread; - CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] cf_recv(total=%" + CURL_TRC_CF(data, cf, "[%"PRId64"] cf_recv(total=%" CURL_FORMAT_CURL_OFF_T ") -> %zd, %d", stream ? stream->id : (int64_t)0, ctx->data_recvd, nread, *err); @@ -990,9 +1019,15 @@ static ssize_t h3_open_stream(struct Curl_cfilter *cf, stream->closed = FALSE; stream->reset = FALSE; - infof(data, "Using HTTP/3 Stream ID: %" PRId64, stream3_id); - CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] opened for %s", - stream3_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].name_len, nva[i].name, + (int)nva[i].value_len, nva[i].value); + } + } out: free(nva); @@ -1030,7 +1065,7 @@ static ssize_t cf_quiche_send(struct Curl_cfilter *cf, struct Curl_easy *data, /* TODO: we seem to be blocked on flow control and should HOLD * sending. But when do we open again? */ if(!quiche_conn_stream_writable(ctx->qconn, stream->id, len)) { - CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] send_body(len=%zu) " + CURL_TRC_CF(data, cf, "[%" PRId64 "] send_body(len=%zu) " "-> window exhausted", stream->id, len); stream_send_suspend(cf, data); } @@ -1039,14 +1074,14 @@ static ssize_t cf_quiche_send(struct Curl_cfilter *cf, struct Curl_easy *data, goto out; } else if(nwritten == QUICHE_H3_TRANSPORT_ERR_FINAL_SIZE) { - CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] send_body(len=%zu) " + CURL_TRC_CF(data, cf, "[%" PRId64 "] send_body(len=%zu) " "-> exceeds size", stream->id, len); *err = CURLE_SEND_ERROR; nwritten = -1; goto out; } else if(nwritten < 0) { - CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] send_body(len=%zu) " + CURL_TRC_CF(data, cf, "[%" PRId64 "] send_body(len=%zu) " "-> quiche err %zd", stream->id, len, nwritten); *err = CURLE_SEND_ERROR; nwritten = -1; @@ -1061,7 +1096,7 @@ static ssize_t cf_quiche_send(struct Curl_cfilter *cf, struct Curl_easy *data, if(stream->upload_left == 0) stream->send_closed = TRUE; - CURL_TRC_CF(data, cf, "[h3sid=%" PRId64 "] send body(len=%zu, " + CURL_TRC_CF(data, cf, "[%" PRId64 "] send body(len=%zu, " "left=%" CURL_FORMAT_CURL_OFF_T ") -> %zd", stream->id, len, stream->upload_left, nwritten); *err = CURLE_OK; @@ -1074,7 +1109,7 @@ out: *err = result; nwritten = -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, nwritten, *err); return nwritten; } @@ -1164,7 +1199,7 @@ static CURLcode cf_quiche_data_event(struct Curl_cfilter *cf, stream->upload_left = 0; body[0] = 'X'; sent = cf_quiche_send(cf, data, body, 0, &result); - CURL_TRC_CF(data, cf, "[h3sid=%"PRId64"] DONE_SEND -> %zd, %d", + CURL_TRC_CF(data, cf, "[%"PRId64"] DONE_SEND -> %zd, %d", stream->id, sent, result); } break; @@ -1291,15 +1326,9 @@ static CURLcode cf_connect_start(struct Curl_cfilter *cf, DEBUGASSERT(!ctx->ssl); DEBUGASSERT(!ctx->sslctx); - ctx->sslctx = quic_ssl_ctx(data); - if(!ctx->sslctx) - return CURLE_QUIC_CONNECT_ERROR; - ctx->ssl = SSL_new(ctx->sslctx); - if(!ctx->ssl) - return CURLE_QUIC_CONNECT_ERROR; - - SSL_set_app_data(ctx->ssl, cf); - SSL_set_tlsext_host_name(ctx->ssl, cf->conn->host.name); + result = quic_ssl_setup(cf, data); + if(result) + return result; result = Curl_rand(data, ctx->scid, sizeof(ctx->scid)); if(result)