Bug 54044 - AccessLogValve using stale date/time with SimpleDateFormat
Summary: AccessLogValve using stale date/time with SimpleDateFormat
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 7
Classification: Unclassified
Component: Catalina (show other bugs)
Version: 7.0.30
Hardware: Sun Solaris
: P2 normal (vote)
Target Milestone: ---
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2012-10-23 15:38 UTC by Casey Lucas
Modified: 2013-04-27 13:29 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Casey Lucas 2012-10-23 15:38:56 UTC
We are noticing old/stale date/times in out access logs. I copied (and scrubbed) the entries below from an access log from 2012-10-22.

...,2012-10-15 18:00:56.705-0500,"GET ...
...,2012-10-22 10:29:01.801-0500,"GET ...
...,2012-10-22 10:29:01.802-0500,"GET ...
...,2012-10-22 10:29:01.803-0500,"GET ...
...,2012-10-22 10:29:01.804-0500,"GET ...
...,2012-10-15 18:00:56.804-0500,"GET ...
...,2012-10-15 18:00:56.857-0500,"GET ...

We use using the SimpleDateFormat functionality and the beginTime prefix.  Our "pattern" is:

%{X-Tomcat-Session}i,%S,%{X-Forwarded-For}i,%h,%u,%{begin:yyyy-MM-dd HH:mm:ss.SSSZ}t,"%r",%s,%b,%p,%{Referer}i,"%{User-Agent}i",%T"

In the example above, jvm/tomcat instance was started on 2012-10-15 at 18:00:41 (a few seconds before the stuck time in the access log) so the  2012-10-15 18:00:56 times are likely related to some caching issues/problems.  We also occasionally see other log entries with incorrect (but not startup) dates/times.  For, example, we sometimes see yesterday's date in the access log.

Also, note that the millisecond times do appear to be correct in that they increase in a reasonable way and are unrelated to the date and second-truncated time.
Comment 1 Rainer Jung 2012-10-23 21:24:44 UTC
Note that begin times can be old if your request take a long time to finish.

Can you please add %D to your pattern, which will output the request duration in milliseconds. This is to check, whether the old time stamps belong to requests that took very long in processing.

I suggest:

%{X-Tomcat-Session}i,%S,%{X-Forwarded-For}i,%h,%u,%{begin:yyyy-MM-dd HH:mm:ss.SSSZ}t,"%r",%s,%b,%p,%{Referer}i,"%{User-Agent}i",%T,%{begin},%{end},%{end:yyyy-MM-dd HH:mm:ss.SSSZ}t,%D"

during this debugging so you can check the consistency of begin time, end time and duration as well as consistency with the CLF formatted begin and end time stamps which are formatted by a slightly different format cache.
Comment 2 Casey Lucas 2012-10-23 21:46:58 UTC
I restarted earlier today with an updated pattern trying to get some more useful information.  The format was not the one you recommended (since it was before your request) but I added:

%I - thread - in case the problem is thread related
%t
%{sec}t

For a final pattern of:

%{X-Tomcat-Session}i,%S,%{X-Forwarded-For}i,%h,%u,%I,%t,%{sec}t,%{begin:yyyy-MM-dd HH:mm:ss.SSSZ}t,"%r",%s,%b,%p,%{Referer}i,"%{User-Agent}i",%T

