REPL_SYNC value not found issue
vbalaut Sep 26, 2013 6:17 AMI am not getting data when 1 thread is trying to insert the record and another thread is trying to get the same record from cache which is REPL_SYNC. i have tried with other cahce option like LOCAL, DIST_ASYNC, REPL_ASYNC ant all is working fine.
Sudo code
1. Thread 1 is trying to acquire lock on distLockCache(REPL_SYNC cache)
tm.begin();
distLockCache.getAdvancedCache().lock(getLockKey());
distLockCache.put(getLockKey(), getLockKey());
2. Thread 1 is checking if value v1 present in replCache (REPL_SYNC Cache)
3. Thread 1 did not find value v1 in cache and putting v1 in cache.
if (!replCache.containsKey(id)) {
replCache.put(id, "");
break;
}
4. Thread 1 release Lock on distLockCache(REPL_SYNC cache)
5. Thread 2 is checking if value v1 present in replCache (REPL_SYNC Cache)
6. Thread 2 did not find value v1 in cache and putting v1 in cache. where as Thread2 should find value in cache and should not put the value again.
Cache Configuration is following
EmbeddedCacheManager cacheManager =
new DefaultCacheManager(GlobalConfigurationBuilder
.defaultClusteredBuilder().transport()
.addProperty("configurationFile", "jgroups.xml")
.build(), new ConfigurationBuilder()
.clustering()
.cacheMode(CacheMode.REPL_SYNC)
.transaction().useSynchronization(true)
.transactionMode(TransactionMode.TRANSACTIONAL)
.transactionManagerLookup(
new GenericTransactionManagerLookup())
.lockingMode(LockingMode.PESSIMISTIC).locking().lockAcquisitionTimeout(1 * 60 * 60 * 1000)
// .isolationLevel(IsolationLevel.READ_COMMITTED)
.build());
i have used 5.1.6, 5.3.0 and 6.0.0 and everywhere i found same issue.
Any help will be helpful and appreciated.
Trac log if can be useful
2013-09-2512:43:58 [Thread-2] DEBUG [com.threadissue.infinispan.DistributedTaskLock] lock acquired now trying to execute task TASK10234
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.interceptors.InvocationContextInterceptor] Invoked with command GetKeyValueCommand {key=1001, flags=null} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@5273bd7]
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.statetransfer.StateTransferInterceptor] handleTopologyAffectedCommand for command GetKeyValueCommand {key=1001, flags=null}
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.transaction.TransactionTable] Created a new local transaction: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@6
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.transaction.tm.DummyTransaction] registering synchronization handler SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@6} org.infinispan.transaction.synchronization.SynchronizationAdapter@25
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.container.EntryFactoryImpl] Exists in context? null
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.container.EntryFactoryImpl] Retrieved from container null
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.container.EntryFactoryImpl] Wrap 1001 for read. Entry=null
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.interceptors.CallInterceptor] Executing command: GetKeyValueCommand {key=1001, flags=null}.
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.commands.read.GetKeyValueCommand] Entry not found
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.interceptors.distribution.BaseDistributionInterceptor] Not doing a remote get for key 1001 since entry is mapped to current node (pnq-vbalaut-64165) or is in L1. Owners are [pnq-vbalaut-64165]
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.statetransfer.StateTransferManagerImpl] CommandTopologyId=0, localTopologyId=0
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.interceptors.InvocationContextInterceptor] Invoked with command PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@52c9a2e5]
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.statetransfer.StateTransferInterceptor] handleTopologyAffectedCommand for command PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.interceptors.locking.PessimisticLockingInterceptor] Locking key 1001, no need to check for pending locks.
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] Attempting to lock 1001 with acquisition timeout of 3600000 millis
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.util.concurrent.locks.containers.OwnableReentrantPerEntryLockContainer] Creating and acquiring new lock instance for key 1001
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] Successfully acquired lock 1001!
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.transaction.AbstractCacheTransaction] Registering locked key: 1001
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] Wrapping entry '1001'? true
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.container.EntryFactoryImpl] Exists in context? null
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.container.EntryFactoryImpl] Retrieved from container null
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.container.EntryFactoryImpl] Creating new entry.
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.container.EntryFactoryImpl] Wrap 1001 for put. Entry=ReadCommittedEntry(33e592d9){key=1001, value=null, oldValue=null, isCreated=true, isChanged=false, isRemoved=false, isValid=true, skipRemoteGet=false, metadata=EmbeddedMetadata{version=null}}
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.interceptors.distribution.TxDistributionInterceptor] Not doing a remote get for key 1001 since entry is mapped to current node (pnq-vbalaut-64165), or is in L1. Owners are [pnq-vbalaut-64165]
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.interceptors.CallInterceptor] Executing command: PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}.
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] The return value is null
2013-09-2512:43:58 [Thread-2] TRACE [org.infinispan.transaction.LocalTransaction] Adding modification PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}. Mod list is null
2013-09-2512:43:59 [Thread-2] DEBUG [com.threadissue.infinispan.DistributedTaskLock] TASK10234 executed under lock...
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.tm.DummyTransaction] processing beforeCompletion for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@1} org.infinispan.transaction.synchronization.SynchronizationAdapter@20
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.synchronization.SynchronizationAdapter] beforeCompletion called for LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@1
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.TransactionCoordinator] Received prepare for tx: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@1. Skipping call as 1PC will be used.
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.tm.DummyTransaction] processing beforeCompletion for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[1001], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@6} org.infinispan.transaction.synchronization.SynchronizationAdapter@25
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.synchronization.SynchronizationAdapter] beforeCompletion called for LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[1001], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@6
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.TransactionCoordinator] Received prepare for tx: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[1001], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@6. Skipping call as 1PC will be used.
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.tm.DummyTransaction] processing afterCompletion for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@1} org.infinispan.transaction.synchronization.SynchronizationAdapter@20
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.synchronization.SynchronizationAdapter] afterCompletion(3) called for LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@1.
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.TransactionCoordinator] Committing transaction GlobalTransaction:<pnq-vbalaut-64165>:1:local
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.TransactionCoordinator] Doing an 1PC prepare call on the interceptor chain
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.interceptors.InvocationContextInterceptor] Invoked with command PrepareCommand {modifications=[PutKeyValueCommand{key=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, value=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:1:local, cacheName='DIST_LOCK', topologyId=-1} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@42da831e]
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.statetransfer.StateTransferInterceptor] handleTopologyAffectedCommand for command PrepareCommand {modifications=[PutKeyValueCommand{key=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, value=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:1:local, cacheName='DIST_LOCK', topologyId=-1}
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.interceptors.CallInterceptor] Suppressing invocation of method handlePrepareCommand.
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.interceptors.distribution.BaseDistributionInterceptor] Should invoke remotely? true. hasModifications=true, hasRemoteLocksAcquired=false
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] pnq-vbalaut-64165 invoking PrepareCommand {modifications=[PutKeyValueCommand{key=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, value=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:1:local, cacheName='DIST_LOCK', topologyId=0} to recipient list [pnq-vbalaut-64165] with options RpcOptions{timeout=15000, unit=MILLISECONDS, fifoOrder=false, totalOrder=false, responseFilter=null, responseMode=SYNCHRONOUS_IGNORE_LEAVERS, skipReplicationQueue=false}
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.remoting.transport.jgroups.JGroupsTransport] dests=[pnq-vbalaut-64165], command=PrepareCommand {modifications=[PutKeyValueCommand{key=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, value=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:1:local, cacheName='DIST_LOCK', topologyId=0}, mode=SYNCHRONOUS_IGNORE_LEAVERS, timeout=15000
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] Response(s) to PrepareCommand {modifications=[PutKeyValueCommand{key=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, value=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:1:local, cacheName='DIST_LOCK', topologyId=0} is {}
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.LocalTransaction] Adding remote locks on [pnq-vbalaut-64165]. Remote locks are null
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] About to commit entry ReadCommittedEntry(143f29ee){key=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, value=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, oldValue=null, isCreated=true, isChanged=true, isRemoved=false, isValid=true, skipRemoteGet=false, metadata=EmbeddedMetadata{version=null}}
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.container.entries.ReadCommittedEntry] Updating entry (key=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock removed=false valid=true changed=true created=true loaded=false value=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock metadata=EmbeddedMetadata{version=null})
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] Attempting to unlock com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.util.concurrent.locks.containers.OwnableReentrantPerEntryLockContainer] Unlocking lock instance for key com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.AbstractCacheTransaction] Clearing locked keys: [com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock]
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.interceptors.TxInterceptor] invokeNextInterceptorAndVerifyTransaction :: originatorMissing=false, alreadyCompleted=false
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.statetransfer.StateTransferManagerImpl] CommandTopologyId=0, localTopologyId=0
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.TransactionTable] Removed LocalTransaction{remoteLockedNodes=[pnq-vbalaut-64165], isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@1 from transaction table.
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.AbstractCacheTransaction] Transaction GlobalTransaction:<pnq-vbalaut-64165>:1:local has completed, notifying listening threads.
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.AbstractEnlistmentAdapter] Committed in onePhase? true isOptimistic? false
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.LocalTransaction] getCommitNodes recipients=null, currentTopologyId=0, members=[pnq-vbalaut-64165], txTopologyId=0
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.AbstractEnlistmentAdapter] About to invoke tx completion notification on commitNodes: null
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] pnq-vbalaut-64165 invoking TxCompletionNotificationCommand{ xid=null, internalId=0, topologyId=-1, gtx=GlobalTransaction:<pnq-vbalaut-64165>:1:local, cacheName=DIST_LOCK} to recipient list null with options RpcOptions{timeout=15000, unit=MILLISECONDS, fifoOrder=false, totalOrder=false, responseFilter=null, responseMode=ASYNCHRONOUS_WITH_SYNC_MARSHALLING, skipReplicationQueue=false}
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.remoting.transport.jgroups.JGroupsTransport] dests=null, command=TxCompletionNotificationCommand{ xid=null, internalId=0, topologyId=0, gtx=GlobalTransaction:<pnq-vbalaut-64165>:1:local, cacheName=DIST_LOCK} , mode=ASYNCHRONOUS_WITH_SYNC_MARSHALLING, timeout=15000
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] Response(s) to TxCompletionNotificationCommand{ xid=null, internalId=0, topologyId=0, gtx=GlobalTransaction:<pnq-vbalaut-64165>:1:local, cacheName=DIST_LOCK} is {}
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.tm.DummyTransaction] processing afterCompletion for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[1001], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@6} org.infinispan.transaction.synchronization.SynchronizationAdapter@25
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.synchronization.SynchronizationAdapter] afterCompletion(3) called for LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[1001], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@6.
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.TransactionCoordinator] Committing transaction GlobalTransaction:<pnq-vbalaut-64165>:6:local
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.TransactionCoordinator] Doing an 1PC prepare call on the interceptor chain
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.interceptors.InvocationContextInterceptor] Invoked with command PrepareCommand {modifications=[PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:6:local, cacheName='METRIC_SCORECARD', topologyId=-1} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@7f8caa19]
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.statetransfer.StateTransferInterceptor] handleTopologyAffectedCommand for command PrepareCommand {modifications=[PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:6:local, cacheName='METRIC_SCORECARD', topologyId=-1}
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.interceptors.CallInterceptor] Suppressing invocation of method handlePrepareCommand.
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.interceptors.distribution.BaseDistributionInterceptor] Should invoke remotely? true. hasModifications=true, hasRemoteLocksAcquired=false
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] pnq-vbalaut-64165 invoking PrepareCommand {modifications=[PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:6:local, cacheName='METRIC_SCORECARD', topologyId=0} to recipient list [pnq-vbalaut-64165] with options RpcOptions{timeout=15000, unit=MILLISECONDS, fifoOrder=false, totalOrder=false, responseFilter=null, responseMode=SYNCHRONOUS_IGNORE_LEAVERS, skipReplicationQueue=false}
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.remoting.transport.jgroups.JGroupsTransport] dests=[pnq-vbalaut-64165], command=PrepareCommand {modifications=[PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:6:local, cacheName='METRIC_SCORECARD', topologyId=0}, mode=SYNCHRONOUS_IGNORE_LEAVERS, timeout=15000
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] Response(s) to PrepareCommand {modifications=[PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:6:local, cacheName='METRIC_SCORECARD', topologyId=0} is {}
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.LocalTransaction] Adding remote locks on [pnq-vbalaut-64165]. Remote locks are null
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] About to commit entry ReadCommittedEntry(33e592d9){key=1001, value=, oldValue=null, isCreated=true, isChanged=true, isRemoved=false, isValid=true, skipRemoteGet=false, metadata=EmbeddedMetadata{version=null}}
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.container.entries.ReadCommittedEntry] Updating entry (key=1001 removed=false valid=true changed=true created=true loaded=false value= metadata=EmbeddedMetadata{version=null})
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] Attempting to unlock 1001
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.util.concurrent.locks.containers.OwnableReentrantPerEntryLockContainer] Unlocking lock instance for key 1001
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.AbstractCacheTransaction] Clearing locked keys: [1001]
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.interceptors.TxInterceptor] invokeNextInterceptorAndVerifyTransaction :: originatorMissing=false, alreadyCompleted=false
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.statetransfer.StateTransferManagerImpl] CommandTopologyId=0, localTopologyId=0
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.TransactionTable] Removed LocalTransaction{remoteLockedNodes=[pnq-vbalaut-64165], isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@6 from transaction table.
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.AbstractCacheTransaction] Transaction GlobalTransaction:<pnq-vbalaut-64165>:6:local has completed, notifying listening threads.
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.AbstractEnlistmentAdapter] Committed in onePhase? true isOptimistic? false
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.LocalTransaction] getCommitNodes recipients=null, currentTopologyId=0, members=[pnq-vbalaut-64165], txTopologyId=0
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.transaction.AbstractEnlistmentAdapter] About to invoke tx completion notification on commitNodes: null
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] pnq-vbalaut-64165 invoking TxCompletionNotificationCommand{ xid=null, internalId=0, topologyId=-1, gtx=GlobalTransaction:<pnq-vbalaut-64165>:6:local, cacheName=METRIC_SCORECARD} to recipient list null with options RpcOptions{timeout=15000, unit=MILLISECONDS, fifoOrder=false, totalOrder=false, responseFilter=null, responseMode=ASYNCHRONOUS_WITH_SYNC_MARSHALLING, skipReplicationQueue=false}
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.remoting.transport.jgroups.JGroupsTransport] dests=null, command=TxCompletionNotificationCommand{ xid=null, internalId=0, topologyId=0, gtx=GlobalTransaction:<pnq-vbalaut-64165>:6:local, cacheName=METRIC_SCORECARD} , mode=ASYNCHRONOUS_WITH_SYNC_MARSHALLING, timeout=15000
2013-09-2512:43:59 [Thread-2] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] Response(s) to TxCompletionNotificationCommand{ xid=null, internalId=0, topologyId=0, gtx=GlobalTransaction:<pnq-vbalaut-64165>:6:local, cacheName=METRIC_SCORECARD} is {}
2013-09-2512:43:59 [Thread-2] DEBUG [com.threadissue.infinispan.DistributedTaskLock] Lock com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock released after executing TASK10234
2013-09-2512:43:59 [Thread-5] DEBUG [com.threadissue.infinispan.DistributedTaskLock] lock acquired now trying to execute task TASK10234
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.interceptors.InvocationContextInterceptor] Invoked with command GetKeyValueCommand {key=1001, flags=null} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@6e79d110]
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.statetransfer.StateTransferInterceptor] handleTopologyAffectedCommand for command GetKeyValueCommand {key=1001, flags=null}
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.transaction.TransactionTable] Created a new local transaction: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@7
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.transaction.tm.DummyTransaction] registering synchronization handler SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@7} org.infinispan.transaction.synchronization.SynchronizationAdapter@26
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.container.EntryFactoryImpl] Exists in context? null
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.container.EntryFactoryImpl] Retrieved from container null
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.container.EntryFactoryImpl] Wrap 1001 for read. Entry=null
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.interceptors.CallInterceptor] Executing command: GetKeyValueCommand {key=1001, flags=null}.
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.commands.read.GetKeyValueCommand] Entry not found
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.interceptors.distribution.BaseDistributionInterceptor] Not doing a remote get for key 1001 since entry is mapped to current node (pnq-vbalaut-64165) or is in L1. Owners are [pnq-vbalaut-64165]
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.statetransfer.StateTransferManagerImpl] CommandTopologyId=0, localTopologyId=0
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.interceptors.InvocationContextInterceptor] Invoked with command PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@78c4821c]
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.statetransfer.StateTransferInterceptor] handleTopologyAffectedCommand for command PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.interceptors.locking.PessimisticLockingInterceptor] Locking key 1001, no need to check for pending locks.
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] Attempting to lock 1001 with acquisition timeout of 3600000 millis
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.util.concurrent.locks.containers.OwnableReentrantPerEntryLockContainer] Creating and acquiring new lock instance for key 1001
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] Successfully acquired lock 1001!
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.transaction.AbstractCacheTransaction] Registering locked key: 1001
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] Wrapping entry '1001'? true
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.container.EntryFactoryImpl] Exists in context? null
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.container.EntryFactoryImpl] Retrieved from container ImmortalCacheEntry{key=1001, value=}
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.container.EntryFactoryImpl] Wrap 1001 for put. Entry=ReadCommittedEntry(49c384c5){key=1001, value=, oldValue=, isCreated=false, isChanged=false, isRemoved=false, isValid=true, skipRemoteGet=false, metadata=EmbeddedMetadata{version=null}}
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.interceptors.distribution.TxDistributionInterceptor] Not doing a remote get for key 1001 since entry is mapped to current node (pnq-vbalaut-64165), or is in L1. Owners are [pnq-vbalaut-64165]
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.interceptors.CallInterceptor] Executing command: PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}.
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] The return value is
2013-09-2512:43:59 [Thread-5] TRACE [org.infinispan.transaction.LocalTransaction] Adding modification PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}. Mod list is null
2013-09-2512:44:00 [Thread-5] DEBUG [com.threadissue.infinispan.DistributedTaskLock] TASK10234 executed under lock...
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.tm.DummyTransaction] processing beforeCompletion for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@4} org.infinispan.transaction.synchronization.SynchronizationAdapter@23
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.synchronization.SynchronizationAdapter] beforeCompletion called for LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@4
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.TransactionCoordinator] Received prepare for tx: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@4. Skipping call as 1PC will be used.
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.tm.DummyTransaction] processing beforeCompletion for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[1001], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@7} org.infinispan.transaction.synchronization.SynchronizationAdapter@26
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.synchronization.SynchronizationAdapter] beforeCompletion called for LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[1001], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@7
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.TransactionCoordinator] Received prepare for tx: LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[1001], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@7. Skipping call as 1PC will be used.
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.tm.DummyTransaction] processing afterCompletion for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@4} org.infinispan.transaction.synchronization.SynchronizationAdapter@23
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.synchronization.SynchronizationAdapter] afterCompletion(3) called for LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@4.
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.TransactionCoordinator] Committing transaction GlobalTransaction:<pnq-vbalaut-64165>:4:local
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.TransactionCoordinator] Doing an 1PC prepare call on the interceptor chain
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.interceptors.InvocationContextInterceptor] Invoked with command PrepareCommand {modifications=[PutKeyValueCommand{key=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, value=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:4:local, cacheName='DIST_LOCK', topologyId=-1} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@3bebd19a]
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.statetransfer.StateTransferInterceptor] handleTopologyAffectedCommand for command PrepareCommand {modifications=[PutKeyValueCommand{key=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, value=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:4:local, cacheName='DIST_LOCK', topologyId=-1}
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.interceptors.CallInterceptor] Suppressing invocation of method handlePrepareCommand.
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.interceptors.distribution.BaseDistributionInterceptor] Should invoke remotely? true. hasModifications=true, hasRemoteLocksAcquired=false
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] pnq-vbalaut-64165 invoking PrepareCommand {modifications=[PutKeyValueCommand{key=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, value=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:4:local, cacheName='DIST_LOCK', topologyId=0} to recipient list [pnq-vbalaut-64165] with options RpcOptions{timeout=15000, unit=MILLISECONDS, fifoOrder=false, totalOrder=false, responseFilter=null, responseMode=SYNCHRONOUS_IGNORE_LEAVERS, skipReplicationQueue=false}
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.remoting.transport.jgroups.JGroupsTransport] dests=[pnq-vbalaut-64165], command=PrepareCommand {modifications=[PutKeyValueCommand{key=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, value=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:4:local, cacheName='DIST_LOCK', topologyId=0}, mode=SYNCHRONOUS_IGNORE_LEAVERS, timeout=15000
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] Response(s) to PrepareCommand {modifications=[PutKeyValueCommand{key=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, value=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:4:local, cacheName='DIST_LOCK', topologyId=0} is {}
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.LocalTransaction] Adding remote locks on [pnq-vbalaut-64165]. Remote locks are null
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] About to commit entry ReadCommittedEntry(3679ac99){key=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, value=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, oldValue=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock, isCreated=false, isChanged=true, isRemoved=false, isValid=true, skipRemoteGet=false, metadata=EmbeddedMetadata{version=null}}
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.container.entries.ReadCommittedEntry] Updating entry (key=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock removed=false valid=true changed=true created=false loaded=false value=com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock metadata=EmbeddedMetadata{version=null})
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] Attempting to unlock com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.util.concurrent.locks.containers.OwnableReentrantPerEntryLockContainer] Unlocking lock instance for key com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.AbstractCacheTransaction] Clearing locked keys: [com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock]
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.interceptors.TxInterceptor] invokeNextInterceptorAndVerifyTransaction :: originatorMissing=false, alreadyCompleted=false
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.statetransfer.StateTransferManagerImpl] CommandTopologyId=0, localTopologyId=0
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.TransactionTable] Removed LocalTransaction{remoteLockedNodes=[pnq-vbalaut-64165], isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@4 from transaction table.
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.AbstractCacheTransaction] Transaction GlobalTransaction:<pnq-vbalaut-64165>:4:local has completed, notifying listening threads.
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.AbstractEnlistmentAdapter] Committed in onePhase? true isOptimistic? false
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.LocalTransaction] getCommitNodes recipients=null, currentTopologyId=0, members=[pnq-vbalaut-64165], txTopologyId=0
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.AbstractEnlistmentAdapter] About to invoke tx completion notification on commitNodes: null
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] pnq-vbalaut-64165 invoking TxCompletionNotificationCommand{ xid=null, internalId=0, topologyId=-1, gtx=GlobalTransaction:<pnq-vbalaut-64165>:4:local, cacheName=DIST_LOCK} to recipient list null with options RpcOptions{timeout=15000, unit=MILLISECONDS, fifoOrder=false, totalOrder=false, responseFilter=null, responseMode=ASYNCHRONOUS_WITH_SYNC_MARSHALLING, skipReplicationQueue=false}
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.remoting.transport.jgroups.JGroupsTransport] dests=null, command=TxCompletionNotificationCommand{ xid=null, internalId=0, topologyId=0, gtx=GlobalTransaction:<pnq-vbalaut-64165>:4:local, cacheName=DIST_LOCK} , mode=ASYNCHRONOUS_WITH_SYNC_MARSHALLING, timeout=15000
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] Response(s) to TxCompletionNotificationCommand{ xid=null, internalId=0, topologyId=0, gtx=GlobalTransaction:<pnq-vbalaut-64165>:4:local, cacheName=DIST_LOCK} is {}
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.tm.DummyTransaction] processing afterCompletion for SynchronizationAdapter{localTransaction=LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[1001], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@7} org.infinispan.transaction.synchronization.SynchronizationAdapter@26
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.synchronization.SynchronizationAdapter] afterCompletion(3) called for LocalTransaction{remoteLockedNodes=null, isMarkedForRollback=false, lockedKeys=[1001], backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@7.
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.TransactionCoordinator] Committing transaction GlobalTransaction:<pnq-vbalaut-64165>:7:local
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.TransactionCoordinator] Doing an 1PC prepare call on the interceptor chain
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.interceptors.InvocationContextInterceptor] Invoked with command PrepareCommand {modifications=[PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:7:local, cacheName='METRIC_SCORECARD', topologyId=-1} and InvocationContext [org.infinispan.context.impl.LocalTxInvocationContext@541569f1]
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.statetransfer.StateTransferInterceptor] handleTopologyAffectedCommand for command PrepareCommand {modifications=[PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:7:local, cacheName='METRIC_SCORECARD', topologyId=-1}
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.interceptors.CallInterceptor] Suppressing invocation of method handlePrepareCommand.
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.interceptors.distribution.BaseDistributionInterceptor] Should invoke remotely? true. hasModifications=true, hasRemoteLocksAcquired=false
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] pnq-vbalaut-64165 invoking PrepareCommand {modifications=[PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:7:local, cacheName='METRIC_SCORECARD', topologyId=0} to recipient list [pnq-vbalaut-64165] with options RpcOptions{timeout=15000, unit=MILLISECONDS, fifoOrder=false, totalOrder=false, responseFilter=null, responseMode=SYNCHRONOUS_IGNORE_LEAVERS, skipReplicationQueue=false}
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.remoting.transport.jgroups.JGroupsTransport] dests=[pnq-vbalaut-64165], command=PrepareCommand {modifications=[PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:7:local, cacheName='METRIC_SCORECARD', topologyId=0}, mode=SYNCHRONOUS_IGNORE_LEAVERS, timeout=15000
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] Response(s) to PrepareCommand {modifications=[PutKeyValueCommand{key=1001, value=, flags=null, putIfAbsent=false, metadata=EmbeddedMetadata{version=null}, successful=true}], onePhaseCommit=true, gtx=GlobalTransaction:<pnq-vbalaut-64165>:7:local, cacheName='METRIC_SCORECARD', topologyId=0} is {}
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.LocalTransaction] Adding remote locks on [pnq-vbalaut-64165]. Remote locks are null
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.interceptors.EntryWrappingInterceptor] About to commit entry ReadCommittedEntry(49c384c5){key=1001, value=, oldValue=, isCreated=false, isChanged=true, isRemoved=false, isValid=true, skipRemoteGet=false, metadata=EmbeddedMetadata{version=null}}
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.container.entries.ReadCommittedEntry] Updating entry (key=1001 removed=false valid=true changed=true created=false loaded=false value= metadata=EmbeddedMetadata{version=null})
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.util.concurrent.locks.LockManagerImpl] Attempting to unlock 1001
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.util.concurrent.locks.containers.OwnableReentrantPerEntryLockContainer] Unlocking lock instance for key 1001
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.AbstractCacheTransaction] Clearing locked keys: [1001]
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.interceptors.TxInterceptor] invokeNextInterceptorAndVerifyTransaction :: originatorMissing=false, alreadyCompleted=false
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.statetransfer.StateTransferManagerImpl] CommandTopologyId=0, localTopologyId=0
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.TransactionTable] Removed LocalTransaction{remoteLockedNodes=[pnq-vbalaut-64165], isMarkedForRollback=false, lockedKeys=null, backupKeyLocks=null, topologyId=0, isFromStateTransfer=false} org.infinispan.transaction.synchronization.SyncLocalTransaction@7 from transaction table.
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.AbstractCacheTransaction] Transaction GlobalTransaction:<pnq-vbalaut-64165>:7:local has completed, notifying listening threads.
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.AbstractEnlistmentAdapter] Committed in onePhase? true isOptimistic? false
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.LocalTransaction] getCommitNodes recipients=null, currentTopologyId=0, members=[pnq-vbalaut-64165], txTopologyId=0
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.transaction.AbstractEnlistmentAdapter] About to invoke tx completion notification on commitNodes: null
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] pnq-vbalaut-64165 invoking TxCompletionNotificationCommand{ xid=null, internalId=0, topologyId=-1, gtx=GlobalTransaction:<pnq-vbalaut-64165>:7:local, cacheName=METRIC_SCORECARD} to recipient list null with options RpcOptions{timeout=15000, unit=MILLISECONDS, fifoOrder=false, totalOrder=false, responseFilter=null, responseMode=ASYNCHRONOUS_WITH_SYNC_MARSHALLING, skipReplicationQueue=false}
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.remoting.transport.jgroups.JGroupsTransport] dests=null, command=TxCompletionNotificationCommand{ xid=null, internalId=0, topologyId=0, gtx=GlobalTransaction:<pnq-vbalaut-64165>:7:local, cacheName=METRIC_SCORECARD} , mode=ASYNCHRONOUS_WITH_SYNC_MARSHALLING, timeout=15000
2013-09-2512:44:00 [Thread-5] TRACE [org.infinispan.remoting.rpc.RpcManagerImpl] Response(s) to TxCompletionNotificationCommand{ xid=null, internalId=0, topologyId=0, gtx=GlobalTransaction:<pnq-vbalaut-64165>:7:local, cacheName=METRIC_SCORECARD} is {}
2013-09-2512:44:00 [Thread-5] DEBUG [com.threadissue.infinispan.DistributedTaskLock] Lock com.threadissue.infinispan.DistributedTaskLockTest$MessageProcessorLock released after executing TASK10234
2013-09-2512:44:00 [Thread-5] INFO [com.threadissue.infinispan.DistributedTaskLockTest] get Command : 1001