[QPID-8161] [Broker-J] [BDB] Broker failed due to lock timeout exception on MESSAGE_METADATA_SEQ

• Type: Bug
• Status: Open
• Priority: Major
• Resolution: Unresolved
• Affects Version/s: qpid-java-broker-7.0.3
• Component/s: Broker-J
• Assignee: Unassigned
• Reporter: Keith Wall
• Created: 12/Apr/18 10:12
• Updated: 18/Jul/21 19:57

Description

The following lock timeout exception occur during a connection establishment phase (client was an Qpid JMS AMQP 0-x client). The Broker treats this exception as fatal, so the Broker shut itself down.  No message loss would have occurred.

 

 

2018-04-12 04:17:00,412 ERROR [IO-/xxx.xx.xx.xx:54010] (o.a.q.s.Main) - Uncaught exception, shutting down.
org.apache.qpid.server.util.ServerScopedRuntimeException: org.apache.qpid.server.store.StoreException: Cannot get sequence value for new message
                at org.apache.qpid.server.protocol.v0_8.AMQPConnection_0_8Impl$1.run(AMQPConnection_0_8Impl.java:269)
                at org.apache.qpid.server.protocol.v0_8.AMQPConnection_0_8Impl$1.run(AMQPConnection_0_8Impl.java:249)
                at java.security.AccessController.doPrivileged(Native Method)
                at org.apache.qpid.server.protocol.v0_8.AMQPConnection_0_8Impl.received(AMQPConnection_0_8Impl.java:248)
                at org.apache.qpid.server.transport.MultiVersionProtocolEngine.received(MultiVersionProtocolEngine.java:135)
                at org.apache.qpid.server.transport.NonBlockingConnection.processAmqpData(NonBlockingConnection.java:610)
                at org.apache.qpid.server.transport.NonBlockingConnectionPlainDelegate.processData(NonBlockingConnectionPlainDelegate.java:58)
                at org.apache.qpid.server.transport.NonBlockingConnection.doRead(NonBlockingConnection.java:496)
                at org.apache.qpid.server.transport.NonBlockingConnection.doWork(NonBlockingConnection.java:270)
                at org.apache.qpid.server.transport.NetworkConnectionScheduler.processConnection(NetworkConnectionScheduler.java:134)
                at org.apache.qpid.server.transport.SelectorThread$ConnectionProcessor.processConnection(SelectorThread.java:575)
                at org.apache.qpid.server.transport.SelectorThread$SelectionTask.performSelect(SelectorThread.java:366)
                at org.apache.qpid.server.transport.SelectorThread$SelectionTask.run(SelectorThread.java:97)
                at org.apache.qpid.server.transport.SelectorThread.run(SelectorThread.java:533)
                at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
                at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
                at org.apache.qpid.server.bytebuffer.QpidByteBufferFactory.lambda$null$0(QpidByteBufferFactory.java:464)
                at java.lang.Thread.run(Thread.java:745)
