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
