2 Replies Latest reply on Apr 26, 2007 5:14 AM by clarich

    Connection Problem with Release 2.2.0

    clarich

      Hi there,
      I have a confusing problem with my client and server. The problem does not occur always (so might be a timing issue) but sometimes my client receives an InvalidStateException from the server. Actually it sometimes times out or just stucks, when my server runs into this Exception. I tried to figure out where this issue might come from, but I am going in circles about it.

      Here is the dump I get from my client:

      2007-03-20 09:47:05,128 INFO [Thread-103:shutdownRequest:-18691] org.jboss.remoting.transport.multiplex.MultiplexingManager: shutdown: true
      2007-03-20 09:47:05,128 INFO [Thread-103:shutdownRequest:-18691] org.jboss.remoting.transport.multiplex.MultiplexingManager: ShutdownRequestThread.run() done: true
      2007-03-20 09:47:05,128 ERROR [input:-18691] org.jboss.remoting.transport.multiplex.InputMultiplexor: handleChannelException()
      2007-03-20 09:47:05,128 ERROR [input:-18691] org.jboss.remoting.transport.multiplex.InputMultiplexor: java.io.EOFException
      2007-03-20 09:47:05,128 INFO [Thread-105:shutdown] org.jboss.remoting.transport.multiplex.MultiplexingManager: removing from allManagers: Socket[addr=myserver/16.58.5.10,port=1101,localport=1497](1174380425035)
      
      2007-03-20 09:47:05,144 INFO [Thread-105:shutdown] org.jboss.remoting.transport.multiplex.MultiplexingManager: manager shut down (: 1174380425035): Socket[addr=myserver/16.58.5.10,port=1101,localport=1497]
      
      2007-03-20 09:47:05,144 INFO [main] Client: receiving remote Object from Server
      
      2007-03-20 09:47:05,332 INFO [pending actions:-18691] org.jboss.remoting.transport.multiplex.MultiplexingManager: Socket[addr=myserver/16.58.5.10,port=1101,localport=1499]: entering unRegisterSocket()
      2007-03-20 09:47:05,332 INFO [pending actions:-18691] org.jboss.remoting.transport.multiplex.MultiplexingManager: Socket[addr=myserver/16.58.5.10,port=1101,localport=1499]: leaving unRegisterSocket()
      2007-03-20 09:47:05,332 INFO [pending actions:-18691] org.jboss.remoting.transport.multiplex.MultiplexingManager: Socket[addr=myserver/16.58.5.10,port=1101,localport=1499]: entering unRegisterSocket()
      2007-03-20 09:47:05,332 INFO [pending actions:-18691] org.jboss.remoting.transport.multiplex.MultiplexingManager: Socket[addr=myserver/16.58.5.10,port=1101,localport=1499]: leaving unRegisterSocket()
      2007-03-20 09:47:05,332 INFO [input:-18691] org.jboss.remoting.transport.multiplex.InputMultiplexor: unknown socket id: 112
      
      2007-03-20 09:47:05,347 ERROR [main] ClientTest: Test failed:
      java.lang.reflect.UndeclaredThrowableException
       at $Proxy1.getActions(Unknown Source)
       at com.hp.eis.iobus.client.IOBusClient.updatePossibleActions(IOBusClient.java:278)
       at com.hp.eis.iobus.client.IOBusClient.isFileAction(IOBusClient.java:398)
       at com.hp.eis.iobus.client.IOBusClient.runAction(IOBusClient.java:245)
       at com.hp.eis.iobus.client.test.IOBusClientExecuteTest.testRunExecute(IOBusClientExecuteTest.java:60)
       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 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: org.jboss.remoting.ServerInvoker$InvalidStateException: Can not process invocation request since is not in started state.
       at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:745)
       at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:553)
       at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:363)
       at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:159)
       at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:163)
       at org.jboss.remoting.Client.invoke(Client.java:1544)
       at org.jboss.remoting.Client.invoke(Client.java:530)
       at org.jboss.remoting.Client.invoke(Client.java:518)
       at org.jboss.remoting.transporter.TransporterClient.invoke(TransporterClient.java:297)
       ... 25 more
      2007-03-20 09:47:05,363 DEBUG [main] ClientTest: ******************* testRunExecuteWithParams **********************
      2007-03-20 09:47:05,363 INFO [main] Client: starting Client ...
      2007-03-20 09:47:05,378 INFO [main] Client: receiving remote Object from Server
      2007-03-20 09:47:05,378 ERROR [main] ClientTest: Test failed:
      java.lang.reflect.UndeclaredThrowableException
       at $Proxy1.getActions(Unknown Source)
       at com.hp.eis.iobus.client.IOBusClient.updatePossibleActions(IOBusClient.java:278)
       at com.hp.eis.iobus.client.IOBusClient.isFileAction(IOBusClient.java:398)
       at com.hp.eis.iobus.client.IOBusClient.runAction(IOBusClient.java:245)
       at com.hp.eis.iobus.client.test.IOBusClientExecuteTest.testRunExecuteWithParams(IOBusClientExecuteTest.java:35)
       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 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: org.jboss.remoting.ServerInvoker$InvalidStateException: Can not process invocation request since is not in started state.
       at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:745)
       at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:553)
       at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:377)
       at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:159)
       at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:163)
       at org.jboss.remoting.Client.invoke(Client.java:1544)
       at org.jboss.remoting.Client.invoke(Client.java:530)
       at org.jboss.remoting.Client.invoke(Client.java:518)
       at org.jboss.remoting.transporter.TransporterClient.invoke(TransporterClient.java:297)
       ... 25 more
      


      And this is what happens on the server at the same time:
      2007-03-20 09:47:05,128 INFO [pending actions:31889] org.jboss.remoting.transport.multiplex.MultiplexingManager: Socket[addr=/16.58.5.10,port=1497,localport=1101]: entering unRegisterSocket()
      2007-03-20 09:47:05,128 INFO [pending actions:31889] org.jboss.remoting.transport.multiplex.MultiplexingManager: Socket[addr=/16.58.5.10,port=1497,localport=1101]: leaving unRegisterSocket()
      2007-03-20 09:47:05,128 INFO [MultiplexServerInvoker#0v-VirtualServerSocket[Socket[addr=/16.58.5.10,port=1497,localport=1101]]] org.jboss.remoting.transport.multiplex.MultiplexServerInvoker: socket is closed: stopping thread
      2007-03-20 09:47:05,128 INFO [pending actions:31889] org.jboss.remoting.transport.multiplex.MultiplexingManager: Socket[addr=/16.58.5.10,port=1497,localport=1101]: entering unRegisterSocket()
      2007-03-20 09:47:05,128 INFO [pending actions:31889] org.jboss.remoting.transport.multiplex.MultiplexingManager: Socket[addr=/16.58.5.10,port=1497,localport=1101]starting ShutdownRequestThread: Thread[Thread-121:shutdownRequest:31889,5,main]
      2007-03-20 09:47:05,128 INFO [Thread-121:shutdownRequest:31889] org.jboss.remoting.transport.multiplex.MultiplexingManager: shutdown: true
      2007-03-20 09:47:05,128 INFO [Thread-121:shutdownRequest:31889] org.jboss.remoting.transport.multiplex.MultiplexingManager: ShutdownRequestThread.run() done: true
      2007-03-20 09:47:05,128 INFO [pending actions:31889] org.jboss.remoting.transport.multiplex.MultiplexingManager: Socket[addr=/16.58.5.10,port=1497,localport=1101]: leaving unRegisterSocket()
      2007-03-20 09:47:05,128 INFO [Thread-122:shutdown] org.jboss.remoting.transport.multiplex.MultiplexingManager: removing from allManagers: Socket[addr=/16.58.5.10,port=1497,localport=1101](1174380425035)
      2007-03-20 09:47:05,128 INFO [Thread-122:shutdown] org.jboss.remoting.transport.multiplex.MultiplexingManager: manager shut down (: 1174380425035): Socket[addr=/16.58.5.10,port=1497,localport=1101]
      
      2007-03-20 09:47:05,332 INFO [MultiplexServerInvoker#0v-VirtualServerSocket[Socket[addr=/16.58.5.10,port=1499,localport=1101]]] org.jboss.remoting.transport.multiplex.MultiplexServerInvoker: socket is closed: stopping thread
      
      2007-03-20 09:47:05,347 WARN [WorkerThread#51[16.58.5.10:1499]] org.jboss.remoting.ServerInvoker: MultiplexServerInvoker[virtual:/16.58.5.10:1101->/16.58.5.10:1499] can not process invocation requests since is not in started state!
      
      2007-03-20 09:47:05,378 WARN [WorkerThread#51[16.58.5.10:1499]] org.jboss.remoting.ServerInvoker: MultiplexServerInvoker[virtual:/16.58.5.10:1101->/16.58.5.10:1499] can not process invocation requests since is not in started state!
      
      2007-03-20 09:47:05,441 WARN [WorkerThread#51[16.58.5.10:1499]] org.jboss.remoting.ServerInvoker: MultiplexServerInvoker[virtual:/16.58.5.10:1101->/16.58.5.10:1499] can not process invocation requests since is not in started state!
      
      2007-03-20 09:47:05,457 WARN [WorkerThread#51[16.58.5.10:1499]] org.jboss.remoting.ServerInvoker: MultiplexServerInvoker[virtual:/16.58.5.10:1101->/16.58.5.10:1499] can not process invocation requests since is not in started state!
      
      2007-03-20 09:47:05,738 WARN [WorkerThread#51[16.58.5.10:1499]] org.jboss.remoting.ServerInvoker: MultiplexServerInvoker[virtual:/16.58.5.10:1101->/16.58.5.10:1499] can not process invocation requests since is not in started state!
      2007-03-20 09:47:05,738 WARN [WorkerThread#51[16.58.5.10:1499]] org.jboss.remoting.ServerInvoker: MultiplexServerInvoker[virtual:/16.58.5.10:1101->/16.58.5.10:1499] can not process invocation requests since is not in started state!
      2007-03-20 09:47:05,738 WARN [WorkerThread#51[16.58.5.10:1499]] org.jboss.remoting.ServerInvoker: MultiplexServerInvoker[virtual:/16.58.5.10:1101->/16.58.5.10:1499] can not process invocation requests since is not in started state!
      
      2007-03-20 09:47:05,754 WARN [WorkerThread#51[16.58.5.10:1499]] org.jboss.remoting.ServerInvoker: MultiplexServerInvoker[virtual:/16.58.5.10:1101->/16.58.5.10:1499] can not process invocation requests since is not in started state!
      
      


      What I could find out was, that the Exception happens when the Worker Thread stops before an invocation can be adressed to it. Means, a pending actions thread or a VirtualServerSocket thread runs ServerThread.stop(), afterwards a Worker Thread tries to call ServerThread.invoke() and runs into the InvalidStateException

      I don't know why this happens. Does anybody have an idea? Might this be a configuration problem or is this a bug or might it be something else?

      P.S.: I had this problem in release 2.0.0 as well as in the new release 2.2.0