Commit 47971d51 authored by Yann Ylavic's avatar Yann Ylavic
Browse files

Merged r979120 from trunk. 


r979120 | rjung | 2010-07-25 23:08:15 +0200 (Sun, 25 Jul 2010) | 26 lines

Adding sub second timestamps and request end time to mod_log_config.

Add special format tokens to %{...}t. The extended syntax allows the
form: "WHICH:WHAT".

WHICH is either:
- "begin": use the time when the request started
- "end": take "now" as the time
You can omit WHICH, default is "begin".
If you omit WHICH, the separating column is not allowed.

WHAT is either:
- "sec": timestamp in Unix seconds
- "msec": timestamp in Unix milliseconds
- "msec_frac": millisecond fraction of the Unix timestamp,
               3 digits, 0-padded
- "usec": timestamp in Unix microseconds
- "usec_frac": microsecond fraction of the Unix timestamp
               6 digits, 0-padded
- anything different from those tokens: use strftime()
You can omit WHAT, default is the formatted timestamp as
used by the Common Log Format.

The implementation uses a new request_config for mod_log_config
to pass the request end time around between different calls to
log formatters, but the end time is only generated if needed.


Reviewed by: rjung, wrowe, ylavic
Backported by: ylavic


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

CHANGES

+3 −0
Original line number Diff line number Diff line
@@ -9,6 +9,9 @@ Changes with Apache 2.2.30 
  *) mpm_winnt: Accept utf-8 (Unicode) service names and descriptions for

     internationalization.  [William Rowe]



  *) mod_log_config: Implement logging for sub second timestamps and

     request end time.  [Rainer Jung]



  *) 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]

STATUS

+0 −11
Original line number Diff line number Diff line
@@ -101,17 +101,6 @@ RELEASE SHOWSTOPPERS: 
PATCHES ACCEPTED TO BACKPORT FROM TRUNK:

  [ start all new proposals below, under PATCHES PROPOSED. ]



   * mod_log_config: Allow to choose request start or end time

     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.

     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-v2.patch

     +1: rjung, wrowe, ylavic

     rjung: I had forgotten the docs part. Added in v2 patch. OK to keep Bill's vote?





PATCHES PROPOSED TO BACKPORT FROM TRUNK:

  [ New proposals should be added at the end of the list ]

docs/manual/mod/mod_log_config.xml

+29 −1
Original line number Diff line number Diff line
@@ -179,7 +179,25 @@ 


    <tr><td><code>%{<var>format</var>}t</code></td>

        <td>The time, in the form given by format, which should be in

        <code>strftime(3)</code> format. (potentially localized)</td></tr>

        an extended <code>strftime(3)</code> format (potentially localized).

        If the format starts with <code>begin:</code> (default) the time is taken

        at the beginning of the request processing. If it starts with

        <code>end:</code> it is the time when the log entry gets written,

        close to the end of the request processing. In addition to the formats

        supported by <code>strftime(3)</code>, the following format tokens are

        supported:

        <table>

        <tr><td><code>sec</code></td><td>number of seconds since the Epoch</td></tr>

        <tr><td><code>msec</code></td><td>number of milliseconds since the Epoch</td></tr>

        <tr><td><code>usec</code></td><td>number of microseconds since the Epoch</td></tr>

        <tr><td><code>msec_frac</code></td><td>millisecond fraction</td></tr>

        <tr><td><code>usec_frac</code></td><td>microsecond fraction</td></tr>

        </table>

        These tokens can not be combined with each other or <code>strftime(3)</code>

        formatting in the same format string. You can use multiple

        <code>%{<var>format</var>}t</code> tokens instead. The extended

        <code>strftime(3)</code> tokens are available in 2.2.30 and later.

        </td></tr>



    <tr><td><code>%T</code></td>

        <td>The time taken to serve the request, in seconds.</td></tr>
@@ -322,6 +340,16 @@ 
        <dt>Agent (Browser) log format</dt>

        <dd><code>"%{User-agent}i"</code></dd>

      </dl>



      <p>You can use the <code>%{format}t</code> directive multiple

      times to build up a time format using the extended format tokens

      like <code>msec_frac</code>:</p>

      <dl>

<dt>Timestamp including milliseconds</dt>

<dd><code>"%{%d/%b/%Y %T}t.%{msec_frac}t %{%z}t"</code></dd>



      </dl>



    </section>

</section>

modules/loggers/mod_log_config.c

+91 −22
Original line number Diff line number Diff line
@@ -595,6 +595,14 @@ typedef struct { 
    unsigned t_validate;

} cached_request_time;



#define TIME_FMT_CUSTOM          0

#define TIME_FMT_CLF             1

#define TIME_FMT_ABS_SEC         2

#define TIME_FMT_ABS_MSEC        3

#define TIME_FMT_ABS_USEC        4

#define TIME_FMT_ABS_MSEC_FRAC   5

