Connection timeout problem

[Ralph.Henze]

Hi,

I'm trying to run a pre-1.3 nightly build version of Synapse.
Unfortunately I'm getting lots of connection timeout messages in the logs:

ERROR [org.apache.synapse.transport.nhttp.ServerHandler] Connection
Timeout - before message body was fully read : [/127.0.0.18:56740]

Web service clients are getting a HTTP 502 error with about 10 %
frequency.
I tried increasing http.connection.timeout and http.socket.timeout but
that did not change the behaviour.

The released version Synapse 1.2 is no option for me, because the issue
SYNAPSE-404 freezes the entire ESB and forces a restart about 3 times per
day, which is not feasible for productive use. But using Synapse 1.2 does
not show the timeout messages and runs with no HTTP 502 errors (as long as
it hasn't run into SYNAPSE-404).

What causes the connection timeouts and how can I prevent them?
BTW I'm desperately awaiting the release of 1.3 as there are 8 critical
fixes (and 1 blocker) since 1.2 that have not gone into a release yet.

Thanks for your help.

Kind regards,

Ralph Henze.

[Asankha C. Perera]

Hi Ralph

> I'm trying to run a pre-1.3 nightly build version of Synapse.
> Unfortunately I'm getting lots of connection timeout messages in the logs:
>
> ERROR [org.apache.synapse.transport.nhttp.ServerHandler] Connection
> Timeout - before message body was fully read : [/127.0.0.18:56740]
>
> Web service clients are getting a HTTP 502 error with about 10 %
> frequency.
> I tried increasing http.connection.timeout and http.socket.timeout but
> that did not change the behaviour.
>  

Can you set the following on the lib/log4j.properties and send me a
zipped trace

log4j.category.org.apache.synapse=DEBUG
..
log4j.category.org.apache.synapse.transport.nhttp.util=DEBUG
log4j.category.org.apache.http.impl.nio.reactor=DEBUG
> The released version Synapse 1.2 is no option for me, because the issue
> SYNAPSE-404 freezes the entire ESB and forces a restart about 3 times per
> day, which is not feasible for productive use. But using Synapse 1.2 does
> not show the timeout messages and runs with no HTTP 502 errors (as long as
> it hasn't run into SYNAPSE-404).
>
> What causes the connection timeouts and how can I prevent them?
>  
If possible, get a wireshark, tcpdump trace of the messages too and send me

cheers
asankha

--
Asankha C. Perera
AdroitLogic, http://adroitlogic.org

http://esbmagic.blogspot.com

[Ralph.Henze]

Hello Asanka,

thank you for your quick response.

I attached the server log file.
I asked my administrator to create a tcp trace and will forward it as soon as I get it.



Cheers
Ralph.

Asankha Perera <asankha.apache@...> schrieb am 02.09.2009 16:04:18:

> [Bild entfernt]
>
> Re: Connection timeout problem
>
> Asankha C. Perera
>
> an:
>
> user
>
> 02.09.2009 16:05
>
> Gesendet von:
>
> Asankha Perera <asankha.apache@...>
>
> Bitte Antwort an user
>
> Hi Ralph
> > I'm trying to run a pre-1.3 nightly build version of Synapse.
> > Unfortunately I'm getting lots of connection timeout messages in the logs:
> >
> > ERROR [org.apache.synapse.transport.nhttp.ServerHandler] Connection
> > Timeout - before message body was fully read : [/127.0.0.18:56740]
> >
> > Web service clients are getting a HTTP 502 error with about 10 %
> > frequency.
> > I tried increasing http.connection.timeout and http.socket.timeout but
> > that did not change the behaviour.
> >  
> Can you set the following on the lib/log4j.properties and send me a
> zipped trace
>
> log4j.category.org.apache.synapse=DEBUG
> ..
> log4j.category.org.apache.synapse.transport.nhttp.util=DEBUG
> log4j.category.org.apache.http.impl.nio.reactor=DEBUG
> > The released version Synapse 1.2 is no option for me, because the issue
> > SYNAPSE-404 freezes the entire ESB and forces a restart about 3 times per
> > day, which is not feasible for productive use. But using Synapse 1.2 does
> > not show the timeout messages and runs with no HTTP 502 errors (as long as
> > it hasn't run into SYNAPSE-404).
> >
> > What causes the connection timeouts and how can I prevent them?
> >  
> If possible, get a wireshark, tcpdump trace of the messages too and send me
>
> cheers
> asankha
>
> --
> Asankha C. Perera
> AdroitLogic, http://adroitlogic.org
>
> http://esbmagic.blogspot.com
>
>
>
>

[Asankha C. Perera]

Hi Ralph
> I attached the server log file.
> I asked my administrator to create a tcp trace and will forward it as
> soon as I get it.
Here is a filtered snippet of the log:
2009-09-02 16:59:32,307 DEBUG
[org.apache.synapse.transport.nhttp.ServerHandler] HTTP connection
[/127.0.0.18:46523]: GET /soap/ HTTP/1.1
2009-09-02 16:59:32,310 DEBUG
[org.apache.synapse.transport.nhttp.ServerHandler] HTTP connection
[/127.0.0.18:46523]: Output ready
2009-09-02 16:59:32,311 DEBUG
[org.apache.synapse.transport.nhttp.ServerHandler] HTTP connection
[/127.0.0.18:46523]: Content encoder [chunk-coded; completed: false]
.....
2009-09-02 16:59:32,313 DEBUG
[org.apache.synapse.transport.nhttp.ServerHandler] HTTP connection
[/127.0.0.18:46523]: Content encoder [chunk-coded; completed: true]
2009-09-02 16:59:32,313 DEBUG
[org.apache.synapse.transport.nhttp.ServerHandler] HTTP connection
[/127.0.0.18:46523]: Response ready
2009-09-02 17:01:33,278 DEBUG
[org.apache.synapse.transport.nhttp.ServerHandler] HTTP connection
[/127.0.0.18:46523]: Timeout

It seems like you issue a GET /soap/ request? I also saw many of those..
what is the purpose of issuing that? Anyway.. this seems like a harmless
possible bug - where the connection gets timedout - but Synapse thinks
its response was not fully read by the client. This could happen if the
client just looks at the header of the response, and does not read the
entity body - which will prevent the HTTP connection from being re-used
again (i.e. as a keepalive) - however, I also suspect a slight bug in
the code where this message could be dumped in a harmless case. Do you
see an actual error at the client side?

cheers
asankha

--
Asankha C. Perera
AdroitLogic, http://adroitlogic.org

http://esbmagic.blogspot.com

[Ralph.Henze]

Hi Asankha,

thank you for your analysis.

The GET /soap/ requests are those issued by the monitoring system. The
monitoring assumes that the esb is available if the list of services is
retrieved or there is a problem/outage otherwise.

In our infrastructure there is an Apache HTTP server that is placed in
front of synapse, so that the tcp connection client from synapse's
perspective is always the HTTP server. The HTTP server terminates SSL
connections and connects to synapse via mod_proxy. Do you presume that a
possible solution lies in HTTP server configuration?

> It seems like you issue a GET /soap/ request? I also saw many of those..
> what is the purpose of issuing that? Anyway.. this seems like a harmless
> possible bug - where the connection gets timedout - but Synapse thinks
> its response was not fully read by the client. This could happen if the
> client just looks at the header of the response, and does not read the
> entity body - which will prevent the HTTP connection from being re-used
> again (i.e. as a keepalive) - however, I also suspect a slight bug in
> the code where this message could be dumped in a harmless case. Do you
> see an actual error at the client side?

Yes, there is an effect at the service client side. About 10 percent of
client requests are responded with HTTP error code 502. I'm not sure of
how that behaviour relates to the timeout message, because there are a lot
more timeout messages in the log than actual client errors. But we didn't
have that when we were on synapse 1.2. But as stated earlier, synapse 1.2
freezed up to 3 times a day and had to be restarted, which we assume is a
consequence of bug SYNAPSE-404.

Are you planning to prepare a fix?

Thanks again.

Cheers, Ralph.

[Asankha C. Perera]

Hi Ralph
> The GET /soap/ requests are those issued by the monitoring system. The
> monitoring assumes that the esb is available if the list of services is
> retrieved or there is a problem/outage otherwise.
>  
Typically it would be better to issue a real call through Synapse itself
for monitoring purposes. I think Eric might be able to tell you more
about the monitoring etc they do in their deployment environment.

> In our infrastructure there is an Apache HTTP server that is placed in
> front of synapse, so that the tcp connection client from synapse's
> perspective is always the HTTP server. The HTTP server terminates SSL
> connections and connects to synapse via mod_proxy. Do you presume that a
> possible solution lies in HTTP server configuration?
>
>  
>> It seems like you issue a GET /soap/ request? I also saw many of those..
>> what is the purpose of issuing that? Anyway.. this seems like a harmless
>> possible bug - where the connection gets timedout - but Synapse thinks
>> its response was not fully read by the client. This could happen if the
>> client just looks at the header of the response, and does not read the
>> entity body - which will prevent the HTTP connection from being re-used
>> again (i.e. as a keepalive) - however, I also suspect a slight bug in
>> the code where this message could be dumped in a harmless case. Do you
>> see an actual error at the client side?
>>    
>
> Yes, there is an effect at the service client side. About 10 percent of
> client requests are responded with HTTP error code 502.

Synapse does not return 502.. so this is returned by Apache.. but the
reason behind would need some investigation.. If you could re-create
this with a single request and get me a tcpdump it would be great
>  I'm not sure of
> how that behaviour relates to the timeout message, because there are a lot
> more timeout messages in the log than actual client errors. But we didn't
> have that when we were on synapse 1.2. But as stated earlier, synapse 1.2
> freezed up to 3 times a day and had to be restarted, which we assume is a
> consequence of bug SYNAPSE-404.
>
> Are you planning to prepare a fix?
>  
Yes, I could fix the issue I suspect - but that would not solve the 502
issue.. what I noticed is that Synapse may report the "Connection
Timeout - before message body was fully read " message when the remote
party (i.e. client to synapse) terminated its socket - since that was
what was happening in your logs

cheers
asankha

--
Asankha C. Perera
AdroitLogic, http://adroitlogic.org

http://esbmagic.blogspot.com

[Supun Kamburugamuva]

Hi Ralph,

Did you get a solution to this problem?

Thanks,
Supun..

On Thu, Sep 3, 2009 at 1:13 AM, Asankha C. Perera <asankha@...>wrote:

> Hi Ralph
> > The GET /soap/ requests are those issued by the monitoring system. The
> > monitoring assumes that the esb is available if the list of services is
> > retrieved or there is a problem/outage otherwise.
> >
> Typically it would be better to issue a real call through Synapse itself
> for monitoring purposes. I think Eric might be able to tell you more
> about the monitoring etc they do in their deployment environment.
> > In our infrastructure there is an Apache HTTP server that is placed in
> > front of synapse, so that the tcp connection client from synapse's
> > perspective is always the HTTP server. The HTTP server terminates SSL
> > connections and connects to synapse via mod_proxy. Do you presume that a
> > possible solution lies in HTTP server configuration?
> >
> >
> >> It seems like you issue a GET /soap/ request? I also saw many of those..
> >> what is the purpose of issuing that? Anyway.. this seems like a harmless
> >> possible bug - where the connection gets timedout - but Synapse thinks
> >> its response was not fully read by the client. This could happen if the
> >> client just looks at the header of the response, and does not read the
> >> entity body - which will prevent the HTTP connection from being re-used
> >> again (i.e. as a keepalive) - however, I also suspect a slight bug in
> >> the code where this message could be dumped in a harmless case. Do you
> >> see an actual error at the client side?
> >>
> >
> > Yes, there is an effect at the service client side. About 10 percent of
> > client requests are responded with HTTP error code 502.
> Synapse does not return 502.. so this is returned by Apache.. but the
> reason behind would need some investigation.. If you could re-create
> this with a single request and get me a tcpdump it would be great
> >  I'm not sure of
> > how that behaviour relates to the timeout message, because there are a
> lot
> > more timeout messages in the log than actual client errors. But we didn't
> > have that when we were on synapse 1.2. But as stated earlier, synapse 1.2
> > freezed up to 3 times a day and had to be restarted, which we assume is a
> > consequence of bug SYNAPSE-404.
> >
> > Are you planning to prepare a fix?
> >
> Yes, I could fix the issue I suspect - but that would not solve the 502
> issue.. what I noticed is that Synapse may report the "Connection
> Timeout - before message body was fully read " message when the remote
> party (i.e. client to synapse) terminated its socket - since that was
> what was happening in your logs
>
> cheers
> asankha
>
> --
> Asankha C. Perera
> AdroitLogic, http://adroitlogic.org
>
> http://esbmagic.blogspot.com
>
>
>
>
>

--
Software Engineer, WSO2 Inc
http://wso2.org
supunk.blogspot.com

[Ralph.Henze]

Hi Suprun,

yes, we have a solution for this.

Our analysis showed that the timeouts were due to a misbehaviour of our
.net service client.
The client is sending a "100-continue" HTTP header and waits infinitely
for a "100 Continue" response before sending the request body, resulting
in timeouts.
This behaviour is not according to HTTP 1.1 spec, though.

Synapse by now is not responding to 100-continue headers and waits for the
client to send the request body (according to HTTP 1.1).

For future versions of Synapse it would be desirable that synapse gets the
ability to respond with "100 Continue" responses.
This would prevent interoperability issues with older .net clients like
this.

Asankha provided us with a quick fix; perhaps it would be possible that
his fix flows into the Synapse trunk?

Thank you and cheers!

i. A. Ralph Henze
Dipl.-Informatiker (Univ.)
Sparda-Datenverarbeitung eG
AE-ABS/Softwarearchitektur


Supun Kamburugamuva <supun06@...> schrieb am 26.10.2009 05:04:58:

> [Bild entfernt]
>
> Re: Antwort: Re: Antwort: Re: Connection timeout problem
>
> Supun Kamburugamuva
>
> an:
>
> user
>
> 26.10.2009 05:05
>
> [Bild entfernt]
>
> Von:
>
> Supun Kamburugamuva <supun06@...>
>
> An:
>
> user@...
>
> Bitte Antwort an user@...
>
> Hi Ralph,
>
> Did you get a solution to this problem?
>
> Thanks,
> Supun..
>
> On Thu, Sep 3, 2009 at 1:13 AM, Asankha C. Perera

<asankha@...>wrote:
>
> > Hi Ralph
> > > The GET /soap/ requests are those issued by the monitoring system.
The
> > > monitoring assumes that the esb is available if the list of services
is
> > > retrieved or there is a problem/outage otherwise.
> > >
> > Typically it would be better to issue a real call through Synapse
itself
> > for monitoring purposes. I think Eric might be able to tell you more
> > about the monitoring etc they do in their deployment environment.
> > > In our infrastructure there is an Apache HTTP server that is placed
in
> > > front of synapse, so that the tcp connection client from synapse's
> > > perspective is always the HTTP server. The HTTP server terminates
SSL
> > > connections and connects to synapse via mod_proxy. Do you presume
that a
> > > possible solution lies in HTTP server configuration?
> > >
> > >
> > >> It seems like you issue a GET /soap/ request? I also saw many of
those..
> > >> what is the purpose of issuing that? Anyway.. this seems like a
harmless
> > >> possible bug - where the connection gets timedout - but Synapse
thinks
> > >> its response was not fully read by the client. This could happen if
the
> > >> client just looks at the header of the response, and does not read
the
> > >> entity body - which will prevent the HTTP connection from being
re-used
> > >> again (i.e. as a keepalive) - however, I also suspect a slight bug
in
> > >> the code where this message could be dumped in a harmless case. Do
you
> > >> see an actual error at the client side?
> > >>
> > >
> > > Yes, there is an effect at the service client side. About 10 percent
of
> > > client requests are responded with HTTP error code 502.
> > Synapse does not return 502.. so this is returned by Apache.. but the
> > reason behind would need some investigation.. If you could re-create
> > this with a single request and get me a tcpdump it would be great
> > >  I'm not sure of
> > > how that behaviour relates to the timeout message, because there are
a
> > lot
> > > more timeout messages in the log than actual client errors. But we
didn't
> > > have that when we were on synapse 1.2. But as stated earlier,
synapse 1.2
> > > freezed up to 3 times a day and had to be restarted, which we assume
is a
> > > consequence of bug SYNAPSE-404.
> > >
> > > Are you planning to prepare a fix?
> > >
> > Yes, I could fix the issue I suspect - but that would not solve the
502

> > issue.. what I noticed is that Synapse may report the "Connection
> > Timeout - before message body was fully read " message when the remote
> > party (i.e. client to synapse) terminated its socket - since that was
> > what was happening in your logs
> >
> > cheers
> > asankha
> >
> > --
> > Asankha C. Perera
> > AdroitLogic, http://adroitlogic.org
> >
> > http://esbmagic.blogspot.com
> >
> >
> >
> >
> >
>
>
> --
> Software Engineer, WSO2 Inc
> http://wso2.org
> supunk.blogspot.com
>

[Asankha C. Perera]

Hi Ralph / Supun
> For future versions of Synapse it would be desirable that synapse gets the ability to respond with "100 Continue" responses. This would prevent interoperability issues with older .net clients like this.
>
> Asankha provided us with a quick fix; perhaps it would be possible that his fix flows into the Synapse trunk?
>  
I've committed the fix against SYNAPSE-231

cheers
asankha

--
Asankha C. Perera
AdroitLogic, http://adroitlogic.org

http://esbmagic.blogspot.com