From ad1e0c4d507ce08a8d6265b896aef685b7ce952e Mon Sep 17 00:00:00 2001 From: Stefan Eissing Date: Tue, 20 Jun 2023 11:53:19 +0200 Subject: [PATCH 1/4] Merge 1907696,1907697 from trunk: *) mod_http2: new directive 'H2MaxDataFrameLen n' to limit the maximum amount of response body bytes put into a single HTTP/2 DATA frame. Setting this to 0 places no limit (but the max size allowed by the protocol is observed). The module, by default, tries to use the maximum size possible, which is somewhat around 16KB. This sets the maximum. When less response data is available, smaller frames will be sent. --- changes-entries/h2_max_data_frame_len.txt | 7 +++++++ modules/http2/h2_config.c | 22 ++++++++++++++++++++ modules/http2/h2_config.h | 1 + modules/http2/h2_session.c | 9 +++++--- modules/http2/h2_session.h | 3 ++- modules/http2/h2_stream.c | 5 +++++ modules/http2/h2_switch.c | 5 +++-- modules/http2/h2_version.h | 4 ++-- test/modules/http2/test_107_frame_lengths.py | 2 -- 9 files changed, 48 insertions(+), 10 deletions(-) create mode 100644 changes-entries/h2_max_data_frame_len.txt diff --git a/changes-entries/h2_max_data_frame_len.txt b/changes-entries/h2_max_data_frame_len.txt new file mode 100644 index 00000000000..f32f6e076e4 --- /dev/null +++ b/changes-entries/h2_max_data_frame_len.txt @@ -0,0 +1,7 @@ + *) mod_http2: new directive 'H2MaxDataFrameLen n' to limit the maximum + amount of response body bytes put into a single HTTP/2 DATA frame. + Setting this to 0 places no limit (but the max size allowed by the + protocol is observed). + The module, by default, tries to use the maximum size possible, which is + somewhat around 16KB. This sets the maximum. When less response data is + available, smaller frames will be sent. diff --git a/modules/http2/h2_config.c b/modules/http2/h2_config.c index eea4be2c595..f6dd1065dbb 100644 --- a/modules/http2/h2_config.c +++ b/modules/http2/h2_config.c @@ -75,6 +75,7 @@ typedef struct h2_config { int padding_always; int output_buffered; apr_interval_time_t stream_timeout;/* beam timeout */ + int max_data_frame_len; /* max # bytes in a single h2 DATA frame */ } h2_config; typedef struct h2_dir_config { @@ -110,6 +111,7 @@ static h2_config defconf = { 1, /* padding always */ 1, /* stream output buffered */ -1, /* beam timeout */ + 0, /* max DATA frame len, 0 == no extra limit */ }; static h2_dir_config defdconf = { @@ -153,6 +155,7 @@ void *h2_config_create_svr(apr_pool_t *pool, server_rec *s) conf->padding_always = DEF_VAL; conf->output_buffered = DEF_VAL; conf->stream_timeout = DEF_VAL; + conf->max_data_frame_len = DEF_VAL; return conf; } @@ -195,6 +198,7 @@ static void *h2_config_merge(apr_pool_t *pool, void *basev, void *addv) n->padding_bits = H2_CONFIG_GET(add, base, padding_bits); n->padding_always = H2_CONFIG_GET(add, base, padding_always); n->stream_timeout = H2_CONFIG_GET(add, base, stream_timeout); + n->max_data_frame_len = H2_CONFIG_GET(add, base, max_data_frame_len); return n; } @@ -278,6 +282,8 @@ static apr_int64_t h2_srv_config_geti64(const h2_config *conf, h2_config_var_t v return H2_CONFIG_GET(conf, &defconf, output_buffered); case H2_CONF_STREAM_TIMEOUT: return H2_CONFIG_GET(conf, &defconf, stream_timeout); + case H2_CONF_MAX_DATA_FRAME_LEN: + return H2_CONFIG_GET(conf, &defconf, max_data_frame_len); default: return DEF_VAL; } @@ -337,6 +343,9 @@ static void h2_srv_config_seti(h2_config *conf, h2_config_var_t var, int val) case H2_CONF_OUTPUT_BUFFER: H2_CONFIG_SET(conf, output_buffered, val); break; + case H2_CONF_MAX_DATA_FRAME_LEN: + H2_CONFIG_SET(conf, max_data_frame_len, val); + break; default: break; } @@ -583,6 +592,17 @@ static const char *h2_conf_set_stream_max_mem_size(cmd_parms *cmd, return NULL; } +static const char *h2_conf_set_max_data_frame_len(cmd_parms *cmd, + void *dirconf, const char *value) +{ + int val = (int)apr_atoi64(value); + if (val < 0) { + return "value must be 0 or larger"; + } + CONFIG_CMD_SET(cmd, dirconf, H2_CONF_MAX_DATA_FRAME_LEN, val); + return NULL; +} + static const char *h2_conf_set_session_extra_files(cmd_parms *cmd, void *dirconf, const char *value) { @@ -937,6 +957,8 @@ const command_rec h2_cmds[] = { RSRC_CONF, "set stream output buffer on/off"), AP_INIT_TAKE1("H2StreamTimeout", h2_conf_set_stream_timeout, NULL, RSRC_CONF, "set stream timeout"), + AP_INIT_TAKE1("H2MaxDataFrameLen", h2_conf_set_max_data_frame_len, NULL, + RSRC_CONF, "maximum number of bytes in a single HTTP/2 DATA frame"), AP_END_CMD }; diff --git a/modules/http2/h2_config.h b/modules/http2/h2_config.h index 6d2e65f926a..018be648830 100644 --- a/modules/http2/h2_config.h +++ b/modules/http2/h2_config.h @@ -43,6 +43,7 @@ typedef enum { H2_CONF_PADDING_ALWAYS, H2_CONF_OUTPUT_BUFFER, H2_CONF_STREAM_TIMEOUT, + H2_CONF_MAX_DATA_FRAME_LEN, } h2_config_var_t; struct apr_hash_t; diff --git a/modules/http2/h2_session.c b/modules/http2/h2_session.c index 7ba49cf8d5e..1d99ae61f2c 100644 --- a/modules/http2/h2_session.c +++ b/modules/http2/h2_session.c @@ -902,7 +902,8 @@ apr_status_t h2_session_create(h2_session **psession, conn_rec *c, request_rec * session->max_stream_count = h2_config_sgeti(s, H2_CONF_MAX_STREAMS); session->max_stream_mem = h2_config_sgeti(s, H2_CONF_STREAM_MAX_MEM); - + session->max_data_frame_len = h2_config_sgeti(s, H2_CONF_MAX_DATA_FRAME_LEN); + session->out_c1_blocked = h2_iq_create(session->pool, (int)session->max_stream_count); session->ready_to_process = h2_iq_create(session->pool, (int)session->max_stream_count); @@ -983,13 +984,15 @@ apr_status_t h2_session_create(h2_session **psession, conn_rec *c, request_rec * H2_SSSN_LOG(APLOGNO(03200), session, "created, max_streams=%d, stream_mem=%d, " "workers_limit=%d, workers_max=%d, " - "push_diary(type=%d,N=%d)"), + "push_diary(type=%d,N=%d), " + "max_data_frame_len=%d"), (int)session->max_stream_count, (int)session->max_stream_mem, session->mplx->processing_limit, session->mplx->processing_max, session->push_diary->dtype, - (int)session->push_diary->N); + (int)session->push_diary->N, + (int)session->max_data_frame_len); } apr_pool_pre_cleanup_register(pool, c, session_pool_cleanup); diff --git a/modules/http2/h2_session.h b/modules/http2/h2_session.h index fbddfdd2a36..3328509de8a 100644 --- a/modules/http2/h2_session.h +++ b/modules/http2/h2_session.h @@ -103,7 +103,8 @@ typedef struct h2_session { apr_size_t max_stream_count; /* max number of open streams */ apr_size_t max_stream_mem; /* max buffer memory for a single stream */ - + apr_size_t max_data_frame_len; /* max amount of bytes for a single DATA frame */ + apr_size_t idle_frames; /* number of rcvd frames that kept session in idle state */ apr_interval_time_t idle_delay; /* Time we delay processing rcvd frames in idle state */ diff --git a/modules/http2/h2_stream.c b/modules/http2/h2_stream.c index cf6f79897dd..c514df64994 100644 --- a/modules/http2/h2_stream.c +++ b/modules/http2/h2_stream.c @@ -1361,6 +1361,11 @@ static ssize_t stream_data_cb(nghttp2_session *ng2s, length = chunk_len; } } + /* We allow configurable max DATA frame length. */ + if (stream->session->max_data_frame_len > 0 + && length > stream->session->max_data_frame_len) { + length = stream->session->max_data_frame_len; + } /* How much data do we have in our buffers that we can write? * if not enough, receive more. */ diff --git a/modules/http2/h2_switch.c b/modules/http2/h2_switch.c index a30f27ce9d9..3799701723c 100644 --- a/modules/http2/h2_switch.c +++ b/modules/http2/h2_switch.c @@ -104,9 +104,10 @@ static int h2_protocol_propose(conn_rec *c, request_rec *r, /* We also allow switching only for requests that have no body. */ p = apr_table_get(r->headers_in, "Content-Length"); - if (p && strcmp(p, "0")) { + if ((p && strcmp(p, "0")) + || (!p && apr_table_get(r->headers_in, "Transfer-Encoding"))) { ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, APLOGNO(03087) - "upgrade with content-length: %s, declined", p); + "upgrade with body declined"); return DECLINED; } } diff --git a/modules/http2/h2_version.h b/modules/http2/h2_version.h index c9610899015..380818bbc41 100644 --- a/modules/http2/h2_version.h +++ b/modules/http2/h2_version.h @@ -27,7 +27,7 @@ * @macro * Version number of the http2 module as c string */ -#define MOD_HTTP2_VERSION "2.0.11" +#define MOD_HTTP2_VERSION "2.0.13" /** * @macro @@ -35,7 +35,7 @@ * release. This is a 24 bit number with 8 bits for major number, 8 bits * for minor and 8 bits for patch. Version 1.2.3 becomes 0x010203. */ -#define MOD_HTTP2_VERSION_NUM 0x02000b +#define MOD_HTTP2_VERSION_NUM 0x02000d #endif /* mod_h2_h2_version_h */ diff --git a/test/modules/http2/test_107_frame_lengths.py b/test/modules/http2/test_107_frame_lengths.py index f53f8eb9bff..d6360939bea 100644 --- a/test/modules/http2/test_107_frame_lengths.py +++ b/test/modules/http2/test_107_frame_lengths.py @@ -32,8 +32,6 @@ def _class_scope(self, env): 99, 1024, 8192 ]) def test_h2_107_01(self, env, data_frame_len): - if not env.httpd_is_at_least('2.5.0'): - pytest.skip(f'needs r1907696+r1907697 from trunk') conf = H2Conf(env, extras={ f'cgi.{env.http_tld}': [ f'H2MaxDataFrameLen {data_frame_len}', From 930268233c82885e62f7d1476b5b5b35c3f71a9a Mon Sep 17 00:00:00 2001 From: Stefan Eissing Date: Tue, 20 Jun 2023 12:06:47 +0200 Subject: [PATCH 2/4] Merge r1909769 from trunk (plus sync mod_http2.xml) *) mod_http2: v2.0.15 with the following fixes and improvements - New directive 'H2EarlyHint name value' to add headers to a response, picked up already when a "103 Early Hints" response is sent. 'name' and 'value' must comply to the HTTP field restrictions. This directive can be repeated several times and header fields of the same names add. Sending a 'Link' header with 'preload' relation will also cause a HTTP/2 PUSH if enabled and supported by the client. - Fixed an issue where requests were not logged and accounted in a timely fashion when the connection returns to "keepalive" handling, e.g. when the request served was the last outstanding one. This led to late appearance in access logs with wrong duration times reported. - Accurately report the bytes sent for a request in the '%O' Log format. This addresses #203, a long outstanding issue where mod_h2 has reported numbers over-eagerly from internal buffering and not what has actually been placed on the connection. The numbers are now the same with and without H2CopyFiles enabled. --- changes-entries/h2_early_hints_and_fixes.txt | 18 +++ docs/manual/mod/mod_http2.xml | 78 ++++++++++ modules/http2/h2_bucket_beam.c | 20 +++ modules/http2/h2_bucket_beam.h | 1 + modules/http2/h2_c2.c | 115 ++++++++------- modules/http2/h2_c2_filter.c | 4 +- modules/http2/h2_config.c | 62 ++++++++ modules/http2/h2_config.h | 1 + modules/http2/h2_conn_ctx.h | 1 + modules/http2/h2_headers.c | 3 + modules/http2/h2_mplx.c | 15 +- modules/http2/h2_mplx.h | 8 ++ modules/http2/h2_request.c | 16 ++- modules/http2/h2_session.c | 3 +- modules/http2/h2_stream.c | 6 + modules/http2/h2_version.h | 4 +- test/modules/http2/test_008_ranges.py | 144 +++++++++++++++++++ test/modules/http2/test_009_timing.py | 74 ++++++++++ test/modules/http2/test_500_proxy.py | 6 + 19 files changed, 516 insertions(+), 63 deletions(-) create mode 100644 changes-entries/h2_early_hints_and_fixes.txt diff --git a/changes-entries/h2_early_hints_and_fixes.txt b/changes-entries/h2_early_hints_and_fixes.txt new file mode 100644 index 00000000000..74e57315e52 --- /dev/null +++ b/changes-entries/h2_early_hints_and_fixes.txt @@ -0,0 +1,18 @@ + *) mod_http2: v2.0.15 with the following fixes and improvements + - New directive 'H2EarlyHint name value' to add headers to a response, + picked up already when a "103 Early Hints" response is sent. 'name' and + 'value' must comply to the HTTP field restrictions. + This directive can be repeated several times and header fields of the + same names add. Sending a 'Link' header with 'preload' relation will + also cause a HTTP/2 PUSH if enabled and supported by the client. + - Fixed an issue where requests were not logged and accounted in a timely + fashion when the connection returns to "keepalive" handling, e.g. when + the request served was the last outstanding one. + This led to late appearance in access logs with wrong duration times + reported. + - Accurately report the bytes sent for a request in the '%O' Log format. + This addresses #203, a long outstanding issue where mod_h2 has reported + numbers over-eagerly from internal buffering and not what has actually + been placed on the connection. + The numbers are now the same with and without H2CopyFiles enabled. + [Stefan Eissing] diff --git a/docs/manual/mod/mod_http2.xml b/docs/manual/mod/mod_http2.xml index 2df6af2a002..0703bc0cf61 100644 --- a/docs/manual/mod/mod_http2.xml +++ b/docs/manual/mod/mod_http2.xml @@ -1002,4 +1002,82 @@ H2TLSCoolDownSecs 0 + + H2StreamTimeout + Maximum time waiting when sending/receiving data to stream processing + H2StreamTimeout time-interval[s] + Value of Timeout + + server config + virtual host + directory + + Available in version 2.5.1 and later. + + +

