Commit c30ccc9c authored by Rainer Jung's avatar Rainer Jung
Browse files

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
parent 3bccad70

CHANGES

+4 −0
Original line number Diff line number Diff line
@@ -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]

STATUS

+1 −13
Original line number Diff line number Diff line
@@ -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

modules/loggers/mod_log_config.c

+33 −4
Original line number Diff line number Diff line
@@ -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..

     */