Uploaded image for project: 'Confluence Data Center'
  1. Confluence Data Center
  2. CONFSERVER-21986

Database deadlock during initialisation of plugins

XMLWordPrintable

      This issue is also described in http://confluence.atlassian.com/display/CONFKB/Unable+to+Start+Confluence+or+Some+Plugins+are+Disabled+upon+Startup

      This issue can affect Confluence installed on SQL Server, Oracle, MySQL but most commonly affects SQL Server.

      Confluence may fail to start up due to database deadlocks in the Bandana table caused by multi-threaded spring context initialisation. What happens seems to be:

      • The main plugin-thread looks up the general state of the plugin system in bandana, thereby locking the whole bandana table
      • That thread spawns separate threads in separate transactions to initialise individual Spring contexts for plugins.
      • Some plugins try to look up their own settings in the bandana table during that initialisation but must wait for the main plugin-thread to release the lock.
      • Eventually the initalisation of the plugin times out like this: 
        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

      This can result in Confluence failing to be usable at all, or can result in just those plugins not working.

      Patch

      We strongly recommend upgrading to Confluence 3.5.9 or newer, which contains a proper fix for this issue. This unsupported patch has only been tested against Confluence 3.3 but should work for other versions up to 3.5.7 as well. If upgrading is not an option, you may follow these steps to patch your version of Confluence:

      First, shut down Confluence.

      Then, alter the Bandana table to do the following:

      • Remove duplicate rows.
      • Remove or update any rows with a null bandanacontext value
      • Remove or update any rows with a null bandanakey value
      • Alter the bandanacontext and bandanakey columns and set them to not null
      • Add a unique constraint to the bandana table on the bandanacontext and bandanakey columns
      • Drop the band_key_idx index
      • Create a new index called band_cont_key_idx on the bandanacontext and bandanakey columns

      If running PostgreSQL, you may run the following:

      -- Find duplicate rows, keep only one of each
