[
https://issues.apache.org/jira/browse/QPID-8161?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16435350#comment-16435350
]
Keith Wall edited comment on QPID-8161 at 4/12/18 11:01 AM:
------------------------------------------------------------
In the case of this problem, the Broker had been up for two hours before the
failure occurred, and had successfully established many AMQP 0-x messaging
connection. I conclude from that the {{MESSAGE_METADATA_SEQ}} sequence must
have been initialised and placed in the CHM. The message store only ever uses
a single sequence value, and this sequence is created and cached on first use,
and then the same sequence value remains in use until the store is closed. In
this case, there is no evidence that the Broker or Virtualhost was being
closed, so I cannot explain how following CHM lookup
\{{StandardEnvironmentFacade.java:485}} can have ever return null, so I cannot
explain why the sequence was being recreated.
{code:java}
Sequence cachedSequence = _cachedSequences.get(sequenceKey);{code}
The sequence caching was done by QPID-5801 (0.30).
was (Author: k-wall):
In the case of this problem, the Broker had been up for two hours before the
failure occurred, and had successfully established many AMQP 0-x messaging
connection. I conclude from that the {{MESSAGE_METADATA_SEQ}} sequence must
have been initialised and placed in the CHM. The message store only ever uses
a single sequence value, and this sequence is created and cached on first use,
and then the same sequence value remains in use until the store is closed. In
this case, there is no evidence that the Broker or Virtualhost was being
closed, so I cannot explain how following CHM lookup
{{StandardEnvironmentFacade.java:485 }}can have ever return null, so I cannot
explain why the sequence was being recreated.
{code:java}
Sequence cachedSequence = _cachedSequences.get(sequenceKey);{code}
The sequence caching was done by QPID-5801 (0.30).
> [Broker-J] [BDB] Broker failed due to lock timeout exception on
> MESSAGE_METADATA_SEQ
> ------------------------------------------------------------------------------------
>
> Key: QPID-8161
> URL: https://issues.apache.org/jira/browse/QPID-8161
> Project: Qpid
> Issue Type: Bug
> Components: Broker-J
> Affects Versions: qpid-java-broker-7.0.3
> Reporter: Keith Wall
> Priority: Major
>
> 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.
>
>
> {code:java}
> 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{code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@qpid.apache.org
For additional commands, e-mail: dev-h...@qpid.apache.org
