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 sounds reasonable.