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 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: single large tomcat or multiple tomcats
On Fri, Dec 30, 2011 at 11:57 AM, S Ahmed sahmed1...@gmail.com wrote: I know with other frameworks (like python/rails) people tend to run multiple instaces of the web server and round robin requests to each using something like haproxy. Is this known in the tomcat community at all? If I have a server with 16GB ram, would it make sense to run a few tomcat processes on different ports and use haproxy to round robin requests to each tomcat instance? I realize python/ruby do this because of their poor threading support. thanks! Take a look at: http://tomcat.apache.org/tomcat-7.0-doc/cluster-howto.html Tomcat has extensive clustering support. Best, Matt Tyson
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 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
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 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
/cometd/connect?message=%5B%7B%22channel%22
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
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 java.lang.Thread.run
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
Errors with NIO processor
Hey Guys, We are seeing the following errors (in production of course, testing didn't reveal this) after switching to NIO protocol. This is Tomcat 7.0.22 on CentOS 6. There is a load balancer sending only comet traffic to port 8080, where the NIO protocol is used. Nov 15, 2011 8:39:29 AM org.apache.tomcat.util.net.NioEndpoint processSocket SEVERE: Error allocating socket processor java.lang.NullPointerException Nov 15, 2011 8:39:51 AM org.apache.tomcat.util.net.NioEndpoint processSocket SEVERE: Error allocating socket processor java.lang.NullPointerException at org.apache.tomcat.util.net.NioEndpoint.processSocket(NioEndpoint.java:712) at org.apache.tomcat.util.net.NioEndpoint$Poller.processKey(NioEndpoint.java:1200) at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1136) at java.lang.Thread.run(Thread.java:662) Nov 15, 2011 8:39:52 AM org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process SEVERE: null java.lang.IllegalStateException: Calling [asyncPostProcess()] is not valid for a request with Async state [STARTED] at org.apache.coyote.AsyncStateMachine.asyncPostProcess(AsyncStateMachine.java:202) at org.apache.coyote.AbstractProcessor.asyncPostProcess(AbstractProcessor.java:104) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:519) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1550) 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) Exception in declaration() I see more of the Calling [asyncPostProcess()] is not valid for a request with Async state [STARTED] error by itself also. Here is the connector setup: Connector port=8080 protocol=org.apache.coyote.http11.Http11NioProtocol connectionTimeout=2 redirectPort=8443 / Any direction on where to look for the cause? Thanks, Matt
Re: Errors with NIO processor
Is there more info I can provide to help diagnose this error? It is killing us. Thanks, Matt On Tue, Nov 15, 2011 at 9:00 AM, Matthew Tyson matthewcarlty...@gmail.comwrote: Hey Guys, We are seeing the following errors (in production of course, testing didn't reveal this) after switching to NIO protocol. This is Tomcat 7.0.22 on CentOS 6. There is a load balancer sending only comet traffic to port 8080, where the NIO protocol is used. Nov 15, 2011 8:39:29 AM org.apache.tomcat.util.net.NioEndpoint processSocket SEVERE: Error allocating socket processor java.lang.NullPointerException Nov 15, 2011 8:39:51 AM org.apache.tomcat.util.net.NioEndpoint processSocket SEVERE: Error allocating socket processor java.lang.NullPointerException at org.apache.tomcat.util.net.NioEndpoint.processSocket(NioEndpoint.java:712) at org.apache.tomcat.util.net.NioEndpoint$Poller.processKey(NioEndpoint.java:1200) at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1136) at java.lang.Thread.run(Thread.java:662) Nov 15, 2011 8:39:52 AM org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process SEVERE: null java.lang.IllegalStateException: Calling [asyncPostProcess()] is not valid for a request with Async state [STARTED] at org.apache.coyote.AsyncStateMachine.asyncPostProcess(AsyncStateMachine.java:202) at org.apache.coyote.AbstractProcessor.asyncPostProcess(AbstractProcessor.java:104) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:519) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1550) 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) Exception in declaration() I see more of the Calling [asyncPostProcess()] is not valid for a request with Async state [STARTED] error by itself also. Here is the connector setup: Connector port=8080 protocol=org.apache.coyote.http11.Http11NioProtocol connectionTimeout=2 redirectPort=8443 / Any direction on where to look for the cause? Thanks, Matt
Re: Errors with NIO processor
Thanks Bob. It doesn't seem to be a load problem. It happens consistently even for just 1 user. If I switch the connector back to HTTP/1.1, instead of NIO, the problem goes away. Sometimes, there doesn't appear to be an error in catalina.out, but there is a response with no body, just headers like this: DateWed, 16 Nov 2011 00:43:58 GMT ServerApache-Coyote/1.1 Content-Typetext/html;charset=ISO-8859-1 Cache-Controlmax-age=2 ExpiresWed, 16 Nov 2011 00:44:00 GMT Set-Cookiexgh=gnweb10; path=/; BIGipCookie=00 000 000 VaryUser-Agent,Accept-Encoding P3P policyref=http://www.company.net/w3c/p3p.xmlhttp://www.gaggle.net/w3c/p3p.xml, CP=ALL Content-Encodinggzip Content-Length20 Connectionclose On Tue, Nov 15, 2011 at 4:51 PM, Bob Hall rfha...@yahoo.com wrote: Matt, Did the testing include load testing? Have you checked the open file limit values? If not, you may be running into an open file limit for the OS and/or user that is running Tomcat. - Bob From: Matthew Tyson matthewcarlty...@gmail.com To: Tomcat Users List users@tomcat.apache.org Sent: Tuesday, November 15, 2011 4:18 PM Subject: Re: Errors with NIO processor Is there more info I can provide to help diagnose this error? It is killing us. Thanks, Matt On Tue, Nov 15, 2011 at 9:00 AM, Matthew Tyson matthewcarlty...@gmail.comwrote: Hey Guys, We are seeing the following errors (in production of course, testing didn't reveal this) after switching to NIO protocol. This is Tomcat 7.0.22 on CentOS 6. There is a load balancer sending only comet traffic to port 8080, where the NIO protocol is used. Nov 15, 2011 8:39:29 AM org.apache.tomcat.util.net.NioEndpoint processSocket SEVERE: Error allocating socket processor java.lang.NullPointerException Nov 15, 2011 8:39:51 AM org.apache.tomcat.util.net.NioEndpoint processSocket SEVERE: Error allocating socket processor java.lang.NullPointerException at org.apache.tomcat.util.net.NioEndpoint.processSocket(NioEndpoint.java:712) at org.apache.tomcat.util.net.NioEndpoint$Poller.processKey(NioEndpoint.java:1200) at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:1136) at java.lang.Thread.run(Thread.java:662) Nov 15, 2011 8:39:52 AM org.apache.coyote.AbstractProtocol$AbstractConnectionHandler process SEVERE: null java.lang.IllegalStateException: Calling [asyncPostProcess()] is not valid for a request with Async state [STARTED] at org.apache.coyote.AsyncStateMachine.asyncPostProcess(AsyncStateMachine.java:202) at org.apache.coyote.AbstractProcessor.asyncPostProcess(AbstractProcessor.java:104) at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:519) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1550) 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) Exception in declaration() I see more of the Calling [asyncPostProcess()] is not valid for a request with Async state [STARTED] error by itself also. Here is the connector setup: Connector port=8080 protocol=org.apache.coyote.http11.Http11NioProtocol connectionTimeout=2 redirectPort=8443 / Any direction on where to look for the cause? Thanks, Matt
Re: Tomcat 7, Servlet 3.0, and Non-Blocking
That's very illuminating, thanks. I was looking at the table at the bottom of http://tomcat.apache.org/tomcat-7.0-doc/config/ajp.html#NIO_specific_configuration, and got the impression APR was blocking also, but now I see 'waiting for next request' is non-blocking in the TC7 table. Would you give us a sense of how using a non-blocking connector would be important when doing comet? Once startAsync is called, will the standard (blocking) connector continue to hold resources (where the NIO connectors won't)? Thanks, Matt On Wed, Nov 9, 2011 at 1:24 AM, ma...@apache.org wrote: Matthew Tyson matthewcarlty...@gmail.com wrote: I guess what I'm asking is if I just start using the Servlet 3.0 support for suspending requests out of the box, will it be a thread blocking implementation I'm using? That depends what you mean by thread blocking. Once startAsync has been called the thread that was processing the request/response is released to handle other requests regardless of connector. HTTP APR/native is blocking as well, correct? Wrong. You should read the docs, particularly the summary at the bottom of the HTTP connector configuration page So if I want to use Servlet 3.0 async (eg, a call to request.startAsync), and have it be handled without blocking IO, I need to use the NIO connector? Wrong again. All Servlet IO is blocking IO. If you look at the API you'll see that all read and write calls are blocking. You seem to be mixing up blocking and non-blocking IO with whether or not a thread is dedicated to processing a request/reponse pair for the life of the request/response. They are very different beasts. All connectors release the thread to handle other requests once startAsync has been called. As an aside, the non-blocking connectors will use non-blocking IO where they can but once you get to the Servlet API, that is always blocking IO. Mark - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Tomcat 7, Servlet 3.0, and Non-Blocking
Hey Guys, It has been my assumption that Tomcat 7's comet implementation (ie, asyncSupported=true), will automatically use NIO processing. Is that not true? Do I need to set the connector to be org.apache.coyote.http11.Http11NioProtocol explicitly? Thanks, Matt
Re: Tomcat 7, Servlet 3.0, and Non-Blocking
I guess what I'm asking is if I just start using the Servlet 3.0 support for suspending requests out of the box, will it be a thread blocking implementation I'm using? HTTP APR/native is blocking as well, correct? So if I want to use Servlet 3.0 async (eg, a call to request.startAsync), and have it be handled without blocking IO, I need to use the NIO connector? Thanks, Matt On Tue, Nov 8, 2011 at 12:27 PM, Mark Thomas ma...@apache.org wrote: On 08/11/2011 20:15, Matthew Tyson wrote: Hey Guys, It has been my assumption that Tomcat 7's comet implementation (ie, asyncSupported=true), will automatically use NIO processing. Comet != Servlet 3.0 async Is that not true? Yes, that is not true. Do I need to set the connector to be org.apache.coyote.http11.Http11NioProtocol explicitly? If you want to use Comet you'll need to use HTTP NIO or HTTP APR/native. Servlet 3.0 async works with any connector. Mark - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Servlet 3.0 Specific Error: Invalid byte tag in constant pool
Adding that to the skip list definitely prevented that error, but I'm getting many jars with the same problem. I thought I could maybe get away with just skipping them all, but I'm starting to see some jars that have taglibs in them (and so need to be scanned). All these jars are giving the same error: ,asm.jar,jboss-cache.jar,backport-util-concurrent.jar,struts-tiles-1.3.5.jar,shared-ldap-0.9.5.5.jar,jniwrap-3.6.jar,org.osgi.core-4.1.0.jar,fontbox-1.6.0.jar,apacheds-server-jndi-1.0.2.jar,apacheds-protocol-ldap-1.0.2.jar,jetm-1.2.2.jar,gdata-contacts-meta-3.0.jar,standard.jar,xbean-spring-2.8.jar,custom_rhino.jar,apacheds-server-ssl-1.0.2.jar,poi-ooxml-schemas-3.8-beta2-20110408.jar,commons-cli-1.2.jar,gdata-contacts-3.0.jar,webservices-rt.jar,iText-2.1.7.jar,javassist-3.9.0.GA.jar,mime-util-2.1.3.jar,jcaptcha-all-1.0-RC3.jar,ical4j-1.0-rc3-SNAPSHOT.jar,tomcat-jdbc.jar,dnsns.jar,jcharset.jar,pager-taglib.jar Any ideas? Thanks, Matt On Wed, Jul 20, 2011 at 12:21 AM, Mark Thomas ma...@apache.org wrote: On 20/07/2011 03:55, Matthew Tyson wrote: Hey guys, tomcat 7.0.19 Java 1.6.0_22 CentOS 5.6 I just switched the web.xml to servlet 3.0 (from a app running servlet 2.4 previously without issue) and now I'm seeing the following error (turned on fine logging in the util class): FINE: Scanning JAR [file:/usr/java/jdk1.6.0_22/jre/lib/ext/jcharset.jar] from classpath Jul 19, 2011 10:04:40 AM org.apache.catalina.startup.HostConfig deployDirectory SEVERE: Error deploying web application directory ROOT org.apache.tomcat.util.bcel.classfile.ClassFormatException: Invalid byte tag in constant pool: 60 That might be a BCEL bug or could be a corrupted JAR. Just add it to the jarsToSkip property in catalina.properties. Also, if you open a bugzilla issue, someone will take a closer look. Mark - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Servlet 3.0 Specific Error: Invalid byte tag in constant pool
java -version: java version 1.6.0_26 Java(TM) SE Runtime Environment (build 1.6.0_26-b03) Java HotSpot(TM) Server VM (build 20.1-b02, mixed mode) We just upgraded it from 1.6.0_22 to see if it would address this problem (it didn't). 1. Are you using Tomcat downloaded from tomcat.apache.org? Yes. 3. Maybe if you enable debug logging in org.apache.tomcat.util.bcel you will able to provide some context where the issue happens? Did that - its actually how I got the name of the files failing. Thanks for taking a look. Matt On Wed, Jul 20, 2011 at 11:43 AM, Konstantin Kolinko knst.koli...@gmail.com wrote: 2011/7/20 Matthew Tyson matthewcarlty...@gmail.com: Adding that to the skip list definitely prevented that error, but I'm getting many jars with the same problem. I thought I could maybe get away with just skipping them all, but I'm starting to see some jars that have taglibs in them (and so need to be scanned). All these jars are giving the same error: 2. Where that JDK 1.6.0_22 is from? What is shown by `java -version`? 3. Maybe if you enable debug logging in org.apache.tomcat.util.bcel you will able to provide some context where the issue happens? Best regards, Konstantin Kolinko - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Servlet 3.0 Specific Error: Invalid byte tag in constant pool
Konstantin, I may have to give the debugger a try - thanks for the info. Matt On Wed, Jul 20, 2011 at 1:02 PM, Konstantin Kolinko knst.koli...@gmail.comwrote: org.apache.tomcat.util.bcel.classfile.ClassFormatException: Invalid byte tag in constant pool: 60 The above message is created by o.a.tomcat.util.bcel.classfile.Constant#readConstant(...). There is a switch() and default: label results in this exception being thrown. Expected values there are from 1 to 12. Your 60 is far outside the range. 2011/7/21 Matthew Tyson matthewcarlty...@gmail.com: 3. Maybe if you enable debug logging in org.apache.tomcat.util.bcel you will able to provide some context where the issue happens? Did that - its actually how I got the name of the files failing. I hoped to see some information about what class files in those jars BCEL tries to scan when it fails. Call hierarchy is bcel.classfile.Constant#readConstant(...) - bcel.classfile.ConstantPool#ConstantPool(stream) - bcel.classfile.ClassParser#readConstantPool() - bcel.classfile.parse() - o.a.catalina.startup.ContextConfig#processAnnotationsStream(stream, webxml) Unfortunately there is no debug printing in ContextConfig, and ClassParser operates on a stream and so does not know its context. Maybe you can run your copy of Tomcat with debugger, using remote debugging? http://wiki.apache.org/tomcat/FAQ/Developing#Debugging Best regards, Konstantin Kolinko - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Servlet 3.0 Specific Error: Invalid byte tag in constant pool
Hey guys, tomcat 7.0.19 Java 1.6.0_22 CentOS 5.6 I just switched the web.xml to servlet 3.0 (from a app running servlet 2.4 previously without issue) and now I'm seeing the following error (turned on fine logging in the util class): FINE: Scanning JAR [file:/usr/java/jdk1.6.0_22/jre/lib/ext/jcharset.jar] from classpath Jul 19, 2011 10:04:40 AM org.apache.catalina.startup.HostConfig deployDirectory SEVERE: Error deploying web application directory ROOT org.apache.tomcat.util.bcel.classfile.ClassFormatException: Invalid byte tag in constant pool: 60 Thanks, Matt
