From 75fa15aa475868e13902b3dee0397881e385b1b9 Mon Sep 17 00:00:00 2001 From: Yann Ylavic Date: Tue, 29 May 2018 21:16:29 +0000 Subject: [PATCH] Merge r1826687, r1827166, r1828210, r1828232, r1828687 from trunk: Instrument 'bbout' mod_http2: use proper ARP defined for formatting apr_off_t On the trunk: mod_http2: on level trace2, log any unsuccessful HTTP/2 direct connection upgrade with base64 encoding to unify its appearance in possible bug reports. On the trunk: * mod_http2: calculate unencrypted connection sniffing base64 only when log level is at required height. [Ruediger Pluem] On the trunk: mod_http2: accurate reporting of h2 data input/output per request via mod_logio. Fixes an issue where output sizes where counted n-times on reused slave connections. See gituhub issue: https://github.com/icing/mod_h2/issues/158 Submitted by: jailletc36, icing, icing, icing, icing Reviewed by: icing, jim, ylavic git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/branches/2.4.x@1832489 13f79535-47bb-0310-9956-ffa450edef68 --- CHANGES | 5 +++ modules/http2/h2.h | 5 +++ modules/http2/h2_conn.c | 12 +++++-- modules/http2/h2_filter.c | 6 ++-- modules/http2/h2_from_h1.c | 6 +++- modules/http2/h2_h2.c | 6 ++-- modules/http2/h2_headers.c | 7 +++-- modules/http2/h2_headers.h | 4 ++- modules/http2/h2_mplx.c | 64 +++++++++++++++++++++----------------- modules/http2/h2_push.c | 2 +- modules/http2/h2_request.c | 5 +-- modules/http2/h2_request.h | 2 +- modules/http2/h2_session.c | 9 ++++-- modules/http2/h2_stream.c | 18 ++++++----- modules/http2/h2_stream.h | 7 +++-- modules/http2/h2_task.c | 7 +++++ modules/http2/h2_version.h | 4 +-- 17 files changed, 109 insertions(+), 60 deletions(-) diff --git a/CHANGES b/CHANGES index e63f78f40f..d778cdd831 100644 --- a/CHANGES +++ b/CHANGES @@ -1,6 +1,11 @@ -*- coding: utf-8 -*- Changes with Apache 2.4.34 + *) mod_http2: accurate reporting of h2 data input/output per request via mod_logio. Fixes + an issue where output sizes where counted n-times on reused slave connections. See + gituhub issue: https://github.com/icing/mod_h2/issues/158 + [Stefan Eissing] + *) mod_http2: Fix unnecessary timeout waits in case streams are aborted. [Stefan Eissing] diff --git a/modules/http2/h2.h b/modules/http2/h2.h index 48d023e434..38b4019ab8 100644 --- a/modules/http2/h2.h +++ b/modules/http2/h2.h @@ -51,6 +51,9 @@ extern const char *H2_MAGIC_TOKEN; /* Max data size to write so it fits inside a TLS record */ #define H2_DATA_CHUNK_SIZE ((16*1024) - 100 - 9) +/* Size of the frame header itself in HTTP/2 */ +#define H2_FRAME_HDR_LEN 9 + /* Maximum number of padding bytes in a frame, rfc7540 */ #define H2_MAX_PADLEN 256 /* Initial default window size, RFC 7540 ch. 6.5.2 */ @@ -137,6 +140,7 @@ struct h2_request { apr_time_t request_time; unsigned int chunked : 1; /* iff requst body needs to be forwarded as chunked */ unsigned int serialize : 1; /* iff this request is written in HTTP/1.1 serialization */ + apr_off_t raw_bytes; /* RAW network bytes that generated this request - if known. */ }; typedef struct h2_headers h2_headers; @@ -145,6 +149,7 @@ struct h2_headers { int status; apr_table_t *headers; apr_table_t *notes; + apr_off_t raw_bytes; /* RAW network bytes that generated this request - if known. */ }; typedef apr_status_t h2_io_data_cb(void *ctx, const char *data, apr_off_t len); diff --git a/modules/http2/h2_conn.c b/modules/http2/h2_conn.c index 11f54da258..862d4c1959 100644 --- a/modules/http2/h2_conn.c +++ b/modules/http2/h2_conn.c @@ -302,8 +302,6 @@ conn_rec *h2_slave_create(conn_rec *master, int slave_id, apr_pool_t *parent) c->log = NULL; c->log_id = apr_psprintf(pool, "%ld-%d", master->id, slave_id); - /* Simulate that we had already a request on this connection. */ - c->keepalives = 1; c->aborted = 0; /* We cannot install the master connection socket on the slaves, as * modules mess with timeouts/blocking of the socket, with @@ -338,6 +336,14 @@ void h2_slave_destroy(conn_rec *slave) apr_status_t h2_slave_run_pre_connection(conn_rec *slave, apr_socket_t *csd) { - return ap_run_pre_connection(slave, csd); + if (slave->keepalives == 0) { + /* Simulate that we had already a request on this connection. Some + * hooks trigger special behaviour when keepalives is 0. + * (Not necessarily in pre_connection, but later. Set it here, so it + * is in place.) */ + slave->keepalives = 1; + return ap_run_pre_connection(slave, csd); + } + return APR_SUCCESS; } diff --git a/modules/http2/h2_filter.c b/modules/http2/h2_filter.c index 862c87421a..8b254b131d 100644 --- a/modules/http2/h2_filter.c +++ b/modules/http2/h2_filter.c @@ -290,6 +290,8 @@ apr_bucket *h2_bucket_observer_beam(struct h2_bucket_beam *beam, return NULL; } +static apr_status_t bbout(apr_bucket_brigade *bb, const char *fmt, ...) + __attribute__((format(printf,2,3))); static apr_status_t bbout(apr_bucket_brigade *bb, const char *fmt, ...) { va_list args; @@ -351,8 +353,8 @@ static int add_stream(h2_stream *stream, void *ctx) bbout(x->bb, " \"created\": %f,\n", ((double)stream->created)/APR_USEC_PER_SEC); bbout(x->bb, " \"flowIn\": %d,\n", flowIn); bbout(x->bb, " \"flowOut\": %d,\n", flowOut); - bbout(x->bb, " \"dataIn\": %"APR_UINT64_T_FMT",\n", stream->in_data_octets); - bbout(x->bb, " \"dataOut\": %"APR_UINT64_T_FMT"\n", stream->out_data_octets); + bbout(x->bb, " \"dataIn\": %"APR_OFF_T_FMT",\n", stream->in_data_octets); + bbout(x->bb, " \"dataOut\": %"APR_OFF_T_FMT"\n", stream->out_data_octets); bbout(x->bb, " }"); ++x->idx; diff --git a/modules/http2/h2_from_h1.c b/modules/http2/h2_from_h1.c index 17d7a1dbd7..ae264a9341 100644 --- a/modules/http2/h2_from_h1.c +++ b/modules/http2/h2_from_h1.c @@ -413,7 +413,7 @@ static apr_status_t pass_response(h2_task *task, ap_filter_t *f, h2_headers *response = h2_headers_create(parser->http_status, make_table(parser), - NULL, task->pool); + NULL, 0, task->pool); apr_brigade_cleanup(parser->tmp); b = h2_bucket_headers_create(task->c->bucket_alloc, response); APR_BRIGADE_INSERT_TAIL(parser->tmp, b); @@ -772,6 +772,10 @@ apr_status_t h2_filter_request_in(ap_filter_t* f, APR_BUCKET_REMOVE(b); apr_bucket_destroy(b); ap_remove_input_filter(f); + + if (headers->raw_bytes && h2_task_logio_add_bytes_in) { + h2_task_logio_add_bytes_in(task->c, headers->raw_bytes); + } break; } } diff --git a/modules/http2/h2_h2.c b/modules/http2/h2_h2.c index f5fda0a00b..dfee6b56b0 100644 --- a/modules/http2/h2_h2.c +++ b/modules/http2/h2_h2.c @@ -635,10 +635,10 @@ int h2_h2_process_conn(conn_rec* c) } h2_ctx_protocol_set(ctx, h2_h2_is_tls(c)? "h2" : "h2c"); } - else { + else if (APLOGctrace2(c)) { ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, c, - "h2_h2, not detected in %d bytes: %s", - (int)slen, s); + "h2_h2, not detected in %d bytes(base64): %s", + (int)slen, h2_util_base64url_encode(s, slen, c->pool)); } apr_brigade_destroy(temp); diff --git a/modules/http2/h2_headers.c b/modules/http2/h2_headers.c index 94cb214aa3..f01ab88aab 100644 --- a/modules/http2/h2_headers.c +++ b/modules/http2/h2_headers.c @@ -111,7 +111,8 @@ apr_bucket *h2_bucket_headers_beam(struct h2_bucket_beam *beam, h2_headers *h2_headers_create(int status, apr_table_t *headers_in, - apr_table_t *notes, apr_pool_t *pool) + apr_table_t *notes, apr_off_t raw_bytes, + apr_pool_t *pool) { h2_headers *headers = apr_pcalloc(pool, sizeof(h2_headers)); headers->status = status; @@ -125,7 +126,7 @@ h2_headers *h2_headers_create(int status, apr_table_t *headers_in, h2_headers *h2_headers_rcreate(request_rec *r, int status, apr_table_t *header, apr_pool_t *pool) { - h2_headers *headers = h2_headers_create(status, header, r->notes, pool); + h2_headers *headers = h2_headers_create(status, header, r->notes, 0, pool); if (headers->status == HTTP_FORBIDDEN) { const char *cause = apr_table_get(r->notes, "ssl-renegotiate-forbidden"); if (cause) { @@ -149,7 +150,7 @@ h2_headers *h2_headers_rcreate(request_rec *r, int status, h2_headers *h2_headers_copy(apr_pool_t *pool, h2_headers *h) { return h2_headers_create(h->status, apr_table_copy(pool, h->headers), - apr_table_copy(pool, h->notes), pool); + apr_table_copy(pool, h->notes), h->raw_bytes, pool); } h2_headers *h2_headers_die(apr_status_t type, diff --git a/modules/http2/h2_headers.h b/modules/http2/h2_headers.h index e7e88e3db4..840e8c4333 100644 --- a/modules/http2/h2_headers.h +++ b/modules/http2/h2_headers.h @@ -41,10 +41,12 @@ apr_bucket *h2_bucket_headers_beam(struct h2_bucket_beam *beam, * @param status the headers status * @param header the headers of the headers * @param notes the notes carried by the headers + * @param raw_bytes the raw network bytes (if known) used to transmit these * @param pool the memory pool to use */ h2_headers *h2_headers_create(int status, apr_table_t *header, - apr_table_t *notes, apr_pool_t *pool); + apr_table_t *notes, apr_off_t raw_bytes, + apr_pool_t *pool); /** * Create the headers from the given request_rec. diff --git a/modules/http2/h2_mplx.c b/modules/http2/h2_mplx.c index dc3418c059..05667abe03 100644 --- a/modules/http2/h2_mplx.c +++ b/modules/http2/h2_mplx.c @@ -286,34 +286,6 @@ static int output_consumed_signal(h2_mplx *m, h2_task *task) return 0; } -static void task_destroy(h2_mplx *m, h2_task *task) -{ - conn_rec *slave = NULL; - int reuse_slave = 0; - - slave = task->c; - - if (m->s->keep_alive_max == 0 || slave->keepalives < m->s->keep_alive_max) { - reuse_slave = ((m->spare_slaves->nelts < (m->limit_active * 3 / 2)) - && !task->rst_error); - } - - if (slave) { - if (reuse_slave && slave->keepalive == AP_CONN_KEEPALIVE) { - h2_beam_log(task->output.beam, m->c, APLOG_DEBUG, - APLOGNO(03385) "h2_task_destroy, reuse slave"); - h2_task_destroy(task); - APR_ARRAY_PUSH(m->spare_slaves, conn_rec*) = slave; - } - else { - h2_beam_log(task->output.beam, m->c, APLOG_TRACE1, - "h2_task_destroy, destroy slave"); - slave->sbh = NULL; - h2_slave_destroy(slave); - } - } -} - static int stream_destroy_iter(void *ctx, void *val) { h2_mplx *m = ctx; @@ -331,8 +303,42 @@ static int stream_destroy_iter(void *ctx, void *val) } if (stream->task) { - task_destroy(m, stream->task); + h2_task *task = stream->task; + conn_rec *slave; + int reuse_slave = 0; + stream->task = NULL; + slave = task->c; + if (slave) { + /* On non-serialized requests, the IO logging has not accounted for any + * meta data send over the network: response headers and h2 frame headers. we + * counted this on the stream and need to add this now. + * This is supposed to happen before the EOR bucket triggers the + * logging of the transaction. *fingers crossed* */ + if (task->request && !task->request->serialize && h2_task_logio_add_bytes_out) { + apr_off_t unaccounted = stream->out_frame_octets - stream->out_data_octets; + if (unaccounted > 0) { + h2_task_logio_add_bytes_out(slave, unaccounted); + } + } + + if (m->s->keep_alive_max == 0 || slave->keepalives < m->s->keep_alive_max) { + reuse_slave = ((m->spare_slaves->nelts < (m->limit_active * 3 / 2)) + && !task->rst_error); + } + + if (reuse_slave && slave->keepalive == AP_CONN_KEEPALIVE) { + h2_beam_log(task->output.beam, m->c, APLOG_DEBUG, + APLOGNO(03385) "h2_task_destroy, reuse slave"); + h2_task_destroy(task); + APR_ARRAY_PUSH(m->spare_slaves, conn_rec*) = slave; + } + else { + h2_beam_log(task->output.beam, m->c, APLOG_TRACE1, + "h2_task_destroy, destroy slave"); + h2_slave_destroy(slave); + } + } } h2_stream_destroy(stream); return 0; diff --git a/modules/http2/h2_push.c b/modules/http2/h2_push.c index 05add9a8cb..9a3b19bdc2 100644 --- a/modules/http2/h2_push.c +++ b/modules/http2/h2_push.c @@ -352,7 +352,7 @@ static int add_push(link_ctx *ctx) ctx->req->authority, path, headers, ctx->req->serialize); /* atm, we do not push on pushes */ - h2_request_end_headers(req, ctx->pool, 1); + h2_request_end_headers(req, ctx->pool, 1, 0); push->req = req; if (has_param(ctx, "critical")) { h2_priority *prio = apr_pcalloc(ctx->pool, sizeof(*prio)); diff --git a/modules/http2/h2_request.c b/modules/http2/h2_request.c index 5280e98155..8899c4feb7 100644 --- a/modules/http2/h2_request.c +++ b/modules/http2/h2_request.c @@ -150,7 +150,7 @@ apr_status_t h2_request_add_header(h2_request *req, apr_pool_t *pool, return status; } -apr_status_t h2_request_end_headers(h2_request *req, apr_pool_t *pool, int eos) +apr_status_t h2_request_end_headers(h2_request *req, apr_pool_t *pool, int eos, size_t raw_bytes) { const char *s; @@ -190,7 +190,8 @@ apr_status_t h2_request_end_headers(h2_request *req, apr_pool_t *pool, int eos) apr_table_setn(req->headers, "Content-Length", "0"); } } - + req->raw_bytes += raw_bytes; + return APR_SUCCESS; } diff --git a/modules/http2/h2_request.h b/modules/http2/h2_request.h index cc24e5f15a..48aee09d95 100644 --- a/modules/http2/h2_request.h +++ b/modules/http2/h2_request.h @@ -30,7 +30,7 @@ apr_status_t h2_request_add_trailer(h2_request *req, apr_pool_t *pool, const char *name, size_t nlen, const char *value, size_t vlen); -apr_status_t h2_request_end_headers(h2_request *req, apr_pool_t *pool, int eos); +apr_status_t h2_request_end_headers(h2_request *req, apr_pool_t *pool, int eos, size_t raw_bytes); h2_request *h2_request_clone(apr_pool_t *p, const h2_request *src); diff --git a/modules/http2/h2_session.c b/modules/http2/h2_session.c index 3a80949fa7..805d6774dc 100644 --- a/modules/http2/h2_session.c +++ b/modules/http2/h2_session.c @@ -348,7 +348,8 @@ static int on_frame_recv_cb(nghttp2_session *ng2s, * trailers */ stream = h2_session_stream_get(session, frame->hd.stream_id); if (stream) { - rv = h2_stream_recv_frame(stream, NGHTTP2_HEADERS, frame->hd.flags); + rv = h2_stream_recv_frame(stream, NGHTTP2_HEADERS, frame->hd.flags, + frame->hd.length + H2_FRAME_HDR_LEN); } break; case NGHTTP2_DATA: @@ -358,7 +359,8 @@ static int on_frame_recv_cb(nghttp2_session *ng2s, H2_STRM_LOG(APLOGNO(02923), stream, "DATA, len=%ld, flags=%d"), (long)frame->hd.length, frame->hd.flags); - rv = h2_stream_recv_frame(stream, NGHTTP2_DATA, frame->hd.flags); + rv = h2_stream_recv_frame(stream, NGHTTP2_DATA, frame->hd.flags, + frame->hd.length + H2_FRAME_HDR_LEN); } break; case NGHTTP2_PRIORITY: @@ -546,7 +548,8 @@ static int on_frame_send_cb(nghttp2_session *ngh2, stream = h2_session_stream_get(session, stream_id); if (stream) { - h2_stream_send_frame(stream, frame->hd.type, frame->hd.flags); + h2_stream_send_frame(stream, frame->hd.type, frame->hd.flags, + frame->hd.length + H2_FRAME_HDR_LEN); } return 0; } diff --git a/modules/http2/h2_stream.c b/modules/http2/h2_stream.c index b2703de712..22c5902444 100644 --- a/modules/http2/h2_stream.c +++ b/modules/http2/h2_stream.c @@ -221,7 +221,8 @@ static apr_status_t close_input(h2_stream *stream) stream->in_buffer = apr_brigade_create(stream->pool, c->bucket_alloc); } - r = h2_headers_create(HTTP_OK, stream->trailers, NULL, stream->pool); + r = h2_headers_create(HTTP_OK, stream->trailers, NULL, + stream->in_trailer_octets, stream->pool); stream->trailers = NULL; b = h2_bucket_headers_create(c->bucket_alloc, r); APR_BRIGADE_INSERT_TAIL(stream->in_buffer, b); @@ -369,7 +370,7 @@ static void set_policy_for(h2_stream *stream, h2_request *r) r->serialize = h2_config_geti(stream->session->config, H2_CONF_SER_HEADERS); } -apr_status_t h2_stream_send_frame(h2_stream *stream, int ftype, int flags) +apr_status_t h2_stream_send_frame(h2_stream *stream, int ftype, int flags, size_t frame_len) { apr_status_t status = APR_SUCCESS; int new_state, eos = 0; @@ -381,7 +382,9 @@ apr_status_t h2_stream_send_frame(h2_stream *stream, int ftype, int flags) AP_DEBUG_ASSERT(new_state > S_XXX); return transit(stream, new_state); } - + + ++stream->out_frames; + stream->out_frame_octets += frame_len; switch (ftype) { case NGHTTP2_DATA: eos = (flags & NGHTTP2_FLAG_END_STREAM); @@ -395,7 +398,7 @@ apr_status_t h2_stream_send_frame(h2_stream *stream, int ftype, int flags) /* start pushed stream */ ap_assert(stream->request == NULL); ap_assert(stream->rtmp != NULL); - status = h2_request_end_headers(stream->rtmp, stream->pool, 1); + status = h2_request_end_headers(stream->rtmp, stream->pool, 1, 0); if (status != APR_SUCCESS) { return status; } @@ -416,7 +419,7 @@ apr_status_t h2_stream_send_frame(h2_stream *stream, int ftype, int flags) return status; } -apr_status_t h2_stream_recv_frame(h2_stream *stream, int ftype, int flags) +apr_status_t h2_stream_recv_frame(h2_stream *stream, int ftype, int flags, size_t frame_len) { apr_status_t status = APR_SUCCESS; int new_state, eos = 0; @@ -441,6 +444,7 @@ apr_status_t h2_stream_recv_frame(h2_stream *stream, int ftype, int flags) if (!eos) { h2_stream_rst(stream, H2_ERR_PROTOCOL_ERROR); } + stream->in_trailer_octets += frame_len; } else { /* request HEADER */ @@ -452,7 +456,7 @@ apr_status_t h2_stream_recv_frame(h2_stream *stream, int ftype, int flags) * to abort the connection here, since this is clearly a protocol error */ return APR_EINVAL; } - status = h2_request_end_headers(stream->rtmp, stream->pool, eos); + status = h2_request_end_headers(stream->rtmp, stream->pool, eos, frame_len); if (status != APR_SUCCESS) { return status; } @@ -629,7 +633,7 @@ apr_status_t h2_stream_set_request_rec(h2_stream *stream, stream->rtmp = req; /* simulate the frames that led to this */ return h2_stream_recv_frame(stream, NGHTTP2_HEADERS, - NGHTTP2_FLAG_END_STREAM); + NGHTTP2_FLAG_END_STREAM, 0); } return status; } diff --git a/modules/http2/h2_stream.h b/modules/http2/h2_stream.h index ba63a3867e..7ecc0ad6bc 100644 --- a/modules/http2/h2_stream.h +++ b/modules/http2/h2_stream.h @@ -96,10 +96,13 @@ struct h2_stream { struct h2_task *task; /* assigned task to fullfill request */ const h2_priority *pref_priority; /* preferred priority for this stream */ + apr_off_t out_frames; /* # of frames sent out */ + apr_off_t out_frame_octets; /* # of RAW frame octets sent out */ apr_off_t out_data_frames; /* # of DATA frames sent */ apr_off_t out_data_octets; /* # of DATA octets (payload) sent */ apr_off_t in_data_frames; /* # of DATA frames received */ apr_off_t in_data_octets; /* # of DATA octets (payload) received */ + apr_off_t in_trailer_octets; /* # of HEADER octets (payload) received in trailers */ h2_stream_monitor *monitor; /* optional monitor for stream states */ }; @@ -196,8 +199,8 @@ apr_status_t h2_stream_add_header(h2_stream *stream, const char *name, size_t nlen, const char *value, size_t vlen); -apr_status_t h2_stream_send_frame(h2_stream *stream, int frame_type, int flags); -apr_status_t h2_stream_recv_frame(h2_stream *stream, int frame_type, int flags); +apr_status_t h2_stream_send_frame(h2_stream *stream, int frame_type, int flags, size_t frame_len); +apr_status_t h2_stream_recv_frame(h2_stream *stream, int frame_type, int flags, size_t frame_len); /* * Process a frame of received DATA. diff --git a/modules/http2/h2_task.c b/modules/http2/h2_task.c index d69afdfa7e..86fb0267bd 100644 --- a/modules/http2/h2_task.c +++ b/modules/http2/h2_task.c @@ -675,7 +675,14 @@ static apr_status_t h2_task_process_request(h2_task *task, conn_rec *c) ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, c, "h2_task(%s): start process_request", task->id); + /* Add the raw bytes of the request (e.g. header frame lengths to + * the logio for this request. */ + if (req->raw_bytes && h2_task_logio_add_bytes_in) { + h2_task_logio_add_bytes_in(c, req->raw_bytes); + } + ap_process_request(r); + if (task->frozen) { ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, c, "h2_task(%s): process_request frozen", task->id); diff --git a/modules/http2/h2_version.h b/modules/http2/h2_version.h index a9fdc2fe2d..50cfd118ae 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 "1.10.16" +#define MOD_HTTP2_VERSION "1.10.17" /** * @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 0x010a10 +#define MOD_HTTP2_VERSION_NUM 0x010a11 #endif /* mod_h2_h2_version_h */ -- 2.40.0