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
