We have occasional failed requests on our servers running tomcat 5.0.19 (working
under java 1.5.0 with system assertions enabled via -esa option). This also
seams to be an issue with newer versions of tomcat up to the current snapshot
taken from the CVS repository.
The following exception gets thrown:
java.lang.AssertionError: cache control: inconsictency, cachedFixedDate=732122,
computed=732107, date=2005-06-10T00:00:00.000Z
at java.util.GregorianCalendar.computeFields(GregorianCalendar.java:2050)
at java.util.GregorianCalendar.computeFields(GregorianCalendar.java:1971)
at java.util.Calendar.setTimeInMillis(Calendar.java:1066)
at java.util.Calendar.setTime(Calendar.java:1032)
at java.text.SimpleDateFormat.format(SimpleDateFormat.java:785)
at java.text.SimpleDateFormat.format(SimpleDateFormat.java:778)
at java.text.DateFormat.format(DateFormat.java:314)
at
org.apache.tomcat.util.http.FastHttpDateFormat.getCurrentDate(FastHttpDateFormat.java:152)
at
org.apache.coyote.http11.Http11Processor.prepareResponse(Http11Processor.java:1529)
at org.apache.coyote.http11.Http11Processor.action(Http11Processor.java:926)
at org.apache.coyote.Response.action(Response.java:224)
at
org.apache.coyote.http11.InternalOutputBuffer.doWrite(InternalOutputBuffer.java:605)
at org.apache.coyote.Response.doWrite(Response.java:586)
at
org.apache.coyote.tomcat5.OutputBuffer.realWriteBytes(OutputBuffer.java:411)
at org.apache.tomcat.util.buf.ByteChunk.flushBuffer(ByteChunk.java:436)
at org.apache.tomcat.util.buf.ByteChunk.append(ByteChunk.java:356)
at org.apache.coyote.tomcat5.OutputBuffer.writeBytes(OutputBuffer.java:444)
at org.apache.coyote.tomcat5.OutputBuffer.write(OutputBuffer.java:431)
at
org.apache.coyote.tomcat5.CoyoteOutputStream.write(CoyoteOutputStream.java:108)
at
org.apache.coyote.tomcat5.CoyoteOutputStream.write(CoyoteOutputStream.java:102)
at com.scene7.is.ImageServlet.sendResponse(ImageServlet.java:197)
at com.scene7.is.ImageServlet.doGet(ImageServlet.java:147)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:743)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:856)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:284)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:204)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:257)
at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:151)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:567)
at
org.apache.catalina.core.StandardContextValve.invokeInternal(StandardContextValve.java:245)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:199)
at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:151)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:567)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:184)
at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:151)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:164)
at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:149)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:567)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:156)
at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:151)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:578)
at
org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:149)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:567)
at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:972)
at org.apache.coyote.tomcat5.CoyoteAdapter.service(CoyoteAdapter.java:206)
at
org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:833)
at
org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:732)
at
org.apache.tomcat.util.net.TcpWorkerThread.runIt(PoolTcpEndpoint.java:619)
at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:688)
at java.lang.Thread.run(Thread.java:595)
Analysing stack traces and error messages suggests that the reason is internal
data corruption in java.uti.GregorianCalendar class caused by accessing it
simultaneously from multiple threads.
The problem is that org.apache.tomcat.util.http.FastHttpDateFormat that is used
for date conversion appears not to be entirely thread safe.
This class uses shared instance of java.util.SimpleDateFormat:
protected static final SimpleDateFormat format =
new SimpleDateFormat("EEE, dd MMM yyyy HH:mm:ss zzz", Locale.US);
and there are two methods that use this instance:
public static final String getCurrentDate()
and
public static final String formatDate
(long value, DateFormat threadLocalformat)
As SympleDateFormat class is documented to be not thread safe both methods
synchronize access to it. However the synchronization is done against two
different locks, so in case of overlapped calls of these two methods from
different threads there is still possibility for data corruption.
The exposure ot this is very narrow because getCurrentDate meghod actually uses
format instance only ones per second at best, however the following test case is
balse to reproduce this providing it is ran with JRE 1.5.0 with system
assertions enabled (-esa switch)
package org.apache.tomcat.util.http;
import java.util.Date;
import java.util.Random;
public class FastHttpDateFormatTest {
public static void main(String[] args) throws InterruptedException {
Thread t1 = new Thread("getCurrentDate() invoker") {
public void run() {
while (true) {
try {
FastHttpDateFormat.getCurrentDate();
} catch (Throwable e) {
reportError(e);
}
}
}
};
Thread t2 = new Thread("formatDate() invoker") {
private Random random = new Random();
public void run() {
while (true) {
try {
FastHttpDateFormat.formatDate(random.nextLong(), null);
} catch (Throwable e) {
reportError(e);
}
}
}
};
t1.start();
t2.start();
}
private synchronized static void reportError(Throwable e) {
System.out.println(new Date() + " [" + Thread.currentThread().getName()
+ "]: " + e.getMessage());
System.out.println(e.getMessage());
e.printStackTrace();
}
}
This problem seams to be easily fixable by putting additional synchronization
around access to format instance in FastHttpDateFormat.formatDate(...) method.
Here are the diffs:
$ diff -u
~/lib/versions/jakarta-tomcat-5.0.19-src/jakarta-tomcat-connectors/util/java/org/apache/tomcat/util/http/FastHttpDateFormat.java
org/apache/tomcat/util/http/FastHttpDateFormat.java
---
/home/akrainiouk/lib/versions/jakarta-tomcat-5.0.19-src/jakarta-tomcat-connectors/util/java/org/apache/tomcat/util/http/FastHttpDateFormat.java
2004-02-14 02:27:02.000000000 -0800
+++ org/apache/tomcat/util/http/FastHttpDateFormat.java 2005-08-12
14:22:05.000000000 -0700
@@ -182,7 +182,9 @@
}
} else {
synchronized (formatCache) {
- newDate = format.format(dateValue);
+ synchronized (format) {
+ newDate = format.format(dateValue);
+ }
updateCache(formatCache, longValue, newDate);
}
}

This is ASF Bugzilla: the Apache Software Foundation bug system. In case
of problems with the functioning of ASF Bugzilla, please contact
bugzilla-admin@apache.org.
Please Note: this e-mail address is only for reporting problems
with ASF Bugzilla. Mail about any other subject will be silently
ignored.