-
Bug
-
Resolution: Not an Issue
-
P3
-
7u51
-
linux
When creating a RMIRegistry programmatically on a custom port, then later
unexport the registry, it is expected the server socket to be unbound and
available for re-use. However sometimes the unexportObject call will return
successfully, but the server socket will remain bound for a short period.
The unexportObject call do not seem to be waiting the termination of the RMI
TCP Accept thread, so at application level it is difficult to know when port
becomes available for reuse.
The customer uses a server application that permits the user to dynamically
assign ports (including the RMIRegistry port) through a management UI. The
user may change/stop/start the RMI port at runtime. The issue occurs during
our automated system testing of these features.
A testcase has been provided to reproduce the error:
Exception in thread "main" java.net.BindException: Address already in use
I have a small program that demonstrate the problem and have the JUL output
from sub.rmi.transport.
I have reproduced the problem on JDK 1.7_0.51 and 1.8.0_05-b13.
Issue Clarification
===================
Using the following testcase:
import java.io.IOException;
import java.net.InetSocketAddress;
import java.net.ServerSocket;
import java.rmi.registry.LocateRegistry;
import java.rmi.registry.Registry;
import java.rmi.server.RMIServerSocketFactory;
import java.rmi.server.UnicastRemoteObject;
import java.util.logging.*;
public class Main {
private static Logger LOGGER = Logger.getLogger(Main.class.getName());
public static void main(String[] args) throws Exception
{
int i=0;
try
{
while(true)
{
i++;
LOGGER.fine("==================== Running test
==========================");
Registry reg = LocateRegistry.createRegistry(5001, null, new
RMIServerSocketFactory()
{
@Override
public ServerSocket createServerSocket(final int port) throws IOException
{
ServerSocket serverSocket = new ServerSocket()
{
@Override
public void close() throws IOException
{
try
{
super.close();
}
finally
{
LOGGER.fine("Thread " + Thread.currentThread() + " closing socket " + port +
"-" + System.nanoTime());
}
}
};
serverSocket.setReuseAddress(true);
serverSocket.bind(new InetSocketAddress(port));
return serverSocket;
}
});
UnicastRemoteObject.unexportObject(reg, true); // I expect this to free
5001
LOGGER.fine("Successfully unexported object" + System.nanoTime());
ServerSocket testSocketFree = new ServerSocket(5001);
// Expecting port to be successfully bound
testSocketFree.close();
}
}
catch(Exception e)
{
LOGGER.log(Level.SEVERE, "an exception was thrown", e);
throw e;
}
finally
{
LOGGER.fine("Exited after " + i + " iteration(s)");
}
}
}
The application should be run with a modified logging properties, and after a
lot of cycles it fails with Exception
$ grep FINE logging.properties
.level= FINER
java.util.logging.ConsoleHandler.level = FINER
$ /usr/java/jdk1.7.0_51/bin/java -showversion
-Djava.util.logging.config.file=./logging.properties
-Djava.rmi.server.logCalls=true -classpath
. Main
...
....
FINE: Successfully unexported object9000961531569661
Jul 04, 2014 9:55:38 AM Main$1$1 close
FINE: Thread Thread[RMI TCP Accept-5001,5,system] closing socket
5001-9000961531547091
Jul 04, 2014 9:55:38 AM Main main
FINE: ==================== Running test ==========================
Jul 04, 2014 9:55:38 AM sun.rmi.transport.tcp.TCPTransport <init>
FINE: main: Version = 2, ep = [140.84.226.207:5001,Main$1@60a5b3a9]
Jul 04, 2014 9:55:38 AM sun.rmi.transport.tcp.TCPEndpoint getLocalEndpoint
FINE: main: created local endpoint for socket factory Main$1@60a5b3a9 on port
5001
Jul 04, 2014 9:55:39 AM sun.rmi.transport.WeakRef pin
FINER: main: strongRef = RegistryImpl[UnicastServerRef2 [liveRef:
[endpoint:[140.84.226.207:5001,Main$1@60a5b3a9](local),objID:[0:0:0, 0]]]]
Jul 04, 2014 9:55:39 AM sun.rmi.transport.tcp.TCPTransport listen
FINE: main: (port 5001) create server socket
Jul 04, 2014 9:55:39 AM sun.rmi.transport.tcp.TCPEndpoint newServerSocket
FINER: main: creating server socket on [140.84.226.207:5001,Main$1@60a5b3a9]
Jul 04, 2014 9:55:39 AM sun.rmi.transport.ObjectTable putTarget
FINER: main: add object [0:0:0, 0]
Jul 04, 2014 9:55:39 AM sun.rmi.transport.tcp.TCPTransport$AcceptLoop
executeAcceptLoop
FINE: RMI TCP Accept-5001: listening on port 5001
Jul 04, 2014 9:55:39 AM sun.rmi.transport.ObjectTable removeTarget
FINER: main: remove object [0:0:0, 0]
Jul 04, 2014 9:55:39 AM Main$1$1 close
FINE: Thread Thread[main,5,main] closing socket 5001-9000961544458041
Jul 04, 2014 9:55:39 AM Main main
FINE: Successfully unexported object9000961544541121
Jul 04, 2014 9:55:39 AM Main$1$1 close
FINE: Thread Thread[RMI TCP Accept-5001,5,system] closing socket
5001-9000961545215935
Jul 04, 2014 9:55:39 AM Main main
SEVERE: an exception was thrown
java.net.BindException: Address already in use
at java.net.PlainSocketImpl.socketBind(Native Method)
at java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:376)
at java.net.ServerSocket.bind(ServerSocket.java:376)
at java.net.ServerSocket.<init>(ServerSocket.java:237)
at java.net.ServerSocket.<init>(ServerSocket.java:128)
at Main.main(Main.java:53)
Jul 04, 2014 9:55:39 AM Main main
FINE: Exited after 91009 iteration(s)
Exception in thread "main" java.net.BindException: Address already in use
at java.net.PlainSocketImpl.socketBind(Native Method)
at java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:376)
at java.net.ServerSocket.bind(ServerSocket.java:376)
at java.net.ServerSocket.<init>(ServerSocket.java:237)
at java.net.ServerSocket.<init>(ServerSocket.java:128)
at Main.main(Main.java:53)
unexport the registry, it is expected the server socket to be unbound and
available for re-use. However sometimes the unexportObject call will return
successfully, but the server socket will remain bound for a short period.
The unexportObject call do not seem to be waiting the termination of the RMI
TCP Accept thread, so at application level it is difficult to know when port
becomes available for reuse.
The customer uses a server application that permits the user to dynamically
assign ports (including the RMIRegistry port) through a management UI. The
user may change/stop/start the RMI port at runtime. The issue occurs during
our automated system testing of these features.
A testcase has been provided to reproduce the error:
Exception in thread "main" java.net.BindException: Address already in use
I have a small program that demonstrate the problem and have the JUL output
from sub.rmi.transport.
I have reproduced the problem on JDK 1.7_0.51 and 1.8.0_05-b13.
Issue Clarification
===================
Using the following testcase:
import java.io.IOException;
import java.net.InetSocketAddress;
import java.net.ServerSocket;
import java.rmi.registry.LocateRegistry;
import java.rmi.registry.Registry;
import java.rmi.server.RMIServerSocketFactory;
import java.rmi.server.UnicastRemoteObject;
import java.util.logging.*;
public class Main {
private static Logger LOGGER = Logger.getLogger(Main.class.getName());
public static void main(String[] args) throws Exception
{
int i=0;
try
{
while(true)
{
i++;
LOGGER.fine("==================== Running test
==========================");
Registry reg = LocateRegistry.createRegistry(5001, null, new
RMIServerSocketFactory()
{
@Override
public ServerSocket createServerSocket(final int port) throws IOException
{
ServerSocket serverSocket = new ServerSocket()
{
@Override
public void close() throws IOException
{
try
{
super.close();
}
finally
{
LOGGER.fine("Thread " + Thread.currentThread() + " closing socket " + port +
"-" + System.nanoTime());
}
}
};
serverSocket.setReuseAddress(true);
serverSocket.bind(new InetSocketAddress(port));
return serverSocket;
}
});
UnicastRemoteObject.unexportObject(reg, true); // I expect this to free
5001
LOGGER.fine("Successfully unexported object" + System.nanoTime());
ServerSocket testSocketFree = new ServerSocket(5001);
// Expecting port to be successfully bound
testSocketFree.close();
}
}
catch(Exception e)
{
LOGGER.log(Level.SEVERE, "an exception was thrown", e);
throw e;
}
finally
{
LOGGER.fine("Exited after " + i + " iteration(s)");
}
}
}
The application should be run with a modified logging properties, and after a
lot of cycles it fails with Exception
$ grep FINE logging.properties
.level= FINER
java.util.logging.ConsoleHandler.level = FINER
$ /usr/java/jdk1.7.0_51/bin/java -showversion
-Djava.util.logging.config.file=./logging.properties
-Djava.rmi.server.logCalls=true -classpath
. Main
...
....
FINE: Successfully unexported object9000961531569661
Jul 04, 2014 9:55:38 AM Main$1$1 close
FINE: Thread Thread[RMI TCP Accept-5001,5,system] closing socket
5001-9000961531547091
Jul 04, 2014 9:55:38 AM Main main
FINE: ==================== Running test ==========================
Jul 04, 2014 9:55:38 AM sun.rmi.transport.tcp.TCPTransport <init>
FINE: main: Version = 2, ep = [140.84.226.207:5001,Main$1@60a5b3a9]
Jul 04, 2014 9:55:38 AM sun.rmi.transport.tcp.TCPEndpoint getLocalEndpoint
FINE: main: created local endpoint for socket factory Main$1@60a5b3a9 on port
5001
Jul 04, 2014 9:55:39 AM sun.rmi.transport.WeakRef pin
FINER: main: strongRef = RegistryImpl[UnicastServerRef2 [liveRef:
[endpoint:[140.84.226.207:5001,Main$1@60a5b3a9](local),objID:[0:0:0, 0]]]]
Jul 04, 2014 9:55:39 AM sun.rmi.transport.tcp.TCPTransport listen
FINE: main: (port 5001) create server socket
Jul 04, 2014 9:55:39 AM sun.rmi.transport.tcp.TCPEndpoint newServerSocket
FINER: main: creating server socket on [140.84.226.207:5001,Main$1@60a5b3a9]
Jul 04, 2014 9:55:39 AM sun.rmi.transport.ObjectTable putTarget
FINER: main: add object [0:0:0, 0]
Jul 04, 2014 9:55:39 AM sun.rmi.transport.tcp.TCPTransport$AcceptLoop
executeAcceptLoop
FINE: RMI TCP Accept-5001: listening on port 5001
Jul 04, 2014 9:55:39 AM sun.rmi.transport.ObjectTable removeTarget
FINER: main: remove object [0:0:0, 0]
Jul 04, 2014 9:55:39 AM Main$1$1 close
FINE: Thread Thread[main,5,main] closing socket 5001-9000961544458041
Jul 04, 2014 9:55:39 AM Main main
FINE: Successfully unexported object9000961544541121
Jul 04, 2014 9:55:39 AM Main$1$1 close
FINE: Thread Thread[RMI TCP Accept-5001,5,system] closing socket
5001-9000961545215935
Jul 04, 2014 9:55:39 AM Main main
SEVERE: an exception was thrown
java.net.BindException: Address already in use
at java.net.PlainSocketImpl.socketBind(Native Method)
at java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:376)
at java.net.ServerSocket.bind(ServerSocket.java:376)
at java.net.ServerSocket.<init>(ServerSocket.java:237)
at java.net.ServerSocket.<init>(ServerSocket.java:128)
at Main.main(Main.java:53)
Jul 04, 2014 9:55:39 AM Main main
FINE: Exited after 91009 iteration(s)
Exception in thread "main" java.net.BindException: Address already in use
at java.net.PlainSocketImpl.socketBind(Native Method)
at java.net.AbstractPlainSocketImpl.bind(AbstractPlainSocketImpl.java:376)
at java.net.ServerSocket.bind(ServerSocket.java:376)
at java.net.ServerSocket.<init>(ServerSocket.java:237)
at java.net.ServerSocket.<init>(ServerSocket.java:128)
at Main.main(Main.java:53)