[jetty-dev] [jira] (JETTY-1346) java.lang.IllegalStateException: STATE!=START

    [ https://jira.codehaus.org/browse/JETTY-1346?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=293426#comment-293426 ] 

kytv commented on JETTY-1346:
-----------------------------

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]={HTTP/1.1 200 OK\0d\0a}
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.
                
> java.lang.IllegalStateException: STATE!=START
> ---------------------------------------------
>
>                 Key: JETTY-1346
>                 URL: https://jira.codehaus.org/browse/JETTY-1346
>             Project: Jetty
>          Issue Type: Bug
>          Components: HTTP
>    Affects Versions: 6.1.21, 6.1.26, 7.3.1
>         Environment: Ubuntu 10.04.2 x86_64
>            Reporter: Vidar S. Ramdal
>            Assignee: Greg Wilkins
>
> We're seing a number of these stacktraces in our logs, seen with Jetty
> 6.1.21, 6.1.26 and 7.3.1v20110307:
> HTTP/1.1 21.02.2011 14:59:04.892 *WARN* [446583619@qtp-904935057-66]
> org.apache.felix.http.jetty handle failed
> (java.lang.IllegalStateException: STATE!=START)
> java.lang.IllegalStateException: STATE!=START
>        at
> org.mortbay.jetty.AbstractGenerator.setVersion(AbstractGenerator.java:319)
>        at
> org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:859)
>        at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:539)
>        at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:212)
>        at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:405)
>        at
> org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
>        at
> org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)
> This is the full stacktrace, as you can see, the only code involved
> here is Jetty code.
> This happens on about 1% of the requests, and causes the request to
> fail with a 503.
> We're only seeing this in production, and the problem seems to occur
> completely randomly, so we haven't ben able to debug the problem
> properly.
> But we have added some debug output, and found that when this
> situation occurs, o.m.j.AbstractGenerator._state is not properly reset
> from the previous request on the same connection. This causes the if
> (_state != STATE_HEADER) test in setVersion to return false, thus
> throwing the IllegalStateException.
> The previous request, however, has been returned correctly with a 200 OK.
> This LOOKS as though it could be related to JETTY-743, but that one has been closed as "Not a bug".

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://jira.codehaus.org/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email