You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@httpd.apache.org by Rainer Jung <ra...@kippdata.de> on 2010/06/01 14:56:44 UTC
Enhanced error log format for trunk?
I repeatedly inserted millisecond or microsecond timestamps as well as
PID and thread ID information into the ErrorLog when trying to diagnose
problems, most often in combination with additional log lines.
Due to the increased load and capability of systems and increasing
amount of concurrency, would those features be interesting by default?
1) Sub-second timestamps in error log
Index: server/util_time.c
===================================================================
--- server/util_time.c (revision 949733)
+++ server/util_time.c (working copy)
@@ -151,6 +151,8 @@
apr_time_exp_t xt;
const char *s;
int real_year;
+ int usec;
+ int div;
/* example: "Wed Jun 30 21:49:08 1993" */
/* 123456789012345678901234 */
@@ -177,6 +179,12 @@
*date_str++ = ':';
*date_str++ = xt.tm_sec / 10 + '0';
*date_str++ = xt.tm_sec % 10 + '0';
+ *date_str++ = '.';
+ usec = (int)xt.tm_usec;
+ for (div=100000; div>0; div=div/10) {
+ *date_str++ = usec / div + '0';
+ usec = usec % div;
+ }
*date_str++ = ' ';
real_year = 1900 + xt.tm_year;
*date_str++ = real_year / 1000 + '0';
Index: server/log.c
===================================================================
--- server/log.c (revision 949733)
+++ server/log.c (working copy)
@@ -594,9 +594,9 @@
if (logf && ((level & APLOG_STARTUP) != APLOG_STARTUP)) {
errstr[0] = '[';
ap_recent_ctime(errstr + 1, apr_time_now());
- errstr[1 + APR_CTIME_LEN - 1] = ']';
- errstr[1 + APR_CTIME_LEN ] = ' ';
- len = 1 + APR_CTIME_LEN + 1;
+ errstr[1 + APR_CTIME_LEN + 7 - 1] = ']';
+ errstr[1 + APR_CTIME_LEN + 7 ] = ' ';
+ len = 1 + APR_CTIME_LEN + 7 + 1;
} else {
len = 0;
}
and maybe switching away from the CTIME name, because it's no longer
real ctime.
2) PID and thread ID
Index: server/log.c
===================================================================
--- server/log.c (revision 949733)
+++ server/log.c (working copy)
@@ -25,6 +25,7 @@
#include "apr_general.h" /* for signal stuff */
#include "apr_strings.h"
#include "apr_errno.h"
+#include "apr_portable.h"
#include "apr_thread_proc.h"
#include "apr_lib.h"
#include "apr_signal.h"
@@ -606,6 +607,18 @@
"[%s] ", priorities[level_and_mask].t_name);
}
+ len += apr_snprintf(errstr + len, MAX_STRING_LEN - len,
+ "[%" APR_PID_T_FMT, getpid());
+#if APR_HAS_THREADS
+ {
+ apr_os_thread_t tid = apr_os_thread_current();
+ len += apr_snprintf(errstr + len, MAX_STRING_LEN - len,
+ ":%pT", &tid);
+ }
+#endif
+ errstr[len++] = ']';
+ errstr[len++] = ' ';
+
if (file && level_and_mask == APLOG_DEBUG) {
#if defined(_OSD_POSIX) || defined(WIN32) || defined(__MVS__)
char tmp[256];
PID and thread id are useful, because the can be correlated with the
access_log (when added there). they also help to understand, which
messages belong "together" when multiple log events are intertwined.
3) Related things for access log
There's a related open Bugzilla about adding sub-second timestamps (not:
duration) to the access log (BZ 49251). The OP suggests to use %M for an
absolute timestamp. It would be nice to improve the strftime use of
%{format}t to allow for a proprietary microsecond letter which will add
the microsecond part of the actual time. I found no standards defined
for that.
4) General correlation improvements
To be able to correlate error and access log, it would be helpful to
share a common id, e.g. the unique_id, and be able to log it in both
files. The id generated by mod_unique_id comes too late though
(post_read_request). Since it actually only uses the request timestamp
and the connection id of the request, it could be calculated much earlier.
Regards,
Rainer
Re: Enhanced error log format for trunk?
Posted by Rainer Jung <ra...@kippdata.de>.
On 09.06.2010 14:37, Jeff Trawick wrote:
> On Tue, Jun 1, 2010 at 8:56 AM, Rainer Jung <rainer.jung@kippdata.de
> <ma...@kippdata.de>> wrote:
>
> I repeatedly inserted millisecond or microsecond timestamps as well
> as PID and thread ID information into the ErrorLog when trying to
> diagnose problems, most often in combination with additional log lines.
>
> Due to the increased load and capability of systems and increasing
> amount of concurrency, would those features be interesting by default?
>
>
> I realize it is a bit late for this...
>
>
> 1) Sub-second timestamps in error log
> 2) PID and thread ID
> 4) General correlation improvements
>
> To be able to correlate error and access log, it would be helpful to
> share a common id, e.g. the unique_id, and be able to log it in both
> files. The id generated by mod_unique_id comes too late though
> (post_read_request). Since it actually only uses the request
> timestamp and the connection id of the request, it could be
> calculated much earlier.
>
>
> Apologies if I misunderstand what is already committed... (swamped)
>
> Any thoughts about making this extra information configurable?
See the latest replies in this thread. Stefan compiled a list of things
that could be interesting to log (and would be to huge to add by
default) and I was asking whether copyin something from mod_log_config
would be helpful (forma patterns and callback functions).
> (Would you want your prefork error log to have a different format than your
> worker error log, for example? (thread id)
The tid has already been removed if the MPM is not threaded. There is
discussion though, how to best cache this information (threaded or not),
because the dynamically loaded MPM can now change between reloads (yes
it works) and a simple static variable in the parent won't be
reinitialized during reload.
> Would you even want you
> httpd 2.4 error log to have a different format from your 1.3-2.2 error
> log, at least until you can update any parsing scripts?
In my opinion that should be allowed in a 2.2 to 2.4 change. The changes
to the format are pretty trivial to add to parsers (ignoring additional
tokens).
> Any thoughts about modules being able to control some or all of this
> extra information?
Not yet, but if we clone the mod_log_config solution they could register
callbacks.
> A real world example would be a system (perhaps a set of products with
> common logging standards) with its own request correlation (some unique
> id) which is already implemented by many components. It is important
> for the Apache logs to use that particular id.
Right. But if you are in front of the id generating system (as the web
server often is) you are out of luck and then you would be the
generating system yourself. If your are somewhere behind, you could
extract from headers and then use your other suggestion (let modules
influence the common part of the error log line).
Regards,
Rainer
Re: Enhanced error log format for trunk?
Posted by Jeff Trawick <tr...@gmail.com>.
On Tue, Jun 1, 2010 at 8:56 AM, Rainer Jung <ra...@kippdata.de> wrote:
> I repeatedly inserted millisecond or microsecond timestamps as well as PID
> and thread ID information into the ErrorLog when trying to diagnose
> problems, most often in combination with additional log lines.
>
> Due to the increased load and capability of systems and increasing amount
> of concurrency, would those features be interesting by default?
>
I realize it is a bit late for this...
>
> 1) Sub-second timestamps in error log
> 2) PID and thread ID
> 4) General correlation improvements
>
> To be able to correlate error and access log, it would be helpful to share
> a common id, e.g. the unique_id, and be able to log it in both files. The id
> generated by mod_unique_id comes too late though (post_read_request). Since
> it actually only uses the request timestamp and the connection id of the
> request, it could be calculated much earlier.
>
Apologies if I misunderstand what is already committed... (swamped)
Any thoughts about making this extra information configurable? (Would you
want your prefork error log to have a different format than your worker
error log, for example? (thread id) Would you even want you httpd 2.4 error
log to have a different format from your 1.3-2.2 error log, at least until
you can update any parsing scripts?
Any thoughts about modules being able to control some or all of this extra
information?
A real world example would be a system (perhaps a set of products with
common logging standards) with its own request correlation (some unique id)
which is already implemented by many components. It is important for the
Apache logs to use that particular id.
Re: Enhanced error log format for trunk?
Posted by Stefan Fritsch <sf...@sfritsch.de>.
On Tuesday 08 June 2010, Rainer Jung wrote:
> On 08.06.2010 22:56, Stefan Fritsch wrote:
> > On Monday 07 June 2010, Rainer Jung wrote:
> >> On 03.06.2010 16:49, Stefan Fritsch wrote:
> >>> On Tuesday 01 June 2010, Rainer Jung wrote:
> >>>> 4) General correlation improvements
> >>>>
> >>>> To be able to correlate error and access log, it would be
> >>>> helpful to share a common id, e.g. the unique_id, and be able
> >>>> to log it in both files. The id generated by mod_unique_id
> >>>> comes too late though (post_read_request). Since it actually
> >>>> only uses the request timestamp and the connection id of the
> >>>> request, it could be calculated much earlier.
> >>>
> >>> I have thought about this before, but I wanted to get the
> >>> per-module loglevel configuration into trunk first.
> >>>
> >>> The log id could be created by the first call to ap_log_rerror.
> >>> If there has not been an errorlog entry for a request by the
> >>> time of the log transaction hook, the corresponding field in
> >>> the access log would just be "-".
> >>
> >> That's an interesting idea, making it pretty trivial to filter
> >> those lines, that have any error log entries.
> >>
> >>> The function creating the log id could also log some
> >>> interesting information once per request, instead of logging
> >>> it for every log line. For example PID/TID, local+remote
> >>> IP+Port, number of keep-alives on the connection, ...
> >>
> >> Hmmm, but some basics should stay on each line, otherwise it's
> >> to much hassle collection stuff (or we provide a script). Being
> >> able to correlate between access and error log is nice, being
> >> forced to correlate inside the error log to collect the data is
> >> not so nice.
> >
> > The script would be "grep log-id error_log". I fear the useful
> > information depends very much on the situation. Logging
> > everything makes sure that we have the useful information. But
> > this would obviously flood the error log if we do it on every
> > line or even for every request. Hence my suggestion to only log
> > it for requests which have at least one other error log message
> > logged.
> >
> > This should be configurable. Either this conditional verbose
> > logging or the "some information in every line" style that we
> > have now. And it should also be configurable what the "some
> > information" should be.
> >
> >> Do you already have any code fragments for that?
> >
> > No, these are only ideas so far. I have thought of following
> > things which may be nice to have as error log flags:
> >
> > - timestamp granularity
> > - don't log to the error log file (useful for modules using the
> > error log hook)
> > - log some kind of unique id
> > - do conditional verbose logging as outlined above
> > - log the name of the module
> > - always or never log source file name+line number, or make it
> > depend on the log level like now
> > - log process/thread id
> > - log errors that are induced by the client at level error or at
> > level debug (e.g. file not found, connection closed by client)
> >
> > Information that may be useful in the conditional verbose
> > logging: - local/remote port+ip,
> > - vhost/Host-header
> > - some way to correlate which requests are on the same
> > connection, like a connection id (I think pid/tid are not enough
> > with mpm event, but I could be mistaken)
>
> Correct
>
> > - Referrer-header
> > - number of keep-alive requests on the connection
> >
> > That's a lot, but I can think of situations where any of the
> > above information would be useful. Actually, for most pieces I
> > can remember situations where the information would have been
> > useful.
>
> What about introducing log formats for the error log, like
> mod_log_config does for the access log? Parsing the format string
> once and registering callbacks to do the actual formatting.
That would be the most flexible solution. To make me happy, there
would be one format string for the actual line format, one that is
logged once per connection, and one that is logged once per request.
> Naive implementation would mean a lot of code copying from
> mod_log_config.
There would be some added complications:
- log format items may need any of server_rec, conn_req, or
request_req but it is possible that some or all of these are not
available
- We cannot simply allocate memory from the server/connection/request
pool. Either we allocate a subpool from the respective pool and
destroy that after each line (but we don't even have a server_rec
during startup), or we would need a dedicated logging pool (per
thread?) that is cleared after each log line.
But it certainly sounds do-able.
Re: Enhanced error log format for trunk?
Posted by Rainer Jung <ra...@kippdata.de>.
On 08.06.2010 22:56, Stefan Fritsch wrote:
> On Monday 07 June 2010, Rainer Jung wrote:
>> On 03.06.2010 16:49, Stefan Fritsch wrote:
>>> On Tuesday 01 June 2010, Rainer Jung wrote:
>>>> 4) General correlation improvements
>>>>
>>>> To be able to correlate error and access log, it would be
>>>> helpful to share a common id, e.g. the unique_id, and be able
>>>> to log it in both files. The id generated by mod_unique_id
>>>> comes too late though (post_read_request). Since it actually
>>>> only uses the request timestamp and the connection id of the
>>>> request, it could be calculated much earlier.
>>>
>>> I have thought about this before, but I wanted to get the
>>> per-module loglevel configuration into trunk first.
>>>
>>> The log id could be created by the first call to ap_log_rerror.
>>> If there has not been an errorlog entry for a request by the
>>> time of the log transaction hook, the corresponding field in the
>>> access log would just be "-".
>>
>> That's an interesting idea, making it pretty trivial to filter
>> those lines, that have any error log entries.
>>
>>> The function creating the log id could also log some interesting
>>> information once per request, instead of logging it for every log
>>> line. For example PID/TID, local+remote IP+Port, number of
>>> keep-alives on the connection, ...
>>
>> Hmmm, but some basics should stay on each line, otherwise it's to
>> much hassle collection stuff (or we provide a script). Being able
>> to correlate between access and error log is nice, being forced to
>> correlate inside the error log to collect the data is not so nice.
>
> The script would be "grep log-id error_log". I fear the useful
> information depends very much on the situation. Logging everything
> makes sure that we have the useful information. But this would
> obviously flood the error log if we do it on every line or even for
> every request. Hence my suggestion to only log it for requests which
> have at least one other error log message logged.
>
> This should be configurable. Either this conditional verbose logging
> or the "some information in every line" style that we have now. And it
> should also be configurable what the "some information" should be.
>
>> Do you already have any code fragments for that?
>
> No, these are only ideas so far. I have thought of following things
> which may be nice to have as error log flags:
>
> - timestamp granularity
> - don't log to the error log file (useful for modules using the error
> log hook)
> - log some kind of unique id
> - do conditional verbose logging as outlined above
> - log the name of the module
> - always or never log source file name+line number, or make it depend
> on the log level like now
> - log process/thread id
> - log errors that are induced by the client at level error or at level
> debug (e.g. file not found, connection closed by client)
>
> Information that may be useful in the conditional verbose logging:
> - local/remote port+ip,
> - vhost/Host-header
> - some way to correlate which requests are on the same connection,
> like a connection id (I think pid/tid are not enough with mpm event,
> but I could be mistaken)
Correct
> - Referrer-header
> - number of keep-alive requests on the connection
>
> That's a lot, but I can think of situations where any of the above
> information would be useful. Actually, for most pieces I can remember
> situations where the information would have been useful.
What about introducing log formats for the error log, like
mod_log_config does for the access log? Parsing the format string once
and registering callbacks to do the actual formatting.
Naive implementation would mean a lot of code copying from mod_log_config.
Rainer
Re: Enhanced error log format for trunk?
Posted by Stefan Fritsch <sf...@sfritsch.de>.
On Monday 07 June 2010, Rainer Jung wrote:
> On 03.06.2010 16:49, Stefan Fritsch wrote:
> > On Tuesday 01 June 2010, Rainer Jung wrote:
> >> 4) General correlation improvements
> >>
> >> To be able to correlate error and access log, it would be
> >> helpful to share a common id, e.g. the unique_id, and be able
> >> to log it in both files. The id generated by mod_unique_id
> >> comes too late though (post_read_request). Since it actually
> >> only uses the request timestamp and the connection id of the
> >> request, it could be calculated much earlier.
> >
> > I have thought about this before, but I wanted to get the
> > per-module loglevel configuration into trunk first.
> >
> > The log id could be created by the first call to ap_log_rerror.
> > If there has not been an errorlog entry for a request by the
> > time of the log transaction hook, the corresponding field in the
> > access log would just be "-".
>
> That's an interesting idea, making it pretty trivial to filter
> those lines, that have any error log entries.
>
> > The function creating the log id could also log some interesting
> > information once per request, instead of logging it for every log
> > line. For example PID/TID, local+remote IP+Port, number of
> > keep-alives on the connection, ...
>
> Hmmm, but some basics should stay on each line, otherwise it's to
> much hassle collection stuff (or we provide a script). Being able
> to correlate between access and error log is nice, being forced to
> correlate inside the error log to collect the data is not so nice.
The script would be "grep log-id error_log". I fear the useful
information depends very much on the situation. Logging everything
makes sure that we have the useful information. But this would
obviously flood the error log if we do it on every line or even for
every request. Hence my suggestion to only log it for requests which
have at least one other error log message logged.
This should be configurable. Either this conditional verbose logging
or the "some information in every line" style that we have now. And it
should also be configurable what the "some information" should be.
> Do you already have any code fragments for that?
No, these are only ideas so far. I have thought of following things
which may be nice to have as error log flags:
- timestamp granularity
- don't log to the error log file (useful for modules using the error
log hook)
- log some kind of unique id
- do conditional verbose logging as outlined above
- log the name of the module
- always or never log source file name+line number, or make it depend
on the log level like now
- log process/thread id
- log errors that are induced by the client at level error or at level
debug (e.g. file not found, connection closed by client)
Information that may be useful in the conditional verbose logging:
- local/remote port+ip,
- vhost/Host-header
- some way to correlate which requests are on the same connection,
like a connection id (I think pid/tid are not enough with mpm event,
but I could be mistaken)
- Referrer-header
- number of keep-alive requests on the connection
That's a lot, but I can think of situations where any of the above
information would be useful. Actually, for most pieces I can remember
situations where the information would have been useful.
Re: Enhanced error log format for trunk?
Posted by Rainer Jung <ra...@kippdata.de>.
On 03.06.2010 16:49, Stefan Fritsch wrote:
> On Tuesday 01 June 2010, Rainer Jung wrote:
>> 4) General correlation improvements
>>
>> To be able to correlate error and access log, it would be helpful
>> to share a common id, e.g. the unique_id, and be able to log it in
>> both files. The id generated by mod_unique_id comes too late
>> though (post_read_request). Since it actually only uses the
>> request timestamp and the connection id of the request, it could
>> be calculated much earlier.
>
> I have thought about this before, but I wanted to get the per-module
> loglevel configuration into trunk first.
>
> The log id could be created by the first call to ap_log_rerror. If
> there has not been an errorlog entry for a request by the time of the
> log transaction hook, the corresponding field in the access log would
> just be "-".
That's an interesting idea, making it pretty trivial to filter those
lines, that have any error log entries.
> The function creating the log id could also log some interesting
> information once per request, instead of logging it for every log
> line. For example PID/TID, local+remote IP+Port, number of keep-alives
> on the connection, ...
Hmmm, but some basics should stay on each line, otherwise it's to much
hassle collection stuff (or we provide a script). Being able to
correlate between access and error log is nice, being forced to
correlate inside the error log to collect the data is not so nice.
> But I think a shorter id than the 20+ bytes of the unique id would be
> sufficient in most cases, and cause less disk space usage. I guess it
> would be good enough if the id is unique for one httpd instance in one
> day.
Definitey.
> Of course, if mod_unique_id is loaded, its long unique id could
> be used.
+1
Do you already have any code fragments for that?
Rainer
Re: Enhanced error log format for trunk?
Posted by Stefan Fritsch <sf...@sfritsch.de>.
On Tuesday 01 June 2010, Rainer Jung wrote:
> I repeatedly inserted millisecond or microsecond timestamps as well
> as PID and thread ID information into the ErrorLog when trying to
> diagnose problems, most often in combination with additional log
> lines.
>
> Due to the increased load and capability of systems and increasing
> amount of concurrency, would those features be interesting by
> default?
Absolutely. Either by default of by some config directive. Having to
recompile modules to get such information is a PITA.
> 4) General correlation improvements
>
> To be able to correlate error and access log, it would be helpful
> to share a common id, e.g. the unique_id, and be able to log it in
> both files. The id generated by mod_unique_id comes too late
> though (post_read_request). Since it actually only uses the
> request timestamp and the connection id of the request, it could
> be calculated much earlier.
I have thought about this before, but I wanted to get the per-module
loglevel configuration into trunk first.
The log id could be created by the first call to ap_log_rerror. If
there has not been an errorlog entry for a request by the time of the
log transaction hook, the corresponding field in the access log would
just be "-".
The function creating the log id could also log some interesting
information once per request, instead of logging it for every log
line. For example PID/TID, local+remote IP+Port, number of keep-alives
on the connection, ...
But I think a shorter id than the 20+ bytes of the unique id would be
sufficient in most cases, and cause less disk space usage. I guess it
would be good enough if the id is unique for one httpd instance in one
day. Of course, if mod_unique_id is loaded, its long unique id could
be used.
Cheers,
Stefan
Re: Enhanced error log format for trunk?
Posted by Rainer Jung <ra...@kippdata.de>.
On 01.06.2010 14:56, Rainer Jung wrote:
> I repeatedly inserted millisecond or microsecond timestamps as well as
> PID and thread ID information into the ErrorLog when trying to diagnose
> problems, most often in combination with additional log lines.
>
> Due to the increased load and capability of systems and increasing
> amount of concurrency, would those features be interesting by default?
>
> 1) Sub-second timestamps in error log
Committed as r952203.
> 2) PID and thread ID
> PID and thread id are useful, because the can be correlated with the
> access_log (when added there). they also help to understand, which
> messages belong "together" when multiple log events are intertwined.
Committed as r952201.
> 3) Related things for access log
>
> There's a related open Bugzilla about adding sub-second timestamps (not:
> duration) to the access log (BZ 49251). The OP suggests to use %M for an
> absolute timestamp. It would be nice to improve the strftime use of
> %{format}t to allow for a proprietary microsecond letter which will add
> the microsecond part of the actual time. I found no standards defined
> for that.
Any comments on my patch at:
http://people.apache.org/~rjung/patches/httpd-trunk-adding-milliseconds-and-microseconds-to-the-access-log.patch
It extends the patterns used by %{...}t. More detailed explanations at
the beginning of the patch.
Rainer