Confluence startup takes very long time afer upgrade to 6.15.2

[thiema]

After upgrading confluence from 5.9.3 to 6.15.9 the startup of confluence seems to be delayed or something like.

I am using offical docker image atlassian/confluence-server:6.15.9. I did the upgrade from a docker container running a custom jira installation based on centos:centos7 image. I followed the upgrade instructions according to documentation: https://confluence.atlassian.com/conf615/upgrading-confluence-manually-967338800.html

In the tomcat log one can see silence of around 7 minutes until the webapp is started:

confluence_1 | 07-Oct-2019 08:09:51.809 INFO [Catalina-utility-2] org.springframework.web.servlet.DispatcherServlet.initServletBean FrameworkServlet 'dispatcher': initialization completed in 2147 ms
confluence_1 | 07-Oct-2019 08:17:11.732 INFO [Catalina-utility-2] org.apache.catalina.startup.HostConfig.deployDescriptor Deploying deployment descriptor [/opt/atlassian/confluence/conf/Standalone/localhost/synchrony-proxy.xml]
confluence_1 | 07-Oct-2019 08:17:11.737 WARNING [Catalina-utility-2] org.apache.catalina.startup.HostConfig.deployDescriptor The path attribute with value [/synchrony-proxy] in deployment descriptor [/opt/atlassian/confluence/conf/Standalone/localhost/synchrony-proxy.xml] has been ignored
confluence_1 | 07-Oct-2019 08:17:11.757 WARNING [Catalina-utility-2] org.apache.catalina.startup.SetContextPropertiesRule.begin [SetContextPropertiesRule]{Context} Setting property 'debug' to '0' did not find a matching property.
confluence_1 | 07-Oct-2019 08:17:13.610 INFO [Catalina-utility-2] org.apache.catalina.core.ApplicationContext.log Spring WebApplicationInitializers detected on classpath: [com.atlassian.synchrony.proxy.SynchronyDispatcherServletInitializer@6c0babb3]
confluence_1 | 07-Oct-2019 08:17:13.731 INFO [Catalina-utility-2] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
confluence_1 | 07-Oct-2019 08:17:14.067 INFO [Catalina-utility-2] org.apache.catalina.core.ApplicationContext.log Initializing Spring FrameworkServlet 'dispatcher'
confluence_1 | 07-Oct-2019 08:17:14.074 INFO [Catalina-utility-2] org.springframework.web.servlet.DispatcherServlet.initServletBean FrameworkServlet 'dispatcher': initialization started
confluence_1 | 07-Oct-2019 08:17:14.096 INFO [Catalina-utility-2] org.springframework.web.context.support.AnnotationConfigWebApplicationContext.prepareRefresh Refreshing WebApplicationContext for namespace 'dispatcher-servlet': startup date [Mon Oct 07 08:17:14 GMT 2019]; root of context hierarchy
confluence_1 | 07-Oct-2019 08:17:14.323 INFO [Catalina-utility-2] org.springframework.web.context.support.AnnotationConfigWebApplicationContext.loadBeanDefinitions Registering annotated classes: [class com.atlassian.synchrony.proxy.websocket.WebSocketConfig,class com.atlassian.synchrony.proxy.web.SynchronyWebMvcConfig]
confluence_1 | SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
confluence_1 | SLF4J: Defaulting to no-operation (NOP) logger implementation
confluence_1 | SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
confluence_1 | 07-Oct-2019 08:17:15.198 INFO [Catalina-utility-2] org.springframework.scheduling.concurrent.ThreadPoolTaskScheduler.initialize Initializing ExecutorService 'defaultSockJsTaskScheduler'
confluence_1 | 07-Oct-2019 08:17:15.262 INFO [Catalina-utility-2] org.springframework.web.socket.server.support.WebSocketHandlerMapping.registerHandler Mapped URL path [/v1/bayeux-sync1] onto handler of type [class org.springframework.web.socket.server.support.WebSocketHttpRequestHandler]
confluence_1 | 07-Oct-2019 08:17:15.579 INFO [Catalina-utility-2] org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping.register Mapped "{[/reload],methods=[PUT]}" onto public org.springframework.http.ResponseEntity com.atlassian.synchrony.proxy.web.SynchronyProxyRestController.reloadConfiguration(com.atlassian.synchrony.proxy.web.SynchronyProxyConfigPayload)
confluence_1 | 07-Oct-2019 08:17:15.582 INFO [Catalina-utility-2] org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping.register Mapped "{[/healthcheck]}" onto public com.atlassian.synchrony.proxy.web.HealthCheckResult com.atlassian.synchrony.proxy.web.SynchronyProxyRestController.getSynchronyProxyInfo()
confluence_1 | 07-Oct-2019 08:17:15.612 INFO [Catalina-utility-2] org.springframework.web.servlet.handler.SimpleUrlHandlerMapping.registerHandler Mapped URL path [/**] onto handler of type [class org.springframework.web.servlet.resource.DefaultServletHttpRequestHandler]
confluence_1 | 07-Oct-2019 08:17:16.260 INFO [Catalina-utility-2] org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.initControllerAdviceCache Looking for @ControllerAdvice: WebApplicationContext for namespace 'dispatcher-servlet': startup date [Mon Oct 07 08:17:14 GMT 2019]; root of context hierarchy
confluence_1 | 07-Oct-2019 08:17:16.611 INFO [Catalina-utility-2] org.springframework.context.support.DefaultLifecycleProcessor.start Starting beans in phase 2147483647
confluence_1 | 07-Oct-2019 08:17:16.641 INFO [Catalina-utility-2] org.springframework.web.servlet.DispatcherServlet.initServletBean FrameworkServlet 'dispatcher': initialization completed in 2565 ms
confluence_1 | 07-Oct-2019 08:17:16.644 INFO [Catalina-utility-2] org.apache.catalina.startup.HostConfig.deployDescriptor Deployment of deployment descriptor [/opt/atlassian/confluence/conf/Standalone/localhost/synchrony-proxy.xml] has finished in [4,912] ms
confluence_1 | 07-Oct-2019 08:17:16.648 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8090"]
confluence_1 | 07-Oct-2019 08:17:16.799 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [450,212] milliseconds

I am unsure which logs to provide from file atlassian-confluence.log, because There are tons of warnings, hard to say what is relevant.

2019-10-07 08:10:24,571 WARN [Catalina-utility-1] [org.twdata.pkgscanner.ExportPackageListBuilder] logDuplicateWarning Package Scanner found duplicates for package 'javax.annotation' with di
fferent versions. Files: javax.annotation-api-1.3.2.jar and jsr305-3.0.1.jar
'/opt/atlassian/confluence/confluence/WEB-INF/lib/javax.annotation-api-1.3.2.jar'
'/opt/atlassian/confluence/confluence/WEB-INF/lib/jsr305-3.0.1.jar'
2019-10-07 08:10:27,669 WARN [FelixStartLevel] [extender.internal.support.ExtenderConfiguration] addDefaultDependencyFactories Gemini Blueprint extensions bundle not present, annotation proc
essing disabled.
2019-10-07 08:10:56,571 WARN [ThreadPoolAsyncTaskExecutor::Thread 8] [spring.scanner.util.ProductFilterUtil] detectProduct Couldn't detect product, will use ProductFilter.ALL
2019-10-07 08:11:39,489 WARN [Navlink Plugin Executor:thread-1] [confluence.impl.vcache.SynchronousExternalCache] lambda$get$11 Failed to read entry from cache 'com.atlassian.bandana.Bandana
Persister': Failed due to UNCLASSIFIED_FAILURE
... last warning (Failed to read entry from cache) happens every 10 sec
2019-10-07 08:15:59,357 WARN [Navlink Plugin Executor:thread-5] [confluence.impl.vcache.SynchronousExternalCache] lambda$get$11 Failed to read entry from cache 'com.atlassian.bandana.BandanaPersister': Failed due to UNCLASSIFIED_FAILURE
2019-10-07 08:16:00,464 WARN [Spring DM Context Creation Timer] [internal.dependencies.startup.DependencyWaiterApplicationContextExecutor] timeout Timeout occurred before finding service dependencies for [NonValidatingOsgiBundleXmlApplicationContext(bundle=com.atlassian.gadgets.directory, config=osgibundle:/META-INF/spring/*.xml)]
2019-10-07 08:16:00,470 ERROR [Spring DM Context Creation Timer] [plugin.osgi.factory.OsgiPlugin] logAndClearOustandingDependencies Plugin 'com.atlassian.gadgets.directory' never resolved service '&externalGadgetSpecStore' with filter '(&(objectClass=com.atlassian.gadgets.directory.spi.ExternalGadgetSpecStore)(objectClass=com.atlassian.gadgets.directory.spi.ExternalGadgetSpecStore))'
2019-10-07 08:16:00,470 ERROR [Spring DM Context Creation Timer] [plugin.osgi.factory.OsgiPlugin] logAndClearOustandingDependencies Plugin 'com.atlassian.gadgets.directory' never resolved service '&subscribedGadgetFeedStore' with filter '(&(objectClass=com.atlassian.gadgets.directory.spi.SubscribedGadgetFeedStore)(objectClass=com.atlassian.gadgets.directory.spi.SubscribedGadgetFeedStore))'
2019-10-07 08:16:00,471 ERROR [Spring DM Context Creation Timer] [plugin.osgi.factory.OsgiPlugin] logAndClearOustandingDependencies Plugin 'com.atlassian.gadgets.directory' never resolved service '&directoryPermissionService' with filter '(&(objectClass=com.atlassian.gadgets.directory.spi.DirectoryPermissionService)(objectClass=com.atlassian.gadgets.directory.spi.DirectoryPermissionService))'
2019-10-07 08:16:00,473 ERROR [Spring DM Context Creation Timer] [plugin.osgi.factory.OsgiPlugin] onPluginContainerFailed Unable to start the plugin container for plugin 'com.atlassian.gadgets.directory'
org.springframework.context.ApplicationContextException: Application context initialization for 'com.atlassian.gadgets.directory' has timed out waiting for (|(&(objectClass=com.atlassian.gadgets.directory.spi.DirectoryPermissionService)(objectClass=com.atlassian.gadgets.directory.spi.DirectoryPermissionService))(&(objectClass=com.atlassian.gadgets.directory.spi.ExternalGadgetSpecStore)(objectClass=com.atlassian.gadgets.directory.spi.ExternalGadgetSpecStore))(&(objectClass=com.atlassian.gadgets.directory.spi.SubscribedGadgetFeedStore)(objectClass=com.atlassian.gadgets.directory.spi.SubscribedGadgetFeedStore)))
at org.eclipse.gemini.blueprint.extender.internal.dependencies.startup.DependencyWaiterApplicationContextExecutor.timeout(DependencyWaiterApplicationContextExecutor.java:489)
at org.eclipse.gemini.blueprint.extender.internal.dependencies.startup.DependencyWaiterApplicationContextExecutor.access$000(DependencyWaiterApplicationContextExecutor.java:54)
at org.eclipse.gemini.blueprint.extender.internal.dependencies.startup.DependencyWaiterApplicationContextExecutor$WatchDogTask.run(DependencyWaiterApplicationContextExecutor.java:109)
at java.util.TimerThread.mainLoop(Unknown Source)
at java.util.TimerThread.run(Unknown Source)
2019-10-07 08:16:00,497 WARN [Gemini Blueprint context shutdown thread 1] [beans.factory.support.DisposableBeanAdapter] destroy Invocation of destroy method failed on bean with name 'dashboardItemModulesList': java.lang.NullPointerException
2019-10-07 08:16:00,498 WARN [Gemini Blueprint context shutdown thread 1] [beans.factory.support.DisposableBeanAdapter] destroy Invocation of destroy method failed on bean with name 'localGadgetSpecProviders': java.lang.NullPointerException
2019-10-07 08:16:00,500 WARN [Gemini Blueprint context shutdown thread 1] [beans.factory.support.DisposableBeanAdapter] destroy Invocation of destroy method failed on bean with name 'gadgetSpecProviders': java.lang.NullPointerException

[Shannon S]

Hello Thiema,

I see my colleague was able to address your SPAM questions; it appears that the filter was being triggered, probably due to the logs that you sent. It happens sometimes, so thank you for letting us know about it.

For your atlassian-confluence.log, I would recommend starting up Confluence again while tailing the logs, then look for anything that says ERROR instead of INFO or WARN during startup, It should follow with a line that starts with 'caused by' to let you know the exact problem in starting up. 

When you're able to get more information from the logs about the startup, please send it along here or use something like Dropbox or Pastebin to avoid any issues with the spam filter.

Regards,

Shannon

[thiema]

Hello,

thanks for your reply.

logs of severity WARN and ERROR found in file atlassian-confluence.log during startup: https://pastebin.com/KKCckwPb

I already tried to enable the plugin com.atlassian.confluence.plugins.gadgets.spi, by setting boolean to true: like this

...

<entry>
<string>com.atlassian.confluence.plugins.gadgets.spi</string>
<boolean>false</boolean>
</entry>

...

and updating database table BANDANA manually. If I do this Confluence breaks, and will fail to start.

[Shannon S]

Hello @thiema,

Thank you for providing those logs.

It looks like you are running into this issue:

• Plugins are disabled at startup and various timeout errors appear in the logs after startup 

The first step is to clear your plugins cache:

1. Shutdown Confluence

2. Ensure the user running Confluence has full read/write privileges to the confluence-home directory.

3. Remove the following directories This will remove the plugin cache files only and will not permanently remove any plugins. These directories will be recreated during the next Confluence startup.  However, some third-party plugins may store metadata in these directories, so we recommend creating a temporary backup of the directories.

   • <confluence-home>/bundled-plugins
   • <confluence-home>/plugins-cache
   • <confluence-home>/plugins-osgi-cache
   • <confluence-home>/plugins-temp
   • <confluence-home>/bundled-plugins_language

4. Start Confluence

If that doesn't solve your issue, then have a look at the article for the following workarounds.

One more thing, since you mentioned you were using Docker. I know recently that the Atlassian Docker images are resetting the server.xml file upon restart. Is there a chance that you had modifications in that file, or another, such as confluence.cfg.xml? Are those changes still there, or have they been reset?

If they have, some users were discussing the same on the thread Server.xml is overwritten by Dockerfile and were able to resolve it.

I hope this helps, but let me know if you have any issues.

Regards,

Shannon