Re: [xmlblaster] locking bug

[Póka Balázs]

Hi Marcel,

nice approach!
> Please report what you find out,
>

I got the problem! It's a deadlock between two ReentrantLocks. I just
captured the following log messages:

2008-10-28 12:32:27,413 ERROR [XmlBlaster.DispatchWorkerPool.nova-226]
(DebugReentrantLock.java:46) - trylock failed, locked by
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:485)
at
EDU.oswego.cs.dl.util.concurrent.ReentrantLock.acquire(ReentrantLock.java:40)
at org.xmlBlaster.util.ReentrantLock.lock(ReentrantLock.java:23)
at
org.xmlBlaster.engine.TopicHandler.forwardToDestinations(TopicHandler.java:844)
at org.xmlBlaster.engine.TopicHandler.publish(TopicHandler.java:728)
at
org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1679)
at
org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1405)
at
org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1393)
at
org.xmlBlaster.engine.XmlBlasterImpl.publish(XmlBlasterImpl.java:180)
at
org.xmlBlaster.engine.XmlBlasterImpl.publishArr(XmlBlasterImpl.java:219)
at
org.xmlBlaster.engine.XmlBlasterImpl.publishOneway(XmlBlasterImpl.java:233)
at
org.xmlBlaster.util.protocol.RequestReplyExecutor.receiveReply(RequestReplyExecutor.java:441)
at
org.xmlBlaster.protocol.socket.HandleClient.handleMessage(HandleClient.java:194)
at
org.xmlBlaster.protocol.socket.HandleClient$1.run(HandleClient.java:369)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:665)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:690)
at java.lang.Thread.run(Thread.java:619)
2008-10-28 12:32:27,413 ERROR [XmlBlaster.DispatchWorkerPool.nova-226]
(DebugReentrantLock.java:49) - lock() called
at
org.xmlBlaster.debug.DebugReentrantLock.tryLock(DebugReentrantLock.java:40)
at
org.xmlBlaster.engine.TopicAccessor$TopicContainer.lock(TopicAccessor.java:416)
at
org.xmlBlaster.engine.TopicAccessor.findOrCreate(TopicAccessor.java:187)
at
org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1677)
at
org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1405)
at
org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1393)
at
org.xmlBlaster.engine.XmlBlasterImpl.publish(XmlBlasterImpl.java:180)
at
org.xmlBlaster.engine.XmlBlasterImpl.publishArr(XmlBlasterImpl.java:219)
at
org.xmlBlaster.engine.XmlBlasterImpl.publishOneway(XmlBlasterImpl.java:233)
at
org.xmlBlaster.util.protocol.RequestReplyExecutor.receiveReply(RequestReplyExecutor.java:441)
at
org.xmlBlaster.protocol.socket.HandleClient.handleMessage(HandleClient.java:194)
at
org.xmlBlaster.protocol.socket.HandleClient$1.run(HandleClient.java:369)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:665)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:690)
at java.lang.Thread.run(Thread.java:619)
2008-10-28 12:32:27,414 ERROR [XmlBlaster.DispatchWorkerPool.nova-226]
(DebugReentrantLock.java:51) - failed to lock()
at
org.xmlBlaster.debug.DebugReentrantLock.tryLock(DebugReentrantLock.java:51)
at
org.xmlBlaster.engine.TopicAccessor$TopicContainer.lock(TopicAccessor.java:416)
at org.xmlBlaster.engine.TopicAccessor.access(TopicAccessor.java:93)
at
org.xmlBlaster.engine.MsgUnitWrapper.toDestroyed(MsgUnitWrapper.java:595)
at
org.xmlBlaster.engine.MsgUnitWrapper.incrementReferenceCounter(MsgUnitWrapper.java:279)
at
org.xmlBlaster.engine.queuemsg.ReferenceEntry.incrementReferenceCounter(ReferenceEntry.java:191)
at
org.xmlBlaster.engine.queuemsg.ReferenceEntry.removed(ReferenceEntry.java:230)
at
org.xmlBlaster.util.queue.ram.RamQueuePlugin.removeRandom(RamQueuePlugin.java:543)
at
org.xmlBlaster.util.dispatch.DispatchManager.removeFromQueue(DispatchManager.java:519)
at
org.xmlBlaster.util.dispatch.DispatchWorker.run(DispatchWorker.java:123)
at
EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:732)
at java.lang.Thread.run(Thread.java:619)

