hc-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Asankha C. Perera (JIRA)" <j...@apache.org>
Subject [jira] Commented: (HTTPCORE-170) Race condition in SharedOutputBuffer may cause a connection to hang.
Date Tue, 23 Sep 2008 12:56:44 GMT

    [ 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


Mime
View raw message