Created attachment 29929 [details] Project for reproduction of bug I've recently observed a bug in Tomcat 7 that is causing our servers to fail to start-up, with the root cause being that, in response to a JMX request, Tomcat 7 is loading our servlet on a Thread whose contextClassLoader is NOT that of the web application. This may lead to various problems; in our case, it leads to failure of Spring to find the requisite XSDs that are present in jars in our web app's WEB-INF/lib directory. Here is the stack trace that is reported for Tomcat7.0.35 + Spring 3.1.1: org.springframework.beans.factory.parsing.BeanDefinitionParsingException: Configuration problem: Unable to locate Spring NamespaceHandler for XML schema namespace [http://www.springframework.org/schema/context] Offending resource: ServletContext resource [/WEB-INF/spring-servlet.xml] at org.springframework.beans.factory.parsing.FailFastProblemReporter.error(FailFastProblemReporter.java:68) at org.springframework.beans.factory.parsing.ReaderContext.error(ReaderContext.java:85) at org.springframework.beans.factory.parsing.ReaderContext.error(ReaderContext.java:80) at org.springframework.beans.factory.xml.BeanDefinitionParserDelegate.error(BeanDefinitionParserDelegate.java:316) at org.springframework.beans.factory.xml.BeanDefinitionParserDelegate.parseCustomElement(BeanDefinitionParserDelegate.java:1416) at org.springframework.beans.factory.xml.BeanDefinitionParserDelegate.parseCustomElement(BeanDefinitionParserDelegate.java:1409) at org.springframework.beans.factory.xml.DefaultBeanDefinitionDocumentReader.parseBeanDefinitions(DefaultBeanDefinitionDocumentReader.java:184) at org.springframework.beans.factory.xml.DefaultBeanDefinitionDocumentReader.doRegisterBeanDefinitions(DefaultBeanDefinitionDocumentReader.java:140) at org.springframework.beans.factory.xml.DefaultBeanDefinitionDocumentReader.registerBeanDefinitions(DefaultBeanDefinitionDocumentReader.java:111) at org.springframework.beans.factory.xml.XmlBeanDefinitionReader.registerBeanDefinitions(XmlBeanDefinitionReader.java:493) at org.springframework.beans.factory.xml.XmlBeanDefinitionReader.doLoadBeanDefinitions(XmlBeanDefinitionReader.java:390) at org.springframework.beans.factory.xml.XmlBeanDefinitionReader.loadBeanDefinitions(XmlBeanDefinitionReader.java:334) at org.springframework.beans.factory.xml.XmlBeanDefinitionReader.loadBeanDefinitions(XmlBeanDefinitionReader.java:302) at org.springframework.beans.factory.support.AbstractBeanDefinitionReader.loadBeanDefinitions(AbstractBeanDefinitionReader.java:174) at org.springframework.beans.factory.support.AbstractBeanDefinitionReader.loadBeanDefinitions(AbstractBeanDefinitionReader.java:209) at org.springframework.beans.factory.support.AbstractBeanDefinitionReader.loadBeanDefinitions(AbstractBeanDefinitionReader.java:180) at org.springframework.web.context.support.XmlWebApplicationContext.loadBeanDefinitions(XmlWebApplicationContext.java:125) at org.springframework.web.context.support.XmlWebApplicationContext.loadBeanDefinitions(XmlWebApplicationContext.java:94) at org.springframework.context.support.AbstractRefreshableApplicationContext.refreshBeanFactory(AbstractRefreshableApplicationContext.java:131) at org.springframework.context.support.AbstractApplicationContext.obtainFreshBeanFactory(AbstractApplicationContext.java:522) at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:436) at org.springframework.web.servlet.FrameworkServlet.configureAndRefreshWebApplicationContext(FrameworkServlet.java:631) at org.springframework.web.servlet.FrameworkServlet.createWebApplicationContext(FrameworkServlet.java:588) at org.springframework.web.servlet.FrameworkServlet.createWebApplicationContext(FrameworkServlet.java:645) at org.springframework.web.servlet.FrameworkServlet.initWebApplicationContext(FrameworkServlet.java:508) at org.springframework.web.servlet.FrameworkServlet.initServletBean(FrameworkServlet.java:449) at org.springframework.web.servlet.HttpServletBean.init(HttpServletBean.java:133) at javax.servlet.GenericServlet.init(GenericServlet.java:160) at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1274) at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1186) at org.apache.catalina.core.StandardWrapper.allocate(StandardWrapper.java:858) at org.apache.catalina.core.StandardWrapper.isSingleThreadModel(StandardWrapper.java:592) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.apache.tomcat.util.modeler.BaseModelMBean.getAttribute(BaseModelMBean.java:190) at org.apache.tomcat.util.modeler.BaseModelMBean.getAttributes(BaseModelMBean.java:234) at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.getAttributes(DefaultMBeanServerInterceptor.java:726) at com.sun.jmx.mbeanserver.JmxMBeanServer.getAttributes(JmxMBeanServer.java:665) at javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1408) at javax.management.remote.rmi.RMIConnectionImpl.access$200(RMIConnectionImpl.java:72) at javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1265) at javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1360) at javax.management.remote.rmi.RMIConnectionImpl.getAttributes(RMIConnectionImpl.java:636) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:303) at sun.rmi.transport.Transport$1.run(Transport.java:159) at java.security.AccessController.doPrivileged(Native Method) at sun.rmi.transport.Transport.serviceCall(Transport.java:155) at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649) 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:680) I've attached a simple Maven-based WAR project that can reproduce this -- see the README for exact steps. In this case, the exception will occur, but after the artificially imposed 30 second delay completes, the servlet appears to load fine. In our actual systems, the servlet appears to remain in an incompletely loaded state. My hypothesis is that this is timing-related... if StandardWrapper.allocate does not complete before the main thread that is loading the web application correctly, then I think the main thread adds a reference to the mis-loaded servlet, and the subsequent deallocate call in StandardWrapper.isSingleThreadModel does not unload the servlet, causing it to remain in its impaired state. Please investigate this bug, since it is likely to affect users combining Tomcat + Spring WebMVC + JMX monitoring, which I believe to be a common use case.
> Please investigate this bug, since it is likely to affect users combining > Tomcat + Spring WebMVC + JMX monitoring, which I believe to be a common use > case. Given that the code concerned hasn't changed in quite some time, if this were a common use case then you wouldn't be the first person to report it. There is no need to try and make a bug sound more important than it really is. Every bug report gets investigated and - currently - valid bugs are fixed for the next release which means for Tomcat 7 at most a 4-6 week wait for a binary release. Patches are usually available within a few days. This bug, for example, had a patch available in just over 12 hours. The patch has been applied to trunk and 7.0.x and will be included in 7.0.37 onwards.
Pardon my naivety in submitting a bug ticket -- I just wanted to clarify that the bug didn't require some exotic use case. Thanks for getting this fixed so quickly!
It seems like this bug still occur for Tomcat 8.0.20. As you can see on stacktrace below, during application start-up (thread [myApp-startStop-1]), another thread (thread [RMI TCP Connection(14)-172.17.14.64]) starts initializing app servlet. Should I report new bug for this issue? 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] Thread name: myApp-startStop-1.19 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] java.lang.Thread.getStackTrace(Thread.java:1567) 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] pl.my.MyContextLoaderListener.initWebApplicationContext(MyContextLoaderListener.java:30) 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:112) 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4728) 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5162) 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150) 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:725) 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:701) 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] org.apache.catalina.core.StandardHost.addChild(StandardHost.java:717) 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:917) 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1701) 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] java.util.concurrent.FutureTask.run(FutureTask.java:166) 2015-03-26 09:27:57,353 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) 2015-03-26 09:27:57,354 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) 2015-03-26 09:27:57,354 [myApp-startStop-1] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [CL] java.lang.Thread.run(Thread.java:722) 2015-03-26 09:30:23,419 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] Thread name: RMI TCP Connection(14)-172.17.14.64.436 2015-03-26 09:30:23,419 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] java.lang.Thread.getStackTrace(Thread.java:1567) 2015-03-26 09:30:23,419 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] pl.my.MyDispatcherServlet.initWebApplicationContext(MyDispatcherServlet.java:28) 2015-03-26 09:30:23,419 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] org.springframework.web.servlet.FrameworkServlet.initServletBean(FrameworkServlet.java:459) 2015-03-26 09:30:23,419 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] org.springframework.web.servlet.HttpServletBean.init(HttpServletBean.java:136) 2015-03-26 09:30:23,420 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] javax.servlet.GenericServlet.init(GenericServlet.java:158) 2015-03-26 09:30:23,420 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1231) 2015-03-26 09:30:23,420 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1144) 2015-03-26 09:30:23,420 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] org.apache.catalina.core.StandardWrapper.allocate(StandardWrapper.java:817) 2015-03-26 09:30:23,420 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] org.apache.catalina.core.StandardWrapper.isSingleThreadModel(StandardWrapper.java:559) 2015-03-26 09:30:23,420 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) 2015-03-26 09:30:23,420 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) 2015-03-26 09:30:23,420 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 2015-03-26 09:30:23,420 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] java.lang.reflect.Method.invoke(Method.java:601) 2015-03-26 09:30:23,420 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] org.apache.tomcat.util.modeler.BaseModelMBean.getAttribute(BaseModelMBean.java:189) 2015-03-26 09:30:23,420 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] org.apache.tomcat.util.modeler.BaseModelMBean.getAttributes(BaseModelMBean.java:233) 2015-03-26 09:30:23,420 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.getAttributes(DefaultMBeanServerInterceptor.java:709) 2015-03-26 09:30:23,420 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] com.sun.jmx.mbeanserver.JmxMBeanServer.getAttributes(JmxMBeanServer.java:695) 2015-03-26 09:30:23,420 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1428) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] javax.management.remote.rmi.RMIConnectionImpl.access$200(RMIConnectionImpl.java:89) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1292) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1380) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] javax.management.remote.rmi.RMIConnectionImpl.getAttributes(RMIConnectionImpl.java:657) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] sun.reflect.GeneratedMethodAccessor193.invoke(Unknown Source) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] java.lang.reflect.Method.invoke(Method.java:601) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:322) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] sun.rmi.transport.Transport$1.run(Transport.java:177) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] sun.rmi.transport.Transport$1.run(Transport.java:174) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] java.security.AccessController.doPrivileged(Native Method) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] sun.rmi.transport.Transport.serviceCall(Transport.java:173) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:553) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:808) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:667) 2015-03-26 09:30:23,421 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) 2015-03-26 09:30:23,422 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) 2015-03-26 09:30:23,422 [RMI TCP Connection(14)-172.17.14.64] INFO org.apache.catalina.core.ContainerBase.[Catalina-myApp].[myApp].[/]- [DS] java.lang.Thread.run(Thread.java:722)