The actual time of capture was 23/Oct/2012:14:49:59. I left on the %T data which is small.  These were not long duration requests.  Note the 11:18:18 entries. 11:18:18 is a few seconds after the jvm was started. I thought this might be relavent because of the child/parent caching logic in AccessLogValve.

 ... ,tomcat-exec-20,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 14:49:59.341-0500,"GET ... ,0.000
 ... ,tomcat-exec-5,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 14:49:59.337-0500,"GET ... ,0.005
 ... ,tomcat-exec-18,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 14:49:58.833-0500,"GET ... ,0.590
 ... ,tomcat-exec-20,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 14:49:59.424-0500,"GET ... ,0.002
 ... ,tomcat-exec-5,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 14:49:59.424-0500,"GET ... ,0.009
 ... ,tomcat-exec-18,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.433-0500,"GET ... ,0.001
 ... ,tomcat-exec-20,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 14:49:59.431-0500,"GET ... ,0.008
 ... ,tomcat-exec-25,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.444-0500,"GET ... ,0.007
 ... ,tomcat-exec-25,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.545-0500,"GET ... ,0.007
 ... ,tomcat-exec-25,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.555-0500,"GET ... ,0.009
 ... ,tomcat-exec-25,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.645-0500,"GET ... ,0.004
 ... ,tomcat-exec-18,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.645-0500,"GET ... ,0.006
 ... ,tomcat-exec-25,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.654-0500,"GET ... ,0.001
 ... ,tomcat-exec-18,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.653-0500,"GET ... ,0.012
 ... ,tomcat-exec-25,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.665-0500,"GET ... ,0.012
 ... ,tomcat-exec-25,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.765-0500,"GET ... ,0.006
 ... ,tomcat-exec-25,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.855-0500,"GET ... ,0.006
 ... ,tomcat-exec-25,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.865-0500,"GET ... ,0.008
 ... ,tomcat-exec-25,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.885-0500,"GET ... ,0.012
 ... ,tomcat-exec-25,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.901-0500,"GET ... ,0.007
 ... ,tomcat-exec-25,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.911-0500,"GET ... ,0.010
 ... ,tomcat-exec-25,[23/Oct/2012:14:49:59 -0500],1351021799,2012-10-23 11:18:18.925-0500,"GET ... ,0.010
 ... ,tomcat-exec-25,[23/Oct/2012:14:50:00 -0500],1351021800,2012-10-23 11:18:18.976-0500,"GET ... ,0.082
 ... ,tomcat-exec-5,[23/Oct/2012:14:50:00 -0500],1351021800,2012-10-23 14:50:00.075-0500,"GET ... ,0.010
 ... ,tomcat-exec-5,[23/Oct/2012:14:50:00 -0500],1351021800,2012-10-23 14:50:00.146-0500,"GET ... ,0.011
 ... ,tomcat-exec-5,[23/Oct/2012:14:50:00 -0500],1351021800,2012-10-23 14:50:00.161-0500,"GET ... ,0.012

