Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Service does not run on Windows 2019 - FDB Snapshot 20200510 #10

Closed
adamretter opened this issue May 11, 2020 · 3 comments
Closed

Service does not run on Windows 2019 - FDB Snapshot 20200510 #10

adamretter opened this issue May 11, 2020 · 3 comments

Comments

@adamretter
Copy link
Member

adamretter commented May 11, 2020 •
edited

Using a SNAPSHOT build of fdb from 20200510, installing the service works on Windows 2019 DataCentre. However the service fails to start.

launcher.log

2020-05-11 18:11:57,788 [AWT-EventQueue-0] DEBUG (WindowsServiceManager.java [run]:429) - WindowsServiceManager Executing: [cmd.exe, /c, ""C:\Program Files\FusionDB Server\bin\prunsrv-x86_64.exe" install FusionDB-Server --DisplayName=FusionDB-Server --Description="FusionDB Server" --StdError=auto --StdOutput=auto --LogPath="C:\Users\aretter\AppData\Roaming\FusionDB Server\logs" --LogPrefix=service --PidFile=service.pid --Startup=auto --ServiceUser=LocalSystem --Jvm="C:\Program Files\BellSoft\LibericaJRE-11-Full\bin\client\jvm.dll" --Classpath="C:/Program Files/FusionDB Server/lib/*" --JvmMs=128m --StartMode=jvm --StartClass=org.exist.service.ExistDbDaemon --StartMethod=start --StopMode=jvm --StopClass=org.exist.service.ExistDbDaemon --StopMethod=stop --JvmOptions="-Dfile.encoding=UTF-8;-Dlog4j.configurationFile=C:\Program Files\FusionDB Server/etc/log4j2.xml;-Djetty.home=C:\Program Files\FusionDB Server;-Dexist.jetty.config=C:\Program Files\FusionDB Server/etc/jetty/standard.enabled-jetty-configs;-Djetty.git.hash=ab228fde9e55e9164c738d7fa121f8ac5acd51c9;-Dexist.home=C:\Program Files\FusionDB Server;-Dexist.configurationFile=C:\Program Files\FusionDB Server/etc/conf.xml" --StartParams="C:\Program Files\FusionDB Server\etc\conf.xml" --JvmMx=4224m"] 
2020-05-11 18:11:57,913 [AWT-EventQueue-0] DEBUG (WindowsServiceManager.java [run]:429) - WindowsServiceManager Executing: [sc.exe, query, FusionDB-Server] 
2020-05-11 18:11:57,944 [AWT-EventQueue-0] DEBUG (WindowsServiceManager.java [run]:429) - WindowsServiceManager Executing: [cmd.exe, /c, ""C:\Program Files\FusionDB Server\bin\prunsrv-x86_64.exe" start FusionDB-Server"] 
2020-05-11 18:12:01,230 [AWT-EventQueue-0] ERROR (WindowsServiceManager.java [start]:232) - Could not start service, exitCode=5, output=''

fusiondb-server-stdout.2020-05-11.log

2020-05-11 18:11:58 Apache Commons Daemon procrun stdout initialized.
11 May 2020 18:11:59,931 [main] INFO  (JettyStart.java [run]:182) - Running with Java 11.0.7 [BellSoft (OpenJDK 64-Bit Client VM) in C:\Program Files\BellSoft\LibericaJRE-11-Full] 
11 May 2020 18:11:59,931 [main] INFO  (JettyStart.java [run]:189) - Approximate maximum amount of memory for JVM: 247 MB 
11 May 2020 18:11:59,931 [main] INFO  (JettyStart.java [run]:190) - Number of processors available to JVM: 2 
11 May 2020 18:11:59,931 [main] INFO  (JettyStart.java [run]:192) - Running as user 'EC2AMAZ-N4968ER$' 
11 May 2020 18:11:59,931 [main] INFO  (JettyStart.java [run]:193) - [FusionDB Home : C:\Program Files\FusionDB Server] 
11 May 2020 18:11:59,931 [main] INFO  (JettyStart.java [run]:194) - [FusionDB Version : 1.0.0-SNAPSHOT] 
11 May 2020 18:11:59,931 [main] INFO  (JettyStart.java [run]:195) - [FusionDB Build : 20200510233829] 
11 May 2020 18:11:59,931 [main] INFO  (JettyStart.java [run]:196) - [Git commit : 6227cf129eb8a6822d50425e3f88067f0c4c1702] 
11 May 2020 18:11:59,931 [main] INFO  (JettyStart.java [run]:198) - [Operating System : Windows Server 2019 10.0 amd64] 
11 May 2020 18:12:00,369 [main] INFO  (JettyStart.java [run]:212) - Configuring FusionDB eXist component from C:\Program Files\FusionDB Server\etc\conf.xml 
11 May 2020 18:12:00,776 [main] ERROR (JettyStart.java [run]:225) - configuration error: java.lang.UnsatisfiedLinkError: C:\Windows\Temp\librocksdbjni18005926251924699790.dll: Can't find dependent libraries 
org.exist.EXistException: java.lang.UnsatisfiedLinkError: C:\Windows\Temp\librocksdbjni18005926251924699790.dll: Can't find dependent libraries
	at org.exist.storage.BrokerPool.initialize(BrokerPool.java:504) ~[exist-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	at org.exist.storage.BrokerPools.configure(BrokerPools.java:174) ~[exist-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	at org.exist.storage.BrokerPools.configure(BrokerPools.java:109) ~[exist-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	at org.exist.jetty.JettyStart.run(JettyStart.java:217) [exist-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	at org.exist.jetty.JettyStart.main(JettyStart.java:104) [exist-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:?]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[?:?]
	at org.exist.start.Main.invokeMain(Main.java:118) [exist-start-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	at org.exist.start.Main.runEx(Main.java:248) [exist-start-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	at org.exist.service.ExistDbDaemon.start(ExistDbDaemon.java:36) [exist-service-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	at org.exist.service.ExistDbDaemon.start(ExistDbDaemon.java:64) [exist-service-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
Caused by: java.lang.UnsatisfiedLinkError: C:\Windows\Temp\librocksdbjni18005926251924699790.dll: Can't find dependent libraries
	at java.lang.ClassLoader$NativeLibrary.load0(Native Method) ~[?:?]
	at java.lang.ClassLoader$NativeLibrary.load(Unknown Source) ~[?:?]
	at java.lang.ClassLoader$NativeLibrary.loadLibrary(Unknown Source) ~[?:?]
	at java.lang.ClassLoader.loadLibrary0(Unknown Source) ~[?:?]
	at java.lang.ClassLoader.loadLibrary(Unknown Source) ~[?:?]
	at java.lang.Runtime.load0(Unknown Source) ~[?:?]
	at java.lang.System.load(Unknown Source) ~[?:?]
	at org.rocksdb.NativeLibraryLoader.loadLibraryFromJar(NativeLibraryLoader.java:79) ~[rocksdbjni-202004011324-patched-debug.jar:?]
	at org.rocksdb.NativeLibraryLoader.loadLibrary(NativeLibraryLoader.java:57) ~[rocksdbjni-202004011324-patched-debug.jar:?]
	at org.rocksdb.RocksDB.loadLibrary(RocksDB.java:67) ~[rocksdbjni-202004011324-patched-debug.jar:?]
	at org.rocksdb.RocksDB.<clinit>(RocksDB.java:38) ~[rocksdbjni-202004011324-patched-debug.jar:?]
	at org.exist.storage.rocks.RocksDatabase.open(RocksDatabase.java:102) ~[exist-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	at org.exist.storage.rocks.RocksDatabase.open(RocksDatabase.java:92) ~[exist-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	at org.exist.storage.BrokerPool.initialiseRocksDB(BrokerPool.java:800) ~[exist-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	at org.exist.storage.BrokerPool._initialize(BrokerPool.java:529) ~[exist-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	at org.exist.storage.BrokerPool.initialize(BrokerPool.java:490) ~[exist-core-1.0.0-SNAPSHOT.jar:1.0.0-SNAPSHOT]
	... 12 more

fusiondb-server-stderr.2020-05-11.log

2020-05-11 18:11:58 Apache Commons Daemon procrun stderr initialized.
org.exist.EXistException: java.lang.UnsatisfiedLinkError: C:\Windows\Temp\librocksdbjni18005926251924699790.dll: Can't find dependent libraries
	at org.exist.storage.BrokerPool.initialize(BrokerPool.java:504)
	at org.exist.storage.BrokerPools.configure(BrokerPools.java:174)
	at org.exist.storage.BrokerPools.configure(BrokerPools.java:109)
	at org.exist.jetty.JettyStart.run(JettyStart.java:217)
	at org.exist.jetty.JettyStart.main(JettyStart.java:104)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.base/java.lang.reflect.Method.invoke(Unknown Source)
	at org.exist.start.Main.invokeMain(Main.java:118)
	at org.exist.start.Main.runEx(Main.java:248)
	at org.exist.service.ExistDbDaemon.start(ExistDbDaemon.java:36)
	at org.exist.service.ExistDbDaemon.start(ExistDbDaemon.java:64)
Caused by: java.lang.UnsatisfiedLinkError: C:\Windows\Temp\librocksdbjni18005926251924699790.dll: Can't find dependent libraries
	at java.base/java.lang.ClassLoader$NativeLibrary.load0(Native Method)
	at java.base/java.lang.ClassLoader$NativeLibrary.load(Unknown Source)
	at java.base/java.lang.ClassLoader$NativeLibrary.loadLibrary(Unknown Source)
	at java.base/java.lang.ClassLoader.loadLibrary0(Unknown Source)
	at java.base/java.lang.ClassLoader.loadLibrary(Unknown Source)
	at java.base/java.lang.Runtime.load0(Unknown Source)
	at java.base/java.lang.System.load(Unknown Source)
	at org.rocksdb.NativeLibraryLoader.loadLibraryFromJar(NativeLibraryLoader.java:79)
	at org.rocksdb.NativeLibraryLoader.loadLibrary(NativeLibraryLoader.java:57)
	at org.rocksdb.RocksDB.loadLibrary(RocksDB.java:67)
	at org.rocksdb.RocksDB.<clinit>(RocksDB.java:38)
	at org.exist.storage.rocks.RocksDatabase.open(RocksDatabase.java:102)
	at org.exist.storage.rocks.RocksDatabase.open(RocksDatabase.java:92)
	at org.exist.storage.BrokerPool.initialiseRocksDB(BrokerPool.java:800)
	at org.exist.storage.BrokerPool._initialize(BrokerPool.java:529)
	at org.exist.storage.BrokerPool.initialize(BrokerPool.java:490)
	... 12 more


Failed to start service.

service.log

[2020-05-11 20:48:48] [debug] ( prunsrv.c:1763) [ 4100] Apache Commons Daemon procrun log initialized.
[2020-05-11 20:48:48] [info]  ( prunsrv.c:1767) [ 4100] Apache Commons Daemon procrun (1.2.2.0 64-bit) started.
[2020-05-11 20:48:48] [info]  ( prunsrv.c:1677) [ 4100] Running Service 'FusionDB-Server'...
[2020-05-11 20:48:48] [debug] ( prunsrv.c:1448) [ 6104] Inside ServiceMain...
[2020-05-11 20:48:48] [debug] ( prunsrv.c:910 ) [ 6104] reportServiceStatusE: dwCurrentState = 2, dwWin32ExitCode = 0, dwWaitHint = 3000, dwServiceSpecificExitCode = 0.
[2020-05-11 20:48:48] [info]  ( prunsrv.c:1203) [ 6104] Starting service...
[2020-05-11 20:48:48] [debug] ( javajni.c:216 ) [ 6104] Explicit RuntimeLib specified 'C:\Program Files\BellSoft\LibericaJRE-11-Full\bin\client\jvm.dll'
[2020-05-11 20:48:48] [debug] ( javajni.c:285 ) [ 6104] loading jvm 'C:\Program Files\BellSoft\LibericaJRE-11-Full\bin\client\jvm.dll'
[2020-05-11 20:48:48] [debug] ( javajni.c:795 ) [ 6112] Jvm Option[0] -Dfile.encoding=UTF-8
[2020-05-11 20:48:48] [debug] ( javajni.c:795 ) [ 6112] Jvm Option[1] -Dlog4j.configurationFile=C:\Program Files\FusionDB Server/etc/log4j2.xml
[2020-05-11 20:48:48] [debug] ( javajni.c:795 ) [ 6112] Jvm Option[2] -Djetty.home=C:\Program Files\FusionDB Server
[2020-05-11 20:48:48] [debug] ( javajni.c:795 ) [ 6112] Jvm Option[3] -Dexist.jetty.config=C:\Program Files\FusionDB Server/etc/jetty/standard.enabled-jetty-configs
[2020-05-11 20:48:48] [debug] ( javajni.c:795 ) [ 6112] Jvm Option[4] -Djetty.git.hash=ab228fde9e55e9164c738d7fa121f8ac5acd51c9
[2020-05-11 20:48:48] [debug] ( javajni.c:795 ) [ 6112] Jvm Option[5] -Dexist.home=C:\Program Files\FusionDB Server
[2020-05-11 20:48:48] [debug] ( javajni.c:795 ) [ 6112] Jvm Option[6] -Dexist.configurationFile=C:\Program Files\FusionDB Server/etc/conf.xml
[2020-05-11 20:48:48] [debug] ( javajni.c:795 ) [ 6112] Jvm Option[7] -Djava.class.path=C:/Program Files/FusionDB Server/lib/ant-1.10.7.jar;C:/Program Files/FusionDB Server/lib/ant-launcher-1.10.7.jar;C:/Program Files/FusionDB Server/lib/antlr-2.7.7.jar;C:/Program Files/FusionDB Server/lib/antlr-3.0.jar;C:/Program Files/FusionDB Server/lib/aopalliance-1.0.jar;C:/Program Files/FusionDB Server/lib/apache-mime4j-core-0.8.3.jar;C:/Program Files/FusionDB Server/lib/apache-mime4j-dom-0.8.3.jar;C:/Program Files/FusionDB Server/lib/appassembler-booter-2.1.0.jar;C:/Program Files/FusionDB Server/lib/appassembler-model-2.1.0.jar;C:/Program Files/FusionDB Server/lib/asm-7.1.jar;C:/Program Files/FusionDB Server/lib/asm-analysis-7.2.jar;C:/Program Files/FusionDB Server/lib/asm-commons-7.2.jar;C:/Program Files/FusionDB Server/lib/asm-tree-7.2.jar;C:/Program Files/FusionDB Server/lib/aspectjrt-1.9.4.jar;C:/Program Files/FusionDB Server/lib/avalon-framework-api-4.3.1.jar;C:/Program Files/FusionDB Server/lib/avalon-framework-impl-4.3.1.jar;C:/Program Files/FusionDB Server/lib/backu
[2020-05-11 20:48:48] [debug] ( javajni.c:795 ) [ 6112] Jvm Option[8] exit
[2020-05-11 20:48:48] [debug] ( javajni.c:795 ) [ 6112] Jvm Option[9] abort
[2020-05-11 20:48:51] [debug] ( javajni.c:981 ) [ 6112] argv[0] = C:\Program Files\FusionDB Server\etc\conf.xml
[2020-05-11 20:48:51] [debug] ( javajni.c:1034) [ 6112] Java Worker thread started org/exist/service/ExistDbDaemon:start
[2020-05-11 20:48:52] [debug] ( prunsrv.c:1261) [ 6104] Java started 'org/exist/service/ExistDbDaemon'.
[2020-05-11 20:48:52] [info]  ( prunsrv.c:1359) [ 6104] Service started in 4384 milliseconds.
[2020-05-11 20:48:52] [debug] ( prunsrv.c:910 ) [ 6104] reportServiceStatusE: dwCurrentState = 4, dwWin32ExitCode = 0, dwWaitHint = 0, dwServiceSpecificExitCode = 0.
[2020-05-11 20:48:52] [debug] ( prunsrv.c:1603) [ 6104] Waiting for worker to finish...
[2020-05-11 20:49:00] [debug] ( javajni.c:1057) [ 6112] Java Worker thread finished org/exist/service/ExistDbDaemon:start with status = 0
[2020-05-11 20:49:00] [debug] ( prunsrv.c:1608) [ 6104] Worker finished.
[2020-05-11 20:49:00] [debug] ( prunsrv.c:1635) [ 6104] Waiting for all threads to exit.
[2020-05-11 20:49:00] [debug] ( prunsrv.c:910 ) [ 6104] reportServiceStatusE: dwCurrentState = 3, dwWin32ExitCode = 0, dwWaitHint = 0, dwServiceSpecificExitCode = 0.
[2020-05-11 20:49:00] [debug] ( prunsrv.c:1639) [ 6104] JVM destroyed.
[2020-05-11 20:49:00] [debug] ( prunsrv.c:910 ) [ 6104] reportServiceStatusE: dwCurrentState = 1, dwWin32ExitCode = 0, dwWaitHint = 0, dwServiceSpecificExitCode = 0.
[2020-05-11 20:49:00] [info]  ( prunsrv.c:1679) [ 4100] Run service finished.
[2020-05-11 20:49:00] [info]  ( prunsrv.c:1848) [ 4100] Apache Commons Daemon procrun finished.

Windows Service Manager

Screenshot 2020-05-11 at 20 36 36

sc.exe qc FusionDB-Server

Screenshot 2020-05-11 at 20 44 16

Windows Event Viewer

Screenshot 2020-05-11 at 20 35 26
@adamretter
Copy link
Member Author

adamretter commented May 11, 2020 •
edited

It is interesting that both Windows Service Manager and sc.exe show LocalSystem, but that Windows Event Viewer shows NTAuthority\Local Service.

LocalService has less access rights than LocalSystem, see:

  1. https://docs.microsoft.com/en-us/windows/win32/services/localsystem-account
  2. https://docs.microsoft.com/en-us/windows/win32/services/localservice-account
  3. Use lower-privileged service account on Windows eXist-db/exist#2994
  4. https://github.com/eXist-db/exist/pull/2995/files#diff-f45a02c50ade3dd44f140c8896e9e689R112

TODO

  • Check the Apache Commons Daemon - Procrun source code to find out what exit code 5 from prunsrv-x86_64.exe start FusionDB-Server means.

    Exit Code 5 means that prunsrv-x86_64.exe start could not start the service.

  • Test Starting Service with Allow Service to interact with desktop checked in Windows Service Manager

    No change in behaviour. Same error!

  • Test Start Service under User's Account as Log on as in Windows Service Manager.

    Ran under user account aretter. No change in behaviour. Same error!

  • Test on an older Windows Server (2012?)

    1. ISSUE - had to set Full Control for running user aretter on C:\Program Files\FusionDB Server to enable the LauncherWrapper to create and save the settings file C:\Program Files\FusionDB Server\etc\launcher.properties.
    2. Once that was done, I was able to both Install and Start the service successfully. This was using Oracle JDK 8 (already installed).
      • Should test a clean Win2K12 with Oracle JDK 8
      • Should test another clean Win2K12 with Liberica Full JRE 11.
      • Does the error that happens on Windows Server 2019 also happen on Windows 2K12 if I change the service account from LocalSystem to LocalService? That might indicate that Windows Server 2019 has tighter permissions or doesn't really still support LocalSystem?!?

@adamretter
Copy link
Member Author

Ultimately the problem was with both the production and debug versions of the native library being on the classpath. The debug version was being loaded by the service, and that only works on debug platforms (i.e. with Visual Studio installed).

See - https://markmail.org/message/owugwjastwvr6jfs

@adamretter
Copy link
Member Author

Fixed 12th May 2020

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@adamretter