I added a bunch of "System.out.println"s to Synapse and to httpcore
(printlns because httpcore doesn't 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 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, and we get our exception.
________________________________
From: WALTON Jason [mailto:[EMAIL PROTECTED]
Sent: Tuesday, August 26, 2008 9:53 AM
To: [email protected]
Subject: RE: Occasionally loosing response for hosted service
within Synapse?
I was chatting with Jake Lambert, and he suspects this is
related to https://issues.apache.org/jira/browse/SYNAPSE-344. They look
similar, except his is client side whereas mine is server side.
It looks like some sort of race condition between a I/O
Dispatcher thread and a HttpServerWorker thread. The exception is
thrown in DefaultNHttpServerConnection.submitResponse():
if (this.response != null) {
throw new HttpException("Response already
submitted");
}
In other words, this connection object already has a response,
and it working on writing it out to the socket. this.response is set
back to null by DefaultNHttpServerConnection.resetOutput(), which in
turn is called by DefaultNHttpServerConnection.produceOutput(), once the
response has been written to the encoder. submitResponse() is called in
the HttpServerWorker context, whereas produceOutput() is called from the
I/O Dispatcher context. There are a few possible failure scenarios; a
connection might process a request, start writing the response, and then
a new request comes in and the new request's HttpServerWorker is
submitting a response to a connection before the connection has finished
writing the first response (I don't yet see how the transport code
protects against this, although I'm still figuring out how this all
works. :). Possibly, the logic for when to call resetOutput() is
incorrect, although it looks OK to me. Possibly we're failing out
somewhere else and somehow failing to clean up the connection?
________________________________
From: Hubert, Eric [mailto:[EMAIL PROTECTED]
Sent: Monday, August 25, 2008 4:52 PM
To: [email protected]
Subject: RE: Occasionally loosing response for hosted
service within Synapse?
Hi all,
I have also noticed the exact same exception, but it
only rarely occurs in our environment. Since June I find it about 20
times spread around 3 different servers. Last occurrence has been on
August 11. I tried to reproduce this but had no luck. As we are
currently "hunting" bigger problems I have put those on hold.
Nevertheless I would also be very happy about any findings on this
issue.
Regards,
Eric
________________________________
From: WALTON Jason
[mailto:[EMAIL PROTECTED]
Sent: Monday, August 25, 2008 7:13 PM
To: [email protected]
Subject: Occasionally loosing response for hosted
service within Synapse?
Ok, I realize this is a bit of a stretch, as my Synapse
code is not exactly an official release, but;
I'm running Synapse 1.1.1, with the NHTTP transport code
from Synapse 1.2 (didn't want to take Axis 1.4 for reasons I won't go
into here). I'm also hosting an Axis2 generated service within my
Synapse runtime. I have an Axis2 generated client which is calling into
my hosted service. The client is running over the blocking HttpClient
based transport, and obviously the service is running on the Synapse
NHTTP transport. I should also mention I'm running with the fix I
proposed for JIRA-415 (since without that fix, I run out of
HttpServerWorkers in less than a minute).
Every now and then (maybe once every 30 seconds under
heavy load?), I'll send a request from the client, the server will
receive it and process it, but then will fail to send a reply back to my
client. Every now and then I see this happen for my proxy services,
too, but I have yet to figure out a way to reproduce it consistently,
whereas I can make it happen easily for the hosted service. Looking at
the Synapse logs, I see:
<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(Def
aultNHttpServerConnection.java:202)
at
org.apache.synapse.transport.nhttp.ServerHandler.commitResponse(ServerHa
ndler.java:212)
at
org.apache.synapse.transport.nhttp.ServerWorker.run(ServerWorker.java:20
8)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecuto
r.java:885)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.ja
va:907)
at java.lang.Thread.run(Thread.java:619)
]]></log4j:throwable>
</log4j:event>
So, it seems that the service isn't writing a reply,
because for some reason it believes the response has already been
written. Thoughts? Pointers for how to chase this down?
