mod_logio: Add LogIOTrackTTFU and %^FU logformat

to log the time difference between request start
and last request body byte read (finished upload).

git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/trunk@1828727 13f79535-47bb-0310-9956-ffa450edef68

diff --git a/CHANGES b/CHANGES
index e845909e72ae1f51528ed66282b38455b3fc6e2d..6e248269d876b4c109a8825482a408995d2f74d1 100644 (file)
--- a/CHANGES
+++ b/CHANGES
@@ -1,6 +1,10 @@
                                                          -*- coding: utf-8 -*-
 Changes with Apache 2.5.1
 
+  *) mod_logio: Add LogIOTrackTTFU and %^FU logformat to log the time
+     difference between request start and last request body byte read (finished upload).
+     [Rainer Jung]
+
   *) mod_ssl: add support for TLSv1.3 (tested with OpenSSL v1.1.1-pre4, other libs may
      need more sugar). SSL(Proxy)CipherSuite now has an optional first parameter for the
      protocol the ciphers are for.

diff --git a/docs/manual/mod/mod_logio.xml b/docs/manual/mod/mod_logio.xml
index 910a47ee564b4ea2fca8076299a018573288abc9..e36844d4659d2d585a352e4ed156251be3dad1d2 100644 (file)
--- a/docs/manual/mod/mod_logio.xml
+++ b/docs/manual/mod/mod_logio.xml
@@ -73,6 +73,13 @@
         cannot be zero. This is the combination of %I and %O.<br />
         Available in Apache 2.4.7 and later</td></tr>
 
+    <tr><td><code>%^FU</code></td>
+        <td>Delay in microseconds between when the request arrived and the
+        last byte of the request body was read (finished upload).
+        Only available if <directive>LogIOTrackTTFU</directive> is set to
+        ON.<br />
+        Available in Apache 2.4.34 and later</td></tr>
+
     <tr><td><code>%^FB</code></td>
         <td>Delay in microseconds between when the request arrived and the
         first byte of the response headers are written.  Only available if
@@ -89,9 +96,29 @@
     </dl>
 </section>
 
+<directivesynopsis>
+<name>LogIOTrackTTFU</name>
+<description>Enable tracking of time to last request byte (TTFU = time to finish
+upload)</description>
+<syntax>LogIOTrackTTFU ON|OFF</syntax>
+<default>LogIOTrackTTFU OFF</default>
+<contextlist><context>server config</context><context>virtual host</context>
+<context>directory</context><context>.htaccess</context></contextlist>
+<override>All</override>
+<compatibility>Apache HTTP Server 2.4.34 and later</compatibility>
+
+<usage>
+    <p>This directive configures whether this module tracks the delay
+    between the request being read and the last byte of the request
+    body being read (finished upload).  The resulting value may be logged
+    with the <code>%^FU</code> format.</p>
+</usage>
+</directivesynopsis>
+
 <directivesynopsis>
 <name>LogIOTrackTTFB</name>
-<description>Enable tracking of time to first byte (TTFB)</description>
+<description>Enable tracking of time to first byte (TTFB = time to first byte)
+</description>
 <syntax>LogIOTrackTTFB ON|OFF</syntax>
 <default>LogIOTrackTTFB OFF</default>
 <contextlist><context>server config</context><context>virtual host</context>

diff --git a/modules/loggers/mod_logio.c b/modules/loggers/mod_logio.c
index b609f7f270fadfcf78d3d0d70dcfd3d5f6887acd..bf98ccb84c456d2734f610214aee26a83e81022f 100644 (file)
--- a/modules/loggers/mod_logio.c
+++ b/modules/loggers/mod_logio.c
@@ -38,6 +38,7 @@
 module AP_MODULE_DECLARE_DATA logio_module;
 
 static const char logio_filter_name[] = "LOG_INPUT_OUTPUT";
