Mailing-List: contact cvs-help@httpd.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@httpd.apache.org
Content-Type: text/plain; charset="utf-8"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Subject: svn commit: r1727080 - in /httpd/httpd/trunk: CHANGES
 modules/http2/h2_conn.c modules/http2/h2_conn.h modules/http2/h2_filter.c
 modules/http2/h2_h2.c modules/http2/h2_session.c modules/http2/h2_session.h
Date: Wed, 27 Jan 2016 15:06:36 -0000
To: cvs@httpd.apache.org
From: icing@apache.org
Message-Id: <20160127150636.8DB063A0873@svn01-us-west.apache.org>

Author: icing
Date: Wed Jan 27 15:06:36 2016
New Revision: 1727080

URL: http://svn.apache.org/viewvc?rev=1727080&view=rev
Log:
async handling of idle http2 connections

Modified:
    httpd/httpd/trunk/CHANGES
    httpd/httpd/trunk/modules/http2/h2_conn.c
    httpd/httpd/trunk/modules/http2/h2_conn.h
    httpd/httpd/trunk/modules/http2/h2_filter.c
    httpd/httpd/trunk/modules/http2/h2_h2.c
    httpd/httpd/trunk/modules/http2/h2_session.c
    httpd/httpd/trunk/modules/http2/h2_session.h

Modified: httpd/httpd/trunk/CHANGES
URL: http://svn.apache.org/viewvc/httpd/httpd/trunk/CHANGES?rev=1727080&r1=1727079&r2=1727080&view=diff
==============================================================================
--- httpd/httpd/trunk/CHANGES [utf-8] (original)
+++ httpd/httpd/trunk/CHANGES [utf-8] Wed Jan 27 15:06:36 2016
@@ -1,6 +1,12 @@
                                                          -*- coding: utf-8 -*-
 Changes with Apache 2.5.0
 
+  *) mod_http2: idle connections are returned to async mpms. new hook
+     "pre_close_connection" used to send GOAWAY frame when not already done.
+     Setting event mpm server config "by hand" for the main connection to
+     the correct negotiated server.
+     [Stefan Eissing]
+  
   *) core: new hook "pre_close_connection" which is run before the lingering
      close of connections is started. This gives protocol handlers one last
      chance to use a connection before it goes down.

Modified: httpd/httpd/trunk/modules/http2/h2_conn.c
URL: http://svn.apache.org/viewvc/httpd/httpd/trunk/modules/http2/h2_conn.c?rev=1727080&r1=1727079&r2=1727080&view=diff
==============================================================================
--- httpd/httpd/trunk/modules/http2/h2_conn.c (original)
+++ httpd/httpd/trunk/modules/http2/h2_conn.c Wed Jan 27 15:06:36 2016
@@ -75,6 +75,8 @@ static void check_modules(int force)
     }
 }
 
+static void fix_event_master_conn(h2_session *session);
+
 apr_status_t h2_conn_child_init(apr_pool_t *pool, server_rec *s)
 {
     const h2_config *config = h2_config_sget(s);
@@ -168,6 +170,15 @@ apr_status_t h2_conn_setup(h2_ctx *ctx,
     }
 
     h2_ctx_session_set(ctx, session);
+    
+    switch (h2_conn_mpm_type()) {
+        case H2_MPM_EVENT: 
+            fix_event_master_conn(session);
+            break;
+        default:
+            break;
+    }
+
     return APR_SUCCESS;
 }
 
@@ -182,9 +193,6 @@ apr_status_t h2_conn_run(struct h2_ctx *
         }
         status = h2_session_process(h2_ctx_session_get(ctx), async_mpm);
         
-        if (c->cs) {
-            c->cs->state = CONN_STATE_WRITE_COMPLETION;
-        }
         if (APR_STATUS_IS_EOF(status)) {
             ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, c, APLOGNO(03045)
                           "h2_session(%ld): process, closing conn", c->id);
@@ -204,6 +212,17 @@ apr_status_t h2_conn_run(struct h2_ctx *
     return DONE;
 }
 
+apr_status_t h2_conn_pre_close(struct h2_ctx *ctx, conn_rec *c)
+{
+    apr_status_t status;
+    
+    status = h2_session_pre_close(h2_ctx_session_get(ctx), async_mpm);
+    if (status == APR_SUCCESS) {
+        return DONE; /* This is the same, right? */
+    }
+    return status;
+}
+
 
 static void fix_event_conn(conn_rec *c, conn_rec *master);
 