+ H2StreamTimeout specifies the maximum time that + a stream being processed will wait for its data to be sent/received. +

+
+
+ + + H2MaxDataFrameLen + Maximum bytes inside a single HTTP/2 DATA frame + H2MaxDataFrameLen n + H2MaxDataFrameLen 0 + + server config + virtual host + + Available in version 2.5.1 and later. + + +

+ H2MaxDataFrameLen limits the maximum + amount of response body bytes placed into a single HTTP/2 DATA + frame. Setting this to 0 places no limit (but the max size + allowed by the protocol is observed). +

+ The module, by default, tries to use the maximum size possible, + which is somewhat around 16KB. This sets the maximum. When less + response data is availble, smaller frames will be sent. +

+
+
+ + + H2EarlyHint + Add a response header to be picked up in 103 Early Hints + H2EarlyHint name value + + server config + virtual host + directory + .htaccess + + Available in version 2.5.1 and later. + + +

+ H2EarlyHint allows adding a response + header before the real request processing is started. Such headers + are picked up for "103 Early Hints" intermediate responses. The main + purpose is to send "preload" information to client browsers. +

+ name and value must be valid HTTP header fields + or will lead to failed responses. H2EarlyHints + must still be enabled to allow 103 intermediate responses to be sent. + This directive can be repeated several times and header fields of the + same names add. +

