You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Matthew Tyson <ma...@gmail.com> on 2011/12/24 00:39:16 UTC
Odd NIO connector behavior
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.
The problems only crop up after a couple minutes under some load (modest
load, around 2-3 connections per second).
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).
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
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.
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?
Regards,
Matt Tyson
Re: Odd NIO connector behavior
Posted by Matthew Tyson <ma...@gmail.com>.
On Tue, Dec 27, 2011 at 11:11 AM, Mark Thomas <ma...@apache.org> wrote:
> On 25/12/2011 02:17, Matthew Tyson wrote:
>
> >> 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)
>
> That all looks pretty normal. What I am wondering now, is what is
> calling NioEndpoint.processSocket()
>
> I'd suggest if at all possible, setting up your Tomcat instance to allow
> remote debugging and then once the instance gets into this state check
> what is calling that code. It gets called far too often to output a
> stack trace every call during normal operation.
>
> >>> 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.
>
> I'm not sure my debug code is in the right place for this. If the
> debugging above isn't possible then patching Tomcat may be the only
> option. It sounds like you know enough of what you are doing to just
> patch it if required (noting that any such patch will generate a lot of
> output in normal running) but feel free to ask here if I have misjudged
> things.
>
>
> > 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?
>
> Strange. I don't see anything wrong with that but if there is a
> threading problem at the bottom of this, the timing change this creates
> may be enough to trigger whatever the problem is.
>
> Mark
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
Although removing the Valve seems to have prevented the ghost requests, I
still see issues. I often see requests come in that then get an empty 200
response sent back, but the service method is never executed in the servlet
(the logging statement never outputs).
For instance, here is output from ngrep:
T clientIP:33517 -> serverIP:8080 [A]
GET
/cometd/connect?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%22465%22%2C%22clientId%22%3A%22jwa1dr7eoo2er4ds1ssfmbpjp5thr%22%7D%5D&jsonp=dojo.io.script.jsonp_dojoIoScript333._jsonpCallback
HTTP/1.1..Host: www.company.
net..User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:8.0.1)
Gecko/20100101 Firefox/8.0.1..Accept: */*..Accept-Language:
en-us,en;q=0.5..Accept-Encoding: gzip, defl
ate..Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7..Connection:
keep-alive..Referer: https://www. company .net/main.do..Cookie:
__utma=185983734.486327630.1323474267.13
25005195.1325007098.17;
__utmz=185983734.1323474267.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none);
companyDomain=company.net; hasFlash=true; isYtBlocked=false; xgh=
gnweb10; __utmc=185983734; JSESSIONID=AF05B4D0A31052BD5913676680F3001D;
BIGipCookie=0000000000000000000000000000000000000000000000000000000000000000000000000000000000
00000000000000000000000000000000000000; contest-data=null;
PHPSESSID=hutnu4pn10qgs1o32fqdmistc6;
BAYEUX_BROWSER=806a-4yh4dbz5t2ddgwkybwa8pd6; cdnPath="https://cdn.gag
gle.net";
SESSION$STATE=10ba57c6bdb00759e37d5224a6372ef36e765b3df408d50f3aff12c1f38245789bec173ae0d1356c50ba7a36fb13618268e15e95860fa6952677fc7b790be48e;
TIME$STATE=1
0ba57c6bdb00759e37d5224a6372ef36e765b3df408d50f3aff12c1f38245789bec173ae0d1356c50ba7a36fb13618268e15e95860fa6952677fc7b790be48e;
JID
##
T clientIP:33517 -> serverIP:8080 [AP]
=mtyson; company .web5. company .net.kyz2ni.0874Frid=5478438;
company .web5.company.net.kyz2ni.0874Fsid=ab2a2c9b-3bd8-4513-9339-a9fc1d6a6b35....
##
T serverIP:8080 -> clientIP:33517 [AP]
HTTP/1.1 200 OK..Server: Apache-Coyote/1.1..Transfer-Encoding:
chunked..Date: Tue, 27 Dec 2011 20:28:28 GMT....0....
But the cometdServlet (mapped to cometd/*) never hits the logging statement
in service().
This problem also does not appear until the tomcat instance has been
running for a few minutes (the initial connections work normally).
Does it seem best to re-enable the Valve and attempt to troubleshoot that,
or approach this problem?
Thanks,
Matt Tyson
PS. After watching the logs for a while, it could be that the service()
method does get called, but in a delayed fashion, after the empty 200 has
been sent already. Its also possible that the service() method is called,
but with the wrong remoteAddr() returned from the request.
Re: Odd NIO connector behavior
Posted by Mark Thomas <ma...@apache.org>.
On 25/12/2011 02:17, Matthew Tyson wrote:
>> 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)
That all looks pretty normal. What I am wondering now, is what is
calling NioEndpoint.processSocket()
I'd suggest if at all possible, setting up your Tomcat instance to allow
remote debugging and then once the instance gets into this state check
what is calling that code. It gets called far too often to output a
stack trace every call during normal operation.
>>> 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.
I'm not sure my debug code is in the right place for this. If the
debugging above isn't possible then patching Tomcat may be the only
option. It sounds like you know enough of what you are doing to just
patch it if required (noting that any such patch will generate a lot of
output in normal running) but feel free to ask here if I have misjudged
things.
> 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?
Strange. I don't see anything wrong with that but if there is a
threading problem at the bottom of this, the timing change this creates
may be enough to trigger whatever the problem is.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Odd NIO connector behavior
Posted by Konstantin Kolinko <kn...@gmail.com>.
2011/12/25 Matthew Tyson <ma...@gmail.com>:
> On Sat, Dec 24, 2011 at 10:33 AM, Matthew Tyson
> <ma...@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-unsubscribe@tomcat.apache.org
>>> For additional commands, e-mail: users-help@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-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Odd NIO connector behavior
Posted by Matthew Tyson <ma...@gmail.com>.
On Sat, Dec 24, 2011 at 10:33 AM, Matthew Tyson
<ma...@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-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@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.
Re: Odd NIO connector behavior
Posted by Stefan Mayr <st...@mayr-stefan.de>.
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-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>> Thanks for your help.
>
> Regards,
>
> Matt Tyson
>
Regards,
Stefan
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Odd NIO connector behavior
Posted by Matthew Tyson <ma...@gmail.com>.
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-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
> Thanks for your help.
Regards,
Matt Tyson
Re: Odd NIO connector behavior
Posted by Mark Thomas <ma...@apache.org>.
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.
> 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.
> 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.
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.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Odd NIO connector behavior
Posted by Matthew Tyson <ma...@gmail.com>.
Just a heads up to the Tomcat team - I switched all our comet handling to
Jetty, and these issues are resolved. Something is definitely amiss in the
NIO connector.
Regards,
Matt Tyson
On Sat, Dec 31, 2011 at 10:23 AM, Mark Thomas <ma...@apache.org> wrote:
> On 31/12/2011 16:35, Matthew Tyson wrote:
> > On Wed, Dec 28, 2011 at 1:04 AM, <ma...@apache.org> wrote:
> >
> >> Matthew Tyson <ma...@gmail.com> wrote:
> >>
> >>> That's right, there is an f5 load balancer. The valve is used to keep
> >>> track of whether the request was via HTTPS or not.
> >>
> >> What happens if you go direct to Tomcat and bypass the F5?
> >>
> >>> tcpdump seems to confirm the same. What are you thinking?
> >>
> >> Probably, like me, that the F5 isn't handling the Comet requests
> correctly.
> >>
> >> Mark
> >>
> >>
> > I am trying to understand how the load balancer could cause Tomcat to
> > respond with an empty 200 response to a request, without ever executing
> the
> > service method on the servlet mapped to the url.
>
> I've seen all sorts of odd behaviors when something is expecting HTTP
> but doesn't get it.
>
> > The inbound request to tomcat is correct, and it is sometimes
> > handled correctly. However, much of the time it is sending the empty
> 200.
>
> Given that there appears to be multiple issues here, I'd suggest
> concentrating on the one that is likely easiest to debug. Fix that and
> then see what the other problems then look like. We might be seeing two
> sides of the same issue.
>
> My recommendation is:
> - if possible, test without the F5 just to be sure this is purely a
> Tomcat issue
> - investigate the repeated calls to service() with no incoming request
> as that is likely to be easier to debug. As per my previous suggestion,
> get Tomcat into this state and then use remote debugging to see what is
> calling NioEndpoint.processSocket()
>
> Mark
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
Re: Odd NIO connector behavior
Posted by Mark Thomas <ma...@apache.org>.
On 31/12/2011 16:35, Matthew Tyson wrote:
> On Wed, Dec 28, 2011 at 1:04 AM, <ma...@apache.org> wrote:
>
>> Matthew Tyson <ma...@gmail.com> wrote:
>>
>>> That's right, there is an f5 load balancer. The valve is used to keep
>>> track of whether the request was via HTTPS or not.
>>
>> What happens if you go direct to Tomcat and bypass the F5?
>>
>>> tcpdump seems to confirm the same. What are you thinking?
>>
>> Probably, like me, that the F5 isn't handling the Comet requests correctly.
>>
>> Mark
>>
>>
> I am trying to understand how the load balancer could cause Tomcat to
> respond with an empty 200 response to a request, without ever executing the
> service method on the servlet mapped to the url.
I've seen all sorts of odd behaviors when something is expecting HTTP
but doesn't get it.
> The inbound request to tomcat is correct, and it is sometimes
> handled correctly. However, much of the time it is sending the empty 200.
Given that there appears to be multiple issues here, I'd suggest
concentrating on the one that is likely easiest to debug. Fix that and
then see what the other problems then look like. We might be seeing two
sides of the same issue.
My recommendation is:
- if possible, test without the F5 just to be sure this is purely a
Tomcat issue
- investigate the repeated calls to service() with no incoming request
as that is likely to be easier to debug. As per my previous suggestion,
get Tomcat into this state and then use remote debugging to see what is
calling NioEndpoint.processSocket()
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Odd NIO connector behavior
Posted by Matthew Tyson <ma...@gmail.com>.
On Wed, Dec 28, 2011 at 1:04 AM, <ma...@apache.org> wrote:
> Matthew Tyson <ma...@gmail.com> wrote:
>
> >That's right, there is an f5 load balancer. The valve is used to keep
> >track of whether the request was via HTTPS or not.
>
> What happens if you go direct to Tomcat and bypass the F5?
>
> >tcpdump seems to confirm the same. What are you thinking?
>
> Probably, like me, that the F5 isn't handling the Comet requests correctly.
>
> Mark
>
>
I am trying to understand how the load balancer could cause Tomcat to
respond with an empty 200 response to a request, without ever executing the
service method on the servlet mapped to the url. That just doesn't seem
possible. The inbound request to tomcat is correct, and it is sometimes
handled correctly. However, much of the time it is sending the empty 200.
Matt Tyson
Re: Odd NIO connector behavior
Posted by Pid <pi...@pidster.com>.
On 29/12/2011 19:22, Matthew Tyson wrote:
> On Thu, Dec 29, 2011 at 11:07 AM, Pid <pi...@pidster.com> wrote:
>
>> On 29/12/2011 17:27, Matthew Tyson wrote:
>>> On Wed, Dec 28, 2011 at 6:22 PM, Matthew Tyson
>>> <ma...@gmail.com>wrote:
>>>
>>>> On Wed, Dec 28, 2011 at 8:58 AM, Stefan Mayr <stefan@mayr-stefan.de
>>> wrote:
>>>>
>>>>> Am 28.12.2011 10:04, schrieb markt@apache.org:
>>>>>
>>>>> Matthew Tyson<matthewcarltyson@gmail.**com <
>> matthewcarltyson@gmail.com>>
>>>>>> wrote:
>>>>>>
>>>>>> That's right, there is an f5 load balancer. The valve is used to
>> keep
>>>>>>> track of whether the request was via HTTPS or not.
>>>>>>>
>>>>>>
>>>>>> What happens if you go direct to Tomcat and bypass the F5?
>>>>>>
>>>>>> tcpdump seems to confirm the same. What are you thinking?
>>>>>>>
>>>>>>
>>>>>> Probably, like me, that the F5 isn't handling the Comet requests
>>>>>> correctly.
>>>>>>
>>>>>
>>>>> This is what I would guess. We have a loadbalancing device that
>> handles n
>>>>> client-lb connections with m lb-server connections in its HTTP mode.
>> There
>>>>> we have to switch to TCP proxy mode to keep 1:1 relations.
>>>>>
>>>>> Your F5 is where to do start crosschecking with tcpdump: client <-> F5
>> vs
>>>>> F5 <-> server
>>>>>
>>>>> Stefan
>>>>>
>>>>>
>>>> You think its possible that multiplexing or some load-balancer config
>>>> would cause the two observed issues:
>>>>
>>>> 1) When the custom valve is in use, zombie service() executions continue
>>>> with no actual inbound requests
>>>> 2) Inbound requests are being replied to with blank 200s, without ever
>>>> executing the service method.
>>>>
>>>> Thanks,
>>>>
>>>> Matt Tyson
>>>>
>>>>
>>> I think maybe I wasn't clear before. I am running ngrep on the server,
>>> inside the f5.
>>>
>>> F5 <-> ngrep <-> tomcat
>>>
>>> So the behavior I am seeing is inbound traffic from the F5 to Tomcat,
>> then
>>> outbound traffic from Tomcat (empty 200s that don't execute the servlet
>>> service) back to the F5. It seems very unlikely that F5 configuration is
>>> the cause there.
>>
>> Can you post the CometdServlet code?
>>
>>
>> p
>>
>>
> Here is the code from the service method, it is basically from the
> cometd.org project, with some added logging. There's obviously quite a bit
> more involved in how cometd processes things, but in this case, the servlet
> itself is very simple. How an empty 200 response could be generated
> without executing the logging statement here is a mystery.
Can you make a minimal test that reproduces the problem?
Is it reproducible with Tomcat's own Comet support?
E.g.
http://svn.apache.org/repos/asf/tomcat/trunk/test/org/apache/catalina/comet/TestCometProcessor.java
p
> protected void service(HttpServletRequest request, HttpServletResponse
> response) throws ServletException, IOException
> {
> logger.info("REQUEST: " + request.getRemoteAddr() + " " +
> request.getMethod() + " " + request.getQueryString() + " | TRACE: ", new
> Throwable());
>
> if ("OPTIONS".equals(request.getMethod()))
> {
> serviceOptions(request, response);
> return;
> }
>
> HttpTransport transport = null;
> List<String> allowedTransports = _bayeux.getAllowedTransports();
> for (String transportName : allowedTransports)
> {
> ServerTransport serverTransport =
> _bayeux.getTransport(transportName);
> if (serverTransport instanceof HttpTransport)
> {
> HttpTransport t = (HttpTransport)serverTransport;
> if (t.accept(request))
> {
> transport = t;
> logger.info("ACCEPTED: " + request.getRemoteAddr() + "
> " + t.getClass().getName());
> break;
> } else {
> logger.info("NOT ACCEPTED: " + request.getRemoteAddr() + "
> " + t.getClass().getName());
> }
> }
> }
>
> if (transport == null)
> {
> if (!response.isCommitted()) {
> response.sendError(HttpServletResponse.SC_BAD_REQUEST, "Unknown
> Bayeux Transport");
> } else {
> logger.info("NULL TRANSPORT: " + request.getRemoteAddr());
> }
> }
> else
> {
> try
> {
> _bayeux.setCurrentTransport(transport);
> transport.setCurrentRequest(request);
> transport.handle(request, response);
> }
> finally
> {
> transport.setCurrentRequest(null);
> BayeuxServerImpl bayeux = _bayeux;
> if (bayeux != null)
> bayeux.setCurrentTransport(null);
> }
> }
> }
>
> Best,
>
> Matt Tyson
>
--
[key:62590808]
Re: Odd NIO connector behavior
Posted by Matthew Tyson <ma...@gmail.com>.
On Thu, Dec 29, 2011 at 12:02 PM, Tim Watts <ti...@cliftonfarm.org> wrote:
> On Thu, 2011-12-29 at 11:22 -0800, Matthew Tyson wrote:
>
> <BIG SNIP>
>
> > How an empty 200 response could be generated
> > without executing the logging statement here is a mystery.
> >
>
> Do you still have that MonitoringFilter configured in the web app?
> Perhaps it is short circuiting the chain.
>
>
I've been running tests without the filter in place - unfortunately, same
results. Empty 200s from tomcat for many requests.
Thanks,
Matt Tyson
Re: Odd NIO connector behavior
Posted by Tim Watts <ti...@cliftonfarm.org>.
On Thu, 2011-12-29 at 11:22 -0800, Matthew Tyson wrote:
<BIG SNIP>
> How an empty 200 response could be generated
> without executing the logging statement here is a mystery.
>
Do you still have that MonitoringFilter configured in the web app?
Perhaps it is short circuiting the chain.
> protected void service(HttpServletRequest request, HttpServletResponse
> response) throws ServletException, IOException
> {
> logger.info("REQUEST: " + request.getRemoteAddr() + " " +
> request.getMethod() + " " + request.getQueryString() + " | TRACE: ", new
> Throwable());
>
> if ("OPTIONS".equals(request.getMethod()))
> {
> serviceOptions(request, response);
> return;
> }
>
> HttpTransport transport = null;
> List<String> allowedTransports = _bayeux.getAllowedTransports();
> for (String transportName : allowedTransports)
> {
> ServerTransport serverTransport =
> _bayeux.getTransport(transportName);
> if (serverTransport instanceof HttpTransport)
> {
> HttpTransport t = (HttpTransport)serverTransport;
> if (t.accept(request))
> {
> transport = t;
> logger.info("ACCEPTED: " + request.getRemoteAddr() + "
> " + t.getClass().getName());
> break;
> } else {
> logger.info("NOT ACCEPTED: " + request.getRemoteAddr() + "
> " + t.getClass().getName());
> }
> }
> }
>
> if (transport == null)
> {
> if (!response.isCommitted()) {
> response.sendError(HttpServletResponse.SC_BAD_REQUEST, "Unknown
> Bayeux Transport");
> } else {
> logger.info("NULL TRANSPORT: " + request.getRemoteAddr());
> }
> }
> else
> {
> try
> {
> _bayeux.setCurrentTransport(transport);
> transport.setCurrentRequest(request);
> transport.handle(request, response);
> }
> finally
> {
> transport.setCurrentRequest(null);
> BayeuxServerImpl bayeux = _bayeux;
> if (bayeux != null)
> bayeux.setCurrentTransport(null);
> }
> }
> }
>
> Best,
>
> Matt Tyson
Re: Odd NIO connector behavior
Posted by Matthew Tyson <ma...@gmail.com>.
On Thu, Dec 29, 2011 at 11:07 AM, Pid <pi...@pidster.com> wrote:
> On 29/12/2011 17:27, Matthew Tyson wrote:
> > On Wed, Dec 28, 2011 at 6:22 PM, Matthew Tyson
> > <ma...@gmail.com>wrote:
> >
> >> On Wed, Dec 28, 2011 at 8:58 AM, Stefan Mayr <stefan@mayr-stefan.de
> >wrote:
> >>
> >>> Am 28.12.2011 10:04, schrieb markt@apache.org:
> >>>
> >>> Matthew Tyson<matthewcarltyson@gmail.**com <
> matthewcarltyson@gmail.com>>
> >>>> wrote:
> >>>>
> >>>> That's right, there is an f5 load balancer. The valve is used to
> keep
> >>>>> track of whether the request was via HTTPS or not.
> >>>>>
> >>>>
> >>>> What happens if you go direct to Tomcat and bypass the F5?
> >>>>
> >>>> tcpdump seems to confirm the same. What are you thinking?
> >>>>>
> >>>>
> >>>> Probably, like me, that the F5 isn't handling the Comet requests
> >>>> correctly.
> >>>>
> >>>
> >>> This is what I would guess. We have a loadbalancing device that
> handles n
> >>> client-lb connections with m lb-server connections in its HTTP mode.
> There
> >>> we have to switch to TCP proxy mode to keep 1:1 relations.
> >>>
> >>> Your F5 is where to do start crosschecking with tcpdump: client <-> F5
> vs
> >>> F5 <-> server
> >>>
> >>> Stefan
> >>>
> >>>
> >> You think its possible that multiplexing or some load-balancer config
> >> would cause the two observed issues:
> >>
> >> 1) When the custom valve is in use, zombie service() executions continue
> >> with no actual inbound requests
> >> 2) Inbound requests are being replied to with blank 200s, without ever
> >> executing the service method.
> >>
> >> Thanks,
> >>
> >> Matt Tyson
> >>
> >>
> > I think maybe I wasn't clear before. I am running ngrep on the server,
> > inside the f5.
> >
> > F5 <-> ngrep <-> tomcat
> >
> > So the behavior I am seeing is inbound traffic from the F5 to Tomcat,
> then
> > outbound traffic from Tomcat (empty 200s that don't execute the servlet
> > service) back to the F5. It seems very unlikely that F5 configuration is
> > the cause there.
>
> Can you post the CometdServlet code?
>
>
> p
>
>
Here is the code from the service method, it is basically from the
cometd.org project, with some added logging. There's obviously quite a bit
more involved in how cometd processes things, but in this case, the servlet
itself is very simple. How an empty 200 response could be generated
without executing the logging statement here is a mystery.
protected void service(HttpServletRequest request, HttpServletResponse
response) throws ServletException, IOException
{
logger.info("REQUEST: " + request.getRemoteAddr() + " " +
request.getMethod() + " " + request.getQueryString() + " | TRACE: ", new
Throwable());
if ("OPTIONS".equals(request.getMethod()))
{
serviceOptions(request, response);
return;
}
HttpTransport transport = null;
List<String> allowedTransports = _bayeux.getAllowedTransports();
for (String transportName : allowedTransports)
{
ServerTransport serverTransport =
_bayeux.getTransport(transportName);
if (serverTransport instanceof HttpTransport)
{
HttpTransport t = (HttpTransport)serverTransport;
if (t.accept(request))
{
transport = t;
logger.info("ACCEPTED: " + request.getRemoteAddr() + "
" + t.getClass().getName());
break;
} else {
logger.info("NOT ACCEPTED: " + request.getRemoteAddr() + "
" + t.getClass().getName());
}
}
}
if (transport == null)
{
if (!response.isCommitted()) {
response.sendError(HttpServletResponse.SC_BAD_REQUEST, "Unknown
Bayeux Transport");
} else {
logger.info("NULL TRANSPORT: " + request.getRemoteAddr());
}
}
else
{
try
{
_bayeux.setCurrentTransport(transport);
transport.setCurrentRequest(request);
transport.handle(request, response);
}
finally
{
transport.setCurrentRequest(null);
BayeuxServerImpl bayeux = _bayeux;
if (bayeux != null)
bayeux.setCurrentTransport(null);
}
}
}
Best,
Matt Tyson
Re: Odd NIO connector behavior
Posted by Pid <pi...@pidster.com>.
On 29/12/2011 17:27, Matthew Tyson wrote:
> On Wed, Dec 28, 2011 at 6:22 PM, Matthew Tyson
> <ma...@gmail.com>wrote:
>
>> On Wed, Dec 28, 2011 at 8:58 AM, Stefan Mayr <st...@mayr-stefan.de>wrote:
>>
>>> Am 28.12.2011 10:04, schrieb markt@apache.org:
>>>
>>> Matthew Tyson<matthewcarltyson@gmail.**com <ma...@gmail.com>>
>>>> wrote:
>>>>
>>>> That's right, there is an f5 load balancer. The valve is used to keep
>>>>> track of whether the request was via HTTPS or not.
>>>>>
>>>>
>>>> What happens if you go direct to Tomcat and bypass the F5?
>>>>
>>>> tcpdump seems to confirm the same. What are you thinking?
>>>>>
>>>>
>>>> Probably, like me, that the F5 isn't handling the Comet requests
>>>> correctly.
>>>>
>>>
>>> This is what I would guess. We have a loadbalancing device that handles n
>>> client-lb connections with m lb-server connections in its HTTP mode. There
>>> we have to switch to TCP proxy mode to keep 1:1 relations.
>>>
>>> Your F5 is where to do start crosschecking with tcpdump: client <-> F5 vs
>>> F5 <-> server
>>>
>>> Stefan
>>>
>>>
>> You think its possible that multiplexing or some load-balancer config
>> would cause the two observed issues:
>>
>> 1) When the custom valve is in use, zombie service() executions continue
>> with no actual inbound requests
>> 2) Inbound requests are being replied to with blank 200s, without ever
>> executing the service method.
>>
>> Thanks,
>>
>> Matt Tyson
>>
>>
> I think maybe I wasn't clear before. I am running ngrep on the server,
> inside the f5.
>
> F5 <-> ngrep <-> tomcat
>
> So the behavior I am seeing is inbound traffic from the F5 to Tomcat, then
> outbound traffic from Tomcat (empty 200s that don't execute the servlet
> service) back to the F5. It seems very unlikely that F5 configuration is
> the cause there.
Can you post the CometdServlet code?
p
--
[key:62590808]
Re: Odd NIO connector behavior
Posted by Matthew Tyson <ma...@gmail.com>.
On Wed, Dec 28, 2011 at 6:22 PM, Matthew Tyson
<ma...@gmail.com>wrote:
> On Wed, Dec 28, 2011 at 8:58 AM, Stefan Mayr <st...@mayr-stefan.de>wrote:
>
>> Am 28.12.2011 10:04, schrieb markt@apache.org:
>>
>> Matthew Tyson<matthewcarltyson@gmail.**com <ma...@gmail.com>>
>>> wrote:
>>>
>>> That's right, there is an f5 load balancer. The valve is used to keep
>>>> track of whether the request was via HTTPS or not.
>>>>
>>>
>>> What happens if you go direct to Tomcat and bypass the F5?
>>>
>>> tcpdump seems to confirm the same. What are you thinking?
>>>>
>>>
>>> Probably, like me, that the F5 isn't handling the Comet requests
>>> correctly.
>>>
>>
>> This is what I would guess. We have a loadbalancing device that handles n
>> client-lb connections with m lb-server connections in its HTTP mode. There
>> we have to switch to TCP proxy mode to keep 1:1 relations.
>>
>> Your F5 is where to do start crosschecking with tcpdump: client <-> F5 vs
>> F5 <-> server
>>
>> Stefan
>>
>>
> You think its possible that multiplexing or some load-balancer config
> would cause the two observed issues:
>
> 1) When the custom valve is in use, zombie service() executions continue
> with no actual inbound requests
> 2) Inbound requests are being replied to with blank 200s, without ever
> executing the service method.
>
> Thanks,
>
> Matt Tyson
>
>
I think maybe I wasn't clear before. I am running ngrep on the server,
inside the f5.
F5 <-> ngrep <-> tomcat
So the behavior I am seeing is inbound traffic from the F5 to Tomcat, then
outbound traffic from Tomcat (empty 200s that don't execute the servlet
service) back to the F5. It seems very unlikely that F5 configuration is
the cause there.
Matt Tyson
Re: Odd NIO connector behavior
Posted by Matthew Tyson <ma...@gmail.com>.
On Wed, Dec 28, 2011 at 8:58 AM, Stefan Mayr <st...@mayr-stefan.de> wrote:
> Am 28.12.2011 10:04, schrieb markt@apache.org:
>
> Matthew Tyson<matthewcarltyson@gmail.**com <ma...@gmail.com>>
>> wrote:
>>
>> That's right, there is an f5 load balancer. The valve is used to keep
>>> track of whether the request was via HTTPS or not.
>>>
>>
>> What happens if you go direct to Tomcat and bypass the F5?
>>
>> tcpdump seems to confirm the same. What are you thinking?
>>>
>>
>> Probably, like me, that the F5 isn't handling the Comet requests
>> correctly.
>>
>
> This is what I would guess. We have a loadbalancing device that handles n
> client-lb connections with m lb-server connections in its HTTP mode. There
> we have to switch to TCP proxy mode to keep 1:1 relations.
>
> Your F5 is where to do start crosschecking with tcpdump: client <-> F5 vs
> F5 <-> server
>
> Stefan
>
>
You think its possible that multiplexing or some load-balancer config would
cause the two observed issues:
1) When the custom valve is in use, zombie service() executions continue
with no actual inbound requests
2) Inbound requests are being replied to with blank 200s, without ever
executing the service method.
Thanks,
Matt Tyson
Re: Odd NIO connector behavior
Posted by Stefan Mayr <st...@mayr-stefan.de>.
Am 28.12.2011 10:04, schrieb markt@apache.org:
> Matthew Tyson<ma...@gmail.com> wrote:
>
>> That's right, there is an f5 load balancer. The valve is used to keep
>> track of whether the request was via HTTPS or not.
>
> What happens if you go direct to Tomcat and bypass the F5?
>
>> tcpdump seems to confirm the same. What are you thinking?
>
> Probably, like me, that the F5 isn't handling the Comet requests correctly.
This is what I would guess. We have a loadbalancing device that handles
n client-lb connections with m lb-server connections in its HTTP mode.
There we have to switch to TCP proxy mode to keep 1:1 relations.
Your F5 is where to do start crosschecking with tcpdump: client <-> F5
vs F5 <-> server
Stefan
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Odd NIO connector behavior
Posted by ma...@apache.org.
Matthew Tyson <ma...@gmail.com> wrote:
>That's right, there is an f5 load balancer. The valve is used to keep
>track of whether the request was via HTTPS or not.
What happens if you go direct to Tomcat and bypass the F5?
>tcpdump seems to confirm the same. What are you thinking?
Probably, like me, that the F5 isn't handling the Comet requests correctly.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Odd NIO connector behavior
Posted by Matthew Tyson <ma...@gmail.com>.
On Tue, Dec 27, 2011 at 1:31 PM, Stefan Mayr <st...@mayr-stefan.de> wrote:
> Am 24.12.2011 00:39, schrieb Matthew Tyson:
>
> 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.
>>
>> The problems only crop up after a couple minutes under some load (modest
>> load, around 2-3 connections per second).
>>
>> 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).
>>
>> 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
>>
>> 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.
>> 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.
>>
>>
> Your Valves code makes me suspicious: the proxy port looks like there
> could be something between your client and your tomcat. A loadbalancer with
> some kind of TCP multiplexing maybe?
>
That's right, there is an f5 load balancer. The valve is used to keep
track of whether the request was via HTTPS or not.
>
> Have you already tried a tcpdump to crosscheck?
>
>
tcpdump seems to confirm the same. What are you thinking?
> Stefan
>
>
>
> ------------------------------**------------------------------**---------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.**apache.org<us...@tomcat.apache.org>
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
Thanks,
Matt Tyson
Re: Odd NIO connector behavior
Posted by Stefan Mayr <st...@mayr-stefan.de>.
Am 24.12.2011 00:39, schrieb Matthew Tyson:
> 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.
>
> The problems only crop up after a couple minutes under some load (modest
> load, around 2-3 connections per second).
>
> 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).
>
> 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
>
> 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.
> 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.
>
Your Valves code makes me suspicious: the proxy port looks like there
could be something between your client and your tomcat. A loadbalancer
with some kind of TCP multiplexing maybe?
Have you already tried a tcpdump to crosscheck?
Stefan
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org