Explanation:
The first stacktrace is the current state of the thread which was the last
to successfully acquire the lock. The second stacktrace is from the same
thread as the first, but it reflects the state when the last locking was
successfully acquired. The third stacktrace is the stack of the thread which
timed out while trying to acquire the lock.

To conclude, the deadlock is between two instances of the following locks:
1) org.xmlBlaster.engine.SessionInfo.lock
2) org.xmlBlaster.authentication.TopicAccessor.TopicContainer.lock

I'm trying to decipher the exact cause and if it can b

Re: [xmlblaster] locking bug

[Póka Balázs]

Hi,

The previous mail was missing the thread which was locking the instance of
org.xmlBlaster.engine.SessionInfo.lock, so here it is:

2008-10-28 12:32:27,613 ERROR [XmlBlaster.SessionTimer]
(DebugReentrantLock.java:51) - failed to lock() at
java.lang.Exception
at
org.xmlBlaster.debug.DebugReentrantLock.tryLock(DebugReentrantLock.java:51)
at
org.xmlBlaster.engine.TopicAccessor$TopicContainer.lock(TopicAccessor.java:416)
at org.xmlBlaster.engine.TopicAccessor.access(TopicAccessor.java:93)
at
org.xmlBlaster.engine.MsgUnitWrapper.toDestroyed(MsgUnitWrapper.java:595)
at
org.xmlBlaster.engine.MsgUnitWrapper.incrementReferenceCounter(MsgUnitWrapper.java:279)
at
org.xmlBlaster.engine.queuemsg.ReferenceEntry.incrementReferenceCounter(ReferenceEntry.java:191)
at
org.xmlBlaster.engine.queuemsg.ReferenceEntry.removed(ReferenceEntry.java:230)
at
org.xmlBlaster.util.queue.ram.RamQueuePlugin.clear(RamQueuePlugin.java:241)
at
org.xmlBlaster.authentication.Authenticate.resetSessionInfo(Authenticate.java:806)
at
org.xmlBlaster.authentication.Authenticate.disconnect(Authenticate.java:557)
at
org.xmlBlaster.authentication.AuthenticateProtector.disconnect(AuthenticateProtector.java:119)
at
org.xmlBlaster.authentication.SessionInfo.timeout(SessionInfo.java:462)
at org.xmlBlaster.util.Timeout.run(Timeout.java:190)

That in turn means that the cause is probably:

1) org.xmlBlaster.engine.SessionInfo.lock locked at
org.xmlBlaster.authentication.SessionInfo.timeout(SessionInfo.java:462)
trying to lock
org.xmlBlaster.authentication.TopicAccessor.TopicContainer.lock;

2) org.xmlBlaster.authentication.TopicAccessor.TopicContainer.lock locked at
org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1679) trying
to lock org.xmlBlaster.engine.SessionInfo.lock at
org.xmlBlaster.engine.TopicHandler.forwardToDestinations(TopicHandler.java:844).

regards,
Balázs Póka

Re: [xmlblaster] locking bug

[Marcel Ruff]

Hi again,

i think our mails crossed, I came to the same result.

I hope i find a solution for this as one session can be in touch with
many topics and vice versa ...

Marcel

Póka Balázs schrieb:

Hi,

The previous mail was missing the thread which was locking the 
instance of org.xmlBlaster.engine.SessionInfo.lock, so here it is:


2008-10-28 12:32:27,613 ERROR [XmlBlaster.SessionTimer] 
(DebugReentrantLock.java:51) - failed to lock() at

java.lang.Exception
at 
org.xmlBlaster.debug.DebugReentrantLock.tryLock(DebugReentrantLock.java:51)
at 
org.xmlBlaster.engine.TopicAccessor$TopicContainer.lock(TopicAccessor.java:416)
at 
org.xmlBlaster.engine.TopicAccessor.access(TopicAccessor.java:93)
at 
org.xmlBlaster.engine.MsgUnitWrapper.toDestroyed(MsgUnitWrapper.java:595)
at 
org.xmlBlaster.engine.MsgUnitWrapper.incrementReferenceCounter(MsgUnitWrapper.java:279)
at 
org.xmlBlaster.engine.queuemsg.ReferenceEntry.incrementReferenceCounter(ReferenceEntry.java:191)
at 
org.xmlBlaster.engine.queuemsg.ReferenceEntry.removed(ReferenceEntry.java:230)
at 
org.xmlBlaster.util.queue.ram.RamQueuePlugin.clear(RamQueuePlugin.java:241)
at 
org.xmlBlaster.authentication.Authenticate.resetSessionInfo(Authenticate.java:806)
at 
org.xmlBlaster.authentication.Authenticate.disconnect(Authenticate.java:557)
at 
org.xmlBlaster.authentication.AuthenticateProtector.disconnect(AuthenticateProtector.java:119)
at 
org.xmlBlaster.authentication.SessionInfo.timeout(SessionInfo.java:462)

