tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Steve Demy <steve.d...@shaw.ca>
Subject Tomcat 9.0.14 startup fails
Date Thu, 27 Dec 2018 04:19:50 GMT
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.


Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message