LeasePinger, sessionId, jboss messaging

[mark_v_torres]

Hi,

We're experiencing intermittent connection issues with jboss messaging.

Client

jboss app server 4.2.3.GA

jboss messaging 1.4.5.GA

jboss remoting 2.2.3.SP3

Server

jboss app server 4.2.3.GA

jboss messaging 1.4.5.GA

jboss remoting 2.2.3.SP3

We've set up an exception listener on the client side that "reconnects" upon failure. However, we do get into situations where the connection becomes dead on the server side, but the exception listener does not fire on the client side.

We're able to recreate the issue locally when we pause the client...

kill -s STOP <pid>

wait till the server detects and disconnects the client, and resume the client

kill -s CONT <pid>

I tried tracing the issue and come across a possible cause...

During the resume, 2 ping threads awake, one for LeasePinger and one for ConnectionValidator

LeasePinger does not set ServerInvoker.INVOKER_SESSION_ID on the requestPayload map, but ConnectionValidator.doCheckConnectionWithLease does.

On the server side, ServerInvoker.invoke, if ServerInvoker.INVOKER_SESSION_ID is not in the requestPayloadMap, the server creates/updates the lease.

I think the issue happens when the LeasePinger thread fires before the ConnectionValidator thread.

Can you please give us insights on how we can overcome this problem.

I attached the remoting-bisocket config on the server side.

[mark_v_torres]

In the mean time we're trying to bump up the clientLeasePeriod to 120000, from the 10000 that was in jboss messaging 1.4.5.GA distribution.

Do I need to create a jira issue? This sounds like a bug to me.

[ron_sigal]

Hi Mark,

Actually, the behavior you describe is what I would expect.  Assuming the LeasePinger fires before the ConnectionValidator when you let the Client run:

1. The Lease times out and gets destroyed.

2. The LeasePinger fires, the ServerInvoker sees a new clientSessionId and recreates the Lease.

3. The ConnectionValidator fires, the ServerInvoker sees an existing lease, returns true, and the ConnectionValidator is happy.

I don't consider this sequence a Remoting bug since there is no specification that says anything different should happen.  However, it may be a semantic mismatch with JBoss Messaging requirements.  More about that further on.

But I'm not sure your "recreation" is a faithful representation of the problem.  When you say "the connection becomes dead on the server side", do you mean

1. the server is alive but the network connection has failed, or

2. the server has died and been restarted.

In the first case, which, I think, matches your recreation, it's not clear to me that there's a problem.  If the server is temporarily unavailable, is it necessary for the client to disconnect?  That's a question for JBoss Messaging.  I don't know the answer.

In the second case, it turns out, JBoss Messaging wants the client to disconnect.  We became aware of this requirement only recently, and I've implemented JBREM-1144 "Extend connection identity to server side" in response.  The matchng JBoss Messaging issue is JBMESSAGING-1843 "Incorporate JBREM-1144". This new feature, which will be availble in the next releases of Remoting and JBoss Messaging, will make it possible for the ConnectionValidator to recognize that the server has been replaced and to declare that the connection has been broken.

So, I believe case 2 is solved.  I don't know what should happen in case 1.  What do you think?

-Ron

[mark_v_torres]

Hi Ron,

Thanks for your reply.

Its been a couple of weeks so the exact behavior is a little hazy in my memory. I'll try to test later.

For the case where the LeasePinger awakes first, what happens is the server cleans up its associated resources for that lease, but the client eventually still tries to use the lease.

We eventually end up with repeating log entries that contains the following

