Default FailFast configuration leading to intermittent failures in spring wiring

Mon Jul 25 16:31:53 EDT 2016

I agree that it doesn't seem possible, hence my appeals. I have been able to "fix" this issue by just changing random files and restarting basically, no caches invalided (that I know about anyways).

I added a debugger hook to BeanDefinitionValueResolver and printed out the name of the beans it is trying to load. What I discovered was our monitoring tool was querying the JMX bean exposed by tomcat before the rest of the spring universe is ready. When the jmx monitoring tries to load the "isSingleThreadModel" attribute it _causes_ the webapplication context to be constructed before the shibboleth spring stuff has finished loading. This means it is trying to get "flowRegistry, "flowBuilderServices","flowExecutor" before any of the shibboleth beans have been constructed. This appears to cache some beans that are misconfigured but then stored in the spring bean singleton map for the 

Why spring and tomcat allows a call to a JMX Bean to lazily create the application when the overall startup hasn't been completed is a mystery to me. We can't be the only company using tomcat and JMX to monitor it so I am surprised I couldn't google up any similar instances. Is there something unusual about the way shibboleth uses spring/springflow?

Looks like I found my problem and a workaround (don't query Catalina:j2eeType=Servlet,name=default,*). We had recently added more monitoring to all of the newly affected nodes; had I been thinking I might have noticed the correlation sooner.

Thanks Scott and Tom for your help.
Sam Hendley

Full stack included to help googlers in the future. Summary: Be careful if monitoring tomcat servers with JMX, it can cause these crazy issues.

"RMI TCP Connection(14)-10.22.3.72 at 3004" daemon prio=5 tid=0x19 nid=NA runnable
  java.lang.Thread.State: RUNNABLE
	  at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveReference(BeanDefinitionValueResolver.java:339)
	  at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveValueIfNecessary(BeanDefinitionValueResolver.java:108)
	  at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.applyPropertyValues(AbstractAutowireCapableBeanFactory.java:1481)
	  at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.populateBean(AbstractAutowireCapableBeanFactory.java:1226)
	  at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:543)
	  at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:482)
	  at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306)
	  at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
	  - locked <0x1062> (a java.util.concurrent.ConcurrentHashMap)
	  at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302)
	  at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197)
	  at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:772)
	  at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:838)
	  at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:537)
	  - locked <0x1063> (a java.lang.Object)
	  at org.springframework.web.servlet.FrameworkServlet.configureAndRefreshWebApplicationContext(FrameworkServlet.java:667)
	  at org.springframework.web.servlet.FrameworkServlet.createWebApplicationContext(FrameworkServlet.java:633)
	  at org.springframework.web.servlet.FrameworkServlet.createWebApplicationContext(FrameworkServlet.java:681)
	  at org.springframework.web.servlet.FrameworkServlet.initWebApplicationContext(FrameworkServlet.java:552)
	  at org.springframework.web.servlet.FrameworkServlet.initServletBean(FrameworkServlet.java:493)
	  at org.springframework.web.servlet.HttpServletBean.init(HttpServletBean.java:136)
	  at javax.servlet.GenericServlet.init(GenericServlet.java:158)
	  at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1238)
	  - locked <0x1017> (a org.apache.catalina.core.StandardWrapper)
	  at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1151)
	  at org.apache.catalina.core.StandardWrapper.allocate(StandardWrapper.java:828)
	  at org.apache.catalina.core.StandardWrapper.isSingleThreadModel(StandardWrapper.java:565)
	  at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
	  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	  at java.lang.reflect.Method.invoke(Method.java:498)
	  at org.apache.tomcat.util.modeler.BaseModelMBean.getAttribute(BaseModelMBean.java:189)
	  at org.apache.tomcat.util.modeler.BaseModelMBean.getAttributes(BaseModelMBean.java:233)
	  at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.getAttributes(DefaultMBeanServerInterceptor.java:709)
	  at com.sun.jmx.mbeanserver.JmxMBeanServer.getAttributes(JmxMBeanServer.java:705)
	  at javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1449)
	  at javax.management.remote.rmi.RMIConnectionImpl.access$300(RMIConnectionImpl.java:76)
	  at javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1309)
	  at javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1401)
	  at javax.management.remote.rmi.RMIConnectionImpl.getAttributes(RMIConnectionImpl.java:675)
	  at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
	  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	  at java.lang.reflect.Method.invoke(Method.java:498)
	  at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:324)
	  at sun.rmi.transport.Transport$1.run(Transport.java:200)
	  at sun.rmi.transport.Transport$1.run(Transport.java:197)
	  at java.security.AccessController.doPrivileged(AccessController.java:-1)
	  at sun.rmi.transport.Transport.serviceCall(Transport.java:196)
	  at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:568)
	  at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:826)
	  at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:683)
	  at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$1.783195622.run(Unknown Source:-1)
	  at java.security.AccessController.doPrivileged(AccessController.java:-1)
	  at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:682)
	  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	  at java.lang.Thread.run(Thread.java:745)

-----Original Message-----
From: users [mailto:users-bounces at shibboleth.net] On Behalf Of Cantor, Scott
Sent: Monday, July 25, 2016 2:26 PM
To: Shib Users
Subject: RE: Default FailFast configuration leading to intermittent failures in spring wiring

> We are using tomcat but this is a "single purpose" container that is 
> used only for shibboleth. Also this is a completely fresh install, 
> reverted down to base OS and reinstalled from scratch and this error 
> occurs on the first attempt after boot.

Then there's got to be an error in the files...

> What could be being cached that would cause this sort of spring wiring 
> issue? Is there possibly a race in the initial startup that then 
> populates some sort of cache that gets loaded from then on?

No. That's just not possible.

Where is the IdP configuration set coming from? Something has to be corrupting it if it's working and then not working.

> I am also not trying to restart it at any level other than the whole 
> tomcat server.

Just making sure, you said something about shutdown.

-- Scott

--
To unsubscribe from this list send an email to users-unsubscribe at shibboleth.net