Service fails to start with BITBUCKET_HOME on network drive - SpringMVC could not be started

[Gavin]

I recently migrated BBS to a new server and subsequently moved the repositories (BITBUCKET_HOME) to a network drive.

BBS works fine if I launch it as a normal Windows process using the start-bitbucket.bat batch file in the 'bin' directory.

When trying to run as a service, the startup sequence fails with the error message

SpringMVC dispatcher [springMvc] could not be started

The service is set to run as a local user and that user has full control of the BITBUCKET_HOME folder on the network.

Other points to note...

• BitBucket Server v6.4.0 (note install directory is 6.4.1)
• Accessing network share via symbolic link (mklink) rather than mapped drive or UNC path
• Setting BITBUCKET_HOME to use a mapped drive stops the service from starting altogether
• The log reports 'connection refused' but it's not clear what is refusing the connection or why

Any thoughts of suggestions on how to resolve this issue would be greatly appreciated :-)

. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.1.3.RELEASE)


2020-07-30 22:13:10,786 INFO [main] c.a.b.i.b.BitbucketServerApplication Starting BitbucketServerApplication on LEA-BITBUCKET-1 with PID 5932 (C:\Atlassian\Bitbucket\6.4.1\app\WEB-INF\classes started by batman in C:\Atlassian\Bitbucket\6.4.1\app)
2020-07-30 22:13:10,786 INFO [main] c.a.b.i.b.BitbucketServerApplication The following profiles are active: windows
2020-07-30 22:13:11,296 INFO [main] c.a.b.i.boot.log.BuildInfoLogger Starting Bitbucket 6.4.0 (31a17cd built on Mon Jun 17 06:06:41 BST 2019)
2020-07-30 22:13:11,296 INFO [main] c.a.b.i.boot.log.BuildInfoLogger JVM: Oracle Corporation Java HotSpot(TM) 64-Bit Server VM 1.8.0_172-b11
2020-07-30 22:13:13,093 INFO [main] c.a.b.i.b.BitbucketServerApplication Started BitbucketServerApplication in 4.167 seconds (JVM running for 7.886)
2020-07-30 22:13:15,923 INFO [spring-startup] c.a.s.internal.home.HomeLockAcquirer Successfully acquired lock on home directory \\lea-nas-bit-1\Repos\BBSData
2020-07-30 22:13:20,140 INFO [spring-startup] c.a.s.internal.home.HomeLockAcquirer Successfully acquired lock on home directory \\lea-nas-bit-1\Repos\BBSData\shared
2020-07-30 22:13:21,736 WARN [spring-startup] com.hazelcast.instance.Node [192.168.113.217]:5701 [batman] [3.11.1] No join method is enabled! Starting standalone.
2020-07-30 22:13:32,427 INFO [hz.hazelcast.event-1] com.atlassian.bitbucket Switching to log level [DEBUG]
2020-07-30 22:13:32,427 WARN [hz.hazelcast.event-3] ROOT Switching to log level [INFO]
2020-07-30 22:13:32,427 WARN [hz.hazelcast.event-4] org.hibernate Switching to log level [INFO]
2020-07-30 22:13:32,427 INFO [hz.hazelcast.event-1] com.atlassian.stash Switching to log level [DEBUG]
2020-07-30 22:13:32,427 WARN [hz.hazelcast.event-4] org.springframework Switching to log level [INFO]
2020-07-30 22:13:32,427 ERROR [hz.hazelcast.event-3] com.atlassian.event.remote Switching to log level [DEBUG]
2020-07-30 22:13:32,427 INFO [hz.hazelcast.event-3] c.h.i.diagnostics.HealthMonitor Switching to log level [DEBUG]
2020-07-30 22:13:32,833 DEBUG [spring-startup] c.a.s.i.s.DefaultOperatingSystemService Pre-fetch of CPU load: 0.0
2020-07-30 22:13:32,865 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [git-lfs] Configuration-derived value for fixed ticket limit: 80
2020-07-30 22:13:32,880 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [git-lfs] Configured fixed throttling: [tickets=80, queue-timeout=0s]
2020-07-30 22:13:32,880 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [scm-hosting] Configuration-derived value for minimum ticket limit: 8
2020-07-30 22:13:32,880 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [scm-hosting] Configuration-derived value for maximum ticket limit: 32
2020-07-30 22:13:32,880 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [scm-hosting] The total memory on this machine is 16158 MB
2020-07-30 22:13:32,880 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [scm-hosting] Estimated typical memory per ticket: 256 MB
2020-07-30 22:13:32,880 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [scm-hosting] Estimated application webapp requirement: 1024 MB
2020-07-30 22:13:32,880 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [scm-hosting] Estimated application search requirement: 512 MB
2020-07-30 22:13:32,880 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [scm-hosting] Estimated combined application webapp and search requirements: 1536 MB
2020-07-30 22:13:32,880 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [scm-hosting] Estimated remaining memory available to ticketed operations: 14622 MB
2020-07-30 22:13:32,880 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [scm-hosting] Estimated safe max tickets: 57
2020-07-30 22:13:32,880 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [scm-hosting] Choosing an adaptive ticket range of 8..32
2020-07-30 22:13:32,896 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [scm-hosting] Configuration-derived value for fixed ticket limit: 12
2020-07-30 22:13:32,896 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [scm-hosting] Configured adaptive throttling: [range=8..32, no-cpu-tickets=12, cpu-target=0.75, cpu-per-typical-ticket=0.01, cpu-historical-weighting=0.8, interval=5s, queue-timeout=300s, no-cpu-threshold=20s]
2020-07-30 22:13:32,896 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [scm-command] Configuration-derived value for fixed ticket limit: 25
2020-07-30 22:13:32,896 DEBUG [spring-startup] c.a.s.i.t.ResourceThrottleStrategyProvider [scm-command] Configured fixed throttling: [tickets=25, queue-timeout=2s]
2020-07-30 22:13:32,912 DEBUG [spring-startup] c.a.s.i.t.SemaphoreThrottleService Configured resource [scm-hosting]
2020-07-30 22:13:32,912 DEBUG [spring-startup] c.a.s.i.t.SemaphoreThrottleService Configured resource [git-lfs]
2020-07-30 22:13:32,912 DEBUG [spring-startup] c.a.s.i.t.SemaphoreThrottleService Configured resource [scm-command]
2020-07-30 22:13:34,208 INFO [spring-startup] c.a.s.i.h.s.WindowsHookScriptCommandLineFactory Found GNU bash at C:\Program Files\Git\bin\bash.exe
2020-07-30 22:13:34,396 DEBUG [spring-startup] c.a.s.i.i.u.MoveSnapshotDirUpgradeTask Skipping upgrade task to move the repository snapshots as this has already been completed
2020-07-30 22:13:36,708 WARN [spring-startup] o.s.w.c.s.XmlWebApplicationContext Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'mailSupportInfo' defined in URL [jar:file:/C:/Atlassian/Bitbucket/6.4.1/app/WEB-INF/lib/bitbucket-service-impl-6.4.0.jar!/com/atlassian/stash/internal/mail/MailSupportInfo.class]: Unsatisfied dependency expressed through constructor parameter 0; nested exception is org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'dateFormatter' defined in URL [jar:file:/C:/Atlassian/Bitbucket/6.4.1/app/WEB-INF/lib/bitbucket-service-impl-6.4.0.jar!/com/atlassian/stash/internal/util/DefaultDateFormatter.class]: Unsatisfied dependency expressed through constructor parameter 2; nested exception is org.springframework.beans.factory.BeanExpressionException: Expression parsing failed; nested exception is org.springframework.expression.spel.SpelEvaluationException: EL1021E: A problem occurred whilst attempting to access the property 'dateFormatProperties': 'Error creating bean with name 'dateFormatProperties' defined in class path resource [stash-context.xml]: Invocation of init method failed; nested exception is java.net.ConnectException: Connection refused: connect'
2020-07-30 22:13:36,724 DEBUG [spring-startup] c.a.s.i.c.HazelcastBucketedExecutor Executor service has shutdown gracefully
2020-07-30 22:13:36,739 INFO [spring-startup] o.s.s.c.ThreadPoolExecutorFactoryBean Shutting down ExecutorService 'org.springframework.scheduling.concurrent.ThreadPoolExecutorFactoryBean#7ba81c63'
2020-07-30 22:13:36,755 DEBUG [spring-startup] c.a.s.i.topic.HazelcastTopicService Executor service has shutdown gracefully
2020-07-30 22:13:36,770 INFO [spring-startup] o.h.internal.SessionFactoryRegistry HHH000097: Unbound factory from JNDI name: bitbucket.core
2020-07-30 22:13:36,770 INFO [spring-startup] c.a.s.internal.home.HomeLockAcquirer Releasing lock on \\lea-nas-bit-1\Repos\BBSData\shared
2020-07-30 22:13:36,786 DEBUG [spring-startup] c.a.s.i.e.SingletonEventExecutorFactory Executor service has shutdown gracefully
2020-07-30 22:13:36,786 INFO [spring-startup] com.zaxxer.hikari.HikariDataSource bitbucket - Shutdown initiated...
2020-07-30 22:13:36,802 INFO [spring-startup] com.zaxxer.hikari.HikariDataSource bitbucket - Shutdown completed.
2020-07-30 22:13:36,802 INFO [spring-startup] c.a.s.internal.home.HomeLockAcquirer Releasing lock on \\lea-nas-bit-1\Repos\BBSData
2020-07-30 22:13:36,817 ERROR [spring-startup] c.a.j.s.w.s.JohnsonDispatcherServlet SpringMVC dispatcher [springMvc] could not be started
org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'mailSupportInfo' defined in URL [jar:file:/C:/Atlassian/Bitbucket/6.4.1/app/WEB-INF/lib/bitbucket-service-impl-6.4.0.jar!/com/atlassian/stash/internal/mail/MailSupportInfo.class]: Unsatisfied dependency expressed through constructor parameter 0; nested exception is org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'dateFormatter' defined in URL [jar:file:/C:/Atlassian/Bitbucket/6.4.1/app/WEB-INF/lib/bitbucket-service-impl-6.4.0.jar!/com/atlassian/stash/internal/util/DefaultDateFormatter.class]: Unsatisfied dependency expressed through constructor parameter 2; nested exception is org.springframework.beans.factory.BeanExpressionException: Expression parsing failed; nested exception is org.springframework.expression.spel.SpelEvaluationException: EL1021E: A problem occurred whilst attempting to access the property 'dateFormatProperties': 'Error creating bean with name 'dateFormatProperties' defined in class path resource [stash-context.xml]: Invocation of init method failed; nested exception is java.net.ConnectException: Connection refused: connect'
at org.springframework.beans.factory.support.ConstructorResolver.createArgumentArray(ConstructorResolver.java:769)
at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:877)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:549)
at javax.servlet.GenericServlet.init(GenericServlet.java:158)
at java.lang.Thread.run(Thread.java:748)
... 18 frames trimmed
Caused by: org.springframework.beans.factory.UnsatisfiedDependencyException: Error creating bean with name 'dateFormatter' defined in URL [jar:file:/C:/Atlassian/Bitbucket/6.4.1/app/WEB-INF/lib/bitbucket-service-impl-6.4.0.jar!/com/atlassian/stash/internal/util/DefaultDateFormatter.class]: Unsatisfied dependency expressed through constructor parameter 2; nested exception is org.springframework.beans.factory.BeanExpressionException: Expression parsing failed; nested exception is org.springframework.expression.spel.SpelEvaluationException: EL1021E: A problem occurred whilst attempting to access the property 'dateFormatProperties': 'Error creating bean with name 'dateFormatProperties' defined in class path resource [stash-context.xml]: Invocation of init method failed; nested exception is java.net.ConnectException: Connection refused: connect'
... 6 common frames omitted
Caused by: org.springframework.beans.factory.BeanExpressionException: Expression parsing failed; nested exception is org.springframework.expression.spel.SpelEvaluationException: EL1021E: A problem occurred whilst attempting to access the property 'dateFormatProperties': 'Error creating bean with name 'dateFormatProperties' defined in class path resource [stash-context.xml]: Invocation of init method failed; nested exception is java.net.ConnectException: Connection refused: connect'
at org.springframework.context.expression.StandardBeanExpressionResolver.evaluate(StandardBeanExpressionResolver.java:164)
... 5 common frames omitted
Caused by: org.springframework.expression.spel.SpelEvaluationException: EL1021E: A problem occurred whilst attempting to access the property 'dateFormatProperties': 'Error creating bean with name 'dateFormatProperties' defined in class path resource [stash-context.xml]: Invocation of init method failed; nested exception is java.net.ConnectException: Connection refused: connect'
at org.springframework.expression.spel.ast.PropertyOrFieldReference.readProperty(PropertyOrFieldReference.java:209)
at org.springframework.expression.spel.ast.PropertyOrFieldReference.getValueInternal(PropertyOrFieldReference.java:104)
at org.springframework.expression.spel.ast.PropertyOrFieldReference.getValueInternal(PropertyOrFieldReference.java:91)
at org.springframework.expression.spel.ast.SpelNodeImpl.getValue(SpelNodeImpl.java:109)
at org.springframework.expression.spel.standard.SpelExpression.getValue(SpelExpression.java:265)
at org.springframework.context.expression.StandardBeanExpressionResolver.evaluate(StandardBeanExpressionResolver.java:161)
... 5 common frames omitted
Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'dateFormatProperties' defined in class path resource [stash-context.xml]: Invocation of init method failed; nested exception is java.net.ConnectException: Connection refused: connect
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1762)
at org.springframework.context.expression.BeanExpressionContextAccessor.read(BeanExpressionContextAccessor.java:45)
at org.springframework.expression.spel.ast.PropertyOrFieldReference.readProperty(PropertyOrFieldReference.java:204)
... 10 common frames omitted
Caused by: java.net.ConnectException: Connection refused: connect
at java.net.DualStackPlainSocketImpl.waitForConnect(Native Method)
at java.net.DualStackPlainSocketImpl.socketConnect(DualStackPlainSocketImpl.java:85)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:172)
at java.net.Socket.connect(Socket.java:589)
at sun.net.ftp.impl.FtpClient.doConnect(FtpClient.java:962)
at sun.net.ftp.impl.FtpClient.tryConnect(FtpClient.java:924)
at sun.net.ftp.impl.FtpClient.connect(FtpClient.java:1019)
at sun.net.ftp.impl.FtpClient.connect(FtpClient.java:1005)
at sun.net.www.protocol.ftp.FtpURLConnection.connect(FtpURLConnection.java:294)
at sun.net.www.protocol.ftp.FtpURLConnection.getInputStream(FtpURLConnection.java:400)
at org.springframework.core.io.UrlResource.getInputStream(UrlResource.java:173)
at org.springframework.core.io.support.EncodedResource.getInputStream(EncodedResource.java:159)
at org.springframework.core.io.support.PropertiesLoaderUtils.fillProperties(PropertiesLoaderUtils.java:99)
at org.springframework.core.io.support.PropertiesLoaderSupport.loadProperties(PropertiesLoaderSupport.java:181)
at org.springframework.core.io.support.PropertiesLoaderSupport.mergeProperties(PropertiesLoaderSupport.java:162)
... 12 common frames omitted
2020-07-30 22:13:36,849 INFO [spring-startup] c.a.j.s.l.LifecycleDispatcherServlet$1 Completed initialization in 23703 ms
2020-07-30 22:14:23,042 WARN [http-nio-7990-exec-1] c.a.j.s.w.f.BypassableDelegatingFilterProxy Bypassing [hazelcastFilter]; no Spring WebApplicationContext is available

