Bug 36173

Summary: AssertionFailure in java.util.GregorianCalendar.computeFields() when sending response
Product: Tomcat 5 Reporter: Alexei <akrainiouk>
Component: Connector:HTTPAssignee: Tomcat Developers Mailing List <dev>
Status: RESOLVED FIXED    
Severity: normal    
Priority: P2    
Version: 5.5.9   
Target Milestone: ---   
Hardware: All   
OS: All   

Description Alexei 2005-08-12 23:40:33 UTC
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);
             }
         }
Comment 1 Remy Maucherat 2005-08-16 18:53:25 UTC
This sounds reasonable.