Windows Server – Service not starting with ‘Error 1067: The process terminated unexpectedly’ – again

Some months ago, I wrote a blog regarding a Windows Service not starting up with the error 1067. The first time I faced this issue, it was about an fmeAG Migration Center installation and as said in this previous blog, I’m not an expert in this software so I started to work on the Windows side of the issue and I found a workaround, which I explained in the above mentioned blog. A few weeks ago, I faced the exact same issue on another environment. Since I had a few hours available at that time and since I was much more familiar with the fmeAG Migration Center, I tried to really find the issue and not just apply a – kind of stupid – workaround. You guessed it, I found the issue, otherwise I wouldn’t have written this blog in the first place…

So first of all, the Windows Service that couldn’t start is the “Migration Center Job Server” which uses the wrapper.exe which can be found in the installation folder (E.g.: D:fmeAGmigration-center Server Components 3.3). In this folder, there is a wrapper.log as well as wrapper.conf so that looked like a good starting point. From the logs, this is what I could find (I cut most of the non-needed lines):

STATUS | wrapper  | 2018/06/14 12:46:47 | --> Wrapper Started as Service
STATUS | wrapper  | 2018/06/14 12:46:48 | Launching a JVM...
INFO   | jvm 1    | 2018/06/14 12:46:48 | Usage: java [-options] class [args...]
INFO   | jvm 1    | 2018/06/14 12:46:48 |            (to execute a class)
INFO   | jvm 1    | 2018/06/14 12:46:48 |    or  java [-options] -jar jarfile [args...]
INFO   | jvm 1    | 2018/06/14 12:46:48 |            (to execute a jar file)
INFO   | jvm 1    | 2018/06/14 12:46:48 | where options include:
INFO   | jvm 1    | 2018/06/14 12:46:48 |     -d32	  use a 32-bit data model if available
INFO   | jvm 1    | 2018/06/14 12:46:48 |     -d64	  use a 64-bit data model if available
...
INFO   | jvm 1    | 2018/06/14 12:46:48 | See http://www.oracle.com/technetwork/java/javase/documentation/index.html for more details.
ERROR  | wrapper  | 2018/06/14 12:46:48 | JVM exited while loading the application.
STATUS | wrapper  | 2018/06/14 12:46:52 | Launching a JVM...
...
ERROR  | wrapper  | 2018/06/14 12:46:53 | JVM exited while loading the application.
STATUS | wrapper  | 2018/06/14 12:46:57 | Launching a JVM...
...
ERROR  | wrapper  | 2018/06/14 12:46:58 | JVM exited while loading the application.
STATUS | wrapper  | 2018/06/14 12:47:02 | Launching a JVM...
...
ERROR  | wrapper  | 2018/06/14 12:47:02 | JVM exited while loading the application.
STATUS | wrapper  | 2018/06/14 12:47:07 | Launching a JVM...
...
ERROR  | wrapper  | 2018/06/14 12:47:07 | JVM exited while loading the application.
FATAL  | wrapper  | 2018/06/14 12:47:07 | There were 5 failed launches in a row, each lasting less than 300 seconds.  Giving up.
FATAL  | wrapper  | 2018/06/14 12:47:07 |   There may be a configuration problem: please check the logs.
STATUS | wrapper  | 2018/06/14 12:47:07 | <-- Wrapper Stopped

This actually looked quite interesting… The fact that when starting the JVM, the java “help” is displayed would tend to show that the start command isn’t correct or that there is something wrong with it. I was able to start a JVM using the Windows command line tools so it wasn’t an issue with Java. As a result, I checked the wrapper.conf which was shipped with the software. In our installation, we only slightly updated this configuration file to add custom JVM parameters but this wasn’t the issue (I still checked with the default file to be sure). There were no issue with the content of this file or with its formatting but there are still something useful in it: the possibility to change the log level. There are the relevant settings:

# Log Level for console output.  (See docs for log levels)
wrapper.console.loglevel=ERROR

# Log file to use for wrapper output logging.
wrapper.logfile=./wrapper.log

# Log Level for log file output.  (See docs for log levels)
wrapper.logfile.loglevel=INFO

So to see more information on the log file, you simply have to switch “wrapper.logfile.loglevel” from INFO to DEBUG for example. After doing that, the logs were clearer:

