SSH Server doesn't start
Symptoms
Stash comes up but the SSH server won't start.
We mapped out a few situations in which that could happen.
Issue #1:
The following appears in the atlassian-stash.log
:
2015-03-15 21:45:39,968 INFO [spring-startup] c.a.s.i.server.BuildInfoLogger Starting Stash 3.7.1 (b3e3aaf built on Tue Mar 10 05:08:08 CET 2015)
2015-03-15 21:45:39,978 INFO [spring-startup] c.a.s.i.server.BuildInfoLogger JVM: Oracle Corporation Java HotSpot(TM) 64-Bit Server VM 1.7.0_17-b02
2015-03-15 21:45:39,992 INFO [spring-startup] c.a.s.internal.home.HomeLockAcquirer Successfully acquired lock on home directory /var/atlassian/application-data/stash
2015-03-15 21:45:44,176 INFO [spring-startup] c.a.s.internal.home.HomeLockAcquirer Successfully acquired lock on home directory /var/atlassian/application-data/stash/shared
...
...
...
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 appears 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 appears in the atlassian.stash.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
Cause
Issue #1:
From catalina.out
, we can see a long time being taken to create SecureRandom
.
The problem is down to the /dev/random
device having insufficient entropy when Stash 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.
Issue #2:
The presence of the following JAVA option will cause this to occur;
-Dsun.net.spi.nameservice.provider.1=dns,sun
Resolution
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 Stash 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 Stash is started.
Issue #2:
Remove the option and restart the Stash service.