Race condition in ConnectionValidator

[thammoud]

Hello,

I think we have stumbled upon a bug in the ConnectionValidator.

Scenario
pingPeriod is set to 10 seconds and pingTimeout is set to 70 seconds, client leasetime is 70 seconds. Using 2.2 SP11 on JDK 1.6 (Linux)

Ctrl-z the server for more than 20 seconds but less than 70 seconds. When the server is brought back to the foreground, the client's connection is closed even though the pingTimeout has not been exceeded.

Given that the task took more than 10 seconds to complete (Server in the BG), the java Timer will immediately call the run method again with a very small window in which the WaitOnConnectionCheckTimerTask is still running (Waiting on a lock). By the time WaitOnConnectionCheckTimerTask breaks out of its wait, it reads an isValid that is set to false by the run method causing the connection to close.

I have a fix (Not sure if it optimal) that does the following:

- Make the tt (WaitOnConnectionCheckTimerTask) a class member (Must be volatile).

- Add while(tt != null) {}
tt = new WaitOnConnectionCheckTimerTask();
to the run method.

Clear tt at the when WaitOnConnectionCheckTimerTask is done.

I can reproduce this on my machine every time. Thanks.

[ron_sigal]

Hi Tarek,

Yes, I agree with your analysis. However, I believe that the appropriate solution is just to fix the configuration parameters. There is no reason for two WaitOnConnectionCheckTimerTasks to be running at once. Rather, validatorPingPeriod should be longer than validatorPingTimeout, so that if a PING times out, there is time for the ConnectionValidator to notify any listeners and shut itself down before another PING is sent.

For example, JBossMessaging, by default, sets validatorPingPeriod to 10000 ms and validatorPingTimeout to 5000 ms.

I've created JBREM-1108 "Warn against making ConnectionValidator.validatorPingPeriod shorter than ConnectionValidator.validatorPingTimeout" to remind me to make this point clear in the Remoting Guide.

Thanks for bringing this source of failure to my attention.

-Ron

[thammoud]

Hi Ron,

I think that their might be an issue with your suggestion. perhaps you can explain this behavior. I took your advice and bumped up the pingperiod to be more that the timeout and noticed that if we restart the server from under the client and the server comes back in less time than the ping period (Very possible), then the client's JMS connection listener does not get called yet the connection is invalid.

If the pingperiod is relatively short, say 10 seconds then the listener gets called. I do not believe that this is a messaging issue. Not having the JMS connection listener be called causes the client to get into a funny state. Perhaps we can work around that, but it seems to me that you will be putting the burden of cleanups on all your clients. Not very developer friendly.

Again, my fix allows a user to specify a very short ping period and the JMS connection listener gets called immediately.

Thanks for your insight.

[ron_sigal]

"thammoud" wrote:

if we restart the server from under the client and the server comes back in less time than the ping period (Very possible), then the client's JMS connection listener does not get called yet the connection is invalid.

Hmmm. I think what you're seeing is due to the fact that the socket transport uses a connection pool. If you shut down the server gracefully, the client should detect that existing connections are stale, and the next invocation by ConnectionValidator should get a new connection to the new server and, since the invocation succeeds, there's no notification.

But the JBM client should experience the same behavior. Are you actually seeing a case where "the client's JMS connection listener does not get called yet the connection is invalid" ?

By the way, I have a couple of problems with your proposed fix.

"thammoud" wrote:

Make the tt (WaitOnConnectionCheckTimerTask) a class member (Must be volatile).

There could be multiple instances of ConnectionValidator in the same JVM, each connected to a different server.

"thammoud" wrote:

Add while(tt != null) {}

NO BUSY WAITS!!! :)

Anyway, if you set validatorPingPeriod to be longer than validatorPingTimeout, I don't think that would be necessary.

-Ron

[thammoud]

Are you actually seeing a case where "the client's JMS connection listener does not get called yet the connection is invalid" ?

Yes. Only when the server restarts in a time that is less than the ping period.

Make the tt (WaitOnConnectionCheckTimerTask) a class member (Must be volatile).

Did not mean a static. Sorry for the confusion.

while(tt != null) {} . No busy waits

I did say a non optimal solution :) This is up to you to use a latch or something else. Looking at the code, the busy wait looked harmless for our purposes.

[ron_sigal]

Hi Tarek,

"thammoud" wrote:

Are you actually seeing a case where "the client's JMS connection listener does not get called yet the connection is invalid" ?

Yes. Only when the server restarts in a time that is less than the ping period.

Hmmm. How do you know the connection is invalid? Can you post some relevant pieces of a client side log file, where Remoting is logged at DEBUG or even TRACE level?

-Ron

[thammoud]

Ok. This is pretty lengthy (2 Scenarios. One with long pingPeriod and the other one with a much shorter one). The ping period is set to 70 seconds the same as the ping timeout. Server comes back in under 70 seconds from the restart.

Scenario where the server is restarted before ping period. No listener is called.

10:27:51,480 TRACE [ServerThread] WorkerThread#0[192.168.1.20:41977] SocketServerInvoker[UNINITIALIZED].invoke() returned null
10:27:51,480 TRACE [ServerThread] WorkerThread#0[192.168.1.20:41977] oneway request, writing no reply on the wire
10:27:51,480 TRACE [ServerThread] WorkerThread#0[192.168.1.20:41977] preparing to process next invocation invocation
10:27:51,480 TRACE [ServerThread] WorkerThread#0[192.168.1.20:41977] blocking to read version from input stream
10:27:57,312 TRACE [ServerThread] WorkerThread#0[192.168.1.20:41977] read version -1 from input stream

I KILL the server here. Our message listener is not in any stack trace