I can update the pattern to be the one you requested but it may take some time to see the issue crop up again. In the mean time the above data may be useful.
Comment 3 Casey Lucas 2012-10-24 19:09:58 UTC
I changed log format to the one requested (had to add a 't' to the after {begin} and {end}:

%{X-Tomcat-Session}i,%S,%{X-Forwarded-For}i,%h,%u,%{begin:yyyy-MM-dd HH:mm:ss.SSSZ}t,"%r",%s,%b,%p,%{Referer}i,"%{User-Agent}i",%T,%{begin}t,%{end}t,%{end:yyyy-MM-dd HH:mm:ss.SSSZ}t,%D

The stuck/incorrect times in the data below are 10:00:04 and 10:05:40.  The actual timespan was between 11:01:59 and 11:02:01. You can see that these are not long duration requests (all less than a second.)


... ,2012-10-24 11:01:59.288-0500,"GET ... ,0.080,[24/Oct/2012:11:01:59 -0500],[24/Oct/2012:11:01:59 -0500],2012-10-24 11:01:59.368-0500,80
... ,2012-10-24 11:01:59.568-0500,"GET ... ,0.006,[24/Oct/2012:11:01:59 -0500],[24/Oct/2012:11:01:59 -0500],2012-10-24 11:01:59.574-0500,6
... ,2012-10-24 11:01:59.755-0500,"POST ... ,0.246,[24/Oct/2012:11:01:59 -0500],[24/Oct/2012:11:02:00 -0500],2012-10-24 11:02:00.001-0500,246
... ,2012-10-24 10:05:40.932-0500,"GET ... ,0.088,[24/Oct/2012:10:05:40 -0500],[24/Oct/2012:10:00:04 -0500],2012-10-24 10:00:04.020-0500,88
... ,2012-10-24 10:00:04.020-0500,"GET ... ,0.002,[24/Oct/2012:10:00:04 -0500],[24/Oct/2012:10:00:04 -0500],2012-10-24 10:00:04.022-0500,2
... ,2012-10-24 11:01:59.753-0500,"GET ... ,0.313,[24/Oct/2012:11:01:59 -0500],[24/Oct/2012:10:00:04 -0500],2012-10-24 10:00:04.066-0500,313
... ,2012-10-24 10:00:04.072-0500,"GET ... ,0.001,[24/Oct/2012:10:00:04 -0500],[24/Oct/2012:10:00:04 -0500],2012-10-24 10:00:04.073-0500,1
... ,2012-10-24 10:05:40.813-0500,"POST ... ,0.427,[24/Oct/2012:10:05:40 -0500],[24/Oct/2012:10:00:04 -0500],2012-10-24 10:00:04.240-0500,427
... ,2012-10-24 10:00:04.227-0500,"GET ... ,0.079,[24/Oct/2012:10:00:04 -0500],[24/Oct/2012:10:00:04 -0500],2012-10-24 10:00:04.306-0500,79
... ,2012-10-24 11:02:00.370-0500,"GET ... ,0.013,[24/Oct/2012:11:02:00 -0500],[24/Oct/2012:11:02:00 -0500],2012-10-24 11:02:00.383-0500,13
... ,2012-10-24 11:02:00.398-0500,"GET ... ,0.001,[24/Oct/2012:11:02:00 -0500],[24/Oct/2012:11:02:00 -0500],2012-10-24 11:02:00.399-0500,1
... ,2012-10-24 11:02:00.684-0500,"GET ... ,0.011,[24/Oct/2012:11:02:00 -0500],[24/Oct/2012:11:02:00 -0500],2012-10-24 11:02:00.695-0500,11
... ,2012-10-24 10:00:04.379-0500,"GET ... ,0.369,[24/Oct/2012:10:00:04 -0500],[24/Oct/2012:10:00:04 -0500],2012-10-24 10:00:04.748-0500,369
... ,2012-10-24 10:00:04.363-0500,"GET ... ,0.387,[24/Oct/2012:10:00:04 -0500],[24/Oct/2012:10:00:04 -0500],2012-10-24 10:00:04.750-0500,387
... ,2012-10-24 10:00:04.922-0500,"GET ... ,0.003,[24/Oct/2012:10:00:04 -0500],[24/Oct/2012:10:00:04 -0500],2012-10-24 10:00:04.925-0500,3
... ,2012-10-24 10:00:04.972-0500,"GET ... ,0.001,[24/Oct/2012:10:00:04 -0500],[24/Oct/2012:10:00:04 -0500],2012-10-24 10:00:04.973-0500,1
... ,2012-10-24 11:02:01.089-0500,"GET ... ,0.001,[24/Oct/2012:11:02:01 -0500],[24/Oct/2012:11:02:01 -0500],2012-10-24 11:02:01.090-0500,1
... ,2012-10-24 11:02:01.088-0500,"GET ... ,0.008,[24/Oct/2012:11:02:01 -0500],[24/Oct/2012:11:02:01 -0500],2012-10-24 11:02:01.096-0500,8
Comment 4 Mark Thomas 2012-10-26 14:58:21 UTC
Thanks for the detailed report. A code review suggests that AccessLogValve.DateFormatCache has some issues (e.g. offset is never set).

I have started work on a unit test and that appears to have uncovered more issues but I need to check my unit test is correct. I am currently double-checking the unit test and will commit and along with any necessary fixes once that process is complete.
Comment 5 Mark Thomas 2012-10-26 18:17:23 UTC
Found a couple of bugs that have been fixed in trunk and 7.0.x. The fix will be in 7.0.33 onwards.
Comment 6 Konstantin Kolinko 2012-10-26 18:33:02 UTC
Re: r1402604

There is a copy of DateFormatCache class in JULI:
org.apache.juli.DateFormatCache

From a quick look at it, it also needs the same fix. I have not run the test against it though.

(The original plan was to keep just one copy of this class,
as was shortly discussed on dev@ on 2011-06-23,
http://tomcat.markmail.org/thread/iucbedl7pnszytc6
)
Comment 7 Mark Thomas 2012-10-26 19:28:51 UTC
Fixed. I haven't removed the copy since they are not identical.
Comment 8 Konstantin Kolinko 2012-11-12 21:15:27 UTC
This issue affects the cache used by org.apache.juli.OneLineFormatter in Tomcat 6.

The AccessLogValve is not affected (it does not have such cache there).
Other JULI components are not affected.

I proposed the patch (r1408459) for Tomcat 6.
Comment 9 Konstantin Kolinko 2013-04-27 13:29:45 UTC
Fixed in Tomcat 6 by r1476547 , will be in 6.0.37.