STATUS | wrapper  | 2018/06/14 12:53:10 | --> Wrapper Started as Service
DEBUG  | wrapper  | 2018/06/14 12:53:10 | Using tick timer.
DEBUG  | wrapperp | 2018/06/14 12:53:10 | server listening on port 32000.
STATUS | wrapper  | 2018/06/14 12:53:10 | Launching a JVM...
DEBUG  | wrapper  | 2018/06/14 12:53:10 | command: "D:Javajdk1.8.0_171binjava.exe" -Xss512k -DdocumentDirectory.home="%DOCUMENTDIRECTORY_HOME%" -Dclb.library.path=.libmc-d2-importerLockBoxlibnativewin_vc100_ia32 -Duser.timezone=UTC -Xms512m -Xmx1536m -Djava.library.path=".;./lib/mc-outlook-adaptor;./lib/mc-domino-scanner/lib;D:DFCDFC_7.3Shared;D:Oracleinstantclient_12_2;D:Javajdk1.8.0_171bin;C:windowssystem32;C:windows;C:windowsSystem32Wbem;C:windowsSystem32WindowsPowerShellv1.0;C:Program Files1ENomadBranch"" -classpath "wrappertest.jar;wrapper.jar;./lib/mc-common/mc-common-3.3.jar;./lib/mc-api/mc-api-3.3.jar;./lib/mc-api/ojdbc7.jar;./lib/mc-api/orai18n.jar;./lib/mc-api/runtime12.jar;./lib/mc-api/translator.jar;./lib/mc-server;./lib/mc-server/log4j-1.2.17.jar;./lib/mc-server/mc-server-3.3.jar;./lib/mc-dctm-adaptor;./lib/mc-dctm-adaptor/mc-dctm-adaptor-3.3.jar;./lib/mc-d2-importer;./lib/mc-d2-importer/C2-API.jar;./lib/mc-d2-importer/C6-Common-4.7.0.jar;./lib/mc-d2-importer/commons-collections-3.2.jar;./lib/mc-d2-importer/commons-compress-1.5.jar;./lib/mc-d2-importer/commons-io-1.4.jar;./lib/mc-d2-importer/commons-lang-2.4.jar;./lib/mc-d2-importer/D2-API-4.7.0.jar;./lib/mc-d2-importer/D2-BOCS-65.jar;./lib/mc-d2-importer/D2-Specifications-API.jar;./lib/mc-d2-importer/D2-Specifications.jar;./lib/mc-d2-importer/D2BofServices-4.7.0.jar;./lib/mc-d2-importer/D2FS-Generated-4.7.0.jar;./lib/mc-d2-importer/D2FS4DCTM-API-4.7.0.jar;./lib/mc-d2-importer/dfc.jar;./lib/mc-d2-importer/diff-0.4.2.jar;./lib/mc-d2-importer/ehcache-core-1.7.2.jar;./lib/mc-d2-importer/emc-dfs-rt.jar;./lib/mc-d2-importer/emc-dfs-services.jar;./lib/mc-d2-importer/gwt-servlet-2.5.1.jar;./lib/mc-d2-importer/logback-classic-0.9.18.jar;./lib/mc-d2-importer/logback-core-0.9.18.jar;./lib/mc-d2-importer/mail.jar;./lib/mc-d2-importer/mc-d2-importer-3.3.jar;./lib/mc-d2-importer/poi-3.6-20091214.jar;./lib/mc-d2-importer/poi-contrib-3.6-20091214.jar;./lib/mc-d2-importer/slf4j-api-1.5.10.jar;./lib/mc-dcm-importer;./lib/mc-dcm-importer/dcm.jar;./lib/mc-dcm-importer/dcmibof.jar;./lib/mc-dcm-importer/dcmproperties.jar;./lib/mc-dcm-importer/dcmresource.jar;./lib/mc-dcm-importer/DmcRecords.jar;./lib/mc-dcm-importer/mc-dcm-importer-3.3.jar;./lib/mc-dcm-importer/pss.jar;./lib/mc-otcs-common/activation.jar;./lib/mc-otcs-common/aspectjrt.jar;./lib/mc-otcs-common/commons-lang3-3.3.2.jar;./lib/mc-otcs-common/jaxb-api.jar;./lib/mc-otcs-common/jaxb-impl.jar;./lib/mc-otcs-common/jaxws-api.jar;./lib/mc-otcs-common/jaxws-rt.jar;./lib/mc-otcs-common/jsr173_api.jar;./lib/mc-otcs-common/jsr181-api.jar;./lib/mc-otcs-common/jsr250-api.jar;./lib/mc-otcs-common/mimepull.jar;./lib/mc-otcs-common/resolver.jar;./lib/mc-otcs-common/saaj-api.jar;./lib/mc-otcs-common/saaj-impl.jar;./lib/mc-otcs-common/stax-ex.jar;./lib/mc-otcs-common/streambuffer.jar;./lib/mc-d2-importer/LockBox;./lib/mc-firstdoc-importer;D:Documentumconfig;D:DFCDFC_7.3dctm.jar" -Dwrapper.key="eFO3zr2BRv874Qb4" -Dwrapper.port=32000 -Dwrapper.jvm.port.min=31000 -Dwrapper.jvm.port.max=31999 -Dwrapper.debug="TRUE" -Dwrapper.pid=4832 -Dwrapper.version="3.2.3" -Dwrapper.native_library="wrapper" -Dwrapper.cpu.timeout="10" -Dwrapper.jvmid=1 org.tanukisoftware.wrapper.WrapperSimpleApp de.fme.mc.server.Main
DEBUG  | wrapper  | 2018/06/14 12:53:10 | JVM started (PID=4756)
INFO   | jvm 1    | 2018/06/14 12:53:10 | Usage: java [-options] class [args...]
INFO   | jvm 1    | 2018/06/14 12:53:10 |            (to execute a class)
INFO   | jvm 1    | 2018/06/14 12:53:10 |    or  java [-options] -jar jarfile [args...]
INFO   | jvm 1    | 2018/06/14 12:53:10 |            (to execute a jar file)
INFO   | jvm 1    | 2018/06/14 12:53:10 | where options include:
INFO   | jvm 1    | 2018/06/14 12:53:10 |     -d32	  use a 32-bit data model if available
INFO   | jvm 1    | 2018/06/14 12:53:10 |     -d64	  use a 64-bit data model if available
...
INFO   | jvm 1    | 2018/06/14 12:53:10 | See http://www.oracle.com/technetwork/java/javase/documentation/index.html for more details.
ERROR  | wrapper  | 2018/06/14 12:53:10 | JVM exited while loading the application.
...
FATAL  | wrapper  | 2018/06/14 12:53:30 | There were 5 failed launches in a row, each lasting less than 300 seconds.  Giving up.
FATAL  | wrapper  | 2018/06/14 12:53:30 |   There may be a configuration problem: please check the logs.
STATUS | wrapper  | 2018/06/14 12:53:30 | <-- Wrapper Stopped

