You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Stephen Dawkins <st...@gmail.com> on 2015/05/18 11:31:55 UTC
Tomcat occasionally duplicating responses
Hi
I have an application that uses embedded Tomcat (8.0.22) to serve SOAP
services. I've recently attempted to add javamelody[1] to the app to gather
some stats, however I've run into an issue where occasionally the response
is incorrect, mostly it just duplicates response, although sometimes it's
not a valid HTTP response. I can only seem to reproduce this on a Linux box
(which is running Fedora 19), my Windows machine doesn't appear to have the
same issue.
I've confirmed that the application code is only sending the response once,
and the error only occurs when using the javamelody servlet filter.
However, investigating the filter didn't reveal anything obvious that would
cause the problem (it just collects the amount of bytes sent). It does
override the flushBuffer method in the class it uses to wrap the
HttpServletResponse, but I get the same error even when I don't explicitly
call that method from the application code.
The client I'm using to test with just uses Apache CXF to send one request
at a time to the server. Interestingly I couldn't seem to reproduce it when
I increased the amount of threads that the client was using, however it's
not the most reliable error to reproduce with just a single thread.
I've tried setting breakpoints in various places in the application,
javamelody and Tomcat, but I couldn't get any useful information out of it
(since I'm having to debug remotely, the conditional breakpoints are slow
enough to make reproducing it extremely difficult), and I'm not entirely
certain where the issue is. The only information I've managed to glean is
from using strace to capture the syscalls:
pid timestamp syscall
32189 16:19:34.330576 write(118, "HTTP/1.1 200 OK\r\nServer:
Apache-Coyote/1.1"..., 149) = 149
32189 16:19:34.331728 write(118, "51e\r\n", 5) = 5
32189 16:19:34.332788 write(118, "<?xml version=\"1.0\"
encoding=\"UTF-8\""..., 1310) = 1310
32189 16:19:34.335779 write(118, "\r\n", 2) = 2
32216 16:19:34.336863 write(118, "51e\r\n", 5) = 5
32216 16:19:34.337734 write(118, "<?xml version=\"1.0\"
encoding=\"UTF-8\""..., 1310) = 1310
32216 16:19:34.344520 write(118, "\r\n", 2) = 2
32200 16:19:34.346986 write(118, "0\r\n\r\n", 5) = 5
The pid column is the most interesting. This shows that there are 2
separate threads sending the same response to the client, which doesn't
seem right. Occasionally, I get a slightly different error in the client
(the above response just produces an XML parse error):
32201 16:17:29.592419 write(161, "HTTP/1.1 200 OK\r\nServer:
Apache-Coyote/1.1"..., 149) = 149
32201 16:17:29.593717 write(161, "51e\r\n", 5) = 5
32201 16:17:29.594848 write(161, "<?xml version=\"1.0\"
encoding=\"UTF-8\""..., 1310) = 1310
32235 16:17:29.597871 write(161, "51e\r\n", 5) = 5
32235 16:17:29.603263 write(161, "<?xml version=\"1.0\"
encoding=\"UTF-8\""..., 1310) = 1310
32235 16:17:29.603977 write(161, "\r\n", 2) = 2
32201 16:17:29.605333 write(161, "\r\n", 2) = 2
32216 16:17:29.608646 write(161, "0\r\n\r\n", 5) = -1 EPIPE (Broken pipe)
This produces the following error:
java.io.IOException: missing CR
at
sun.net.www.http.ChunkedInputStream.processRaw(ChunkedInputStream.java:405)
at
sun.net.www.http.ChunkedInputStream.readAheadBlocking(ChunkedInputStream.java:572)
...
Again, 2 separate threads, but this time interleaved in a way that's
invalid.
While I'm happy enough to fix any issue in javamelody if that is what is
causing it, I'm very concerned that it's uncovered a latent issue in Tomcat.
Does anyone have any suggestions as to where the issue could be?
[1] https://code.google.com/p/javamelody/
Thanks & Regards
Stephen
Re: Tomcat occasionally duplicating responses
Posted by Stephen Dawkins <st...@gmail.com>.
On Mon, May 18, 2015 at 2:24 PM, Mark Thomas <ma...@apache.org> wrote:
> On 18/05/2015 13:40, Stephen Dawkins wrote:
>> On Mon, May 18, 2015 at 12:30 PM, Mark Thomas <ma...@apache.org> wrote:
>
> Bingo.
>
> I think I have found the problem (well, a problem anyway). It looks like
> there is a bug in javamelody.
>
> Once a request/response has been put into async mode, control passes to
> the async processing. i.e. from that point onwards the container should
> not be writing to the response until the application returns control to
> the container via a dispatch.
>
> If you look at the this line of code [1], javamelody is flushing the
> response. There needs to be an if (!request.isAsyncStarted()) {...}
> around that code.
I'll try adding this code and see if that resolves the issue.
> Also, looking at the various Response wrapper classes, none of them use
> syncs / or volatile. Since control is passing between threads there is
> the possibility of stale values being observed in the new thread. In my
> experience actually seeing a stale value is pretty rare but it could happen.
I can look into these once I can actually enable javamelody without
breaking anything.
Thanks for you help in this matter.
Regards
Stephen
> HTH,
>
> Mark
>
> [1]
> https://code.google.com/p/javamelody/source/browse/trunk/javamelody-core/src/main/java/net/bull/javamelody/MonitoringFilter.java#199
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Tomcat occasionally duplicating responses
Posted by Mark Thomas <ma...@apache.org>.
On 14/06/2015 15:56, evernat wrote:
>> On Mon, May 18, 2015 at 12:30 PM, Mark Thomas <markt <at> apache.org> wrote:
>
>> Once a request/response has been put into async mode, control passes to
>> the async processing. i.e. from that point onwards the container should
>> not be writing to the response until the application returns control to
>> the container via a dispatch.
>>
>> If you look at the this line of code [1], javamelody is flushing the
>> response. There needs to be an if (!request.isAsyncStarted()) {...}
>> around that code.
>>
>> [1]
>>
> https://code.google.com/p/javamelody/source/browse/trunk/javamelody-core/
> src/main/java/net/bull/javamelody/MonitoringFilter.java#199
>
>
> About this javamelody and async issue, the change for flushBuffer looks good
> and it's merged now. Thanks.
Great. Happy to help.
> Note that there is one known issue with javamelody and some (spring-webmvc)
> async cases, with empty response. And the above change for flushBuffer does
> not fix this issue.
> It can be reproduced with Tomcat and not with Jetty, here is the link:
> https://code.google.com/p/javamelody/issues/detail?id=338#c6
Open a Tomcat bug for that and we'll take a look.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Tomcat occasionally duplicating responses
Posted by evernat <ev...@free.fr>.
> On Mon, May 18, 2015 at 12:30 PM, Mark Thomas <markt <at> apache.org> wrote:
> Once a request/response has been put into async mode, control passes to
> the async processing. i.e. from that point onwards the container should
> not be writing to the response until the application returns control to
> the container via a dispatch.
>
> If you look at the this line of code [1], javamelody is flushing the
> response. There needs to be an if (!request.isAsyncStarted()) {...}
> around that code.
>
> [1]
>
https://code.google.com/p/javamelody/source/browse/trunk/javamelody-core/
src/main/java/net/bull/javamelody/MonitoringFilter.java#199
About this javamelody and async issue, the change for flushBuffer looks good
and it's merged now. Thanks.
Note that there is one known issue with javamelody and some (spring-webmvc)
async cases, with empty response. And the above change for flushBuffer does
not fix this issue.
It can be reproduced with Tomcat and not with Jetty, here is the link:
https://code.google.com/p/javamelody/issues/detail?id=338#c6
- Emeric
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Tomcat occasionally duplicating responses
Posted by Mark Thomas <ma...@apache.org>.
On 18/05/2015 13:40, Stephen Dawkins wrote:
> On Mon, May 18, 2015 at 12:30 PM, Mark Thomas <ma...@apache.org> wrote:
>> Thanks. That rules out some possibilities for application error.
>>
>> When you get two threads writing to the response, if would be useful to
>> know which of the following those threads are:
>> - the Tomcat thread that handled the original request
>> - the application thread that wrote the response
>> - the Tomcat thread that the application dispatched to once the async
>> processing completed
>
> Here's what I've found:
>
> PID
> 15302 initial request received, initial application processing and
> request sent to a remote server asynchornously
> 15305 received response from remote server, more application processing
> 15305 HTTP response sent
> 15302 additional HTTP response sent, eventually fails with Broken Pipe
Bingo.
I think I have found the problem (well, a problem anyway). It looks like
there is a bug in javamelody.
Once a request/response has been put into async mode, control passes to
the async processing. i.e. from that point onwards the container should
not be writing to the response until the application returns control to
the container via a dispatch.
If you look at the this line of code [1], javamelody is flushing the
response. There needs to be an if (!request.isAsyncStarted()) {...}
around that code.
Also, looking at the various Response wrapper classes, none of them use
syncs / or volatile. Since control is passing between threads there is
the possibility of stale values being observed in the new thread. In my
experience actually seeing a stale value is pretty rare but it could happen.
HTH,
Mark
[1]
https://code.google.com/p/javamelody/source/browse/trunk/javamelody-core/src/main/java/net/bull/javamelody/MonitoringFilter.java#199
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Tomcat occasionally duplicating responses
Posted by Stephen Dawkins <st...@gmail.com>.
On Mon, May 18, 2015 at 12:30 PM, Mark Thomas <ma...@apache.org> wrote:
> Thanks. That rules out some possibilities for application error.
>
> When you get two threads writing to the response, if would be useful to
> know which of the following those threads are:
> - the Tomcat thread that handled the original request
> - the application thread that wrote the response
> - the Tomcat thread that the application dispatched to once the async
> processing completed
Here's what I've found:
PID
15302 initial request received, initial application processing and
request sent to a remote server asynchornously
15305 received response from remote server, more application processing
15305 HTTP response sent
15302 additional HTTP response sent, eventually fails with Broken Pipe
> Mark
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Tomcat occasionally duplicating responses
Posted by Mark Thomas <ma...@apache.org>.
On 18/05/2015 12:07, Stephen Dawkins wrote:
> On Mon, May 18, 2015 at 12:00 PM, Mark Thomas <ma...@apache.org> wrote:
>> OK. Is Javamelody async aware? In particular I am wondering if it
>> correctly handles the case where Servlet.service() returns after
>> startAsync() but the app hasn't written any of / all of the response yet.
>>
>> If javamelody is wrapping the response it is going to need to handle the
>> async case correctly.
>>
> The documentation does say to add the relevant option to the web.xml
> if you require async-support.
OK. Lets assume that javamelody is designed to handle async correctly.
> Also, I've tested with the
> org.apache.catalina.connector.RECYCLE_FACADES=true option set, and the
> error still occurs.
Thanks. That rules out some possibilities for application error.
When you get two threads writing to the response, if would be useful to
know which of the following those threads are:
- the Tomcat thread that handled the original request
- the application thread that wrote the response
- the Tomcat thread that the application dispatched to once the async
processing completed
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Tomcat occasionally duplicating responses
Posted by Stephen Dawkins <st...@gmail.com>.
On Mon, May 18, 2015 at 12:00 PM, Mark Thomas <ma...@apache.org> wrote:
> On 18/05/2015 11:50, Stephen Dawkins wrote:
>> On Mon, May 18, 2015 at 11:22 AM, Mark Thomas <ma...@apache.org> wrote:
>>> On 18/05/2015 10:31, Stephen Dawkins wrote:
>>>> Does anyone have any suggestions as to where the issue could be?
>>>
>>> Are you using any Servlet 3.0 async features?
>>>
>> Yes, I have async enabled for the filter and the servlet that
>> processes the request, and the application will likely use a different
>> thread to response than processes the request.
>
> OK. Is Javamelody async aware? In particular I am wondering if it
> correctly handles the case where Servlet.service() returns after
> startAsync() but the app hasn't written any of / all of the response yet.
>
> If javamelody is wrapping the response it is going to need to handle the
> async case correctly.
>
The documentation does say to add the relevant option to the web.xml
if you require async-support.
https://code.google.com/p/javamelody/wiki/UserGuide#2._web.xml_file
Also, I've tested with the
org.apache.catalina.connector.RECYCLE_FACADES=true option set, and the
error still occurs.
Regards
Stephen
> Mark
>
>
>>
>>> Mark
>>>
>>>>
>>>> [1] https://code.google.com/p/javamelody/
>>>>
>>>> Thanks & Regards
>>>> Stephen
>>>>
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>>> For additional commands, e-mail: users-help@tomcat.apache.org
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Tomcat occasionally duplicating responses
Posted by Mark Thomas <ma...@apache.org>.
On 18/05/2015 11:50, Stephen Dawkins wrote:
> On Mon, May 18, 2015 at 11:22 AM, Mark Thomas <ma...@apache.org> wrote:
>> On 18/05/2015 10:31, Stephen Dawkins wrote:
>>
>> Tomcat will call flushBuffer() internally.
>>
>> Tomcat does re-use Request/Response objects so if a reference is
>> accidentally retained to one of them you can see this issue.
>>
>> Try using:
>> org.apache.catalina.connector.RECYCLE_FACADES=true
>>
>> (not the best named attribute but true will cause a new facade to be
>> created for every request/response).
>
> I will test with that property set.
>
>> Are those both Java threads from the same JVM?
> Yes, they're both from the same JVM.
>
>>
>> Can you correlate seeing multiple threads with the error occurring?
>>
> Most of the time, a response is written by just one thread.
> Occasionally the last 0\r\n\r\n is written by a different thread to
> the one that writes the bulk of the response.
>
>>
>> Unlikely but possible to be a Tomcat issue with the information we have
>> so far.
>>
>>> Does anyone have any suggestions as to where the issue could be?
>>
>> Are you using any Servlet 3.0 async features?
>>
> Yes, I have async enabled for the filter and the servlet that
> processes the request, and the application will likely use a different
> thread to response than processes the request.
OK. Is Javamelody async aware? In particular I am wondering if it
correctly handles the case where Servlet.service() returns after
startAsync() but the app hasn't written any of / all of the response yet.
If javamelody is wrapping the response it is going to need to handle the
async case correctly.
Mark
>
>> Mark
>>
>>>
>>> [1] https://code.google.com/p/javamelody/
>>>
>>> Thanks & Regards
>>> Stephen
>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Tomcat occasionally duplicating responses
Posted by Stephen Dawkins <st...@gmail.com>.
On Mon, May 18, 2015 at 11:22 AM, Mark Thomas <ma...@apache.org> wrote:
> On 18/05/2015 10:31, Stephen Dawkins wrote:
>
> Tomcat will call flushBuffer() internally.
>
> Tomcat does re-use Request/Response objects so if a reference is
> accidentally retained to one of them you can see this issue.
>
> Try using:
> org.apache.catalina.connector.RECYCLE_FACADES=true
>
> (not the best named attribute but true will cause a new facade to be
> created for every request/response).
I will test with that property set.
> Are those both Java threads from the same JVM?
Yes, they're both from the same JVM.
>
> Can you correlate seeing multiple threads with the error occurring?
>
Most of the time, a response is written by just one thread.
Occasionally the last 0\r\n\r\n is written by a different thread to
the one that writes the bulk of the response.
>
> Unlikely but possible to be a Tomcat issue with the information we have
> so far.
>
>> Does anyone have any suggestions as to where the issue could be?
>
> Are you using any Servlet 3.0 async features?
>
Yes, I have async enabled for the filter and the servlet that
processes the request, and the application will likely use a different
thread to response than processes the request.
> Mark
>
>>
>> [1] https://code.google.com/p/javamelody/
>>
>> Thanks & Regards
>> Stephen
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Tomcat occasionally duplicating responses
Posted by Mark Thomas <ma...@apache.org>.
On 18/05/2015 10:31, Stephen Dawkins wrote:
> Hi
>
> I have an application that uses embedded Tomcat (8.0.22) to serve SOAP
> services. I've recently attempted to add javamelody[1] to the app to gather
> some stats, however I've run into an issue where occasionally the response
> is incorrect, mostly it just duplicates response, although sometimes it's
> not a valid HTTP response. I can only seem to reproduce this on a Linux box
> (which is running Fedora 19), my Windows machine doesn't appear to have the
> same issue.
>
> I've confirmed that the application code is only sending the response once,
> and the error only occurs when using the javamelody servlet filter.
> However, investigating the filter didn't reveal anything obvious that would
> cause the problem (it just collects the amount of bytes sent). It does
> override the flushBuffer method in the class it uses to wrap the
> HttpServletResponse, but I get the same error even when I don't explicitly
> call that method from the application code.
Tomcat will call flushBuffer() internally.
Tomcat does re-use Request/Response objects so if a reference is
accidentally retained to one of them you can see this issue.
Try using:
org.apache.catalina.connector.RECYCLE_FACADES=true
(not the best named attribute but true will cause a new facade to be
created for every request/response).
> The client I'm using to test with just uses Apache CXF to send one request
> at a time to the server. Interestingly I couldn't seem to reproduce it when
> I increased the amount of threads that the client was using, however it's
> not the most reliable error to reproduce with just a single thread.
>
> I've tried setting breakpoints in various places in the application,
> javamelody and Tomcat, but I couldn't get any useful information out of it
> (since I'm having to debug remotely, the conditional breakpoints are slow
> enough to make reproducing it extremely difficult), and I'm not entirely
> certain where the issue is. The only information I've managed to glean is
> from using strace to capture the syscalls:
>
> pid timestamp syscall
> 32189 16:19:34.330576 write(118, "HTTP/1.1 200 OK\r\nServer:
> Apache-Coyote/1.1"..., 149) = 149
> 32189 16:19:34.331728 write(118, "51e\r\n", 5) = 5
> 32189 16:19:34.332788 write(118, "<?xml version=\"1.0\"
> encoding=\"UTF-8\""..., 1310) = 1310
> 32189 16:19:34.335779 write(118, "\r\n", 2) = 2
> 32216 16:19:34.336863 write(118, "51e\r\n", 5) = 5
> 32216 16:19:34.337734 write(118, "<?xml version=\"1.0\"
> encoding=\"UTF-8\""..., 1310) = 1310
> 32216 16:19:34.344520 write(118, "\r\n", 2) = 2
> 32200 16:19:34.346986 write(118, "0\r\n\r\n", 5) = 5
>
> The pid column is the most interesting. This shows that there are 2
> separate threads sending the same response to the client, which doesn't
> seem right. Occasionally, I get a slightly different error in the client
> (the above response just produces an XML parse error):
Are those both Java threads from the same JVM?
Can you correlate seeing multiple threads with the error occurring?
> 32201 16:17:29.592419 write(161, "HTTP/1.1 200 OK\r\nServer:
> Apache-Coyote/1.1"..., 149) = 149
> 32201 16:17:29.593717 write(161, "51e\r\n", 5) = 5
> 32201 16:17:29.594848 write(161, "<?xml version=\"1.0\"
> encoding=\"UTF-8\""..., 1310) = 1310
> 32235 16:17:29.597871 write(161, "51e\r\n", 5) = 5
> 32235 16:17:29.603263 write(161, "<?xml version=\"1.0\"
> encoding=\"UTF-8\""..., 1310) = 1310
> 32235 16:17:29.603977 write(161, "\r\n", 2) = 2
> 32201 16:17:29.605333 write(161, "\r\n", 2) = 2
> 32216 16:17:29.608646 write(161, "0\r\n\r\n", 5) = -1 EPIPE (Broken pipe)
>
> This produces the following error:
>
> java.io.IOException: missing CR
> at
> sun.net.www.http.ChunkedInputStream.processRaw(ChunkedInputStream.java:405)
> at
> sun.net.www.http.ChunkedInputStream.readAheadBlocking(ChunkedInputStream.java:572)
> ...
>
> Again, 2 separate threads, but this time interleaved in a way that's
> invalid.
>
> While I'm happy enough to fix any issue in javamelody if that is what is
> causing it, I'm very concerned that it's uncovered a latent issue in Tomcat.
Unlikely but possible to be a Tomcat issue with the information we have
so far.
> Does anyone have any suggestions as to where the issue could be?
Are you using any Servlet 3.0 async features?
Mark
>
> [1] https://code.google.com/p/javamelody/
>
> Thanks & Regards
> Stephen
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org