10:27:57,316 TRACE [ServerThread] WorkerThread#0[192.168.1.20:41977] EOFException received. This is likely due to client finishing communication.
java.io.EOFException
at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:565)
at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:420)
at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:173)
10:27:57,317 DEBUG [ServerThread] WorkerThread#0[192.168.1.20:41977] WorkerThread#0[192.168.1.20:41977] closing socketWrapper: ServerSocketWrapper[Socket[a ddr=tarek02/192.168.1.20,port=41977,localport=46727].3770bdf7]
10:27:57,317 DEBUG [SocketWrapper] WorkerThread#0[192.168.1.20:41977] ServerSocketWrapper[Socket[addr=tarek02/192.168.1.20,port=41977,localport=46727].3770 bdf7] closing
10:27:57,317 TRACE [ServerThread] WorkerThread#0[192.168.1.20:41977] WorkerThread#0[192.168.1.20:41977] removing itself from clientpool and going to thread pool
10:27:57,317 TRACE [ServerThread] WorkerThread#0[192.168.1.20:41977] WorkerThread#0[192.168.1.20:41977] begins to wait
10:28:34,968 TRACE [MicroRemoteClientInvoker] Timer-6 SocketClientInvoker[113f25e3, bisocket://tarek02:4457](1) invoking InvocationRequest[4ada629a, JMS, OnewayInvocation[org.jboss.jms.wireformat.SessionSendRequest@477f92da]]
10:28:34,968 TRACE [MicroSocketClientInvoker] Timer-6 SocketClientInvoker[113f25e3, bisocket://tarek02:4457] obtained semaphore: 0
10:28:34,968 TRACE [MicroSocketClientInvoker] Timer-6 SocketClientInvoker[113f25e3, bisocket://tarek02:4457] creating socket
10:28:34,968 TRACE [MicroSocketClientInvoker] Timer-6 SocketClientInvoker[113f25e3, bisocket://tarek02:4457] created socket: Socket[addr=/192.168.1.20,port=4457,localport=38873]
10:28:34,968 TRACE [SocketWrapper] Timer-6 constructing org.jboss.jms.client.remoting.ClientSocketWrapper instance for Socket[addr=/192.168.1.20,port=4457,localport=38873], using timeout 0
10:28:34,968 TRACE [SocketWrapper] Timer-6 ClientSocketWrapper[Socket[addr=/192.168.1.20,port=4457,localport=38873].8824ae2] setting timeout to 0
10:28:34,968 TRACE [MicroSocketClientInvoker] Timer-6 SocketClientInvoker[113f25e3, bisocket://tarek02:4457] writing version 22 on output stream
10:28:34,968 TRACE [MicroSocketClientInvoker] Timer-6 SocketClientInvoker[113f25e3, bisocket://tarek02:4457] writing invocation to marshaller
10:28:34,968 TRACE [MicroSocketClientInvoker] Timer-6 SocketClientInvoker[113f25e3, bisocket://tarek02:4457] done writing invocation to marshaller
10:28:34,969 TRACE [MicroSocketClientInvoker] Timer-6 SocketClientInvoker[113f25e3, bisocket://tarek02:4457] sent oneway invocation, so not waiting for response, returning null
10:28:34,969 TRACE [MicroSocketClientInvoker] Timer-6 SocketClientInvoker[113f25e3, bisocket://tarek02:4457] returned ClientSocketWrapper[Socket[addr=/192.168.1.20,port=4457,localport=38873].8824ae2] to pool
10:28:34,969 TRACE [MicroSocketClientInvoker] Timer-6 SocketClientInvoker[113f25e3, bisocket://tarek02:4457] released semaphore: 1
10:28:43,238 TRACE [LeasePinger] Timer-1 LeasePinger[SocketClientInvoker[76dbab83, bisocket://tarek02:4457](5c4o1k-u8g2wa-ft043q7b-1-ft043z6u-16)] sending ping to server. Currently managing lease for following clients:
5c4o1k-u8g2wa-ft043q7b-1-ft043z6s-14

10:28:43,238 TRACE [MicroRemoteClientInvoker] Timer-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457](1) invoking InvocationRequest[ebd3f80, $PING$]
10:28:43,238 TRACE [MicroSocketClientInvoker] Timer-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] obtained semaphore: 199
10:28:43,238 TRACE [MicroSocketClientInvoker] Timer-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] creating socket
10:28:43,239 TRACE [MicroSocketClientInvoker] Timer-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] created socket: Socket[addr=/192.168.1.20,port=4457,localport=38875]
10:28:43,239 TRACE [SocketWrapper] Timer-1 constructing org.jboss.jms.client.remoting.ClientSocketWrapper instance for Socket[addr=/192.168.1.20,port=4457,localport=38875], using timeout 0
10:28:43,239 TRACE [SocketWrapper] Timer-1 ClientSocketWrapper[Socket[addr=/192.168.1.20,port=4457,localport=38875].2a93f40f] setting timeout to 0
10:28:43,239 TRACE [MicroSocketClientInvoker] Timer-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] writing version 22 on output stream
10:28:43,239 TRACE [MicroSocketClientInvoker] Timer-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] writing invocation to marshaller
10:28:43,240 TRACE [MicroSocketClientInvoker] Timer-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] done writing invocation to marshaller
10:28:43,240 TRACE [MicroSocketClientInvoker] Timer-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] reading version from input stream
10:28:43,374 TRACE [MicroSocketClientInvoker] Timer-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] read version 22 from input stream
10:28:43,375 TRACE [MicroSocketClientInvoker] Timer-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] reading response from unmarshaller
10:28:43,375 TRACE [MicroSocketClientInvoker] Timer-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] returned ClientSocketWrapper[Socket[addr=/192.168.1.20,port=4457,localport=38875].2a93f40f] to pool
10:28:43,375 TRACE [MicroSocketClientInvoker] Timer-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] released semaphore: 200
10:28:43,375 TRACE [MicroSocketClientInvoker] Timer-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] received response InvocationResponse[514e7b87, InvocationResponse[779005c4, true]]
10:28:43,375 TRACE [MicroRemoteClientInvoker] Timer-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] received InvocationResponse so going to return response's return value of InvocationResponse[779005c4, true]
10:28:43,375 TRACE [LeasePinger] Timer-1 LeasePinger[SocketClientInvoker[76dbab83, bisocket://tarek02:4457](5c4o1k-u8g2wa-ft043q7b-1-ft043z6u-16)] successfully pinged the server
10:28:43,418 TRACE [ConnectionValidator] Timer-3 ConnectionValidator[SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457], pingPeriod=70000 ms] sending PING tied to lease
10:28:43,418 TRACE [ConnectionValidator] Timer-3 pinging, sending InvocationRequest[106ac42f, self, $PING$] over SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457]
10:28:43,418 TRACE [MicroRemoteClientInvoker] Timer-3 SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457](1) invoking InvocationRequest[106ac42f, self, $PING$]
10:28:43,418 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457] obtained semaphore: 49
10:28:43,418 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457] creating socket
10:28:43,420 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457] created socket: Socket[addr=/192.168.1.20,port=4457,localport=38876]
10:28:43,420 TRACE [SocketWrapper] Timer-3 constructing org.jboss.jms.client.remoting.ClientSocketWrapper instance for Socket[addr=/192.168.1.20,port=4457,localport=38876], using timeout 0
10:28:43,420 TRACE [SocketWrapper] Timer-3 ClientSocketWrapper[Socket[addr=/192.168.1.20,port=4457,localport=38876].5175f214] setting timeout to 0
10:28:43,420 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457] writing version 22 on output stream
10:28:43,420 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457] writing invocation to marshaller
10:28:43,420 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457] done writing invocation to marshaller
10:28:43,421 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457] reading version from input stream
10:28:43,425 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457] read version 22 from input stream
10:28:43,425 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457] reading response from unmarshaller
10:28:43,425 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457] returned ClientSocketWrapper[Socket[addr=/192.168.1.20,port=4457,localport=38876].5175f214] to pool
10:28:43,425 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457] released semaphore: 50
10:28:43,425 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457] received response InvocationResponse[3a33517f, true]
10:28:43,425 TRACE [MicroRemoteClientInvoker] Timer-3 SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457] received InvocationResponse so going to return response's return value of true
10:28:43,425 TRACE [ConnectionValidator] Timer-3 Return from server ping is :true
Happy ping even though ever was restarted. Strange
10:28:43,425 TRACE [ConnectionValidator] Timer-3 ConnectionValidator got successful ping using SocketClientInvoker[51b2bcc2, bisocket://tarek02:4457]

==============================

10:29:06,725 TRACE [MicroRemoteClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457](1) invoking InvocationRequest[3a5f299d, JMS, org.jboss.jms.wireformat.ConnectionCreateSessionDelegateRequest@3da5205b]
10:29:06,725 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] obtained semaphore: 199
10:29:06,725 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] reusing pooled connection: ClientSocketWrapper[Socket[addr=/192.168.1.20,port=4457,localport=38875].2a93f40f]
10:29:06,725 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] writing version 22 on output stream
10:29:06,725 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] writing invocation to marshaller
10:29:06,725 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] done writing invocation to marshaller
10:29:06,725 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] reading version from input stream
10:29:06,729 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] read version 22 from input stream
10:29:06,729 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] reading response from unmarshaller
10:29:06,732 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] returned ClientSocketWrapper[Socket[addr=/192.168.1.20,port=4457,localport=38875].2a93f40f] to pool
10:29:06,732 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] released semaphore: 200
10:29:06,732 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] received response InvocationResponse[6d5454d, java.lang.IllegalStateException: Cannot find object in dispatcher with id k22-baz340tf-1-fbh040tf-5h3vog-k1o4c5]
10:29:06,732 TRACE [MicroRemoteClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] received a server-side exception as response to the invocation:

