Problem

1. Confluence uses Microsoft SQL Server.
2. Confluence cannot start after installing or upgrading some plugins or the newly installed/upgraded plugins are disabled upon startup. Known affected plugins:
   • Universal Plugin Manager (UPM)
   • Office Connector
   • SharePoint Connector
   • Scroll Office
   • RefinedWiki
   • (New) Code Macro
   • Table Plugin
   • Team Calendars for Confluence

3. The following appears in the atlassian-confluence.log:

   2011-02-28 14:49:29,366 ERROR [Thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.atlassian.confluence.extra.officeconnector, config=osgibundle:/META-INF/spring/*.xml) did not finish in 10000ms; consider taking a snapshot and then shutdown the VM in case the thread still hangs
   

   In context similar to:

   2011-02-28 14:49:19,366 INFO [Thread-1] [atlassian.plugin.manager.DefaultPluginManager] notifyPluginDisabled Disabling com.atlassian.confluence.extra.officeconnector
   2011-02-28 14:49:29,366 ERROR [Thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.atlassian.confluence.extra.officeconnector, config=osgibundle:/META-INF/spring/*.xml) did not finish in 10000ms; consider taking a snapshot and then shutdown the VM in case the thread still hangs
   2011-02-28 14:49:29,398 INFO [Thread-1] [atlassian.plugin.manager.DefaultPluginManager] notifyPluginDisabled Disabling com.atlassian.confluence.extra.sharepoint
   2011-02-28 14:49:39,398 ERROR [Thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.atlassian.confluence.extra.sharepoint, config=osgibundle:/META-INF/spring/*.xml) did not finish in 10000ms; consider taking a snapshot and then shutdown the VM in case the thread still hangs
   2011-02-28 14:49:39,398 ERROR [Thread-1] [atlassian.plugin.manager.PluginEnabler] enable Unable to start the following plugins due to timeout while waiting for plugin to enable: com.atlassian.confluence.extra.officeconnector,com.atlassian.confluence.extra.sharepoint
   2011-02-28 14:49:40,335 INFO [Thread-1] [atlassian.plugin.manager.DefaultPluginManager] init Plugin system started in 0:22:00.859
   2011-02-28 14:49:41,085 ERROR [Spring executor 7] [extender.internal.activator.ContextLoaderListener] onOsgiApplicationEvent Application context refresh failed (NonValidatingOsgiBundleXmlApplicationContext(bundle=com.atlassian.confluence.extra.officeconnector, config=osgibundle:/META-INF/spring/*.xml))
   java.lang.IllegalStateException: Invalid BundleContext.
   	at org.apache.felix.framework.BundleContextImpl.checkValidity(BundleContextImpl.java:366)
   	at org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:236)
   	at org.springframework.osgi.context.support.AbstractOsgiBundleApplicationContext.publishContextAsOsgiServiceIfNecessary(AbstractOsgiBundleApplicationContext.java:344)
   	at org.springframework.osgi.context.support.AbstractOsgiBundleApplicationContext.finishRefresh(AbstractOsgiBundleApplicationContext.java:237)
   	at org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext$4.run(AbstractDelegatedExecutionApplicationContext.java:358)
   	at org.springframework.osgi.util.internal.PrivilegedUtils.executeWithCustomTCCL(PrivilegedUtils.java:85)
   	at org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext.completeRefresh(AbstractDelegatedExecutionApplicationContext.java:320)
   	at org.springframework.osgi.extender.internal.dependencies.startup.DependencyWaiterApplicationContextExecutor$CompleteRefreshTask.run(DependencyWaiterApplicationContextExecutor.java:132)
   	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)
   2011-02-28 14:49:42,163 ERROR [Spring executor 6] [extender.internal.activator.ContextLoaderListener] onOsgiApplicationEvent Application context refresh failed (NonValidatingOsgiBundleXmlApplicationContext(bundle=com.atlassian.confluence.extra.sharepoint, config=osgibundle:/META-INF/spring/*.xml))
   java.lang.IllegalStateException: Invalid BundleContext.
   	at org.apache.felix.framework.BundleContextImpl.checkValidity(BundleContextImpl.java:366)
   	at org.apache.felix.framework.BundleContextImpl.registerService(BundleContextImpl.java:236)
   	at org.springframework.osgi.context.support.AbstractOsgiBundleApplicationContext.publishContextAsOsgiServiceIfNecessary(AbstractOsgiBundleApplicationContext.java:344)
   	at org.springframework.osgi.context.support.AbstractOsgiBundleApplicationContext.finishRefresh(AbstractOsgiBundleApplicationContext.java:237)
   	at org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext$4.run(AbstractDelegatedExecutionApplicationContext.java:358)
   	at org.springframework.osgi.util.internal.PrivilegedUtils.executeWithCustomTCCL(PrivilegedUtils.java:85)
   	at org.springframework.osgi.context.support.AbstractDelegatedExecutionApplicationContext.completeRefresh(AbstractDelegatedExecutionApplicationContext.java:320)
   	at org.springframework.osgi.extender.internal.dependencies.startup.DependencyWaiterApplicationContextExecutor$CompleteRefreshTask.run(DependencyWaiterApplicationContextExecutor.java:132)
   	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)

Diagnosis

Take thread dumps of the process every 30 seconds from start-up until after the timeout warnings. If they contain the following, then the Workaround should apply. If not, the thread-dumps should help diagnose the real problem.

"Spring executor 1" prio=6 tid=0x36810c00 nid=0xfb0 runnable [0x3851e000]
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:129)
	at java.io.DataInputStream.readFully(DataInputStream.java:178)
	at java.io.DataInputStream.readFully(DataInputStream.java:152)
	at net.sourceforge.jtds.jdbc.SharedSocket.readPacket(SharedSocket.java:841)
	at net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(SharedSocket.java:722)
	- locked <0x0465b108> (a java.util.ArrayList)
	at net.sourceforge.jtds.jdbc.ResponseStream.getPacket(ResponseStream.java:466)
	at net.sourceforge.jtds.jdbc.ResponseStream.read(ResponseStream.java:103)
	at net.sourceforge.jtds.jdbc.ResponseStream.peek(ResponseStream.java:88)
	at net.sourceforge.jtds.jdbc.TdsCore.wait(TdsCore.java:3928)
	at net.sourceforge.jtds.jdbc.TdsCore.executeSQL(TdsCore.java:1045)
	- locked <0x04660820> (a net.sourceforge.jtds.jdbc.TdsCore)
	at net.sourceforge.jtds.jdbc.JtdsStatement.executeSQLQuery(JtdsStatement.java:465)
	at net.sourceforge.jtds.jdbc.JtdsPreparedStatement.executeQuery(JtdsPreparedStatement.java:777)
	- locked <0x0465acf8> (a net.sourceforge.jtds.jdbc.ConnectionJDBC3)
	at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76)
	at net.sf.hibernate.impl.BatcherImpl.getResultSet(BatcherImpl.java:89)
	at net.sf.hibernate.loader.Loader.getResultSet(Loader.java:880)
	at net.sf.hibernate.loader.Loader.doQuery(Loader.java:273)
	at net.sf.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:138)
	at net.sf.hibernate.loader.Loader.doList(Loader.java:1063)
	at net.sf.hibernate.loader.Loader.list(Loader.java:1054)
	at net.sf.hibernate.hql.QueryTranslator.list(QueryTranslator.java:854)
	at net.sf.hibernate.impl.SessionImpl.find(SessionImpl.java:1552)
	at net.sf.hibernate.impl.QueryImpl.list(QueryImpl.java:49)
	at com.atlassian.confluence.setup.bandana.persistence.dao.hibernate.HibernateConfluenceBandanaRecordDao$1.doInHibernate(HibernateConfluenceBandanaRecordDao.java:53)
	at org.springframework.orm.hibernate.HibernateTemplate.execute(HibernateTemplate.java:370)
	at org.springframework.orm.hibernate.HibernateTemplate.execute(HibernateTemplate.java:337)
	at com.atlassian.confluence.setup.bandana.persistence.dao.hibernate.HibernateConfluenceBandanaRecordDao.getRecord(HibernateConfluenceBandanaRecordDao.java:45)
	at com.atlassian.confluence.setup.bandana.ConfluenceDaoBandanaPersister.retrieve(ConfluenceDaoBandanaPersister.java:30)
	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.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:304)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
	at $Proxy5.retrieve(Unknown Source)
	at com.atlassian.confluence.setup.bandana.ConfluenceCachingBandanaPersister.retrieve(ConfluenceCachingBandanaPersister.java:61)
	at com.atlassian.bandana.DefaultBandanaManager.getValue(DefaultBandanaManager.java:32)
	at com.atlassian.bandana.DefaultBandanaManager.getValue(DefaultBandanaManager.java:24)
	at sun.reflect.GeneratedMethodAccessor84.invoke(Unknown Source)

Cause

This problem happens when some of the plugins ended up waiting to get access to the BANDANA table. The problem is that Microsoft SQL Server is escalating row locks to table locks and thereby blocking access to the table and causing an effective deadlock. This bug is being tackled at CONFSERVER-21986 - Database deadlock during initialisation of plugins.

Workaround

Configure your database to use the recommended isolation level, which is Read Committed with Row Versioning. Please refer to the workaround listed in this KB article for instructions.

Resolution

1. Resolution 1:
   1. Upgrade to Confluence 3.5.9 or higher where CONFSERVER-21986 - Database deadlock during initialisation of plugins has been fixed.
2. Resolution 2:
   1. Add the JVM parameter -Datlassian.plugins.enable.wait=300. See Configuring System Properties for tips on how to set an environment variable.