From: Stefan Eissing Date: Wed, 18 May 2016 14:39:33 +0000 (+0000) Subject: mod_http2: fixes timeout vs. keepalive timeout use when closing streams on flush... X-Git-Tag: 2.5.0-alpha~1609 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=c242fa55572969d9143c45941622f3b84535bf44;p=thirdparty%2Fapache%2Fhttpd.git mod_http2: fixes timeout vs. keepalive timeout use when closing streams on flush, adding pseudo header length check against limit_req_line git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/trunk@1744415 13f79535-47bb-0310-9956-ffa450edef68 --- diff --git a/CHANGES b/CHANGES index 45c15063a1c..12acb7d4900 100644 --- a/CHANGES +++ b/CHANGES @@ -1,9 +1,13 @@ -*- coding: utf-8 -*- Changes with Apache 2.5.0 + *) mod_http2: Fix async write issue that led to selection of wrong timeout + vs. keepalive timeout selection for idle sessions. + *) mod_http2: checking LimitRequestLine, LimitRequestFields and - LimitRequestFieldSize configurated values for incoming streams. - [Stefan Eissing] + LimitRequestFieldSize configurated values for incoming streams. Returning + HTTP status 431 for too long/many headers fields and 414 for a too long + pseudo header. [Stefan Eissing] *) mod_http2: tracking conn_rec->current_thread on slave connections, so that mod_lua finds the correct one. Fixes PR 59542. [Stefan Eissing] diff --git a/modules/http2/h2_session.c b/modules/http2/h2_session.c index 999a360f283..cdee085fa29 100644 --- a/modules/http2/h2_session.c +++ b/modules/http2/h2_session.c @@ -133,7 +133,6 @@ h2_stream *h2_session_open_stream(h2_session *session, int stream_id, stream = h2_stream_open(stream_id, stream_pool, session, initiated_on, req); - ++session->open_streams; ++session->unanswered_streams; nghttp2_session_set_stream_user_data(session->ngh2, stream_id, stream); h2_ihash_add(session->streams, stream); @@ -151,6 +150,7 @@ h2_stream *h2_session_open_stream(h2_session *session, int stream_id, session->remote.emitted_max = stream->id; } } + dispatch_event(session, H2_SESSION_EV_STREAM_OPEN, 0, NULL); return stream; } @@ -252,7 +252,7 @@ static int on_invalid_frame_recv_cb(nghttp2_session *ngh2, h2_util_frame_print(frame, buffer, sizeof(buffer)/sizeof(buffer[0])); ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, APLOGNO(03063) - "h2_session(%ld): recv unknown FRAME[%s], frames=%ld/%ld (r/s)", + "h2_session(%ld): recv invalid FRAME[%s], frames=%ld/%ld (r/s)", session->id, buffer, (long)session->frames_received, (long)session->frames_sent); } @@ -386,7 +386,6 @@ static int on_header_cb(nghttp2_session *ngh2, const nghttp2_frame *frame, h2_stream * stream; apr_status_t status; - (void)ngh2; (void)flags; if (!is_accepting_streams(session)) { /* just ignore */ @@ -397,15 +396,14 @@ static int on_header_cb(nghttp2_session *ngh2, const nghttp2_frame *frame, if (!stream) { ap_log_cerror(APLOG_MARK, APLOG_ERR, 0, session->c, APLOGNO(02920) - "h2_session: stream(%ld-%d): on_header for unknown stream", + "h2_session: stream(%ld-%d): on_header unknown stream", session->id, (int)frame->hd.stream_id); return NGHTTP2_ERR_TEMPORAL_CALLBACK_FAILURE; } status = h2_stream_add_header(stream, (const char *)name, namelen, (const char *)value, valuelen); - - if (status != APR_SUCCESS) { + if (status != APR_SUCCESS && !stream->response) { return NGHTTP2_ERR_TEMPORAL_CALLBACK_FAILURE; } return 0; @@ -1294,6 +1292,7 @@ static apr_status_t submit_response(h2_session *session, h2_stream *stream) stream->id, err); } + stream->submitted = 1; --session->unanswered_streams; if (stream->request && stream->request->initiated_on) { ++session->pushes_submitted; @@ -1301,7 +1300,6 @@ static apr_status_t submit_response(h2_session *session, h2_stream *stream) else { ++session->responses_submitted; } - stream->submitted = 1; if (nghttp2_is_fatal(rv)) { status = APR_EGENERAL; @@ -1473,10 +1471,10 @@ apr_status_t h2_session_stream_done(h2_session *session, h2_stream *stream) "h2_stream(%ld-%d): EOS bucket cleanup -> done", session->id, stream->id); h2_ihash_remove(session->streams, stream->id); - --session->open_streams; --session->unanswered_streams; h2_mplx_stream_done(session->mplx, stream); + dispatch_event(session, H2_SESSION_EV_STREAM_DONE, 0, NULL); return APR_SUCCESS; } @@ -1862,6 +1860,9 @@ static void h2_session_ev_no_io(h2_session *session, int arg, const char *msg) * CPU cycles. Ideally, we'd like to do a blocking read, but that * is not possible if we have scheduled tasks and wait * for them to produce something. */ + ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, session->c, + "h2_session(%ld): NO_IO event, %d streams open", + session->id, session->open_streams); if (!session->open_streams) { if (!is_accepting_streams(session)) { /* We are no longer accepting new streams and have @@ -1873,7 +1874,7 @@ static void h2_session_ev_no_io(h2_session *session, int arg, const char *msg) apr_time_t now = apr_time_now(); /* When we have no streams, no task event are possible, * switch to blocking reads */ - transit(session, "no io", H2_SESSION_ST_IDLE); + transit(session, "no io (keepalive)", H2_SESSION_ST_IDLE); session->idle_until = (session->remote.emitted_count? session->s->keep_alive_timeout : session->s->timeout) + now; @@ -1882,6 +1883,9 @@ static void h2_session_ev_no_io(h2_session *session, int arg, const char *msg) } else if (!has_unsubmitted_streams(session) && !has_suspended_streams(session)) { + transit(session, "no io (flow wait)", H2_SESSION_ST_IDLE); + session->idle_until = apr_time_now() + session->s->timeout; + session->keep_sync_until = session->idle_until; /* none of our streams is waiting for a response or * new output data from task processing, * switch to blocking reads. We are probably waiting on @@ -1890,9 +1894,6 @@ static void h2_session_ev_no_io(h2_session *session, int arg, const char *msg) dispatch_event(session, H2_SESSION_EV_CONN_ERROR, 0, NULL); return; } - transit(session, "no io", H2_SESSION_ST_IDLE); - session->idle_until = apr_time_now() + session->s->timeout; - session->keep_sync_until = session->idle_until; } else { /* Unable to do blocking reads, as we wait on events from @@ -1970,6 +1971,39 @@ static void h2_session_ev_pre_close(h2_session *session, int arg, const char *ms } } +static void h2_session_ev_stream_open(h2_session *session, int arg, const char *msg) +{ + ++session->open_streams; + switch (session->state) { + case H2_SESSION_ST_IDLE: + if (session->open_streams == 1) { + /* enter tiomeout, since we have a stream again */ + session->idle_until = (session->s->timeout + apr_time_now()); + } + break; + default: + break; + } +} + +static void h2_session_ev_stream_done(h2_session *session, int arg, const char *msg) +{ + --session->open_streams; + if (session->open_streams <= 0) { + } + switch (session->state) { + case H2_SESSION_ST_IDLE: + if (session->open_streams == 0) { + /* enter keepalive timeout, since we no longer have streams */ + session->idle_until = (session->s->keep_alive_timeout + + apr_time_now()); + } + break; + default: + break; + } +} + static void dispatch_event(h2_session *session, h2_session_event_t ev, int arg, const char *msg) { @@ -2010,6 +2044,12 @@ static void dispatch_event(h2_session *session, h2_session_event_t ev, case H2_SESSION_EV_PRE_CLOSE: h2_session_ev_pre_close(session, arg, msg); break; + case H2_SESSION_EV_STREAM_OPEN: + h2_session_ev_stream_open(session, arg, msg); + break; + case H2_SESSION_EV_STREAM_DONE: + h2_session_ev_stream_done(session, arg, msg); + break; default: ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, session->c, "h2_session(%ld): unknown event %d", @@ -2074,8 +2114,10 @@ apr_status_t h2_session_process(h2_session *session, int async) /* make certain, we send everything before we idle */ if (!session->keep_sync_until && async && !session->open_streams && !session->r && session->remote.emitted_count) { - ap_log_cerror( APLOG_MARK, APLOG_TRACE1, status, c, - "h2_session(%ld): async idle, nonblock read", session->id); + ap_log_cerror( APLOG_MARK, APLOG_TRACE3, status, c, + "h2_session(%ld): async idle, nonblock read, " + "%d streams open", session->id, + session->open_streams); /* We do not return to the async mpm immediately, since under * load, mpms show the tendency to throw keep_alive connections * away very rapidly. @@ -2108,6 +2150,10 @@ apr_status_t h2_session_process(h2_session *session, int async) } } else { + ap_log_cerror( APLOG_MARK, APLOG_TRACE3, status, c, + "h2_session(%ld): sync idle, stutter 1-sec, " + "%d streams open", session->id, + session->open_streams); /* We wait in smaller increments, using a 1 second timeout. * That gives us the chance to check for MPMQ_STOPPING often. */ @@ -2133,8 +2179,16 @@ apr_status_t h2_session_process(h2_session *session, int async) session->keep_sync_until = 0; } if (now > session->idle_until) { + ap_log_cerror( APLOG_MARK, APLOG_TRACE3, status, c, + "h2_session(%ld): keepalive timeout", + session->id); dispatch_event(session, H2_SESSION_EV_CONN_TIMEOUT, 0, "timeout"); } + else { + ap_log_cerror( APLOG_MARK, APLOG_TRACE3, status, c, + "h2_session(%ld): keepalive, %f sec left", + session->id, (session->idle_until - now) / 1000000.0f); + } /* continue reading handling */ } else { diff --git a/modules/http2/h2_session.h b/modules/http2/h2_session.h index 32202dc3030..06142f5ae7f 100644 --- a/modules/http2/h2_session.h +++ b/modules/http2/h2_session.h @@ -70,6 +70,8 @@ typedef enum { H2_SESSION_EV_NGH2_DONE, /* nghttp2 wants neither read nor write anything */ H2_SESSION_EV_MPM_STOPPING, /* the process is stopping */ H2_SESSION_EV_PRE_CLOSE, /* connection will close after this */ + H2_SESSION_EV_STREAM_OPEN, /* stream has been opened */ + H2_SESSION_EV_STREAM_DONE, /* stream has been handled completely */ } h2_session_event_t; typedef struct h2_session { diff --git a/modules/http2/h2_stream.c b/modules/http2/h2_stream.c index 9f55d0276fb..dc29d7060c0 100644 --- a/modules/http2/h2_stream.c +++ b/modules/http2/h2_stream.c @@ -290,39 +290,38 @@ apr_status_t h2_stream_add_header(h2_stream *stream, const char *value, size_t vlen) { AP_DEBUG_ASSERT(stream); - if (stream->response) { - /* already have the response, ignore any more request headers - (hint: response might already be a failure due to previous errs */ - return APR_SUCCESS; - } - - if ((nlen > 0) && name[0] == ':') { - if ((vlen) > stream->session->s->limit_req_line) { - /* pseudo header: approximation of request line size check */ + if (!stream->response) { + if (name[0] == ':') { + if ((vlen) > stream->session->s->limit_req_line) { + /* pseudo header: approximation of request line size check */ + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, stream->session->c, + "h2_stream(%ld-%d): pseudo header %s too long", + stream->session->id, stream->id, name); + return h2_stream_set_error(stream, + HTTP_REQUEST_URI_TOO_LARGE); + } + } + else if ((nlen + 2 + vlen) > stream->session->s->limit_req_fieldsize) { + /* header too long */ ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, stream->session->c, - "h2_stream(%ld-%d): pseudo header %s too long", + "h2_stream(%ld-%d): header %s too long", stream->session->id, stream->id, name); return h2_stream_set_error(stream, HTTP_REQUEST_HEADER_FIELDS_TOO_LARGE); } - } - else if ((nlen + 2 + vlen) > stream->session->s->limit_req_fieldsize) { - /* header too long */ - ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, stream->session->c, - "h2_stream(%ld-%d): header %s too long", - stream->session->id, stream->id, name); - return h2_stream_set_error(stream, - HTTP_REQUEST_HEADER_FIELDS_TOO_LARGE); - } - - ++stream->request_headers_added; - if (stream->request_headers_added > stream->session->s->limit_req_fields) { - /* too many header lines */ - ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, stream->session->c, - "h2_stream(%ld-%d): too many header lines", - stream->session->id, stream->id); - return h2_stream_set_error(stream, - HTTP_REQUEST_HEADER_FIELDS_TOO_LARGE); + + if (name[0] != ':') { + ++stream->request_headers_added; + if (stream->request_headers_added + > stream->session->s->limit_req_fields) { + /* too many header lines */ + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, stream->session->c, + "h2_stream(%ld-%d): too many header lines", + stream->session->id, stream->id); + return h2_stream_set_error(stream, + HTTP_REQUEST_HEADER_FIELDS_TOO_LARGE); + } + } } if (h2_stream_is_scheduled(stream)) {