9 Replies Latest reply on Jul 10, 2009 5:07 PM by Ron Sigal

    Race condition in ConnectionValidator

    Tarek Hammoud Novice

      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.

        • 1. Re: Race condition in ConnectionValidator
          Ron Sigal Master

          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

          • 2. Re: Race condition in ConnectionValidator
            Tarek Hammoud Novice

            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.

            • 3. Re: Race condition in ConnectionValidator
              Ron Sigal Master

               

              "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

              • 4. Re: Race condition in ConnectionValidator
                Tarek Hammoud Novice

                 

                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.


                • 5. Re: Race condition in ConnectionValidator
                  Ron Sigal Master

                  Hi Tarek,

                  "thammoud" wrote:

                  "ron.sigal@jboss.com" 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

                  • 6. Re: Race condition in ConnectionValidator
                    Tarek Hammoud Novice

                    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


                    • 7. Re: Race condition in ConnectionValidator
                      Ron Sigal Master

                      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

                      • 8. Re: Race condition in ConnectionValidator
                        Tarek Hammoud Novice

                        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.

                        • 9. Re: Race condition in ConnectionValidator
                          Ron Sigal Master

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