qpid-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Keith Wall (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (QPID-8161) [Broker-J] [BDB] Broker failed due to lock timeout exception on MESSAGE_METADATA_SEQ
Date Thu, 12 Apr 2018 11:02:00 GMT

    [ 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-unsubscribe@qpid.apache.org
For additional commands, e-mail: dev-help@qpid.apache.org


Mime
View raw message