at org.xmlBlaster.util.Timeout.run(Timeout.java:190)

That in turn means that the cause is probably:

1) org.xmlBlaster.engine.SessionInfo.lock locked at 
org.xmlBlaster.authentication.SessionInfo.timeout(SessionInfo.java:462) 
trying to lock 
org.xmlBlaster.authentication.TopicAccessor.TopicContainer.lock;


2) org.xmlBlaster.authentication.TopicAccessor.TopicContainer.lock 
locked at 
org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1679) 
trying to lock org.xmlBlaster.engine.SessionInfo.lock at 
org.xmlBlaster.engine.TopicHandler.forwardToDestinations(TopicHandler.java:844).


regards,
Balázs Póka



--
Marcel Ruff
http://www.xmlBlaster.org
http://watchee.net
Phone: +49 7551 309371

Re: [xmlblaster] locking bug

[Marcel Ruff]

Not yet convinced:

The locking acquire approach is hierarchical, the sequence is always:

 -> topicHandler.lock() -> sessionInfo.lock()

The opposite:

 -> sessionInfo.lock() -> topicHandler.lock()

does not exist in that stack traces.
So this can't lead to a dead lock.

The locks used are reentrant locks, so the same thread can recursively
enter the same object multiple times.

*
But, digging in your stack trace send some days ago I have found 
following, different from all others, thread:


"XmlBlaster.SessionTimer" daemon prio=10 tid=0x2aaac4577c00 
nid=0x372a in Object.wait() [0x4153d000..0x4153da20]

  java.lang.Thread.State: WAITING (on object monitor)
   at java.lang.Object.wait(Native Method)
   at java.lang.Object.wait(Object.java:485)
   at 
edu.emory.mathcs.backport.java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:199)
   - locked <0x2aaab42ec888> (a 
edu.emory.mathcs.backport.java.util.concurrent.locks.ReentrantLock$NonfairSync)
   at 
edu.emory.mathcs.backport.java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:481)
   at 
org.xmlBlaster.engine.TopicAccessor$TopicContainer.lock(TopicAccessor.java:403)

   at org.xmlBlaster.engine.TopicAccessor.access(TopicAccessor.java:91)
   at 
org.xmlBlaster.engine.MsgUnitWrapper.toDestroyed(MsgUnitWrapper.java:595)
   at 
org.xmlBlaster.engine.MsgUnitWrapper.incrementReferenceCounter(MsgUnitWrapper.java:279)
   at 
org.xmlBlaster.engine.queuemsg.ReferenceEntry.incrementReferenceCounter(ReferenceEntry.java:191)
   at 
org.xmlBlaster.engine.queuemsg.ReferenceEntry.removed(ReferenceEntry.java:230)
   at 
org.xmlBlaster.util.queue.ram.RamQueuePlugin.clear(RamQueuePlugin.java:241)
   at 
org.xmlBlaster.authentication.Authenticate.resetSessionInfo(Authenticate.java:806)
   at 
org.xmlBlaster.authentication.Authenticate.disconnect(Authenticate.java:557)
   at 
org.xmlBlaster.authentication.AuthenticateProtector.disconnect(AuthenticateProtector.java:119)
   at 
org.xmlBlaster.authentication.SessionInfo.timeout(SessionInfo.java:462)

   at org.xmlBlaster.util.Timeout.run(Timeout.java:190)

yes, this is the deadlock you report bewteen sessionInfo and 
topicHandler/topicContainer!


  RequestBroker.publish does topicHandler.lock()  --->  
TopicHandler.java does receiverSessionInfo.lock();

versus
  SessionInfo.timeout() does sessionInfo.lock() ---> and wants 
topicHandler.lock()


I'll look for a solution tomorrow morning,

thanks for your valuable input,
Marcel


Póka Balázs schrieb:

Hi Marcel,

nice approach!
Please report what you find out,


I got the problem! It's a deadlock between two ReentrantLocks. I just 
captured the following log messages:


2008-10-28 12:32:27,413 ERROR [XmlBlaster.DispatchWorkerPool.nova-226] 
(DebugReentrantLock.java:46) - trylock failed, locked by