#define TIME_FMT_ABS_USEC_FRAC   6



#define TIME_CACHE_SIZE 4

#define TIME_CACHE_MASK 3

static cached_request_time request_time_cache[TIME_CACHE_SIZE];
@@ -617,29 +625,95 @@ static apr_time_t get_request_end_time(request_rec *r) 
static const char *log_request_time(request_rec *r, char *a)

{

    apr_time_exp_t xt;

    apr_time_t request_time = r->request_time;

    int fmt_type = TIME_FMT_CUSTOM;

    char *fmt = a;



    /* ###  I think getting the time again at the end of the request

     * just for logging is dumb.  i know it's "required" for CLF.

     * folks writing log parsing tools don't realise that out of order

     * times have always been possible (consider what happens if one

     * process calculates the time to log, but then there's a context

     * switch before it writes and before that process is run again the

     * log rotation occurs) and they should just fix their tools rather

     * than force the server to pay extra cpu cycles.  if you've got

     * a problem with this, you can set the define.  -djg

    if (fmt && *fmt) {

        if (!strncmp(fmt, "begin", 5)) {

            fmt += 5;

            if (!*fmt) {

                fmt_type = TIME_FMT_CLF;

            }

            else if (*fmt == ':') {

                fmt++;

                a = fmt;

            }

        }

        else if (!strncmp(fmt, "end", 3)) {

            fmt += 3;

            if (!*fmt) {

                request_time = get_request_end_time(r);

                fmt_type = TIME_FMT_CLF;

            }

            else if (*fmt == ':') {

                fmt++;

                a = fmt;

                request_time = get_request_end_time(r);

            }

        }

        if (!strncmp(fmt, "msec", 4)) {

            fmt += 4;

            if (!*fmt) {

                fmt_type = TIME_FMT_ABS_MSEC;

            }

            else if (!strcmp(fmt, "_frac")) {

                fmt_type = TIME_FMT_ABS_MSEC_FRAC;

            }

        }

        else if (!strncmp(fmt, "usec", 4)) {

            fmt += 4;

            if (!*fmt) {

                fmt_type = TIME_FMT_ABS_USEC;

            }

            else if (!strcmp(fmt, "_frac")) {

                fmt_type = TIME_FMT_ABS_USEC_FRAC;

            }

        }

        else if (!strcmp(fmt, "sec")) {

            fmt_type = TIME_FMT_ABS_SEC;

        }

        else if (!*fmt) {

            fmt_type = TIME_FMT_CLF;

        }

    }

    else {

        fmt_type = TIME_FMT_CLF;

    }



    if (fmt_type >= TIME_FMT_ABS_SEC) {      /* Absolute (micro-/milli-)second time

                                              * or msec/usec fraction

                                              */

    if (a && *a) {              /* Custom format */

        char* buf = apr_palloc(r->pool, 20);

        switch (fmt_type) {

        case TIME_FMT_ABS_SEC:

            apr_snprintf(buf, 20, "%" APR_TIME_T_FMT, apr_time_sec(request_time));

            break;

        case TIME_FMT_ABS_MSEC:

            apr_snprintf(buf, 20, "%" APR_TIME_T_FMT, apr_time_as_msec(request_time));

            break;

        case TIME_FMT_ABS_USEC:

            apr_snprintf(buf, 20, "%" APR_TIME_T_FMT, request_time);

            break;

        case TIME_FMT_ABS_MSEC_FRAC:

            apr_snprintf(buf, 20, "%03" APR_TIME_T_FMT, apr_time_msec(request_time));

            break;

        case TIME_FMT_ABS_USEC_FRAC:

            apr_snprintf(buf, 20, "%06" APR_TIME_T_FMT, apr_time_usec(request_time));

            break;

        default:

            return "-";

        }

        return buf;

    }

    else if (fmt_type == TIME_FMT_CUSTOM) {  /* Custom format */

        /* The custom time formatting uses a very large temp buffer

         * on the stack.  To avoid using so much stack space in the

         * common case where we're not using a custom format, the code

         * for the custom format in a separate function.  (That's why

         * log_request_time_custom is not inlined right here.)

         */

#ifdef I_INSIST_ON_EXTRA_CYCLES_FOR_CLF_COMPLIANCE

        ap_explode_recent_localtime(&xt, get_request_end_time(r));

#else

        ap_explode_recent_localtime(&xt, r->request_time);

#endif

        ap_explode_recent_localtime(&xt, request_time);

        return log_request_time_custom(r, a, &xt);

    }

    else {                                   /* CLF format */
@@ -649,11 +723,6 @@ 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 = get_request_end_time(r);

#else

        apr_time_t request_time = r->request_time;

#endif

        unsigned t_seconds = (unsigned)apr_time_sec(request_time);

        unsigned i = t_seconds & TIME_CACHE_MASK;

        *cached_time = request_time_cache[i];