[Red Hat JIRA] (ISPN-12468) Prevent from unnecessary WARN messages ISPN000299 to acquire a lock for expiration handling
11:29 a.m.
[
https://issues.redhat.com/browse/ISPN-12468?page=com.atlassian.jira.plugi...
]
Dan Berindei commented on ISPN-12468:
-------------------------------------
On the node where the lock acquisition failed, the lock acquisition timeout is also logged
as an ERROR in addition to the WARN message in the description:
{noformat}
12:52:27,364+0100 ERROR [org.infinispan.interceptors.impl.InvocationContextInterceptor]
(expiration-thread--p5-t1) ISPN000136: Error executing command RemoveExpiredCommand on
Cache 'PACS008_ACTIVATOR', writing keys
[[4619b98805e540c3a39cfb3b377aa0e3|BARRIT26|2021-02-05T12:50:49.570646+01:00]]:
org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire lock after
0 milliseconds for key
[4619b98805e540c3a39cfb3b377aa0e3|BARRIT26|2021-02-05T12:50:49.570646+01:00] and requestor
GlobalTransaction{id=185255, addr=ebaipm1tpbe91-48322, remote=false, xid=null,
internalId=-1}. Lock is held by GlobalTransaction{id=183703, addr=ebaipm1tpbe91-48322,
remote=false, xid=null, internalId=-1}
at
org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.get(DefaultLockManager.java:292)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.get(DefaultLockManager.java:222)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.checkState(InfinispanLock.java:440)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.util.concurrent.locks.impl.InfinispanLock$LockPlaceHolder.toInvocationStage(InfinispanLock.java:412)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.toInvocationStage(DefaultLockManager.java:252)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.toInvocationStage(DefaultLockManager.java:276)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.locking.AbstractLockingInterceptor.lockAndRecord(AbstractLockingInterceptor.java:277)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.checkPendingAndLockKey(AbstractTxLockingInterceptor.java:137)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.locking.AbstractTxLockingInterceptor.lockOrRegisterBackupLock(AbstractTxLockingInterceptor.java:65)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.locking.PessimisticLockingInterceptor.acquireLocalLock(PessimisticLockingInterceptor.java:92)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.locking.PessimisticLockingInterceptor.acquireLocalLockAndInvokeNext(PessimisticLockingInterceptor.java:285)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.locking.PessimisticLockingInterceptor.visitDataWriteCommand(PessimisticLockingInterceptor.java:150)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitRemoveCommand(AbstractLockingInterceptor.java:102)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at org.infinispan.commands.Visitor.visitRemoveExpiredCommand(Visitor.java:64)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.commands.write.RemoveExpiredCommand.acceptVisitor(RemoveExpiredCommand.java:46)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.BaseAsyncInterceptor.invokeNextAndFinally(BaseAsyncInterceptor.java:155)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.impl.TxInterceptor.handleWriteCommand(TxInterceptor.java:394)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.impl.TxInterceptor.visitRemoveCommand(TxInterceptor.java:232)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at org.infinispan.commands.Visitor.visitRemoveExpiredCommand(Visitor.java:64)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.commands.write.RemoveExpiredCommand.acceptVisitor(RemoveExpiredCommand.java:46)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.BaseAsyncInterceptor.invokeNext(BaseAsyncInterceptor.java:59)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.DDAsyncInterceptor.handleDefault(DDAsyncInterceptor.java:53)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.partitionhandling.impl.PartitionHandlingInterceptor.handleSingleWrite(PartitionHandlingInterceptor.java:89)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.partitionhandling.impl.PartitionHandlingInterceptor.visitRemoveCommand(PartitionHandlingInterceptor.java:62)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at org.infinispan.commands.Visitor.visitRemoveExpiredCommand(Visitor.java:64)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.commands.write.RemoveExpiredCommand.acceptVisitor(RemoveExpiredCommand.java:46)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.BaseAsyncInterceptor.invokeNext(BaseAsyncInterceptor.java:59)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitCommand(TransactionSynchronizerInterceptor.java:41)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.BaseAsyncInterceptor.invokeNextAndHandle(BaseAsyncInterceptor.java:190)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.statetransfer.StateTransferInterceptor.handleTxWriteCommand(StateTransferInterceptor.java:259)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.statetransfer.StateTransferInterceptor.handleWriteCommand(StateTransferInterceptor.java:249)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.statetransfer.StateTransferInterceptor.visitRemoveCommand(StateTransferInterceptor.java:108)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at org.infinispan.commands.Visitor.visitRemoveExpiredCommand(Visitor.java:64)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.commands.write.RemoveExpiredCommand.acceptVisitor(RemoveExpiredCommand.java:46)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.BaseAsyncInterceptor.invokeNextAndFinally(BaseAsyncInterceptor.java:155)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.impl.CacheMgmtInterceptor.visitRemoveCommand(CacheMgmtInterceptor.java:484)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at org.infinispan.commands.Visitor.visitRemoveExpiredCommand(Visitor.java:64)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.commands.write.RemoveExpiredCommand.acceptVisitor(RemoveExpiredCommand.java:46)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.BaseAsyncInterceptor.invokeNextAndExceptionally(BaseAsyncInterceptor.java:128)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.impl.InvocationContextInterceptor.visitCommand(InvocationContextInterceptor.java:90)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.BaseAsyncInterceptor.invokeNext(BaseAsyncInterceptor.java:61)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.DDAsyncInterceptor.handleDefault(DDAsyncInterceptor.java:53)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.DDAsyncInterceptor.visitRemoveCommand(DDAsyncInterceptor.java:64)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at org.infinispan.commands.Visitor.visitRemoveExpiredCommand(Visitor.java:64)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.commands.write.RemoveExpiredCommand.acceptVisitor(RemoveExpiredCommand.java:46)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.DDAsyncInterceptor.visitCommand(DDAsyncInterceptor.java:49)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invokeAsync(AsyncInterceptorChainImpl.java:226)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at org.infinispan.cache.impl.InvocationHelper.doInvokeAsync(InvocationHelper.java:293)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.cache.impl.InvocationHelper.executeCommandAsyncWithInjectedTx(InvocationHelper.java:219)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at org.infinispan.cache.impl.InvocationHelper.invokeAsync(InvocationHelper.java:146)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at org.infinispan.cache.impl.CacheImpl.performRemoveExpiredCommand(CacheImpl.java:719)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at org.infinispan.cache.impl.CacheImpl.removeLifespanExpired(CacheImpl.java:700)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.cache.impl.DecoratedCache.removeLifespanExpired(DecoratedCache.java:415)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.expiration.impl.ClusterExpirationManager.removeLifespan(ClusterExpirationManager.java:244)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.expiration.impl.ClusterExpirationManager.handleEitherExpiration(ClusterExpirationManager.java:268)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.expiration.impl.ClusterExpirationManager.handleLifespanExpireEntry(ClusterExpirationManager.java:240)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.expiration.impl.ClusterExpirationManager.purgeInMemoryContents(ClusterExpirationManager.java:159)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
at
org.infinispan.expiration.impl.ClusterExpirationManager.processExpiration(ClusterExpirationManager.java:100)
[infinispan-core-11.0.9.Final-redhat-00001.jar:11.0.9.Final-redhat-00001]
{noformat}
Prevent from unnecessary WARN messages ISPN000299 to acquire a lock
for expiration handling
-------------------------------------------------------------------------------------------
Key: ISPN-12468
URL: https://issues.redhat.com/browse/ISPN-12468
Project: Infinispan
Issue Type: Enhancement
Components: Core
Affects Versions: 12.0.0.Dev05
Reporter: Wolf-Dieter Fink
Priority: Minor
If locking will fail to remove expired entries this can be ignored, but the WARN message
with stacktrace is confusing for the user and might fill the logfile.
So the following exception should be at DEBUG level if the cause is expiration
{noformat}
WARN [org.infinispan.persistence.manager.PersistenceManagerImpl] (pool-14-thread-1)
ISPN000026: Caught exception purging data container!:
java.util.concurrent.CompletionException: org.infinispan.remoting.RemoteException:
ISPN000217: Received exception from node2, see cause for remote stack trace
at org.infinispan.util.concurrent.CompletionStages.join(CompletionStages.java:83)
at
org.infinispan.expiration.impl.InternalExpirationManager.handleInStoreExpiration(InternalExpirationManager.java:60)
...
Caused by: org.infinispan.remoting.RemoteException: ISPN000217: Received exception from
node2, see cause for remote stack trace
at
org.infinispan.remoting.transport.ResponseCollectors.wrapRemoteException(ResponseCollectors.java:28)
at
org.infinispan.remoting.transport.ValidSingleResponseCollector.withException(ValidSingleResponseCollector.java:37)
at
org.infinispan.remoting.transport.ValidSingleResponseCollector.addResponse(ValidSingleResponseCollector.java:21)
at
org.infinispan.remoting.transport.impl.SingleTargetRequest.receiveResponse(SingleTargetRequest.java:52)
at
org.infinispan.remoting.transport.impl.SingleTargetRequest.onResponse(SingleTargetRequest.java:35)
at
org.infinispan.remoting.transport.impl.RequestRepository.addResponse(RequestRepository.java:52)
at
org.infinispan.remoting.transport.jgroups.JGroupsTransport.processResponse(JGroupsTransport.java:1380)
...
Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000299: Unable to acquire
lock after 0 milliseconds for key WrappedByteArray\{bytes=[B0x0..[], hashCode=-123} and
requestor CommandInvocation:node2. Lock is held by CommandInvocation:node1:12720556
at
org.infinispan.util.concurrent.locks.impl.DefaultLockManager$KeyAwareExtendedLockPromise.get(DefaultLockManager.java:288)
...
at org.infinispan.commands.Visitor.visitRemoveExpiredCommand(Visitor.java:66)
... more
{noformat}
--
This message was sent by Atlassian Jira
(v8.13.1#813001)
1413
days inactive
1413
days old
infinispan-issues@lists.jboss.org
0 comments
1 participants
participants (1)
-
Dan Berindei (Jira)