Am 24.12.2011 19:33, schrieb Matthew Tyson:
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)
I guess com.company is something your company developed. Monitoring
sounds optional. Can you reproduce your error without it?
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)
Again com.company: What is this valve doing? Can you reproduce the
problem without it?
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
Regards,
Stefan
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
