Skip to content

Commit

Permalink
timeouts for hanging requests, event mpm fixes
Browse files Browse the repository at this point in the history
  • Loading branch information
Stefan Eissing committed Jan 27, 2016
1 parent e78f0cb commit 1e4eee5
Show file tree
Hide file tree
Showing 6 changed files with 110 additions and 38 deletions.
7 changes: 7 additions & 0 deletions ChangeLog
View file
Original file line number Diff line number Diff line change
@@ -1,3 +1,10 @@
v1.2.3
--------------------------------------------------------------------------------
* connection timeout handling when requests do not report back
* setting correct server config for event mpm on main connection, so that
timeouts, keepalives use the correct values
* fixes event hack to match changes in structures

v1.2.2
--------------------------------------------------------------------------------
* removed unused code
Expand Down
2 changes: 1 addition & 1 deletion configure.ac
View file
Original file line number Diff line number Diff line change
Expand Up @@ -14,7 +14,7 @@
#

AC_PREREQ([2.69])
AC_INIT([mod_http2], [1.2.2], [[email protected]])
AC_INIT([mod_http2], [1.2.3], [[email protected]])

LT_PREREQ([2.2.6])
LT_INIT()
Expand Down
24 changes: 24 additions & 0 deletions mod_http2/h2_conn.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -168,6 +170,15 @@ apr_status_t h2_conn_setup(h2_ctx *ctx, conn_rec *c, request_rec *r)
}

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;
}

Expand Down Expand Up @@ -292,6 +303,8 @@ struct event_conn_state_t {
conn_rec *c;
/** request record (if any) this struct refers to */
request_rec *r;
/** server config this struct refers to */
void *sc;
/** is the current conn_rec suspended? (disassociated with
* a particular MPM thread; for suspend_/resume_connection
* hooks)
Expand Down Expand Up @@ -327,3 +340,14 @@ static void fix_event_conn(conn_rec *c, conn_rec *master)
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());
}

107 changes: 73 additions & 34 deletions mod_http2/h2_session.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,8 @@
#include <apr_base64.h>
#include <apr_strings.h>

#include <ap_mpm.h>

#include <httpd.h>
#include <http_core.h>
#include <http_config.h>
Expand Down Expand Up @@ -1534,8 +1536,9 @@ static int frame_print(const nghttp2_frame *frame, char *buffer, size_t maxlen)
}
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,
Expand Down Expand Up @@ -1823,22 +1826,34 @@ static void h2_session_ev_no_io(h2_session *session, int arg, const char *msg)
{
switch (session->state) {
case H2_SESSION_ST_BUSY:
case H2_SESSION_ST_LOCAL_SHUTDOWN:
case H2_SESSION_ST_REMOTE_SHUTDOWN:
/* nothing for input and output to do. If we remain
* in this state, we go into a tight loop and suck up
* 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. */
if (h2_stream_set_is_empty(session->streams)) {
/* When we have no streams, no task event are possible,
* switch to blocking reads */
transit(session, "no io", H2_SESSION_ST_IDLE);
if (!is_accepting_streams(session)) {
/* We are no longer accepting new streams and have
* finished processing existing ones. Time to leave. */
h2_session_shutdown(session, arg, msg);
transit(session, "no io", H2_SESSION_ST_DONE);
}
else {
/* When we have no streams, no task event are possible,
* switch to blocking reads */
transit(session, "no io", H2_SESSION_ST_IDLE);
session->keepalive_remain = session->keepalive_secs;
}
}
else if (!h2_stream_set_has_unsubmitted(session->streams)
&& !h2_stream_set_has_suspended(session->streams)) {
/* none of our streams is waiting for a response or
* new output data from task processing,
* switch to blocking reads. */
transit(session, "no io", H2_SESSION_ST_IDLE);
session->keepalive_remain = session->keepalive_secs;
}
else {
/* Unable to do blocking reads, as we wait on events from
Expand All @@ -1853,18 +1868,6 @@ static void h2_session_ev_no_io(h2_session *session, int arg, const char *msg)
}
}

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) {
Expand Down Expand Up @@ -1902,6 +1905,19 @@ static void h2_session_ev_ngh2_done(h2_session *session, int arg, const char *ms
}
}

static void h2_session_ev_mpm_stopping(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);
break;
}
}

static void dispatch_event(h2_session *session, h2_session_event_t ev,
int arg, const char *msg)
{
Expand All @@ -1927,9 +1943,6 @@ 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_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;
Expand All @@ -1939,6 +1952,9 @@ static void dispatch_event(h2_session *session, h2_session_event_t ev,
case H2_SESSION_EV_NGH2_DONE:
h2_session_ev_ngh2_done(session, arg, msg);
break;
case H2_SESSION_EV_MPM_STOPPING:
h2_session_ev_mpm_stopping(session, arg, msg);
break;
default:
ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, session->c,
"h2_session(%ld): unknown event %d",
Expand All @@ -1957,14 +1973,25 @@ apr_status_t h2_session_process(h2_session *session, int async)
{
apr_status_t status = APR_SUCCESS;
conn_rec *c = session->c;
int rv, have_written, have_read;
int rv, have_written, have_read, mpm_state;

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;

if (!ap_mpm_query(AP_MPMQ_MPM_STATE, &mpm_state)) {
if (mpm_state == AP_MPMQ_STOPPING) {
dispatch_event(session, H2_SESSION_EV_MPM_STOPPING, 0, NULL);
break;
}
}

switch (session->state) {
case H2_SESSION_ST_INIT:
if (!h2_is_acceptable_connection(c, 1)) {
Expand All @@ -1986,7 +2013,6 @@ apr_status_t h2_session_process(h2_session *session, int async)

case H2_SESSION_ST_IDLE:
h2_filter_cin_timeout_set(session->cin, session->keepalive_secs);
ap_update_child_status(c->sbh, SERVER_BUSY_KEEPALIVE, NULL);
status = h2_session_read(session, 1, 10);
if (status == APR_SUCCESS) {
have_read = 1;
Expand All @@ -1996,8 +2022,7 @@ apr_status_t h2_session_process(h2_session *session, int async)
/* nothing to read */
}
else if (APR_STATUS_IS_TIMEUP(status)) {
dispatch_event(session, H2_SESSION_EV_CONN_TIMEOUT, 0, NULL);
break;
dispatch_event(session, H2_SESSION_EV_CONN_TIMEOUT, 0, "timeout");
}
else {
dispatch_event(session, H2_SESSION_EV_CONN_ERROR, 0, NULL);
Expand Down Expand Up @@ -2062,32 +2087,46 @@ apr_status_t h2_session_process(h2_session *session, int async)
}

if (have_read || have_written) {
session->wait_us = 0;
if (session->wait_us) {
session->wait_us = 0;
}
}
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();
}
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, "timeout");
}
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);
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");
Expand Down
4 changes: 3 additions & 1 deletion mod_http2/h2_session.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -72,10 +72,10 @@ 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_event_t;