[Manuel Bähnisch · Accepted solution]

Hi Gavin,

got it running. The following files were missing in the BitbucketHome\shared folder:

1. bitbucket.properties
2. date-formats.properties
3. help-paths.properties

1. contains the database connection details. I got the files from a previous run where I started bitbucket on the windows shell (not as a service).

2. can be found in atlassian-bitbucket-7.4.1-source.zip\bitbucket-7.4.1-source\bitbucket-parent\webapp\default\src\main\resources\

3. can be found in c:\Users\mbaehnisch\Downloads\atlassian-bitbucket-7.4.1-source.zip\bitbucket-7.4.1-source\bitbucket-parent\webapp\default\src\main\resources\help

The files are in the jars though and the jars are part of the JAVA_PATH environment. I have no clue why this causes an error. Looking at the stash-context.xml in the sources the classpath is defined as the internal file as part of the jar and the file in the directory. So it should be able to find both files in the classpath.

Hope this helps.

Manuel

[Gavin]

Hi Manuel,

Many thanks for the update. I'll have a look at it again this evening after my Users have finished for the day (they get grumpy if I take BB down whilst they're trying to work on it). I'll let you know how I got on in a few hours if that's OK?

BR,
Gavin

[Gavin]

Hi Enamuel,

Thanks for the suggestions and glad you managed to resolve the issue on your installation. I added the two missing properties files (the other was already there) but unfortunately that didn't fix it for me.

