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
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]
