7 Replies Latest reply on Jun 4, 2007 8:35 AM by Claudia Richter

    unexpected server shutdown with sslsocket

    Claudia Richter Newbie

      Hi there,
      I have a problem with connections between my client and my server when using sslsocket protocol. My server unexpectedly shuts down during refresh. I looked at it for my self and this is what I found out:

      It happens that somehow during a refresh in the SocketServerInvoker, the socket is not unbound correctly after a not allowed atempt to connect. So when creating a new socket and trying to bind it to the old address, a BindException occures, when calling this line:

      ServerSocket newServerSocket = createServerSocket(getServerBindPort(), backlog, bindAddress);
      


      in the refreshServerSocket() method.

      My server then shuts down and my client is not able to conect anymore. Here is what my client shows:
      
      2007-04-26 09:54:15,957 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[90c06f, sslsocket://CRICHTER:1101] disconnecting ...
      2007-04-26 09:54:15,957 DEBUG [main] org.jboss.remoting.MicroRemoteClientInvoker: disconnect called for: SocketClientInvoker[90c06f, sslsocket://CRICHTER:1101]
      2007-04-26 09:54:15,957 DEBUG [main] org.jboss.remoting.transport.socket.SocketWrapper: ClientSocketWrapper[1829e6f[TLS_DHE_DSS_WITH_AES_128_CBC_SHA: Socket[addr=CRICHTER.emea.hpqcorp.net/16.58.6.211,port=1101,localport=1636]].1829e6f] closing
      successfully handled this request
      ***************** positive test ******************
      2007-04-26 09:54:30,971 INFO [main] client.ServerConnector: receiving remote Object from Server
      2007-04-26 09:54:30,971 DEBUG [main] client.ServerConnector: setting SSL Properties
      2007-04-26 09:54:30,971 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] constructed
      2007-04-26 09:54:30,971 DEBUG [main] org.jboss.remoting.MicroRemoteClientInvoker: connect called for: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101]
      2007-04-26 09:54:30,971 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] added new pool ([]) as ServerAddress[16.58.6.211:1101, NO enableTcpNoDelay timeout 1800000 ms]
      2007-04-26 09:54:31,986 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1015 ms
      2007-04-26 09:54:32,002 DEBUG [Finalizer] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[90c06f, sslsocket://CRICHTER:1101] disconnecting ...
      2007-04-26 09:54:32,002 DEBUG [Finalizer] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[90c06f, sslsocket://CRICHTER:1101] disconnecting ...
      2007-04-26 09:54:33,002 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1016 ms
      2007-04-26 09:54:34,001 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 999 ms
      2007-04-26 09:54:35,001 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:36,017 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:37,017 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:38,032 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1015 ms
      2007-04-26 09:54:39,032 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:40,032 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:41,047 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1015 ms
      2007-04-26 09:54:42,047 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:43,047 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:44,062 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:44,094 DEBUG [Finalizer] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[2e1f1f, sslsocket://CRICHTER:1101] disconnecting ...
      2007-04-26 09:54:44,094 DEBUG [Finalizer] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[2e1f1f, sslsocket://CRICHTER:1101] disconnecting ...
      2007-04-26 09:54:44,094 DEBUG [Finalizer] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[9934d4, sslsocket://CRICHTER:1101] disconnecting ...
      2007-04-26 09:54:44,094 DEBUG [Finalizer] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[9934d4, sslsocket://CRICHTER:1101] disconnecting ...
      2007-04-26 09:54:44,094 DEBUG [Finalizer] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[16f144c, sslsocket://CRICHTER:1101] disconnecting ...
      2007-04-26 09:54:44,094 DEBUG [Finalizer] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[16f144c, sslsocket://CRICHTER:1101] disconnecting ...
      2007-04-26 09:54:44,094 DEBUG [Finalizer] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[12bcd4b, sslsocket://CRICHTER:1101] disconnecting ...
      2007-04-26 09:54:44,094 DEBUG [Finalizer] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[12bcd4b, sslsocket://CRICHTER:1101] disconnecting ...
      2007-04-26 09:54:45,062 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:46,078 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1016 ms
      2007-04-26 09:54:47,077 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 999 ms
      2007-04-26 09:54:48,077 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:49,093 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1016 ms
      2007-04-26 09:54:50,093 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:51,092 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 999 ms
      2007-04-26 09:54:52,108 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:53,108 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:54,123 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1015 ms
      2007-04-26 09:54:55,123 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:56,123 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:57,138 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1015 ms
      2007-04-26 09:54:58,138 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      2007-04-26 09:54:59,154 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1016 ms
      2007-04-26 09:55:00,153 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 999 ms
      2007-04-26 09:55:01,153 DEBUG [main] org.jboss.remoting.transport.socket.MicroSocketClientInvoker: SocketClientInvoker[180f96c, sslsocket://CRICHTER:1101] got Exception java.net.ConnectException: Connection refused: connect, creation attempt took 1000 ms
      org.jboss.remoting.CannotConnectException: Can not get connection to server. Problem establishing socket connection for InvokerLocator [sslsocket://CRICHTER:1101/]
       at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:525)
       at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:125)
       at org.jboss.remoting.Client.invoke(Client.java:630)
       at org.jboss.remoting.Client.invoke(Client.java:622)
       at org.jboss.remoting.Client.invoke(Client.java:607)
       at org.jboss.remoting.transporter.TransporterClient.invoke(TransporterClient.java:276)
       at $Proxy0.getHandle(Unknown Source)
       at client.Client.getHandle(Client.java:28)
       at client.ClientTest.testGetHandlePositiveMultiple(ClientTest.java:43)
       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
       at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
       at java.lang.reflect.Method.invoke(Unknown Source)
       at junit.framework.TestCase.runTest(TestCase.java:154)
       at junit.framework.TestCase.runBare(TestCase.java:127)
       at junit.framework.TestResult$1.protect(TestResult.java:106)
       at junit.framework.TestResult.runProtected(TestResult.java:124)
       at junit.framework.TestResult.run(TestResult.java:109)
       at junit.framework.TestCase.run(TestCase.java:118)
       at junit.framework.TestSuite.runTest(TestSuite.java:208)
       at junit.framework.TestSuite.run(TestSuite.java:203)
       at org.eclipse.jdt.internal.junit.runner.junit3.JUnit3TestReference.run(JUnit3TestReference.java:128)
       at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
       at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:460)
       at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:673)
       at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:386)
       at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:196)
      Caused by: java.net.ConnectException: Connection refused: connect
       at java.net.PlainSocketImpl.socketConnect(Native Method)
       at java.net.PlainSocketImpl.doConnect(Unknown Source)
       at java.net.PlainSocketImpl.connectToAddress(Unknown Source)
       at java.net.PlainSocketImpl.connect(Unknown Source)
       at java.net.SocksSocketImpl.connect(Unknown Source)
       at java.net.Socket.connect(Unknown Source)
       at com.sun.net.ssl.internal.ssl.SSLSocketImpl.connect(Unknown Source)
       at org.jboss.remoting.transport.socket.SocketClientInvoker.createSocket(SocketClientInvoker.java:187)
       at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.getConnection(MicroSocketClientInvoker.java:796)
       at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:521)
       ... 26 more
      


      And here is what I see on the server when the BindException occures:

      2007-04-26 09:54:25,362 DEBUG [Timer-0] server.Reloader: reloading Truststore, Round 16
      2007-04-26 09:54:25,362 INFO [Timer-0] org.jboss.remoting.transport.socket.SocketServerInvoker: ServerSocketFactory has been updated
      2007-04-26 09:54:25,362 DEBUG [ServerSocketRefresh] org.jboss.remoting.transport.socket.SocketServerInvoker: got notice about new ServerSocketFactory
      2007-04-26 09:54:25,362 DEBUG [ServerSocketRefresh] org.jboss.remoting.transport.socket.SocketServerInvoker: refreshing server socket
      2007-04-26 09:54:25,362 DEBUG [Timer-0] server.Reloader: successfully reloaded truststore
      2007-04-26 09:54:25,362 DEBUG [ServerSocketRefresh] org.jboss.remoting.transport.socket.SocketServerInvoker: could not refresh server socket
      2007-04-26 09:54:25,362 ERROR [AcceptorThread#0:1101] org.jboss.remoting.transport.socket.SocketServerInvoker: SocketServerInvoker[UNINITIALIZED] failed to handle socket
      java.net.SocketException: socket closed
       at java.net.PlainSocketImpl.socketAccept(Native Method)
       at java.net.PlainSocketImpl.accept(Unknown Source)
       at java.net.ServerSocket.implAccept(Unknown Source)
       at com.sun.net.ssl.internal.ssl.SSLServerSocketImpl.accept(Unknown Source)
       at org.jboss.remoting.transport.socket.SocketServerInvoker.run(SocketServerInvoker.java:520)
       at java.lang.Thread.run(Unknown Source)
      2007-04-26 09:54:25,362 DEBUG [ServerSocketRefresh] org.jboss.remoting.transport.socket.SocketServerInvoker: message is: Address already in use: JVM_Bind
      2007-04-26 09:54:25,362 DEBUG [ServerSocketRefresh] org.jboss.remoting.transport.socket.SocketServerInvoker: server socket refreshed
      2007-04-26 09:54:25,362 ERROR [AcceptorThread#0:1101] org.jboss.remoting.transport.socket.SocketServerInvoker: Cannot proceed without functioning server socket. Shutting down
      2007-04-26 09:54:25,362 DEBUG [AcceptorThread#0:1101] org.jboss.remoting.ServerInvoker: SocketServerInvoker[UNINITIALIZED] stopped


      Especially this line is interesting:

      2007-04-26 09:02:09,458 ERROR [AcceptorThread#0:1101] org.jboss.remoting.transport.socket.SocketServerInvoker: Cannot proceed without functioning server socket. Shutting down
      


      In refreshServerSocket() the serverSocket is set to null but then the Exception occures and serverSocket is not set anymore. I guess the BindException shouldn't occur. Is this is a bug? And shall I open a JIRA issue?

      (btw. I use the CVS version of jboss-remoting)

      Thanks for your help
      Claudia