SELECT b1.* 
FROM BANDANA b1, BANDANA b2 
WHERE b1.BANDANAID <> b2.BANDANAID AND 
b1.BANDANACONTEXT = b2.BANDANACONTEXT AND 
b1.BANDANAKEY = b2.BANDANAKEY 
ORDER BY b1.BANDANACONTEXT, b1.BANDANAKEY, b1.BANDANAID DESC
-- Remove null values
update BANDANA set BANDANACONTEXT = 'CONF22428-NULL-BACKUP' where BANDANACONTEXT is null;
update BANDANA set BANDANAKEY = 'CONF22428-NULL-BACKUP' where BANDANAKEY is null;
-- Add not null constraints
alter table BANDANA alter column BANDANACONTEXT set not null;
alter table BANDANA alter column BANDANAKEY set not null;
-- Add unique constraint
alter table BANDANA add constraint bandana_unique_key unique (BANDANACONTEXT, BANDANAKEY);
-- Optimise indexes
drop index band_key_idx;
create index band_cont_key_idx on BANDANA (BANDANACONTEXT, BANDANAKEY);
      Warning

      After altering the bandana table as mentioned above, you may have problems upgrading to Confluence 3.5.9 and 3.5.11. We recommend you upgrade to 3.5.12 or above instead.

      Next, extract the attached patch zip file to your confluence/WEB-INF/classes directory. Ensure that the following files are created:

      • com/atlassian/confluence/setup/bandana/persistence/dao/hibernate/HibernateConfluenceBandanaRecordDao$3.class
      • com/atlassian/confluence/setup/bandana/persistence/dao/hibernate/HibernateConfluenceBandanaRecordDao$2.class
      • com/atlassian/confluence/setup/bandana/persistence/dao/hibernate/HibernateConfluenceBandanaRecordDao.class
      • com/atlassian/confluence/setup/bandana/persistence/dao/hibernate/HibernateConfluenceBandanaRecordDao$1.class
      • com/atlassian/confluence/setup/bandana/ConfluenceCachingBandanaPersister.class
      • com/atlassian/confluence/setup/bandana/ConfluenceBandanaRecord.hbm.xml
      • com/atlassian/confluence/setup/bandana/ConfluenceCachingBandanaPersister$EmptyCachePlaceholder.class

      The patch is now applied and you can start Confluence again.

      Known workaround for SQL Server

      Setting the isolation level of the database as follows is known to fix the issue:

      ALTER DATABASE <database name>
   SET READ_COMMITTED_SNAPSHOT ON
   WITH ROLLBACK IMMEDIATE;

      It's possible there is another fix, such as making the plugin system close its transaction at some stage, or adding an index to the bandana table (since a lack of appropriate indices in sql server has given us similar issues before.

        1. CONF-22428_Bandana_contention_fix_Confluence_3_3.patch
          10 kB
        2. CONF-22428-Confluence-3.3-Patch.zip
          11 kB

            [CONFSERVER-21986] Database deadlock during initialisation of plugins

            Evy Lizárraga added a comment -

            The same is happening for our instance of Confluence at the Uof A. Here is a copy of our log errors when updating the plugin.

            2016-09-08 15:03:49,969 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=net.customware.confluence.plugin.box, 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
            – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette
            2016-09-08 15:04:00,318 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=net.customware.confluence.plugin.composition, 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
            – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette
            2016-09-08 15:04:10,544 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=net.customware.confluence.plugin.visibility, 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
            – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette
            2016-09-08 15:04:20,673 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.filtering.confluence, 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
            – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette
            2016-09-08 15:04:30,710 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.supplier.confluence, 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
            – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette
            2016-09-08 15:04:40,792 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.supplier.core, 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
            – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette
            2016-09-08 15:04:50,859 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.support.confluence, 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
            – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette
            2016-09-08 15:04:50,913 INFO [UpmAsynchronousTaskManager:thread-1] [atlassian.plugin.manager.DefaultPluginManager] addPlugins Found mandatory, optional and dynamically dependent plugins to re-enable after plugin upgrade 'org.randombits.support.support-core': [net.customware.confluence.plugin.box, net.customware.confluence.plugin.composition, net.customware.confluence.plugin.visibility, org.randombits.filtering.filtering-confluence, org.randombits.supplier.supplier-confluence, org.randombits.supplier.supplier-core, org.randombits.support.confluence]. Enabling...
            2016-09-08 15:04:50,914 INFO [UpmAsynchronousTaskManager:thread-1] [atlassian.plugin.manager.DefaultPluginManager] updatePlugin Updating plugin 'org.randombits.support.support-core' from version '1.5.0' to version '1.5.1'
            2016-09-08 15:04:50,914 INFO [UpmAsynchronousTaskManager:thread-1] [atlassian.plugin.manager.DefaultPluginManager] broadcastPluginDisabling Disabling org.randombits.support.support-core
            2016-09-08 15:05:00,946 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.support.core, 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
            – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette
            2016-09-08 15:05:12,438 WARN [UpmScheduler:thread-2] [atlassian.upm.pac.PacClientImpl] getUpdates Update check request may take longer because of the number of add-ons
            – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette

            Evy Lizárraga added a comment - The same is happening for our instance of Confluence at the Uof A. Here is a copy of our log errors when updating the plugin. 2016-09-08 15:03:49,969 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=net.customware.confluence.plugin.box, 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 – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette 2016-09-08 15:04:00,318 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=net.customware.confluence.plugin.composition, 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 – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette 2016-09-08 15:04:10,544 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=net.customware.confluence.plugin.visibility, 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 – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette 2016-09-08 15:04:20,673 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.filtering.confluence, 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 – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette 2016-09-08 15:04:30,710 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.supplier.confluence, 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 – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette 2016-09-08 15:04:40,792 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.supplier.core, 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 – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette 2016-09-08 15:04:50,859 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.support.confluence, 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 – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette 2016-09-08 15:04:50,913 INFO [UpmAsynchronousTaskManager:thread-1] [atlassian.plugin.manager.DefaultPluginManager] addPlugins Found mandatory, optional and dynamically dependent plugins to re-enable after plugin upgrade 'org.randombits.support.support-core': [net.customware.confluence.plugin.box, net.customware.confluence.plugin.composition, net.customware.confluence.plugin.visibility, org.randombits.filtering.filtering-confluence, org.randombits.supplier.supplier-confluence, org.randombits.supplier.supplier-core, org.randombits.support.confluence] . Enabling... 2016-09-08 15:04:50,914 INFO [UpmAsynchronousTaskManager:thread-1] [atlassian.plugin.manager.DefaultPluginManager] updatePlugin Updating plugin 'org.randombits.support.support-core' from version '1.5.0' to version '1.5.1' 2016-09-08 15:04:50,914 INFO [UpmAsynchronousTaskManager:thread-1] [atlassian.plugin.manager.DefaultPluginManager] broadcastPluginDisabling Disabling org.randombits.support.support-core 2016-09-08 15:05:00,946 ERROR [UpmAsynchronousTaskManager:thread-1] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.support.core, 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 – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette 2016-09-08 15:05:12,438 WARN [UpmScheduler:thread-2] [atlassian.upm.pac.PacClientImpl] getUpdates Update check request may take longer because of the number of add-ons – url: /rest/plugins/1.0/ | referer: https://plankton.uits.arizona.edu/plugins/servlet/upm | userName: yvette

            Abyakta Lenka added a comment -

            Hi Atlassian,

            I found this is confluence 4.3 as well. When we are trying to stop confluence its giving a similar log .i have to kill confluence process in our linux box .

            Here is the log snippet :

            .threaddump, 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
            2013-06-26 15:42:02,798 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.gliffy.plugin.confluence.gliffy-confluence-plugin, 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
            2013-06-26 15:42:12,800 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.adaptavist.confluence.subsection, 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
            2013-06-26 15:42:22,801 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.swift.confluence.table-sorter-plugin, 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
            2013-06-26 15:42:32,802 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.storage.servlet, 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
            2013-06-26 15:42:42,804 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.javahollic.confluence.confluencesu, 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
            2013-06-26 15:42:52,805 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.atlassian.support.stp, 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
            2013-06-26 15:43:02,806 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.confluence.conveyor, 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
            2013-06-26 15:43:12,807 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=nl.avisi.confluence.plugins.numberedheadings, 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
            2013-06-26 15:43:22,809 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=net.artemissoftware.plugins.conf.multiexcerpt4.multiexcerpt-conf-plugin-4, 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
            2013-06-26 15:43:32,810 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.storage.parameters, 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
            2013-06-26 15:43:42,811 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.swift.confluence.macro-security-plugin, 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
            2013-06-26 15:43:52,813 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.atlassian.confluence.extra.rsvp, 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
            2013-06-26 15:44:02,814 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.tngtech.confluence.plugins.umlgraph, 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
            2013-06-26 15:44:12,815 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.atlassian.plugins.search.opensearch-plugin, 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
            2013-06-26 15:44:22,817 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.atlassian.upm.plugin-license-storage-plugin, 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
            2013-06-26 15:44:32,818 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=confluence.extra.jira, 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
            2013-06-26 15:44:42,819 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.andya.confluence.plugins.metadata, 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

            Regards
            Abyakta

            Abyakta Lenka added a comment - Hi Atlassian, I found this is confluence 4.3 as well. When we are trying to stop confluence its giving a similar log .i have to kill confluence process in our linux box . Here is the log snippet : .threaddump, 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 2013-06-26 15:42:02,798 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.gliffy.plugin.confluence.gliffy-confluence-plugin, 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 2013-06-26 15:42:12,800 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.adaptavist.confluence.subsection, 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 2013-06-26 15:42:22,801 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.swift.confluence.table-sorter-plugin, 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 2013-06-26 15:42:32,802 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.storage.servlet, 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 2013-06-26 15:42:42,804 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.javahollic.confluence.confluencesu, 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 2013-06-26 15:42:52,805 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.atlassian.support.stp, 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 2013-06-26 15:43:02,806 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.confluence.conveyor, 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 2013-06-26 15:43:12,807 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=nl.avisi.confluence.plugins.numberedheadings, 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 2013-06-26 15:43:22,809 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=net.artemissoftware.plugins.conf.multiexcerpt4.multiexcerpt-conf-plugin-4, 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 2013-06-26 15:43:32,810 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.randombits.storage.parameters, 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 2013-06-26 15:43:42,811 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.swift.confluence.macro-security-plugin, 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 2013-06-26 15:43:52,813 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.atlassian.confluence.extra.rsvp, 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 2013-06-26 15:44:02,814 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.tngtech.confluence.plugins.umlgraph, 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 2013-06-26 15:44:12,815 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.atlassian.plugins.search.opensearch-plugin, 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 2013-06-26 15:44:22,817 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.atlassian.upm.plugin-license-storage-plugin, 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 2013-06-26 15:44:32,818 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=confluence.extra.jira, 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 2013-06-26 15:44:42,819 ERROR [main] [internal.util.concurrent.RunnableTimedExecution] execute Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=org.andya.confluence.plugins.metadata, 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 Regards Abyakta

            Scott Dudley [Inactive] added a comment - - edited

            Niraj,

            Thank you for the information. I admit that it's a bit of a hard sell to say "your plugin will hang somewhat less often", considering that the only acceptable level of hangs in zero. (Additionally, our plugin has to change the state of certain modules, especially if we want to work in the face of bugs such as CONF-22390.)

            Anyway, I just ran into this issue again when doing a production 4.0 upgrade: I clicked the "upgrade all" button in the UPM, and when in the middle of upgrading the 4.0-compat version of Adaptavist's Plugin Licensing Manager, it bombed out with a similar set of errors (below). The PLM is widely used, so I have to believe that there is some way to fix this issue.

            2011-09-23 11:51:39,838 INFO [Spring executor 11] [atlassian.plugin.manager.DefaultPluginManager] notifyPluginDisabled Disabling com.adaptavist.confluence.contentFormattingMacros
