You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@qpid.apache.org by "Keith Wall (JIRA)" <ji...@apache.org> on 2016/03/18 15:13:33 UTC

[jira] [Updated] (QPID-7154) JMX QueueMBean#clearQueue operation does not acquire messages prior to dequeue which allows for store level lock timeout

     [ https://issues.apache.org/jira/browse/QPID-7154?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Keith Wall updated QPID-7154:
-----------------------------
    Description: 
The following was reported by a user using a 0.32 derivative.

The background was an operator was attempting to clear queue with very large depth using JMX management (QueueMBean#clearQueue) as the same time as a messaging client (consumer) was rejecting messages which were being routed to another queue and then dequeued.

The message client (consumer) store level transaction timed out. This caused the Broker to fail (uncaught exception).

{code}
com.sleepycat.je.LockTimeoutException: (JE 5.0.104) Lock expired. Locker 792611890 1557851806_IoReceiver - /xxx.xx.xx.xx:32962_Txn: waited for lock on database=QUEUE_ENTRIES LockAddr:1959781711 LSN=0x74a70/0x94db8e type=WRITE grant=WAIT_NEW timeoutMillis=500 startTime=1458223769602 endTime=1458223770102
Owners: [<LockInfo locker="1466269883 1557851804_RMI TCP Connection(16333)-xx.xx.xx.xx_Txn" type="WRITE"/>]
Waiters: []
 
                at com.sleepycat.je.txn.LockManager.newLockTimeoutException(LockManager.java:665)
                at com.sleepycat.je.txn.LockManager.makeTimeoutMsgInternal(LockManager.java:623)
                at com.sleepycat.je.txn.SyncedLockManager.makeTimeoutMsg(SyncedLockManager.java:97)
                at com.sleepycat.je.txn.LockManager.lockInternal(LockManager.java:390)
                at com.sleepycat.je.txn.LockManager.lock(LockManager.java:276)
                at com.sleepycat.je.txn.Txn.lockInternal(Txn.java:522)
                at com.sleepycat.je.txn.Locker.lock(Locker.java:443)
                at com.sleepycat.je.dbi.CursorImpl.lockLN(CursorImpl.java:2642)
                at com.sleepycat.je.dbi.CursorImpl.lockLN(CursorImpl.java:2443)
                at com.sleepycat.je.dbi.CursorImpl.searchAndPosition(CursorImpl.java:2168)
                at com.sleepycat.je.Cursor.searchInternal(Cursor.java:2822)
                at com.sleepycat.je.Cursor.searchAllowPhantoms(Cursor.java:2732)
                at com.sleepycat.je.Cursor.searchNoDups(Cursor.java:2586)
                at com.sleepycat.je.Cursor.search(Cursor.java:2553)
                at com.sleepycat.je.Database.deleteInternal(Database.java:1151)
                at com.sleepycat.je.Database.delete(Database.java:1080)
                at org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore.dequeueMessage(AbstractBDBMessageStore.java:819)
                at org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore.access$1000(AbstractBDBMessageStore.java:71)
                at org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore$BDBTransaction.dequeueMessage(AbstractBDBMessageStore.java:1496)
                at org.apache.qpid.server.txn.LocalTransaction.dequeue(LocalTransaction.java:110)
                at org.apache.qpid.server.queue.QueueEntryImpl.routeToAlternate(QueueEntryImpl.java:463)
                at org.apache.qpid.server.protocol.v0_8.AMQChannel.deadLetter(AMQChannel.java:1795)
                at org.apache.qpid.server.protocol.v0_8.AMQChannel.receiveBasicReject(AMQChannel.java:2431)
                at org.apache.qpid.framing.BasicRejectBody.process(BasicRejectBody.java:123)
                at org.apache.qpid.codec.ServerDecoder.processMethod(ServerDecoder.java:188)
                at org.apache.qpid.codec.AMQDecoder.processFrame(AMQDecoder.java:388)
                at org.apache.qpid.server.protocol.v0_8.BrokerDecoder.doProcessFrame(BrokerDecoder.java:113)
                at org.apache.qpid.server.protocol.v0_8.BrokerDecoder.access$000(BrokerDecoder.java:36)
                at org.apache.qpid.server.protocol.v0_8.BrokerDecoder$1.run(BrokerDecoder.java:79)
                at org.apache.qpid.server.protocol.v0_8.BrokerDecoder$1.run(BrokerDecoder.java:75)
                at java.security.AccessController.doPrivileged(Native Method)
                at javax.security.auth.Subject.doAs(Subject.java:415)
                at org.apache.qpid.server.protocol.v0_8.BrokerDecoder.processFrame(BrokerDecoder.java:74)
                at org.apache.qpid.codec.AMQDecoder.processInput(AMQDecoder.java:370)
                at org.apache.qpid.codec.AMQDecoder.decodeBuffer(AMQDecoder.java:259)
                at org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine$2.run(AMQProtocolEngine.java:334)
                at org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine$2.run(AMQProtocolEngine.java:311)
                at java.security.AccessController.doPrivileged(Native Method)
                at javax.security.auth.Subject.doAs(Subject.java:356)
                at org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine.received(AMQProtocolEngine.java:310)
                at org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine.received(AMQProtocolEngine.java:95)
                at org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:153)
                at org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:51)
                at org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:161)
                at java.lang.Thread.run(Thread.java:744)
{code}

  was:
