Tomcat 9.0.14 startup fails, or at least is not recognized as complete by
Ubuntu’s systemd which times out:
Dec 25 05:19:09 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:09.586 INFO
[main] org.apache.catalina.startup.Catalina.start Server startup in [1,868]
milliseconds
Dec 25 05:20:34 vps169399 systemd[1]: tomcat.service: Start operation timed
out. Terminating.
A stop operation then fails (port 8005 held by the hung start operation?) and
tomcat is killed by the OS.
Systemd then restarts Tomcat 10 seconds later resulting in a start/stop loop.
After a system reboot, one start operation will proceed normally, but any
restart results in the start/stop loop. There are no webapps involved except
the tomcat packed ones.
Tomcat 9.0.13 works perfectly with identical installation and configuration.
What is systemd is expecting that it is not getting from 9.0.14? Any clue will
be much appreciated.
The systemd script and full startup log are enclosed below, which contains
details of the environment.
[Unit]
Description=Apache Tomcat Web Application Container
After=network.target
[Service]
Type=forking
Environment=JAVA_HOME=/usr/lib/jvm/jdk-11.0.1
Environment=CATALINA_PID=/opt/tomcat/temp/tomcat.pid
Environment=CATALINA_HOME=/opt/tomcat
Environment=CATALINA_BASE=/opt/tomcat
Environment='JAVA_OPTS=-Djava.awt.headless=true
-Djava.security.egd=file:/dev/./urandom'
Environment=LD_LIBRARY_PATH=/opt/tomcat/lib
Environment='CATALINA_OPTS=-Xms1024m -Xmx1024m'
ExecStart=/opt/tomcat/bin/startup.sh
ExecStop=/opt/tomcat/bin/shutdown.sh
User=tomcatuser
Group=tomcatgroup
UMask=0007
RestartSec=10
Restart=always
[Install]
WantedBy=multi-user.target
Complete startup log:
-- Unit tomcat.service has begun starting up.
Dec 25 05:19:04 vps169399 catalina.sh[9716]: NOTE: Picked up JDK_JAVA_OPTIONS:
--add-opens=java.base/java.lang=ALL-UNNAMED
--add-opens=java.base/java.io=ALL-UNNAMED
--add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.362 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Server version
name: Apache Tomcat/9.0.14
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.376 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Server built:
Dec 6 2018 21:13:53 UTC
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.380 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Server version
number: 9.0.14.0
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.381 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:
Linux
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.382 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:
4.15.0-43-generic
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.383 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:
amd64
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.383 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:
/usr/lib/jvm/jdk-11.0.1
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.384 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:
11.0.1+13
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.384 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:
Oracle Corporation
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.386 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:
/opt/tomcat
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.386 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:
/opt/tomcat
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.387 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: --add-opens=java.base/java.lang=ALL-UNNAMED
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.388 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: --add-opens=java.base/java.io=ALL-UNNAMED
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.390 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.392 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: -Djava.util.logging.config.file=/opt/tomcat/conf/logging.properties
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.396 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.396 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: -Djava.awt.headless=true
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.397 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: -Djava.security.egd=file:/dev/./urandom
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.398 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: -Djdk.tls.ephemeralDHKeySize=2048
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.399 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.399 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.404 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: -Xms1024m
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.405 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: -Xmx1024m
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.406 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: -Dignore.endorsed.dirs=
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.407 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: -Dcatalina.base=/opt/tomcat
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.407 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: -Dcatalina.home=/opt/tomcat
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.409 INFO
[main] org.apache.catalina.startup.VersionLoggerListener.log Command line
argument: -Djava.io.tmpdir=/opt/tomcat/temp
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.410 INFO
[main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded APR
based Apache Tomcat Native library [1.2.19] using APR version [1.6.5].
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.411 INFO
[main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR
capabilities: IPv6 [true], sendfile [true], accept filters [false], random
[true].
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.411 INFO
[main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR/OpenSSL
configuration: useAprConnector [false], useOpenSSL [true]
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.427 INFO
[main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL
successfully initialized [OpenSSL 1.1.0g 2 Nov 2017]
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.561 INFO
[main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
["http-nio-8080"]
Dec 25 05:19:06 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:06.646 INFO
[main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
["https-jsse-nio-8443"]
Dec 25 05:19:07 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:07.712 INFO
[main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler
["ajp-nio-8009"]
Dec 25 05:19:07 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:07.717 INFO
[main] org.apache.catalina.startup.Catalina.load Server initialization in
[2,772] milliseconds
Dec 25 05:19:07 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:07.857 INFO
[main] org.apache.catalina.core.StandardService.startInternal Starting service
[Catalina]
Dec 25 05:19:07 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:07.860 INFO
[main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet
engine: [Apache Tomcat/9.0.14]
Dec 25 05:19:07 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:07.876 INFO
[main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web
application directory [/opt/tomcat/webapps/host-manager]
Dec 25 05:19:08 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:08.698 INFO
[main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web
application directory [/opt/tomcat/webapps/host-manager] has finished in [822]
ms
Dec 25 05:19:08 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:08.700 INFO
[main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web
application directory [/opt/tomcat/webapps/examples]
Dec 25 05:19:09 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:09.344 INFO
[main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web
application directory [/opt/tomcat/webapps/examples] has finished in [644] ms
Dec 25 05:19:09 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:09.345 INFO
[main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web
application directory [/opt/tomcat/webapps/docs]
Dec 25 05:19:09 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:09.405 INFO
[main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web
application directory [/opt/tomcat/webapps/docs] has finished in [59] ms
Dec 25 05:19:09 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:09.405 INFO
[main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web
application directory [/opt/tomcat/webapps/manager]
Dec 25 05:19:09 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:09.467 INFO
[main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web
application directory [/opt/tomcat/webapps/manager] has finished in [61] ms
Dec 25 05:19:09 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:09.470 INFO
[main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web
application directory [/opt/tomcat/webapps/ROOT]
Dec 25 05:19:09 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:09.523 INFO
[main] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web
application directory [/opt/tomcat/webapps/ROOT] has finished in [52] ms
Dec 25 05:19:09 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:09.534 INFO
[main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
["http-nio-8080"]
Dec 25 05:19:09 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:09.572 INFO
[main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
["https-jsse-nio-8443"]
Dec 25 05:19:09 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:09.582 INFO
[main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
["ajp-nio-8009"]
Dec 25 05:19:09 vps169399 catalina.sh[9716]: 25-Dec-2018 05:19:09.586 INFO
[main] org.apache.catalina.startup.Catalina.start Server startup in [1,868]
milliseconds
Dec 25 05:20:34 vps169399 systemd[1]: tomcat.service: Start operation timed
out. Terminating.
Dec 25 05:20:34 vps169399 catalina.sh[9716]: 25-Dec-2018 05:20:34.531 INFO
[Thread-5] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["http-nio-8080"]
Dec 25 05:20:34 vps169399 catalina.sh[9716]: 25-Dec-2018 05:20:34.550 INFO
[Thread-5] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["https-jsse-nio-8443"]
Dec 25 05:20:34 vps169399 catalina.sh[9716]: 25-Dec-2018 05:20:34.552 INFO
[Thread-5] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler
["ajp-nio-8009"]
Dec 25 05:20:34 vps169399 catalina.sh[9716]: 25-Dec-2018 05:20:34.553 INFO
[Thread-5] org.apache.catalina.core.StandardService.stopInternal Stopping
service [Catalina]
Dec 25 05:20:34 vps169399 catalina.sh[9716]: 25-Dec-2018 05:20:34.675 INFO
[Thread-5] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
["http-nio-8080"]
Dec 25 05:20:34 vps169399 catalina.sh[9716]: 25-Dec-2018 05:20:34.686 INFO
[Thread-5] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
["https-jsse-nio-8443"]
Dec 25 05:20:34 vps169399 catalina.sh[9716]: 25-Dec-2018 05:20:34.689 INFO
[Thread-5] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler
["ajp-nio-8009"]
Dec 25 05:20:34 vps169399 catalina.sh[9716]: 25-Dec-2018 05:20:34.693 INFO
[Thread-5] org.apache.coyote.AbstractProtocol.destroy Destroying
ProtocolHandler ["http-nio-8080"]
Dec 25 05:20:34 vps169399 catalina.sh[9716]: 25-Dec-2018 05:20:34.695 INFO
[Thread-5] org.apache.coyote.AbstractProtocol.destroy Destroying
ProtocolHandler ["https-jsse-nio-8443"]
Dec 25 05:20:34 vps169399 catalina.sh[9716]: 25-Dec-2018 05:20:34.696 INFO
[Thread-5] org.apache.coyote.AbstractProtocol.destroy Destroying
ProtocolHandler ["ajp-nio-8009"]
Dec 25 05:20:34 vps169399 systemd[1]: tomcat.service: Control process exited,
code=exited status=143
Dec 25 05:20:34 vps169399 sudo[9713]: pam_unix(sudo:session): session closed
for user root
Dec 25 05:20:34 vps169399 systemd[1]: tomcat.service: Failed with result
'timeout'.
Dec 25 05:20:34 vps169399 systemd[1]: Failed to start Apache Tomcat Web
Application Container.
