Connection Problem with Release 2.2.0
clarich Mar 22, 2007 9:21 AMHi 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