[prev in list] [next in list] [prev in thread] [next in thread] 

List:       httpclient-commons-dev
Subject:    [jira] Commented: (HTTPCORE-170) Race condition in
From:       "Jason Walton (JIRA)" <jira () apache ! org>
Date:       2008-09-23 15:21:46
Message-ID: 699449336.1222183306241.JavaMail.jira () brutus
[Download RAW message or body]


    [ https://issues.apache.org/jira/browse/HTTPCORE-170?page=com.atlassian.jira.plugi \
n.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


[prev in list] [next in list] [prev in thread] [next in thread]