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 wrote: > On 31/12/2011 16:35, Matthew Tyson wrote: > > On Wed, Dec 28, 2011 at 1:04 AM, wrote: > > > >> Matthew Tyson 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, wrote: > Matthew Tyson 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 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 Thu, Dec 29, 2011 at 12:02 PM, Tim Watts wrote: > On Thu, 2011-12-29 at 11:22 -0800, Matthew Tyson wrote: > > > > > 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 Thu, Dec 29, 2011 at 11:07 AM, Pid wrote: > On 29/12/2011 17:27, Matthew Tyson wrote: > > On Wed, Dec 28, 2011 at 6:22 PM, Matthew Tyson > > wrote: > > > >> On Wed, Dec 28, 2011 at 8:58 AM, Stefan Mayr >wrote: > >> > >>> Am 28.12.2011 10:04, schrieb ma...@apache.org: > >>> > >>> 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. > >>>> > >>> > >>> This is what I would guess. We have a loadbalancing device that > handles n > >>> client-lb connections with m lb-server connections in its HTTP mode. > There > >>> we have to switch to TCP proxy mode to keep 1:1 relations. > >>> > >>> Your F5 is where to do start crosschecking with tcpdump: client <-> F5 > vs > >>> F5 <-> server > >>> > >>> Stefan > >>> > >>> > >> You think its possible that multiplexing or some load-balancer config > >> would cause the two observed issues: > >> > >> 1) When the custom valve is in use, zombie service() executions continue > >> with no actual inbound requests > >> 2) Inbound requests are being replied to with blank 200s, without ever > >> executing the service method. > >> > >> Thanks, > >> > >> Matt Tyson > >> > >> > > I think maybe I wasn't clear before. I am running ngrep on the server, > > inside the f5. > > > > F5 <-> ngrep <-> tomcat > > > > So the behavior I am seeing is inbound traffic from the F5 to Tomcat, > then > > outbound traffic from Tomcat (empty 200s that don't execute the servlet > > service) back to the F5. It seems very unlikely that F5 configuration is > > the cause there. > > Can you post the CometdServlet code? > > > p > > Here is the code from the service method, it is basically from the cometd.org project, with some added logging. There's obviously quite a bit more involved in how cometd processes things, but in this case, the servlet itself is very simple. How an empty 200 response could be generated without executing the logging statement here is a mystery. protected void service(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException { logger.info("REQUEST: " + request.getRemoteAddr() + " " + request.getMethod() + " " + request.getQueryString() + " | TRACE: ", new Throwable()); if ("OPTIONS".equals(request.getMethod())) { serviceOptions(request, response); return; } HttpTransport transport = null; List 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 Wed, Dec 28, 2011 at 6:22 PM, Matthew Tyson wrote: > On Wed, Dec 28, 2011 at 8:58 AM, Stefan Mayr wrote: > >> Am 28.12.2011 10:04, schrieb ma...@apache.org: >> >> Matthew Tyson> >>> 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 Wed, Dec 28, 2011 at 8:58 AM, Stefan Mayr wrote: > Am 28.12.2011 10:04, schrieb ma...@apache.org: > > Matthew Tyson> >> 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 1:31 PM, Stefan Mayr wrote: > Am 24.12.2011 00:39, schrieb Matthew Tyson: > > Hello, >> >> We have been having quite a few problems with using long-polling >> connections in Tomcat, via the NIO connector. Upgrading to Tomcat 7.0.23 >> definitely improved things, but we are still seeing major issues. >> >> The problems only crop up after a couple minutes under some load (modest >> load, around 2-3 connections per second). >> >> One very clear problem I am looking at right now is that the service >> method >> on a servlet is continually being called, although there is no traffic >> coming into tomcat from that remote IP (we verified this at the ethernet >> device). >> >> The logging statement at the beginning of the service method is being >> executed every so often, like so: >> >> logger.info("REQUEST: " + request.getRemoteAddr() + " " + >> request.getMethod() + " " + request.getQueryString()); >> >> INFO 2011-12-23 15:30:50,860 org.cometd.server.**CometdServlet REQUEST: >> 75.149.42.46 POST null >> INFO 2011-12-23 15:31:02,484 org.cometd.server.**CometdServlet REQUEST: >> 75.149.42.46 GET >> message=%5B%7B%22channel%22%**3A%22%2Fmeta%2Fconnect%22%2C%** >> 22connectionType%22%3A%**22callback-polling%22%2C%** >> 22advice%22%3A%7B%22timeout%**22%3A0%7D%2C%22id%22%3A%22354%** >> 22%2C%22clientId%22%3A%**222b611tiekwk6p2mfh5bye3bm6y7l**%22%7D%5D&jsonp= >> dojo.io.**script.jsonp_dojoIoScript135._**jsonpCallback >> INFO 2011-12-23 15:31:28,512 org.cometd.server.**CometdServlet REQUEST: >> 75.149.42.46 POST null >> INFO 2011-12-23 15:31:36,571 org.cometd.server.**CometdServlet REQUEST: >> 75.149.42.46 POST null >> >> But again, there is no traffic from that IP. I'm not sure if this is some >> sort of loop, a very long delay, or other connections being mixed up. >> Probably the last, since I don't see any loop pattern, and it has >> continued without any traffic for almost a half an hour now. >> >> > Your Valves code makes me suspicious: the proxy port looks like there > could be something between your client and your tomcat. A loadbalancer with > some kind of TCP multiplexing maybe? > That's right, there is an f5 load balancer. The valve is used to keep track of whether the request was via HTTPS or not. > > Have you already tried a tcpdump to crosscheck? > > tcpdump seems to confirm the same. What are you thinking? >Stefan > > > > --**--**- > To unsubscribe, e-mail: > users-unsubscribe@tomcat.**apache.org > For additional commands, e-mail: users-h...@tomcat.apache.org > > Thanks, Matt Tyson
Re: Odd NIO connector behavior
On Tue, Dec 27, 2011 at 11:11 AM, Mark Thomas 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
Re: Odd NIO connector behavior
On Sat, Dec 24, 2011 at 10:33 AM, Matthew Tyson wrote: > On Sat, Dec 24, 2011 at 1:06 AM, Mark Thomas wrote: > >> On 23/12/2011 23:39, Matthew Tyson wrote: >> > Hello, >> > >> > We have been having quite a few problems with using long-polling >> > connections in Tomcat, via the NIO connector. Upgrading to Tomcat >> 7.0.23 >> > definitely improved things, but we are still seeing major issues. >> >> Glad to hear things are getting better. No so glad to hear you are still >> having problems. >> >> > The problems only crop up after a couple minutes under some load (modest >> > load, around 2-3 connections per second). >> >> That's pretty low load. >> > > It is. We have just a small portion of connections routed to this server. > > >> >> > One very clear problem I am looking at right now is that the service >> method >> > on a servlet is continually being called, although there is no traffic >> > coming into tomcat from that remote IP (we verified this at the ethernet >> > device). >> >> Hmm. Very strange that the service method is being called. There needs >> to be a complete and valid set of HTTP headers for that to happen and >> the request/response gets recycled afterwards so the data shouldn't get >> processed twice. >> >> > It is very strange. > > >> > The logging statement at the beginning of the service method is being >> > executed every so often, like so: >> >> > logger.info("REQUEST: " + request.getRemoteAddr() + " " + >> > request.getMethod() + " " + request.getQueryString()); >> > >> > INFO 2011-12-23 15:30:50,860 org.cometd.server.CometdServlet REQUEST: >> > 75.149.42.46 POST null >> > INFO 2011-12-23 15:31:02,484 org.cometd.server.CometdServlet REQUEST: >> > 75.149.42.46 GET >> > >> >> message=%5B%7B%22channel%22%3A%22%2Fmeta%2Fconnect%22%2C%22connectionType%22%3A%22callback-polling%22%2C%22advice%22%3A%7B%22timeout%22%3A0%7D%2C%22id%22%3A%22354%22%2C%22clientId%22%3A%222b611tiekwk6p2mfh5bye3bm6y7l%22%7D%5D&jsonp=dojo.io.script.jsonp_dojoIoScript135._jsonpCallback >> > INFO 2011-12-23 15:31:28,512 org.cometd.server.CometdServlet REQUEST: >> > 75.149.42.46 POST null >> > INFO 2011-12-23 15:31:36,571 org.cometd.server.CometdServlet REQUEST: >> > 75.149.42.46 POST null >> >> Odd. So there are at least two different requests being processed here. >> >> > But again, there is no traffic from that IP. I'm not sure if this is >> some >> > sort of loop, a very long delay, or other connections being mixed up. >> >> I'm not aware of any connection mix up issues that might explain this. >> >> > Probably the last, since I don't see any loop pattern, and it has >> > continued without any traffic for almost a half an hour now. >> > >> > Thoughts? >> >> We need more information :) >> >> If you can create a simple web application that reproduces this I'd be >> happy to take a look. I suspect that is non-trivial so I'll suggest a >> couple of other options. >> >> 1. The simple thing is to add a stack trace to that log message so we >> can see exactly what code path is triggered this. >> >> > Here is a couple stack traces from this when the problem is occurring: > > INFO 2011-12-24 10:25:35,578 COMET REQUEST: 75.149.42.46 POST null | > TRACE: > java.lang.Throwable > at org.cometd.server.CometdServlet.service(CometdServlet.java:149) > at javax.servlet.http.HttpServlet.service(HttpServlet.java:722) > at > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305) > at > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) > at > com.company.util.filter.MonitoringFilter.doFilter(MonitoringFilter.java:47) > at > org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) > at > org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) > at > org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:224) > at > org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:169) > at > org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472) > at > org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168) >
Re: Odd NIO connector behavior
On Sat, Dec 24, 2011 at 1:06 AM, Mark Thomas wrote: > On 23/12/2011 23:39, Matthew Tyson wrote: > > Hello, > > > > We have been having quite a few problems with using long-polling > > connections in Tomcat, via the NIO connector. Upgrading to Tomcat 7.0.23 > > definitely improved things, but we are still seeing major issues. > > Glad to hear things are getting better. No so glad to hear you are still > having problems. > > > The problems only crop up after a couple minutes under some load (modest > > load, around 2-3 connections per second). > > That's pretty low load. > It is. We have just a small portion of connections routed to this server. > > > One very clear problem I am looking at right now is that the service > method > > on a servlet is continually being called, although there is no traffic > > coming into tomcat from that remote IP (we verified this at the ethernet > > device). > > Hmm. Very strange that the service method is being called. There needs > to be a complete and valid set of HTTP headers for that to happen and > the request/response gets recycled afterwards so the data shouldn't get > processed twice. > > It is very strange. > > The logging statement at the beginning of the service method is being > > executed every so often, like so: > > > logger.info("REQUEST: " + request.getRemoteAddr() + " " + > > request.getMethod() + " " + request.getQueryString()); > > > > INFO 2011-12-23 15:30:50,860 org.cometd.server.CometdServlet REQUEST: > > 75.149.42.46 POST null > > INFO 2011-12-23 15:31:02,484 org.cometd.server.CometdServlet REQUEST: > > 75.149.42.46 GET > > > > message=%5B%7B%22channel%22%3A%22%2Fmeta%2Fconnect%22%2C%22connectionType%22%3A%22callback-polling%22%2C%22advice%22%3A%7B%22timeout%22%3A0%7D%2C%22id%22%3A%22354%22%2C%22clientId%22%3A%222b611tiekwk6p2mfh5bye3bm6y7l%22%7D%5D&jsonp=dojo.io.script.jsonp_dojoIoScript135._jsonpCallback > > INFO 2011-12-23 15:31:28,512 org.cometd.server.CometdServlet REQUEST: > > 75.149.42.46 POST null > > INFO 2011-12-23 15:31:36,571 org.cometd.server.CometdServlet REQUEST: > > 75.149.42.46 POST null > > Odd. So there are at least two different requests being processed here. > > > But again, there is no traffic from that IP. I'm not sure if this is > some > > sort of loop, a very long delay, or other connections being mixed up. > > I'm not aware of any connection mix up issues that might explain this. > > > Probably the last, since I don't see any loop pattern, and it has > > continued without any traffic for almost a half an hour now. > > > > Thoughts? > > We need more information :) > > If you can create a simple web application that reproduces this I'd be > happy to take a look. I suspect that is non-trivial so I'll suggest a > couple of other options. > > 1. The simple thing is to add a stack trace to that log message so we > can see exactly what code path is triggered this. > > Here is a couple stack traces from this when the problem is occurring: INFO 2011-12-24 10:25:35,578 COMET REQUEST: 75.149.42.46 POST null | TRACE: java.lang.Throwable at org.cometd.server.CometdServlet.service(CometdServlet.java:149) at javax.servlet.http.HttpServlet.service(HttpServlet.java:722) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:305) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at com.company.util.filter.MonitoringFilter.doFilter(MonitoringFilter.java:47) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:243) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:210) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:224) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:169) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:168) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98) at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:928) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:118) at com.company.util.tomcat.SecureProxyValve.invoke(SecureProxyValve.java:57) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:407) at org.apache.coyote.http11.Ab
Odd NIO connector behavior
Hello, We have been having quite a few problems with using long-polling connections in Tomcat, via the NIO connector. Upgrading to Tomcat 7.0.23 definitely improved things, but we are still seeing major issues. The problems only crop up after a couple minutes under some load (modest load, around 2-3 connections per second). One very clear problem I am looking at right now is that the service method on a servlet is continually being called, although there is no traffic coming into tomcat from that remote IP (we verified this at the ethernet device). The logging statement at the beginning of the service method is being executed every so often, like so: logger.info("REQUEST: " + request.getRemoteAddr() + " " + request.getMethod() + " " + request.getQueryString()); INFO 2011-12-23 15:30:50,860 org.cometd.server.CometdServlet REQUEST: 75.149.42.46 POST null INFO 2011-12-23 15:31:02,484 org.cometd.server.CometdServlet REQUEST: 75.149.42.46 GET message=%5B%7B%22channel%22%3A%22%2Fmeta%2Fconnect%22%2C%22connectionType%22%3A%22callback-polling%22%2C%22advice%22%3A%7B%22timeout%22%3A0%7D%2C%22id%22%3A%22354%22%2C%22clientId%22%3A%222b611tiekwk6p2mfh5bye3bm6y7l%22%7D%5D&jsonp=dojo.io.script.jsonp_dojoIoScript135._jsonpCallback INFO 2011-12-23 15:31:28,512 org.cometd.server.CometdServlet REQUEST: 75.149.42.46 POST null INFO 2011-12-23 15:31:36,571 org.cometd.server.CometdServlet REQUEST: 75.149.42.46 POST null But again, there is no traffic from that IP. I'm not sure if this is some sort of loop, a very long delay, or other connections being mixed up. Probably the last, since I don't see any loop pattern, and it has continued without any traffic for almost a half an hour now. Thoughts? Regards, Matt Tyson
Re: 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.xml<http://www.gaggle.net/w3c/p3p.xml>, CP=ALL Content-Encodinggzip Content-Length20 Connectionclose On Tue, Nov 15, 2011 at 4:51 PM, Bob Hall 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 > To: Tomcat Users List > 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 > wrote: > > > 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: > > > > > 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 wrote: > 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: > > protocol="org.apache.coyote.http11.Http11NioProtocol" >connectionTimeout="2" >redirectPort="8443" /> > > Any direction on where to look for the cause? > > Thanks, > > Matt >
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: 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, wrote: > Matthew Tyson 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 > >
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 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 > >
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: 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 wrote: > > 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 : > >> 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 > >
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 wrote: > 2011/7/20 Matthew Tyson : > > 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
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 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 > >
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