Confluence is hung on startup

[dchisholm]

Started a PDF export of a space which ran and ran but never finished.  Was getting 500 errors in the UI while it was running.

Tried restarting Confluence, and it hung.  Rebooted the server and it still hung.   It is hitting 100% CPU on one of two CPUs of the server.

Cannot get passed this problem.  Any suggestions?

Environment:

* CentOS 6

* Confluence 6.0.1

* Several Scroll add-ons

 I would post the stacktrace but it's too large.

EDIT

Found the following after grepping the logs for deadlock:

[root@techdocs176 logs]# grep -i deadlock *
atlassian-confluence.log:2017-10-16 14:07:02,218 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ran09jjd7j70p|7fc56e90]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@34543fa2 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!
atlassian-confluence.log:2017-10-16 14:07:02,223 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ran09jjd7j70p|7fc56e90]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@34543fa2 -- APPARENT DEADLOCK!!! Complete Status:
atlassian-confluence.log:2017-10-16 14:07:04,796 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ran09jjd7j70p|2f7c2d57]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@175dc4b5 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!
atlassian-confluence.log:2017-10-16 14:07:04,799 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ran09jjd7j70p|2f7c2d57]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@175dc4b5 -- APPARENT DEADLOCK!!! Complete Status:
atlassian-confluence.log:2017-10-16 14:08:17,253 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ran09jjd7j70p|7fc56e90]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log Task com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@6edca088 (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
atlassian-confluence.log:2017-10-16 14:08:17,254 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ran09jjd7j70p|7fc56e90]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log Task com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@66e1bb00 (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
atlassian-confluence.log:2017-10-16 14:08:17,254 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ran09jjd7j70p|7fc56e90]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log Task com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@1857d19c (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
atlassian-confluence.log:2017-10-16 14:08:19,819 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ran09jjd7j70p|2f7c2d57]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log Task com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@49b9d8 (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
atlassian-confluence.log:2017-10-16 14:08:19,819 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ran09jjd7j70p|2f7c2d57]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log Task com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@529f5893 (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
atlassian-confluence.log:2017-10-16 14:08:19,820 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ran09jjd7j70p|2f7c2d57]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log Task com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@8fe9702 (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().

EDIT 2

I have updated the mchange and c3p0 jars to the very latest versions and got the same results.  Adapted this suggestion from https://jira.atlassian.com/browse/CONFSERVER-25531

[dchisholm · Accepted solution]

Thanks for all the responses.  We were not able to recover the instance and had to restore from a backup with some data loss. 

[Nils Bier _K15t_]

Hi David,

To further investigate here, we'd need to have a Confluence Support ZIP, containing the full log of the Confluence start.

Can you please send this one to support@k15t.com ?

We'll then have a closer look and will come back to you.

Best,
Nils

[Steven F Behnke]

1. Consider opening a support request
2. Can we a portion of the log proceeding the deadlock lines? If you're using GREP you can use -B 50 to get the 50 lines before. (-A 50 similarly would get the 50 lines after)

[AnnWorley]

@Steven F Behnke The customer is most likely using a starter license so the Community Forum is their exclusive support channel.

[dchisholm]

Yes, we are.  Unfortunately we discovered today that the support for starters has changed.

[dchisholm]

Here are the gory details of the lines prior to the deadlocks but I had to reduce the count to 20 to fit the comment limits:

[root@techdocs176 logs]# grep -i -B 20 deadlock *
atlassian-confluence.log-2017-10-16 17:15:29,992 WARN [localhost-startStop-1] [atlassian.confluence.renderer.DefaultMacroManager] registerMacro Unregistering existing macro 'scroll-pi' (LazyLoadedMacroDecorator{name=com.k15t.scroll.scroll-html:scroll.pi}) to replace with macro with same name (LazyLoadedMacroDecorator{name=com.k15t.scroll.scroll-office:scroll.pi})
atlassian-confluence.log-2017-10-16 17:15:29,995 WARN [localhost-startStop-1] [atlassian.confluence.renderer.DefaultMacroManager] registerMacro Unregistering existing macro 'scroll-ignore' (LazyLoadedMacroDecorator{name=com.k15t.scroll.scroll-html:scroll.ignore}) to replace with macro with same name (LazyLoadedMacroDecorator{name=com.k15t.scroll.scroll-office:scroll.ignore})
atlassian-confluence.log-2017-10-16 17:15:29,996 WARN [localhost-startStop-1] [atlassian.confluence.renderer.DefaultMacroManager] registerMacro Unregistering existing macro 'scroll-only' (LazyLoadedMacroDecorator{name=com.k15t.scroll.scroll-html:scroll.only}) to replace with macro with same name (LazyLoadedMacroDecorator{name=com.k15t.scroll.scroll-office:scroll.only})
atlassian-confluence.log-2017-10-16 17:15:29,998 WARN [localhost-startStop-1] [atlassian.confluence.renderer.DefaultMacroManager] registerMacro Unregistering existing macro 'scroll-only-inline' (LazyLoadedMacroDecorator{name=com.k15t.scroll.scroll-html:scroll.only.inline}) to replace with macro with same name (LazyLoadedMacroDecorator{name=com.k15t.scroll.scroll-office:scroll.only.inline})
atlassian-confluence.log-2017-10-16 17:15:29,999 WARN [localhost-startStop-1] [atlassian.confluence.renderer.DefaultMacroManager] registerMacro Unregistering existing macro 'scroll-ignore-inline' (LazyLoadedMacroDecorator{name=com.k15t.scroll.scroll-html:scroll.ignore.inline}) to replace with macro with same name (LazyLoadedMacroDecorator{name=com.k15t.scroll.scroll-office:scroll.ignore.inline})
atlassian-confluence.log-2017-10-16 17:15:30,001 WARN [localhost-startStop-1] [atlassian.confluence.renderer.DefaultMacroManager] registerMacro Unregistering existing macro 'scroll-title' (LazyLoadedMacroDecorator{name=com.k15t.scroll.scroll-html:scroll.title}) to replace with macro with same name (LazyLoadedMacroDecorator{name=com.k15t.scroll.scroll-office:scroll.title})
atlassian-confluence.log-2017-10-16 17:15:30,003 WARN [localhost-startStop-1] [atlassian.confluence.renderer.DefaultMacroManager] registerMacro Unregistering existing macro 'scroll-pagetitle' (LazyLoadedMacroDecorator{name=com.k15t.scroll.scroll-html:scroll.pagetitle}) to replace with macro with same name (LazyLoadedMacroDecorator{name=com.k15t.scroll.scroll-office:scroll.pagetitle})
atlassian-confluence.log-2017-10-16 17:15:30,387 INFO [localhost-startStop-1] [services.upgrade.impl.DefaultScrollUpgradeManager] upgradeGlobal Scroll Platform is up-to-date.
atlassian-confluence.log-2017-10-16 17:15:31,397 INFO [localhost-startStop-1] [atlassian.plugin.manager.DefaultPluginManager] logTime Plugin system lateStartup ended
atlassian-confluence.log-2017-10-16 17:15:31,665 WARN [lifecycle:thread-1] [hql.internal.ast.HqlSqlWalker] generatePositionalParameter [DEPRECATION] Encountered positional parameter near line 1, column 93 in HQL: [FROM com.atlassian.confluence.impl.schedule.caesium.SchedulerClusteredJob t WHERE t.jobId = ?]. Positional parameter are considered deprecated; use named parameters or JPA-style positional parameters instead.
atlassian-confluence.log-2017-10-16 17:15:32,491 WARN [UpmScheduler:thread-1] [hql.internal.ast.HqlSqlWalker] generatePositionalParameter [DEPRECATION] Encountered positional parameter near line 1, column 110 in HQL: [SELECT usr.name, usr.lowerName FROM com.atlassian.crowd.model.user.InternalUser usr WHERE usr.directory.id = ? AND usr.active = ? ORDER BY usr.lowerName]. Positional parameter are considered deprecated; use named parameters or JPA-style positional parameters instead.
atlassian-confluence.log-2017-10-16 17:15:32,497 WARN [UpmScheduler:thread-1] [hql.internal.ast.HqlSqlWalker] generatePositionalParameter [DEPRECATION] Encountered positional parameter near line 1, column 129 in HQL: [SELECT usr.name, usr.lowerName FROM com.atlassian.crowd.model.user.InternalUser usr WHERE usr.directory.id = ? AND usr.active = ? ORDER BY usr.lowerName]. Positional parameter are considered deprecated; use named parameters or JPA-style positional parameters instead.
atlassian-confluence.log-2017-10-16 17:15:32,841 WARN [UpmScheduler:thread-1] [hql.internal.ast.HqlSqlWalker] generatePositionalParameter [DEPRECATION] Encountered positional parameter near line 1, column 159 in HQL: [SELECT mem.userMember.name FROM com.atlassian.crowd.embedded.hibernate2.HibernateMembership mem WHERE mem.groupMember is null and mem.parentGroup.lowerName = ? and mem.parentGroup.directory.id = ? and mem.parentGroup.type = ? ORDER BY mem.userMember.lowerName]. Positional parameter are considered deprecated; use named parameters or JPA-style positional parameters instead.
atlassian-confluence.log-2017-10-16 17:15:32,842 WARN [UpmScheduler:thread-1] [hql.internal.ast.HqlSqlWalker] generatePositionalParameter [DEPRECATION] Encountered positional parameter near line 1, column 196 in HQL: [SELECT mem.userMember.name FROM com.atlassian.crowd.embedded.hibernate2.HibernateMembership mem WHERE mem.groupMember is null and mem.parentGroup.lowerName = ? and mem.parentGroup.directory.id = ? and mem.parentGroup.type = ? ORDER BY mem.userMember.lowerName]. Positional parameter are considered deprecated; use named parameters or JPA-style positional parameters instead.
atlassian-confluence.log-2017-10-16 17:15:32,847 WARN [UpmScheduler:thread-1] [hql.internal.ast.HqlSqlWalker] generatePositionalParameter [DEPRECATION] Encountered positional parameter near line 1, column 225 in HQL: [SELECT mem.userMember.name FROM com.atlassian.crowd.embedded.hibernate2.HibernateMembership mem WHERE mem.groupMember is null and mem.parentGroup.lowerName = ? and mem.parentGroup.directory.id = ? and mem.parentGroup.type = ? ORDER BY mem.userMember.lowerName]. Positional parameter are considered deprecated; use named parameters or JPA-style positional parameters instead.
atlassian-confluence.log-2017-10-16 17:15:33,004 INFO [UpmScheduler:thread-1] [atlassian.confluence.user.DefaultUserAccessor] getUserNamesWithConfluenceAccess Found USE permission with no associated username or group: [USECONFLUENCE,0,null,null,null]
atlassian-confluence.log-2017-10-16 17:15:36,065 INFO [localhost-startStop-1] [confluence.upgrade.impl.DefaultUpgradeGate] waitForBooleanValue Waiting to find if plugin dependent upgrades are required. Maximum wait time will be 90 seconds.
atlassian-confluence.log-2017-10-16 17:15:36,088 INFO [localhost-startStop-1] [confluence.upgrade.impl.DefaultUpgradeGate] waitForBooleanValue plugin dependent upgrades are required : false.
atlassian-confluence.log-2017-10-16 17:15:36,148 INFO [localhost-startStop-1] [xhtml.migration.macro.RemigrationLifecycleItem] startup Remigration is required
atlassian-confluence.log-2017-10-16 17:15:44,448 WARN [UpmScheduler:thread-1] [atlassian.upm.pac.PacClientImpl] getUpdates Update check request may take longer because of the number of add-ons
atlassian-confluence.log:2017-10-16 17:16:11,755 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ratrkeu475ho9|4f61f657]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@2146e36 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!
atlassian-confluence.log:2017-10-16 17:16:11,764 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ratrkeu475ho9|4f61f657]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@2146e36 -- APPARENT DEADLOCK!!! Complete Status:
--
atlassian-confluence.log- com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:1076)
atlassian-confluence.log- com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)
atlassian-confluence.log- Thread[C3P0PooledConnectionPoolManager[identityToken->2s071s9ratrkeu475ho9|4f61f657]-HelperThread-#0,5,main]
atlassian-confluence.log- java.net.SocketInputStream.socketRead0(Native Method)
atlassian-confluence.log- java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
atlassian-confluence.log- java.net.SocketInputStream.read(SocketInputStream.java:170)
atlassian-confluence.log- java.net.SocketInputStream.read(SocketInputStream.java:141)
atlassian-confluence.log- java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
atlassian-confluence.log- java.io.BufferedInputStream.read(BufferedInputStream.java:265)
atlassian-confluence.log- java.io.DataInputStream.readInt(DataInputStream.java:387)
atlassian-confluence.log- org.h2.value.Transfer.readInt(Transfer.java:157)
atlassian-confluence.log- org.h2.engine.SessionRemote.done(SessionRemote.java:599)
atlassian-confluence.log- org.h2.engine.SessionRemote.close(SessionRemote.java:552)
atlassian-confluence.log- org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:383)
atlassian-confluence.log- com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:642)
atlassian-confluence.log- com.mchange.v2.c3p0.impl.NewPooledConnection.closeMaybeCheckedOut(NewPooledConnection.java:255)
atlassian-confluence.log- com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:622)
atlassian-confluence.log- com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:1076)
atlassian-confluence.log- com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)
atlassian-confluence.log-
atlassian-confluence.log:2017-10-16 17:16:13,288 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ratrkeu475ho9|822832b]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@24484846 -- APPARENT DEADLOCK!!! Creating emergency threads for unassigned pending tasks!
atlassian-confluence.log:2017-10-16 17:16:13,294 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ratrkeu475ho9|822832b]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log com.mchange.v2.async.ThreadPoolAsynchronousRunner$DeadlockDetector@24484846 -- APPARENT DEADLOCK!!! Complete Status:
--
atlassian-confluence.log- com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)
atlassian-confluence.log- Thread[C3P0PooledConnectionPoolManager[identityToken->2s071s9ratrkeu475ho9|822832b]-HelperThread-#0,5,main]
atlassian-confluence.log- java.net.SocketInputStream.socketRead0(Native Method)
atlassian-confluence.log- java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
atlassian-confluence.log- java.net.SocketInputStream.read(SocketInputStream.java:170)
atlassian-confluence.log- java.net.SocketInputStream.read(SocketInputStream.java:141)
atlassian-confluence.log- java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
atlassian-confluence.log- java.io.BufferedInputStream.read(BufferedInputStream.java:265)
atlassian-confluence.log- java.io.DataInputStream.readInt(DataInputStream.java:387)
atlassian-confluence.log- org.h2.value.Transfer.readInt(Transfer.java:157)
atlassian-confluence.log- org.h2.engine.SessionRemote.done(SessionRemote.java:599)
atlassian-confluence.log- org.h2.engine.SessionRemote.close(SessionRemote.java:552)
atlassian-confluence.log- org.h2.jdbc.JdbcConnection.close(JdbcConnection.java:383)
atlassian-confluence.log- com.mchange.v2.c3p0.impl.NewPooledConnection.close(NewPooledConnection.java:642)
atlassian-confluence.log- com.mchange.v2.c3p0.impl.NewPooledConnection.closeMaybeCheckedOut(NewPooledConnection.java:255)
atlassian-confluence.log- com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool$1PooledConnectionResourcePoolManager.destroyResource(C3P0PooledConnectionPool.java:622)
atlassian-confluence.log- com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask.run(BasicResourcePool.java:1076)
atlassian-confluence.log- com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:696)
atlassian-confluence.log-
atlassian-confluence.log-2017-10-16 17:16:44,461 WARN [UpmScheduler:thread-1] [atlassian.upm.pac.PacClientImpl] getUpdates Timed out while checking for addon updates: com.atlassian.util.concurrent.RuntimeTimeoutException: com.atlassian.util.concurrent.TimedOutException: Timed out after: 60000000000 NANOSECONDS
atlassian-confluence.log:2017-10-16 17:17:26,764 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ratrkeu475ho9|4f61f657]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log Task com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@4dee9a3f (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
atlassian-confluence.log:2017-10-16 17:17:26,766 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ratrkeu475ho9|4f61f657]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log Task com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@6c2a386a (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
atlassian-confluence.log:2017-10-16 17:17:26,766 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ratrkeu475ho9|4f61f657]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log Task com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@7c69d65b (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
atlassian-confluence.log:2017-10-16 17:17:28,296 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ratrkeu475ho9|822832b]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log Task com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@4e4cf427 (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
atlassian-confluence.log:2017-10-16 17:17:28,296 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ratrkeu475ho9|822832b]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log Task com.mchange.v2.resourcepool.BasicResourcePool$ScatteredAcquireTask@614ad2ab (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().
atlassian-confluence.log:2017-10-16 17:17:28,296 WARN [C3P0PooledConnectionPoolManager[identityToken->2s071s9ratrkeu475ho9|822832b]-AdminTaskTimer] [mchange.v2.async.ThreadPoolAsynchronousRunner] log Task com.mchange.v2.resourcepool.BasicResourcePool$1DestroyResourceTask@50e11626 (in deadlocked PoolThread) failed to complete in maximum time 60000ms. Trying interrupt().

[Steven F Behnke]

The KB article you're looking for should be here: https://confluence.atlassian.com/confkb/troubleshooting-deadlocks-in-confluence-182683241.html

They all point to systemic issues, counter to the theory that this had anything to do with a PDF Export. 

[AnnWorley]

As space exports are resource intensive, please look for "outofmemory" in the logs and if you find it, follow this guide: How to fix out of memory errors by increasing available memory

The logs to examine are: 

• <confluence_install>/logs/ (anything recent in this directory)
• <confluence_home>/logs/atlassian-confluence.log
   (The <confluence_home> directory is the path defined in the following file: <confluence_install>/confluence/WEB-INF/classes/confluence-init.properties)

[dchisholm]

It's not an OOM issue.