[jboss-user] [JBoss Remoting] - Re: LeasePinger, sessionId, jboss messaging

Tue Jan 25 13:34:44 EST 2011

Mark Torres [http://community.jboss.org/people/mark_v_torres] created the discussion

"Re: LeasePinger, sessionId, jboss messaging"

To view the discussion, visit: http://community.jboss.org/message/583131#583131

--------------------------------------------------------------
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$ http://community.jboss.org/mailto:ControlMonitorTimerTask@2b22ebae ControlMonitorTimerTask at 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$ http://community.jboss.org/mailto:ControlMonitorTimerTask@2b22ebae ControlMonitorTimerTask at 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$ http://community.jboss.org/mailto:ControlMonitorTimerTask@2b22ebae ControlMonitorTimerTask at 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$ http://community.jboss.org/mailto:ControlMonitorTimerTask@2b22ebae ControlMonitorTimerTask at 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 at 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]  mailto:org.jboss.remoting.ConnectionNotifier at fe8c4 org.jboss.remoting.ConnectionNotifier at 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]  mailto:org.jboss.remoting.ConnectionNotifier at fe8c4 org.jboss.remoting.ConnectionNotifier at 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 at 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
--------------------------------------------------------------

Reply to this message by going to Community
[http://community.jboss.org/message/583131#583131]

Start a new discussion in JBoss Remoting at Community
[http://community.jboss.org/choose-container!input.jspa?contentType=1&containerType=14&container=2050]

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.jboss.org/pipermail/jboss-user/attachments/20110125/4de62e75/attachment-0001.html 