@@ -296,6 +315,11 @@ struct event_conn_state_t {
      * a particular MPM thread; for suspend_/resume_connection
      * hooks)
      */
+    void *sc;
+    /** is the current conn_rec suspended?  (disassociated with
+     * a particular MPM thread; for suspend_/resume_connection
+     * hooks)
+     */
     int suspended;
     /** memory pool to allocate from */
     apr_pool_t *p;
@@ -327,3 +351,14 @@ static void fix_event_conn(conn_rec *c,
     c->cs = &(cs->pub);
 }
 
+static void fix_event_master_conn(h2_session *session)
+{
+    /* TODO: event MPM normally does this in a post_read_request hook. But
+     * we never encounter that on our master connection. We *do* know which
+     * server was selected during protocol negotiation, so lets set that.
+     */
+    event_conn_state_t *cs = ap_get_module_config(session->c->conn_config, 
+                                                  h2_conn_mpm_module());
+    cs->sc = ap_get_module_config(session->s->module_config, h2_conn_mpm_module());
+}
+

Modified: httpd/httpd/trunk/modules/http2/h2_conn.h
URL: http://svn.apache.org/viewvc/httpd/httpd/trunk/modules/http2/h2_conn.h?rev=1727080&r1=1727079&r2=1727080&view=diff
==============================================================================
--- httpd/httpd/trunk/modules/http2/h2_conn.h (original)
+++ httpd/httpd/trunk/modules/http2/h2_conn.h Wed Jan 27 15:06:36 2016
@@ -38,6 +38,12 @@ apr_status_t h2_conn_setup(struct h2_ctx
  */
 apr_status_t h2_conn_run(struct h2_ctx *ctx, conn_rec *c);
 
+/**
+ * The connection is about to close. If we have not send a GOAWAY
+ * yet, this is the last chance.
+ */
+apr_status_t h2_conn_pre_close(struct h2_ctx *ctx, conn_rec *c);
+
 /* Initialize this child process for h2 connection work,
  * to be called once during child init before multi processing
  * starts.

Modified: httpd/httpd/trunk/modules/http2/h2_filter.c
URL: http://svn.apache.org/viewvc/httpd/httpd/trunk/modules/http2/h2_filter.c?rev=1727080&r1=1727079&r2=1727080&view=diff
==============================================================================
--- httpd/httpd/trunk/modules/http2/h2_filter.c (original)
+++ httpd/httpd/trunk/modules/http2/h2_filter.c Wed Jan 27 15:06:36 2016
@@ -148,8 +148,6 @@ apr_status_t h2_filter_core_input(ap_fil
         if (saved_timeout != UNSET) {
             apr_socket_timeout_set(cin->socket, saved_timeout);
         }
-        ap_log_cerror(APLOG_MARK, APLOG_TRACE1, status, f->c,
-                      "core_input(%ld): got_brigade", (long)f->c->id);
     }
     
     switch (status) {
@@ -159,6 +157,8 @@ apr_status_t h2_filter_core_input(ap_fil
         case APR_EOF:
         case APR_EAGAIN:
         case APR_TIMEUP:
+            ap_log_cerror(APLOG_MARK, APLOG_TRACE1, status, f->c,
+                          "core_input(%ld): read", (long)f->c->id);
             break;
         default:
             ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, f->c, APLOGNO(03046)

Modified: httpd/httpd/trunk/modules/http2/h2_h2.c
URL: http://svn.apache.org/viewvc/httpd/httpd/trunk/modules/http2/h2_h2.c?rev=1727080&r1=1727079&r2=1727080&view=diff
==============================================================================
--- httpd/httpd/trunk/modules/http2/h2_h2.c (original)
+++ httpd/httpd/trunk/modules/http2/h2_h2.c Wed Jan 27 15:06:36 2016
@@ -441,6 +441,7 @@ static int cipher_is_blacklisted(const c
  * - process_conn take over connection in case of h2
  */
 static int h2_h2_process_conn(conn_rec* c);
+static int h2_h2_pre_close_conn(conn_rec* c);
 static int h2_h2_post_read_req(request_rec *r);
 
 /*******************************************************************************
@@ -565,7 +566,11 @@ void h2_h2_register_hooks(void)
      */
     ap_hook_process_connection(h2_h2_process_conn, 
                                mod_ssl, mod_reqtimeout, APR_HOOK_LAST);
-                               
+    
+    /* One last chance to properly say goodbye if we have not done so
+     * already. */
+    ap_hook_pre_close_connection(h2_h2_pre_close_conn, NULL, mod_ssl, APR_HOOK_LAST);
+
     /* With "H2SerializeHeaders On", we install the filter in this hook
      * that parses the response. This needs to happen before any other post
      * read function terminates the request with an error. Otherwise we will
@@ -658,6 +663,25 @@ int h2_h2_process_conn(conn_rec* c)
     return DECLINED;
 }
 
+static int h2_h2_pre_close_conn(conn_rec *c)
+{
+    h2_ctx *ctx;
+
+    /* slave connection? */
+    if (c->master) {
+        return DECLINED;
+    }
+
+    ctx = h2_ctx_get(c, 0);
+    if (ctx) {
+        /* If the session has been closed correctly already, we will not
+         * fiond a h2_ctx here. The presence indicates that the session
+         * is still ongoing. */
+        return h2_conn_pre_close(ctx, c);
+    }
+    return DECLINED;
+}
+
 static int h2_h2_post_read_req(request_rec *r)
 {
     /* slave connection? */

Modified: httpd/httpd/trunk/modules/http2/h2_session.c
URL: http://svn.apache.org/viewvc/httpd/httpd/trunk/modules/http2/h2_session.c?rev=1727080&r1=1727079&r2=1727080&view=diff
==============================================================================
--- httpd/httpd/trunk/modules/http2/h2_session.c (original)
+++ httpd/httpd/trunk/modules/http2/h2_session.c Wed Jan 27 15:06:36 2016
@@ -1536,8 +1536,9 @@ static int frame_print(const nghttp2_fra
         }
         case NGHTTP2_WINDOW_UPDATE: {
             return apr_snprintf(buffer, maxlen,
-                                "WINDOW_UPDATE[length=%d, stream=%d]",
-                                (int)frame->hd.length, frame->hd.stream_id);
+                                "WINDOW_UPDATE[stream=%d, incr=%d]",
+                                frame->hd.stream_id, 
+                                frame->window_update.window_size_increment);
         }
         default:
             return apr_snprintf(buffer, maxlen,
@@ -1867,18 +1868,6 @@ static void h2_session_ev_no_io(h2_sessi
     }
 }
 