From the beginning, this looked like an issue with the java command executed so I took a close look at it and I could find that there were indeed something wrong. If you have good eyes (and took the time to scroll a little bit), you can see that at some point, there are two consecutive double quotes ( “” ) to close the “-Djava.library.path” JVM parameter. As a result, the following parameter which is -classpath isn’t taken properly and it just cause the whole command to be wrongly formatted…

The value to be used for the “-Djava.library.path” JVM parameter is coming from the wrapper.conf file as well: in this file, you can find the “wrapper.java.library.path.X=” lines where X is a number starting with 1 and each of these values are concatenated (separated with semicolon) to form the final value. By default, the last of these lines will have “%PATH%” as value so it will replace it at runtime with the actual value of this environment variable. Since it was identified that the issue is coming from the double quotes at the end of the “-Djava.library.path”, it is therefore safe to assume that the issue is inside %PATH% definition…

Checking its value using the command prompt didn’t show anything strange but through the Control Panel, it confirmed my suspicions: the declaration of the %PATH% environment variable for the current user ended with a double quote ( ” ) while there were no double quotes at the start of this declaration. After removing it, the Service was able to start successfully. After investigation on the root cause, it appeared that this double quote was actually coming from an issue with the Windows Server delivery tool that wrongly set this environment variable on the server delivery. This also explained why the workaround I described in the previous blog worked: it cleaned the environment variables for this user (there were no specific declaration on this user’s %PATH%, it was only the default Windows stuff).