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 <[email protected]>
Sent: Tuesday, January 8, 2019 00:10
To: Tomcat Users List <[email protected]>
Subject: Re: Tomcat 9.0.14 Windows service slow to stop
On Mon, Jan 7, 2019 at 8:57 PM Christopher Schultz <
[email protected]> 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 <[email protected]>
> >> 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: [email protected]
> >> For additional commands, e-mail: [email protected]
> >>
> >
> >
> > --------------------------------------------------------------------
> > -
> >
> >
> To unsubscribe, e-mail: [email protected]
> > For additional commands, e-mail: [email protected]
> >
> -----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: [email protected]
> For additional commands, e-mail: [email protected]
>
>