at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:485)
at 
EDU.oswego.cs.dl.util.concurrent.ReentrantLock.acquire(ReentrantLock.java:40)

at org.xmlBlaster.util.ReentrantLock.lock(ReentrantLock.java:23)
at 
org.xmlBlaster.engine.TopicHandler.forwardToDestinations(TopicHandler.java:844)
at 
org.xmlBlaster.engine.TopicHandler.publish(TopicHandler.java:728)
at 
org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1679)
at 
org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1405)
at 
org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1393)
at 
org.xmlBlaster.engine.XmlBlasterImpl.publish(XmlBlasterImpl.java:180)
at 
org.xmlBlaster.engine.XmlBlasterImpl.publishArr(XmlBlasterImpl.java:219)
at 
org.xmlBlaster.engine.XmlBlasterImpl.publishOneway(XmlBlasterImpl.java:233)
at 
org.xmlBlaster.util.protocol.RequestReplyExecutor.receiveReply(RequestReplyExecutor.java:441)
at 
org.xmlBlaster.protocol.socket.HandleClient.handleMessage(HandleClient.java:194)
at 
org.xmlBlaster.protocol.socket.HandleClient$1.run(HandleClient.java:369)
at 
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:665)
at 
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:690)

at java.lang.Thread.run(Thread.java:619)
2008-10-28 12:32:27,413 ERROR [XmlBlaster.DispatchWorkerPool.nova-226] 
(DebugReentrantLock.java:49) - lock() called
at 
org.xmlBlaster.debug.DebugReentrantLock.tryLock(DebugReentrantLock.java:40)
at 
org.xmlBlaster.engine.TopicAccessor$TopicContainer.lock(TopicAccessor.java:416)
at 
org.xmlBlaster.engine.TopicAccessor.findOrCreate(TopicAccessor.java:187)
at 
org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1677)
at 
org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1405)
at 
org.xmlBlaster.engine.RequestBroker.publish(RequestBroker.java:1393)
at 
org.

Re: [xmlblaster] locking bug

[Póka Balázs]

Hi there,

Just a thought: what if you modified SessionInfo.timeout(Object) like this:

   public final void timeout(Object userData) {
  synchronized (this.EXPIRY_TIMER_MONITOR) {
 this.timerKey = null;
 log.warning(ME+": Session timeout for " + getLoginName() + "
occurred, session '" + getSecretSessionId() + "' is expired, autologout");
  }
  DisconnectQosServer qos = new DisconnectQosServer(glob);
  qos.deleteSubjectQueue(true);
  try {
 glob.getAuthenticate().disconnect(getAddressServer(),
getSecretSessionId(), qos.toXml());
  } catch (XmlBlasterException e) {
 log.severe(ME+": Internal problem with disconnect: " +
e.toString());
  }
   }

It seems as if timerKey is protected by EXPIRY_TIMER_MONITOR elsewhere, but
not here (this might be an error). I simply removed the locking of "lock"
from the method. Does this make it thread-unsafe? :)

regards,
Balázs

Re: [xmlblaster] locking bug

[Marcel Ruff]

Póka Balázs schrieb:

Hi there,

Just a thought: what if you modified SessionInfo.timeout(Object) like 
this:


   public final void timeout(Object userData) {
  synchronized (this.EXPIRY_TIMER_MONITOR) {
 this.timerKey = null;
 log.warning(ME+": Session timeout for " + getLoginName() + " 
occurred, session '" + getSecretSessionId() + "' is expired, autologout");

  }
  DisconnectQosServer qos = new DisconnectQosServer(glob);
  qos.deleteSubjectQueue(true);
  try {
 glob.getAuthenticate().disconnect(getAddressServer(), 
getSecretSessionId(), qos.toXml());

  } catch (XmlBlasterException e) {
 log.severe(ME+": Internal problem with disconnect: " + 
e.toString());

  }
   }

It seems as if timerKey is protected by EXPIRY_TIMER_MONITOR 
elsewhere, but not here (this might be an error). I simply removed the 
locking of "lock" from the method. Does this make it 
thread-unsafe? :)

No, i think the original sync did not make sense,
as the disconnect (coming here from a timeout thread)
can also come from a remote client which disconnects at any time,
so the core must be capable to handle this situation anyhow.

I have removed the sync here and also in shutdown() to prevent the deadlock.
The current code is now committed to svn.

thanks again
Marcel


regards,
Balázs



--
Marcel Ruff
http://www.xmlBlaster.org
http://watchee.net
Phone: +49 7551 309371