From: Rainer Jung Date: Sat, 23 May 2015 06:38:13 +0000 (+0000) Subject: mod_log_config: Backport get_request_end_time(). X-Git-Tag: 2.2.30~62 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=e8a759086b208520ab31c84fedb6002805b1e3d9;p=thirdparty%2Fapache%2Fhttpd.git 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 600eac02143..7162a1a49ea 100644 --- 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 f17f1bf2816..9bc22bdfea1 100644 --- 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 21ae6760569..1bac9b3b26f 100644 --- 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.. */