Re: Tomcat 9.0.14 Windows service slow to stop
This sounds similar to: http://mail-archives.apache.org/mod_mbox/tomcat-dev/201812.mbox/ajax/%3Cbug-63041-78%40https.bz.apache.org%2Fbugzilla%2F%3E and, http://mail-archives.apache.org/mod_mbox/tomcat-users/201812.mbox/ajax/%3CDEB74971-2714-401F-9428-25EE0ECC6D11%40shaw.ca%3E I’m not fluent in Tomcat, but it appears something changed in the catalina.sh script of 9.0.14 that changed the stop/start behaviour. Steve > On Jan 7, 2019, at 3:38 PM, Jean-Pascal Houde wrote: > > Hello, > > I'm having a problem that seems to occur only since Tomcat 9.0.14. I'm using > Tomcat installed as a service on a Windows 2012 R2 server. > The service starts normally, but stopping it from the Windows Services window > takes a long time (about a minute). This happens even with no web application > deployed on the server. I've tried downgrading to 9.0.13 and 9.0.12 and both > version stops normally, under 1-2 seconds. > > Here is what I am doing: > 1. Download Tomcat Windows 64-bit zip > 2. Install service using "service install tomcat9" > 3. Open Windows "Services" control panel > 3. Start Tomcat9 service -> very fast > 4. Stop Tomcat9 service -> gets stuck on "stopping service..." for around a > minute. > > This is what the commons-daemon log file shows: > [2019-01-07 18:27:21] [info] [ 7500] Commons Daemon procrun (1.1.0.0 64-bit) > started > [2019-01-07 18:27:21] [info] [ 7500] Running 'tomcat9' Service... > [2019-01-07 18:27:21] [info] [ 3904] Starting service... > [2019-01-07 18:27:22] [info] [ 3904] Service started in 1190 ms. > [2019-01-07 18:27:23] [info] [ 9796] Stopping service... > [2019-01-07 18:27:24] [info] [ 9796] Service stop thread completed. > [2019-01-07 18:28:24] [info] [ 7500] Run service finished. > [2019-01-07 18:28:24] [info] [ 7500] Commons Daemon procrun finished > > You can see the full minute between the initial "Stopping services..." and > the finish of the stopping process. Other log files don't show anything > suspicious. > > Anyone seeing the same issue with this version? > > Thanks, > > > Jean-Pascal Houde > > > - > To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org > For additional commands, e-mail: users-h...@tomcat.apache.org > - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 9.0.14 startup fails
I opened a bug on this (https://bz.apache.org/bugzilla/show_bug.cgi?id=63041). It was closed by Christopher Shultz suggesting a probable configuration issue. Possibly so, but the configuration is out of the box prior to any /conf file modification and with no user web apps involved. And as you’ve confirmed Greg, 9.0.13 works as expected where 9.0.14 fails, all else unchanged. Any further pointers as to where to look would be appreciated. Steve > On Dec 29, 2018, at 8:54 AM, Greg Huber wrote: > > I used your startup script as a test, there does seem to be some > differences between v13 and v14. v13 starts OK but v14 fails, I can see > the temp/tomcat.pid being created but then disappears. > > > systemctl status -l tomcat > ● tomcat.service - Apache Tomcat Web Application Container > Loaded: loaded (/etc/systemd/system/tomcat.service; disabled; vendor > preset: disabled) > Active: inactive (dead) > > Dec 29 16:50:52 dev.box shutdown.sh[22941]: at > java.net.Socket.(Socket.java:211) > Dec 29 16:50:52 dev.box shutdown.sh[22941]: at > org.apache.catalina.startup.Catalina.stopServer(Catalina.java:513) > Dec 29 16:50:52 dev.box shutdown.sh[22941]: at > sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > Dec 29 16:50:52 dev.box shutdown.sh[22941]: at > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) > Dec 29 16:50:52 dev.box shutdown.sh[22941]: at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > Dec 29 16:50:52 dev.boxshutdown.sh[22941]: at > java.lang.reflect.Method.invoke(Method.java:498) > Dec 29 16:50:52 dev.box shutdown.sh[22941]: at > org.apache.catalina.startup.Bootstrap.stopServer(Bootstrap.java:403) > Dec 29 16:50:52 dev.box shutdown.sh[22941]: at > org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:497) > Dec 29 16:50:52 dev.box shutdown.sh[22941]: The stop command failed. > Attempting to signal the process to stop through OS signal. > Dec 29 16:50:53 dev.box shutdown.sh[22941]: Tomcat stopped. > > > It seems to work OK using jsvc however. There are no error logs. > > Cheers Greg
Re: Tomcat 9.0.14 startup fails
Maybe there is a clue here: 1) Eliminated systemd script and rebooted server. 2) Manually started Tomcat using startup.sh run . Tomcat starts normally. 3) Manually stopped Tomcat using shutdown.sh. Got stack trace: Using CATALINA_BASE: /opt/tomcat Using CATALINA_HOME: /opt/tomcat Using CATALINA_TMPDIR: /opt/tomcat/temp Using JRE_HOME:/usr Using CLASSPATH: /opt/tomcat/bin/bootstrap.jar:/opt/tomcat/bin/tomcat-juli.jar 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 28, 2018 9:57:32 PM org.apache.catalina.startup.Catalina stopServer SEVERE: Could not contact [localhost:8005] (base port [8005] and offset [0]). Tomcat may not be running. Dec 28, 2018 9:57:32 PM org.apache.catalina.startup.Catalina stopServer SEVERE: Error stopping Catalina java.net.ConnectException: Connection refused (Connection refused) at java.base/java.net.PlainSocketImpl.socketConnect(Native Method) at java.base/java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:399) at java.base/java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:242) at java.base/java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:224) at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:403) at java.base/java.net.Socket.connect(Socket.java:591) at java.base/java.net.Socket.connect(Socket.java:540) at java.base/java.net.Socket.(Socket.java:436) at java.base/java.net.Socket.(Socket.java:213) at org.apache.catalina.startup.Catalina.stopServer(Catalina.java:513) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at org.apache.catalina.startup.Bootstrap.stopServer(Bootstrap.java:403) at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:497) Tomcat is shut down - it is absent from the process list. I think 8005 is being contacted *after* Tomcat is shut down, leading to the error. With systemd involved, the failed shutdown triggers a restart timer, which evokes a shutdown command, which fails in the same manner leading to the start/stop loop. Is this a new bug in 9.0.14 or do I have a configuration problem that manifests in 9.0.14 for the first time? - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Tomcat 9.0.14 startup fails
Another fresh install of 9.0.14 using the longer "TimeoutStopSec=180”. Rebooted the system: sudo systemctl status tomcat ● tomcat.service - Apache Tomcat Web Application Container Loaded: loaded (/etc/systemd/system/tomcat.service; enabled; vendor preset: enabled) Active: active (running) since Fri 2018-12-28 04:30:23 EST; 41s ago Process: 938 ExecStart=/opt/tomcat/bin/startup.sh (code=exited, status=0/SUCCESS) Main PID: 969 (java) Tasks: 100 (limit: 2262) CGroup: /system.slice/tomcat.service └─969 /usr/lib/jvm/jdk-11.0.1/bin/java -Djava.util.logging.config.file=/opt/tomcat/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.awt.headless=true -Djava.security.egd=file:/dev/./urandom -Djdk.tls.ephemeralDHKeySize=2048 -Djava.protocol.handle Dec 28 04:30:23 vps169399 systemd[1]: Starting Apache Tomcat Web Application Container... Dec 28 04:30:23 vps169399 startup.sh[938]: Tomcat started. Dec 28 04:30:23 vps169399 systemd[1]: Started Apache Tomcat Web Application Container. That looks good. Let’s try stopping it: sudo systemctl stop tomcat -- Unit tomcat.service has begun shutting down. Dec 28 04:31:35 vps169399 shutdown.sh[1619]: 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 28 04:31:37 vps169399 shutdown.sh[1619]: Tomcat stopped. Dec 28 04:31:37 vps169399 systemd[1]: Stopped Apache Tomcat Web Application Container. -- Subject: Unit tomcat.service has finished shutting down No trouble yet. Let’s try another start: sudo systemctl start tomcat -- The start-up result is RESULT. Dec 28 04:32:29 vps169399 shutdown.sh[1683]: 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 28 04:32:31 vps169399 shutdown.sh[1683]: Dec 28, 2018 4:32:31 AM org.apache.catalina.startup.Catalina stopServer Dec 28 04:32:31 vps169399 shutdown.sh[1683]: SEVERE: Could not contact [localhost:8005] (base port [8005] and offset [0]). Tomcat may not be running. Dec 28 04:32:31 vps169399 shutdown.sh[1683]: Dec 28, 2018 4:32:31 AM org.apache.catalina.startup.Catalina stopServer Dec 28 04:32:31 vps169399 shutdown.sh[1683]: SEVERE: Error stopping Catalina Dec 28 04:32:31 vps169399 shutdown.sh[1683]: java.net.ConnectException: Connection refused (Connection refused) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at java.base/java.net.PlainSocketImpl.socketConnect(Native Method) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at java.base/java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:399) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at java.base/java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:242) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at java.base/java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:224) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:403) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at java.base/java.net.Socket.connect(Socket.java:591) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at java.base/java.net.Socket.connect(Socket.java:540) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at java.base/java.net.Socket.(Socket.java:436) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at java.base/java.net.Socket.(Socket.java:213) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at org.apache.catalina.startup.Catalina.stopServer(Catalina.java:513) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at java.base/java.lang.reflect.Method.invoke(Method.java:566) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at org.apache.catalina.startup.Bootstrap.stopServer(Bootstrap.java:403) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:497) Dec 28 04:32:31 vps169399 shutdown.sh[1683]: The stop command failed. Attempting to signal the process to stop through OS signal. Dec 28 04:32:32 vps169399 shutdown.sh[1683]: Tomcat stopped. That didn’t go so well. The " systemctl start tomcat" encountered a Catalina stopServer command and it seems unable to use port 8005. Is 8005 not being released after the previous stop? Again returned to 9.0.13, everything else identical
Tomcat 9.0.14 startup fails
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
