Confluence Intermittently Fails on Start Up

[drewhubley]

We have confluence, jira and bitbucket on the same host. Every night the system reboots at midnight to take a snapshot. Jira and Bitbucket run without issue however once every couple of weeks confluence fails to start after the snapshot is taken. Any thoughts or suggestions?

2018-06-04 04:34:41,919 ERROR [localhost-startStop-5] [hipchat.spacetoroom.service.SpaceToRoomNotificationService] hipChatNotifications Failed to obtain hipchat notifications for event com.atlassian.plugin.event.events.PluginFrameworkShutdownEvent@55585f0b: service proxy has been destroyed
2018-06-04 04:34:41,921 WARN [localhost-startStop-5] [confluence.util.profiling.DurationThresholdWarningTimingHelperFactory] logMessage Execution time for publishing event com.atlassian.plugin.event.events.PluginFrameworkShutdownEvent@55585f0b took 11799 ms (warning threshold is 5000 ms)
2018-06-04 04:34:42,005 ERROR [localhost-startStop-5] [atlassian.confluence.setup.ConfluenceListableBeanFactory] destroyBean Destroy method on bean with name 'contentPropertyService' threw an exception
com.atlassian.util.concurrent.LazyReference$InitializationException: java.lang.IllegalStateException: Unable to create a tracker when osgi is not running
    at com.atlassian.util.concurrent.LazyReference.getInterruptibly(LazyReference.java:149)
    at com.atlassian.util.concurrent.LazyReference.get(LazyReference.java:112)
    at com.atlassian.confluence.osgi.OsgiServiceRegistryImpl$ServiceTrackingProxy.getServiceTracker(OsgiServiceRegistryImpl.java:75)
    at com.atlassian.confluence.osgi.OsgiServiceRegistryImpl$ServiceTrackingProxy.invoke(OsgiServiceRegistryImpl.java:80)
    at com.sun.proxy.$Proxy204.hashCode(Unknown Source)
    at java.util.concurrent.ConcurrentHashMap.replaceNode(ConcurrentHashMap.java:1106)
    at java.util.concurrent.ConcurrentHashMap.remove(ConcurrentHashMap.java:1097)
    at org.springframework.orm.jpa.support.PersistenceAnnotationBeanPostProcessor.postProcessBeforeDestruction(PersistenceAnnotationBeanPostProcessor.java:374)
    at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:243)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:578)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:554)
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:972)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:523)
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:979)
    at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1006)
    at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:982)
    at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:934)
    at org.springframework.web.context.ContextLoader.closeWebApplicationContext(ContextLoader.java:581)
    at org.springframework.web.context.ContextLoaderListener.contextDestroyed(ContextLoaderListener.java:116)
    at org.apache.catalina.core.StandardContext.listenerStop(StandardContext.java:4899)
    at org.apache.catalina.core.StandardContext.stopInternal(StandardContext.java:5536)
    at org.apache.catalina.util.LifecycleBase.stop(LifecycleBase.java:221)
    at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1424)
    at org.apache.catalina.core.ContainerBase$StopChild.call(ContainerBase.java:1413)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.IllegalStateException: Unable to create a tracker when osgi is not running
    at com.atlassian.plugin.osgi.container.felix.FelixOsgiContainerManager.getServiceTracker(FelixOsgiContainerManager.java:490)
    at com.atlassian.plugin.osgi.container.felix.FelixOsgiContainerManager.getServiceTracker(FelixOsgiContainerManager.java:482)
    at com.atlassian.confluence.osgi.OsgiServiceRegistryImpl$1.create(OsgiServiceRegistryImpl.java:46)
    at com.atlassian.confluence.osgi.OsgiServiceRegistryImpl$1.create(OsgiServiceRegistryImpl.java:43)
    at com.atlassian.util.concurrent.LazyReference$Sync.run(LazyReference.java:325)
    at com.atlassian.util.concurrent.LazyReference.getInterruptibly(LazyReference.java:143)
    ... 27 more
