mod_log_config: Backport get_request_end_time().

This makes data consistent if a log format uses
multiple %{...}T and/or %D.
The end time of a request is only taken once and
the same time is used for each log field.

Backport of r979120 (partial) plus r1467765 from trunk
resp. r979120 (partial) plus r1467981 from 2.4.x.

Committed By: rjung
Reviewed By: rjung, trawick, wrowe
Backported By: rjung

git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/branches/2.2.x@1681269 13f79535-47bb-0310-9956-ffa450edef68

diff --git a/CHANGES b/CHANGES
index 600eac02143c958c613b404cf3c0b680205a1812..7162a1a49ea162bbbe8a6c1dd1a59d3d63cde469 100644 (file)
--- a/CHANGES
+++ b/CHANGES
@@ -4,6 +4,10 @@ Changes with Apache 2.2.30
   *) mpm_winnt: Accept utf-8 (Unicode) service names and descriptions for
      internationalization.  [William Rowe]
 
+  *) mod_log_config: Ensure that time data is consistent if multiple
+     duration patterns are used in combination, e.g. %D and %{ms}T.
+     [Rainer Jung]
+
   *) mod_log_config: Add "%{UNIT}T" format to output request duration in
      seconds, milliseconds or microseconds depending on UNIT ("s", "ms", "us").
      [Ben Reser, Rainer Jung]

diff --git a/STATUS b/STATUS
index f17f1bf2816592618eefd0d28c92214197e959e3..9bc22bdfea126569b33a4378fcd91beca2a137b1 100644 (file)
--- a/STATUS
+++ b/STATUS
@@ -101,18 +101,6 @@ RELEASE SHOWSTOPPERS:
 PATCHES ACCEPTED TO BACKPORT FROM TRUNK:
   [ start all new proposals below, under PATCHES PROPOSED. ]
 
-   * mod_log_config: Backport get_request_end_time().
-     This makes data consistent if a log format uses multiple %{...}T
-     and/or %D. The end time of a request is only taken once and the
-     same time is used for each log field.
-     trunk patch: http://svn.apache.org/r979120 (partial)
-                  http://svn.apache.org/r1467765
-     2.4.x patch: http://svn.apache.org/r979120 (partial)
-                  http://svn.apache.org/r1467981
-     2.2.x patch: http://people.apache.org/~rjung/patches/httpd-2.2.x-mod_log_config-get_request_end_time.patch
-     +1: rjung, trawick, wrowe
-
-
 PATCHES PROPOSED TO BACKPORT FROM TRUNK:
   [ New proposals should be added at the end of the list ]
 
@@ -128,7 +116,7 @@ PATCHES PROPOSED TO BACKPORT FROM TRUNK:
      as time stamp in log (httpd traditionally uses start, many
      other components, e.g. Tomcat use end time, so they are kind
      of hard to correlate). Also add more format choices for time stamps.
-     Assumes backport of get_request_end_time() above.
+     Needed get_request_end_time() was already ported back.
      trunk patch: http://svn.apache.org/r979120 (remaining parts)
      2.4.x patch: http://svn.apache.org/r979120 (remaining parts)
      2.2.x patch: http://people.apache.org/~rjung/patches/httpd-2.2.x-mod_log_config-more_time_formats.patch

diff --git a/modules/loggers/mod_log_config.c b/modules/loggers/mod_log_config.c
index 21ae6760569d1bdfaffcb9bde22d3148a245c382..1bac9b3b26fe09cc45a2c7cb499ae7251b79d574 100644 (file)
--- a/modules/loggers/mod_log_config.c
+++ b/modules/loggers/mod_log_config.c
@@ -268,6 +268,14 @@ typedef struct {
     char *condition_var;
 } config_log_state;
 
+/*
+ * log_request_state holds request specific log data that is not
+ * part of the request_rec.
+ */
+typedef struct {
+    apr_time_t request_end_time;
+} log_request_state;
+
 /*
  * Format items...
  * Note that many of these could have ap_sprintfs replaced with static buffers.
@@ -591,6 +599,21 @@ typedef struct {
 #define TIME_CACHE_MASK 3
 static cached_request_time request_time_cache[TIME_CACHE_SIZE];
 
+static apr_time_t get_request_end_time(request_rec *r)
+{
+    log_request_state *state = (log_request_state *)ap_get_module_config(r->request_config,
+                                                                         &log_config_module);
+    if (!state) {
+        state = apr_pcalloc(r->pool, sizeof(log_request_state));
+        ap_set_module_config(r->request_config, &log_config_module, state);
+    }
+    if (state->request_end_time == 0) {
+        state->request_end_time = apr_time_now();
+    }
+    return state->request_end_time;
+}
+
+
 static const char *log_request_time(request_rec *r, char *a)
 {
     apr_time_exp_t xt;
@@ -613,7 +636,7 @@ static const char *log_request_time(request_rec *r, char *a)
          * log_request_time_custom is not inlined right here.)
          */
 #ifdef I_INSIST_ON_EXTRA_CYCLES_FOR_CLF_COMPLIANCE
-        ap_explode_recent_localtime(&xt, apr_time_now());
+        ap_explode_recent_localtime(&xt, get_request_end_time(r));
 #else
         ap_explode_recent_localtime(&xt, r->request_time);
 #endif
@@ -627,7 +650,7 @@ static const char *log_request_time(request_rec *r, char *a)
         cached_request_time* cached_time = apr_palloc(r->pool,
                                                       sizeof(*cached_time));
 #ifdef I_INSIST_ON_EXTRA_CYCLES_FOR_CLF_COMPLIANCE
-        apr_time_t request_time = apr_time_now();
+        apr_time_t request_time = get_request_end_time(r);
 #else
         apr_time_t request_time = r->request_time;
 #endif
@@ -668,12 +691,12 @@ static const char *log_request_time(request_rec *r, char *a)
 static const char *log_request_duration_microseconds(request_rec *r, char *a)
 {
     return apr_psprintf(r->pool, "%" APR_TIME_T_FMT,
-                        (apr_time_now() - r->request_time));
+                        (get_request_end_time(r) - r->request_time));
 }
 
 static const char *log_request_duration_scaled(request_rec *r, char *a)
 {
-    apr_time_t duration = apr_time_now() - r->request_time;
+    apr_time_t duration = get_request_end_time(r) - r->request_time;
     if (*a == '\0' || !strcasecmp(a, "s")) {
         duration = apr_time_sec(duration);
     }
@@ -1074,6 +1097,12 @@ static int multi_log_transaction(request_rec *r)
     config_log_state *clsarray;
     int i;
 
+    /*
+     * Initialize per request state
+     */
+    log_request_state *state = apr_pcalloc(r->pool, sizeof(log_request_state));
+    ap_set_module_config(r->request_config, &log_config_module, state);
+
     /*
      * Log this transaction..
      */