'Is RMI leak prevention working properly? Shutdown failure'

[prev in list] [next in list] [prev in thread] [next in thread] 

List:       tomcat-user
Subject:    Is RMI leak prevention working properly? Shutdown failure
From:       Leon Atherton <leon () idrsolutions ! com>
Date:       2023-10-18 12:12:46
Message-ID: cafcd706-aaed-4a14-be9c-8e234e2c7656 () idrsolutions ! com
[Download RAW message or body]

Hello,

I have observed that the Tomcat process does not shut down properly when 
the RMI leak prevention is triggered. The process remains alive and 
holds onto the RMI port.

I have created this sample project to demonstrate the issue:
https://github.com/leonatherton/rmi-leak-test/blob/master/src/main/java/rmi/RmiLeakTestServlet.java

There are prebuilt wars here:
https://github.com/leonatherton/rmi-leak-test/releases/tag/v0.0.0

Steps to reproduce:
1. Deploy the war (rmi-leak-test.war)
2. Trigger a shutdown
3. Observe that the process does not end, and holds on to the RMI port 
(can be seen with netstat -tulpn)

This message is logged:

SEVERE [main] 
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesRmiTargets 
Found RMI Target with stub class class [com.sun.proxy.$Proxy5] and value 
[Proxy[MyRemote,RemoteObjectInvocationHandler[UnicastRef [liveRef: 
[endpoint:[127.0.0.1:46013](local),objID:[-30127669:18b42a65f21:-7fff, 
8331338290308659576]]]]]]. This RMI Target has been forcibly removed to 
prevent a memory leak.

Tomcat obviously tries to tidy up, but it seems like maybe not 
successfully. I am wondering if it is expected behaviour for the process 
to remain alive?

Full log below.

