[
https://issues.apache.org/jira/browse/HTTPCORE-170?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12633731#action_12633731
]
Oleg Kalnichevski commented on HTTPCORE-170:
--------------------------------------------
Asankha
What I see as a problem is that there was another #RequestReceived event fired
on the same connection while the protocol handler was still busy streaming out
the response body for the previous one. As far I know Synapse is not able (and
is not supposed) to pipeline requests. Therefore input events should remain
suspended while the response body is being streamed out. I suspect something
went wrong in the protocol handling code that resulted in input enabled
prematurely.
Does this help in any way?
Oleg
> Race condition in SharedOutputBuffer may cause a connection to hang.
> --------------------------------------------------------------------
>
> Key: HTTPCORE-170
> URL: https://issues.apache.org/jira/browse/HTTPCORE-170
> Project: HttpComponents HttpCore
> Issue Type: Bug
> Components: HttpCore NIO
> Affects Versions: 4.0-beta2
> Environment: Synapse 1.2
> Reporter: Jason Walton
> Fix For: 4.0-beta3
>
>
> I found this problem while tracking down a problem in Synapse 1.2's nhttp
> transport. Occasionally under heavy load, Synapse would dump out this
> exception:
> <log4j:event logger="org.apache.synapse.transport.nhttp.ServerHandler"
> timestamp="1219446649613" level="ERROR" thread="HttpServerWorker-27">
> <log4j:message><![CDATA[Unexpected HTTP protocol error : Response already
> submitted]]></log4j:message>
> <log4j:throwable><![CDATA[org.apache.http.HttpException: Response already
> submitted
> at
> org.apache.http.impl.nio.DefaultNHttpServerConnection.submitResponse(DefaultNHttpServerConnection.java:202)
> at
> org.apache.synapse.transport.nhttp.ServerHandler.commitResponse(ServerHandler.java:212)
> at
> org.apache.synapse.transport.nhttp.ServerWorker.run(ServerWorker.java:208)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
> at java.lang.Thread.run(Thread.java:619)
> ]]></log4j:throwable>
> </log4j:event>
> I added a bunch of "System.out.println"s to Synapse and to httpcore (printlns
> because httpcore doesn't appear to use any logging libraries). Here's an
> example of a connection which has failed (the "33211218" is how I'm
> correlating data on a per-connection basis, and is the return value of
> DefaultNHttpServerConnection.hashCode()):
>
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.consumeInput()
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> ServerHandler.requestReceived()
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.consumeInput() - contentDecoder complete
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.resetInput
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> ServerHandler.commitResponse()
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.submitResponse()
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.produceOutput()
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218: ServerHandler.outputReady()
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218: ServerHandler.outputReady():
> Wrote 0 and encoder complete: true
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.resetOutput()
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.produceOutput()
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.produceOutput() closing session2
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.consumeInput()
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> ServerHandler.requestReceived()
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.consumeInput() - contentDecoder complete
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.resetInput()
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> ServerHandler.commitResponse()
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.submitResponse()
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.produceOutput()
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218: ServerHandler.outputReady()
> Wed Aug 27 12:32:31 EDT 2008: jwalton: 33211218: ServerHandler.outputReady():
> Wrote 0 and encoder complete: false
> Wed Aug 27 12:37:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.consumeInput()
> Wed Aug 27 12:37:31 EDT 2008: jwalton: 33211218:
> ServerHandler.requestReceived()
> Wed Aug 27 12:37:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.consumeInput() - contentDecoder complete
> Wed Aug 27 12:37:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.resetInput()
> Wed Aug 27 12:37:31 EDT 2008: jwalton: 33211218:
> ServerHandler.commitResponse()
> Wed Aug 27 12:37:31 EDT 2008: jwalton: 33211218:
> DefaultNHttpServerConnection.submitResponse()
> Wed Aug 27 12:37:31 EDT 2008: jwalton: 33211218: RESPONSE ALREADY SUBMITTED!
> Wed Aug 27 12:37:31 EDT 2008: jwalton: 33211218:
> ServerHandler.commitResponse(): HttpException: org.apache.http.HttpException:
> Response already submitted
> As you can see, the failure occurs at the last entry with the timestamp
> 12:32:31, where the ServerHandler tries to write the reply, but for some
> reason encoder.isComplete() returns false. Another request comes in on the
> still-waiting-to-write-a-reply ServerHandler a full five minutes later, and
> we get our exception.
> The problem appears to be in SharedOutputBuffer.
> SharedOutputBuffer.produceContent() is called from the [I/O Dispatcher]
> thread, and says:
> synchronized(this.mutex) {
> ...
> if (!this.endOfStream) {
> // suspend output events
> this.ioctrl.suspendOutput();
> }
> ...
> }
> So, essentially, "If we've run out of stuff to write to the encoder, but
> we're expecting more (!this.endOfStream), then tell the IOReactor to stop
> sending us output events for now, because we don't have any data to write
> anyways." Note that this is protected by a mutex.
>
>
> SharedOutputBuffer.writeCompleted() is called from the [HttpServerWorker]
> thread says:
> public void writeCompleted() throws IOException {
> if (this.endOfStream) {
> return;
> }
> this.endOfStream = true;
> this.ioctrl.requestOutput();
> }
> So, if this were called immediately after the producedContent() call, this
> would set endOfStream to true, and start up the output events again. The
> next call into produceContent() would end up calling encoder.complete(), and
> all would be well in the world.
>
> The problem here is that writeCompleted() is not protected by a mutex. This
> means that the "if(!this.endOfStream)" line in produceContent() could be
> executed by the I/O Dispatcher, followed immediately by writeCompleted() by
> the HttpServerWorker, followed by "this.ioctrl.suspendOutput()" in the I/O
> Dispatcher again. This would set us up in a state where endOfStream is true,
> so we're ready to finish writing data to the encoder, however we have
> suspended output events, so we will never get that opportunity.
> Fix is:
> public void writeCompleted() throws IOException {
> + synchronized(this.mutex) {
> if (this.endOfStream) {
> return;
> }
> this.endOfStream = true;
> this.ioctrl.requestOutput();
> + }
> }
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
---------------------------------------------------------------------
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]