The following was reported by a user using a 0.32 derivative.

The background was an operator was attempting to clear queue with very large depth using JMX management (QueueMBean#clearQueue) as the same time as a messaging client (consumer) was rejecting messages which were being routed to another queue and then dequeued.

The message client (consumer) store level transaction timed out. This caused the Broker to fail.

{code}
com.sleepycat.je.LockTimeoutException: (JE 5.0.104) Lock expired. Locker 792611890 1557851806_IoReceiver - /xxx.xx.xx.xx:32962_Txn: waited for lock on database=QUEUE_ENTRIES LockAddr:1959781711 LSN=0x74a70/0x94db8e type=WRITE grant=WAIT_NEW timeoutMillis=500 startTime=1458223769602 endTime=1458223770102
Owners: [<LockInfo locker="1466269883 1557851804_RMI TCP Connection(16333)-xx.xx.xx.xx_Txn" type="WRITE"/>]
Waiters: []
 
                at com.sleepycat.je.txn.LockManager.newLockTimeoutException(LockManager.java:665)
                at com.sleepycat.je.txn.LockManager.makeTimeoutMsgInternal(LockManager.java:623)
                at com.sleepycat.je.txn.SyncedLockManager.makeTimeoutMsg(SyncedLockManager.java:97)
                at com.sleepycat.je.txn.LockManager.lockInternal(LockManager.java:390)
                at com.sleepycat.je.txn.LockManager.lock(LockManager.java:276)
                at com.sleepycat.je.txn.Txn.lockInternal(Txn.java:522)
                at com.sleepycat.je.txn.Locker.lock(Locker.java:443)
                at com.sleepycat.je.dbi.CursorImpl.lockLN(CursorImpl.java:2642)
                at com.sleepycat.je.dbi.CursorImpl.lockLN(CursorImpl.java:2443)
                at com.sleepycat.je.dbi.CursorImpl.searchAndPosition(CursorImpl.java:2168)
                at com.sleepycat.je.Cursor.searchInternal(Cursor.java:2822)
                at com.sleepycat.je.Cursor.searchAllowPhantoms(Cursor.java:2732)
                at com.sleepycat.je.Cursor.searchNoDups(Cursor.java:2586)
                at com.sleepycat.je.Cursor.search(Cursor.java:2553)
                at com.sleepycat.je.Database.deleteInternal(Database.java:1151)
                at com.sleepycat.je.Database.delete(Database.java:1080)
                at org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore.dequeueMessage(AbstractBDBMessageStore.java:819)
                at org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore.access$1000(AbstractBDBMessageStore.java:71)
                at org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore$BDBTransaction.dequeueMessage(AbstractBDBMessageStore.java:1496)
                at org.apache.qpid.server.txn.LocalTransaction.dequeue(LocalTransaction.java:110)
                at org.apache.qpid.server.queue.QueueEntryImpl.routeToAlternate(QueueEntryImpl.java:463)
                at org.apache.qpid.server.protocol.v0_8.AMQChannel.deadLetter(AMQChannel.java:1795)
                at org.apache.qpid.server.protocol.v0_8.AMQChannel.receiveBasicReject(AMQChannel.java:2431)
                at org.apache.qpid.framing.BasicRejectBody.process(BasicRejectBody.java:123)
                at org.apache.qpid.codec.ServerDecoder.processMethod(ServerDecoder.java:188)
                at org.apache.qpid.codec.AMQDecoder.processFrame(AMQDecoder.java:388)
                at org.apache.qpid.server.protocol.v0_8.BrokerDecoder.doProcessFrame(BrokerDecoder.java:113)
                at org.apache.qpid.server.protocol.v0_8.BrokerDecoder.access$000(BrokerDecoder.java:36)
                at org.apache.qpid.server.protocol.v0_8.BrokerDecoder$1.run(BrokerDecoder.java:79)
                at org.apache.qpid.server.protocol.v0_8.BrokerDecoder$1.run(BrokerDecoder.java:75)
                at java.security.AccessController.doPrivileged(Native Method)
                at javax.security.auth.Subject.doAs(Subject.java:415)
                at org.apache.qpid.server.protocol.v0_8.BrokerDecoder.processFrame(BrokerDecoder.java:74)
                at org.apache.qpid.codec.AMQDecoder.processInput(AMQDecoder.java:370)
                at org.apache.qpid.codec.AMQDecoder.decodeBuffer(AMQDecoder.java:259)
                at org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine$2.run(AMQProtocolEngine.java:334)
                at org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine$2.run(AMQProtocolEngine.java:311)
                at java.security.AccessController.doPrivileged(Native Method)
                at javax.security.auth.Subject.doAs(Subject.java:356)
                at org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine.received(AMQProtocolEngine.java:310)
                at org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine.received(AMQProtocolEngine.java:95)
                at org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:153)
                at org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:51)
                at org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:161)
                at java.lang.Thread.run(Thread.java:744)
{code}


