You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@hc.apache.org by "Jason Walton (JIRA)" <ji...@apache.org> on 2008/08/27 22:05:44 UTC
[jira] Created: (HTTPCORE-170) Race condition in SharedOutputBuffer
may cause a connection to hang.
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: dev-unsubscribe@hc.apache.org
For additional commands, e-mail: dev-help@hc.apache.org
[jira] Commented: (HTTPCORE-170) Race condition in
SharedOutputBuffer may cause a connection to hang.
Posted by "Jason Walton (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HTTPCORE-170?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12633764#action_12633764 ]
Jason Walton commented on HTTPCORE-170:
---------------------------------------
I didn't see the problem you described, Asankha. I'm driving traffic with SoapUI through a single Synapse, though, so it's possible that SoapUI is "well behaved", and not sending a second request before reading the entire reply for the first request?
I'd agree with Oleg's analysis, though; it sounds like this is just the reverse of SYNAPSE-341.
> 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
[jira] Updated: (HTTPCORE-170) Race condition in SharedOutputBuffer
may cause a connection to hang.
Posted by "Oleg Kalnichevski (JIRA)" <ji...@apache.org>.
[ 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
[jira] Commented: (HTTPCORE-170) Race condition in
SharedOutputBuffer may cause a connection to hang.
Posted by "Oleg Kalnichevski (JIRA)" <ji...@apache.org>.
[ 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: dev-unsubscribe@hc.apache.org
For additional commands, e-mail: dev-help@hc.apache.org
[jira] Commented: (HTTPCORE-170) Race condition in
SharedOutputBuffer may cause a connection to hang.
Posted by "Asankha C. Perera (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HTTPCORE-170?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12633717#action_12633717 ]
Asankha C. Perera commented on HTTPCORE-170:
--------------------------------------------
Jason / Oleg
I tried the latest from the HttpComponenets trunk with Synapse 1.2+some changes, but I am still seeing this issue. According to some debug information I generated, here is what I see for this:
Connected : [/127.0.0.1:24568]
RequestReceived : [/127.0.0.1:24568]
InputReady : [localhost/127.0.0.1:24568]
InputReady : [localhost/127.0.0.1:24568]
...
InputReady : [localhost/127.0.0.1:24568]
InputReady : [localhost/127.0.0.1:24568]
InputReady - and completed : [localhost/127.0.0.1:24568]
CommitResponse : [localhost/127.0.0.1:24568]
submitResponse for : [localhost/127.0.0.1:24568] request fully read : true
OutputReady : [localhost/127.0.0.1:24568]
RequestReceived : [localhost/127.0.0.1:24568]
InputReady : [localhost/127.0.0.1:24568]
OutputReady : [localhost/127.0.0.1:24568]
InputReady : [localhost/127.0.0.1:24568]
InputReady : [localhost/127.0.0.1:24568]
...
InputReady : [localhost/127.0.0.1:24568]
InputReady : [localhost/127.0.0.1:24568]
CommitResponse : [localhost/127.0.0.1:24568]
submitResponse for : [localhost/127.0.0.1:24568] request fully read : false
Problematic connection : [localhost/127.0.0.1:24568] request fully read : false
The problem seems to be that we started reading the second request over the same [keep-alive] connection, before we finished writing the output of the first one. This somehow resulted in the second submitResponse, before the first finished.
Jason, did you try with the latest HttpComponenets snapshot, and do you see this issue as fixed somehow after your suggested fix? I am load testing with the 500K request and 100 iterations at 10 users of concurrency, and I see this off and on for about 5 or 6 of the connections
thanks
asankha
> 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
[jira] Resolved: (HTTPCORE-170) Race condition in
SharedOutputBuffer may cause a connection to hang.
Posted by "Oleg Kalnichevski (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HTTPCORE-170?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Oleg Kalnichevski resolved HTTPCORE-170.
----------------------------------------
Resolution: Fixed
Patch checked in. Many thanks, Jason
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
[jira] Commented: (HTTPCORE-170) Race condition in
SharedOutputBuffer may cause a connection to hang.
Posted by "Asankha C. Perera (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HTTPCORE-170?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12633738#action_12633738 ]
Asankha C. Perera commented on HTTPCORE-170:
--------------------------------------------
Hi Oleg
Yes, this seems to be the problem.. and I suspect the bug to be on the Synapse side.. I will take a fresh look tomorrow to figure out what went wrong and how we should fix this.. at the same time was curious since Jason proposed a fix as the solution, and was wondering how it apparently solved the issue for him..
many thanks
asankha
> 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