javajava-11tomcat9procrunjava-16

Embedded tomcat running as windows service takes long time to stop the service


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())

Shutdown & Startup tags in the prunmgr UI

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.

GUI after the stop service.. progress bar dismissed but button not enabled

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

Solution

  • 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();
        }