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 14:07:44 GMT

    [ 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


Mime
View raw message