[ 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: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]