From 484aba5048e3457dc1d15189f1910d007b1a4a76 Mon Sep 17 00:00:00 2001
From: Jim Jagielski <jim@apache.org>
Date: Wed, 12 Sep 2018 20:38:02 +0000
Subject: [PATCH] Merge r1840010 from trunk:

On the trunk:

mod_http2: connection IO event handling reworked. Instead of reacting on
     incoming bytes, the state machine now acts on incoming frames that are
     affecting it. This reduces state transitions.


Submitted by: icing
Reviewed by: icing, ylavic, jim


git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/branches/2.4.x@1840757 13f79535-47bb-0310-9956-ffa450edef68
CVE: CVE-2018-11763
Upstream-Status: Backport [https://github.com/apache/httpd/commit/484aba5048e3457dc1d15189f1910d007b1a4a76]

Signed-off-by: Mingli Yu <Mingli.Yu@windriver.com>
---
 modules/http2/h2_session.c | 238 +++++++++++++++++++++++--------------
 modules/http2/h2_session.h |   7 +-
 modules/http2/h2_version.h |   4 +-
 3 files changed, 158 insertions(+), 97 deletions(-)

diff --git a/modules/http2/h2_session.c b/modules/http2/h2_session.c
index 805d6774dc..a1b31d2b30 100644
--- a/modules/http2/h2_session.c
+++ b/modules/http2/h2_session.c
@@ -235,6 +235,7 @@ static int on_data_chunk_recv_cb(nghttp2_session *ngh2, uint8_t flags,
     stream = h2_session_stream_get(session, stream_id);
     if (stream) {
         status = h2_stream_recv_DATA(stream, flags, data, len);
+        dispatch_event(session, H2_SESSION_EV_STREAM_CHANGE, 0, "stream data rcvd");
     }
     else {
         ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, APLOGNO(03064)
@@ -317,9 +318,9 @@ static int on_header_cb(nghttp2_session *ngh2, const nghttp2_frame *frame,
 }
 
 /**
- * nghttp2 session has received a complete frame. Most, it uses
- * for processing of internal state. HEADER and DATA frames however
- * we need to handle ourself.
+ * nghttp2 session has received a complete frame. Most are used by nghttp2
+ * for processing of internal state. Some, like HEADER and DATA frames,
+ * we need to act on.
  */
 static int on_frame_recv_cb(nghttp2_session *ng2s,
                             const nghttp2_frame *frame,
@@ -378,6 +379,9 @@ static int on_frame_recv_cb(nghttp2_session *ng2s,
                           "h2_stream(%ld-%d): WINDOW_UPDATE incr=%d", 
                           session->id, (int)frame->hd.stream_id,
                           frame->window_update.window_size_increment);
+            if (nghttp2_session_want_write(session->ngh2)) {
+                dispatch_event(session, H2_SESSION_EV_FRAME_RCVD, 0, "window update");
+            }
             break;
         case NGHTTP2_RST_STREAM:
             ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, APLOGNO(03067)
@@ -404,6 +408,12 @@ static int on_frame_recv_cb(nghttp2_session *ng2s,
                                frame->goaway.error_code, NULL);
             }
             break;
+        case NGHTTP2_SETTINGS:
+            if (APLOGctrace2(session->c)) {
+                ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, session->c,
+                              H2_SSSN_MSG(session, "SETTINGS, len=%ld"), (long)frame->hd.length);
+            }
+            break;
         default:
             if (APLOGctrace2(session->c)) {
                 char buffer[256];
@@ -415,7 +425,40 @@ static int on_frame_recv_cb(nghttp2_session *ng2s,
             }
             break;
     }
-    return (APR_SUCCESS == rv)? 0 : NGHTTP2_ERR_PROTO;
+    
+    if (session->state == H2_SESSION_ST_IDLE) {
+        /* We received a frame, but session is in state IDLE. That means the frame
+         * did not really progress any of the (possibly) open streams. It was a meta
+         * frame, e.g. SETTINGS/WINDOW_UPDATE/unknown/etc.
+         * Remember: IDLE means we cannot send because either there are no streams open or
+         * all open streams are blocked on exhausted WINDOWs for outgoing data.
+         * The more frames we receive that do not change this, the less interested we
+         * become in serving this connection. This is expressed in increasing "idle_delays".
+         * Eventually, the connection will timeout and we'll close it. */
+        session->idle_frames = H2MIN(session->idle_frames + 1, session->frames_received);
+            ap_log_cerror( APLOG_MARK, APLOG_TRACE2, 0, session->c,
+                          H2_SSSN_MSG(session, "session has %ld idle frames"), 
+                          (long)session->idle_frames);
+        if (session->idle_frames > 10) {
+            apr_size_t busy_frames = H2MAX(session->frames_received - session->idle_frames, 1);
+            int idle_ratio = (int)(session->idle_frames / busy_frames); 
+            if (idle_ratio > 100) {
+                session->idle_delay = apr_time_from_msec(H2MIN(1000, idle_ratio));
+            }
+            else if (idle_ratio > 10) {
+                session->idle_delay = apr_time_from_msec(10);
+            }
+            else if (idle_ratio > 1) {
+                session->idle_delay = apr_time_from_msec(1);
+            }
+            else {
+                session->idle_delay = 0;
+            }
+        }
+    }
+    
+    if (APR_SUCCESS != rv) return NGHTTP2_ERR_PROTO;
+    return 0;
 }
 
 static int h2_session_continue_data(h2_session *session) {
@@ -1603,23 +1646,57 @@ static void update_child_status(h2_session *session, int status, const char *msg
 
 static void transit(h2_session *session, const char *action, h2_session_state nstate)
 {
+    apr_time_t timeout;
+    int ostate, loglvl;
+    const char *s;
+    
     if (session->state != nstate) {
-        int loglvl = APLOG_DEBUG;
-        if ((session->state == H2_SESSION_ST_BUSY && nstate == H2_SESSION_ST_WAIT)
-            || (session->state == H2_SESSION_ST_WAIT && nstate == H2_SESSION_ST_BUSY)){
+        ostate = session->state;
+        session->state = nstate;
+        
+        loglvl = APLOG_DEBUG;
+        if ((ostate == H2_SESSION_ST_BUSY && nstate == H2_SESSION_ST_WAIT)
+            || (ostate == H2_SESSION_ST_WAIT && nstate == H2_SESSION_ST_BUSY)){
             loglvl = APLOG_TRACE1;
         }
         ap_log_cerror(APLOG_MARK, loglvl, 0, session->c, 
                       H2_SSSN_LOG(APLOGNO(03078), session, 
                       "transit [%s] -- %s --> [%s]"), 
-                      h2_session_state_str(session->state), action, 
+                      h2_session_state_str(ostate), action, 
                       h2_session_state_str(nstate));
-        session->state = nstate;
+        
         switch (session->state) {
             case H2_SESSION_ST_IDLE:
-                update_child_status(session, (session->open_streams == 0? 
-                                              SERVER_BUSY_KEEPALIVE
-                                              : SERVER_BUSY_READ), "idle");
+                if (!session->remote.emitted_count) {
+                    /* on fresh connections, with async mpm, do not return
+                     * to mpm for a second. This gives the first request a better
+                     * chance to arrive (und connection leaving IDLE state).
+                     * If we return to mpm right away, this connection has the
+                     * same chance of being cleaned up by the mpm as connections
+                     * that already served requests - not fair. */
+                    session->idle_sync_until = apr_time_now() + apr_time_from_sec(1);
+                    s = "timeout";
+                    timeout = H2MAX(session->s->timeout, session->s->keep_alive_timeout);
+                    update_child_status(session, SERVER_BUSY_READ, "idle");
+                    ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, session->c, 
+                                  H2_SSSN_LOG("", session, "enter idle, timeout = %d sec"), 
+                                  (int)apr_time_sec(H2MAX(session->s->timeout, session->s->keep_alive_timeout)));
+                }
+                else if (session->open_streams) {
+                    s = "timeout";
+                    timeout = session->s->keep_alive_timeout;
+                    update_child_status(session, SERVER_BUSY_KEEPALIVE, "idle");
+                }
+                else {
+                    /* normal keepalive setup */
+                    s = "keepalive";
+                    timeout = session->s->keep_alive_timeout;
+                    update_child_status(session, SERVER_BUSY_KEEPALIVE, "idle");
+                }
+                session->idle_until = apr_time_now() + timeout; 
+                ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, session->c, 
+                              H2_SSSN_LOG("", session, "enter idle, %s = %d sec"), 
+                              s, (int)apr_time_sec(timeout));
                 break;
             case H2_SESSION_ST_DONE:
                 update_child_status(session, SERVER_CLOSING, "done");
@@ -1726,8 +1803,6 @@ static void h2_session_ev_no_io(h2_session *session, int arg, const char *msg)
                      * This means we only wait for WINDOW_UPDATE from the 
                      * client and can block on READ. */
                     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;
                     /* Make sure we have flushed all previously written output
                      * so that the client will react. */
                     if (h2_conn_io_flush(&session->io) != APR_SUCCESS) {
@@ -1738,12 +1813,7 @@ static void h2_session_ev_no_io(h2_session *session, int arg, const char *msg)
             }
             else if (session->local.accepting) {
                 /* When we have no streams, but accept new, switch to idle */
-                apr_time_t now = apr_time_now();
                 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;
-                session->keep_sync_until = now + apr_time_from_sec(1);
             }
             else {
                 /* We are no longer accepting new streams and there are
@@ -1758,12 +1828,25 @@ static void h2_session_ev_no_io(h2_session *session, int arg, const char *msg)
     }
 }
 
-static void h2_session_ev_data_read(h2_session *session, int arg, const char *msg)
+static void h2_session_ev_frame_rcvd(h2_session *session, int arg, const char *msg)
+{
+    switch (session->state) {
+        case H2_SESSION_ST_IDLE:
+        case H2_SESSION_ST_WAIT:
+            transit(session, "frame received", H2_SESSION_ST_BUSY);
+            break;
+        default:
+            /* nop */
+            break;
+    }
+}
+
+static void h2_session_ev_stream_change(h2_session *session, int arg, const char *msg)
 {
     switch (session->state) {
         case H2_SESSION_ST_IDLE:
         case H2_SESSION_ST_WAIT:
-            transit(session, "data read", H2_SESSION_ST_BUSY);
+            transit(session, "stream change", H2_SESSION_ST_BUSY);
             break;
         default:
             /* nop */
@@ -1803,16 +1886,6 @@ static void h2_session_ev_pre_close(h2_session *session, int arg, const char *ms
 static void ev_stream_open(h2_session *session, h2_stream *stream)
 {
     h2_iq_append(session->in_process, stream->id);
-    switch (session->state) {
-        case H2_SESSION_ST_IDLE:
-            if (session->open_streams == 1) {
-                /* enter timeout, since we have a stream again */
-                session->idle_until = (session->s->timeout + apr_time_now());
-            }
-            break;
-        default:
-            break;
-    }
 }
 
 static void ev_stream_closed(h2_session *session, h2_stream *stream)
@@ -1825,11 +1898,6 @@ static void ev_stream_closed(h2_session *session, h2_stream *stream)
     }
     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;
@@ -1887,6 +1955,7 @@ static void on_stream_state_enter(void *ctx, h2_stream *stream)
         default:
             break;
     }
+    dispatch_event(session, H2_SESSION_EV_STREAM_CHANGE, 0, "stream state change");
 }
 
 static void on_stream_event(void *ctx, h2_stream *stream, 
@@ -1945,8 +2014,8 @@ static void dispatch_event(h2_session *session, h2_session_event_t ev,
         case H2_SESSION_EV_NO_IO:
             h2_session_ev_no_io(session, arg, msg);
             break;
-        case H2_SESSION_EV_DATA_READ:
-            h2_session_ev_data_read(session, arg, msg);
+        case H2_SESSION_EV_FRAME_RCVD:
+            h2_session_ev_frame_rcvd(session, arg, msg);
             break;
         case H2_SESSION_EV_NGH2_DONE:
             h2_session_ev_ngh2_done(session, arg, msg);
@@ -1957,6 +2026,9 @@ 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_CHANGE:
+            h2_session_ev_stream_change(session, arg, msg);
+            break;
         default:
             ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, session->c,
                           H2_SSSN_MSG(session, "unknown event %d"), ev);
@@ -1990,13 +2062,15 @@ apr_status_t h2_session_process(h2_session *session, int async)
     apr_status_t status = APR_SUCCESS;
     conn_rec *c = session->c;
     int rv, mpm_state, trace = APLOGctrace3(c);
-
+    apr_time_t now;
+    
     if (trace) {
         ap_log_cerror( APLOG_MARK, APLOG_TRACE3, status, c,
                       H2_SSSN_MSG(session, "process start, async=%d"), async);
     }
                   
     while (session->state != H2_SESSION_ST_DONE) {
+        now = apr_time_now();
         session->have_read = session->have_written = 0;
 
         if (session->local.accepting 
@@ -2034,39 +2108,42 @@ apr_status_t h2_session_process(h2_session *session, int async)
                 break;
                 
             case H2_SESSION_ST_IDLE:
-                /* We trust our connection into the default timeout/keepalive
-                 * handling of the core filters/mpm iff:
-                 * - keep_sync_until is not set
-                 * - we have an async mpm
-                 * - we have no open streams to process
-                 * - we are not sitting on a Upgrade: request
-                 * - we already have seen at least one request
-                 */
-                if (!session->keep_sync_until && async && !session->open_streams
-                    && !session->r && session->remote.emitted_count) {
+                if (session->idle_until && (apr_time_now() + session->idle_delay) > session->idle_until) {
+                    ap_log_cerror( APLOG_MARK, APLOG_TRACE1, status, c,
+                                  H2_SSSN_MSG(session, "idle, timeout reached, closing"));
+                    if (session->idle_delay) {
+                        apr_table_setn(session->c->notes, "short-lingering-close", "1"); 
+                    }
+                    dispatch_event(session, H2_SESSION_EV_CONN_TIMEOUT, 0, "timeout");
+                    goto out;
+                }
+                
+                if (session->idle_delay) {
+                    /* we are less interested in spending time on this connection */
+                    ap_log_cerror( APLOG_MARK, APLOG_TRACE2, status, c,
+                                  H2_SSSN_MSG(session, "session is idle (%ld ms), idle wait %ld sec left"), 
+                                  (long)apr_time_as_msec(session->idle_delay),
+                                  (long)apr_time_sec(session->idle_until - now));
+                    apr_sleep(session->idle_delay);
+                    session->idle_delay = 0;
+                }
+
+                h2_conn_io_flush(&session->io);
+                if (async && !session->r && (now > session->idle_sync_until)) {
                     if (trace) {
                         ap_log_cerror(APLOG_MARK, APLOG_TRACE3, status, c,
                                       H2_SSSN_MSG(session, 
                                       "nonblock read, %d streams open"), 
                                       session->open_streams);
                     }
-                    h2_conn_io_flush(&session->io);
                     status = h2_session_read(session, 0);
                     
                     if (status == APR_SUCCESS) {
                         session->have_read = 1;
-                        dispatch_event(session, H2_SESSION_EV_DATA_READ, 0, NULL);
                     }
-                    else if (APR_STATUS_IS_EAGAIN(status) 
-                        || APR_STATUS_IS_TIMEUP(status)) {
-                        if (apr_time_now() > session->idle_until) {
-                            dispatch_event(session, 
-                                           H2_SESSION_EV_CONN_TIMEOUT, 0, NULL);
-                        }
-                        else {
-                            status = APR_EAGAIN;
-                            goto out;
-                        }
+                    else if (APR_STATUS_IS_EAGAIN(status) || APR_STATUS_IS_TIMEUP(status)) {
+                        status = APR_EAGAIN;
+                        goto out;
                     }
                     else {
                         ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, c,
@@ -2078,7 +2155,6 @@ apr_status_t h2_session_process(h2_session *session, int async)
                 }
                 else {
                     /* make certain, we send everything before we idle */
-                    h2_conn_io_flush(&session->io);
                     if (trace) {
                         ap_log_cerror(APLOG_MARK, APLOG_TRACE3, status, c,
                                       H2_SSSN_MSG(session, 
@@ -2090,7 +2166,6 @@ apr_status_t h2_session_process(h2_session *session, int async)
                      */
                     status = h2_mplx_idle(session->mplx);
                     if (status == APR_EAGAIN) {
-                        dispatch_event(session, H2_SESSION_EV_DATA_READ, 0, NULL);
                         break;
                     }
                     else if (status != APR_SUCCESS) {
@@ -2101,33 +2176,11 @@ apr_status_t h2_session_process(h2_session *session, int async)
                     status = h2_session_read(session, 1);
                     if (status == APR_SUCCESS) {
                         session->have_read = 1;
-                        dispatch_event(session, H2_SESSION_EV_DATA_READ, 0, NULL);
                     }
                     else if (status == APR_EAGAIN) {
                         /* nothing to read */
                     }
                     else if (APR_STATUS_IS_TIMEUP(status)) {
-                        apr_time_t now = apr_time_now();
-                        if (now > session->keep_sync_until) {
-                            /* if we are on an async mpm, now is the time that
-                             * we may dare to pass control to it. */
-                            session->keep_sync_until = 0;
-                        }
-                        if (now > session->idle_until) {
-                            if (trace) {
-                                ap_log_cerror(APLOG_MARK, APLOG_TRACE3, status, c,
-                                              H2_SSSN_MSG(session, 
-                                              "keepalive timeout"));
-                            }
-                            dispatch_event(session, 
-                                           H2_SESSION_EV_CONN_TIMEOUT, 0, "timeout");
-                        }
-                        else if (trace) {                        
-                            ap_log_cerror(APLOG_MARK, APLOG_TRACE3, status, c,
-                                          H2_SSSN_MSG(session, 
-                                          "keepalive, %f sec left"),
-                                          (session->idle_until - now) / 1000000.0f);
-                        }
                         /* continue reading handling */
                     }
                     else if (APR_STATUS_IS_ECONNABORTED(status)
@@ -2145,6 +2198,18 @@ apr_status_t h2_session_process(h2_session *session, int async)
                         dispatch_event(session, H2_SESSION_EV_CONN_ERROR, 0, "error");
                     }
                 }
+                if (nghttp2_session_want_write(session->ngh2)) {
+                    ap_update_child_status(session->c->sbh, SERVER_BUSY_WRITE, NULL);
+                    status = h2_session_send(session);
+                    if (status == APR_SUCCESS) {
+                        status = h2_conn_io_flush(&session->io);
+                    }
+                    if (status != APR_SUCCESS) {
+                        dispatch_event(session, H2_SESSION_EV_CONN_ERROR, 
+                                       H2_ERR_INTERNAL_ERROR, "writing");
+                        break;
+                    }
+                }
                 break;
                 
             case H2_SESSION_ST_BUSY:
@@ -2154,7 +2219,6 @@ apr_status_t h2_session_process(h2_session *session, int async)
                     status = h2_session_read(session, 0);
                     if (status == APR_SUCCESS) {
                         session->have_read = 1;
-                        dispatch_event(session, H2_SESSION_EV_DATA_READ, 0, NULL);
                     }
                     else if (status == APR_EAGAIN) {
                         /* nothing to read */
@@ -2218,7 +2282,7 @@ apr_status_t h2_session_process(h2_session *session, int async)
                                              session->iowait);
                 if (status == APR_SUCCESS) {
                     session->wait_us = 0;
-                    dispatch_event(session, H2_SESSION_EV_DATA_READ, 0, NULL);
+                        dispatch_event(session, H2_SESSION_EV_STREAM_CHANGE, 0, NULL);
                 }
                 else if (APR_STATUS_IS_TIMEUP(status)) {
                     /* go back to checking all inputs again */
diff --git a/modules/http2/h2_session.h b/modules/http2/h2_session.h
index 486938b009..df2a862445 100644
--- a/modules/http2/h2_session.h
+++ b/modules/http2/h2_session.h
@@ -66,10 +66,11 @@ typedef enum {
     H2_SESSION_EV_PROTO_ERROR,      /* protocol error */
     H2_SESSION_EV_CONN_TIMEOUT,     /* connection timeout */
     H2_SESSION_EV_NO_IO,            /* nothing has been read or written */
-    H2_SESSION_EV_DATA_READ,        /* connection data has been read */
+    H2_SESSION_EV_FRAME_RCVD,       /* a frame has been received */
     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_CHANGE,    /* a stream (state/input/output) changed */
 } h2_session_event_t;
 
 typedef struct h2_session {
@@ -118,7 +119,9 @@ typedef struct h2_session {
     apr_size_t max_stream_mem;      /* max buffer memory for a single stream */
     
     apr_time_t idle_until;          /* Time we shut down due to sheer boredom */
-    apr_time_t keep_sync_until;     /* Time we sync wait until passing to async mpm */
+    apr_time_t idle_sync_until;     /* Time we sync wait until keepalive handling kicks in */
+    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 */
     
     apr_bucket_brigade *bbtmp;      /* brigade for keeping temporary data */
     struct apr_thread_cond_t *iowait; /* our cond when trywaiting for data */
diff --git a/modules/http2/h2_version.h b/modules/http2/h2_version.h
index 5c53abd575..2ac718fc0f 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.20"
+#define MOD_HTTP2_VERSION "1.11.0"
 
 /**
  * @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 0x010a14
+#define MOD_HTTP2_VERSION_NUM 0x010b00
 
 
 #endif /* mod_h2_h2_version_h */
-- 
2.17.1