Thanks,
Leon

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.base/java.util=ALL-UNNAMED 
--add-opens=java.base/java.util.concurrent=ALL-UNNAMED 
--add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
18-Oct-2023 11:57:59.621 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Server version 
name:   Apache Tomcat/9.0.73
18-Oct-2023 11:57:59.650 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Server 
built:          Feb 27 2023 15:33:40 UTC
18-Oct-2023 11:57:59.650 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Server version 
number: 9.0.73.0
18-Oct-2023 11:57:59.650 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log OS 
Name:               Linux
18-Oct-2023 11:57:59.650 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log OS 
Version:            3.10.0-1160.45.1.el7.x86_64
18-Oct-2023 11:57:59.650 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log 
Architecture:          amd64
18-Oct-2023 11:57:59.650 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Java 
Home:             /usr/lib/jvm/java-11-amazon-corretto
18-Oct-2023 11:57:59.650 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log JVM 
Version:           11.0.20.1+9-LTS
18-Oct-2023 11:57:59.650 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log JVM 
Vendor:            Amazon.com Inc.
18-Oct-2023 11:57:59.651 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log 
CATALINA_BASE:         /home/converter/apache-tomcat-base
18-Oct-2023 11:57:59.651 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log 
CATALINA_HOME:         /home/converter/apache-tomcat-9.0.73
18-Oct-2023 11:57:59.669 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Command line 
argument: --add-opens=java.base/java.lang=ALL-UNNAMED
18-Oct-2023 11:57:59.669 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Command line 
argument: --add-opens=java.base/java.io=ALL-UNNAMED
18-Oct-2023 11:57:59.669 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Command line 
argument: --add-opens=java.base/java.util=ALL-UNNAMED
18-Oct-2023 11:57:59.669 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Command line 
argument: --add-opens=java.base/java.util.concurrent=ALL-UNNAMED
18-Oct-2023 11:57:59.669 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Command line 
argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
18-Oct-2023 11:57:59.669 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Command line 
argument: 
-Djava.util.logging.config.file=/home/converter/apache-tomcat-base//conf/logging.properties
18-Oct-2023 11:57:59.670 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Command line 
argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
18-Oct-2023 11:57:59.670 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Command line 
argument: -Djdk.tls.ephemeralDHKeySize=2048
18-Oct-2023 11:57:59.670 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Command line 
argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
18-Oct-2023 11:57:59.670 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Command line 
argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
18-Oct-2023 11:57:59.670 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Command line 
argument: -Dignore.endorsed.dirs=
18-Oct-2023 11:57:59.670 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Command line 
argument: -Dcatalina.base=/home/converter/apache-tomcat-base/
18-Oct-2023 11:57:59.670 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Command line 
argument: -Dcatalina.home=/home/converter/apache-tomcat
18-Oct-2023 11:57:59.670 INFO [main] 
org.apache.catalina.startup.VersionLoggerListener.log Command line 
argument: -Djava.io.tmpdir=/home/converter/apache-tomcat-base//temp
18-Oct-2023 11:57:59.672 INFO [main] 
org.apache.catalina.core.AprLifecycleListener.lifecycleEvent The Apache 
Tomcat Native library which allows using OpenSSL was not found on the 
java.library.path: [/usr/java/packages/lib:/usr/lib64:/lib64:/lib:/usr/lib]
18-Oct-2023 11:58:00.555 INFO [main] 
org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler 
["http-nio-8080"]
18-Oct-2023 11:58:00.626 INFO [main] 
org.apache.catalina.startup.Catalina.load Server initialization in 
[1422] milliseconds
18-Oct-2023 11:58:00.754 INFO [main] 
org.apache.catalina.core.StandardService.startInternal Starting service 
[Catalina]
18-Oct-2023 11:58:00.754 INFO [main] 
org.apache.catalina.core.StandardEngine.startInternal Starting Servlet 
engine: [Apache Tomcat/9.0.73]
18-Oct-2023 11:58:00.757 SEVERE [main] 
org.apache.catalina.startup.HostConfig.beforeStart Unable to create 
directory for deployment: 
[/home/converter/apache-tomcat-base/conf/Catalina/localhost]
18-Oct-2023 11:58:00.784 INFO [main] 
org.apache.catalina.startup.HostConfig.deployWAR Deploying web 
application archive 
[/home/converter/apache-tomcat-base/webapps/rmi-leak-test.war]
18-Oct-2023 11:58:01.483 INFO [main] rmi.RmiLeakTestServlet.init Init 
leak test
18-Oct-2023 11:58:01.561 INFO [main] 
org.apache.catalina.startup.HostConfig.deployWAR Deployment of web 
application archive 
[/home/converter/apache-tomcat-base/webapps/rmi-leak-test.war] has 
finished in [776] ms
18-Oct-2023 11:58:01.594 INFO [main] 
org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler 
["http-nio-8080"]
18-Oct-2023 11:58:01.651 INFO [main] 
org.apache.catalina.startup.Catalina.start Server startup in [1025] 
milliseconds
18-Oct-2023 11:58:09.825 INFO [main] 
org.apache.catalina.core.StandardServer.await A valid shutdown command 
was received via the shutdown port. Stopping the Server instance.
18-Oct-2023 11:58:09.826 INFO [main] 
org.apache.coyote.AbstractProtocol.pause Pausing ProtocolHandler 
["http-nio-8080"]
18-Oct-2023 11:58:09.843 INFO [main] 
org.apache.catalina.core.StandardService.stopInternal Stopping service 
[Catalina]
18-Oct-2023 11:58:09.844 INFO [main] rmi.RmiLeakTestServlet.destroy 
Destroy leak test
18-Oct-2023 11:58:09.964 SEVERE [main] 
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesRmiTargets 
Found RMI Target with stub class class [com.sun.proxy.$Proxy5] and value 
[Proxy[MyRemote,RemoteObjectInvocationHandler[UnicastRef [liveRef: 
[endpoint:[127.0.0.1:46013](local),objID:[-30127669:18b42a65f21:-7fff, 
8331338290308659576]]]]]]. This RMI Target has been forcibly removed to 
prevent a memory leak.
18-Oct-2023 11:58:09.966 INFO [main] 
org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler 
["http-nio-8080"]
18-Oct-2023 11:58:09.979 INFO [main] 
org.apache.coyote.AbstractProtocol.destroy Destroying ProtocolHandler 
["http-nio-8080"]


---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org

[prev in list] [next in list] [prev in thread] [next in thread]
Configure | About | News | Add a list | Sponsored by KoreLogic