On Sat, Dec 24, 2011 at 10:33 AM, Matthew Tyson
<matthewcarlty...@gmail.com>wrote:
> On Sat, Dec 24, 2011 at 1:06 AM, Mark Thomas <ma...@apache.org> wrote:
>
>> On 23/12/2011 23:39, Matthew Tyson wrote:
>> > Hello,
>> >
>> > We have been having quite a few problems with using long-polling
>> > connections in Tomcat, via the NIO connector. Upgrading to Tomcat
>> 7.0.23
>> > definitely improved things, but we are still seeing major issues.
>>
>> Glad to hear things are getting better. No so glad to hear you are still
>> having problems.
>>
>> > The problems only crop up after a couple minutes under some load (modest
>> > load, around 2-3 connections per second).
>>
>> That's pretty low load.
>>
>
> It is. We have just a small portion of connections routed to this server.
>
>
>>
>> > One very clear problem I am looking at right now is that the service
>> method
>> > on a servlet is continually being called, although there is no traffic
>> > coming into tomcat from that remote IP (we verified this at the ethernet
>> > device).
>>
>> Hmm. Very strange that the service method is being called. There needs
>> to be a complete and valid set of HTTP headers for that to happen and
>> the request/response gets recycled afterwards so the data shouldn't get
>> processed twice.
>>
>>
> It is very strange.
>
>
>> > The logging statement at the beginning of the service method is being
>> > executed every so often, like so:
>>
>> > logger.info("REQUEST: " + request.getRemoteAddr() + " " +
>> > request.getMethod() + " " + request.getQueryString());
>> >
>> > INFO 2011-12-23 15:30:50,860 org.cometd.server.CometdServlet REQUEST:
>> > 75.149.42.46 POST null
>> > INFO 2011-12-23 15:31:02,484 org.cometd.server.CometdServlet REQUEST:
>> > 75.149.42.46 GET
>> >
>>
>> message=%5B%7B%22channel%22%3A%22%2Fmeta%2Fconnect%22%2C%22connectionType%22%3A%22callback-polling%22%2C%22advice%22%3A%7B%22timeout%22%3A0%7D%2C%22id%22%3A%22354%22%2C%22clientId%22%3A%222b611tiekwk6p2mfh5bye3bm6y7l%22%7D%5D&jsonp=dojo.io.script.jsonp_dojoIoScript135._jsonpCallback
>> > INFO 2011-12-23 15:31:28,512 org.cometd.server.CometdServlet REQUEST:
>> > 75.149.42.46 POST null
>> > INFO 2011-12-23 15:31:36,571 org.cometd.server.CometdServlet REQUEST:
>> > 75.149.42.46 POST null
>>
>> Odd. So there are at least two different requests being processed here.
>>
>> > But again, there is no traffic from that IP. I'm not sure if this is
>> some
>> > sort of loop, a very long delay, or other connections being mixed up.
>>
>> I'm not aware of any connection mix up issues that might explain this.
>>
>> > Probably the last, since I don't see any loop pattern, and it has
>> > continued without any traffic for almost a half an hour now.
>> >
>> > Thoughts?
>>
>> We need more information :)
>>
>> If you can create a simple web application that reproduces this I'd be
>> happy to take a look. I suspect that is non-trivial so I'll suggest a
>> couple of other options.
>>
>> 1. The simple thing is to add a stack trace to that log message so we
>> can see exactly what code path is triggered this.
>>
>>
> Here is a couple stack traces from this when the problem is occurring:
>
> INFO 2011-12-24 10:25:35,578 COMET REQUEST: 75.149.42.46 POST null |
> TRACE:
> java.lang.Throwable
> at org.cometd.server.CometdServlet.service(CometdServlet.java:149)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:722)
> at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
> at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
> at
> com.company.util.filter.MonitoringFilter.doFilter(MonitoringFilter.java:47)
> at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
> at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
> at
> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:224)
> at
> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:169)
> at
> org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
> at
> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168)
> at
> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)
> at
> org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:928)
> at
> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
> at
> com.company.util.tomcat.SecureProxyValve.invoke(SecureProxyValve.java:57)
> at
> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407)
> at
> org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:987)
> at
> org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:539)
> at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1571)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> at java.lang.Thread.run(Thread.java:662)
>
> INFO 2011-12-24 10:25:35,807 COMET REQUEST: 96.41.34.58 POST null |
> TRACE:
> java.lang.Throwable
> at org.cometd.server.CometdServlet.service(CometdServlet.java:149)
> at javax.servlet.http.HttpServlet.service(HttpServlet.java:722)
> at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305)
> at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
> at
> com.company.util.filter.MonitoringFilter.doFilter(MonitoringFilter.java:47)
> at
> org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243)
> at
> org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210)
> at
> org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:224)
> at
> org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:169)
> at
> org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472)
> at
> org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168)
> at
> org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)
> at
> org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:928)
> at
> org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118)
> at
> com.company.util.tomcat.SecureProxyValve.invoke(SecureProxyValve.java:57)
> at
> org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407)
> at
> org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:987)
> at
> org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:539)
> at
> org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1571)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
> at java.lang.Thread.run(Thread.java:662)
>
>
>> 2. How comfortable are you patching Tomcat and building it from source?
>> I have some debug logging sat in a git branch that I use for debugging
>> similar issues that will generate a lot of logging but show exactly what
>> is happening. I can either provide you with the patch or an updated JAR
>> (or JARs) that you can drop into a 7.0.23 instance.
>>
>>
> Does the stack trace shed any light? If not, I can try the JAR or the git
> branch.
>
>
>> Mark
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
>> For additional commands, e-mail: users-h...@tomcat.apache.org
>>
>> Thanks for your help.
>
> Regards,
>
> Matt Tyson
>
I noticed in the stack trace our custom valve. Its a very simple valve
that just checks what port a request came in on and sets a flag on the
request object:
public void invoke(Request req, Response resp) throws IOException,
ServletException {
if (req.getLocalPort() == secureProxyPort) {
req.setSecure(true);
req.setServerPort(serverPort);
}
if (getNext() != null) {
getNext().invoke(req, resp);
}
}
I disabled the valve, and so far, the repeating requests have stopped. (I
should mention that asyncSupported is true on this valve).
Any thoughts on why this would cause this problem?
Regards,
Matt Tyson
PS. I had written this before Stefan's email and have been giving it more
time to let the problem resurface. I'm still not seeing the repeated
request issue.