The error after subsequent JMS calls. Never recovers

java.lang.IllegalStateException: Cannot find object in dispatcher with id k22-baz340tf-1-fbh040tf-5h3vog-k1o4c5
10:29:06,733 ERROR [JMSLeaseRenewStrategy] SwingWorker-pool-1-thread-1 Failed to invoke
org.jboss.jms.exception.MessagingJMSException: Failed to invoke
at org.jboss.jms.client.delegate.DelegateSupport.handleThrowable(DelegateSupport.java:271)
at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:205)
at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:160)
at org.jboss.jms.client.delegate.ClientConnectionDelegate.org$jboss$jms$client$delegate$ClientConnectionDelegate$createSessionDelegate$aop(ClientConnectionDelegate.java:186)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$createSessionDelegate_6052335267724906805.invokeNext(ClientConnectionDelegate$createSessionDelegate_6052335267724906805.java)
at org.jboss.jms.client.container.StateCreationAspect.handleCreateSessionDelegate(StateCreationAspect.java:122)
at org.jboss.aop.advice.org.jboss.jms.client.container.StateCreationAspect2.invoke(StateCreationAspect2.java)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$createSessionDelegate_6052335267724906805.invokeNext(ClientConnectionDelegate$createSessionDelegate_6052335267724906805.java)
at org.jboss.jms.client.container.ConnectionAspect.handleCreateSessionDelegate(ConnectionAspect.java:164)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.jboss.aop.advice.PerInstanceAdvice.invoke(PerInstanceAdvice.java:121)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$createSessionDelegate_6052335267724906805.invokeNext(ClientConnectionDelegate$createSessionDelegate_6052335267724906805.java)
at org.jboss.jms.client.container.FailoverValveInterceptor.invoke(FailoverValveInterceptor.java:92)
at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$createSessionDelegate_6052335267724906805.invokeNext(ClientConnectionDelegate$createSessionDelegate_6052335267724906805.java)
at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$createSessionDelegate_6052335267724906805.invokeNext(ClientConnectionDelegate$createSessionDelegate_6052335267724906805.java)
at org.jboss.jms.client.delegate.ClientConnectionDelegate.createSessionDelegate(ClientConnectionDelegate.java)
at org.jboss.jms.client.JBossConnection.createSessionInternal(JBossConnection.java:269)
at org.jboss.jms.client.JBossConnection.createSession(JBossConnection.java:91)
at com.enfusion.lease.JMSLeaseRenewStrategy.(JMSLeaseRenewStrategy.java:26)
at com.enfusion.feed.client.transport.jms.JMSFeedSessionTransport.(JMSFeedSessionTransport.java:96)
at com.enfusion.feed.client.FeedSession.createJMSFeedSession(FeedSession.java:35)
at com.enfusion.fas.feeds.report.RemoteDocument.(RemoteDocument.java:60)
at com.enfusion.mazzika.report.service.ReportComponent$DynamicReportWorker.doInBackground(ReportComponent.java:560)
at javax.swing.SwingWorker$1.call(SwingWorker.java:278)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at javax.swing.SwingWorker.run(SwingWorker.java:317)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:619)
Caused by: java.lang.IllegalStateException: Cannot find object in dispatcher with id k22-baz340tf-1-fbh040tf-5h3vog-k1o4c5
at org.jboss.jms.wireformat.ConnectionCreateSessionDelegateRequest.serverInvoke(ConnectionCreateSessionDelegateRequest.java:84)
at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:143)
at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:866)
at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:608)
at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:420)
at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:173)
at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:174)
at org.jboss.remoting.Client.invoke(Client.java:1645)
at org.jboss.remoting.Client.invoke(Client.java:559)
at org.jboss.remoting.Client.invoke(Client.java:547)
at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:189)
... 34 more
10:29:06,735 TRACE [MicroRemoteClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457](1) invoking InvocationRequest[eebafe, JMS, org.jboss.jms.wireformat.ConnectionCreateSessionDelegateRequest@39367a2c]
10:29:06,735 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] obtained semaphore: 199
10:29:06,735 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] reusing pooled connection: ClientSocketWrapper[Socket[addr=/192.168.1.20,port=4457,localport=38875].2a93f40f]
10:29:06,735 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] writing version 22 on output stream
10:29:06,735 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] writing invocation to marshaller
10:29:06,735 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] done writing invocation to marshaller
10:29:06,735 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] reading version from input stream
10:29:06,735 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] read version 22 from input stream
10:29:06,736 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] reading response from unmarshaller
10:29:06,736 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] returned ClientSocketWrapper[Socket[addr=/192.168.1.20,port=4457,localport=38875].2a93f40f] to pool
10:29:06,736 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] released semaphore: 200
10:29:06,736 TRACE [MicroSocketClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] received response InvocationResponse[19f21412, java.lang.IllegalStateException: Cannot find object in dispatcher with id k22-baz340tf-1-fbh040tf-5h3vog-k1o4c5]
10:29:06,736 TRACE [MicroRemoteClientInvoker] SwingWorker-pool-1-thread-1 SocketClientInvoker[76dbab83, bisocket://tarek02:4457] received a server-side exception as response to the invocation: java.lang.IllegalStateException: Cannot find object in dispatcher with id k22-baz340tf-1-fbh040tf-5h3vog-k1o4c5
10:29:06,736 ERROR [JMSFeedSessionTransport] SwingWorker-pool-1-thread-1 Failed to invoke
org.jboss.jms.exception.MessagingJMSException: Failed to invoke
at org.jboss.jms.client.delegate.DelegateSupport.handleThrowable(DelegateSupport.java:271)
at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:205)
at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:160)
at org.jboss.jms.client.delegate.ClientConnectionDelegate.org$jboss$jms$client$delegate$ClientConnectionDelegate$createSessionDelegate$aop(ClientConnectionDelegate.java:186)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$createSessionDelegate_6052335267724906805.invokeNext(ClientConnectionDelegate$createSessionDelegate_6052335267724906805.java)
at org.jboss.jms.client.container.StateCreationAspect.handleCreateSessionDelegate(StateCreationAspect.java:122)
at org.jboss.aop.advice.org.jboss.jms.client.container.StateCreationAspect2.invoke(StateCreationAspect2.java)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$createSessionDelegate_6052335267724906805.invokeNext(ClientConnectionDelegate$createSessionDelegate_6052335267724906805.java)
at org.jboss.jms.client.container.ConnectionAspect.handleCreateSessionDelegate(ConnectionAspect.java:164)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.jboss.aop.advice.PerInstanceAdvice.invoke(PerInstanceAdvice.java:121)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$createSessionDelegate_6052335267724906805.invokeNext(ClientConnectionDelegate$createSessionDelegate_6052335267724906805.java)
at org.jboss.jms.client.container.FailoverValveInterceptor.invoke(FailoverValveInterceptor.java:92)
at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$createSessionDelegate_6052335267724906805.invokeNext(ClientConnectionDelegate$createSessionDelegate_6052335267724906805.java)
at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$createSessionDelegate_6052335267724906805.invokeNext(ClientConnectionDelegate$createSessionDelegate_6052335267724906805.java)
at org.jboss.jms.client.delegate.ClientConnectionDelegate.createSessionDelegate(ClientConnectionDelegate.java)
at org.jboss.jms.client.JBossConnection.createSessionInternal(JBossConnection.java:269)
at org.jboss.jms.client.JBossConnection.createSession(JBossConnection.java:91)
at com.enfusion.feed.client.transport.jms.JMSFeedSessionTransport.(JMSFeedSessionTransport.java:100)
at com.enfusion.feed.client.FeedSession.createJMSFeedSession(FeedSession.java:35)
at com.enfusion.fas.feeds.report.RemoteDocument.(RemoteDocument.java:60)
at com.enfusion.mazzika.report.service.ReportComponent$DynamicReportWorker.doInBackground(ReportComponent.java:560)
at javax.swing.SwingWorker$1.call(SwingWorker.java:278)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at javax.swing.SwingWorker.run(SwingWorker.java:317)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:619)
Caused by: java.lang.IllegalStateException: Cannot find object in dispatcher with id k22-baz340tf-1-fbh040tf-5h3vog-k1o4c5
at org.jboss.jms.wireformat.ConnectionCreateSessionDelegateRequest.serverInvoke(ConnectionCreateSessionDelegateRequest.java:84)
at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:143)
at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:866)
at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:608)
at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:420)
at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:173)
at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:174)
at org.jboss.remoting.Client.invoke(Client.java:1645)
at org.jboss.remoting.Client.invoke(Client.java:559)
at org.jboss.remoting.Client.invoke(Client.java:547)
at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:189)
... 33 more
10:29:06,782 ERROR [ReportComponent$DynamicReportWorker] AWT-EventQueue-0 org.jboss.jms.exception.MessagingJMSException: Failed to invoke
java.lang.RuntimeException: org.jboss.jms.exception.MessagingJMSException: Failed to invoke
at com.enfusion.feed.client.transport.jms.JMSFeedSessionTransport.(JMSFeedSessionTransport.java:152)
at com.enfusion.feed.client.FeedSession.createJMSFeedSession(FeedSession.java:35)
at com.enfusion.fas.feeds.report.RemoteDocument.(RemoteDocument.java:60)
at com.enfusion.mazzika.report.service.ReportComponent$DynamicReportWorker.doInBackground(ReportComponent.java:560)
at javax.swing.SwingWorker$1.call(SwingWorker.java:278)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at javax.swing.SwingWorker.run(SwingWorker.java:317)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:619)
Caused by: org.jboss.jms.exception.MessagingJMSException: Failed to invoke
at org.jboss.jms.client.delegate.DelegateSupport.handleThrowable(DelegateSupport.java:271)
at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:205)
at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:160)
at org.jboss.jms.client.delegate.ClientConnectionDelegate.org$jboss$jms$client$delegate$ClientConnectionDelegate$createSessionDelegate$aop(ClientConnectionDelegate.java:186)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$createSessionDelegate_6052335267724906805.invokeNext(ClientConnectionDelegate$createSessionDelegate_6052335267724906805.java)
at org.jboss.jms.client.container.StateCreationAspect.handleCreateSessionDelegate(StateCreationAspect.java:122)
at org.jboss.aop.advice.org.jboss.jms.client.container.StateCreationAspect2.invoke(StateCreationAspect2.java)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$createSessionDelegate_6052335267724906805.invokeNext(ClientConnectionDelegate$createSessionDelegate_6052335267724906805.java)
at org.jboss.jms.client.container.ConnectionAspect.handleCreateSessionDelegate(ConnectionAspect.java:164)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.jboss.aop.advice.PerInstanceAdvice.invoke(PerInstanceAdvice.java:121)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$createSessionDelegate_6052335267724906805.invokeNext(ClientConnectionDelegate$createSessionDelegate_6052335267724906805.java)
at org.jboss.jms.client.container.FailoverValveInterceptor.invoke(FailoverValveInterceptor.java:92)
at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$createSessionDelegate_6052335267724906805.invokeNext(ClientConnectionDelegate$createSessionDelegate_6052335267724906805.java)
at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$createSessionDelegate_6052335267724906805.invokeNext(ClientConnectionDelegate$createSessionDelegate_6052335267724906805.java)
at org.jboss.jms.client.delegate.ClientConnectionDelegate.createSessionDelegate(ClientConnectionDelegate.java)
at org.jboss.jms.client.JBossConnection.createSessionInternal(JBossConnection.java:269)
at org.jboss.jms.client.JBossConnection.createSession(JBossConnection.java:91)
at com.enfusion.feed.client.transport.jms.JMSFeedSessionTransport.(JMSFeedSessionTransport.java:100)
... 10 more
Caused by: java.lang.IllegalStateException: Cannot find object in dispatcher with id k22-baz340tf-1-fbh040tf-5h3vog-k1o4c5
at org.jboss.jms.wireformat.ConnectionCreateSessionDelegateRequest.serverInvoke(ConnectionCreateSessionDelegateRequest.java:84)
at org.jboss.jms.server.remoting.JMSServerInvocationHandler.invoke(JMSServerInvocationHandler.java:143)
at org.jboss.remoting.ServerInvoker.invoke(ServerInvoker.java:866)
at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:608)
at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:420)
at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:173)
at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:174)
at org.jboss.remoting.Client.invoke(Client.java:1645)
at org.jboss.remoting.Client.invoke(Client.java:559)
at org.jboss.remoting.Client.invoke(Client.java:547)
at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:189)
... 33 more