2011-09-23 11:51:43,336 INFO [Spring executor 11] [atlassian.plugin.manager.DefaultPluginManager] disableDependentPlugins Found dependent enabled plugins for uninstalled plugin 'com.adaptavist.plm.plugin.plm-plugin': [].  Disabling...
2011-09-23 11:51:43,337 INFO [Spring executor 11] [atlassian.plugin.manager.DefaultPluginManager] notifyPluginDisabled Disabling com.adaptavist.plm.plugin.plm-plugin
2011-09-23 11:52:35,488 ERROR [Spring executor 11] [sf.hibernate.util.JDBCExceptionReporter] logExceptions Lock wait timeout exceeded; try restarting transaction
 -- referer: https://tools.arsenalesystems.com/confluence/plugins/servlet/upm | url: /confluence/rest/plugins/1.0/upgrades/all | userName: scott
2011-09-23 11:52:35,490 ERROR [Spring executor 11] [sf.hibernate.impl.SessionImpl] execute Could not synchronize database state with session
 -- referer: https://tools.arsenalesystems.com/confluence/plugins/servlet/upm | url: /confluence/rest/plugins/1.0/upgrades/all | userName: scott
2011-09-23 11:52:40,333 INFO [pool-6-thread-1] [atlassian.plugin.manager.DefaultPluginManager] notifyPluginDisabled Disabling com.adaptavist.plm.plugin.plm-plugin-installer

            Anyway, I have filed a new issue here to track it: CONF-23301

            Scott Dudley [Inactive] added a comment - - edited Niraj, Thank you for the information. I admit that it's a bit of a hard sell to say "your plugin will hang somewhat less often", considering that the only acceptable level of hangs in zero. (Additionally, our plugin has to change the state of certain modules, especially if we want to work in the face of bugs such as CONF-22390 .) Anyway, I just ran into this issue again when doing a production 4.0 upgrade: I clicked the "upgrade all" button in the UPM, and when in the middle of upgrading the 4.0-compat version of Adaptavist's Plugin Licensing Manager, it bombed out with a similar set of errors (below). The PLM is widely used, so I have to believe that there is some way to fix this issue. 2011-09-23 11:51:39,838 INFO [Spring executor 11] [atlassian.plugin.manager.DefaultPluginManager] notifyPluginDisabled Disabling com.adaptavist.confluence.contentFormattingMacros 2011-09-23 11:51:43,336 INFO [Spring executor 11] [atlassian.plugin.manager.DefaultPluginManager] disableDependentPlugins Found dependent enabled plugins for uninstalled plugin 'com.adaptavist.plm.plugin.plm-plugin' : []. Disabling... 2011-09-23 11:51:43,337 INFO [Spring executor 11] [atlassian.plugin.manager.DefaultPluginManager] notifyPluginDisabled Disabling com.adaptavist.plm.plugin.plm-plugin 2011-09-23 11:52:35,488 ERROR [Spring executor 11] [sf.hibernate.util.JDBCExceptionReporter] logExceptions Lock wait timeout exceeded; try restarting transaction -- referer: https: //tools.arsenalesystems.com/confluence/plugins/servlet/upm | url: /confluence/ rest /plugins/1.0/upgrades/all | userName: scott 2011-09-23 11:52:35,490 ERROR [Spring executor 11] [sf.hibernate.impl.SessionImpl] execute Could not synchronize database state with session -- referer: https: //tools.arsenalesystems.com/confluence/plugins/servlet/upm | url: /confluence/ rest /plugins/1.0/upgrades/all | userName: scott 2011-09-23 11:52:40,333 INFO [pool-6-thread-1] [atlassian.plugin.manager.DefaultPluginManager] notifyPluginDisabled Disabling com.adaptavist.plm.plugin.plm-plugin-installer Anyway, I have filed a new issue here to track it: CONF-23301

            Niraj Bhawnani added a comment - - edited

            Hi Scott,

            I asked around and found that that problem is known to occur when trying to change plugin state during plugin initialisation. You can reduce the chance of this occurring by reducing the number of writes that your plugin does. For instance, checking if the plugin/module you want to ensure is disabled before calling the PluginController.disablePluginModule method. If you're implementing InitializingBean and doing your initialisation in afterPropertiesSet, it seems changing to com.atlassian.sal.api.lifecycle.LifecycleAware and doing the pluginController calls in onStart also helps.

            You could raise a new issue, but I'm not sure this is something that can be fixed. It's probably worth us writing a KB article or something similar, though. Hope this helps.

            Niraj.

            Niraj Bhawnani added a comment - - edited Hi Scott, I asked around and found that that problem is known to occur when trying to change plugin state during plugin initialisation. You can reduce the chance of this occurring by reducing the number of writes that your plugin does. For instance, checking if the plugin/module you want to ensure is disabled before calling the PluginController.disablePluginModule method. If you're implementing InitializingBean and doing your initialisation in afterPropertiesSet , it seems changing to com.atlassian.sal.api.lifecycle.LifecycleAware and doing the pluginController calls in onStart also helps. You could raise a new issue, but I'm not sure this is something that can be fixed. It's probably worth us writing a KB article or something similar, though. Hope this helps. Niraj.

            Scott Dudley [Inactive] added a comment -

            Niraj,

            We are using MySQL.

            We previously ran into the CONF-21986 issue when testing our plugin on Confluence 3.5.x (including the exact error messages shown in the issue description, timeouts and then our plugin getting hosed), but we were able to work around it by changing some of our plugin's initialization code...then we started seeing these new error messages (as reported above in the comments) when testing against 4.0. This got us wondering if the fix in Conf 3.5.8+ might have broken our workaround.

            It seems that our plugin's Spring initialization is getting invoked while Confluence still holds a lock on some part of the plugin table. Our initialization code sometimes tries to modify other plugin modules (primarily, we call PluginController.disablePluginModule to disable incompatible modules of other plugins), which sometimes provokes the deadlock.

            If we call the above method too soon after our plugin gets initialized, we deadlock. If we wait a while before trying to disable the other plugin modules, everything works correctly. One correlating factor is that if we have not seen our own PluginInstallEvent by the time we try to call disablePluginModule(), we seem to deadlock. But once we've received that event, we seem to be okay.

            If this belongs as another new JIRA issue, please let me know and I can file it!

            Scott Dudley [Inactive] added a comment - Niraj, We are using MySQL. We previously ran into the CONF-21986 issue when testing our plugin on Confluence 3.5.x (including the exact error messages shown in the issue description, timeouts and then our plugin getting hosed), but we were able to work around it by changing some of our plugin's initialization code...then we started seeing these new error messages (as reported above in the comments) when testing against 4.0. This got us wondering if the fix in Conf 3.5.8+ might have broken our workaround. It seems that our plugin's Spring initialization is getting invoked while Confluence still holds a lock on some part of the plugin table. Our initialization code sometimes tries to modify other plugin modules (primarily, we call PluginController.disablePluginModule to disable incompatible modules of other plugins), which sometimes provokes the deadlock. If we call the above method too soon after our plugin gets initialized, we deadlock. If we wait a while before trying to disable the other plugin modules, everything works correctly. One correlating factor is that if we have not seen our own PluginInstallEvent by the time we try to call disablePluginModule(), we seem to deadlock. But once we've received that event, we seem to be okay. If this belongs as another new JIRA issue, please let me know and I can file it!

            Niraj Bhawnani added a comment -

            Hi Scott,

            I can confirm that CONF-21986 is fixed in Confluence 4.0 as well. The issue you are seeing seems to be a separate issue. What symptoms are you experiencing? CONF-21986 occurs on startup or causes a running instance to become unusable for some period of time, or until a restart. Also what DBMS are you running?

            Thanks,
            Niraj.

            Niraj Bhawnani added a comment - Hi Scott, I can confirm that CONF-21986 is fixed in Confluence 4.0 as well. The issue you are seeing seems to be a separate issue. What symptoms are you experiencing? CONF-21986 occurs on startup or causes a running instance to become unusable for some period of time, or until a restart. Also what DBMS are you running? Thanks, Niraj.

            Scott Dudley [Inactive] added a comment -

            Can you confirm if this is supposed to be fixed in Confluence 4.0 as well? I encountered the following error in Confluence 4.0-rc7 while testing doing a reinstall of one of our plugins through the UPM:

            2011-09-16 16:04:21,439 INFO [pool-6-thread-2] [atlassian.plugin.manager.DefaultPluginManager] disableDependentPlugins Found dependent enabled plugins for uninstalled plugin 'com.arsenale.plugins.lockpoint': []. Disabling...
            2011-09-16 16:04:21,441 INFO [pool-6-thread-2] [atlassian.plugin.manager.DefaultPluginManager] updatePlugin Updating plugin 'com.arsenale.plugins.lockpoint' to 'com.arsenale.plugins.lockpoint'
            2011-09-16 16:04:21,443 INFO [pool-6-thread-2] [atlassian.plugin.manager.DefaultPluginManager] notifyPluginDisabled Disabling com.arsenale.plugins.lockpoint
            2011-09-16 16:04:23,133 ERROR [http-8090-5] [sf.hibernate.util.JDBCExceptionReporter] logExceptions Deadlock found when trying to get lock; try restarting transaction
            – referer: http://172.16.16.10:8090/plugins/servlet/upm | url: /rest/plugins/1.0/pending/008decc2-f4fb-421f-a4f0-6d05489257d7 | userName: admin
            2011-09-16 16:04:23,134 ERROR [http-8090-5] [sf.hibernate.impl.SessionImpl] execute Could not synchronize database state with session
            – referer: http://172.16.16.10:8090/plugins/servlet/upm | url: /rest/plugins/1.0/pending/008decc2-f4fb-421f-a4f0-6d05489257d7 | userName: admin

            I can't reproduce this easily, but I've seen it happen once each on Confluence 4.0-rc3 and 4.0-rc7.

            Scott Dudley [Inactive] added a comment - Can you confirm if this is supposed to be fixed in Confluence 4.0 as well? I encountered the following error in Confluence 4.0-rc7 while testing doing a reinstall of one of our plugins through the UPM: 2011-09-16 16:04:21,439 INFO [pool-6-thread-2] [atlassian.plugin.manager.DefaultPluginManager] disableDependentPlugins Found dependent enabled plugins for uninstalled plugin 'com.arsenale.plugins.lockpoint': []. Disabling... 2011-09-16 16:04:21,441 INFO [pool-6-thread-2] [atlassian.plugin.manager.DefaultPluginManager] updatePlugin Updating plugin 'com.arsenale.plugins.lockpoint' to 'com.arsenale.plugins.lockpoint' 2011-09-16 16:04:21,443 INFO [pool-6-thread-2] [atlassian.plugin.manager.DefaultPluginManager] notifyPluginDisabled Disabling com.arsenale.plugins.lockpoint 2011-09-16 16:04:23,133 ERROR [http-8090-5] [sf.hibernate.util.JDBCExceptionReporter] logExceptions Deadlock found when trying to get lock; try restarting transaction – referer: http://172.16.16.10:8090/plugins/servlet/upm | url: /rest/plugins/1.0/pending/008decc2-f4fb-421f-a4f0-6d05489257d7 | userName: admin 2011-09-16 16:04:23,134 ERROR [http-8090-5] [sf.hibernate.impl.SessionImpl] execute Could not synchronize database state with session – referer: http://172.16.16.10:8090/plugins/servlet/upm | url: /rest/plugins/1.0/pending/008decc2-f4fb-421f-a4f0-6d05489257d7 | userName: admin I can't reproduce this easily, but I've seen it happen once each on Confluence 4.0-rc3 and 4.0-rc7.

            Amit Narayanan added a comment -

            Thanks Niraj. Just the .java/.xml source files would've sufficed. But .patch is even better.

            -Amit.

            Amit Narayanan added a comment - Thanks Niraj. Just the .java/.xml source files would've sufficed. But .patch is even better. -Amit.

            Niraj Bhawnani added a comment -

            Hi Amit,

            My apologies for not attaching the source patch earlier. I've attached a patch file for the Confluence 3.3 source.

            Cheers,
            Niraj.

            Niraj Bhawnani added a comment - Hi Amit, My apologies for not attaching the source patch earlier. I've attached a patch file for the Confluence 3.3 source. Cheers, Niraj.

            Amit Narayanan added a comment -

            Can we get the source for this patch?

            -Amit.

            Amit Narayanan added a comment - Can we get the source for this patch? -Amit.

              Unassigned Unassigned
              don.willis@atlassian.com Don Willis
              Affected customers:
              9 This affects my team
              Watchers:
              18 Start watching this issue

                Created:
                Updated:
                Resolved:

                  Estimated:
                  Original Estimate - 8h
                  8h
                  Remaining:
                  Remaining Estimate - 8h
                  8h
                  Logged:
                  Time Spent - Not Specified
                  Not Specified