Caused by: org.apache.qpid.server.store.StoreException: Cannot get sequence value for new message
                at org.apache.qpid.server.store.berkeleydb.StandardEnvironmentFacade.handleDatabaseException(StandardEnvironmentFacade.java:447)
                at org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore.getNextMessageId(AbstractBDBMessageStore.java:158)
                at org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore.addMessage(AbstractBDBMessageStore.java:128)
                at org.apache.qpid.server.message.internal.InternalMessage.createMessage(InternalMessage.java:165)
                at org.apache.qpid.server.message.internal.InternalMessage.createBytesMessage(InternalMessage.java:209)
                at org.apache.qpid.server.message.internal.InternalMessage.createBytesMessage(InternalMessage.java:203)
                at org.apache.qpid.server.virtualhost.VirtualHostPropertiesNode.createMessage(VirtualHostPropertiesNode.java:89)
                at org.apache.qpid.server.virtualhost.VirtualHostPropertiesNode.addConsumer(VirtualHostPropertiesNode.java:59)
                at org.apache.qpid.server.virtualhost.VirtualHostPropertiesNode.addConsumer(VirtualHostPropertiesNode.java:37)
                at org.apache.qpid.server.protocol.v0_8.AMQChannel.consumeFromSource(AMQChannel.java:683)
                at org.apache.qpid.server.protocol.v0_8.AMQChannel.receiveBasicConsume(AMQChannel.java:1796)
                at org.apache.qpid.server.protocol.v0_8.transport.BasicConsumeBody.process(BasicConsumeBody.java:208)
                at org.apache.qpid.server.protocol.v0_8.ServerDecoder.processMethod(ServerDecoder.java:182)
                at org.apache.qpid.server.protocol.v0_8.AMQDecoder.processFrame(AMQDecoder.java:203)
                at org.apache.qpid.server.protocol.v0_8.BrokerDecoder.doProcessFrame(BrokerDecoder.java:141)
                at org.apache.qpid.server.protocol.v0_8.BrokerDecoder.processFrame(BrokerDecoder.java:65)
                at org.apache.qpid.server.protocol.v0_8.AMQDecoder.processInput(AMQDecoder.java:185)
                at org.apache.qpid.server.protocol.v0_8.BrokerDecoder$1.run(BrokerDecoder.java:104)
                at org.apache.qpid.server.protocol.v0_8.BrokerDecoder$1.run(BrokerDecoder.java:97)
                at java.security.AccessController.doPrivileged(Native Method)
                at org.apache.qpid.server.protocol.v0_8.BrokerDecoder.processAMQPFrames(BrokerDecoder.java:96)
                at org.apache.qpid.server.protocol.v0_8.AMQDecoder.decode(AMQDecoder.java:118)
                at org.apache.qpid.server.protocol.v0_8.ServerDecoder.decodeBuffer(ServerDecoder.java:44)
                at org.apache.qpid.server.protocol.v0_8.AMQPConnection_0_8Impl$1.run(AMQPConnection_0_8Impl.java:257)
                ... 17 common frames omitted
Caused by: com.sleepycat.je.LockTimeoutException: (JE 7.4.5) Lock expired. Locker 1014771653 -1_IO-/xxx.xx.xx.xx:54010_ThreadLocker: waited for lock on database=MESSAGE_METADATA.SEQ LockAddr:131624795 LSN=0x1bb/0x27892f type=READ grant=WAIT_NEW timeoutMillis=500 startTime=1523520994484 endTime=1523520995016
Owners: [<LockInfo locker="1070453463 11876631_IO-/xxx.xx.xx.xx:53770_Txn" type="WRITE"/>]
Waiters: [<LockInfo locker="1014771653 -1_IO-/xxx.xx.xx.xx:54010_ThreadLocker" type="READ"/>, <LockInfo locker="1147831496 -1_IO-/xxx.xx.xx.xx:54062_ThreadLocker" type="READ"/>]
 
                at com.sleepycat.je.txn.LockManager.makeTimeoutException(LockManager.java:1117)
                at com.sleepycat.je.txn.LockManager.waitForLock(LockManager.java:606)
                at com.sleepycat.je.txn.LockManager.lock(LockManager.java:345)
                at com.sleepycat.je.txn.BasicLocker.lockInternal(BasicLocker.java:124)
                at com.sleepycat.je.txn.Locker.lock(Locker.java:499)
                at com.sleepycat.je.dbi.CursorImpl.lockLN(CursorImpl.java:3641)
                at com.sleepycat.je.dbi.CursorImpl.lockLN(CursorImpl.java:3372)
                at com.sleepycat.je.dbi.CursorImpl.lockLNAndCheckDefunct(CursorImpl.java:2156)
                at com.sleepycat.je.dbi.CursorImpl.searchExact(CursorImpl.java:1968)
                at com.sleepycat.je.Cursor.searchExact(Cursor.java:4195)
                at com.sleepycat.je.Cursor.searchNoDups(Cursor.java:4056)
                at com.sleepycat.je.Cursor.search(Cursor.java:3858)
                at com.sleepycat.je.Cursor.getInternal(Cursor.java:1282)
                at com.sleepycat.je.Cursor.get(Cursor.java:1238)
                at com.sleepycat.je.Cursor.getSearchKey(Cursor.java:2004)
                at com.sleepycat.je.Sequence.readData(Sequence.java:546)
                at com.sleepycat.je.Sequence.<init>(Sequence.java:150)
                at com.sleepycat.je.Database.openSequence(Database.java:830)
                at org.apache.qpid.server.store.berkeleydb.StandardEnvironmentFacade.openSequence(StandardEnvironmentFacade.java:488)
                at org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore.getNextMessageId(AbstractBDBMessageStore.java:151)
                ... 39 common frames omitted