Much Smaller ping period 10 seconds. The results is what I expect.

10:41:32,976 TRACE [ConnectionValidator] Timer-3 ConnectionValidator[SocketClientInvoker[1197886c, bisocket://tarek02:4457], pingPeriod=10000 ms] sending PING tied to lease
10:41:32,977 TRACE [ConnectionValidator] Timer-3 pinging, sending InvocationRequest[712d0ef5, self, $PING$] over SocketClientInvoker[1197886c, bisocket://tarek02:4457]
10:41:32,977 TRACE [MicroRemoteClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457](1) invoking InvocationRequest[712d0ef5, self, $PING$]
10:41:32,977 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] obtained semaphore: 49
10:41:32,977 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] creating socket
10:41:32,977 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] created socket: Socket[addr=/192.168.1.20,port=4457,localport=34532]
10:41:32,977 TRACE [SocketWrapper] Timer-3 constructing org.jboss.jms.client.remoting.ClientSocketWrapper instance for Socket[addr=/192.168.1.20,port=4457,localport=34532], using timeout 0
10:41:32,977 TRACE [SocketWrapper] Timer-3 ClientSocketWrapper[Socket[addr=/192.168.1.20,port=4457,localport=34532].207fa3f6] setting timeout to 0
10:41:32,978 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] writing version 22 on output stream
10:41:32,978 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] writing invocation to marshaller
10:41:32,978 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] done writing invocation to marshaller
10:41:32,978 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] reading version from input stream
10:41:32,978 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] read version 22 from input stream
10:41:32,978 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] reading response from unmarshaller
10:41:32,978 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] returned ClientSocketWrapper[Socket[addr=/192.168.1.20,port=4457,localport=34532].207fa3f6] to pool
10:41:32,978 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] released semaphore: 50
10:41:32,978 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] received response InvocationResponse[8763c3c, true]
10:41:32,979 TRACE [MicroRemoteClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] received InvocationResponse so going to return response's return value of true
10:41:32,979 TRACE [ConnectionValidator] Timer-3 Return from server ping is :true
10:41:32,979 TRACE [ConnectionValidator] Timer-3 ConnectionValidator got successful ping using SocketClientInvoker[1197886c, bisocket://tarek02:4457]

10:41:35,107 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] read version 22 from input stream
10:41:35,108 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] blocking to read invocation from unmarshaller
10:41:35,108 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] read InvocationRequest[a6c8b7b, CALLBACK, OnewayInvocation[InternalInvocation[5c393d95]]] from unmarshaller
10:41:35,108 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] about to call SocketServerInvoker[UNINITIALIZED].invoke()
10:41:35,108 TRACE [ServerInvoker] WorkerThread#0[192.168.1.20:57607] SocketServerInvoker[UNINITIALIZED] received OnewayInvocation[InternalInvocation[5c393d95]]
10:41:35,108 TRACE [ServerInvoker] WorkerThread#0[192.168.1.20:57607] reusing oneway thread pool
10:41:35,108 TRACE [ServerInvoker] WorkerThread#0[192.168.1.20:57607] SocketServerInvoker[UNINITIALIZED] placing InvocationRequest[a6c8b7b, CALLBACK, InternalInvocation[5c393d95]] in onewayThreadPool
10:41:35,108 TRACE [ServerInvoker] WorkerThread#0[192.168.1.20:57607] SocketServerInvoker[UNINITIALIZED] received InternalInvocation[5c393d95]
10:41:35,108 TRACE [ServerInvoker] WorkerThread#0[192.168.1.20:57607] handling InternalInvocation where method name = handleCallback
10:41:35,108 TRACE [ServerInvoker] WorkerThread#0[192.168.1.20:57607] ServerInvoker (SocketServerInvoker[UNINITIALIZED]) is being asked to deliver callback on client callback handler with session id of null.
10:41:35,108 TRACE [ServerInvoker] WorkerThread#0[192.168.1.20:57607] SocketServerInvoker[UNINITIALIZED] successfully dispatched invocation, returning null from subsystem 'CALLBACK' to client null
10:41:35,108 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] SocketServerInvoker[UNINITIALIZED].invoke() returned null
10:41:35,108 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] oneway request, writing no reply on the wire
10:41:35,108 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] preparing to process next invocation invocation
10:41:35,108 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] blocking to read version from input stream
10:41:35,108 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] read version 22 from input stream
10:41:35,108 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] blocking to read invocation from unmarshaller
10:41:35,108 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] read InvocationRequest[31fa3080, CALLBACK, OnewayInvocation[InternalInvocation[20863d22]]] from unmarshaller
10:41:35,108 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] about to call SocketServerInvoker[UNINITIALIZED].invoke()
10:41:35,108 TRACE [ServerInvoker] WorkerThread#0[192.168.1.20:57607] SocketServerInvoker[UNINITIALIZED] received OnewayInvocation[InternalInvocation[20863d22]]
10:41:35,108 TRACE [ServerInvoker] WorkerThread#0[192.168.1.20:57607] reusing oneway thread pool
10:41:35,108 TRACE [ServerInvoker] WorkerThread#0[192.168.1.20:57607] SocketServerInvoker[UNINITIALIZED] placing InvocationRequest[31fa3080, CALLBACK, InternalInvocation[20863d22]] in onewayThreadPool
10:41:35,108 TRACE [ServerInvoker] WorkerThread#0[192.168.1.20:57607] SocketServerInvoker[UNINITIALIZED] received InternalInvocation[20863d22]
10:41:35,108 TRACE [ServerInvoker] WorkerThread#0[192.168.1.20:57607] handling InternalInvocation where method name = handleCallback
10:41:35,108 TRACE [ServerInvoker] WorkerThread#0[192.168.1.20:57607] ServerInvoker (SocketServerInvoker[UNINITIALIZED]) is being asked to deliver callback on client callback handler with session id of null.
10:41:35,108 TRACE [ServerInvoker] WorkerThread#0[192.168.1.20:57607] SocketServerInvoker[UNINITIALIZED] successfully dispatched invocation, returning null from subsystem 'CALLBACK' to client null
10:41:35,108 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] SocketServerInvoker[UNINITIALIZED].invoke() returned null
10:41:35,108 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] oneway request, writing no reply on the wire
10:41:35,108 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] preparing to process next invocation invocation
10:41:35,110 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] blocking to read version from input stream
10:41:40,471 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] read version -1 from input stream
10:41:40,474 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] EOFException received. This is likely due to client finishing communication.
java.io.EOFException
at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:565)
at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:420)
at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:173)
10:41:40,475 DEBUG [ServerThread] WorkerThread#0[192.168.1.20:57607] WorkerThread#0[192.168.1.20:57607] closing socketWrapper: ServerSocketWrapper[Socket[addr=tarek02/192.168.1.20,port=57607,localport=44371].161abc23]
10:41:40,475 DEBUG [SocketWrapper] WorkerThread#0[192.168.1.20:57607] ServerSocketWrapper[Socket[addr=tarek02/192.168.1.20,port=57607,localport=44371].161abc23] closing
10:41:40,475 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] WorkerThread#0[192.168.1.20:57607] removing itself from clientpool and going to threadpool
10:41:40,476 TRACE [ServerThread] WorkerThread#0[192.168.1.20:57607] WorkerThread#0[192.168.1.20:57607] begins to wait
10:41:42,976 TRACE [ConnectionValidator] Timer-3 ConnectionValidator[SocketClientInvoker[1197886c, bisocket://tarek02:4457], pingPeriod=10000 ms] sending PING tied to lease
10:41:42,976 TRACE [ConnectionValidator] Timer-3 pinging, sending InvocationRequest[6045e90f, self, $PING$] over SocketClientInvoker[1197886c, bisocket://tarek02:4457]
10:41:42,976 TRACE [MicroRemoteClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457](1) invoking InvocationRequest[6045e90f, self, $PING$]
10:41:42,976 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] obtained semaphore: 49
10:41:42,976 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] reusing pooled connection: ClientSocketWrapper[Socket[addr=/192.168.1.20,port=4457,localport=34532].207fa3f6]
10:41:42,976 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] writing version 22 on output stream
10:41:42,976 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] writing invocation to marshaller
10:41:42,976 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] done writing invocation to marshaller
10:41:42,976 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] reading version from input stream
10:41:42,976 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] read version -1 from input stream
10:41:42,977 DEBUG [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] got SocketException java.net.SocketException: end of file
10:41:42,977 TRACE [MicroSocketClientInvoker] Timer-3 SocketClientInvoker[1197886c, bisocket://tarek02:4457] released semaphore: 50
10:41:42,977 DEBUG [SocketWrapper] Timer-3 ClientSocketWrapper[Socket[addr=/192.168.1.20,port=4457,localport=34532].207fa3f6] closing
10:41:42,977 ERROR [SocketClientInvoker] Timer-3 Got marshalling exception, exiting
java.net.SocketException: end of file
at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:624)
at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.transport(BisocketClientInvoker.java:422)
at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:133)
at org.jboss.remoting.ConnectionValidator.doCheckConnectionWithLease(ConnectionValidator.java:551)
at org.jboss.remoting.ConnectionValidator.run(ConnectionValidator.java:331)
at java.util.TimerThread.mainLoop(Timer.java:512)
at java.util.TimerThread.run(Timer.java:462)
10:41:42,979 DEBUG [ConnectionValidator] Timer-3 ConnectionValidator failed to ping via SocketClientInvoker[1197886c, bisocket://tarek02:4457]
java.rmi.MarshalException: Failed to communicate. Problem during marshalling/unmarshalling; nested exception is:
java.net.SocketException: end of file
at org.jboss.remoting.transport.socket.SocketClientInvoker.handleException(SocketClientInvoker.java:127)
at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:699)
at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.transport(BisocketClientInvoker.java:422)
at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:133)
at org.jboss.remoting.ConnectionValidator.doCheckConnectionWithLease(ConnectionValidator.java:551)
at org.jboss.remoting.ConnectionValidator.run(ConnectionValidator.java:331)
at java.util.TimerThread.mainLoop(Timer.java:512)
at java.util.TimerThread.run(Timer.java:462)
Caused by: java.net.SocketException: end of file
at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:624)
... 6 more
10:41:42,979 DEBUG [ConnectionValidator] Timer-4 ConnectionValidator[SocketClientInvoker[1197886c, bisocket://tarek02:4457], pingPeriod=10000 ms]'s connections is invalid
10:41:42,980 ERROR [JBOSSMessagingDelegate] Thread-15 Failure on underlying remoting connection
javax.jms.JMSException: Failure on underlying remoting connection
at org.jboss.jms.client.remoting.ConsolidatedRemotingConnectionListener.handleConnectionException(ConsolidatedRemotingConnectionListener.java:102)
at org.jboss.remoting.ConnectionValidator$1.run(ConnectionValidator.java:649)
10:41:42,981 TRACE [InvokerRegistry] Timer-4 destroying client invoker InvokerLocator [bisocket://tarek02:4457/?JBM_clientMaxPoolSize=200&clientLeasePeriod=70000&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.wireformat.JMSWireFormat&numberOfCallRetries=1&numberOfRetries=10&pingFrequency=214748364&pingWindowFactor=10&socket.check_connection=false&stopLeaseOnFailure=true&timeout=0&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat&validatorPingPeriod=10000&validatorPingTimeout=70000], config {validatorPingPeriod=10000, numberOfRetries=10, socket.check_connection=false, stopLeaseOnFailure=true, marshaller=org.jboss.jms.wireformat.JMSWireFormat, unmarshaller=org.jboss.jms.wireformat.JMSWireFormat, clientLeasePeriod=70000, clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper, numberOfCallRetries=1, dataType=jms, pingWindowFactor=10, connection_checker=true, NumberOfCallRetries=1, JBM_clientMaxPoolSize=200, pingFrequency=214748364, timeout=70000, validatorPingTimeout=70000}
10:41:42,982 DEBUG [InvokerRegistry] Timer-4 removed SocketClientInvoker[1197886c, bisocket://tarek02:4457] from registry
10:41:42,982 TRACE [InvokerRegistry] Timer-4 disconnecting SocketClientInvoker[1197886c, bisocket://tarek02:4457]
10:41:42,982 DEBUG [MicroSocketClientInvoker] Timer-4 SocketClientInvoker[1197886c, bisocket://tarek02:4457] disconnecting ...
10:41:42,982 TRACE [MicroRemoteClientInvoker] Timer-4 SocketClientInvoker[1197886c, bisocket://tarek02:4457] disconnecting ...
10:41:42,982 TRACE [MicroRemoteClientInvoker] Timer-4 SocketClientInvoker[1197886c, bisocket://tarek02:4457] disconnected
10:41:42,982 DEBUG [ConnectionValidator] Timer-4 ConnectionValidator[SocketClientInvoker[1197886c, bisocket://tarek02:4457], pingPeriod=10000 ms] stopped, returning true
10:41:42,982 DEBUG [ConnectionValidator] Timer-4 org.jboss.remoting.ConnectionValidator$WaitOnConnectionCheckTimerTask@37190ae9 detected connection failure: stopping LeasePinger
10:41:42,982 DEBUG [LeasePinger] Timer-4 LeasePinger[SocketClientInvoker[38c5564e, bisocket://tarek02:4457](5c4o1k-zhbdmy-ft04lhns-1-ft04lr9o-16)] setting disconnect timeout to: -1
10:41:42,983 TRACE [LeasePinger] Timer-4 LeasePinger[SocketClientInvoker[38c5564e, bisocket://tarek02:4457](5c4o1k-zhbdmy-ft04lhns-1-ft04lr9o-16)] stopping lease timer
10:41:42,983 TRACE [MicroRemoteClientInvoker] Timer-4 SocketClientInvoker[38c5564e, bisocket://tarek02:4457](1) invoking InvocationRequest[411167f3, $DISCONNECT$]
10:41:42,983 TRACE [MicroSocketClientInvoker] Timer-4 SocketClientInvoker[38c5564e, bisocket://tarek02:4457] obtained semaphore: 199
10:41:42,983 TRACE [MicroSocketClientInvoker] Timer-4 SocketClientInvoker[38c5564e, bisocket://tarek02:4457] creating socket
10:41:42,986 TRACE [MicroSocketClientInvoker] Timer-4 SocketClientInvoker[38c5564e, bisocket://tarek02:4457] released semaphore: 200
10:41:42,986 DEBUG [MicroRemoteClientInvoker] Timer-4 error shutting down lease pinger
10:41:42,986 DEBUG [ConnectionValidator] Timer-4 ConnectionValidator[SocketClientInvoker[1197886c, bisocket://tarek02:4457], pingPeriod=10000 ms] shut down lease pinger
10:41:42,986 TRACE [MicroRemoteClientInvoker] Thread-15 SocketClientInvoker[38c5564e, bisocket://tarek02:4457](1) invoking InvocationRequest[1140d57b, JMS, org.jboss.jms.wireformat.ConnectionStopRequest@377f8716]
10:41:42,987 TRACE [MicroSocketClientInvoker] Thread-15 SocketClientInvoker[38c5564e, bisocket://tarek02:4457] obtained semaphore: 199
10:41:42,987 TRACE [MicroSocketClientInvoker] Thread-15 SocketClientInvoker[38c5564e, bisocket://tarek02:4457] creating socket
10:41:42,987 TRACE [MicroSocketClientInvoker] Thread-15 SocketClientInvoker[38c5564e, bisocket://tarek02:4457] released semaphore: 200
10:41:42,987 ERROR [JBOSSMessagingDelegate] Thread-15
org.jboss.jms.exception.MessagingNetworkFailureException
at org.jboss.jms.client.delegate.DelegateSupport.handleThrowable(DelegateSupport.java:240)
at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:205)
at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:160)
at org.jboss.jms.client.delegate.ClientConnectionDelegate.org$jboss$jms$client$delegate$ClientConnectionDelegate$stop$aop(ClientConnectionDelegate.java:258)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$stop_N2856118408655404442.invokeNext(ClientConnectionDelegate$stop_N2856118408655404442.java)
at org.jboss.jms.client.container.ConnectionAspect.handleStop(ConnectionAspect.java:157)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.jboss.aop.advice.PerInstanceAdvice.invoke(PerInstanceAdvice.java:121)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$stop_N2856118408655404442.invokeNext(ClientConnectionDelegate$stop_N2856118408655404442.java)
at org.jboss.jms.client.container.FailoverValveInterceptor.invoke(FailoverValveInterceptor.java:92)
at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$stop_N2856118408655404442.invokeNext(ClientConnectionDelegate$stop_N2856118408655404442.java)
at org.jboss.jms.client.container.ClosedInterceptor.invoke(ClosedInterceptor.java:170)
at org.jboss.aop.advice.PerInstanceInterceptor.invoke(PerInstanceInterceptor.java:105)
at org.jboss.jms.client.delegate.ClientConnectionDelegate$stop_N2856118408655404442.invokeNext(ClientConnectionDelegate$stop_N2856118408655404442.java)
at org.jboss.jms.client.delegate.ClientConnectionDelegate.stop(ClientConnectionDelegate.java)
at org.jboss.jms.client.JBossConnection.stop(JBossConnection.java:126)
Our listener being called
at com.enfusion.feed.client.transport.jms.JBOSSMessagingDelegate.close(JBOSSMessagingDelegate.java:56)
at com.enfusion.feed.client.transport.jms.JBOSSMessagingDelegate$ExceptionListenerImpl.onException(JBOSSMessagingDelegate.java:117)
at org.jboss.jms.client.remoting.ConsolidatedRemotingConnectionListener.handleConnectionException(ConsolidatedRemotingConnectionListener.java:113)
at org.jboss.remoting.ConnectionValidator$1.run(ConnectionValidator.java:649)
Caused by: org.jboss.remoting.CannotConnectException: Can not get connection to server. Problem establishing socket connection for InvokerLocator [bisocket://tarek02:4457/?JBM_clientMaxPoolSize=200&clientLeasePeriod=70000&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&dataType=jms&marshaller=org.jboss.jms.wireformat.JMSWireFormat&numberOfCallRetries=1&numberOfRetries=10&pingFrequency=214748364&pingWindowFactor=10&socket.check_connection=fal se&stopLeaseOnFailure=true&timeout=0&unmarshaller=org.jboss.jms.wireformat.JMSWireFormat&validatorPingPeriod=10000&validatorPingTimeout=70000]
at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:579)
at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.transport(BisocketClientInvoker.java:422)
at org.jboss.remoting.MicroRemoteClientInvoker.invoke(MicroRemoteClientInvoker.java:133)
at org.jboss.remoting.Client.invoke(Client.java:1645)
at org.jboss.remoting.Client.invoke(Client.java:559)
at org.jboss.remoting.Client.invoke(Client.java:547)
at org.jboss.jms.client.delegate.DelegateSupport.doInvoke(DelegateSupport.java:189)
... 22 more
Caused by: java.net.ConnectException: Connection refused
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195)
at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
at java.net.Socket.connect(Socket.java:519)
at org.jboss.remoting.transport.socket.SocketClientInvoker.createSocket(SocketClientInvoker.java:192)
at org.jboss.remoting.transport.bisocket.BisocketClientInvoker.createSocket(BisocketClientInvoker.java:429)
at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.getConnection(MicroSocketClientInvoker.java:827)
at org.jboss.remoting.transport.socket.MicroSocketClientInvoker.transport(MicroSocketClientInvoker.java:569)
... 28 more

[ron_sigal]

Hi Tarek,

"thammoud" wrote:

Make the tt (WaitOnConnectionCheckTimerTask) a class member (Must be volatile).

Did not mean a static. Sorry for the confusion.

My mistake. Maybe I was thinking in C++? :)

I think I can explain your first scenario, with the exception that I'm not sure I understand the timing of the stopping and restarting of the server. I'm assuming that the sequence is:

1. ConnectionValidator pings successfully
2. Server goes down
3. Server comes back
4. ConnectionValidator pings successfully

and then JBossMessaging fails.

The ConnectionValidator was intended to detect that a connection exists to a server at a certain InvokerLocator. It doesn't detect that the server that it pinged last time is the same as the one it pings this time. So it's getting a "happy ping" at step 4. But JBossMessaging isn't happy because the new server doesn't have the same state as the old server.

I think the solution is to turn the happy ping into an unhappy ping. For example, the server could return its unique identity and the ConnectionValidator could compare to the previous result.

If, in fact, I'm interpreting your scenario correctly, then I'll create a JIRA issue for it.

-Ron

[thammoud]

A JIRA should be opened.The JMS connection is no longer valid in between restarts and the connection listener must be called. Your solution that involves a server id makes sense.

[ron_sigal]

JBREM-1144 "Extend connection identity to server side".