From: Yann Ylavic Date: Sat, 23 May 2015 09:23:13 +0000 (+0000) Subject: Merged r979120 from trunk. X-Git-Tag: 2.2.30~57 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=5db1d71f130f77a126280f177448d0be0c68a0bd;p=thirdparty%2Fapache%2Fhttpd.git 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 --- diff --git a/CHANGES b/CHANGES index 9ca970e3e0d..d7dfcbce77d 100644 --- a/CHANGES +++ b/CHANGES @@ -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] diff --git a/STATUS b/STATUS index dc05311c133..a4432516328 100644 --- a/STATUS +++ b/STATUS @@ -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 ] diff --git a/docs/manual/mod/mod_log_config.xml b/docs/manual/mod/mod_log_config.xml index 1fd816a9325..2db111a8000 100644 --- a/docs/manual/mod/mod_log_config.xml +++ b/docs/manual/mod/mod_log_config.xml @@ -179,7 +179,25 @@ %{format}t The time, in the form given by format, which should be in - strftime(3) format. (potentially localized) + an extended strftime(3) format (potentially localized). + If the format starts with begin: (default) the time is taken + at the beginning of the request processing. If it starts with + end: 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 strftime(3), the following format tokens are + supported: + + + + + + +
secnumber of seconds since the Epoch
msecnumber of milliseconds since the Epoch
usecnumber of microseconds since the Epoch
msec_fracmillisecond fraction
usec_fracmicrosecond fraction
+ These tokens can not be combined with each other or strftime(3) + formatting in the same format string. You can use multiple + %{format}t tokens instead. The extended + strftime(3) tokens are available in 2.2.30 and later. + %T The time taken to serve the request, in seconds. @@ -322,6 +340,16 @@
Agent (Browser) log format
"%{User-agent}i"
+ +

You can use the %{format}t directive multiple + times to build up a time format using the extended format tokens + like msec_frac:

+
+
Timestamp including milliseconds
+
"%{%d/%b/%Y %T}t.%{msec_frac}t %{%z}t"
+ +
+ diff --git a/modules/loggers/mod_log_config.c b/modules/loggers/mod_log_config.c index 1bac9b3b26f..acfdcccd7ff 100644 --- a/modules/loggers/mod_log_config.c +++ b/modules/loggers/mod_log_config.c @@ -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,43 +625,104 @@ 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; + + 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; + } - /* ### 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 (a && *a) { /* Custom format */ + if (fmt_type >= TIME_FMT_ABS_SEC) { /* Absolute (micro-/milli-)second time + * or msec/usec fraction + */ + 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 */ + else { /* CLF format */ /* This code uses the same technique as ap_explode_recent_localtime(): * optimistic caching with logic to detect and correct race conditions. * See the comments in server/util_time.c for more information. */ 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];