WARN  [org.jboss.remoting.transport.bisocket.BisocketServerInvoker] org.jboss.remoting.transport.bisocket.BisocketServerInvoker$ControlMonitorTimerTask@2b22ebae: detected failure on control connection Thread[control: Socket[addr=/*.*.*.*,port=*****,localport=*****],5,jboss] (3j011-cnnwn5-gg6xpq1c-1-gg6xw0ay-c: requesting new control connection

WARN  [org.jboss.remoting.transport.bisocket.BisocketServerInvoker] org.jboss.remoting.transport.bisocket.BisocketServerInvoker$ControlMonitorTimerTask@2b22ebae: detected failure on control connection Thread[control: Socket[addr=/*.*.*.*,port=*****,localport=*****],5,jboss] (3j011-cnnwn5-gg6xpq1c-1-gg6xw0ay-c: requesting new control connection

WARN  [org.jboss.remoting.transport.bisocket.BisocketServerInvoker] org.jboss.remoting.transport.bisocket.BisocketServerInvoker$ControlMonitorTimerTask@2b22ebae: detected failure on control connection Thread[control: Socket[addr=/*.*.*.*,port=*****,localport=*****],5,jboss] (3j011-cnnwn5-gg6xpq1c-1-gg6xw0ay-c: requesting new control connection

WARN  [org.jboss.remoting.transport.bisocket.BisocketServerInvoker] org.jboss.remoting.transport.bisocket.BisocketServerInvoker$ControlMonitorTimerTask@2b22ebae: detected failure on control connection Thread[control: Socket[addr=/*.*.*.*,port=*****,localport=*****],5,jboss] (3j011-cnnwn5-gg6xpq1c-1-gg6xw0ay-c: requesting new control connection

But I'm not sure your "recreation" is a faithful representation of the problem.  When you say "the connection becomes dead on the server side", do you mean

Neither the server nor the client gets restarted. They remain connected on the network, but on my "recreation" the client experienced a heavy load that its not able to send out pings for some time.

"The connection becomes dead on the server side" - What I mean to say is that the resources have been cleaned up from the server side for that lease, but the actual server jvm is still running.

Here's the trace log that I got from the server during an unsuccesful disconnection...

--connect

2010-12-28 09:15:09,940 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read version from input stream

2010-12-28 09:15:19,911 TRACE [org.jboss.remoting.transport.socket.ServerThread] read version 22 from input stream

2010-12-28 09:15:19,911 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read invocation from unmarshaller

2010-12-28 09:15:19,911 TRACE [org.jboss.remoting.transport.socket.ServerThread] read InvocationRequest[5d4a62, $PING$] from unmarshaller

2010-12-28 09:15:19,911 TRACE [org.jboss.remoting.transport.socket.ServerThread] about to call SocketServerInvoker[192.168.1.3:4457].invoke()

2010-12-28 09:15:19,911 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[192.168.1.3:4457] received $PING$

2010-12-28 09:15:19,911 TRACE [org.jboss.remoting.ServerInvoker] Getting lease for invoker session id: 5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8

2010-12-28 09:15:19,912 TRACE [org.jboss.remoting.ServerInvoker] Lease[406c7e:5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8:5c4o16-3bs5xt-gi8uuno8-1-gi8uw222-9] matches: leasePingerId: 5c4o16-3bs5xt-gi8uuno8-1-gi8uw222-9

2010-12-28 09:15:19,912 TRACE [org.jboss.remoting.Lease] Lease[406c7e:5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8:5c4o16-3bs5xt-gi8uuno8-1-gi8uw222-9] requestMap: {ClientHolderKey={5c4o16-3bs5xt-gi8uuno8-1-gi8uw21m-6=org.jboss.remoting.ClientHolder@be8e12}, timeStamp=1293545641187, leasePingerId=5c4o16-3bs5xt-gi8uuno8-1-gi8uw222-9}

2010-12-28 09:15:19,912 TRACE [org.jboss.remoting.Lease] Lease[406c7e:5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8:5c4o16-3bs5xt-gi8uuno8-1-gi8uw222-9] last update: 1293545631187, this update: 1293545641187

2010-12-28 09:15:19,912 TRACE [org.jboss.remoting.Lease] Lease[406c7e:5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8:5c4o16-3bs5xt-gi8uuno8-1-gi8uw222-9] updating: new Client list:

2010-12-28 09:15:19,912 TRACE [org.jboss.remoting.Lease] 5c4o16-3bs5xt-gi8uuno8-1-gi8uw222-9:  5c4o16-3bs5xt-gi8uuno8-1-gi8uw21m-6

2010-12-28 09:15:19,912 TRACE [org.jboss.remoting.ServerInvoker] Updated lease for invoker session id (5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8)

2010-12-28 09:15:19,912 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[192.168.1.3:4457] returning InvocationResponse[6159c4, true]

2010-12-28 09:15:19,912 TRACE [org.jboss.remoting.transport.socket.ServerThread] SocketServerInvoker[192.168.1.3:4457].invoke() returned InvocationResponse[6159c4, true]

2010-12-28 09:15:19,912 TRACE [org.jboss.remoting.transport.socket.ServerThread] creating response instance

2010-12-28 09:15:19,912 TRACE [org.jboss.remoting.transport.socket.ServerThread] wrote response to the output stream

2010-12-28 09:15:19,912 TRACE [org.jboss.remoting.transport.socket.ServerThread] preparing to process next invocation invocation

-- disconnect

2010-12-28 09:15:59,806 TRACE [org.jboss.remoting.Lease] Lease[406c7e:5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8:5c4o16-3bs5xt-gi8uuno8-1-gi8uw222-9] did not receive ping: 5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8

2010-12-28 09:15:59,808 TRACE [org.jboss.remoting.Lease] Lease[406c7e:5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8:5c4o16-3bs5xt-gi8uuno8-1-gi8uw222-9] notifying listeners about 1 expired client(s)

2010-12-28 09:15:59,808 DEBUG [org.jboss.remoting.ConnectionNotifier] org.jboss.remoting.ConnectionNotifier@fe8c4 Server connection lost to client (session id = 5c4o16-3bs5xt-gi8uuno8-1-gi8uw21m-6

2010-12-28 09:15:59,809 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[192.168.1.3:4457] removing server callback handler ServerInvokerCallbackHandler[5c4o16-3bs5xt-gi8uuno8-1-gi8uw21m-6+5c4o16-3bs5xt-gi8uuno8-1-gi8uw25b-d].

2010-12-28 09:15:59,809 TRACE [org.jboss.remoting.Client] Client[4806599:3j011-y3aa1o-gi84ufr8-1-gi8uxqvf-c] entering disconnect()

2010-12-28 09:15:59,809 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[43fb68, bisocket://192.168.1.6:452753942] entering terminateLease() for null

2010-12-28 09:15:59,809 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[43fb68, bisocket://192.168.1.6:452753942] leasePinger is null: must have been shut down already

2010-12-28 09:15:59,809 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[43fb68, bisocket://192.168.1.6:452753942] leaving terminateLease() for null

2010-12-28 09:15:59,809 TRACE [org.jboss.remoting.InvokerRegistry] destroying client invoker InvokerLocator [bisocket://192.168.1.6:452753942/callback?callbackServerHost=192.168.1.6&callbackServerPort=452753942&callbackServerProtocol=bisocket&clientMaxPoolSize=1&clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper&datatype=jms&guid=5c4o16-3bs5xt-gi8uuno8-1-gi8uw24g-c&isCallbackServer=true&onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool&serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper], config {callbackErrorsAllowed=1, registerCallbackListener=false, callbackServerProtocol=bisocket, serverInvokerCallbackHandler=ServerInvokerCallbackHandler[5c4o16-3bs5xt-gi8uuno8-1-gi8uw21m-6+5c4o16-3bs5xt-gi8uuno8-1-gi8uw25b-d], stopLeaseOnFailure=true, socket.check_connection=false, listenerId=5c4o16-3bs5xt-gi8uuno8-1-gi8uw25b-d, unmarshaller=org.jboss.jms.wireformat.JMSWireFormat, marshaller=org.jboss.jms.wireformat.JMSWireFormat, serverInvoker=SocketServerInvoker[192.168.1.3:4457], clientLeasePeriod=10000, onewayThreadPool=org.jboss.jms.server.remoting.DirectThreadPool, useClientConnectionIdentity=true, callbackServerHost=192.168.1.6, JBM_clientMaxPoolSize=200, callbackTimeout=10000, clientMaxPoolSize=1, validatorPingTimeout=5000, isCallbackServer=true, validatorPingPeriod=10000, numberOfRetries=10, serverSocketClass=org.jboss.jms.server.remoting.ServerSocketWrapper, failureDisconnectTimeout=0, clientSocketClass=org.jboss.jms.client.remoting.ClientSocketWrapper, callbackServerPort=452753942, guid=5c4o16-3bs5xt-gi8uuno8-1-gi8uw24g-c, dataType=jms, serverBindPort=4457, datatype=jms, serverBindAddress=192.168.1.3, timeout=10000}

2010-12-28 09:15:59,809 DEBUG [org.jboss.remoting.InvokerRegistry] removed SocketClientInvoker[43fb68, bisocket://192.168.1.6:452753942] from registry

2010-12-28 09:15:59,809 TRACE [org.jboss.remoting.InvokerRegistry] disconnecting SocketClientInvoker[43fb68, bisocket://192.168.1.6:452753942]

2010-12-28 09:15:59,809 DEBUG [org.jboss.remoting.transport.socket.MicroSocketClientInvoker] SocketClientInvoker[43fb68, bisocket://192.168.1.6:452753942] disconnecting ...

2010-12-28 09:15:59,809 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[43fb68, bisocket://192.168.1.6:452753942] disconnecting ...

2010-12-28 09:15:59,809 TRACE [org.jboss.remoting.MicroRemoteClientInvoker] SocketClientInvoker[43fb68, bisocket://192.168.1.6:452753942] disconnected

2010-12-28 09:15:59,809 DEBUG [org.jboss.remoting.Client] Client[4806599:3j011-y3aa1o-gi84ufr8-1-gi8uxqvf-c] is disconnected

2010-12-28 09:15:59,809 DEBUG [org.jboss.remoting.callback.ServerInvokerCallbackHandler] ServerInvokerCallbackHandler[5c4o16-3bs5xt-gi8uuno8-1-gi8uw21m-6+5c4o16-3bs5xt-gi8uuno8-1-gi8uw25b-d] shut down

2010-12-28 09:15:59,810 DEBUG [org.jboss.remoting.ConnectionNotifier] org.jboss.remoting.ConnectionNotifier@fe8c4 notified ConnectionManager[1aea727] of connection lost to: 5c4o16-3bs5xt-gi8uuno8-1-gi8uw21m-6

2010-12-28 09:15:59,810 TRACE [org.jboss.remoting.Lease] Lease[406c7e:5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8:5c4o16-3bs5xt-gi8uuno8-1-gi8uw222-9] Notified connection listener of lease expired due to lost connection from client (client session id = 5c4o16-3bs5xt-gi8uuno8-1-gi8uw21m-6

2010-12-28 09:15:59,810 TRACE [org.jboss.remoting.Lease] Lease[406c7e:5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8:5c4o16-3bs5xt-gi8uuno8-1-gi8uw222-9] removed lease:5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8

--ping returns true but should be false

2010-12-28 09:18:47,448 TRACE [org.jboss.remoting.transport.socket.ServerThread] read version 22 from input stream

2010-12-28 09:18:47,448 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read invocation from unmarshaller

2010-12-28 09:18:47,449 TRACE [org.jboss.remoting.transport.socket.ServerThread] read InvocationRequest[1887dd5, $PING$] from unmarshaller

2010-12-28 09:18:47,449 TRACE [org.jboss.remoting.transport.socket.ServerThread] about to call SocketServerInvoker[192.168.1.3:4457].invoke()

2010-12-28 09:18:47,449 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[192.168.1.3:4457] received $PING$

2010-12-28 09:18:47,449 TRACE [org.jboss.remoting.ServerInvoker] Getting lease for invoker session id: 5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8

2010-12-28 09:18:47,449 TRACE [org.jboss.remoting.Lease] Lease[c83cfd:5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8:5c4o16-3bs5xt-gi8uuno8-1-gi8uw222-9] initialized with lastUpdate: 1293545848717

2010-12-28 09:18:47,449 TRACE [org.jboss.remoting.Lease] Lease[c83cfd:5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8:5c4o16-3bs5xt-gi8uuno8-1-gi8uw222-9] initialized with requestPayload: {5c4o16-3bs5xt-gi8uuno8-1-gi8uw21m-6=org.jboss.remoting.ClientHolder@1c232a}

2010-12-28 09:18:47,449 TRACE [org.jboss.remoting.Lease] leasePingerId: 5c4o16-3bs5xt-gi8uuno8-1-gi8uw222-9

2010-12-28 09:18:47,449 TRACE [org.jboss.remoting.Lease] Starting lease for client invoker (session id = 5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8) with lease window time of 20000

2010-12-28 09:18:47,449 TRACE [org.jboss.remoting.ServerInvoker] No lease established for invoker session id (5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8), so starting a new one:Lease[c83cfd:5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8:5c4o16-3bs5xt-gi8uuno8-1-gi8uw222-9]

2010-12-28 09:18:47,449 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[192.168.1.3:4457] returning InvocationResponse[148ccb8, true]

2010-12-28 09:18:47,449 TRACE [org.jboss.remoting.transport.socket.ServerThread] SocketServerInvoker[192.168.1.3:4457].invoke() returned InvocationResponse[148ccb8, true]

2010-12-28 09:18:47,449 TRACE [org.jboss.remoting.transport.socket.ServerThread] creating response instance

2010-12-28 09:18:47,450 TRACE [org.jboss.remoting.transport.socket.ServerThread] wrote response to the output stream

2010-12-28 09:18:47,450 TRACE [org.jboss.remoting.transport.socket.ServerThread] preparing to process next invocation invocation

2010-12-28 09:18:47,450 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read version from input stream

2010-12-28 09:18:47,486 TRACE [org.jboss.remoting.transport.socket.ServerThread] read version 22 from input stream

2010-12-28 09:18:47,487 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read invocation from unmarshaller

2010-12-28 09:18:47,487 TRACE [org.jboss.remoting.transport.socket.ServerThread] read InvocationRequest[d1e832, self, $PING$] from unmarshaller

2010-12-28 09:18:47,487 TRACE [org.jboss.remoting.transport.socket.ServerThread] about to call SocketServerInvoker[192.168.1.3:4457].invoke()

2010-12-28 09:18:47,487 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[192.168.1.3:4457] received $PING$

2010-12-28 09:18:47,487 TRACE [org.jboss.remoting.ServerInvoker] Checking lease for invoker session id: 5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8

2010-12-28 09:18:47,487 TRACE [org.jboss.remoting.ServerInvoker] Found lease for invoker session id (5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8)

2010-12-28 09:18:47,487 TRACE [org.jboss.remoting.ServerInvoker] SocketServerInvoker[192.168.1.3:4457] responding true to $PING$ for invoker sessionId 5c4o16-3bs5xt-gi8uuno8-1-gi8uw21q-8

2010-12-28 09:18:47,487 TRACE [org.jboss.remoting.transport.socket.ServerThread] SocketServerInvoker[192.168.1.3:4457].invoke() returned true

2010-12-28 09:18:47,487 TRACE [org.jboss.remoting.transport.socket.ServerThread] creating response instance

2010-12-28 09:18:47,487 TRACE [org.jboss.remoting.transport.socket.ServerThread] wrote response to the output stream

2010-12-28 09:18:47,487 TRACE [org.jboss.remoting.transport.socket.ServerThread] preparing to process next invocation invocation

2010-12-28 09:18:47,487 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read version from input stream

2010-12-28 09:18:57,440 TRACE [org.jboss.remoting.transport.socket.ServerThread] read version 22 from input stream

2010-12-28 09:18:57,440 TRACE [org.jboss.remoting.transport.socket.ServerThread] blocking to read invocation from unmarshaller

2010-12-28 09:18:57,440 TRACE [org.jboss.remoting.transport.socket.ServerThread] read InvocationRequest[84a74, InternalI

[ron_sigal]

Hi Mark,

Ok, when the Lease times out, it notifies JBoss Messaging, which, presumably, shuts down the server end of the JMS connection.  One of the things that happens is that the bisocket ping from server to client gets turned off, which is why you see those "detected failure on control connection" error messages.  That makes sense.

Now, the interesting thing is that server remains alive, but the Lease has changed.  My recent changes to create a server identity wouldn't handle this situation.  Ok, let me think about it.

Thanks,

-Ron

[mark_v_torres]

Hi Ron,

Thanks for looking into this.

[ron_sigal]

Hey Mark,

I've made a change which should address your situation.  Now, each Lease has a unique identity, which is returned to ConnectionValidator.  When the Lease changes, ConnectionValidator considers the connection to be broken.

I attached a jboss-remoting.jar to JBREM-1144 with the fix, if you want to give it a spin.  It's a preview of 2.2.3.SP4, so it should be compatible with the rest of your system.

-Ron

[ron_sigal]

The new unit test for the circumstance described in this thread is passing, so I've re-closed JBREM-1144.

-Ron

[mark_v_torres]

Hi Ron,

Sorry, I had a different priority this past few days so I wasnt able to test this.

I just tested the jar attached on my dev instance. The reconnection worked for both scenarios(LeasePinger,Connection validator waking up first). Just wanted to note, if ever people are gonna try your 2.2.3.SP4 pre-release jar, that I had to add

<attribute name="useServerConnectionIdentity" isParam="true">true</attribute>

to my remoting-bisocket-service.xml to get the new feature to work.

Thanks for the fix.

[ron_sigal]

Hi Mark,

Right.  Thanks for pointing that out.

-Ron