Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8050876

Unexporting an RMIRegistry returns before the server socket is unbound

XMLWordPrintable

      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)

            dmeetry Dmeetry Degrave (Inactive)
            shadowbug Shadow Bug
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: