Event async

configure.in

@@ -471,6 +471,7 @@ AC_CHECK_HEADERS( \
 string.h \
 limits.h \
 unistd.h \
+time.h \
 sys/socket.h \
 pwd.h \
 grp.h \
@@ -533,6 +534,7 @@ getpwnam \
 getgrnam \
 initgroups \
 bindprocessor \
+clock_gettime \
 prctl \
 procctl \
 timegm \

docs/log-message-tags/next-number

@@ -1 +1 @@
-10379
+10380

include/ap_mmn.h

@@ -702,6 +702,8 @@
  * 20211221.2 (2.5.1-dev)  Add AGAIN, AP_MPMQ_CAN_AGAIN.
  * 20211221.3 (2.5.1-dev)  Add ap_thread_create(), ap_thread_main_create()
  *                         and ap_thread_current()
+ * 20211221.4 (2.5.1-dev)  Add min_connection_timeout hook and
+ *                         ap_get_connection_timeout()
  *
  */
 
@@ -710,7 +712,7 @@
 #ifndef MODULE_MAGIC_NUMBER_MAJOR
 #define MODULE_MAGIC_NUMBER_MAJOR 20211221
 #endif
-#define MODULE_MAGIC_NUMBER_MINOR 3             /* 0...n */
+#define MODULE_MAGIC_NUMBER_MINOR 4             /* 0...n */
 
 /**
  * Determine if the server's current MODULE_MAGIC_NUMBER is at least a

include/http_connection.h

@@ -171,6 +171,11 @@ AP_DECLARE(conn_rec *) ap_create_connection(apr_pool_t *p,
                                             apr_bucket_alloc_t *alloc,
                                             unsigned int outgoing);
 
+AP_DECLARE_HOOK(int, min_connection_timeout,
+                (conn_rec *c, server_rec *s, apr_interval_time_t *min_timeout))
+
+AP_DECLARE(apr_interval_time_t) ap_get_connection_timeout(conn_rec *c,
+                                                          server_rec *s);
 
 /** End Of Connection (EOC) bucket */
 AP_DECLARE_DATA extern const apr_bucket_type_t ap_bucket_type_eoc;

modules/filters/mod_reqtimeout.c

@@ -45,6 +45,7 @@ typedef struct
     int max_timeout;        /* max timeout in secs */
     int min_rate;           /* min rate in bytes/s */
     apr_time_t rate_factor; /* scale factor (#usecs per min_rate) */
+    apr_interval_time_t server_timeout; /* server timeout at this stage */
 } reqtimeout_stage_t;
 
 typedef struct
