Re: [xmlblaster] locking bug
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
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
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
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
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
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