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@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@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@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@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]
mailto:org.jboss.remoting.ConnectionNotifier@fe8c4
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]
mailto:org.jboss.remoting.ConnectionNotifier@fe8c4
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
--------------------------------------------------------------
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&...]