You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@hc.apache.org by "Oleg Kalnichevski (JIRA)" <ji...@apache.org> on 2008/08/28 11:21:44 UTC
[jira] Updated: (HTTPCORE-170) Race condition in SharedOutputBuffer
may cause a connection to hang.
[ https://issues.apache.org/jira/browse/HTTPCORE-170?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Oleg Kalnichevski updated HTTPCORE-170:
---------------------------------------
Fix Version/s: 4.0-beta3
Jason,
Thank you for the detailed analysis of the problem and the fix. I'll commit the patch today or tomorrow the latest, if no one beats me to it
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: dev-unsubscribe@hc.apache.org
For additional commands, e-mail: dev-help@hc.apache.org