Many thanks anyway.

Best regards,
Gavin

[Manuel Bähnisch]

Hi Gavin,

sorry for the late reply, but two more things that worked for me:

In case you haven't found out yourself: you can switch on debug logging in the bitbucket.properties file via the following lines:

logging.logger.ROOT=DEBUG
logging.logger.com.atlassian.bitbucket=DEBUG

That helped me allot to drill down the problem in detail.

I managed to get it running by the following installation routine:

1. Install Bitbucket by starting the *.exe file from a cmd as an administrator
2. Configure the UNC path, i used \\server\share\BitbucketHome.
3. Don't install it as a service - that will be installed later manually
4. At the end of the installation I didn't choose "Launch now"
5. In my case I had to add the MySQL 8 jdbc driver into the BitbucketHome\lib dir.
6. in the BitbucketHome\bin dir I edited the set-bitbucket-home.bat by removing the escaped backslahes (e. g. \\\\server\\share\\BitbucketHome to \\server\share\BitbucketHome)
7. Added environment variables BITBUCKET_HOME, CONF_DIR, DATA_DIR, LOG_DIR, JAVA_HOME and PATH according to https://confluence.atlassian.com/bitbucketserver/running-bitbucket-server-as-a-windows-service-776640048.html
8. Logged off/on to get the variables working
9. Manual installation of the services according to link above (service install for Bitbucket, robocopy followed by service install for the elasticsearch).
10. In the elasticsearch service I changed the java.io.tmpdir variable to a vm local drive, e. g. c:\tmp and created that folder manually
11. Added the property files (date-format and help-path) in BitbucketHome\shared and add an empty bitbucket.properties file
12. Started both services and finished the configuration (database, etc.) via browser

The services are then running under the local system account not the atlbitbucket user, as the routine would install it via the installation.exe. 

Fingers crossed.

Manuel

[Gavin]

Thanks Manuel, I'll try a fresh install on a test system and follow your steps.

I suspect it's a permissions issue on our live server although not sure what and for whom. The services are configured to run as a local user and that user has access to the network share.

BR,
Gavin

[Manuel Bähnisch]

Hi Gavin,

I ran into the same problem with my BitbucketServer Version 7.4.1. In my case it was a fresh installation on a Windows vm and I mapped the BitbucketHome dir via UNC path. The elasticsearch daemon is running fine though. At first I thought access to the home dir via UNC was the problem but since all sub dirs in the BitbucketHome dir were created during initial start-up something else must cause the problems. Especially since log files are written and the elasticsearch daemon is running.

Did you have any luck finding a solution so far?

Thanks

Manuel