typedef struct h2_session {
Expand Down Expand Up @@ -110,6 +110,8 @@ typedef struct h2_session {

apr_size_t max_stream_count; /* max number of open streams */
apr_size_t max_stream_mem; /* max buffer memory for a single stream */
int keepalive_remain; /* remaining seconds of keepalive */
apr_time_t start_wait; /* Time we started waiting for sth. to happen */

int timeout_secs; /* connection timeout (seconds) */
int keepalive_secs; /* connection idle timeout (seconds) */
Expand Down
4 changes: 2 additions & 2 deletions mod_http2/h2_version.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -26,15 +26,15 @@
* @macro
* Version number of the http2 module as c string
*/
#define MOD_HTTP2_VERSION "1.2.2"
#define MOD_HTTP2_VERSION "1.2.3"

/**
* @macro
* Numerical representation of the version number of the http2 module
* 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 0x010202
#define MOD_HTTP2_VERSION_NUM 0x010203


#endif /* mod_h2_h2_version_h */

4 comments on commit 1e4eee5

@lkraav
Copy link

@lkraav lkraav commented on 1e4eee5 Jan 27, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@icing my chat application now loses connection every time a message is sent with key. Can you log in and check it out before I have to revert back to 1.2.2?

Right before reconnect:

[Wed Jan 27 20:05:48.008123 2016] [http2:warn] [pid 28843:tid 140473104508672] [client 10.24.0.157:49884] h2_mplx(24): release, waiting for 5 seconds now for all h2_workers to return, have still 1 requests outstanding

Current settings:

modules.d/75_mod_http2.conf
8:    H2KeepAliveTimeout 75
9:    Timeout 10

EDIT chat app also times out on its own, without sending any messages.

@lkraav
Copy link

@lkraav lkraav commented on 1e4eee5 Jan 27, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

EDIT2 tinkering with timeouts seems to have improved things. Equalising Timeout now seems like it doesn't trigger the countdown of doom for everyone anymore and app stays up and running.

modules.d/75_mod_http2.conf
8:    H2KeepAliveTimeout 60
9:    Timeout 60

@icing
Copy link
Owner

@icing icing commented on 1e4eee5 Jan 28, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am not certain what the best defaults and behaviour for these two timeouts really are. I think I want to scrap the H2* variants and just use the values from Timeout and KeepAliveTimeout.

The processing model for h2 connections is different from the http1 case. So it is not straightforward how to make best use of these timers.

Your site is a good case for the ones that need long timeouts for request processing, as it is using long polling where requests do not produce data for a minute. How would you prefer to configure this?

@lkraav
Copy link

@lkraav lkraav commented on 1e4eee5 Jan 28, 2016

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Your site is a good case for the ones that need long timeouts for request processing, as it is using long polling where requests do not produce data for a minute. How would you prefer to configure this?

The less directives and options the better.

Unless it really breaks things, in which case there's no way to avoid complexity.

So far it seems that equalizing Timeout and H2KeepAliveTimeout really worked, no issues visible right now.

Please sign in to comment.