> JMX QueueMBean#clearQueue operation does not acquire messages prior to dequeue which allows for store level lock timeout 
> -------------------------------------------------------------------------------------------------------------------------
>
>                 Key: QPID-7154
>                 URL: https://issues.apache.org/jira/browse/QPID-7154
>             Project: Qpid
>          Issue Type: Bug
>          Components: Java Broker
>    Affects Versions: 0.18, 0.22, 0.30, 0.32, qpid-java-6.0.1
>            Reporter: Keith Wall
>             Fix For: qpid-java-6.0.2
>
>
> The following was reported by a user using a 0.32 derivative.
> The background was an operator was attempting to clear queue with very large depth using JMX management (QueueMBean#clearQueue) as the same time as a messaging client (consumer) was rejecting messages which were being routed to another queue and then dequeued.
> The message client (consumer) store level transaction timed out. This caused the Broker to fail (uncaught exception).
> {code}
> com.sleepycat.je.LockTimeoutException: (JE 5.0.104) Lock expired. Locker 792611890 1557851806_IoReceiver - /xxx.xx.xx.xx:32962_Txn: waited for lock on database=QUEUE_ENTRIES LockAddr:1959781711 LSN=0x74a70/0x94db8e type=WRITE grant=WAIT_NEW timeoutMillis=500 startTime=1458223769602 endTime=1458223770102
> Owners: [<LockInfo locker="1466269883 1557851804_RMI TCP Connection(16333)-xx.xx.xx.xx_Txn" type="WRITE"/>]
> Waiters: []
>  
>                 at com.sleepycat.je.txn.LockManager.newLockTimeoutException(LockManager.java:665)
>                 at com.sleepycat.je.txn.LockManager.makeTimeoutMsgInternal(LockManager.java:623)
>                 at com.sleepycat.je.txn.SyncedLockManager.makeTimeoutMsg(SyncedLockManager.java:97)
>                 at com.sleepycat.je.txn.LockManager.lockInternal(LockManager.java:390)
>                 at com.sleepycat.je.txn.LockManager.lock(LockManager.java:276)
>                 at com.sleepycat.je.txn.Txn.lockInternal(Txn.java:522)
>                 at com.sleepycat.je.txn.Locker.lock(Locker.java:443)
>                 at com.sleepycat.je.dbi.CursorImpl.lockLN(CursorImpl.java:2642)
>                 at com.sleepycat.je.dbi.CursorImpl.lockLN(CursorImpl.java:2443)
>                 at com.sleepycat.je.dbi.CursorImpl.searchAndPosition(CursorImpl.java:2168)
>                 at com.sleepycat.je.Cursor.searchInternal(Cursor.java:2822)
>                 at com.sleepycat.je.Cursor.searchAllowPhantoms(Cursor.java:2732)
>                 at com.sleepycat.je.Cursor.searchNoDups(Cursor.java:2586)
>                 at com.sleepycat.je.Cursor.search(Cursor.java:2553)
>                 at com.sleepycat.je.Database.deleteInternal(Database.java:1151)
>                 at com.sleepycat.je.Database.delete(Database.java:1080)
>                 at org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore.dequeueMessage(AbstractBDBMessageStore.java:819)
>                 at org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore.access$1000(AbstractBDBMessageStore.java:71)
>                 at org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore$BDBTransaction.dequeueMessage(AbstractBDBMessageStore.java:1496)
>                 at org.apache.qpid.server.txn.LocalTransaction.dequeue(LocalTransaction.java:110)
>                 at org.apache.qpid.server.queue.QueueEntryImpl.routeToAlternate(QueueEntryImpl.java:463)
>                 at org.apache.qpid.server.protocol.v0_8.AMQChannel.deadLetter(AMQChannel.java:1795)
>                 at org.apache.qpid.server.protocol.v0_8.AMQChannel.receiveBasicReject(AMQChannel.java:2431)
>                 at org.apache.qpid.framing.BasicRejectBody.process(BasicRejectBody.java:123)
>                 at org.apache.qpid.codec.ServerDecoder.processMethod(ServerDecoder.java:188)
>                 at org.apache.qpid.codec.AMQDecoder.processFrame(AMQDecoder.java:388)
>                 at org.apache.qpid.server.protocol.v0_8.BrokerDecoder.doProcessFrame(BrokerDecoder.java:113)
>                 at org.apache.qpid.server.protocol.v0_8.BrokerDecoder.access$000(BrokerDecoder.java:36)
>                 at org.apache.qpid.server.protocol.v0_8.BrokerDecoder$1.run(BrokerDecoder.java:79)
>                 at org.apache.qpid.server.protocol.v0_8.BrokerDecoder$1.run(BrokerDecoder.java:75)
>                 at java.security.AccessController.doPrivileged(Native Method)
>                 at javax.security.auth.Subject.doAs(Subject.java:415)
>                 at org.apache.qpid.server.protocol.v0_8.BrokerDecoder.processFrame(BrokerDecoder.java:74)
>                 at org.apache.qpid.codec.AMQDecoder.processInput(AMQDecoder.java:370)
>                 at org.apache.qpid.codec.AMQDecoder.decodeBuffer(AMQDecoder.java:259)
>                 at org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine$2.run(AMQProtocolEngine.java:334)
>                 at org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine$2.run(AMQProtocolEngine.java:311)
>                 at java.security.AccessController.doPrivileged(Native Method)
>                 at javax.security.auth.Subject.doAs(Subject.java:356)
>                 at org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine.received(AMQProtocolEngine.java:310)
>                 at org.apache.qpid.server.protocol.v0_8.AMQProtocolEngine.received(AMQProtocolEngine.java:95)
>                 at org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:153)
>                 at org.apache.qpid.server.protocol.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:51)
>                 at org.apache.qpid.transport.network.io.IoReceiver.run(IoReceiver.java:161)
>                 at java.lang.Thread.run(Thread.java:744)
> {code}



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org