@@ -59,6 +60,7 @@ typedef struct
 {
     apr_time_t timeout_at;
     apr_time_t max_timeout_at;
+    apr_interval_time_t time_left;
     reqtimeout_stage_t cur_stage;
     int in_keep_alive;
     char *type;
@@ -74,34 +76,45 @@ static int default_body_rate_factor;
 static void extend_timeout(reqtimeout_con_cfg *ccfg, apr_bucket_brigade *bb)
 {
     apr_off_t len;
+    apr_time_t old_timeout_at;
     apr_time_t new_timeout_at;
 
     if (apr_brigade_length(bb, 0, &len) != APR_SUCCESS || len <= 0)
         return;
 
-    new_timeout_at = ccfg->timeout_at + len * ccfg->cur_stage.rate_factor;
+    old_timeout_at = ccfg->timeout_at;
+    new_timeout_at = old_timeout_at + len * ccfg->cur_stage.rate_factor;
     if (ccfg->max_timeout_at > 0 && new_timeout_at > ccfg->max_timeout_at) {
         ccfg->timeout_at = ccfg->max_timeout_at;
     }
     else {
         ccfg->timeout_at = new_timeout_at;
     }
+
+    ccfg->time_left += new_timeout_at - old_timeout_at;
+    if (ccfg->time_left > ccfg->cur_stage.server_timeout) {
+        ccfg->time_left = ccfg->cur_stage.server_timeout;
+    }
 }
 
 static apr_status_t check_time_left(reqtimeout_con_cfg *ccfg,
-                                    apr_time_t *time_left_p,
                                     apr_time_t now)
 {
     if (!now)
         now = apr_time_now();
-    *time_left_p = ccfg->timeout_at - now;
-    if (*time_left_p <= 0)
+
+    ccfg->time_left = ccfg->timeout_at - now;
+    if (ccfg->time_left <= 0)
         return APR_TIMEUP;
 
-    if (*time_left_p < apr_time_from_sec(1)) {
-        *time_left_p = apr_time_from_sec(1);
+    if (ccfg->time_left < apr_time_from_sec(1)) {
+        ccfg->time_left = apr_time_from_sec(1);
     }
-    return APR_SUCCESS;
+    else if (ccfg->time_left > ccfg->cur_stage.server_timeout) {
+        ccfg->time_left = ccfg->cur_stage.server_timeout;
+    }
+
+    return apr_socket_timeout_set(ccfg->socket, ccfg->time_left);
 }
 
 static apr_status_t have_lf_or_eos(apr_bucket_brigade *bb)
@@ -168,16 +181,14 @@ static apr_status_t brigade_append(apr_bucket_brigade *bbOut, apr_bucket_brigade
 }
 
 
-#define MIN(x,y) ((x) < (y) ? (x) : (y))
 static apr_status_t reqtimeout_filter(ap_filter_t *f,
                                       apr_bucket_brigade *bb,
                                       ap_input_mode_t mode,
                                       apr_read_type_e block,
                                       apr_off_t readbytes)
 {
-    apr_time_t time_left;
-    apr_time_t now = 0;
     apr_status_t rv;
+    apr_time_t now = 0;
     apr_interval_time_t saved_sock_timeout = UNSET;
     reqtimeout_con_cfg *ccfg = f->ctx;
 
@@ -213,25 +224,14 @@ static apr_status_t reqtimeout_filter(ap_filter_t *f,
         ccfg->socket = ap_get_conn_socket(f->c);
     }
 
-    rv = check_time_left(ccfg, &time_left, now);
-    if (rv != APR_SUCCESS)
-        goto out;
-
-    if (block == APR_NONBLOCK_READ || mode == AP_MODE_EATCRLF) {
-        rv = ap_get_brigade(f->next, bb, mode, block, readbytes);
-        if (ccfg->cur_stage.rate_factor && rv == APR_SUCCESS) {
-            extend_timeout(ccfg, bb);
-        }
-        return rv;
-    }
-
     rv = apr_socket_timeout_get(ccfg->socket, &saved_sock_timeout);
     AP_DEBUG_ASSERT(rv == APR_SUCCESS);
 
-    rv = apr_socket_timeout_set(ccfg->socket, MIN(time_left, saved_sock_timeout));
-    AP_DEBUG_ASSERT(rv == APR_SUCCESS);
+    rv = check_time_left(ccfg, now);
+    if (rv != APR_SUCCESS)
+        goto cleanup;
 
-    if (mode == AP_MODE_GETLINE) {
+    if (mode == AP_MODE_GETLINE && block == APR_BLOCK_READ) {
         /*
          * For a blocking AP_MODE_GETLINE read, apr_brigade_split_line()
          * would loop until a whole line has been read. As this would make it
@@ -294,14 +294,10 @@ static apr_status_t reqtimeout_filter(ap_filter_t *f,
             if (rv != APR_SUCCESS)
                 break;
 
-            rv = check_time_left(ccfg, &time_left, 0);
+            rv = check_time_left(ccfg, 0);
             if (rv != APR_SUCCESS)
                 break;
 
-            rv = apr_socket_timeout_set(ccfg->socket,
-                                   MIN(time_left, saved_sock_timeout));
-            AP_DEBUG_ASSERT(rv == APR_SUCCESS);
-
         } while (1);
 
         if (ccfg->tmpbb)
@@ -320,9 +316,9 @@ static apr_status_t reqtimeout_filter(ap_filter_t *f,
         }
     }
 
+cleanup:
     apr_socket_timeout_set(ccfg->socket, saved_sock_timeout);
 
-out:
     if (APR_STATUS_IS_TIMEUP(rv)) {
         ap_log_cerror(APLOG_MARK, APLOG_INFO, 0, f->c, APLOGNO(01382)
                       "Request %s read timeout", ccfg->type);
@@ -353,7 +349,7 @@ static apr_status_t reqtimeout_eor(ap_filter_t *f, apr_bucket_brigade *bb)
     return ap_pass_brigade(f->next, bb);
 }
 
-#define INIT_STAGE(cfg, ccfg, stage) do { \
+#define INIT_STAGE(cfg, ccfg, stage, s_timeout) do { \
     if (cfg->stage.timeout != UNSET) { \
         ccfg->cur_stage.timeout     = cfg->stage.timeout; \
         ccfg->cur_stage.max_timeout = cfg->stage.max_timeout; \
@@ -364,6 +360,8 @@ static apr_status_t reqtimeout_eor(ap_filter_t *f, apr_bucket_brigade *bb)
         ccfg->cur_stage.max_timeout = MRT_DEFAULT_##stage##_MAX_TIMEOUT; \
         ccfg->cur_stage.rate_factor = default_##stage##_rate_factor; \
     } \
+    ccfg->cur_stage.server_timeout = s_timeout; \
+    ccfg->time_left = ccfg->cur_stage.timeout; \
 } while (0)
 
 static int reqtimeout_init(conn_rec *c)
@@ -392,7 +390,7 @@ static int reqtimeout_init(conn_rec *c)
 
         ccfg->type = "handshake";
         if (cfg->handshake.timeout > 0) {
-            INIT_STAGE(cfg, ccfg, handshake);
+            INIT_STAGE(cfg, ccfg, handshake, c->base_server->timeout);
         }
     }
 
@@ -422,7 +420,7 @@ static void reqtimeout_before_header(request_rec *r, conn_rec *c)
     ccfg->timeout_at = 0;
     ccfg->max_timeout_at = 0;
     ccfg->in_keep_alive = (c->keepalives > 0);
-    INIT_STAGE(cfg, ccfg, header);
+    INIT_STAGE(cfg, ccfg, header, c->base_server->timeout);
 }
 
 static int reqtimeout_before_body(request_rec *r)
@@ -447,11 +445,31 @@ static int reqtimeout_before_body(request_rec *r)
         ccfg->cur_stage.timeout = 0;
     }
     else {
-        INIT_STAGE(cfg, ccfg, body);
+        INIT_STAGE(cfg, ccfg, body, r->server->timeout);
     }
     return OK;
 }
 
+static int reqtimeout_min_timeout(conn_rec *c, server_rec *s/*unused*/,
+                                  apr_interval_time_t *min_timeout)
+{
+    reqtimeout_con_cfg *ccfg = ap_get_module_config(c->conn_config,
+                                                    &reqtimeout_module);
+    reqtimeout_stage_t *stage = &ccfg->cur_stage;
+
+    if (stage->timeout > 0 || ccfg->timeout_at) {
+        if (ccfg->time_left <= 0) {
+            *min_timeout = 0;
+        }
+        else if (*min_timeout < 0 || *min_timeout > ccfg->time_left) {
+            *min_timeout = ccfg->time_left;
+        }
+        return OK;
+    }
+
+    return DECLINED;
+}
+
 #define UNSET_STAGE(cfg, stage) do { \
     cfg->stage.timeout = UNSET; \
     cfg->stage.max_timeout = UNSET; \
@@ -637,6 +655,9 @@ static void reqtimeout_hooks(apr_pool_t *pool)
     ap_hook_post_read_request(reqtimeout_before_body, NULL, NULL,
                               APR_HOOK_MIDDLE);
 
+    ap_hook_min_connection_timeout(reqtimeout_min_timeout, NULL, NULL,
+                                   APR_HOOK_MIDDLE);
+
 #if MRT_DEFAULT_handshake_MIN_RATE
     default_handshake_rate_factor = apr_time_from_sec(1) /
                                     MRT_DEFAULT_handshake_MIN_RATE;

modules/http/http_request.c

@@ -444,7 +444,8 @@ void ap_process_async_request(request_rec *r)
         const apr_array_header_t *t_h = apr_table_elts(r->headers_in);
         const apr_table_entry_t *t_elt = (apr_table_entry_t *)t_h->elts;
         ap_log_rerror(APLOG_MARK, APLOG_TRACE4, 0, r,
-                      "Headers received from client:");
+                      "Header received from client:");
+        ap_log_rerror(APLOG_MARK, APLOG_TRACE4, 0, r, "  %s", r->the_request);
         for (i = 0; i < t_h->nelts; i++, t_elt++) {
             ap_log_rerror(APLOG_MARK, APLOG_TRACE4, 0, r, "  %s: %s",
                           ap_escape_logitem(r->pool, t_elt->key),

modules/ssl/mod_ssl.c

@@ -731,7 +731,7 @@ static int ssl_hook_process_connection(conn_rec* c)
                 /* we've been asked to come around again, don't block */
 
                 ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, c, APLOGNO(10371)
-                              "SSL handshake in progress, continuing");
+                              "SSL handshake in progress, try again later");
 
                 status = AGAIN;
             }

server/connection.c

@@ -35,13 +35,17 @@ APR_HOOK_STRUCT(
             APR_HOOK_LINK(process_connection)
             APR_HOOK_LINK(pre_connection)
             APR_HOOK_LINK(pre_close_connection)
+            APR_HOOK_LINK(min_connection_timeout)
 )
 AP_IMPLEMENT_HOOK_RUN_FIRST(conn_rec *,create_connection,
                             (apr_pool_t *p, server_rec *server, apr_socket_t *csd, long conn_id, void *sbh, apr_bucket_alloc_t *alloc),
                             (p, server, csd, conn_id, sbh, alloc), NULL)
 AP_IMPLEMENT_HOOK_RUN_FIRST(int,process_connection,(conn_rec *c),(c),DECLINED)
 AP_IMPLEMENT_HOOK_RUN_ALL(int,pre_connection,(conn_rec *c, void *csd),(c, csd),OK,DECLINED)
 AP_IMPLEMENT_HOOK_RUN_ALL(int,pre_close_connection,(conn_rec *c),(c),OK,DECLINED)
+AP_IMPLEMENT_HOOK_RUN_ALL(int,min_connection_timeout,
+                          (conn_rec *c, server_rec *s, apr_interval_time_t *min_timeout),
+                          (c, s, min_timeout),OK,DECLINED)
 
 AP_DECLARE(conn_rec *) ap_create_connection(apr_pool_t *p,
                                             server_rec *server,
@@ -240,3 +244,15 @@ AP_CORE_DECLARE(void) ap_process_connection(conn_rec *c, void *csd)
         ap_run_process_connection(c);
     }
 }
+
+AP_DECLARE(apr_interval_time_t) ap_get_connection_timeout(conn_rec *c,
+                                                          server_rec *s)
+{
+    apr_interval_time_t timeout = -1;
+
+    if (ap_run_min_connection_timeout(c, s, &timeout) != OK || timeout < 0) {
+        timeout = (s) ? s->timeout : c->base_server->timeout;
+    }
+
+    return timeout;
+}

server/log.c

@@ -914,16 +914,30 @@ static int do_errorlog_default(const ap_errorlog_info *info, char *buf,
      * a scoreboard handle, it is likely a client.
      */
     if (info->r) {
-        len += apr_snprintf(buf + len, buflen - len, "[%s %s:%d] ",
+        apr_os_sock_t fd = -1;
+        apr_socket_t *csd = ap_get_conn_socket(info->r->connection);
+        if (csd) {
+            apr_os_sock_get(&fd, csd);
+        }
+
+        len += apr_snprintf(buf + len, buflen - len, "[%s %s:%d/%d] ",
                             info->r->connection->outgoing ? "remote" : "client",
                             info->r->useragent_ip,
-                            info->r->useragent_addr ? info->r->useragent_addr->port : 0);
+                            info->r->useragent_addr ? info->r->useragent_addr->port : 0,
+                            (int)fd);
     }
     else if (info->c) {
-        len += apr_snprintf(buf + len, buflen - len, "[%s %s:%d] ",
+        apr_os_sock_t fd = -1;
+        apr_socket_t *csd = ap_get_conn_socket((conn_rec *)info->c);
+        if (csd) {
+            apr_os_sock_get(&fd, csd);
+        }
+
+        len += apr_snprintf(buf + len, buflen - len, "[%s %s:%d/%d] ",
                             info->c->outgoing ? "remote" : "client",
                             info->c->client_ip,
-                            info->c->client_addr ? info->c->client_addr->port : 0);
+                            info->c->client_addr ? info->c->client_addr->port : 0,
+                            (int)fd);
     }
 
     /* the actual error message */