Re: Odd NIO connector behavior
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 matthewcarlty...@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-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Odd NIO connector behavior
On 29/12/2011 19:22, Matthew Tyson wrote:
On Thu, Dec 29, 2011 at 11:07 AM, Pid p...@pidster.com wrote:
On 29/12/2011 17:27, Matthew Tyson wrote:
On Wed, Dec 28, 2011 at 6:22 PM, Matthew Tyson
matthewcarlty...@gmail.comwrote:
On Wed, Dec 28, 2011 at 8:58 AM, Stefan Mayr ste...@mayr-stefan.de
wrote:
Am 28.12.2011 10:04, schrieb ma...@apache.org:
Matthew Tysonmatthewcarltyson@gmail.**com
matthewcarlty...@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;
ListString 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]
signature.asc
Description: OpenPGP digital signature
Re: Odd NIO connector behavior
On Wed, Dec 28, 2011 at 1:04 AM, ma...@apache.org wrote: Matthew Tyson matthewcarlty...@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
On 31/12/2011 16:35, Matthew Tyson wrote: On Wed, Dec 28, 2011 at 1:04 AM, ma...@apache.org wrote: Matthew Tyson matthewcarlty...@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-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Odd NIO connector behavior
On Wed, Dec 28, 2011 at 6:22 PM, Matthew Tyson matthewcarlty...@gmail.comwrote: On Wed, Dec 28, 2011 at 8:58 AM, Stefan Mayr ste...@mayr-stefan.dewrote: Am 28.12.2011 10:04, schrieb ma...@apache.org: Matthew Tysonmatthewcarltyson@gmail.**com matthewcarlty...@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
On Thu, Dec 29, 2011 at 11:07 AM, Pid p...@pidster.com wrote:
On 29/12/2011 17:27, Matthew Tyson wrote:
On Wed, Dec 28, 2011 at 6:22 PM, Matthew Tyson
matthewcarlty...@gmail.comwrote:
On Wed, Dec 28, 2011 at 8:58 AM, Stefan Mayr ste...@mayr-stefan.de
wrote:
Am 28.12.2011 10:04, schrieb ma...@apache.org:
Matthew Tysonmatthewcarltyson@gmail.**com
matthewcarlty...@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;
ListString 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
On 29/12/2011 17:27, Matthew Tyson wrote: On Wed, Dec 28, 2011 at 6:22 PM, Matthew Tyson matthewcarlty...@gmail.comwrote: On Wed, Dec 28, 2011 at 8:58 AM, Stefan Mayr ste...@mayr-stefan.dewrote: Am 28.12.2011 10:04, schrieb ma...@apache.org: Matthew Tysonmatthewcarltyson@gmail.**com matthewcarlty...@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] signature.asc Description: OpenPGP digital signature
Re: Odd NIO connector behavior
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;
ListString 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
signature.asc
Description: This is a digitally signed message part
Re: Odd NIO connector behavior
On Thu, Dec 29, 2011 at 12:02 PM, Tim Watts t...@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
Matthew Tyson matthewcarlty...@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-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Odd NIO connector behavior
Am 28.12.2011 10:04, schrieb ma...@apache.org: Matthew Tysonmatthewcarlty...@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-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Odd NIO connector behavior
On Wed, Dec 28, 2011 at 8:58 AM, Stefan Mayr ste...@mayr-stefan.de wrote: Am 28.12.2011 10:04, schrieb ma...@apache.org: Matthew Tysonmatthewcarltyson@gmail.**com matthewcarlty...@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
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-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Odd NIO connector behavior
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-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@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
Re: Odd NIO connector behavior
On Tue, Dec 27, 2011 at 1:31 PM, Stefan Mayr ste...@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%5Djsonp= 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.orgusers-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org Thanks, Matt Tyson
Re: Odd NIO connector behavior
2011/12/25 Matthew Tyson matthewcarlty...@gmail.com: On Sat, Dec 24, 2011 at 10:33 AM, Matthew Tyson matthewcarlty...@gmail.comwrote: 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%5Djsonp=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
Re: Odd NIO connector behavior
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%5Djsonp=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-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Odd NIO connector behavior
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%5Djsonp=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
Re: Odd NIO connector behavior
Am 24.12.2011 19:33, schrieb Matthew Tyson: On Sat, Dec 24, 2011 at 1:06 AM, Mark Thomasma...@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%5Djsonp=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
Re: Odd NIO connector behavior
On Sat, Dec 24, 2011 at 10:33 AM, Matthew Tyson matthewcarlty...@gmail.comwrote: 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%5Djsonp=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)
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%5Djsonp=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
