java.lang.IllegalStateException: STATE!=START

Do you have any information about the requests that proceed this error? are they POSTs with content? normal GETs? Do you have the headers for them?

Thanks for looking into this.

There did not seem to be any pattern. The requests involved (the request getting the error, and the preceding request on the same connection) could be any combination of GETs and POSTs, with apparently any combination of headers. I'll look for the old logs, and post them here if I can find them.

We eventually worked around the problem by returning a Connection: Close header (which did not have much of a performance impact, as we have a Varnish cache server in front of Jetty).

Any extra information on this? are you still seeing it?

We really can't do much with this much information as we cannot reproduce.

I'm sorry I don't have any more information at this point. As mentioned, the problem only existed in production, and since we found a workaround (Connection: Close) we have been reluctant to revert to a situation where requests fail.

Correct me if I'm wrong, but it seems the IllegalStateException being thrown indicates a bug in Jetty somewhere, but we have been unable to reproduce it in a debuggable environment.

Hopefully this JIRA issue can be found by others seeing the same symptoms. I'll reopen this issue if we should encounter the error again.

We can reproduce this consistently on Jetty 6.1.24 and 6.1.26, and can confirm that calling response.setHeader("Connection", "Close") hides the problem, but perhaps does not fix it. The problem happens when using Firefox or Chrome, whether or not HTTP/1.1 pipelining is enabled. The root cause appears to be failing to close an output stream on our side.

The server setup is a page with multiple (5 or more) graph images on it. The graphs are generated on-the-fly by a jsp that calls jrobin (a Java stats and graphing library). Generation of each graph can take a while.

In addition, to limit memory usage, graph generation is protected by a java.util.concurrent.Semaphore: Semaphore s = new Semaphore(3, true). This limits simultaneous graph generation to 3, and additional requests will be blocked in the jsp until others have completed.

With Connection: Close, the problem becomes an NPE only visible at WARN log level (and traceback only visible with DEBUG):

WARN [Finalizer ] org.mortbay.jetty.Server : header full: java.lang.NullPointerException
DEBUG [Finalizer ] org.mortbay.jetty.Server : [1678177258,74955508,m=-1,g=0,p=17,c=4096]=

java.lang.NullPointerException
at org.mortbay.jetty.HttpFields$2.hasNext(HttpFields.java:269)
at org.mortbay.jetty.HttpGenerator.completeHeader(HttpGenerator.java:398)
at org.mortbay.jetty.HttpConnection.commitResponse(HttpConnection.java:632)
at org.mortbay.jetty.HttpConnection$Output.flush(HttpConnection.java:1011)
at javax.imageio.stream.MemoryCacheImageOutputStream.flushBefore(MemoryCacheImageOutputStream.java:194)
at javax.imageio.stream.MemoryCacheImageOutputStream.close(MemoryCacheImageOutputStream.java:180)
at javax.imageio.stream.ImageInputStreamImpl.finalize(ImageInputStreamImpl.java:874)
at java.lang.ref.Finalizer.invokeFinalizeMethod(Native Method)
at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:101)
at java.lang.ref.Finalizer.access$100(Finalizer.java:32)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:178)

But this was happening in the Finalizer thread... so obviously we weren't closing our
ImageOutputStream properly... so when we fixed that, the NPE went away.
All we were left with were occasional:

DEBUG [Jetty] org.mortbay.jetty.Server : EOF
org.mortbay.jetty.EofException
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:319)
at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:212)
at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:410)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:679)

So perhaps it is the delays caused by the long image generation time, the Semaphore, the imageio finalizer, or some combination that is triggering the problem. Hopefully this will help others.