+static const char logio_ttfu_filter_name[] = "LOGIO_TTFU_IN";
 static const char logio_ttfb_filter_name[] = "LOGIO_TTFB_OUT";
 
 /*
@@ -51,10 +52,14 @@ typedef struct logio_config_t {
 } logio_config_t;
 
 typedef struct logio_dirconf_t {
+    unsigned int track_ttfu:1;
+    unsigned int track_ttfu_set:1;
     unsigned int track_ttfb:1;
+    unsigned int track_ttfb_set:1;
 } logio_dirconf_t;
 
 typedef struct logio_req_t {
+    apr_time_t ttfu;
     apr_time_t ttfb;
 } logio_req_t;
 
@@ -121,6 +126,18 @@ static const char *log_bytes_combined(request_rec *r, char *a)
     return apr_off_t_toa(r->pool, cf->bytes_out + cf->bytes_in);
 }
 
+static const char *log_ttfu(request_rec *r, char *a)
+{
+    logio_req_t *rconf = ap_get_module_config(r->request_config,
+                                           &logio_module);
+
+    if (!rconf || !rconf->ttfu) { 
+        return "-";
+    }
+
+    return apr_psprintf(r->pool, "%" APR_TIME_T_FMT, rconf->ttfu - r->request_time);
+}
+
 static const char *log_ttfb(request_rec *r, char *a)
 {
     logio_req_t *rconf = ap_get_module_config(r->request_config,
@@ -197,12 +214,43 @@ static int logio_pre_config(apr_pool_t *p, apr_pool_t *plog, apr_pool_t *ptemp)
         log_pfn_register(p, "I", log_bytes_in, 0);
         log_pfn_register(p, "O", log_bytes_out, 0);
         log_pfn_register(p, "S", log_bytes_combined, 0);
+        log_pfn_register(p, "^FU", log_ttfu, 0);
         log_pfn_register(p, "^FB", log_ttfb, 0);
     }
 
     return OK;
 }
 
+static apr_status_t logio_ttfu_filter(ap_filter_t *f,
+                                      apr_bucket_brigade *bb,
+                                      ap_input_mode_t mode,
+                                      apr_read_type_e block,
+                                      apr_off_t readbytes)
+{
+    apr_off_t length;
+    apr_status_t status;
+
+    status = ap_get_brigade(f->next, bb, mode, block, readbytes);
+
+    apr_brigade_length(bb, 0, &length);
+
+    if (length > 0) {
+        request_rec *r = f->r;
+        logio_dirconf_t *conf = ap_get_module_config(r->per_dir_config,
+                                                     &logio_module);
+        if (conf && conf->track_ttfu) { 
+            logio_req_t *rconf = ap_get_module_config(r->request_config, 
+                                                      &logio_module);
+            if (rconf == NULL) { 
+                rconf = apr_pcalloc(r->pool, sizeof(logio_req_t));
+                ap_set_module_config(r->request_config, &logio_module, rconf);
+            }
+            rconf->ttfu = apr_time_now();
+        }
+    }
+    return status;
+}
+
 static apr_status_t logio_ttfb_filter(ap_filter_t *f, apr_bucket_brigade *b)
 {
     request_rec *r = f->r;
@@ -213,9 +261,11 @@ static apr_status_t logio_ttfb_filter(ap_filter_t *f, apr_bucket_brigade *b)
                                                   &logio_module);
         if (rconf == NULL) { 
             rconf = apr_pcalloc(r->pool, sizeof(logio_req_t));
-            rconf->ttfb = apr_time_now() - r->request_time;
             ap_set_module_config(r->request_config, &logio_module, rconf);
         }
+        if (rconf->ttfb == 0) { 
+            rconf->ttfb = apr_time_now() - r->request_time;
+        }
     }
     ap_remove_output_filter(f);
     return ap_pass_brigade(f->next, b);
@@ -225,15 +275,27 @@ static void logio_insert_filter(request_rec * r)
 {
     logio_dirconf_t *conf = ap_get_module_config(r->per_dir_config,
                                                  &logio_module);
+    if (conf->track_ttfu) {
+        ap_add_input_filter(logio_ttfu_filter_name, NULL, r, r->connection);
+    }
     if (conf->track_ttfb) { 
         ap_add_output_filter(logio_ttfb_filter_name, NULL, r, r->connection);
     }
 }
 
+static const char *logio_track_ttfu(cmd_parms *cmd, void *in_dir_config, int arg)
+{
+    logio_dirconf_t *dir_config = in_dir_config;
+    dir_config->track_ttfu = arg;
+    dir_config->track_ttfu_set = 1;
+    return NULL;
+}
+
 static const char *logio_track_ttfb(cmd_parms *cmd, void *in_dir_config, int arg)
 {
     logio_dirconf_t *dir_config = in_dir_config;
     dir_config->track_ttfb = arg;
+    dir_config->track_ttfb_set = 1;
     return NULL;
 }
 
@@ -245,7 +307,24 @@ static void *create_logio_dirconf (apr_pool_t *p, char *dummy)
 }
 
 
+static void *merge_logio_dirconf(apr_pool_t *p, void *basev, void *addv)
+{
+    logio_dirconf_t *new = (logio_dirconf_t *) apr_pcalloc(p, sizeof(logio_dirconf_t));
+    const logio_dirconf_t *add = (logio_dirconf_t *) addv;
+    const logio_dirconf_t *base = (logio_dirconf_t *) basev;
+
+    new->track_ttfu = add->track_ttfu_set ? add->track_ttfu : base->track_ttfu;
+    new->track_ttfu_set = add->track_ttfu_set || base->track_ttfu_set;
+    new->track_ttfb = add->track_ttfb_set ? add->track_ttfb : base->track_ttfb;
+    new->track_ttfb_set = add->track_ttfb_set || base->track_ttfb_set;
+
+    return new;
+}
+
+
 static const command_rec logio_cmds[] = {
+    AP_INIT_FLAG ("LogIOTrackTTFU", logio_track_ttfu, NULL, OR_ALL,
+                  "Set to 'ON' to enable tracking time to finish upload"),
     AP_INIT_FLAG ("LogIOTrackTTFB", logio_track_ttfb, NULL, OR_ALL,
                   "Set to 'ON' to enable tracking time to first byte"),
     {NULL}
@@ -264,6 +343,8 @@ static void register_hooks(apr_pool_t *p)
                              AP_FTYPE_NETWORK - 1);
 
     ap_hook_insert_filter(logio_insert_filter, NULL, NULL, APR_HOOK_LAST);
+    ap_register_input_filter(logio_ttfu_filter_name, logio_ttfu_filter, NULL,
+                              AP_FTYPE_RESOURCE);
     ap_register_output_filter(logio_ttfb_filter_name, logio_ttfb_filter, NULL,
                               AP_FTYPE_RESOURCE);
 
@@ -276,7 +357,7 @@ AP_DECLARE_MODULE(logio) =
 {
     STANDARD20_MODULE_STUFF,
     create_logio_dirconf,       /* create per-dir config */ 
-    NULL,                       /* merge per-dir config */
+    merge_logio_dirconf,        /* merge per-dir config */
     NULL,                       /* server config */
     NULL,                       /* merge server config */
     logio_cmds,                 /* command apr_table_t */