[
https://issues.apache.org/jira/browse/QPID-6809?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Keith Wall updated QPID-6809:
-----------------------------
Description:
A user using the Asynchronous Recovery (0.32) feature encountered the following
issue during a lengthy asynchronous recovery. This suggests that the Broker is
handling JE's LockException properly. In other parts of the code, the code
takes lengths to backoff/retry in the event of a locking exception.
{noformat}
2015-10-21 13:48:49,245 ERROR [Queue Recoverer : xxxx-xxxx (vh: default)]
org.apache.qpid.server.util.ServerScopedRuntimeException Unexpected exception
occurred on store operation
com.sleepycat.je.LockTimeoutException: (JE 5.0.104) Lock expired. Locker
1538378594 -1_Queue Recoverer : xxxx-xxxxx (vh: default)_ThreadLocker: waited
for lock on database=QUEUE_ENTRIES LockAddr:1973403125 LSN=0x9e7d/0x68098
type=READ grant=WAIT_NEW timeoutMillis=500 startTime=1445435328744
endTime=1445435329244
Owners: [<LockInfo locker="1886923901 215323278_IoReceiver -
/xxx.xxx.xxx.xx:59827_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.BasicLocker.lockInternal(BasicLocker.java:118)
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.fetchCurrent(CursorImpl.java:2272)
at
com.sleepycat.je.dbi.CursorImpl.getCurrentAlreadyLatched(CursorImpl.java:1480)
at com.sleepycat.je.dbi.CursorImpl.getNext(CursorImpl.java:1607)
at com.sleepycat.je.Cursor.retrieveNextAllowPhantoms(Cursor.java:3080)
at com.sleepycat.je.Cursor.retrieveNextNoDups(Cursor.java:2957)
at com.sleepycat.je.Cursor.retrieveNext(Cursor.java:2931)
at com.sleepycat.je.Cursor.getNext(Cursor.java:1148)
at
org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore.visitMessageInstances(AbstractBDBMessageStore.java:202)
at
org.apache.qpid.server.virtualhost.AsynchronousMessageStoreRecoverer$AsynchronousRecoverer.recoverQueue(AsynchronousMessageStoreRecoverer.java:145)
at
org.apache.qpid.server.virtualhost.AsynchronousMessageStoreRecoverer$AsynchronousRecoverer.access$900(AsynchronousMessageStoreRecoverer.java:81)
at
org.apache.qpid.server.virtualhost.AsynchronousMessageStoreRecoverer$AsynchronousRecoverer$QueueRecoveringTask.run(AsynchronousMessageStoreRecoverer.java:409)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
{noformat}
was:
By design, the {{ServerScopedRuntimeExceptions}} is intended to be fatal to the
Broker. If such an exception is thrown the Broker should always shutdown as
soon as possible so that the nature of the problem can be investigate.
A user using the Asynchronous Recovery (0.32) feature encountered the following
issue. Despite of the SSRTE, the Broker kept running, meaning that the error
went unnoticed.
{noformat}
2015-10-21 13:48:49,245 ERROR [Queue Recoverer : xxxx-xxxx (vh: default)]
org.apache.qpid.server.util.ServerScopedRuntimeException Unexpected exception
occurred on store operation
com.sleepycat.je.LockTimeoutException: (JE 5.0.104) Lock expired. Locker
1538378594 -1_Queue Recoverer : xxxx-xxxxx (vh: default)_ThreadLocker: waited
for lock on database=QUEUE_ENTRIES LockAddr:1973403125 LSN=0x9e7d/0x68098
type=READ grant=WAIT_NEW timeoutMillis=500 startTime=1445435328744
endTime=1445435329244
Owners: [<LockInfo locker="1886923901 215323278_IoReceiver -
/xxx.xxx.xxx.xx:59827_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.BasicLocker.lockInternal(BasicLocker.java:118)
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.fetchCurrent(CursorImpl.java:2272)
at
com.sleepycat.je.dbi.CursorImpl.getCurrentAlreadyLatched(CursorImpl.java:1480)
at com.sleepycat.je.dbi.CursorImpl.getNext(CursorImpl.java:1607)
at com.sleepycat.je.Cursor.retrieveNextAllowPhantoms(Cursor.java:3080)
at com.sleepycat.je.Cursor.retrieveNextNoDups(Cursor.java:2957)
at com.sleepycat.je.Cursor.retrieveNext(Cursor.java:2931)
at com.sleepycat.je.Cursor.getNext(Cursor.java:1148)
at
org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore.visitMessageInstances(AbstractBDBMessageStore.java:202)
at
org.apache.qpid.server.virtualhost.AsynchronousMessageStoreRecoverer$AsynchronousRecoverer.recoverQueue(AsynchronousMessageStoreRecoverer.java:145)
at
org.apache.qpid.server.virtualhost.AsynchronousMessageStoreRecoverer$AsynchronousRecoverer.access$900(AsynchronousMessageStoreRecoverer.java:81)
at
org.apache.qpid.server.virtualhost.AsynchronousMessageStoreRecoverer$AsynchronousRecoverer$QueueRecoveringTask.run(AsynchronousMessageStoreRecoverer.java:409)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:744)
{noformat}
> LockTimeoutExceptions not handled during asynchronous recovery
> --------------------------------------------------------------
>
> Key: QPID-6809
> URL: https://issues.apache.org/jira/browse/QPID-6809
> Project: Qpid
> Issue Type: Bug
> Components: Java Broker
> Affects Versions: 0.32
> Reporter: Keith Wall
>
> A user using the Asynchronous Recovery (0.32) feature encountered the
> following issue during a lengthy asynchronous recovery. This suggests that
> the Broker is handling JE's LockException properly. In other parts of the
> code, the code takes lengths to backoff/retry in the event of a locking
> exception.
> {noformat}
> 2015-10-21 13:48:49,245 ERROR [Queue Recoverer : xxxx-xxxx (vh: default)]
> org.apache.qpid.server.util.ServerScopedRuntimeException Unexpected exception
> occurred on store operation
> com.sleepycat.je.LockTimeoutException: (JE 5.0.104) Lock expired. Locker
> 1538378594 -1_Queue Recoverer : xxxx-xxxxx (vh: default)_ThreadLocker: waited
> for lock on database=QUEUE_ENTRIES LockAddr:1973403125 LSN=0x9e7d/0x68098
> type=READ grant=WAIT_NEW timeoutMillis=500 startTime=1445435328744
> endTime=1445435329244
> Owners: [<LockInfo locker="1886923901 215323278_IoReceiver -
> /xxx.xxx.xxx.xx:59827_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.BasicLocker.lockInternal(BasicLocker.java:118)
> 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.fetchCurrent(CursorImpl.java:2272)
> at
> com.sleepycat.je.dbi.CursorImpl.getCurrentAlreadyLatched(CursorImpl.java:1480)
> at com.sleepycat.je.dbi.CursorImpl.getNext(CursorImpl.java:1607)
> at com.sleepycat.je.Cursor.retrieveNextAllowPhantoms(Cursor.java:3080)
> at com.sleepycat.je.Cursor.retrieveNextNoDups(Cursor.java:2957)
> at com.sleepycat.je.Cursor.retrieveNext(Cursor.java:2931)
> at com.sleepycat.je.Cursor.getNext(Cursor.java:1148)
> at
> org.apache.qpid.server.store.berkeleydb.AbstractBDBMessageStore.visitMessageInstances(AbstractBDBMessageStore.java:202)
> at
> org.apache.qpid.server.virtualhost.AsynchronousMessageStoreRecoverer$AsynchronousRecoverer.recoverQueue(AsynchronousMessageStoreRecoverer.java:145)
> at
> org.apache.qpid.server.virtualhost.AsynchronousMessageStoreRecoverer$AsynchronousRecoverer.access$900(AsynchronousMessageStoreRecoverer.java:81)
> at
> org.apache.qpid.server.virtualhost.AsynchronousMessageStoreRecoverer$AsynchronousRecoverer$QueueRecoveringTask.run(AsynchronousMessageStoreRecoverer.java:409)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:744)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
