0 Replies Latest reply on Sep 26, 2013 6:17 AM by Viren Balaut

    REPL_SYNC value not found issue

    Viren Balaut Newbie

      I 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