2011/12/25 Matthew Tyson <matthewcarlty...@gmail.com>:
> 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?
>
Valve has access to internal Request/Response objects, bypassing a facade.
(The facade that is recycled when you set
org.apache.catalina.connector.RECYCLE_FACADES=true
in catalina.properties.
I would recommend to set that property, to protect from concurrency
issues that might be inside a web application).
I do not know what is wrong with this specific valve, though.
Do you know that you can set "secure" and "proxyPort" attributes an a
<Connector>? That would be the same as what you are trying to do with
the valve.
Best regards,
Konstantin Kolinko
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
