Bug 63286 - Inconsistencies between AccessLogValve and mod_log_config
Summary: Inconsistencies between AccessLogValve and mod_log_config
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 8
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 8.5.39
Hardware: All All
: P2 enhancement (vote)
Target Milestone: ----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-03-25 11:52 UTC by Michael Osipov
Modified: 2020-03-05 08:25 UTC (History)
1 user (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Michael Osipov 2019-03-25 11:52:21 UTC
I am trying to achieve consistent log formats between HTTPd and Tomcat. Unfortunately, there are subtle differences between conversion patterns.

In Tomcat I have "%h %u %{yyyy-MM-dd'T'HH:mm:ss.SSS}t "%r" %s %b %T"
In HTTPd I have "%h %u %{%FT%T}t.%{msec_frac}t \"%r\" %>s %b %{ms}T"

now the inconsistencies:
%D: In Tomcat it is millisecond resolution, HTTPd microsecond resolution
%T: both in second resolution, but Tomcat used floating point while HTTPd uses integers

%{UNIT}T does not exist on Tomcat at all. Granted.

This all feels weird probably for most having different semantics for the same pattern. I think this needs to be aligned, or at least documented!
Comment 1 Mark Thomas 2019-03-29 12:42:15 UTC
Also see bug 56966. I don't recall why that stalled. It may have been related to the API changes required. Probably time to take another look.
Comment 2 Michael Osipov 2019-03-29 12:46:56 UTC
(In reply to Mark Thomas from comment #1)
> Also see bug 56966. I don't recall why that stalled. It may have been
> related to the API changes required. Probably time to take another look.

It looks related, but the issue you mention is about resolution, this one's different. Three years have passed since the ticket has been touched.
Comment 3 Mark Thomas 2019-03-29 21:48:58 UTC
We can't change the behaviour in the middle of the 9.0.x series. The risk of braking things for users is too great. I've added it to the TODO list for 10.0.x.

Meanwhile, we can clearly document the current behaviour and note the differences with httpd. Working on that now...
Comment 4 Michael Osipov 2019-03-30 00:34:34 UTC
That's fine by me. Though, %{UNIT}T can be introduced in 8.5 and 9, can't it?
Comment 5 Mark Thomas 2019-04-01 11:23:35 UTC
The documentation has been fixed in:
- master for 9.0.18 onwards
- 8.5.x for 8.5.40 onwards
- 7.0.x for 7.0.94 onwards

Moving this to enhancement request to add support for %{UNIT}T
Comment 6 Rainer Jung 2019-04-01 11:45:38 UTC
There's another difference between httpd and Tomcat access logs that people often stumble upon: By default the request timestamp for httpd is the time of the beginning of the request, for Tomcat it is the end of the requst (or more precisely the moment of peparing the access log line).

Since httpd 2.4 and TC 7 (?) one can choose between begin and end with a documented pattern, but the defaults still differ.

The delta makes it harder to align the logs in case of long running requests.

One consequence is, that the timestamp in Tomcat access logs always increase monotonically, but not so in httpd access log. Later but faster requests might get logged before earlier but slower requests.

Should we document this as well?

Regards,

Rainer
Comment 7 Remy Maucherat 2020-02-28 12:25:44 UTC
This should be fixed in 10.0.0-M2.
Comment 8 Michael Osipov 2020-02-28 16:57:34 UTC
(In reply to Remy Maucherat from comment #7)
> This should be fixed in 10.0.0-M2.

I fail to find this commit in https://github.com/apache/tomcat/commits/master/java/org/apache/catalina/valves/AccessLogValve.java and https://github.com/apache/tomcat/commits/master/java/org/apache/catalina/valves/AbstractAccessLogValve.java. Where is it?
Comment 9 Remy Maucherat 2020-02-28 19:42:01 UTC
AccessLogValve was not doing anything related. The argument that used milliseconds was in AbstractALV, now it uses nanoseconds.
Comment 10 Michael Osipov 2020-02-28 20:59:14 UTC
Let me recheck this. I hope docs have been updated too.
Comment 11 Michael Osipov 2020-03-05 08:25:28 UTC
(In reply to Remy Maucherat from comment #9)
> AccessLogValve was not doing anything related. The argument that used
> milliseconds was in AbstractALV, now it uses nanoseconds.

Rémy, I have updated documentation to reflect your changes.