Thanks all, Here is a more detailed service log (at FINE level): [2019-01-08 09:45:21] [debug] ( prunsrv.c:885 ) [ 2752] reportServiceStatusE: dwCurrentState = 3, dwWin32ExitCode = 0, dwWaitHint = 3000, dwServiceSpecificExitCode = 0 [2019-01-08 09:45:21] [info] ( prunsrv.c:984 ) [ 8792] Stopping service... [2019-01-08 09:45:21] [debug] ( javajni.c:937 ) [ 8408] argv[0] = stop [2019-01-08 09:45:21] [debug] ( javajni.c:990 ) [ 8408] Java Worker thread started org/apache/catalina/startup/Bootstrap:main [2019-01-08 09:45:21] [debug] ( javajni.c:1013) [ 4108] Java Worker thread finished org/apache/catalina/startup/Bootstrap:main with status = 0 [2019-01-08 09:45:21] [debug] ( javajni.c:1013) [ 8408] Java Worker thread finished org/apache/catalina/startup/Bootstrap:main with status = 0 [2019-01-08 09:45:21] [debug] ( prunsrv.c:1577) [ 9012] Worker finished. [2019-01-08 09:45:21] [debug] ( prunsrv.c:1586) [ 9012] Waiting for ShutdownEvent [2019-01-08 09:45:21] [debug] ( prunsrv.c:885 ) [ 9012] reportServiceStatusE: dwCurrentState = 3, dwWin32ExitCode = 0, dwWaitHint = 60000, dwServiceSpecificExitCode = 0 [2019-01-08 09:45:22] [debug] ( prunsrv.c:1032) [ 8792] Waiting for Java JNI stop worker to finish... [2019-01-08 09:45:22] [debug] ( prunsrv.c:1034) [ 8792] Java JNI stop worker finished. [2019-01-08 09:45:22] [debug] ( prunsrv.c:885 ) [ 8792] reportServiceStatusE: dwCurrentState = 3, dwWin32ExitCode = 0, dwWaitHint = 300000, dwServiceSpecificExitCode = 0 [2019-01-08 09:45:22] [debug] ( prunsrv.c:1141) [ 8792] Waiting for worker to die naturally... [2019-01-08 09:45:22] [debug] ( prunsrv.c:1152) [ 8792] Worker finished gracefully in 0 ms. [2019-01-08 09:45:22] [info] ( prunsrv.c:1162) [ 8792] Service stop thread completed. [2019-01-08 09:45:22] [debug] ( prunsrv.c:1589) [ 9012] ShutdownEvent signaled [2019-01-08 09:45:22] [debug] ( prunsrv.c:1594) [ 9012] Waiting 1 minute for all threads to exit [2019-01-08 09:45:22] [debug] ( prunsrv.c:885 ) [ 9012] reportServiceStatusE: dwCurrentState = 3, dwWin32ExitCode = 0, dwWaitHint = 60000, dwServiceSpecificExitCode = 0 [2019-01-08 09:46:22] [debug] ( prunsrv.c:1607) [ 9012] JVM destroyed. [2019-01-08 09:46:22] [debug] ( prunsrv.c:885 ) [ 9012] reportServiceStatusE: dwCurrentState = 1, dwWin32ExitCode = 0, dwWaitHint = 0, dwServiceSpecificExitCode = 0 [2019-01-08 09:46:22] [info] ( prunsrv.c:1645) [ 2752] Run service finished. [2019-01-08 09:46:22] [info] ( prunsrv.c:1814) [ 2752] Commons Daemon procrun finished
Catalina log file doesn't have much: 08-Jan-2019 09:44:33.101 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [563] milliseconds 08-Jan-2019 09:44:33.132 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina] 08-Jan-2019 09:44:33.132 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.14] 08-Jan-2019 09:44:33.132 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-7980"] 08-Jan-2019 09:44:33.148 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [42] milliseconds 08-Jan-2019 09:45:21.833 INFO [Thread-5] org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler ["http-nio-7980"] 08-Jan-2019 09:45:21.866 INFO [Thread-5] org.apache.catalina.core.StandardService.stopInternal Stopping service [Catalina] 08-Jan-2019 09:45:21.866 INFO [Thread-5] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-nio-7980"] Below is the result of a thread dump while the service waiting to stop: "Signal Dispatcher" daemon prio=9 tid=4 RUNNABLE "DestroyJavaVM" prio=5 tid=32 RUNNABLE "Finalizer" daemon prio=8 tid=3 WAITING at java.lang.Object.wait(Native Method) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165) Local Variable: java.lang.ref.ReferenceQueue#20 at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216) Local Variable: java.lang.System$2#1 "Catalina-utility-1" prio=1 tid=15 WAITING at sun.misc.Unsafe.park(Native Method) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$Node#38 Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject#1 at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081) Local Variable: java.util.concurrent.locks.ReentrantLock#1 at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809) Local Variable: java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue#1 at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134) Local Variable: java.util.concurrent.ScheduledThreadPoolExecutor#1 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) Local Variable: java.util.concurrent.ThreadPoolExecutor$Worker#10 at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) Local Variable: org.apache.tomcat.util.threads.TaskThread$WrappingRunnable#10 at java.lang.Thread.run(Thread.java:748) "FileHandlerLogFilesCleaner-1" daemon prio=5 tid=12 WAITING at sun.misc.Unsafe.park(Native Method) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject#6 Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$Node#116 at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442) Local Variable: java.util.concurrent.locks.ReentrantLock#128 Local Variable: java.util.concurrent.atomic.AtomicInteger#7 Local Variable: java.util.concurrent.LinkedBlockingQueue#1 at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134) Local Variable: java.util.concurrent.ThreadPoolExecutor#1 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) Local Variable: java.util.concurrent.ThreadPoolExecutor$Worker#12 at java.lang.Thread.run(Thread.java:748) "Attach Listener" daemon prio=5 tid=5 RUNNABLE "NioBlockingSelector.BlockPoller-1" daemon prio=5 tid=14 RUNNABLE at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method) at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296) at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278) Local Variable: sun.nio.ch.WindowsSelectorImpl$SubSelector#2 at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86) Local Variable: java.util.Collections$UnmodifiableSet#4 Local Variable: sun.nio.ch.Util$3#3 at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97) Local Variable: sun.nio.ch.WindowsSelectorImpl#3 at org.apache.tomcat.util.net.NioBlockingSelector$BlockPoller.run(NioBlockingSelector.java:298) "AsyncFileHandlerWriter-1020371697" daemon prio=5 tid=11 TIMED_WAITING at sun.misc.Unsafe.park(Native Method) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078) Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject#4 Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$Node#89 at java.util.concurrent.LinkedBlockingDeque.pollFirst(LinkedBlockingDeque.java:522) Local Variable: java.util.concurrent.locks.ReentrantLock#127 at java.util.concurrent.LinkedBlockingDeque.poll(LinkedBlockingDeque.java:684) Local Variable: java.util.concurrent.LinkedBlockingDeque#1 Local Variable: java.util.concurrent.TimeUnit$3#1 at org.apache.juli.AsyncFileHandler$LoggerThread.run(AsyncFileHandler.java:159) "Reference Handler" daemon prio=10 tid=2 WAITING at java.lang.Object.wait(Native Method) at java.lang.Object.wait(Object.java:502) at java.lang.ref.Reference.tryHandlePending(Reference.java:191) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153) "GC Daemon" daemon prio=2 tid=13 TIMED_WAITING at java.lang.Object.wait(Native Method) at sun.misc.GC$Daemon.run(GC.java:117) JP -----Original Message----- From: Igal Sapir <i...@lucee.org> Sent: Tuesday, January 8, 2019 00:10 To: Tomcat Users List <users@tomcat.apache.org> Subject: Re: Tomcat 9.0.14 Windows service slow to stop On Mon, Jan 7, 2019 at 8:57 PM Christopher Schultz < ch...@christopherschultz.net> wrote: > -----BEGIN PGP SIGNED MESSAGE----- > Hash: SHA256 > > Steve, > > On 1/7/19 19:47, Steve Demy wrote: > > 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 > <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/aj > > ax > /%3CDEB74971-2714-401F-9428-25EE0ECC6D11%40shaw.ca%3E > <http://mail-archives.apache.org/mod_mbox/tomcat-users/201812.mbox/aja > x/%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. > > Certainly nothing in catalina.sh affects Windows Services. Even > catalina.bat is ignored for Windows Services. > +1 > Your issue is that Tomcat's scripts (well, actually, some 3rd-party > scripts, actually) can't manage to stop Tomcat. Jean-Pascal's problem > is that his shutdown is taking 60sec when he thinks it shouldn't take > that long. > I've seen this happen when an application, or a 3rd-party library starts a non-daemon thread and it is not stopped prior to the shutdown attempt. I think that there is a 60 second timeout because I've also noticed about that same time frame when it happens. > > Jean-Pascal, what do the Tomcat logs say? There should be something > like catalina.out or stdout.log or something like that. > +1 Another thing I would try is to look at a thread dump. Igal > > - -chris > > >> On Jan 7, 2019, at 3:38 PM, Jean-Pascal Houde <jpho...@korem.com> > >> 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 > > > -----BEGIN PGP SIGNATURE----- > Comment: Using GnuPG with Thunderbird - https://www.enigmail.net/ > > iQIzBAEBCAAdFiEEMmKgYcQvxMe7tcJcHPApP6U8pFgFAlw0LcEACgkQHPApP6U8 > pFgfsg//Yv9k+Lqnn/nH2Pd2iahEJnPRZVRUeg2bRFQGlpwRURApBzup8646UsFE > zo9zxfJuuw2L/jea7rfZaXJaXay6nhaJ/h5+RPfq1CExNLjcK/3GjJwmZxSUqJxl > PtNtpjsJr8lD3OXMzu9sqr26Zj3AtPbAqpJFr1A9LGlflpIi5ohqzVkpA3h2knEH > luxjEbsD5uaG7YlQdzal76a81RBN0glBUvdgP1dPsgXKscMdYkoIzNYL7G5TniAx > 3Jsilp0oWYfDEJ0oFRmUAjN++jq4QefMZHow3QUEU8xZ8L47JQv6ZlmkSbqPndH0 > /kdrUA9Cv82lN0czBz2u+KmKduot7tc+KEqS+RJD8Pkj9Jy7FOLCu9klLXk3LXFG > M22XPJdwnIDQeVnjJKxjiUhetFjOCSzH3FyL/VuxAsO4qsCqSgiW/RRrU+FdLYfs > OQPjOzGISu/9lwZ+M7yPJ1XzCoBbpVE1iHf0R5vuI0H922oXRu0dyx/IKnEpbGrv > GY6zRrte4AtLO0oMXeDxWH/iC9xgRn+B4oy8Gd3RY9l6A1vLeT41flCSjAvtSkeU > AE5N4iJp39mGJ/iUpWa7C5tzwbV1syv1weC4BzHVl5+W+YBBlv6x/HJX2Zc9dsMO > okn6tCEuKFnSCqc4N4IdocolkISqObVe35RYioYHxBStMDr5dpU= > =xtqK > -----END PGP SIGNATURE----- > > --------------------------------------------------------------------- > To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org > For additional commands, e-mail: users-h...@tomcat.apache.org > >