-static void h2_session_ev_wait_timeout(h2_session *session, int arg, const char *msg)
-{
-    switch (session->state) {
-        case H2_SESSION_ST_WAIT:
-            transit(session, "wait timeout", H2_SESSION_ST_BUSY);
-            break;
-        default:
-            /* nop */
-            break;
-    }
-}
-
 static void h2_session_ev_stream_ready(h2_session *session, int arg, const char *msg)
 {
     switch (session->state) {
@@ -1895,6 +1884,7 @@ static void h2_session_ev_data_read(h2_s
 {
     switch (session->state) {
         case H2_SESSION_ST_IDLE:
+        case H2_SESSION_ST_WAIT:
             transit(session, "data read", H2_SESSION_ST_BUSY);
             break;
             /* fall through */
@@ -1929,6 +1919,20 @@ static void h2_session_ev_mpm_stopping(h
     }
 }
 
+static void h2_session_ev_pre_close(h2_session *session, int arg, const char *msg)
+{
+    switch (session->state) {
+        case H2_SESSION_ST_DONE:
+        case H2_SESSION_ST_LOCAL_SHUTDOWN:
+            /* nop */
+            break;
+        default:
+            h2_session_shutdown(session, arg, msg);
+            h2_conn_io_flush(&session->io);
+            break;
+    }
+}
+
 static void dispatch_event(h2_session *session, h2_session_event_t ev, 
                       int arg, const char *msg)
 {
@@ -1954,9 +1958,6 @@ static void dispatch_event(h2_session *s
         case H2_SESSION_EV_NO_IO:
             h2_session_ev_no_io(session, arg, msg);
             break;
-        case H2_SESSION_EV_WAIT_TIMEOUT:
-            h2_session_ev_wait_timeout(session, arg, msg);
-            break;
         case H2_SESSION_EV_STREAM_READY:
             h2_session_ev_stream_ready(session, arg, msg);
             break;
@@ -1969,6 +1970,9 @@ static void dispatch_event(h2_session *s
         case H2_SESSION_EV_MPM_STOPPING:
             h2_session_ev_mpm_stopping(session, arg, msg);
             break;
+        case H2_SESSION_EV_PRE_CLOSE:
+            h2_session_ev_pre_close(session, arg, msg);
+            break;
         default:
             ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, session->c,
                           "h2_session(%ld): unknown event %d", 
@@ -2005,6 +2009,10 @@ apr_status_t h2_session_process(h2_sessi
     ap_log_cerror( APLOG_MARK, APLOG_TRACE1, status, c,
                   "h2_session(%ld): process start, async=%d", session->id, async);
                   
+    if (c->cs) {
+        c->cs->state = CONN_STATE_WRITE_COMPLETION;
+    }
+    
     while (1) {
         have_read = have_written = 0;
 
@@ -2039,34 +2047,73 @@ apr_status_t h2_session_process(h2_sessi
                 break;
                 
             case H2_SESSION_ST_IDLE:
-                /* We wait in smaller increments, using a 1 second timeout.
-                 * That gives us the chance to check for MPMQ_STOPPING often. */
-                h2_filter_cin_timeout_set(session->cin, 1);
-                update_child_status(session, SERVER_BUSY_KEEPALIVE, "idle");
-                status = h2_session_read(session, 1, 10);
-                if (status == APR_SUCCESS) {
-                    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)) {
-                    if (--session->keepalive_remain <= 0) {
-                        dispatch_event(session, H2_SESSION_EV_CONN_TIMEOUT, 0, NULL);
+                update_child_status(session, (h2_stream_set_is_empty(session->streams)?
+                                              SERVER_BUSY_KEEPALIVE : SERVER_BUSY_READ), 
+                                              "idle");
+                if (async && !session->r) {
+                    ap_log_cerror( APLOG_MARK, APLOG_TRACE1, status, c,
+                                  "h2_session(%ld): async idle, nonblock read", session->id);
+                    if (c->cs) {
+                        c->cs->sense = CONN_SENSE_WANT_READ;
+                    }
+                    status = h2_session_read(session, 0, 1);
+                    if (status == APR_SUCCESS) {
+                        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 (--session->keepalive_remain <= 0) {
+                            dispatch_event(session, H2_SESSION_EV_CONN_TIMEOUT, 0, NULL);
+                        }
+                        else {
+                            status = APR_EAGAIN;
+                            ap_log_cerror( APLOG_MARK, APLOG_DEBUG, status, c,
+                                          "h2_session(%ld): idle, conn->timeout=%d/%d"
+                                          ", conn->keepalive=%d/%d", 
+                                          session->id, 
+                                          (int)session->timeout_secs,
+                                          (int)apr_time_sec(session->s->timeout),
+                                          (int)session->keepalive_secs,
+                                          (int)apr_time_sec(session->s->keep_alive_timeout));
+                            goto out;
+                        }
+                    }
+                    else {
+                        ap_log_cerror( APLOG_MARK, APLOG_DEBUG, status, c,
+                                      "h2_session(%ld): idle, no data, error", 
+                                      session->id);
+                        dispatch_event(session, H2_SESSION_EV_CONN_ERROR, 0, NULL);
                     }
-                    /* continue keepalive handling */
                 }
                 else {
-                    dispatch_event(session, H2_SESSION_EV_CONN_ERROR, 0, NULL);
+                    /* We wait in smaller increments, using a 1 second timeout.
+                     * That gives us the chance to check for MPMQ_STOPPING often. */
+                    h2_filter_cin_timeout_set(session->cin, 1);
+                    status = h2_session_read(session, 1, 10);
+                    if (status == APR_SUCCESS) {
+                        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)) {
+                        if (--session->keepalive_remain <= 0) {
+                            dispatch_event(session, H2_SESSION_EV_CONN_TIMEOUT, 0, "timeout");
+                        }
+                        /* continue keepalive handling */
+                    }
+                    else {
+                        dispatch_event(session, H2_SESSION_EV_CONN_ERROR, 0, NULL);
+                    }
                 }
+                
                 break;
                 
             case H2_SESSION_ST_BUSY:
             case H2_SESSION_ST_LOCAL_SHUTDOWN:
             case H2_SESSION_ST_REMOTE_SHUTDOWN:
                 if (nghttp2_session_want_read(session->ngh2)) {
-                    update_child_status(session, SERVER_BUSY_READ, "busy");
                     h2_filter_cin_timeout_set(session->cin, session->timeout_secs);
                     status = h2_session_read(session, 0, 10);
                     if (status == APR_SUCCESS) {
@@ -2121,33 +2168,48 @@ apr_status_t h2_session_process(h2_sessi
                 }
                 
                 if (have_read || have_written) {
-                    session->wait_us = 0;
+                    if (session->wait_us) {
+                        session->wait_us = 0;
+                        update_child_status(session, SERVER_BUSY_READ, "busy");
+                    }
                 }
-                else {
+                else if (!nghttp2_session_want_write(session->ngh2)) {
                     dispatch_event(session, H2_SESSION_EV_NO_IO, 0, NULL);
                 }
                 break;
                 
             case H2_SESSION_ST_WAIT:
-                session->wait_us = H2MAX(session->wait_us, 10);
+                if (session->wait_us <= 0) {
+                    session->wait_us = 10;
+                    session->start_wait = apr_time_now();
+                    update_child_status(session, SERVER_BUSY_READ, "wait");
+                }
+                else if (apr_time_sec(apr_time_now() - session->start_wait)
+                         >= session->timeout_secs) {
+                    /* waited long enough */
+                    ap_log_cerror(APLOG_MARK, APLOG_TRACE1, APR_TIMEUP, c,
+                                  "h2_session: wait for data");
+                    dispatch_event(session, H2_SESSION_EV_CONN_TIMEOUT, 0, NULL);
+                }
+                else {
+                    /* repeating, increase timer for graceful backoff */
+                    session->wait_us = H2MIN(session->wait_us*2, MAX_WAIT_MICROS);
+                }
+
                 if (APLOGctrace1(c)) {
                     ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, c,
                                   "h2_session: wait for data, %ld micros", 
                                   (long)session->wait_us);
                 }
-                
-                ap_log_cerror( APLOG_MARK, APLOG_TRACE2, status, c,
-                              "h2_session(%ld): process -> trywait", session->id);
-                    update_child_status(session, SERVER_BUSY_READ, "wait");
                 status = h2_mplx_out_trywait(session->mplx, session->wait_us, 
                                              session->iowait);
                 if (status == APR_SUCCESS) {
-                    dispatch_event(session, H2_SESSION_EV_STREAM_READY, 0, NULL);
+                    session->wait_us = 0;
+                    dispatch_event(session, H2_SESSION_EV_DATA_READ, 0, NULL);
                 }
                 else if (status == APR_TIMEUP) {
-                    /* nothing, increase timer for graceful backup */
-                    session->wait_us = H2MIN(session->wait_us*2, MAX_WAIT_MICROS);
-                    dispatch_event(session, H2_SESSION_EV_WAIT_TIMEOUT, 0, NULL);
+                    /* go back to checking all inputs again */
+                    transit(session, "wait cycle", H2_SESSION_ST_BUSY);
                 }
                 else {
                     h2_session_shutdown(session, H2_ERR_INTERNAL_ERROR, "cond wait error");
@@ -2203,3 +2265,11 @@ out:
     
     return status;
 }
+
+apr_status_t h2_session_pre_close(h2_session *session, int async)
+{
+    ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, session->c, 
+                  "h2_session(%ld): pre_close", session->id);
+    dispatch_event(session, H2_SESSION_EV_PRE_CLOSE, 0, "timeout");
+    return APR_SUCCESS;
+}

Modified: httpd/httpd/trunk/modules/http2/h2_session.h
URL: http://svn.apache.org/viewvc/httpd/httpd/trunk/modules/http2/h2_session.h?rev=1727080&r1=1727079&r2=1727080&view=diff
==============================================================================
--- httpd/httpd/trunk/modules/http2/h2_session.h (original)
+++ httpd/httpd/trunk/modules/http2/h2_session.h Wed Jan 27 15:06:36 2016
@@ -72,11 +72,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_WAIT_TIMEOUT,     /* timeout waiting for tasks */
     H2_SESSION_EV_STREAM_READY,     /* stream signalled availability of headers/data */
     H2_SESSION_EV_DATA_READ,        /* connection data has been read */
     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_event_t;
 
 typedef struct h2_session {
@@ -115,6 +115,7 @@ typedef struct h2_session {
     int timeout_secs;               /* connection timeout (seconds) */
     int keepalive_secs;             /* connection idle timeout (seconds) */
     int keepalive_remain;           /* remaining seconds of keepalive */
+    apr_time_t start_wait;          /* Time we started waiting for sth. to happen */
     
     apr_pool_t *pool;               /* pool to use in session handling */
     apr_bucket_brigade *bbtmp;      /* brigade for keeping temporary data */
@@ -170,6 +171,11 @@ h2_session *h2_session_rcreate(request_r
 apr_status_t h2_session_process(h2_session *session, int async);
 
 /**
+ * Last chance to do anything before the connection is closed.
+ */
+apr_status_t h2_session_pre_close(h2_session *session, int async);
+
+/**
  * Cleanup the session and all objects it still contains. This will not
  * destroy h2_task instances that have not finished yet. 
  * @param session the session to destroy