+ Example + +H2EarlyHint Link "</my.css>;rel=preload;as=style" + + +
+
+ diff --git a/modules/http2/h2_bucket_beam.c b/modules/http2/h2_bucket_beam.c index cbf7f348da7..2bf4fdd2cd7 100644 --- a/modules/http2/h2_bucket_beam.c +++ b/modules/http2/h2_bucket_beam.c @@ -24,6 +24,7 @@ #include #include +#include #include #include "h2_private.h" @@ -156,6 +157,23 @@ static void purge_consumed_buckets(h2_bucket_beam *beam) * from sender thread only */ while (!H2_BLIST_EMPTY(&beam->buckets_consumed)) { b = H2_BLIST_FIRST(&beam->buckets_consumed); + if(AP_BUCKET_IS_EOR(b)) { + APR_BUCKET_REMOVE(b); + H2_BLIST_INSERT_TAIL(&beam->buckets_eor, b); + } + else { + apr_bucket_delete(b); + } + } +} + +static void purge_eor_buckets(h2_bucket_beam *beam) +{ + apr_bucket *b; + /* delete all sender buckets in purge brigade, needs to be called + * from sender thread only */ + while (!H2_BLIST_EMPTY(&beam->buckets_eor)) { + b = H2_BLIST_FIRST(&beam->buckets_eor); apr_bucket_delete(b); } } @@ -263,6 +281,7 @@ static apr_status_t beam_cleanup(void *data) { h2_bucket_beam *beam = data; beam_shutdown(beam, APR_SHUTDOWN_READWRITE); + purge_eor_buckets(beam); beam->pool = NULL; /* the pool is clearing now */ return APR_SUCCESS; } @@ -295,6 +314,7 @@ apr_status_t h2_beam_create(h2_bucket_beam **pbeam, conn_rec *from, H2_BLIST_INIT(&beam->buckets_to_send); H2_BLIST_INIT(&beam->buckets_consumed); + H2_BLIST_INIT(&beam->buckets_eor); beam->tx_mem_limits = 1; beam->max_buf_size = max_buf_size; beam->timeout = timeout; diff --git a/modules/http2/h2_bucket_beam.h b/modules/http2/h2_bucket_beam.h index 2a9d5f0f018..94e788a03e8 100644 --- a/modules/http2/h2_bucket_beam.h +++ b/modules/http2/h2_bucket_beam.h @@ -48,6 +48,7 @@ struct h2_bucket_beam { apr_pool_t *pool; h2_blist buckets_to_send; h2_blist buckets_consumed; + h2_blist buckets_eor; apr_size_t max_buf_size; apr_interval_time_t timeout; diff --git a/modules/http2/h2_c2.c b/modules/http2/h2_c2.c index 4553d3a48de..0c2edba55bf 100644 --- a/modules/http2/h2_c2.c +++ b/modules/http2/h2_c2.c @@ -133,10 +133,22 @@ apr_status_t h2_c2_child_init(apr_pool_t *pool, server_rec *s) APR_PROTO_TCP, pool); } +static void h2_c2_log_io(conn_rec *c2, apr_off_t bytes_sent) +{ + if (bytes_sent && h2_c_logio_add_bytes_out) { + h2_c_logio_add_bytes_out(c2, bytes_sent); + } +} + void h2_c2_destroy(conn_rec *c2) { + h2_conn_ctx_t *conn_ctx = h2_conn_ctx_get(c2); + ap_log_cerror(APLOG_MARK, APLOG_TRACE3, 0, c2, "h2_c2(%s): destroy", c2->log_id); + if(!c2->aborted && conn_ctx && conn_ctx->bytes_sent) { + h2_c2_log_io(c2, conn_ctx->bytes_sent); + } apr_pool_destroy(c2->pool); } @@ -146,6 +158,10 @@ void h2_c2_abort(conn_rec *c2, conn_rec *from) AP_DEBUG_ASSERT(conn_ctx); AP_DEBUG_ASSERT(conn_ctx->stream_id); + if(!c2->aborted && conn_ctx->bytes_sent) { + h2_c2_log_io(c2, conn_ctx->bytes_sent); + } + if (conn_ctx->beam_in) { h2_beam_abort(conn_ctx->beam_in, from); } @@ -326,42 +342,13 @@ static apr_status_t h2_c2_filter_in(ap_filter_t* f, static apr_status_t beam_out(conn_rec *c2, h2_conn_ctx_t *conn_ctx, apr_bucket_brigade* bb) { - apr_off_t written, header_len = 0; + apr_off_t written = 0; apr_status_t rv; - if (h2_c_logio_add_bytes_out) { - /* mod_logio wants to report the number of bytes written in a - * response, including header and footer fields. Since h2 converts - * those during c1 processing into the HPACKed h2 HEADER frames, - * we need to give mod_logio something here and count just the - * raw lengths of all headers in the buckets. */ - apr_bucket *b; - for (b = APR_BRIGADE_FIRST(bb); - b != APR_BRIGADE_SENTINEL(bb); - b = APR_BUCKET_NEXT(b)) { -#if AP_HAS_RESPONSE_BUCKETS - if (AP_BUCKET_IS_RESPONSE(b)) { - header_len += (apr_off_t)response_length_estimate(b->data); - } - if (AP_BUCKET_IS_HEADERS(b)) { - header_len += (apr_off_t)headers_length_estimate(b->data); - } -#else - if (H2_BUCKET_IS_HEADERS(b)) { - header_len += (apr_off_t)h2_bucket_headers_headers_length(b); - } -#endif /* AP_HAS_RESPONSE_BUCKETS */ - } - } - rv = h2_beam_send(conn_ctx->beam_out, c2, bb, APR_BLOCK_READ, &written); - if (APR_STATUS_IS_EAGAIN(rv)) { rv = APR_SUCCESS; } - if (written && h2_c_logio_add_bytes_out) { - h2_c_logio_add_bytes_out(c2, written + header_len); - } return rv; } @@ -403,30 +390,56 @@ static apr_status_t h2_c2_filter_out(ap_filter_t* f, apr_bucket_brigade* bb) return rv; } -static void check_push(request_rec *r, const char *tag) +static int addn_headers(void *udata, const char *name, const char *value) { - apr_array_header_t *push_list = h2_config_push_list(r); + apr_table_t *dest = udata; + apr_table_addn(dest, name, value); + return 1; +} - if (!r->expecting_100 && push_list && push_list->nelts > 0) { - int i, old_status; - const char *old_line; +static void check_early_hints(request_rec *r, const char *tag) +{ + apr_array_header_t *push_list = h2_config_push_list(r); + apr_table_t *early_headers = h2_config_early_headers(r); + + if (!r->expecting_100 && + ((push_list && push_list->nelts > 0) || + (early_headers && !apr_is_empty_table(early_headers)))) { + int have_hints = 0, i; + + if (push_list && push_list->nelts > 0) { + ap_log_rerror(APLOG_MARK, APLOG_TRACE1, 0, r, + "%s, early announcing %d resources for push", + tag, push_list->nelts); + for (i = 0; i < push_list->nelts; ++i) { + h2_push_res *push = &APR_ARRAY_IDX(push_list, i, h2_push_res); + apr_table_add(r->headers_out, "Link", + apr_psprintf(r->pool, "<%s>; rel=preload%s", + push->uri_ref, push->critical? "; critical" : "")); + } + have_hints = 1; + } + if (early_headers && !apr_is_empty_table(early_headers)) { + apr_table_do(addn_headers, r->headers_out, early_headers, NULL); + have_hints = 1; + } - ap_log_rerror(APLOG_MARK, APLOG_TRACE1, 0, r, - "%s, early announcing %d resources for push", - tag, push_list->nelts); - for (i = 0; i < push_list->nelts; ++i) { - h2_push_res *push = &APR_ARRAY_IDX(push_list, i, h2_push_res); - apr_table_add(r->headers_out, "Link", - apr_psprintf(r->pool, "<%s>; rel=preload%s", - push->uri_ref, push->critical? "; critical" : "")); + if (have_hints) { + int old_status; + const char *old_line; + + if (h2_config_rgeti(r, H2_CONF_PUSH) == 0 && + h2_config_sgeti(r->server, H2_CONF_PUSH) != 0) { + apr_table_setn(r->connection->notes, H2_PUSH_MODE_NOTE, "0"); + } + old_status = r->status; + old_line = r->status_line; + r->status = 103; + r->status_line = "103 Early Hints"; + ap_send_interim_response(r, 1); + r->status = old_status; + r->status_line = old_line; } - old_status = r->status; - old_line = r->status_line; - r->status = 103; - r->status_line = "103 Early Hints"; - ap_send_interim_response(r, 1); - r->status = old_status; - r->status_line = old_line; } } @@ -439,7 +452,7 @@ static int c2_hook_fixups(request_rec *r) return DECLINED; } - check_push(r, "late_fixup"); + check_early_hints(r, "late_fixup"); return DECLINED; } diff --git a/modules/http2/h2_c2_filter.c b/modules/http2/h2_c2_filter.c index 37254fc1d7b..5b1838b7730 100644 --- a/modules/http2/h2_c2_filter.c +++ b/modules/http2/h2_c2_filter.c @@ -511,10 +511,10 @@ static apr_status_t pass_response(h2_conn_ctx_t *conn_ctx, ap_filter_t *f, { apr_bucket *b; apr_status_t status; - h2_headers *response = h2_headers_create(parser->http_status, make_table(parser), - NULL, 0, parser->pool); + parser->c->notes, + 0, parser->pool); apr_brigade_cleanup(parser->tmp); b = h2_bucket_headers_create(parser->c->bucket_alloc, response); APR_BRIGADE_INSERT_TAIL(parser->tmp, b); diff --git a/modules/http2/h2_config.c b/modules/http2/h2_config.c index f6dd1065dbb..670833ec129 100644 --- a/modules/http2/h2_config.c +++ b/modules/http2/h2_config.c @@ -70,6 +70,7 @@ typedef struct h2_config { int push_diary_size; /* # of entries in push diary */ int copy_files; /* if files shall be copied vs setaside on output */ apr_array_header_t *push_list; /* list of h2_push_res configurations */ + apr_table_t *early_headers; /* HTTP headers for a 103 response */ int early_hints; /* support status code 103 */ int padding_bits; int padding_always; @@ -83,6 +84,7 @@ typedef struct h2_dir_config { int h2_upgrade; /* Allow HTTP/1 upgrade to h2/h2c */ int h2_push; /* if HTTP/2 server push is enabled */ apr_array_header_t *push_list; /* list of h2_push_res configurations */ + apr_table_t *early_headers; /* HTTP headers for a 103 response */ int early_hints; /* support status code 103 */ apr_interval_time_t stream_timeout;/* beam timeout */ } h2_dir_config; @@ -106,6 +108,7 @@ static h2_config defconf = { 256, /* push diary size */ 0, /* copy files across threads */ NULL, /* push list */ + NULL, /* early headers */ 0, /* early hints, http status 103 */ 0, /* padding bits */ 1, /* padding always */ @@ -119,6 +122,7 @@ static h2_dir_config defdconf = { -1, /* HTTP/1 Upgrade support */ -1, /* HTTP/2 server push enabled */ NULL, /* push list */ + NULL, /* early headers */ -1, /* early hints, http status 103 */ -1, /* beam timeout */ }; @@ -150,6 +154,7 @@ void *h2_config_create_svr(apr_pool_t *pool, server_rec *s) conf->push_diary_size = DEF_VAL; conf->copy_files = DEF_VAL; conf->push_list = NULL; + conf->early_headers = NULL; conf->early_hints = DEF_VAL; conf->padding_bits = DEF_VAL; conf->padding_always = DEF_VAL; @@ -194,6 +199,12 @@ static void *h2_config_merge(apr_pool_t *pool, void *basev, void *addv) else { n->push_list = add->push_list? add->push_list : base->push_list; } + if (add->early_headers && base->early_headers) { + n->early_headers = apr_table_overlay(pool, add->early_headers, base->early_headers); + } + else { + n->early_headers = add->early_headers? add->early_headers : base->early_headers; + } n->early_hints = H2_CONFIG_GET(add, base, early_hints); n->padding_bits = H2_CONFIG_GET(add, base, padding_bits); n->padding_always = H2_CONFIG_GET(add, base, padding_always); @@ -236,6 +247,12 @@ void *h2_config_merge_dir(apr_pool_t *pool, void *basev, void *addv) else { n->push_list = add->push_list? add->push_list : base->push_list; } + if (add->early_headers && base->early_headers) { + n->early_headers = apr_table_overlay(pool, add->early_headers, base->early_headers); + } + else { + n->early_headers = add->early_headers? add->early_headers : base->early_headers; + } n->early_hints = H2_CONFIG_GET(add, base, early_hints); n->stream_timeout = H2_CONFIG_GET(add, base, stream_timeout); return n; @@ -511,6 +528,18 @@ apr_array_header_t *h2_config_push_list(request_rec *r) return sconf? sconf->push_list : NULL; } +apr_table_t *h2_config_early_headers(request_rec *r) +{ + const h2_config *sconf; + const h2_dir_config *conf = h2_config_rget(r); + + if (conf && conf->early_headers) { + return conf->early_headers; + } + sconf = h2_config_sget(r->server); + return sconf? sconf->early_headers : NULL; +} + const struct h2_priority *h2_cconfig_get_priority(conn_rec *c, const char *content_type) { const h2_config *conf = h2_config_get(c); @@ -832,6 +861,37 @@ static const char *h2_conf_add_push_res(cmd_parms *cmd, void *dirconf, return NULL; } +static const char *h2_conf_add_early_hint(cmd_parms *cmd, void *dirconf, + const char *name, const char *value) +{ + apr_table_t *hds, **phds; + + if(!name || !*name) + return "Early Hint header name must not be empty"; + if(!value) + return "Early Hint header value must not be empty"; + while (apr_isspace(*value)) + ++value; + if(!*value) + return "Early Hint header value must not be empty/only space"; + if (*ap_scan_http_field_content(value)) + return "Early Hint header value contains invalid characters"; + + if (cmd->path) { + phds = &((h2_dir_config*)dirconf)->early_headers; + } + else { + phds = &(h2_config_sget(cmd->server))->early_headers; + } + hds = *phds; + if (!hds) { + *phds = hds = apr_table_make(cmd->pool, 10); + } + apr_table_add(hds, name, value); + + return NULL; +} + static const char *h2_conf_set_early_hints(cmd_parms *cmd, void *dirconf, const char *value) { @@ -959,6 +1019,8 @@ const command_rec h2_cmds[] = { RSRC_CONF, "set stream timeout"), AP_INIT_TAKE1("H2MaxDataFrameLen", h2_conf_set_max_data_frame_len, NULL, RSRC_CONF, "maximum number of bytes in a single HTTP/2 DATA frame"), + AP_INIT_TAKE2("H2EarlyHint", h2_conf_add_early_hint, NULL, + OR_FILEINFO|OR_AUTHCFG, "add a a 'Link:' header for a 103 Early Hints response."), AP_END_CMD }; diff --git a/modules/http2/h2_config.h b/modules/http2/h2_config.h index 018be648830..5a783712848 100644 --- a/modules/http2/h2_config.h +++ b/modules/http2/h2_config.h @@ -87,6 +87,7 @@ int h2_config_rgeti(request_rec *r, h2_config_var_t var); apr_int64_t h2_config_rgeti64(request_rec *r, h2_config_var_t var); apr_array_header_t *h2_config_push_list(request_rec *r); +apr_table_t *h2_config_early_headers(request_rec *r); void h2_get_workers_config(server_rec *s, int *pminw, int *pmaxw, diff --git a/modules/http2/h2_conn_ctx.h b/modules/http2/h2_conn_ctx.h index 35987bce3f6..90dc9f627dd 100644 --- a/modules/http2/h2_conn_ctx.h +++ b/modules/http2/h2_conn_ctx.h @@ -61,6 +61,7 @@ struct h2_conn_ctx_t { int has_final_response; /* final HTTP response passed on out */ apr_status_t last_err; /* APR_SUCCES or last error encountered in filters */ + apr_off_t bytes_sent; /* c2: bytes acutaly sent via c1 */ /* atomic */ apr_uint32_t started; /* c2: processing was started */ apr_time_t started_at; /* c2: when processing started */ /* atomic */ apr_uint32_t done; /* c2: processing has finished */ diff --git a/modules/http2/h2_headers.c b/modules/http2/h2_headers.c index cbc7b01a342..0fc1d91d6a2 100644 --- a/modules/http2/h2_headers.c +++ b/modules/http2/h2_headers.c @@ -144,6 +144,9 @@ h2_headers *h2_headers_rcreate(request_rec *r, int status, const apr_table_t *header, apr_pool_t *pool) { h2_headers *headers = h2_headers_create(status, header, r->notes, 0, pool); + ap_log_rerror(APLOG_MARK, APLOG_TRACE1, headers->status, r, + "h2_headers_rcreate(%ld): status=%d", + (long)r->connection->id, status); if (headers->status == HTTP_FORBIDDEN) { request_rec *r_prev; for (r_prev = r; r_prev != NULL; r_prev = r_prev->prev) { diff --git a/modules/http2/h2_mplx.c b/modules/http2/h2_mplx.c index 99c47ea8ef9..6e2d5776f2f 100644 --- a/modules/http2/h2_mplx.c +++ b/modules/http2/h2_mplx.c @@ -441,6 +441,8 @@ static int m_stream_cancel_iter(void *ctx, void *val) { return 0; } +static void c1_purge_streams(h2_mplx *m); + void h2_mplx_c1_destroy(h2_mplx *m) { apr_status_t status; @@ -509,7 +511,9 @@ void h2_mplx_c1_destroy(h2_mplx *m) h2_ihash_count(m->shold)); h2_ihash_iter(m->shold, m_unexpected_stream_iter, m); } - + + c1_purge_streams(m); + m->c1->aborted = old_aborted; H2_MPLX_LEAVE(m); @@ -585,6 +589,15 @@ static void c1_purge_streams(h2_mplx *m) apr_array_clear(m->spurge); } +void h2_mplx_c1_going_keepalive(h2_mplx *m) +{ + H2_MPLX_ENTER_ALWAYS(m); + if (m->spurge->nelts) { + c1_purge_streams(m); + } + H2_MPLX_LEAVE(m); +} + apr_status_t h2_mplx_c1_poll(h2_mplx *m, apr_interval_time_t timeout, stream_ev_callback *on_stream_input, stream_ev_callback *on_stream_output, diff --git a/modules/http2/h2_mplx.h b/modules/http2/h2_mplx.h index 1f79aa8248a..ecb4de9cc6f 100644 --- a/modules/http2/h2_mplx.h +++ b/modules/http2/h2_mplx.h @@ -212,6 +212,14 @@ const struct h2_stream *h2_mplx_c2_stream_get(h2_mplx *m, int stream_id); */ apr_status_t h2_mplx_worker_pop_c2(h2_mplx *m, conn_rec **out_c2); + +/** + * Session processing is entering KEEPALIVE, e.g. giving control + * to the MPM for monitoring incoming socket events only. + * Last chance for maintenance work before losing control. + */ +void h2_mplx_c1_going_keepalive(h2_mplx *m); + #define H2_MPLX_MSG(m, msg) \ "h2_mplx(%d-%lu): "msg, m->child_num, (unsigned long)m->id diff --git a/modules/http2/h2_request.c b/modules/http2/h2_request.c index 20e94cd8a3c..00436aa762b 100644 --- a/modules/http2/h2_request.c +++ b/modules/http2/h2_request.c @@ -304,6 +304,7 @@ static void assign_headers(request_rec *r, const h2_request *req, const char *cl; r->headers_in = apr_table_clone(r->pool, req->headers); + if (req->authority) { /* for internal handling, we have to simulate that :authority * came in as Host:, RFC 9113 ch. says that mismatches between @@ -367,12 +368,15 @@ request_rec *h2_create_request_rec(const h2_request *req, conn_rec *c, /* Time to populate r with the data we have. */ r->request_time = req->request_time; AP_DEBUG_ASSERT(req->authority); - if (req->scheme && (ap_cstr_casecmp(req->scheme, - ap_ssl_conn_is_ssl(c->master? c->master : c)? "https" : "http") - || !ap_cstr_casecmp("CONNECT", req->method))) { - /* Client sent a non-matching ':scheme' pseudo header. Forward this - * via an absolute URI in the request line. - */ + if (!apr_strnatcasecmp("CONNECT", req->method)) { + /* CONNECT MUST NOT have scheme or path */ + r->the_request = apr_psprintf(r->pool, "%s %s HTTP/2.0", + req->method, req->authority); + } + else if (req->scheme && ap_cstr_casecmp(req->scheme, "http") + && ap_cstr_casecmp(req->scheme, "https")) { + /* Client sent a ':scheme' pseudo header for something else + * than what we handle by default. Make an absolute URI. */ r->the_request = apr_psprintf(r->pool, "%s %s://%s%s HTTP/2.0", req->method, req->scheme, req->authority, req->path ? req->path : ""); diff --git a/modules/http2/h2_session.c b/modules/http2/h2_session.c index 1d99ae61f2c..0ede886998f 100644 --- a/modules/http2/h2_session.c +++ b/modules/http2/h2_session.c @@ -1947,7 +1947,8 @@ apr_status_t h2_session_process(h2_session *session, int async) ap_log_cerror( APLOG_MARK, APLOG_TRACE3, status, c, H2_SSSN_MSG(session, "process returns")); } - + h2_mplx_c1_going_keepalive(session->mplx); + if (session->state == H2_SESSION_ST_DONE) { if (session->local.error) { char buffer[128]; diff --git a/modules/http2/h2_stream.c b/modules/http2/h2_stream.c index c514df64994..4127069f82c 100644 --- a/modules/http2/h2_stream.c +++ b/modules/http2/h2_stream.c @@ -435,6 +435,12 @@ apr_status_t h2_stream_send_frame(h2_stream *stream, int ftype, int flags, size_ ++stream->out_frames; stream->out_frame_octets += frame_len; + if(stream->c2) { + h2_conn_ctx_t *conn_ctx = h2_conn_ctx_get(stream->c2); + if(conn_ctx) + conn_ctx->bytes_sent = stream->out_frame_octets; + } + switch (ftype) { case NGHTTP2_DATA: eos = (flags & NGHTTP2_FLAG_END_STREAM); diff --git a/modules/http2/h2_version.h b/modules/http2/h2_version.h index 380818bbc41..e556f038d3f 100644 --- a/modules/http2/h2_version.h +++ b/modules/http2/h2_version.h @@ -27,7 +27,7 @@ * @macro * Version number of the http2 module as c string */ -#define MOD_HTTP2_VERSION "2.0.13" +#define MOD_HTTP2_VERSION "2.0.15" /** * @macro @@ -35,7 +35,7 @@ * release. This is a 24 bit number with 8 bits for major number, 8 bits * for minor and 8 bits for patch. Version 1.2.3 becomes 0x010203. */ -#define MOD_HTTP2_VERSION_NUM 0x02000d +#define MOD_HTTP2_VERSION_NUM 0x02000f #endif /* mod_h2_h2_version_h */ diff --git a/test/modules/http2/test_008_ranges.py b/test/modules/http2/test_008_ranges.py index c0b0fa1389e..ce86399a5d4 100644 --- a/test/modules/http2/test_008_ranges.py +++ b/test/modules/http2/test_008_ranges.py @@ -11,6 +11,150 @@ class TestRanges: LOGFILE = "" + @pytest.fixture(autouse=True, scope='class') + def _class_scope(self, env): + TestRanges.LOGFILE = os.path.join(env.server_logs_dir, "test_008") + TestRanges.SRCDIR = os.path.dirname(inspect.getfile(TestRanges)) + if os.path.isfile(TestRanges.LOGFILE): + os.remove(TestRanges.LOGFILE) + destdir = os.path.join(env.gen_dir, 'apache/htdocs/test1') + env.make_data_file(indir=destdir, fname="data-100m", fsize=100*1024*1024) + conf = H2Conf(env=env) + conf.add([ + "CustomLog logs/test_008 combined" + ]) + conf.add_vhost_cgi() + conf.add_vhost_test1() + conf.install() + assert env.apache_restart() == 0 + + def test_h2_008_01(self, env): + # issue: #203 + resource = "data-1k" + full_length = 1000 + chunk = 200 + self.curl_upload_and_verify(env, resource, ["-v", "--http2"]) + assert env.apache_restart() == 0 + url = env.mkurl("https", "cgi", f"/files/{resource}?01full") + r = env.curl_get(url, 5, options=["--http2"]) + assert r.response["status"] == 200 + url = env.mkurl("https", "cgi", f"/files/{resource}?01range") + r = env.curl_get(url, 5, options=["--http1.1", "-H", "Range: bytes=0-{0}".format(chunk-1)]) + assert 206 == r.response["status"] + assert chunk == len(r.response["body"].decode('utf-8')) + r = env.curl_get(url, 5, options=["--http2", "-H", "Range: bytes=0-{0}".format(chunk-1)]) + assert 206 == r.response["status"] + assert chunk == len(r.response["body"].decode('utf-8')) + # Restart for logs to be flushed out + assert env.apache_restart() == 0 + # now check what response lengths have actually been reported + detected = {} + for line in open(TestRanges.LOGFILE).readlines(): + e = json.loads(line) + if e['request'] == f'GET /files/{resource}?01full HTTP/2.0': + assert e['bytes_rx_I'] > 0 + assert e['bytes_resp_B'] == full_length + assert e['bytes_tx_O'] > full_length + detected['h2full'] = 1 + elif e['request'] == f'GET /files/{resource}?01range HTTP/2.0': + assert e['bytes_rx_I'] > 0 + assert e['bytes_resp_B'] == chunk + assert e['bytes_tx_O'] > chunk + assert e['bytes_tx_O'] < chunk + 256 # response + frame stuff + detected['h2range'] = 1 + elif e['request'] == f'GET /files/{resource}?01range HTTP/1.1': + assert e['bytes_rx_I'] > 0 # input bytes received + assert e['bytes_resp_B'] == chunk # response bytes sent (payload) + assert e['bytes_tx_O'] > chunk # output bytes sent + detected['h1range'] = 1 + assert 'h1range' in detected, f'HTTP/1.1 range request not found in {TestRanges.LOGFILE}' + assert 'h2range' in detected, f'HTTP/2 range request not found in {TestRanges.LOGFILE}' + assert 'h2full' in detected, f'HTTP/2 full request not found in {TestRanges.LOGFILE}' + + def test_h2_008_02(self, env, repeat): + path = '/002.jpg' + res_len = 90364 + url = env.mkurl("https", "test1", f'{path}?02full') + r = env.curl_get(url, 5) + assert r.response["status"] == 200 + assert "HTTP/2" == r.response["protocol"] + h = r.response["header"] + assert "accept-ranges" in h + assert "bytes" == h["accept-ranges"] + assert "content-length" in h + clen = h["content-length"] + assert int(clen) == res_len + # get the first 1024 bytes of the resource, 206 status, but content-length as original + url = env.mkurl("https", "test1", f'{path}?02range') + r = env.curl_get(url, 5, options=["-H", "range: bytes=0-1023"]) + assert 206 == r.response["status"] + assert "HTTP/2" == r.response["protocol"] + assert 1024 == len(r.response["body"]) + assert "content-length" in h + assert clen == h["content-length"] + # Restart for logs to be flushed out + assert env.apache_restart() == 0 + # now check what response lengths have actually been reported + found = False + for line in open(TestRanges.LOGFILE).readlines(): + e = json.loads(line) + if e['request'] == f'GET {path}?02range HTTP/2.0': + assert e['bytes_rx_I'] > 0 + assert e['bytes_resp_B'] == 1024 + assert e['bytes_tx_O'] > 1024 + assert e['bytes_tx_O'] < 1024 + 256 # response and frame stuff + found = True + break + assert found, f'request not found in {self.LOGFILE}' + + # send a paced curl download that aborts in the middle of the transfer + def test_h2_008_03(self, env, repeat): + path = '/data-100m' + url = env.mkurl("https", "test1", f'{path}?03broken') + r = env.curl_get(url, 5, options=[ + '--limit-rate', '2k', '-m', '2' + ]) + assert r.exit_code != 0, f'{r}' + found = False + for line in open(TestRanges.LOGFILE).readlines(): + e = json.loads(line) + if e['request'] == f'GET {path}?03broken HTTP/2.0': + assert e['bytes_rx_I'] > 0 + assert e['bytes_resp_B'] == 100*1024*1024 + assert e['bytes_tx_O'] > 1024 + assert e['bytes_tx_O'] < 5*1024*1024 # curl buffers, but not that much + found = True + break + assert found, f'request not found in {self.LOGFILE}' + + # upload and GET again using curl, compare to original content + def curl_upload_and_verify(self, env, fname, options=None): + url = env.mkurl("https", "cgi", "/upload.py") + fpath = os.path.join(env.gen_dir, fname) + r = env.curl_upload(url, fpath, options=options) + assert r.exit_code == 0, f"{r}" + assert 200 <= r.response["status"] < 300 + + r2 = env.curl_get(r.response["header"]["location"]) + assert r2.exit_code == 0 + assert r2.response["status"] == 200 + with open(os.path.join(TestRanges.SRCDIR, fpath), mode='rb') as file: + src = file.read() + assert src == r2.response["body"] + +import inspect +import json +import os +import pytest + +from .env import H2Conf, H2TestEnv + + +@pytest.mark.skipif(condition=H2TestEnv.is_unsupported, reason="mod_http2 not supported here") +class TestRanges: + + LOGFILE = "" + @pytest.fixture(autouse=True, scope='class') def _class_scope(self, env): TestRanges.LOGFILE = os.path.join(env.server_logs_dir, "test_008") diff --git a/test/modules/http2/test_009_timing.py b/test/modules/http2/test_009_timing.py index eca28bc17fc..d73327c2b3e 100644 --- a/test/modules/http2/test_009_timing.py +++ b/test/modules/http2/test_009_timing.py @@ -6,6 +6,80 @@ from .env import H2Conf, H2TestEnv +@pytest.mark.skipif(condition=H2TestEnv.is_unsupported, reason="mod_http2 not supported here") +class TestTiming: + + LOGFILE = "" + + @pytest.fixture(autouse=True, scope='class') + def _class_scope(self, env): + TestTiming.LOGFILE = os.path.join(env.server_logs_dir, "test_009") + if os.path.isfile(TestTiming.LOGFILE): + os.remove(TestTiming.LOGFILE) + conf = H2Conf(env=env) + conf.add([ + "CustomLog logs/test_009 combined" + ]) + conf.add_vhost_cgi() + conf.add_vhost_test1() + conf.install() + assert env.apache_restart() == 0 + + # check that we get a positive time_taken reported on a simple GET + def test_h2_009_01(self, env): + path = '/002.jpg' + url = env.mkurl("https", "test1", f'{path}?01') + args = [ + env.h2load, "-n", "1", "-c", "1", "-m", "1", + f"--connect-to=localhost:{env.https_port}", + f"--base-uri={url}", url + ] + r = env.run(args) + # Restart for logs to be flushed out + assert env.apache_restart() == 0 + found = False + for line in open(TestTiming.LOGFILE).readlines(): + e = json.loads(line) + if e['request'] == f'GET {path}?01 HTTP/2.0': + assert e['time_taken'] > 0 + found = True + assert found, f'request not found in {TestTiming.LOGFILE}' + + # test issue #253, where time_taken in a keepalive situation is not + # reported until the next request arrives + def test_h2_009_02(self, env): + baseurl = env.mkurl("https", "test1", '/') + tscript = os.path.join(env.gen_dir, 'h2load-timing-009_02') + with open(tscript, 'w') as fd: + fd.write('\n'.join([ + f'0.0\t/002.jpg?02a', # 1st request right away + f'1000.0\t/002.jpg?02b', # 2nd a second later + ])) + args = [ + env.h2load, + f'--timing-script-file={tscript}', + f"--connect-to=localhost:{env.https_port}", + f"--base-uri={baseurl}" + ] + r = env.run(args) + # Restart for logs to be flushed out + assert env.apache_restart() == 0 + found = False + for line in open(TestTiming.LOGFILE).readlines(): + e = json.loads(line) + if e['request'] == f'GET /002.jpg?02a HTTP/2.0': + assert e['time_taken'] > 0 + assert e['time_taken'] < 500 * 1000, f'time for 1st request not reported correctly' + found = True + assert found, f'request not found in {TestTiming.LOGFILE}' +import inspect +import json +import os +import pytest + +from .env import H2Conf, H2TestEnv + + @pytest.mark.skipif(condition=H2TestEnv.is_unsupported, reason="mod_http2 not supported here") class TestTiming: diff --git a/test/modules/http2/test_500_proxy.py b/test/modules/http2/test_500_proxy.py index 88a8ece3f6e..deb123d86b3 100644 --- a/test/modules/http2/test_500_proxy.py +++ b/test/modules/http2/test_500_proxy.py @@ -61,6 +61,12 @@ def test_h2_500_11(self, env): ]) self.curl_upload_and_verify(env, "data-1k", ["--http2", "-H", "Content-Length:"]) + def test_h2_500_11(self, env): + self.curl_upload_and_verify(env, "data-1k", [ + "--http1.1", "-H", "Content-Length:", "-H", "Transfer-Encoding: chunked" + ]) + self.curl_upload_and_verify(env, "data-1k", ["--http2", "-H", "Content-Length:"]) + # POST some data using nghttp and see it echo'ed properly back def nghttp_post_and_verify(self, env, fname, options=None): url = env.mkurl("https", "cgi", "/proxy/echo.py") From 04ed56c01e22ce0f45bdb770e5b51817132ace5a Mon Sep 17 00:00:00 2001 From: Stefan Eissing Date: Tue, 20 Jun 2023 13:05:54 +0200 Subject: [PATCH 3/4] Merge r1910157 from trunk * mod_proxy_http2: fixed using the wrong "bucket_alloc" from the backend connection when sending data on the frontend one. This caused crashes or infinite loops in rare situations. * mod_proxy_http2: fixed a bug in retry/response handling that could lead to wrong status codes or HTTP messages send at the end of response bodies exceeding the announced content-length. * mod_proxy_http2: fix retry handling to not leak temporary errors. On detecting that that an existing connection was shutdown by the other side, a 503 response leaked even though the request was retried on a fresh connection. * mod_http2: fixed a bug that did cleanup of consumed and pending buckets in the wrong order when a bucket_beam was destroyed. --- changes-entries/h2_v2.0.18.txt | 13 ++++ modules/http2/h2_bucket_beam.c | 5 +- modules/http2/h2_proxy_session.c | 71 ++++++++++++++-------- modules/http2/h2_proxy_session.h | 5 +- modules/http2/h2_request.c | 3 + modules/http2/h2_stream.c | 2 + modules/http2/h2_version.h | 4 +- modules/http2/mod_proxy_http2.c | 100 ++++++++++++++++--------------- 8 files changed, 126 insertions(+), 77 deletions(-) create mode 100644 changes-entries/h2_v2.0.18.txt diff --git a/changes-entries/h2_v2.0.18.txt b/changes-entries/h2_v2.0.18.txt new file mode 100644 index 00000000000..38d7f5efe62 --- /dev/null +++ b/changes-entries/h2_v2.0.18.txt @@ -0,0 +1,13 @@ + * mod_proxy_http2: fixed using the wrong "bucket_alloc" from the backend + connection when sending data on the frontend one. This caused crashes + or infinite loops in rare situations. + * mod_proxy_http2: fixed a bug in retry/response handling that could lead + to wrong status codes or HTTP messages send at the end of response bodies + exceeding the announced content-length. + * mod_proxy_http2: fix retry handling to not leak temporary errors. + On detecting that that an existing connection was shutdown by the other + side, a 503 response leaked even though the request was retried on a + fresh connection. + * mod_http2: fixed a bug that did cleanup of consumed and pending buckets in + the wrong order when a bucket_beam was destroyed. + [Stefan Eissing] diff --git a/modules/http2/h2_bucket_beam.c b/modules/http2/h2_bucket_beam.c index 2bf4fdd2cd7..72baea3e337 100644 --- a/modules/http2/h2_bucket_beam.c +++ b/modules/http2/h2_bucket_beam.c @@ -272,8 +272,8 @@ static void beam_shutdown(h2_bucket_beam *beam, apr_shutdown_how_e how) /* shutdown sender (or both)? */ if (how != APR_SHUTDOWN_READ) { - h2_blist_cleanup(&beam->buckets_to_send); purge_consumed_buckets(beam); + h2_blist_cleanup(&beam->buckets_to_send); } } @@ -585,6 +585,9 @@ apr_status_t h2_beam_send(h2_bucket_beam *beam, conn_rec *from, rv = APR_ECONNABORTED; } H2_BEAM_LOG(beam, from, APLOG_TRACE2, rv, "end send", sender_bb); + if(rv != APR_SUCCESS && !APR_STATUS_IS_EAGAIN(rv) && sender_bb != NULL) { + apr_brigade_cleanup(sender_bb); + } apr_thread_mutex_unlock(beam->lock); return rv; } diff --git a/modules/http2/h2_proxy_session.c b/modules/http2/h2_proxy_session.c index 378a1ded693..4835ec3e6cd 100644 --- a/modules/http2/h2_proxy_session.c +++ b/modules/http2/h2_proxy_session.c @@ -37,6 +37,7 @@ typedef struct h2_proxy_stream { const char *url; request_rec *r; + conn_rec *cfront; h2_proxy_request *req; const char *real_server_uri; const char *p_server_uri; @@ -401,7 +402,7 @@ static apr_status_t h2_proxy_stream_add_header_out(h2_proxy_stream *stream, char *s = apr_pstrndup(stream->r->pool, v, vlen); apr_table_setn(stream->r->notes, "proxy-status", s); - ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, stream->session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, stream->cfront, "h2_proxy_stream(%s-%d): got status %s", stream->session->id, stream->id, s); stream->r->status = (int)apr_atoi64(s); @@ -413,7 +414,7 @@ static apr_status_t h2_proxy_stream_add_header_out(h2_proxy_stream *stream, return APR_SUCCESS; } - ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, stream->session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, stream->cfront, "h2_proxy_stream(%s-%d): on_header %s: %s", stream->session->id, stream->id, n, v); if (!h2_proxy_res_ignore_header(n, nlen)) { @@ -425,7 +426,7 @@ static apr_status_t h2_proxy_stream_add_header_out(h2_proxy_stream *stream, h2_proxy_util_camel_case_header(hname, nlen); hvalue = apr_pstrndup(stream->pool, v, vlen); - ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, stream->session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, stream->cfront, "h2_proxy_stream(%s-%d): got header %s: %s", stream->session->id, stream->id, hname, hvalue); process_proxy_header(headers, stream, hname, hvalue); @@ -532,22 +533,21 @@ static int stream_response_data(nghttp2_session *ngh2, uint8_t flags, h2_proxy_stream_end_headers_out(stream); } stream->data_received += len; - - b = apr_bucket_transient_create((const char*)data, len, - stream->r->connection->bucket_alloc); + b = apr_bucket_transient_create((const char*)data, len, + stream->cfront->bucket_alloc); APR_BRIGADE_INSERT_TAIL(stream->output, b); /* always flush after a DATA frame, as we have no other indication * of buffer use */ - b = apr_bucket_flush_create(stream->r->connection->bucket_alloc); + b = apr_bucket_flush_create(stream->cfront->bucket_alloc); APR_BRIGADE_INSERT_TAIL(stream->output, b); - + status = ap_pass_brigade(stream->r->output_filters, stream->output); ap_log_rerror(APLOG_MARK, APLOG_DEBUG, status, stream->r, APLOGNO(03359) "h2_proxy_session(%s): stream=%d, response DATA %ld, %ld" " total", session->id, stream_id, (long)len, (long)stream->data_received); if (status != APR_SUCCESS) { - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, session->c, APLOGNO(03344) + ap_log_rerror(APLOG_MARK, APLOG_DEBUG, status, stream->r, APLOGNO(03344) "h2_proxy_session(%s): passing output on stream %d", session->id, stream->id); nghttp2_submit_rst_stream(ngh2, NGHTTP2_FLAG_NONE, @@ -827,12 +827,13 @@ static apr_status_t open_stream(h2_proxy_session *session, const char *url, stream->pool = r->pool; stream->url = url; stream->r = r; + stream->cfront = r->connection; stream->standalone = standalone; stream->session = session; stream->state = H2_STREAM_ST_IDLE; - stream->input = apr_brigade_create(stream->pool, session->c->bucket_alloc); - stream->output = apr_brigade_create(stream->pool, session->c->bucket_alloc); + stream->input = apr_brigade_create(stream->pool, stream->cfront->bucket_alloc); + stream->output = apr_brigade_create(stream->pool, stream->cfront->bucket_alloc); stream->req = h2_proxy_req_create(1, stream->pool); @@ -856,7 +857,7 @@ static apr_status_t open_stream(h2_proxy_session *session, const char *url, /* port info missing and port is not default for scheme: append */ authority = apr_psprintf(stream->pool, "%s:%d", authority, puri.port); } - ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, stream->cfront, "authority=%s from uri.hostname=%s and uri.port=%d", authority, puri.hostname, puri.port); } @@ -943,7 +944,7 @@ static apr_status_t submit_stream(h2_proxy_session *session, h2_proxy_stream *st rv = nghttp2_submit_request(session->ngh2, NULL, hd->nv, hd->nvlen, pp, stream); - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, APLOGNO(03363) + ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, stream->cfront, APLOGNO(03363) "h2_proxy_session(%s): submit %s%s -> %d", session->id, stream->req->authority, stream->req->path, rv); @@ -1088,7 +1089,7 @@ apr_status_t h2_proxy_session_submit(h2_proxy_session *session, static void stream_resume(h2_proxy_stream *stream) { h2_proxy_session *session = stream->session; - ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, stream->cfront, "h2_proxy_stream(%s-%d): resuming", session->id, stream->id); stream->suspended = 0; @@ -1129,7 +1130,7 @@ static apr_status_t check_suspended(h2_proxy_session *session) return APR_SUCCESS; } else if (status != APR_SUCCESS && !APR_STATUS_IS_EAGAIN(status)) { - ap_log_cerror(APLOG_MARK, APLOG_WARNING, status, session->c, + ap_log_cerror(APLOG_MARK, APLOG_WARNING, status, stream->cfront, APLOGNO(03382) "h2_proxy_stream(%s-%d): check input", session->id, stream_id); stream_resume(stream); @@ -1366,27 +1367,39 @@ static void ev_stream_done(h2_proxy_session *session, int stream_id, /* if the stream's connection is aborted, do not send anything * more on it. */ apr_status_t status = (stream->error_code == 0)? APR_SUCCESS : APR_EINVAL; - int touched = (stream->data_sent || + int touched = (stream->data_sent || stream->data_received || stream_id <= session->last_stream_id); - if (!session->c->aborted) { - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, APLOGNO(03364) + if (!stream->cfront->aborted) { + ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, stream->cfront, APLOGNO(03364) "h2_proxy_sesssion(%s): stream(%d) closed " "(touched=%d, error=%d)", session->id, stream_id, touched, stream->error_code); if (status != APR_SUCCESS) { - /* stream failed, error reporting is done by caller - * of proxy_session, e.g. mod_proxy_http2 which also - * decides about retries. */ + /* stream failed. If we have received (and forwarded) response + * data already, we need to append an error buckt to inform + * consumers. + * Otherwise, we have an early fail on the connection and may + * retry this request on a new one. In that case, keep the + * output virgin so that a new attempt can be made. */ + if (stream->data_received) { + int http_status = ap_map_http_request_error(status, HTTP_BAD_REQUEST); + b = ap_bucket_error_create(http_status, NULL, stream->r->pool, + stream->cfront->bucket_alloc); + APR_BRIGADE_INSERT_TAIL(stream->output, b); + b = apr_bucket_eos_create(stream->cfront->bucket_alloc); + APR_BRIGADE_INSERT_TAIL(stream->output, b); + ap_pass_brigade(stream->r->output_filters, stream->output); + } } else if (!stream->data_received) { /* if the response had no body, this is the time to flush * an empty brigade which will also write the response headers */ h2_proxy_stream_end_headers_out(stream); stream->data_received = 1; - b = apr_bucket_flush_create(stream->r->connection->bucket_alloc); + b = apr_bucket_flush_create(stream->cfront->bucket_alloc); APR_BRIGADE_INSERT_TAIL(stream->output, b); - b = apr_bucket_eos_create(stream->r->connection->bucket_alloc); + b = apr_bucket_eos_create(stream->cfront->bucket_alloc); APR_BRIGADE_INSERT_TAIL(stream->output, b); ap_pass_brigade(stream->r->output_filters, stream->output); } @@ -1396,7 +1409,7 @@ static void ev_stream_done(h2_proxy_session *session, int stream_id, h2_proxy_ihash_remove(session->streams, stream_id); h2_proxy_iq_remove(session->suspended, stream_id); if (session->done) { - session->done(session, stream->r, status, touched); + session->done(session, stream->r, status, touched, stream->error_code); } } @@ -1666,9 +1679,9 @@ static int done_iter(void *udata, void *val) { cleanup_iter_ctx *ctx = udata; h2_proxy_stream *stream = val; - int touched = (stream->data_sent || + int touched = (stream->data_sent || stream->data_received || stream->id <= ctx->session->last_stream_id); - ctx->done(ctx->session, stream->r, APR_ECONNABORTED, touched); + ctx->done(ctx->session, stream->r, APR_ECONNABORTED, touched, stream->error_code); return 1; } @@ -1687,6 +1700,12 @@ void h2_proxy_session_cleanup(h2_proxy_session *session, } } +int h2_proxy_session_is_reusable(h2_proxy_session *session) +{ + return (session->state != H2_PROXYS_ST_DONE) && + h2_proxy_ihash_empty(session->streams); +} + static int ping_arrived_iter(void *udata, void *val) { h2_proxy_stream *stream = val; diff --git a/modules/http2/h2_proxy_session.h b/modules/http2/h2_proxy_session.h index f40e5ee52e9..3bc16d70b3e 100644 --- a/modules/http2/h2_proxy_session.h +++ b/modules/http2/h2_proxy_session.h @@ -68,7 +68,8 @@ typedef enum { typedef struct h2_proxy_session h2_proxy_session; typedef void h2_proxy_request_done(h2_proxy_session *s, request_rec *r, - apr_status_t status, int touched); + apr_status_t status, int touched, + int error_code); struct h2_proxy_session { const char *id; @@ -130,4 +131,6 @@ void h2_proxy_session_cleanup(h2_proxy_session *s, h2_proxy_request_done *done); #define H2_PROXY_REQ_URL_NOTE "h2-proxy-req-url" +int h2_proxy_session_is_reusable(h2_proxy_session *s); + #endif /* h2_proxy_session_h */ diff --git a/modules/http2/h2_request.c b/modules/http2/h2_request.c index 00436aa762b..3a6c42b0921 100644 --- a/modules/http2/h2_request.c +++ b/modules/http2/h2_request.c @@ -375,6 +375,9 @@ request_rec *h2_create_request_rec(const h2_request *req, conn_rec *c, } else if (req->scheme && ap_cstr_casecmp(req->scheme, "http") && ap_cstr_casecmp(req->scheme, "https")) { + /* FIXME: we also need to create absolute uris when we are + * in a forward proxy configuration! But there is currently + * no way to detect that. */ /* Client sent a ':scheme' pseudo header for something else * than what we handle by default. Make an absolute URI. */ r->the_request = apr_psprintf(r->pool, "%s %s://%s%s HTTP/2.0", diff --git a/modules/http2/h2_stream.c b/modules/http2/h2_stream.c index 4127069f82c..d8b582ac408 100644 --- a/modules/http2/h2_stream.c +++ b/modules/http2/h2_stream.c @@ -1573,6 +1573,8 @@ static apr_status_t stream_do_response(h2_stream *stream) * denies it, submit resources to push */ const char *s = apr_table_get(resp->notes, H2_PUSH_MODE_NOTE); if (!s || strcmp(s, "0")) { + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, c1, + H2_STRM_MSG(stream, "submit pushes, note=%s"), s); h2_stream_submit_pushes(stream, resp); } } diff --git a/modules/http2/h2_version.h b/modules/http2/h2_version.h index e556f038d3f..aca4ffe0d57 100644 --- a/modules/http2/h2_version.h +++ b/modules/http2/h2_version.h @@ -27,7 +27,7 @@ * @macro * Version number of the http2 module as c string */ -#define MOD_HTTP2_VERSION "2.0.15" +#define MOD_HTTP2_VERSION "2.0.18-git" /** * @macro @@ -35,7 +35,7 @@ * release. This is a 24 bit number with 8 bits for major number, 8 bits * for minor and 8 bits for patch. Version 1.2.3 becomes 0x010203. */ -#define MOD_HTTP2_VERSION_NUM 0x02000f +#define MOD_HTTP2_VERSION_NUM 0x020012 #endif /* mod_h2_h2_version_h */ diff --git a/modules/http2/mod_proxy_http2.c b/modules/http2/mod_proxy_http2.c index 5abccab0972..8c0905f917c 100644 --- a/modules/http2/mod_proxy_http2.c +++ b/modules/http2/mod_proxy_http2.c @@ -50,8 +50,7 @@ static int (*is_h2)(conn_rec *c); typedef struct h2_proxy_ctx { const char *id; - conn_rec *master; - conn_rec *owner; + conn_rec *cfront; apr_pool_t *pool; server_rec *server; const char *proxy_func; @@ -69,7 +68,7 @@ typedef struct h2_proxy_ctx { apr_status_t r_status; /* status of request work */ int r_done; /* request was processed, not necessarily successfully */ int r_may_retry; /* request may be retried */ - h2_proxy_session *session; /* current http2 session against backend */ + int has_reusable_session; /* http2 session is live and clean */ } h2_proxy_ctx; static int h2_proxy_post_config(apr_pool_t *p, apr_pool_t *plog, @@ -160,10 +159,15 @@ static int proxy_http2_canon(request_rec *r, char *url) } else { core_dir_config *d = ap_get_core_module_config(r->per_dir_config); + #ifdef PROXY_CANONENC_NOENCODEDSLASHENCODING int flags = d->allow_encoded_slashes && !d->decode_encoded_slashes ? PROXY_CANONENC_NOENCODEDSLASHENCODING : 0; path = ap_proxy_canonenc_ex(r->pool, url, (int)strlen(url), enc_path, flags, r->proxyreq); +#else + path = ap_proxy_canonenc(r->pool, url, (int)strlen(url), + enc_path, 0, r->proxyreq); +#endif if (!path) { return HTTP_BAD_REQUEST; } @@ -227,79 +231,81 @@ static apr_status_t add_request(h2_proxy_session *session, request_rec *r) } static void request_done(h2_proxy_ctx *ctx, request_rec *r, - apr_status_t status, int touched) + apr_status_t status, int touched, int error_code) { if (r == ctx->r) { ap_log_cerror(APLOG_MARK, APLOG_TRACE1, status, r->connection, - "h2_proxy_session(%s): request done, touched=%d", - ctx->id, touched); + "h2_proxy_session(%s): request done, touched=%d, error=%d", + ctx->id, touched, error_code); ctx->r_done = 1; if (touched) ctx->r_may_retry = 0; - ctx->r_status = ((status == APR_SUCCESS)? APR_SUCCESS - : HTTP_SERVICE_UNAVAILABLE); + ctx->r_status = error_code? HTTP_BAD_GATEWAY : + ((status == APR_SUCCESS)? OK : + ap_map_http_request_error(status, HTTP_SERVICE_UNAVAILABLE)); } } static void session_req_done(h2_proxy_session *session, request_rec *r, - apr_status_t status, int touched) + apr_status_t status, int touched, int error_code) { - request_done(session->user_data, r, status, touched); + request_done(session->user_data, r, status, touched, error_code); } static apr_status_t ctx_run(h2_proxy_ctx *ctx) { apr_status_t status = OK; + h2_proxy_session *session; int h2_front; /* Step Four: Send the Request in a new HTTP/2 stream and * loop until we got the response or encounter errors. */ - h2_front = is_h2? is_h2(ctx->owner) : 0; - ctx->session = h2_proxy_session_setup(ctx->id, ctx->p_conn, ctx->conf, - h2_front, 30, - h2_proxy_log2((int)ctx->req_buffer_size), - session_req_done); - if (!ctx->session) { - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, ctx->owner, + ctx->has_reusable_session = 0; /* don't know yet */ + h2_front = is_h2? is_h2(ctx->cfront) : 0; + session = h2_proxy_session_setup(ctx->id, ctx->p_conn, ctx->conf, + h2_front, 30, + h2_proxy_log2((int)ctx->req_buffer_size), + session_req_done); + if (!session) { + ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, ctx->cfront, APLOGNO(03372) "session unavailable"); return HTTP_SERVICE_UNAVAILABLE; } - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, ctx->owner, APLOGNO(03373) - "eng(%s): run session %s", ctx->id, ctx->session->id); - ctx->session->user_data = ctx; + ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, ctx->cfront, APLOGNO(03373) + "eng(%s): run session %s", ctx->id, session->id); + session->user_data = ctx; ctx->r_done = 0; - add_request(ctx->session, ctx->r); + add_request(session, ctx->r); - while (!ctx->owner->aborted && !ctx->r_done) { + while (!ctx->cfront->aborted && !ctx->r_done) { - status = h2_proxy_session_process(ctx->session); + status = h2_proxy_session_process(session); if (status != APR_SUCCESS) { /* Encountered an error during session processing */ - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, ctx->owner, + ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, ctx->cfront, APLOGNO(03375) "eng(%s): end of session %s", - ctx->id, ctx->session->id); + ctx->id, session->id); /* Any open stream of that session needs to * a) be reopened on the new session iff safe to do so * b) reported as done (failed) otherwise */ - h2_proxy_session_cleanup(ctx->session, session_req_done); + h2_proxy_session_cleanup(session, session_req_done); goto out; } } out: - if (ctx->owner->aborted) { + if (ctx->cfront->aborted) { /* master connection gone */ - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, ctx->owner, + ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, ctx->cfront, APLOGNO(03374) "eng(%s): master connection gone", ctx->id); /* cancel all ongoing requests */ - h2_proxy_session_cancel_all(ctx->session); - h2_proxy_session_process(ctx->session); + h2_proxy_session_cancel_all(session); + h2_proxy_session_process(session); } - - ctx->session->user_data = NULL; - ctx->session = NULL; + ctx->has_reusable_session = h2_proxy_session_is_reusable(session); + session->user_data = NULL; return status; } @@ -344,9 +350,8 @@ static int proxy_http2_handler(request_rec *r, } ctx = apr_pcalloc(r->pool, sizeof(*ctx)); - ctx->master = r->connection->master? r->connection->master : r->connection; - ctx->id = apr_psprintf(r->pool, "%ld", (long)ctx->master->id); - ctx->owner = r->connection; + ctx->id = apr_psprintf(r->pool, "%ld", (long)r->connection->id); + ctx->cfront = r->connection; ctx->pool = r->pool; ctx->server = r->server; ctx->proxy_func = proxy_func; @@ -359,7 +364,7 @@ static int proxy_http2_handler(request_rec *r, ctx->r_done = 0; ctx->r_may_retry = 1; - ap_set_module_config(ctx->owner->conn_config, &proxy_http2_module, ctx); + ap_set_module_config(ctx->cfront->conn_config, &proxy_http2_module, ctx); /* scheme says, this is for us. */ apr_table_setn(ctx->r->notes, H2_PROXY_REQ_URL_NOTE, url); @@ -367,7 +372,7 @@ static int proxy_http2_handler(request_rec *r, "H2: serving URL %s", url); run_connect: - if (ctx->owner->aborted) goto cleanup; + if (ctx->cfront->aborted) goto cleanup; /* Get a proxy_conn_rec from the worker, might be a new one, might * be one still open from another request, or it might fail if the @@ -395,7 +400,7 @@ static int proxy_http2_handler(request_rec *r, * backend->hostname. */ if (ap_proxy_connect_backend(ctx->proxy_func, ctx->p_conn, ctx->worker, ctx->server)) { - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, ctx->owner, APLOGNO(03352) + ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, ctx->cfront, APLOGNO(03352) "H2: failed to make connection to backend: %s", ctx->p_conn->hostname); goto cleanup; @@ -404,7 +409,7 @@ static int proxy_http2_handler(request_rec *r, /* Step Three: Create conn_rec for the socket we have open now. */ status = ap_proxy_connection_create_ex(ctx->proxy_func, ctx->p_conn, ctx->r); if (status != OK) { - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, ctx->owner, APLOGNO(03353) + ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, ctx->cfront, APLOGNO(03353) "setup new connection: is_ssl=%d %s %s %s", ctx->p_conn->is_ssl, ctx->p_conn->ssl_hostname, locurl, ctx->p_conn->hostname); @@ -419,10 +424,10 @@ static int proxy_http2_handler(request_rec *r, "proxy-request-alpn-protos", "h2"); } - if (ctx->owner->aborted) goto cleanup; + if (ctx->cfront->aborted) goto cleanup; status = ctx_run(ctx); - if (ctx->r_status != APR_SUCCESS && ctx->r_may_retry && !ctx->owner->aborted) { + if (ctx->r_status != APR_SUCCESS && ctx->r_may_retry && !ctx->cfront->aborted) { /* Not successfully processed, but may retry, tear down old conn and start over */ if (ctx->p_conn) { ctx->p_conn->close = 1; @@ -436,15 +441,16 @@ static int proxy_http2_handler(request_rec *r, if (reconnects < 2) { goto run_connect; } - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, ctx->owner, APLOGNO(10023) + ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, ctx->cfront, APLOGNO(10023) "giving up after %d reconnects, request-done=%d", reconnects, ctx->r_done); } cleanup: if (ctx->p_conn) { - if (status != APR_SUCCESS) { - /* close socket when errors happened or session shut down (EOF) */ + if (status != APR_SUCCESS || !ctx->has_reusable_session) { + /* close socket when errors happened or session is not "clean", + * meaning in a working condition with no open streams */ ctx->p_conn->close = 1; } #if AP_MODULE_MAGIC_AT_LEAST(20140207, 2) @@ -454,8 +460,8 @@ static int proxy_http2_handler(request_rec *r, ctx->p_conn = NULL; } - ap_set_module_config(ctx->owner->conn_config, &proxy_http2_module, NULL); - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, ctx->owner, + ap_set_module_config(ctx->cfront->conn_config, &proxy_http2_module, NULL); + ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, ctx->cfront, APLOGNO(03377) "leaving handler"); return ctx->r_status; } From 9ce259d4ca3db5cd92fbae2f901c57247f54ce26 Mon Sep 17 00:00:00 2001 From: Stefan Eissing Date: Tue, 20 Jun 2023 13:23:40 +0200 Subject: [PATCH 4/4] Merge of 1910331,1910386,1910441 from trunk *) mod_http2: fixed a bug in flushing pending data on an already closed connection that could lead to a busy loop, preventing the HTTP/2 session to close down successfully. Fixed PR 66624. Fixed a bug that could lead to a crash in main connection output handling. This occured only when the last request on a HTTP/2 connection had been processed and the session decided to shut down. This could lead to an attempt to send a final GOAWAY while the previous write was still in progress. See PR 66646. --- changes-entries/h2_flush_fix.txt | 4 +++ changes-entries/h2_pr66646.txt | 6 ++++ modules/http2/h2_c1_io.c | 28 +++++++++++---- modules/http2/h2_c1_io.h | 3 +- modules/http2/h2_session.c | 9 +++-- modules/http2/h2_stream.c | 60 +++++++++++++++++++++++++++++++- modules/http2/h2_stream.h | 15 ++++++++ modules/http2/h2_version.h | 4 +-- 8 files changed, 113 insertions(+), 16 deletions(-) create mode 100644 changes-entries/h2_flush_fix.txt create mode 100644 changes-entries/h2_pr66646.txt diff --git a/changes-entries/h2_flush_fix.txt b/changes-entries/h2_flush_fix.txt new file mode 100644 index 00000000000..b44a3319f67 --- /dev/null +++ b/changes-entries/h2_flush_fix.txt @@ -0,0 +1,4 @@ + *) mod_http2: fixed a bug in flushing pending data on an already closed + connection that could lead to a busy loop, preventing the HTTP/2 session + to close down successfully. Fixed PR 66624. + [Stefan Eissing] diff --git a/changes-entries/h2_pr66646.txt b/changes-entries/h2_pr66646.txt new file mode 100644 index 00000000000..6bf23cfe47b --- /dev/null +++ b/changes-entries/h2_pr66646.txt @@ -0,0 +1,6 @@ + *) mod_http2: fixed a bug that could lead to a crash in main connection + output handling. This occured only when the last request on a HTTP/2 + connection had been processed and the session decided to shut down. + This could lead to an attempt to send a final GOAWAY while the previous + write was still in progress. See PR 66646. + [Stefan Eissing] diff --git a/modules/http2/h2_c1_io.c b/modules/http2/h2_c1_io.c index ade88366358..55d463f51b8 100644 --- a/modules/http2/h2_c1_io.c +++ b/modules/http2/h2_c1_io.c @@ -260,9 +260,22 @@ static apr_status_t read_to_scratch(h2_c1_io *io, apr_bucket *b) static apr_status_t pass_output(h2_c1_io *io, int flush) { conn_rec *c = io->session->c1; - apr_off_t bblen; + apr_off_t bblen = 0; apr_status_t rv; - + + if (io->is_passing) { + /* recursive call, may be triggered by an H2EOS bucket + * being destroyed and triggering sending more data? */ + AP_DEBUG_ASSERT(0); + ap_log_cerror(APLOG_MARK, APLOG_ERR, rv, c, APLOGNO(10456) + "h2_c1_io(%ld): recursive call of h2_c1_io_pass. " + "Denied to prevent output corruption. This " + "points to a bug in the HTTP/2 implementation.", + c->id); + return APR_EGENERAL; + } + io->is_passing = 1; + append_scratch(io); if (flush) { if (!APR_BUCKET_IS_FLUSH(APR_BRIGADE_LAST(io->output))) { @@ -271,17 +284,16 @@ static apr_status_t pass_output(h2_c1_io *io, int flush) } } if (APR_BRIGADE_EMPTY(io->output)) { - return APR_SUCCESS; + rv = APR_SUCCESS; + goto cleanup; } - + io->unflushed = !APR_BUCKET_IS_FLUSH(APR_BRIGADE_LAST(io->output)); apr_brigade_length(io->output, 0, &bblen); C1_IO_BB_LOG(c, 0, APLOG_TRACE2, "out", io->output); - + rv = ap_pass_brigade(c->output_filters, io->output); if (APR_SUCCESS != rv) goto cleanup; - - io->buffered_len = 0; io->bytes_written += (apr_size_t)bblen; if (io->write_size < WRITE_SIZE_MAX @@ -309,6 +321,8 @@ static apr_status_t pass_output(h2_c1_io *io, int flush) c->id, (long)bblen); } apr_brigade_cleanup(io->output); + io->buffered_len = 0; + io->is_passing = 0; return rv; } diff --git a/modules/http2/h2_c1_io.h b/modules/http2/h2_c1_io.h index d891ffb44df..c4dac38e1ee 100644 --- a/modules/http2/h2_c1_io.h +++ b/modules/http2/h2_c1_io.h @@ -44,7 +44,8 @@ typedef struct { apr_off_t buffered_len; apr_off_t flush_threshold; unsigned int is_flushed : 1; - + unsigned int is_passing : 1; + char *scratch; apr_size_t ssize; apr_size_t slen; diff --git a/modules/http2/h2_session.c b/modules/http2/h2_session.c index 0ede886998f..603e47ce85e 100644 --- a/modules/http2/h2_session.c +++ b/modules/http2/h2_session.c @@ -1281,8 +1281,11 @@ static apr_status_t h2_session_send(h2_session *session) goto cleanup; } } - if (h2_c1_io_needs_flush(&session->io)) { + if (h2_c1_io_needs_flush(&session->io) || + ngrv == NGHTTP2_ERR_WOULDBLOCK) { rv = h2_c1_io_assure_flushed(&session->io); + if (rv != APR_SUCCESS) + goto cleanup; pending = 0; } } @@ -1639,10 +1642,6 @@ static void on_stream_state_enter(void *ctx, h2_stream *stream) h2_mplx_c1_stream_cleanup(session->mplx, stream, &session->open_streams); ++session->streams_done; update_child_status(session, SERVER_BUSY_WRITE, "done", stream); - if (session->open_streams == 0) { - h2_session_dispatch_event(session, H2_SESSION_EV_NO_MORE_STREAMS, - 0, "stream done"); - } break; default: break; diff --git a/modules/http2/h2_stream.c b/modules/http2/h2_stream.c index d8b582ac408..635caf7cb3c 100644 --- a/modules/http2/h2_stream.c +++ b/modules/http2/h2_stream.c @@ -166,6 +166,7 @@ static int on_frame_recv(h2_stream_state_t state, int frame_type) static int on_event(h2_stream* stream, h2_stream_event_t ev) { + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); if (stream->monitor && stream->monitor->on_event) { stream->monitor->on_event(stream->monitor->ctx, stream, ev); } @@ -392,6 +393,7 @@ void h2_stream_dispatch(h2_stream *stream, h2_stream_event_t ev) { int new_state; + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, stream->session->c1, H2_STRM_MSG(stream, "dispatch event %d"), ev); new_state = on_event(stream, ev); @@ -425,6 +427,7 @@ apr_status_t h2_stream_send_frame(h2_stream *stream, int ftype, int flags, size_ apr_status_t status = APR_SUCCESS; int new_state, eos = 0; + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); new_state = on_frame_send(stream->state, ftype); if (new_state < 0) { ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, stream->session->c1, @@ -474,6 +477,7 @@ apr_status_t h2_stream_recv_frame(h2_stream *stream, int ftype, int flags, size_ apr_status_t status = APR_SUCCESS; int new_state, eos = 0; + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); new_state = on_frame_recv(stream->state, ftype); if (new_state < 0) { ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, stream->session->c1, @@ -528,6 +532,7 @@ apr_status_t h2_stream_recv_DATA(h2_stream *stream, uint8_t flags, h2_session *session = stream->session; apr_status_t status = APR_SUCCESS; + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); stream->in_data_frames++; if (len > 0) { if (APLOGctrace3(session->c1)) { @@ -548,11 +553,38 @@ apr_status_t h2_stream_recv_DATA(h2_stream *stream, uint8_t flags, return status; } +#ifdef AP_DEBUG +static apr_status_t stream_pool_destroy(void *data) +{ + h2_stream *stream = data; + switch (stream->magic) { + case H2_STRM_MAGIC_OK: + ap_log_cerror(APLOG_MARK, APLOG_ERR, 0, stream->session->c1, + H2_STRM_MSG(stream, "was not destroyed explicitly")); + AP_DEBUG_ASSERT(0); + break; + case H2_STRM_MAGIC_SDEL: + /* stream has been explicitly destroyed, as it should */ + H2_STRM_ASSIGN_MAGIC(stream, H2_STRM_MAGIC_PDEL); + break; + case H2_STRM_MAGIC_PDEL: + ap_log_cerror(APLOG_MARK, APLOG_ERR, 0, stream->session->c1, + H2_STRM_MSG(stream, "already pool destroyed")); + AP_DEBUG_ASSERT(0); + break; + default: + AP_DEBUG_ASSERT(0); + } + return APR_SUCCESS; +} +#endif + h2_stream *h2_stream_create(int id, apr_pool_t *pool, h2_session *session, h2_stream_monitor *monitor, int initiated_on) { h2_stream *stream = apr_pcalloc(pool, sizeof(h2_stream)); - + + H2_STRM_ASSIGN_MAGIC(stream, H2_STRM_MAGIC_OK); stream->id = id; stream->initiated_on = initiated_on; stream->created = apr_time_now(); @@ -560,6 +592,12 @@ h2_stream *h2_stream_create(int id, apr_pool_t *pool, h2_session *session, stream->pool = pool; stream->session = session; stream->monitor = monitor; +#ifdef AP_DEBUG + if (id) { /* stream 0 has special lifetime */ + apr_pool_cleanup_register(pool, stream, stream_pool_destroy, + apr_pool_cleanup_null); + } +#endif #ifdef H2_NG2_LOCAL_WIN_SIZE if (id) { @@ -581,6 +619,7 @@ void h2_stream_cleanup(h2_stream *stream) * end of the in/out notifications get closed. */ ap_assert(stream); + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); if (stream->out_buffer) { apr_brigade_cleanup(stream->out_buffer); } @@ -589,13 +628,16 @@ void h2_stream_cleanup(h2_stream *stream) void h2_stream_destroy(h2_stream *stream) { ap_assert(stream); + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); ap_log_cerror(APLOG_MARK, APLOG_TRACE3, 0, stream->session->c1, H2_STRM_MSG(stream, "destroy")); + H2_STRM_ASSIGN_MAGIC(stream, H2_STRM_MAGIC_SDEL); apr_pool_destroy(stream->pool); } void h2_stream_rst(h2_stream *stream, int error_code) { + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); stream->rst_error = error_code; if (stream->c2) { h2_c2_abort(stream->c2, stream->session->c1); @@ -611,6 +653,7 @@ apr_status_t h2_stream_set_request_rec(h2_stream *stream, h2_request *req; apr_status_t status; + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); ap_assert(stream->request == NULL); ap_assert(stream->rtmp == NULL); if (stream->rst_error) { @@ -632,6 +675,7 @@ apr_status_t h2_stream_set_request_rec(h2_stream *stream, void h2_stream_set_request(h2_stream *stream, const h2_request *r) { + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); ap_assert(stream->request == NULL); ap_assert(stream->rtmp == NULL); stream->rtmp = h2_request_clone(stream->pool, r); @@ -691,6 +735,7 @@ apr_status_t h2_stream_add_header(h2_stream *stream, int error = 0, was_added = 0; apr_status_t status = APR_SUCCESS; + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); if (stream->response) { return APR_EINVAL; } @@ -797,6 +842,7 @@ apr_status_t h2_stream_end_headers(h2_stream *stream, int eos, size_t raw_bytes) int is_http_or_https; h2_request *req = stream->rtmp; + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); status = h2_request_end_headers(req, stream->pool, raw_bytes); if (APR_SUCCESS != status || req->http_status != H2_HTTP_STATUS_UNSET) { goto cleanup; @@ -1045,6 +1091,7 @@ apr_status_t h2_stream_read_to(h2_stream *stream, apr_bucket_brigade *bb, { apr_status_t rv = APR_SUCCESS; + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); if (stream->rst_error) { return APR_ECONNRESET; } @@ -1139,6 +1186,7 @@ apr_status_t h2_stream_submit_pushes(h2_stream *stream, h2_headers *response) apr_array_header_t *pushes; int i; + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); pushes = h2_push_collect_update(stream, stream->request, response); if (pushes && !apr_is_empty_array(pushes)) { ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, stream->session->c1, @@ -1158,6 +1206,7 @@ apr_status_t h2_stream_submit_pushes(h2_stream *stream, h2_headers *response) apr_table_t *h2_stream_get_trailers(h2_stream *stream) { + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); return NULL; } @@ -1169,6 +1218,7 @@ const h2_priority *h2_stream_get_priority(h2_stream *stream, h2_headers *response) #endif { + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); if (response && stream->initiated_on) { const char *ctype = apr_table_get(response->headers, "content-type"); if (ctype) { @@ -1182,6 +1232,7 @@ const h2_priority *h2_stream_get_priority(h2_stream *stream, int h2_stream_is_ready(h2_stream *stream) { /* Have we sent a response or do we have the response in our buffer? */ + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); if (stream->response) { return 1; } @@ -1193,11 +1244,13 @@ int h2_stream_is_ready(h2_stream *stream) int h2_stream_is_at(const h2_stream *stream, h2_stream_state_t state) { + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); return stream->state == state; } int h2_stream_is_at_or_past(const h2_stream *stream, h2_stream_state_t state) { + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); switch (state) { case H2_SS_IDLE: return 1; /* by definition */ @@ -1220,6 +1273,7 @@ apr_status_t h2_stream_in_consumed(h2_stream *stream, apr_off_t amount) { h2_session *session = stream->session; + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); if (amount > 0) { apr_off_t consumed = amount; @@ -1345,6 +1399,7 @@ static ssize_t stream_data_cb(nghttp2_session *ng2s, H2_SSSN_STRM_MSG(session, stream_id, "data_cb, stream not found")); return NGHTTP2_ERR_CALLBACK_FAILURE; } + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); if (!stream->output || !stream->response || !stream->out_buffer) { return NGHTTP2_ERR_DEFERRED; } @@ -1476,6 +1531,7 @@ static apr_status_t stream_do_response(h2_stream *stream) #endif nghttp2_data_provider provider, *pprovider = NULL; + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); ap_assert(!stream->response); ap_assert(stream->out_buffer); @@ -1666,6 +1722,7 @@ void h2_stream_on_output_change(h2_stream *stream) /* stream->pout_recv_write signalled a change. Check what has happend, read * from it and act on seeing a response/data. */ + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); if (!stream->output) { /* c2 has not assigned the output beam to the stream (yet). */ ap_log_cerror(APLOG_MARK, APLOG_WARNING, 0, c1, @@ -1714,6 +1771,7 @@ void h2_stream_on_output_change(h2_stream *stream) void h2_stream_on_input_change(h2_stream *stream) { + H2_STRM_ASSERT_MAGIC(stream, H2_STRM_MAGIC_OK); ap_assert(stream->input); h2_beam_report_consumption(stream->input); if (h2_stream_is_at(stream, H2_SS_CLOSED_L) diff --git a/modules/http2/h2_stream.h b/modules/http2/h2_stream.h index 695d56ac5e1..638dbdac0d1 100644 --- a/modules/http2/h2_stream.h +++ b/modules/http2/h2_stream.h @@ -63,7 +63,22 @@ typedef struct h2_stream_monitor { trigger a state change */ } h2_stream_monitor; +#ifdef AP_DEBUG +#define H2_STRM_MAGIC_OK 0x5354524d +#define H2_STRM_MAGIC_SDEL 0x5344454c +#define H2_STRM_MAGIC_PDEL 0x5044454c + +#define H2_STRM_ASSIGN_MAGIC(s,m) ((s)->magic = m) +#define H2_STRM_ASSERT_MAGIC(s,m) ap_assert((s)->magic == m) +#else +#define H2_STRM_ASSIGN_MAGIC(s,m) ((void)0) +#define H2_STRM_ASSERT_MAGIC(s,m) ((void)0) +#endif + struct h2_stream { +#ifdef AP_DEBUG + uint32_t magic; +#endif int id; /* http2 stream identifier */ int initiated_on; /* initiating stream id (PUSH) or 0 */ apr_pool_t *pool; /* the memory pool for this stream */ diff --git a/modules/http2/h2_version.h b/modules/http2/h2_version.h index aca4ffe0d57..7de3144ec7f 100644 --- a/modules/http2/h2_version.h +++ b/modules/http2/h2_version.h @@ -27,7 +27,7 @@ * @macro * Version number of the http2 module as c string */ -#define MOD_HTTP2_VERSION "2.0.18-git" +#define MOD_HTTP2_VERSION "2.0.19-git" /** * @macro @@ -35,7 +35,7 @@ * release. This is a 24 bit number with 8 bits for major number, 8 bits * for minor and 8 bits for patch. Version 1.2.3 becomes 0x010203. */ -#define MOD_HTTP2_VERSION_NUM 0x020012 +#define MOD_HTTP2_VERSION_NUM 0x020013 #endif /* mod_h2_h2_version_h */