blob: a2c5b2e02a06de73371d6b4f0368e414278c9abe [file] [log] [blame]
Brad Bishop1a4b7ee2018-12-16 17:11:34 -08001From 484aba5048e3457dc1d15189f1910d007b1a4a76 Mon Sep 17 00:00:00 2001
2From: Jim Jagielski <jim@apache.org>
3Date: Wed, 12 Sep 2018 20:38:02 +0000
4Subject: [PATCH] Merge r1840010 from trunk:
5
6On the trunk:
7
8mod_http2: connection IO event handling reworked. Instead of reacting on
9 incoming bytes, the state machine now acts on incoming frames that are
10 affecting it. This reduces state transitions.
11
12
13Submitted by: icing
14Reviewed by: icing, ylavic, jim
15
16
17git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/branches/2.4.x@1840757 13f79535-47bb-0310-9956-ffa450edef68
18CVE: CVE-2018-11763
19Upstream-Status: Backport [https://github.com/apache/httpd/commit/484aba5048e3457dc1d15189f1910d007b1a4a76]
20
21Signed-off-by: Mingli Yu <Mingli.Yu@windriver.com>
22---
23 modules/http2/h2_session.c | 238 +++++++++++++++++++++++--------------
24 modules/http2/h2_session.h | 7 +-
25 modules/http2/h2_version.h | 4 +-
26 3 files changed, 158 insertions(+), 97 deletions(-)
27
28diff --git a/modules/http2/h2_session.c b/modules/http2/h2_session.c
29index 805d6774dc..a1b31d2b30 100644
30--- a/modules/http2/h2_session.c
31+++ b/modules/http2/h2_session.c
32@@ -235,6 +235,7 @@ static int on_data_chunk_recv_cb(nghttp2_session *ngh2, uint8_t flags,
33 stream = h2_session_stream_get(session, stream_id);
34 if (stream) {
35 status = h2_stream_recv_DATA(stream, flags, data, len);
36+ dispatch_event(session, H2_SESSION_EV_STREAM_CHANGE, 0, "stream data rcvd");
37 }
38 else {
39 ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, APLOGNO(03064)
40@@ -317,9 +318,9 @@ static int on_header_cb(nghttp2_session *ngh2, const nghttp2_frame *frame,
41 }
42
43 /**
44- * nghttp2 session has received a complete frame. Most, it uses
45- * for processing of internal state. HEADER and DATA frames however
46- * we need to handle ourself.
47+ * nghttp2 session has received a complete frame. Most are used by nghttp2
48+ * for processing of internal state. Some, like HEADER and DATA frames,
49+ * we need to act on.
50 */
51 static int on_frame_recv_cb(nghttp2_session *ng2s,
52 const nghttp2_frame *frame,
53@@ -378,6 +379,9 @@ static int on_frame_recv_cb(nghttp2_session *ng2s,
54 "h2_stream(%ld-%d): WINDOW_UPDATE incr=%d",
55 session->id, (int)frame->hd.stream_id,
56 frame->window_update.window_size_increment);
57+ if (nghttp2_session_want_write(session->ngh2)) {
58+ dispatch_event(session, H2_SESSION_EV_FRAME_RCVD, 0, "window update");
59+ }
60 break;
61 case NGHTTP2_RST_STREAM:
62 ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, APLOGNO(03067)
63@@ -404,6 +408,12 @@ static int on_frame_recv_cb(nghttp2_session *ng2s,
64 frame->goaway.error_code, NULL);
65 }
66 break;
67+ case NGHTTP2_SETTINGS:
68+ if (APLOGctrace2(session->c)) {
69+ ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, session->c,
70+ H2_SSSN_MSG(session, "SETTINGS, len=%ld"), (long)frame->hd.length);
71+ }
72+ break;
73 default:
74 if (APLOGctrace2(session->c)) {
75 char buffer[256];
76@@ -415,7 +425,40 @@ static int on_frame_recv_cb(nghttp2_session *ng2s,
77 }
78 break;
79 }
80- return (APR_SUCCESS == rv)? 0 : NGHTTP2_ERR_PROTO;
81+
82+ if (session->state == H2_SESSION_ST_IDLE) {
83+ /* We received a frame, but session is in state IDLE. That means the frame
84+ * did not really progress any of the (possibly) open streams. It was a meta
85+ * frame, e.g. SETTINGS/WINDOW_UPDATE/unknown/etc.
86+ * Remember: IDLE means we cannot send because either there are no streams open or
87+ * all open streams are blocked on exhausted WINDOWs for outgoing data.
88+ * The more frames we receive that do not change this, the less interested we
89+ * become in serving this connection. This is expressed in increasing "idle_delays".
90+ * Eventually, the connection will timeout and we'll close it. */
91+ session->idle_frames = H2MIN(session->idle_frames + 1, session->frames_received);
92+ ap_log_cerror( APLOG_MARK, APLOG_TRACE2, 0, session->c,
93+ H2_SSSN_MSG(session, "session has %ld idle frames"),
94+ (long)session->idle_frames);
95+ if (session->idle_frames > 10) {
96+ apr_size_t busy_frames = H2MAX(session->frames_received - session->idle_frames, 1);
97+ int idle_ratio = (int)(session->idle_frames / busy_frames);
98+ if (idle_ratio > 100) {
99+ session->idle_delay = apr_time_from_msec(H2MIN(1000, idle_ratio));
100+ }
101+ else if (idle_ratio > 10) {
102+ session->idle_delay = apr_time_from_msec(10);
103+ }
104+ else if (idle_ratio > 1) {
105+ session->idle_delay = apr_time_from_msec(1);
106+ }
107+ else {
108+ session->idle_delay = 0;
109+ }
110+ }
111+ }
112+
113+ if (APR_SUCCESS != rv) return NGHTTP2_ERR_PROTO;
114+ return 0;
115 }
116
117 static int h2_session_continue_data(h2_session *session) {
118@@ -1603,23 +1646,57 @@ static void update_child_status(h2_session *session, int status, const char *msg
119
120 static void transit(h2_session *session, const char *action, h2_session_state nstate)
121 {
122+ apr_time_t timeout;
123+ int ostate, loglvl;
124+ const char *s;
125+
126 if (session->state != nstate) {
127- int loglvl = APLOG_DEBUG;
128- if ((session->state == H2_SESSION_ST_BUSY && nstate == H2_SESSION_ST_WAIT)
129- || (session->state == H2_SESSION_ST_WAIT && nstate == H2_SESSION_ST_BUSY)){
130+ ostate = session->state;
131+ session->state = nstate;
132+
133+ loglvl = APLOG_DEBUG;
134+ if ((ostate == H2_SESSION_ST_BUSY && nstate == H2_SESSION_ST_WAIT)
135+ || (ostate == H2_SESSION_ST_WAIT && nstate == H2_SESSION_ST_BUSY)){
136 loglvl = APLOG_TRACE1;
137 }
138 ap_log_cerror(APLOG_MARK, loglvl, 0, session->c,
139 H2_SSSN_LOG(APLOGNO(03078), session,
140 "transit [%s] -- %s --> [%s]"),
141- h2_session_state_str(session->state), action,
142+ h2_session_state_str(ostate), action,
143 h2_session_state_str(nstate));
144- session->state = nstate;
145+
146 switch (session->state) {
147 case H2_SESSION_ST_IDLE:
148- update_child_status(session, (session->open_streams == 0?
149- SERVER_BUSY_KEEPALIVE
150- : SERVER_BUSY_READ), "idle");
151+ if (!session->remote.emitted_count) {
152+ /* on fresh connections, with async mpm, do not return
153+ * to mpm for a second. This gives the first request a better
154+ * chance to arrive (und connection leaving IDLE state).
155+ * If we return to mpm right away, this connection has the
156+ * same chance of being cleaned up by the mpm as connections
157+ * that already served requests - not fair. */
158+ session->idle_sync_until = apr_time_now() + apr_time_from_sec(1);
159+ s = "timeout";
160+ timeout = H2MAX(session->s->timeout, session->s->keep_alive_timeout);
161+ update_child_status(session, SERVER_BUSY_READ, "idle");
162+ ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, session->c,
163+ H2_SSSN_LOG("", session, "enter idle, timeout = %d sec"),
164+ (int)apr_time_sec(H2MAX(session->s->timeout, session->s->keep_alive_timeout)));
165+ }
166+ else if (session->open_streams) {
167+ s = "timeout";
168+ timeout = session->s->keep_alive_timeout;
169+ update_child_status(session, SERVER_BUSY_KEEPALIVE, "idle");
170+ }
171+ else {
172+ /* normal keepalive setup */
173+ s = "keepalive";
174+ timeout = session->s->keep_alive_timeout;
175+ update_child_status(session, SERVER_BUSY_KEEPALIVE, "idle");
176+ }
177+ session->idle_until = apr_time_now() + timeout;
178+ ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, session->c,
179+ H2_SSSN_LOG("", session, "enter idle, %s = %d sec"),
180+ s, (int)apr_time_sec(timeout));
181 break;
182 case H2_SESSION_ST_DONE:
183 update_child_status(session, SERVER_CLOSING, "done");
184@@ -1726,8 +1803,6 @@ static void h2_session_ev_no_io(h2_session *session, int arg, const char *msg)
185 * This means we only wait for WINDOW_UPDATE from the
186 * client and can block on READ. */
187 transit(session, "no io (flow wait)", H2_SESSION_ST_IDLE);
188- session->idle_until = apr_time_now() + session->s->timeout;
189- session->keep_sync_until = session->idle_until;
190 /* Make sure we have flushed all previously written output
191 * so that the client will react. */
192 if (h2_conn_io_flush(&session->io) != APR_SUCCESS) {
193@@ -1738,12 +1813,7 @@ static void h2_session_ev_no_io(h2_session *session, int arg, const char *msg)
194 }
195 else if (session->local.accepting) {
196 /* When we have no streams, but accept new, switch to idle */
197- apr_time_t now = apr_time_now();
198 transit(session, "no io (keepalive)", H2_SESSION_ST_IDLE);
199- session->idle_until = (session->remote.emitted_count?
200- session->s->keep_alive_timeout :
201- session->s->timeout) + now;
202- session->keep_sync_until = now + apr_time_from_sec(1);
203 }
204 else {
205 /* We are no longer accepting new streams and there are
206@@ -1758,12 +1828,25 @@ static void h2_session_ev_no_io(h2_session *session, int arg, const char *msg)
207 }
208 }
209
210-static void h2_session_ev_data_read(h2_session *session, int arg, const char *msg)
211+static void h2_session_ev_frame_rcvd(h2_session *session, int arg, const char *msg)
212+{
213+ switch (session->state) {
214+ case H2_SESSION_ST_IDLE:
215+ case H2_SESSION_ST_WAIT:
216+ transit(session, "frame received", H2_SESSION_ST_BUSY);
217+ break;
218+ default:
219+ /* nop */
220+ break;
221+ }
222+}
223+
224+static void h2_session_ev_stream_change(h2_session *session, int arg, const char *msg)
225 {
226 switch (session->state) {
227 case H2_SESSION_ST_IDLE:
228 case H2_SESSION_ST_WAIT:
229- transit(session, "data read", H2_SESSION_ST_BUSY);
230+ transit(session, "stream change", H2_SESSION_ST_BUSY);
231 break;
232 default:
233 /* nop */
234@@ -1803,16 +1886,6 @@ static void h2_session_ev_pre_close(h2_session *session, int arg, const char *ms
235 static void ev_stream_open(h2_session *session, h2_stream *stream)
236 {
237 h2_iq_append(session->in_process, stream->id);
238- switch (session->state) {
239- case H2_SESSION_ST_IDLE:
240- if (session->open_streams == 1) {
241- /* enter timeout, since we have a stream again */
242- session->idle_until = (session->s->timeout + apr_time_now());
243- }
244- break;
245- default:
246- break;
247- }
248 }
249
250 static void ev_stream_closed(h2_session *session, h2_stream *stream)
251@@ -1825,11 +1898,6 @@ static void ev_stream_closed(h2_session *session, h2_stream *stream)
252 }
253 switch (session->state) {
254 case H2_SESSION_ST_IDLE:
255- if (session->open_streams == 0) {
256- /* enter keepalive timeout, since we no longer have streams */
257- session->idle_until = (session->s->keep_alive_timeout
258- + apr_time_now());
259- }
260 break;
261 default:
262 break;
263@@ -1887,6 +1955,7 @@ static void on_stream_state_enter(void *ctx, h2_stream *stream)
264 default:
265 break;
266 }
267+ dispatch_event(session, H2_SESSION_EV_STREAM_CHANGE, 0, "stream state change");
268 }
269
270 static void on_stream_event(void *ctx, h2_stream *stream,
271@@ -1945,8 +2014,8 @@ static void dispatch_event(h2_session *session, h2_session_event_t ev,
272 case H2_SESSION_EV_NO_IO:
273 h2_session_ev_no_io(session, arg, msg);
274 break;
275- case H2_SESSION_EV_DATA_READ:
276- h2_session_ev_data_read(session, arg, msg);
277+ case H2_SESSION_EV_FRAME_RCVD:
278+ h2_session_ev_frame_rcvd(session, arg, msg);
279 break;
280 case H2_SESSION_EV_NGH2_DONE:
281 h2_session_ev_ngh2_done(session, arg, msg);
282@@ -1957,6 +2026,9 @@ static void dispatch_event(h2_session *session, h2_session_event_t ev,
283 case H2_SESSION_EV_PRE_CLOSE:
284 h2_session_ev_pre_close(session, arg, msg);
285 break;
286+ case H2_SESSION_EV_STREAM_CHANGE:
287+ h2_session_ev_stream_change(session, arg, msg);
288+ break;
289 default:
290 ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, session->c,
291 H2_SSSN_MSG(session, "unknown event %d"), ev);
292@@ -1990,13 +2062,15 @@ apr_status_t h2_session_process(h2_session *session, int async)
293 apr_status_t status = APR_SUCCESS;
294 conn_rec *c = session->c;
295 int rv, mpm_state, trace = APLOGctrace3(c);
296-
297+ apr_time_t now;
298+
299 if (trace) {
300 ap_log_cerror( APLOG_MARK, APLOG_TRACE3, status, c,
301 H2_SSSN_MSG(session, "process start, async=%d"), async);
302 }
303
304 while (session->state != H2_SESSION_ST_DONE) {
305+ now = apr_time_now();
306 session->have_read = session->have_written = 0;
307
308 if (session->local.accepting
309@@ -2034,39 +2108,42 @@ apr_status_t h2_session_process(h2_session *session, int async)
310 break;
311
312 case H2_SESSION_ST_IDLE:
313- /* We trust our connection into the default timeout/keepalive
314- * handling of the core filters/mpm iff:
315- * - keep_sync_until is not set
316- * - we have an async mpm
317- * - we have no open streams to process
318- * - we are not sitting on a Upgrade: request
319- * - we already have seen at least one request
320- */
321- if (!session->keep_sync_until && async && !session->open_streams
322- && !session->r && session->remote.emitted_count) {
323+ if (session->idle_until && (apr_time_now() + session->idle_delay) > session->idle_until) {
324+ ap_log_cerror( APLOG_MARK, APLOG_TRACE1, status, c,
325+ H2_SSSN_MSG(session, "idle, timeout reached, closing"));
326+ if (session->idle_delay) {
327+ apr_table_setn(session->c->notes, "short-lingering-close", "1");
328+ }
329+ dispatch_event(session, H2_SESSION_EV_CONN_TIMEOUT, 0, "timeout");
330+ goto out;
331+ }
332+
333+ if (session->idle_delay) {
334+ /* we are less interested in spending time on this connection */
335+ ap_log_cerror( APLOG_MARK, APLOG_TRACE2, status, c,
336+ H2_SSSN_MSG(session, "session is idle (%ld ms), idle wait %ld sec left"),
337+ (long)apr_time_as_msec(session->idle_delay),
338+ (long)apr_time_sec(session->idle_until - now));
339+ apr_sleep(session->idle_delay);
340+ session->idle_delay = 0;
341+ }
342+
343+ h2_conn_io_flush(&session->io);
344+ if (async && !session->r && (now > session->idle_sync_until)) {
345 if (trace) {
346 ap_log_cerror(APLOG_MARK, APLOG_TRACE3, status, c,
347 H2_SSSN_MSG(session,
348 "nonblock read, %d streams open"),
349 session->open_streams);
350 }
351- h2_conn_io_flush(&session->io);
352 status = h2_session_read(session, 0);
353
354 if (status == APR_SUCCESS) {
355 session->have_read = 1;
356- dispatch_event(session, H2_SESSION_EV_DATA_READ, 0, NULL);
357 }
358- else if (APR_STATUS_IS_EAGAIN(status)
359- || APR_STATUS_IS_TIMEUP(status)) {
360- if (apr_time_now() > session->idle_until) {
361- dispatch_event(session,
362- H2_SESSION_EV_CONN_TIMEOUT, 0, NULL);
363- }
364- else {
365- status = APR_EAGAIN;
366- goto out;
367- }
368+ else if (APR_STATUS_IS_EAGAIN(status) || APR_STATUS_IS_TIMEUP(status)) {
369+ status = APR_EAGAIN;
370+ goto out;
371 }
372 else {
373 ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, c,
374@@ -2078,7 +2155,6 @@ apr_status_t h2_session_process(h2_session *session, int async)
375 }
376 else {
377 /* make certain, we send everything before we idle */
378- h2_conn_io_flush(&session->io);
379 if (trace) {
380 ap_log_cerror(APLOG_MARK, APLOG_TRACE3, status, c,
381 H2_SSSN_MSG(session,
382@@ -2090,7 +2166,6 @@ apr_status_t h2_session_process(h2_session *session, int async)
383 */
384 status = h2_mplx_idle(session->mplx);
385 if (status == APR_EAGAIN) {
386- dispatch_event(session, H2_SESSION_EV_DATA_READ, 0, NULL);
387 break;
388 }
389 else if (status != APR_SUCCESS) {
390@@ -2101,33 +2176,11 @@ apr_status_t h2_session_process(h2_session *session, int async)
391 status = h2_session_read(session, 1);
392 if (status == APR_SUCCESS) {
393 session->have_read = 1;
394- dispatch_event(session, H2_SESSION_EV_DATA_READ, 0, NULL);
395 }
396 else if (status == APR_EAGAIN) {
397 /* nothing to read */
398 }
399 else if (APR_STATUS_IS_TIMEUP(status)) {
400- apr_time_t now = apr_time_now();
401- if (now > session->keep_sync_until) {
402- /* if we are on an async mpm, now is the time that
403- * we may dare to pass control to it. */
404- session->keep_sync_until = 0;
405- }
406- if (now > session->idle_until) {
407- if (trace) {
408- ap_log_cerror(APLOG_MARK, APLOG_TRACE3, status, c,
409- H2_SSSN_MSG(session,
410- "keepalive timeout"));
411- }
412- dispatch_event(session,
413- H2_SESSION_EV_CONN_TIMEOUT, 0, "timeout");
414- }
415- else if (trace) {
416- ap_log_cerror(APLOG_MARK, APLOG_TRACE3, status, c,
417- H2_SSSN_MSG(session,
418- "keepalive, %f sec left"),
419- (session->idle_until - now) / 1000000.0f);
420- }
421 /* continue reading handling */
422 }
423 else if (APR_STATUS_IS_ECONNABORTED(status)
424@@ -2145,6 +2198,18 @@ apr_status_t h2_session_process(h2_session *session, int async)
425 dispatch_event(session, H2_SESSION_EV_CONN_ERROR, 0, "error");
426 }
427 }
428+ if (nghttp2_session_want_write(session->ngh2)) {
429+ ap_update_child_status(session->c->sbh, SERVER_BUSY_WRITE, NULL);
430+ status = h2_session_send(session);
431+ if (status == APR_SUCCESS) {
432+ status = h2_conn_io_flush(&session->io);
433+ }
434+ if (status != APR_SUCCESS) {
435+ dispatch_event(session, H2_SESSION_EV_CONN_ERROR,
436+ H2_ERR_INTERNAL_ERROR, "writing");
437+ break;
438+ }
439+ }
440 break;
441
442 case H2_SESSION_ST_BUSY:
443@@ -2154,7 +2219,6 @@ apr_status_t h2_session_process(h2_session *session, int async)
444 status = h2_session_read(session, 0);
445 if (status == APR_SUCCESS) {
446 session->have_read = 1;
447- dispatch_event(session, H2_SESSION_EV_DATA_READ, 0, NULL);
448 }
449 else if (status == APR_EAGAIN) {
450 /* nothing to read */
451@@ -2218,7 +2282,7 @@ apr_status_t h2_session_process(h2_session *session, int async)
452 session->iowait);
453 if (status == APR_SUCCESS) {
454 session->wait_us = 0;
455- dispatch_event(session, H2_SESSION_EV_DATA_READ, 0, NULL);
456+ dispatch_event(session, H2_SESSION_EV_STREAM_CHANGE, 0, NULL);
457 }
458 else if (APR_STATUS_IS_TIMEUP(status)) {
459 /* go back to checking all inputs again */
460diff --git a/modules/http2/h2_session.h b/modules/http2/h2_session.h
461index 486938b009..df2a862445 100644
462--- a/modules/http2/h2_session.h
463+++ b/modules/http2/h2_session.h
464@@ -66,10 +66,11 @@ typedef enum {
465 H2_SESSION_EV_PROTO_ERROR, /* protocol error */
466 H2_SESSION_EV_CONN_TIMEOUT, /* connection timeout */
467 H2_SESSION_EV_NO_IO, /* nothing has been read or written */
468- H2_SESSION_EV_DATA_READ, /* connection data has been read */
469+ H2_SESSION_EV_FRAME_RCVD, /* a frame has been received */
470 H2_SESSION_EV_NGH2_DONE, /* nghttp2 wants neither read nor write anything */
471 H2_SESSION_EV_MPM_STOPPING, /* the process is stopping */
472 H2_SESSION_EV_PRE_CLOSE, /* connection will close after this */
473+ H2_SESSION_EV_STREAM_CHANGE, /* a stream (state/input/output) changed */
474 } h2_session_event_t;
475
476 typedef struct h2_session {
477@@ -118,7 +119,9 @@ typedef struct h2_session {
478 apr_size_t max_stream_mem; /* max buffer memory for a single stream */
479
480 apr_time_t idle_until; /* Time we shut down due to sheer boredom */
481- apr_time_t keep_sync_until; /* Time we sync wait until passing to async mpm */
482+ apr_time_t idle_sync_until; /* Time we sync wait until keepalive handling kicks in */
483+ apr_size_t idle_frames; /* number of rcvd frames that kept session in idle state */
484+ apr_interval_time_t idle_delay; /* Time we delay processing rcvd frames in idle state */
485
486 apr_bucket_brigade *bbtmp; /* brigade for keeping temporary data */
487 struct apr_thread_cond_t *iowait; /* our cond when trywaiting for data */
488diff --git a/modules/http2/h2_version.h b/modules/http2/h2_version.h
489index 5c53abd575..2ac718fc0f 100644
490--- a/modules/http2/h2_version.h
491+++ b/modules/http2/h2_version.h
492@@ -27,7 +27,7 @@
493 * @macro
494 * Version number of the http2 module as c string
495 */
496-#define MOD_HTTP2_VERSION "1.10.20"
497+#define MOD_HTTP2_VERSION "1.11.0"
498
499 /**
500 * @macro
501@@ -35,7 +35,7 @@
502 * release. This is a 24 bit number with 8 bits for major number, 8 bits
503 * for minor and 8 bits for patch. Version 1.2.3 becomes 0x010203.
504 */
505-#define MOD_HTTP2_VERSION_NUM 0x010a14
506+#define MOD_HTTP2_VERSION_NUM 0x010b00
507
508
509 #endif /* mod_h2_h2_version_h */
510--
5112.17.1
512