Bitbucket Server should not start if the SSH plugin doesn't load

Summary

In some situations the SSH server plugin will fail to start up on Bitbucket Server.

This can make the mirroring feature completely stop as it is highly dependent on SSH.

This issue is potentially linked to BSERV-8210.

Steps to Reproduce

Not known.

Expected Results

SSH server comes up when Bitbucket Server is started.

Actual Results

In a few of our KBs, situations in which the SSH server do not come up have been documented, for example:

• SSH Server doesn't start
  • The KB above documents 2 scenarios:
    • Issue 1: A timeout caused by the generation of SecureRandom. The below exception is thrown in the atlassian-bitbucket.log file:

      2015-03-15 21:47:23,040 ERROR [spring-startup]  o.s.o.e.i.u.c.RunnableTimedExecution Closing runnable for context NonValidatingOsgiBundleXmlApplicationContext(bundle=com.atlassian.stash.ssh, 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
      2015-03-15 21:47:23,063 ERROR [spring-startup]  c.a.plugin.manager.PluginEnabler Unable to start the following plugins due to timeout while waiting for plugin to enable: com.atlassian.stash.ssh-plugin
      ...
      ...
      ...
      2015-03-15 21:47:26,966 ERROR [ThreadPoolAsyncTaskExecutor::Thread 12]  o.s.b.f.s.DefaultListableBeanFactory Destroy method on bean with name 'sshScmProtocol_osgiService' threw an exception
      java.lang.IllegalStateException: Invalid BundleContext.
          at org.apache.felix.framework.BundleContextImpl.checkValidity(BundleContextImpl.java:457) ~[org.apache.felix.framework-3.2.2.jar:na]
          at com.atlassian.stash.plugin.util.EventListenerBeanRegistrar.postProcessBeforeDestruction(EventListenerBeanRegistrar.java:50) ~[stash-plugin-util-3.7.1.jar:na]
          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_17]
          at java.lang.Thread.run(Thread.java:722) [na:1.7.0_17]
          ... 30 frames trimmed
      2015-03-15 21:47:26,971 ERROR [ThreadPoolAsyncTaskExecutor::Thread 12]  o.s.b.f.s.DefaultListableBeanFactory Destroy method on bean with name 'sshScmProtocol' threw an exception
      java.lang.IllegalStateException: Invalid BundleContext.
          at org.apache.felix.framework.BundleContextImpl.checkValidity(BundleContextImpl.java:457) ~[org.apache.felix.framework-3.2.2.jar:na]
          at com.atlassian.stash.plugin.util.EventListenerBeanRegistrar.postProcessBeforeDestruction(EventListenerBeanRegistrar.java:50) ~[stash-plugin-util-3.7.1.jar:na]
          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_17]
          at java.lang.Thread.run(Thread.java:722) [na:1.7.0_17]
          ... 30 frames trimmed
      2015-03-15 21:47:26,973 ERROR [ThreadPoolAsyncTaskExecutor::Thread 12]  o.s.b.f.s.DefaultListableBeanFactory Destroy method on bean with name 'sshKeyService_osgiService' threw an exception
      java.lang.IllegalStateException: Invalid BundleContext.
          at org.apache.felix.framework.BundleContextImpl.checkValidity(BundleContextImpl.java:457) ~[org.apache.felix.framework-3.2.2.jar:na]
          at com.atlassian.stash.plugin.util.EventListenerBeanRegistrar.postProcessBeforeDestruction(EventListenerBeanRegistrar.java:50) ~[stash-plugin-util-3.7.1.jar:na]
          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_17]
          at java.lang.Thread.run(Thread.java:722) [na:1.7.0_17]
          ... 30 frames trimmed
      2015-03-15 21:47:26,976 ERROR [ThreadPoolAsyncTaskExecutor::Thread 12]  o.s.b.f.s.DefaultListableBeanFactory Destroy method on bean with name 'sshConfigurationService_osgiService' threw an exception
      java.lang.IllegalStateException: Invalid BundleContext.
          at org.apache.felix.framework.BundleContextImpl.checkValidity(BundleContextImpl.java:457) ~[org.apache.felix.framework-3.2.2.jar:na]
          at com.atlassian.stash.plugin.util.EventListenerBeanRegistrar.postProcessBeforeDestruction(EventListenerBeanRegistrar.java:50) ~[stash-plugin-util-3.7.1.jar:na]
          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) [na:1.7.0_17]
          at java.lang.Thread.run(Thread.java:722) [na:1.7.0_17]
          ... 30 frames trimmed
      

    • The following also comes out in the catalina.out:

      15-Mar-2015 21:13:08.554 INFO [localhost-startStop-1] org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [65,569] milliseconds.
      (...)
      15-Mar-2015 21:25:46.539 INFO [localhost-startStop-1] org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [59,369] milliseconds.
      (...)
      15-Mar-2015 21:38:40.935 INFO [localhost-startStop-1] org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [97,334] milliseconds.
      (...)
      15-Mar-2015 21:45:36.446 INFO [localhost-startStop-1] org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [107,258] milliseconds.
      (...)
      

  • Issue 2: The following comes out on atlassian-bitbucket.log:

    2015-06-10 00:26:21,021 ERROR [ThreadPoolAsyncTaskExecutor::Thread 22]  c.a.plugin.osgi.factory.OsgiPlugin Unable to start the plugin container for plugin 'com.atlassian.stash.ssh-plugin'
    org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'sshServer' defined in URL [bundle://49.0:0/META-INF/spring/atlassian-plugins-components.xml]: Instantiation of bean failed; nested exception is org.springframework.beans.BeanInstantiationException: Could not instantiate bean class [com.atlassian.stash.internal.ssh.server.SshServer]: Constructor threw exception; nested exception is java.lang.IllegalStateException: BouncyCastle is not registered as expected
        at org.springframework.beans.factory.support.ConstructorResolver.autowireConstructor(ConstructorResolver.java:254) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
        at java.security.AccessController.doPrivileged(Native Method) ~[na:1.8.0_40]
        at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:728) ~[spring-context-4.1.6.RELEASE.jar:4.1.6.RELEASE]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_40]
        at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_40]
        ... 17 frames trimmed
    Caused by: org.springframework.beans.BeanInstantiationException: Could not instantiate bean class [com.atlassian.stash.internal.ssh.server.SshServer]: Constructor threw exception; nested exception is java.lang.IllegalStateException: BouncyCastle is not registered as expected
        at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:115) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
        ... 5 common frames omitted
    Caused by: java.lang.IllegalStateException: BouncyCastle is not registered as expected
        at com.google.common.base.Preconditions.checkState(Preconditions.java:145) ~[guava-11.0.2-atlassian-02.jar:na]
        at com.atlassian.stash.internal.ssh.server.SshServer.<init>(SshServer.java:61) ~[na:na]
        at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:100) ~[spring-beans-4.1.6.RELEASE.jar:4.1.6.RELEASE]
        ... 5 common frames omitted
    

