I've an executable jar file that uses embedded tomcat(9.0.44). And its running as windows service (named "MyApp Test Service") with the apache prunsrv
utility.
But when I try to stop the service it takes some time (more than one minute) to stop the service. But starting the service is pretty quick.
I can confirm that the stop()
method of the tomcat completes quickly. I suspect there is something else within the prunsrv
which waits and takes time to stop the service. Please help to understand what is going on and how to resolve this(stop service right away after executing tomcat.stop()
)
C:\ServiceTest\prunsrv.exe" "//RS//MyApp Test Service"
com.samples.myapp.TestEmbeddedServer::main
com.samples.myapp.TestEmbeddedServer::stop
TomcatEmbeddedServer .java
public class TomcatEmbeddedServer {
private int port;
private Tomcat tomcat;
private Context context;
private static final Logger LOGGER = LoggerFactory.getLogger(TomcatEmbeddedServer.class);
public TomcatEmbeddedServer(int port, String contextName, String tomcatPath, String webAppPath) {
System.setProperty("org.apache.tomcat.util.buf.UDecoder.ALLOW_ENCODED_SLASH", "true");
System.setProperty("org.apache.catalina.connector.CoyoteAdapter.ALLOW_BACKSLASH", "true");
this.port = port;
LOGGER.info("Port: {}", port);
LOGGER.info("Context: {}", contextName);
LOGGER.info("Tomcat Path: {}", tomcatPath);
LOGGER.info("Webapp Path: {}", webAppPath);
// Prepare tomcat server
this.tomcat = new Tomcat();
this.tomcat.setBaseDir(tomcatPath);
// Set up the context
this.context = this.tomcat.addWebapp(contextName, webAppPath);
this.context.setParentClassLoader(Thread.currentThread().getContextClassLoader());
}
public void start() throws LifecycleException {
Connector connector = this.tomcat.getConnector();
connector.setEncodedSolidusHandling(EncodedSolidusHandling.DECODE.getValue());
connector.setPort(this.port);
LOGGER.info("Starting tomcat server ...{}", this.tomcat);
this.tomcat.start();
this.tomcat.getServer().await();
}
public void stop() throws LifecycleException {
this.tomcat.stop();
}
}
TestEmbeddedServer.java
public class TestEmbeddedServer {
private static TomcatEmbeddedServer tomcat;
private static Logger log = LoggerFactory.getLogger(TestEmbeddedServer.class);
public static void main(String[] args) {
String tomcatDir = "D:/testserver/tomcat";
String webAppDir = "D:/testserver/mysampleapp";
String context = "/sampleapp";
int port = 8090;
try
{
tomcat = new TomcatEmbeddedServer(port, context, tomcatDir, webAppDir);
tomcat.start();
} catch (Exception e) {
log.error("Failed to start tomcat server." , e);
}
}
public static void stop(String[] args) {
try {
tomcat.stop();
} catch (LifecycleException e) {
log.error("Failed to stop tomcat.", e);
}
}
}
And following is the prunserv startup/shutdown logs I obtained
[2021-06-02 10:42:36] [debug] ( prunsrv.c:1729) [85696] Commons Daemon procrun log initialized
[2021-06-02 10:42:36] [info] ( prunsrv.c:1733) [85696] Commons Daemon procrun (1.1.0.0 64-bit) started
[2021-06-02 10:42:36] [info] ( prunsrv.c:1643) [85696] Running 'MyApp Test Service' Service...
[2021-06-02 10:42:36] [debug] ( prunsrv.c:1417) [85736] Inside ServiceMain...
[2021-06-02 10:42:36] [debug] ( prunsrv.c:885 ) [85736] reportServiceStatusE: dwCurrentState = 2, dwWin32ExitCode = 0, dwWaitHint = 3000, dwServiceSpecificExitCode = 0
[2021-06-02 10:42:36] [info] ( prunsrv.c:1175) [85736] Starting service...
[2021-06-02 10:42:36] [debug] ( javajni.c:236 ) [85736] loading jvm 'C:\Program Files\Java\bin\server\jvm.dll'
[2021-06-02 10:42:36] [debug] ( javajni.c:753 ) [85744] Jvm Option[0] -Dfile.encoding=UTF8
[2021-06-02 10:42:36] [debug] ( javajni.c:753 ) [85744] Jvm Option[1] --add-opens=java.base/java.lang=ALL-UNNAMED
[2021-06-02 10:42:36] [debug] ( javajni.c:753 ) [85744] Jvm Option[2] --add-opens=java.base/java.io=ALL-UNNAMED
[2021-06-02 10:42:36] [debug] ( javajni.c:753 ) [85744] Jvm Option[3] --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
[2021-06-02 10:42:36] [debug] ( javajni.c:753 ) [85744] Jvm Option[4] --illegal-access=permit
[2021-06-02 10:42:36] [debug] ( javajni.c:753 ) [85744] Jvm Option[5] exit
[2021-06-02 10:42:36] [debug] ( javajni.c:753 ) [85744] Jvm Option[6] abort
[2021-06-02 10:42:39] [debug] ( javajni.c:990 ) [85744] Java Worker thread started com/samples/myapp/TestEmbeddedServer:main
[2021-06-02 10:42:40] [debug] ( prunsrv.c:1235) [85736] Java started com/samples/myapp/TestEmbeddedServer
[2021-06-02 10:42:40] [info] ( prunsrv.c:1333) [85736] Service started in 4102 ms.
[2021-06-02 10:42:40] [debug] ( prunsrv.c:885 ) [85736] reportServiceStatusE: dwCurrentState = 4, dwWin32ExitCode = 0, dwWaitHint = 0, dwServiceSpecificExitCode = 0
[2021-06-02 10:42:40] [debug] ( prunsrv.c:1572) [85736] Waiting for worker to finish...
[2021-06-02 10:43:38] [debug] ( prunsrv.c:885 ) [85696] reportServiceStatusE: dwCurrentState = 3, dwWin32ExitCode = 0, dwWaitHint = 3000, dwServiceSpecificExitCode = 0
[2021-06-02 10:43:39] [info] ( prunsrv.c:984 ) [85296] Stopping service...
[2021-06-02 10:43:40] [debug] ( javajni.c:990 ) [85488] Java Worker thread started com/samples/myapp/TestEmbeddedServer:stop
[2021-06-02 10:43:41] [debug] ( prunsrv.c:1032) [85296] Waiting for Java JNI stop worker to finish...
[2021-06-02 10:43:48] [debug] ( javajni.c:1013) [85744] Java Worker thread finished com/samples/myapp/TestEmbeddedServer:main with status = 0
[2021-06-02 10:43:48] [debug] ( javajni.c:1013) [85488] Java Worker thread finished com/samples/myapp/TestEmbeddedServer:stop with status = 0
[2021-06-02 10:43:48] [debug] ( prunsrv.c:1034) [85296] Java JNI stop worker finished.
[2021-06-02 10:43:48] [debug] ( prunsrv.c:885 ) [85296] reportServiceStatusE: dwCurrentState = 3, dwWin32ExitCode = 0, dwWaitHint = 5000, dwServiceSpecificExitCode = 0
[2021-06-02 10:43:48] [debug] ( prunsrv.c:1141) [85296] Waiting for worker to die naturally...
[2021-06-02 10:43:48] [debug] ( prunsrv.c:1152) [85296] Worker finished gracefully in 0 ms.
[2021-06-02 10:43:48] [info] ( prunsrv.c:1162) [85296] Service stop thread completed.
[2021-06-02 10:43:48] [debug] ( prunsrv.c:1577) [85736] Worker finished.
[2021-06-02 10:43:48] [debug] ( prunsrv.c:1586) [85736] Waiting for ShutdownEvent
[2021-06-02 10:43:48] [debug] ( prunsrv.c:885 ) [85736] reportServiceStatusE: dwCurrentState = 3, dwWin32ExitCode = 0, dwWaitHint = 60000, dwServiceSpecificExitCode = 0
[2021-06-02 10:43:48] [debug] ( prunsrv.c:1589) [85736] ShutdownEvent signaled
[2021-06-02 10:43:48] [debug] ( prunsrv.c:1594) [85736] Waiting 1 minute for all threads to exit
[2021-06-02 10:43:48] [debug] ( prunsrv.c:885 ) [85736] reportServiceStatusE: dwCurrentState = 3, dwWin32ExitCode = 0, dwWaitHint = 60000, dwServiceSpecificExitCode = 0
[2021-06-02 10:44:48] [debug] ( prunsrv.c:1607) [85736] JVM destroyed.
[2021-06-02 10:44:48] [debug] ( prunsrv.c:885 ) [85736] reportServiceStatusE: dwCurrentState = 1, dwWin32ExitCode = 0, dwWaitHint = 0, dwServiceSpecificExitCode = 0
[2021-06-02 10:44:48] [info] ( prunsrv.c:1645) [85696] Run service finished.
[2021-06-02 10:44:48] [info] ( prunsrv.c:1814) [85696] Commons Daemon procrun finished
From these logs after the shut down signal there is exactly 1 minute delay to destroy the JVM. And I think this is where it hung.
[2021-06-02 10:43:48] [debug] ( prunsrv.c:1589) [85736] ShutdownEvent signaled
[2021-06-02 10:43:48] [debug] ( prunsrv.c:1594) [85736] Waiting 1 minute for all threads to exit
[2021-06-02 10:43:48] [debug] ( prunsrv.c:885 ) [85736] reportServiceStatusE: dwCurrentState = 3, dwWin32ExitCode = 0, dwWaitHint = 60000, dwServiceSpecificExitCode = 0
[2021-06-02 10:44:48] [debug] ( prunsrv.c:1607) [85736] JVM destroyed.
In the prunmngr UI, the progress indicator is dismissed but the the start button is not enabled. See screenshot below.
EDIT: Results by varying the versions of Tomcat
Tomcat Version Used | Time Taken to stop |
---|---|
Apache Tomcat/8.5.66 | ~9 seconds |
Apache Tomcat/9.0.1 | ~ 9 seconds |
Apache Tomcat/9.0.10 | ~ 9 seconds |
Apache Tomcat/9.0.13 | ~ 9 seconds |
Apache Tomcat/9.0.14 | ~ 1 min 3 secs |
Apache Tomcat/9.0.16 | ~ 1 min 3 secs |
Apache Tomcat/9.0.20 | ~ 1 min 3 secs |
Apache Tomcat/9.0.30 | ~ 1 min 3 secs |
Apache Tomcat/9.0.40 | ~ 1 min 3 secs |
Apache Tomcat/9.0.44 | ~ 1 min 3 secs |
Apache Tomcat/9.0.46 | ~ 1 min 3 secs |
Apache Tomcat/10.0.6 | ~ 1 min 3 secs |
Since Tomcat version 9.0.14 an utility executor has been introduced:
Add a scheduled executor to the Server, which can be used to process periodic utility tasks. The utility threads are non daemon by default. (remm)
Its threads are intentionally non daemon so that a server stop()
does not close the JVM. To entirely stop the server you must use destroy()
:
public void stop() throws LifecycleException {
this.tomcat.stop();
this.tomcat.destroy();
}