[jboss-user] [Remoting] - Connection Problem with Release 2.2.0
Clarich
do-not-reply at jboss.com
Thu Mar 22 09:21:21 EDT 2007
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
View the original post : http://www.jboss.com/index.html?module=bb&op=viewtopic&p=4030627#4030627
Reply to the post : http://www.jboss.com/index.html?module=bb&op=posting&mode=reply&p=4030627
More information about the jboss-user
mailing list