2018-06-04 04:34:42,050 ERROR [localhost-startStop-5] [atlassian.confluence.setup.ConfluenceListableBeanFactory] destroyBean Destroy method on bean with name 'boostingQueryFactory' threw an exception
com.atlassian.util.concurrent.LazyReference$InitializationException: java.lang.IllegalStateException: Unable to create a tracker when osgi is not running
2018-06-04 04:34:42,129 INFO [localhost-startStop-5] [com.atlassian.confluence.lifecycle] destroy Shutting down long running task service
2018-06-04 04:34:42,136 ERROR [localhost-startStop-5] [atlassian.confluence.setup.ConfluenceListableBeanFactory] destroyBean Destroy method on bean with name 'apiNavigationService' threw an exception
com.atlassian.confluence.osgi.OsgiNoServiceAvailableException: No service available for com.atlassian.confluence.rest.api.services.RestNavigationService

2018-06-04 04:34:42,165 INFO [localhost-startStop-5] [com.atlassian.confluence.lifecycle] shutdownCacheManager Shutting down EhCache cache manager
2018-06-04 04:34:42,175 INFO [localhost-startStop-5] [com.atlassian.confluence.lifecycle] contextDestroyed Stopping Confluence
2018-06-04 04:36:37,416 INFO [localhost-startStop-1] [com.atlassian.confluence.lifecycle] contextInitialized Starting Confluence 6.7.1 [build 7601 based on commit hash d9a7d86ddd6172b1b5a38b9e600c8b90c362def3] - synchrony version 2.1.0-release-confluence_6.5-1a01ab2d
2018-06-04 04:36:47,249 INFO [localhost-startStop-1] [atlassian.confluence.cluster.DefaultClusterConfigurationHelper] lambda$populateExistingClusterSetupConfig$1 Populating setup configuration if running with Cluster mode...
2018-06-04 04:36:47,708 INFO [localhost-startStop-1] [springframework.web.context.ContextLoader] initWebApplicationContext Root WebApplicationContext: initialization started
2018-06-04 04:36:57,535 INFO [localhost-startStop-1] [com.atlassian.confluence.lifecycle] <init> Loading EhCache cache manager
2018-06-04 04:37:32,019 INFO [localhost-startStop-1] [springframework.web.context.ContextLoader] initWebApplicationContext Root WebApplicationContext: initialization completed in 44311 ms
2018-06-04 04:37:35,246 INFO [localhost-startStop-1] [atlassian.plugin.manager.DefaultPluginManager] earlyStartup Plugin system earlyStartup begun
2018-06-04 04:38:26,858 WARN [ThreadPoolAsyncTaskExecutor::Thread 3] [spring.scanner.util.ProductFilterUtil] detectProduct Couldn't detect product, will use ProductFilter.ALL
2018-06-04 04:38:27,312 WARN [ThreadPoolAsyncTaskExecutor::Thread 2] [spring.scanner.util.ProductFilterUtil] detectProduct Couldn't detect product, will use ProductFilter.ALL
2018-06-04 04:39:16,807 INFO [localhost-startStop-1] [atlassian.plugin.manager.DefaultPluginManager] logTime Plugin system earlyStartup ended
2018-06-04 04:39:16,986 INFO [localhost-startStop-1] [atlassian.plugin.manager.DefaultPluginManager] lateStartup Plugin system lateStartup begun
2018-06-04 04:39:29,014 WARN [ThreadPoolAsyncTaskExecutor::Thread 15] [client.eventfilter.whitelist.AnalyticsWhitelistModuleDescriptor] readPluginWhitelist No whitelist resource file found at [mediaviewer/lib/analytics-whitelist.json] in plugin [com.atlassian.confluence.plugins.confluence-previews] (bundle entry not found)
2018-06-04 04:39:29,030 WARN [ThreadPoolAsyncTaskExecutor::Thread 15] [client.eventfilter.whitelist.AnalyticsWhitelistModuleDescriptor] readPluginWhitelist No whitelist resource file found at [mediaviewer/lib/analytics-whitelist.json] in plugin [com.atlassian.confluence.plugins.confluence-previews] (null InputStream)
2018-06-04 04:39:31,485 WARN [ThreadPoolAsyncTaskExecutor::Thread 3] [beans.factory.support.DefaultListableBeanFactory] registerBeanDefinition Overriding user-defined bean definition for bean 'contentEntityManager' with a framework-generated bean definition: replacing [Generic bean: class [com.atlassian.plugin.osgi.bridge.external.HostComponentFactoryBean]; scope=; abstract=false; lazyInit=true; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in URL [bundle://244.0:0/META-INF/spring/atlassian-plugins-host-components.xml]] with [Root bean: class [org.eclipse.gemini.blueprint.service.importer.support.OsgiServiceProxyFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2018-06-04 04:39:31,510 WARN [ThreadPoolAsyncTaskExecutor::Thread 3] [beans.factory.support.DefaultListableBeanFactory] registerBeanDefinition Overriding user-defined bean definition for bean 'likeManager' with a framework-generated bean definition: replacing [Generic bean: class [com.atlassian.plugin.osgi.bridge.external.HostComponentFactoryBean]; scope=; abstract=false; lazyInit=true; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in URL [bundle://244.0:0/META-INF/spring/atlassian-plugins-host-components.xml]] with [Root bean: class [org.eclipse.gemini.blueprint.service.importer.support.OsgiServiceProxyFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2018-06-04 04:39:31,510 WARN [ThreadPoolAsyncTaskExecutor::Thread 3] [beans.factory.support.DefaultListableBeanFactory] registerBeanDefinition Overriding user-defined bean definition for bean 'commentManager' with a framework-generated bean definition: replacing [Generic bean: class [com.atlassian.plugin.osgi.bridge.external.HostComponentFactoryBean]; scope=; abstract=false; lazyInit=true; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in URL [bundle://244.0:0/META-INF/spring/atlassian-plugins-host-components.xml]] with [Root bean: class [org.eclipse.gemini.blueprint.service.importer.support.OsgiServiceProxyFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2018-06-04 04:39:31,511 WARN [ThreadPoolAsyncTaskExecutor::Thread 3] [beans.factory.support.DefaultListableBeanFactory] registerBeanDefinition Overriding user-defined bean definition for bean 'permissionManager' with a framework-generated bean definition: replacing [Generic bean: class [com.atlassian.plugin.osgi.bridge.external.HostComponentFactoryBean]; scope=; abstract=false; lazyInit=true; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in URL [bundle://244.0:0/META-INF/spring/atlassian-plugins-host-components.xml]] with [Root bean: class [org.eclipse.gemini.blueprint.service.importer.support.OsgiServiceProxyFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2018-06-04 04:39:31,547 WARN [ThreadPoolAsyncTaskExecutor::Thread 3] [beans.factory.support.DefaultListableBeanFactory] registerBeanDefinition Overriding user-defined bean definition for bean 'spaceLogoManager' with a framework-generated bean definition: replacing [Generic bean: class [com.atlassian.plugin.osgi.bridge.external.HostComponentFactoryBean]; scope=; abstract=false; lazyInit=true; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in URL [bundle://244.0:0/META-INF/spring/atlassian-plugins-host-components.xml]] with [Root bean: class [org.eclipse.gemini.blueprint.service.importer.support.OsgiServiceProxyFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2018-06-04 04:39:31,547 WARN [ThreadPoolAsyncTaskExecutor::Thread 3] [beans.factory.support.DefaultListableBeanFactory] registerBeanDefinition Overriding user-defined bean definition for bean 'spaceManager' with a framework-generated bean definition: replacing [Generic bean: class [com.atlassian.plugin.osgi.bridge.external.HostComponentFactoryBean]; scope=; abstract=false; lazyInit=true; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in URL [bundle://244.0:0/META-INF/spring/atlassian-plugins-host-components.xml]] with [Root bean: class [org.eclipse.gemini.blueprint.service.importer.support.OsgiServiceProxyFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2018-06-04 04:39:31,547 WARN [ThreadPoolAsyncTaskExecutor::Thread 3] [beans.factory.support.DefaultListableBeanFactory] registerBeanDefinition Overriding user-defined bean definition for bean 'userAccessor' with a framework-generated bean definition: replacing [Generic bean: class [com.atlassian.plugin.osgi.bridge.external.HostComponentFactoryBean]; scope=; abstract=false; lazyInit=true; autowireMode=0; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null; defined in URL [bundle://244.0:0/META-INF/spring/atlassian-plugins-host-components.xml]] with [Root bean: class [org.eclipse.gemini.blueprint.service.importer.support.OsgiServiceProxyFactoryBean]; scope=; abstract=false; lazyInit=false; autowireMode=3; dependencyCheck=0; autowireCandidate=true; primary=false; factoryBeanName=null; factoryMethodName=null; initMethodName=null; destroyMethodName=null]
2018-06-04 04:39:33,781 WARN [localhost-startStop-1] [plugins.createcontent.extensions.BlueprintModuleDescriptor] init i18n-name-key is a required attribute of <blueprint> for module: com.mxgraph.confluence.plugins.diagramly:drawio-custom-templates-blueprint
2018-06-04 04:39:34,261 INFO [ThreadPoolAsyncTaskExecutor::Thread 20] [plugins.synchrony.bootstrap.DefaultSynchronyProxyMonitor] <init> synchrony-proxy healthcheck url: http://127.0.0.1:8092/synchrony-proxy/healthcheck
2018-06-04 04:39:34,928 WARN [ThreadPoolAsyncTaskExecutor::Thread 16] [spring.scanner.util.ProductFilterUtil] detectProduct Couldn't detect product, will use ProductFilter.ALL
2018-06-04 04:39:34,928 WARN [ThreadPoolAsyncTaskExecutor::Thread 14] [spring.scanner.util.ProductFilterUtil] detectProduct Couldn't detect product, will use ProductFilter.ALL
2018-06-04 04:40:02,086 WARN [localhost-startStop-1] [praecipio.plugins.ao.DsSystemService] <clinit> DocuSign System Service Status:  Connected=false.
2018-06-04 04:40:04,454 INFO [localhost-startStop-1] [atlassian.plugin.manager.DefaultPluginManager] logTime Plugin system lateStartup ended
2018-06-04 04:40:04,704 INFO [lifecycle:thread-8] [plugins.synchrony.bootstrap.DefaultSynchronyProcessManager] startup Starting Synchrony and enabling Collaborative Editing
2018-06-04 04:40:04,715 WARN [lifecycle:thread-16] [expose.jmx.schedule.JmxInstrumentSchedulerImpl] onStart atlassian-instrumentation-jmx expose scheduler started.
2018-06-04 04:40:04,940 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.
2018-06-04 04:40:08,012 WARN [UpmScheduler:thread-1] [atlassian.upm.pac.PacClientImpl] getUpdates Update check request may take longer because of the number of add-ons

[Mirek · Accepted solution]

Is there enough resources for all addons to startup?

[drewhubley]

The system has 4 Virtual Cores on a Xeon CPU with 16 GB of ram.

[Mirek]

OK but you mentioned that you are having 3 applications on one host. So the question is what else is running on that host (database, anit-virus, .. etc.), how much RAM is reserved per application, and how big instances you are having. Not enough Java heap might not be reserved to successfully start all modules. If you are saying that every couple of weeks something is failing to start it shows that there is no 100% occurrence of the problem. Problem exist periodically. Do you see any other pattern? I assume everything is done automatically by a script. Is that correct?

[drewhubley]

The issue was insufficient memory on the JVM even though the system itself had plenty the system was not configured to allocate it to the JVM.

[Mike Rathwell]

I am not sure how you are restarting your server but there is also the possibility that, if not explicitly stopping your instances before the server reboot occurs that you are corrupting your plugin cache.

It will take your instances longer to restart but grep Google for how to manually clear plugin caches for BOTH Jira and Confluence (since you're restarting both) and add that to your startup scripts.

I run them both containerized on AWS and on the rare occasion AWS took a header, MOST times they came back clean. Other times, not so much, and it took that cache clean to get them to start again. I've now added that to the startup and they ALWAYS come back now.

[drewhubley]

I also run the applications in AWS and found that abruptly stopping the instance causes slow boot ups. My solution for the problem is adding the shutdown script to the systemd services so that when the shutdown command is issued all the applications stop using the Atlassian stop script. I will look into those caches though.

Thanks

[Mike Rathwell]

@drewhubley, mine is actually containerized and running in ECS. A graceful shutdown (setting desired tasks to 0) stops them cleanly. I did the cache blast for the times when Something Bad happens and they just... go away.

Jira and Confluence would normally take ~5 mins before. Now always takes ~15 mins BUT it always comes up.