• SSH add-on does not load when Bitbucket Server starts

  2014-05-01 09:27:19,729 WARN  [active-objects-ddl-0]  c.a.a.o.AOConfigurationServiceProviderImpl Didn't find any configuration service for bundle com.atlassian.bitbucket.bitbucket-audit nor any entities sc
  anning for default AO packages.
  2014-05-01 09:27:19,730 WARN  [ListenableFutureAdapter-thread-1]  c.a.a.o.ActiveObjectsServiceFactory Resubmitting AO bundle with longer timeout 180000 ms for bundle : com.atlassian.bitbucket.bitbucket-aud
  it [60]
  2014-05-01 09:27:21,749 ERROR [localhost-startStop-1]  c.a.plugin.manager.PluginEnabler Unable to start the following plugins due to timeout while waiting for plugin to enable: com.atlassian.bitbucket.
  ssh-plugin
  2014-05-01 09:27:21,753 ERROR [ThreadPoolAsyncTaskExecutor::Thread 2]  o.s.o.e.i.a.ContextLoaderListener Application context refresh failed (NonValidatingOsgiBundleXmlApplicationContext(bundle=com.
  atlassian.bitbucket.ssh, config=osgibundle:/META-INF/spring/*.xml))
  org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'sshServer_osgiService': Initialization of bean failed; nested exception is java.lang.IllegalStateException: C
  an only register services while bundle is active or activating.
          at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:480) ~[spring-beans-4.0.2.RELEASE.jar:4.0.2.RELEASE]
          at java.security.AccessController.doPrivileged(Native Method) ~[na:1.7.0_09-icedtea]
          at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:728) ~[spring-context-4.0.2.RELEASE.jar:4.0.2.RELEASE]
          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) [na:1.7.0_09-icedtea]
          at java.lang.Thread.run(Thread.java:722) [na:1.7.0_09-icedtea]
          ... 14 frames trimmed
  Caused by: java.lang.IllegalStateException: Can only register services while bundle is active or activating.
          at org.apache.felix.framework.Felix.registerService(Felix.java:2831) ~[org.apache.felix.framework-3.0.9.jar:na]
          ... 5 common frames omitted
  

Notes

• Cause for issue 1:
  The problem is down to the /dev/random device having insufficient entropy when Bitbucket Server is started and because this device blocks until sufficient entropy is attained in the system it blocks both the Tomcat start-up process and the SSH plugin start-up process.
• Cause of issue 2:
  The presence of the following JAVA option will cause this to occur:
  -Dsun.net.spi.nameservice.provider.1=dns,sun
• Cause for issue 3:
  Potential high load on the server when Bitbucket is coming up.

Workaround

• Issue 1:
  The best workaround is to specify the /dev/urandom device as the preferred egd or entropy gathering daemon. This is done by editing setenv.sh and adding -Djava.security.egd=file:/dev/./urandom to JVM_SUPPORT_RECOMMENDED_ARGS and and restarting the Bitbucket Server service.

  #
  # Occasionally Atlassian Support may recommend that you set some specific JVM arguments.  You can use this variable
  # below to do that.
  #
  JVM_SUPPORT_RECOMMENDED_ARGS="-Djava.security.egd=file:/dev/./urandom"
  

  
  Please note that the dots and slashed in java.security.egd must be exactly as above (due to this Java not-quite-a-bug): https://bugs.openjdk.java.net/browse/JDK-6202721

  For a definitive solution, you should try to work out why your system has insufficient entropy at the point Stash is launched. This will probably be tightly coupled to what else is running on in your virtual machine before Bitbucket Server is started.

• Issue 2:
  Remove the -Dsun.net.spi.nameservice.provider.1=dns,sun option from your JVM and restart the Bitbucket Server service.

• Issue 3:

1. Shut Bitbucket Server down.
2. Remove the following directories. They will be rebuilt when Bitbucket Server starts again.

   $BITBUCKET_HOME/plugins/.bundled-plugins/
   $BITBUCKET_HOME/plugins/.osgi-cache/
   

3. From the database, remove any required plugins from the plugin-state table (see https://jira.atlassian.com/browse/BSERV-4290 for more information).
   1. Restart Bitbucket Server.
   2. Upon starting up, Bitbucket Server will re-extract the required plugins from <Bitbucket Server installation directory>/atlassian-bitbucket/WEB-INF/classes/bundled-plugins.zip and rebuild those plugin directories.

PS: after fixing this, Bitbucket server won't come up if the SSH server fails to start. The following message is shown on the UI: