tomcat-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Rainer Jung <>
Subject Re: Objections about formatting options to time stamp in access log
Date Mon, 08 Nov 2010 21:04:32 GMT
On 08.11.2010 21:25, Konstantin Kolinko wrote:
> 2010/11/8 Rainer Jung<>:
>> A typical annoyance when combining Apache web server and Tomcat is the
>> difference in access log timestamp. Apache logs the beginning of the
>> request, Tomcat logs the end of the request.
> According to the HTTPD docs [2], this changed between HTTPD 1.3 and 2.
> 1.3 logs the time when the request processing finished, 2+ logs when it started.
> [2]

OK, but 1.3 isn't really relevant any longer ...

>> I added a feature to Apache trunk (will become 2.4) to make it configurable
>> for Apache, which time stamp to choose ([1]). Furthermore the Apache web
>> server allows to choose the format, in which the time stamp is being logged
>> as something different than just "Common Log Format". This is all configured
>> by an appropriate "format" in %{format}t.
>> Any a priori objections about porting the same functionality to Tomcat
>> trunk?
> I thought about it already. I would like this feature.
> My current idea with implementation is that the timestamp when request
> processing started can be placed in a field in the request. Such
> solution will be compatible with the recently added AccessLog
> interface.

Since any single invocation of addElement() only needs either begin or 
end time, I was thinking about deciding which timestamp to pass when 
calling addElement(). But it might be a bit faster and more generic to 
add the timestamp to the request and let the AccessLogElement retrieve 
it from there.

> There might be a caveat with caching of formatted timestamp strings in
> the access log valve implementations.

Yes, but the momentary implementation isn't that nice, e.g. if you want 
correct sub second resolution. I'm experimenting with something similar 
to httpd, namely using a cyclic buffer of N formatted timestamps 
(seconds granularity). That buffer could be thread local (like the 
currentDateStruct right now). If a new timestamp is not contained in the 
buffer, it could call out to a synchronized global buffer which then 
does the actual formatting. That way there will not be to much locking 
(only if a thread sees a second not in its local cache) and the 
formatting is mostly only done once for each second.

> What happens with async requests?

Good question, I need to see, what the momentary behaviour of the access 
log is with respect to the async lifecycle.

>> Of course due to latency between Apache and Tomcat and due to different
>> timeouts, even when using the same time stamp (begin or end of request) in
>> both products, the timestamps will not always match exactly. But at the
>> moment matching the entries is much harder, than it could be.
> If one needs to match them it would be better to do so by certain id,
> not by a timestamp.
> Something like %{forensic-id}n  [3]
> [3]

Yes! There is mod_unique_id, which generates unique IDs also for 
mod_log_forensic. One can set those as additional request headers and 
that way pass them to Tomcat and log there. I was thinking about a 
simple filter, that

- looks for an incoming ID by checking a configured header

- if the header is not set generates an own ID basically using an atomic

- Checks the presence of a few well known log frameworks and sets the ID 
as a mapped diagnostic context (log4j terminology) or similar so that 
you can configure your webapp logging and in case of log4j also Tomcat 
logging to include the unique ID on each log line.

- optionally reflects the ID by setting a response header, which allows 
to log it on the proxy and also to check its correctness on the proxy.

But first the access log ...



To unsubscribe, e-mail:
For additional commands, e-mail:

View raw message