[jbosscache-issues] [JBoss JIRA] Commented: (JBCACHE-1525) Cache.removeNode does not remove node when buddies are configured and called on instance which does not contains the node.

Cache.removeNode does not remove node when buddies are configured and called on instance which does not contains the node. -------------------------------------------------------------------------------------------------------------------------- Key: JBCACHE-1525 URL: https://jira.jboss.org/jira/browse/JBCACHE-1525 Project: JBoss Cache Issue Type: Bug Security Level: Public(Everyone can see) Components: Buddy Replication Affects Versions: 3.0.0.GA Reporter: Jaroslaw Lewandowski Assignee: Manik Surtani Fix For: 3.3.0.GA When tried to remove node from cache instance which had one budy and the budy on the other side possesed all the data it looks like the node still exists in the cluster. The following test does shows the problem. {code:java} @Test public void stealEachOtherData() throws Exception { Cache<Object,Object> cacheOne = PojoCacheFactory.createCache("configuration/test-jgroups-budies.xml").getCache(); Cache<Object, Object> cacheTwo = PojoCacheFactory.createCache("configuration/test-jgroups-budies.xml").getCache(); Fqn fqn = Fqn.fromString("/test/blah"); String key = "key"; for (int i = 0; i < 100; i++) { String value = "Value"+i; cacheOne.put(fqn, key, value); Node<Object,Object> node; long timeOut = 3000L; node = assertNotNullWithTimeOut(cacheTwo, fqn, timeOut); assertEquals(value, node.get(key)); node = assertNotNullWithTimeOut(cacheOne, fqn, timeOut); assertEquals(value, node.get(key)); _log.debug("BEFORE REMOVE"); cacheTwo.removeNode(fqn); assertNull(cacheOne.getNode(fqn)); assertNull(cacheTwo.getNode(fqn)); } } private Node<Object, Object> assertNotNullWithTimeOut(Cache<Object, Object> cacheTwo, Fqn fqn, long timeOut) throws InterruptedException { Node<Object, Object> node = null; long start = System.currentTimeMillis(); do { node = cacheTwo.getNode(fqn); Thread.sleep(50l); } while (node == null && (System.currentTimeMillis() - start < timeOut)); assertNotNull(node); return node; } {code} here is the configuration {code:xml} <?xml version="1.0" encoding="UTF-8" ?> <jbosscache xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns="urn:jboss:jbosscache-core:config:3.0"> <locking isolationLevel="REPEATABLE_READ" lockParentForChildInsertRemove="false" lockAcquisitionTimeout="20000" nodeLockingScheme="mvcc" writeSkewCheck="false" concurrencyLevel="500"/> <clustering mode="replication" clusterName="TestDigitalVault"> <stateRetrieval timeout="15000" fetchInMemoryState="false"/> <sync replTimeout="15000"/> <buddy enabled="true" communicationTimeout="3000"> <dataGravitation auto="true" removeOnFind="true" searchBackupTrees="true"/> <locator class="org.jboss.cache.buddyreplication.NextMemberBuddyLocator"> <properties> numBuddies = 1 ignoreColocatedBuddies = false </properties> </locator> </buddy> <jgroupsConfig> <TCP bind_port="2000" port_range="5" enable_bundling="false"/> <TCPPING initial_hosts="localhost[2000]" port_range="5" timeout="3000" num_initial_members="1" /> <FD_SOCK/> <FD timeout="10000" max_tries="5" shun="true"/> <VERIFY_SUSPECT timeout="15000"/> <pbcast.NAKACK max_xmit_size="60000" use_mcast_xmit="false" gc_lag="0" retransmit_timeout="300,600,1200,2400,4800" discard_delivered_msgs="true"/> <UNICAST timeout="300,600,1200,2400,3600"/> <pbcast.STABLE stability_delay="1000" desired_avg_gossip="50000" max_bytes="400000"/> <pbcast.GMS print_local_addr="true" join_timeout="5000" join_retry_timeout="2000" shun="false" view_bundling="true" view_ack_collection_timeout="5000"/> <pbcast.STREAMING_STATE_TRANSFER/> <pbcast.FLUSH timeout="0"/> </jgroupsConfig> </clustering> </jbosscache> {code} Here are some logs: {code} 2009-07-30 16:15:25,914 [main] TRACE cache.interceptors.InvocationContextInterceptor - Invoked with command RemoveNodeCommand{fqn=/test/blah, dataVersion=null, globalTransaction=null, skipSendingNodeEvents=false, parentFqn=null, targetNode=null} and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false}, originLocal=true}] 2009-07-30 16:15:25,916 [main] TRACE cache.interceptors.InvocationContextInterceptor - Setting up transactional context. 2009-07-30 16:15:25,916 [main] TRACE cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null 2009-07-30 16:15:25,916 [main] TRACE cache.lock.MVCCLockManager - Attempting to lock /test/blah 2009-07-30 16:15:25,917 [main] TRACE commands.write.RemoveNodeCommand - perform(null, /test/blah) 2009-07-30 16:15:25,917 [main] TRACE commands.write.RemoveNodeCommand - node /test/blah not found 2009-07-30 16:15:25,917 [main] TRACE cache.interceptors.MVCCLockingInterceptor - Releasing lock on [/test/blah] for owner Thread[main,5,main] 2009-07-30 16:15:25,918 [main] TRACE cache.lock.MVCCLockManager - Attempting to unlock /test/blah 2009-07-30 16:15:25,918 [main] TRACE cache.interceptors.ReplicationInterceptor - invoking method RemoveNodeCommand, members=[127.0.0.1:2000, 127.0.0.1:2001], mode=REPL_SYNC, exclude_self=true, timeout=15000 2009-07-30 16:15:25,918 [main] TRACE cache.interceptors.ReplicationInterceptor - Broadcasting call RemoveNodeCommand{fqn=/test/blah, dataVersion=null, globalTransaction=null, skipSendingNodeEvents=false, parentFqn=null, targetNode=null} to recipient list null 2009-07-30 16:15:25,919 [main] TRACE cache.buddyreplication.BuddyManager - Transformed RemoveNodeCommand{fqn=/test/blah, dataVersion=null, globalTransaction=null, skipSendingNodeEvents=false, parentFqn=null, targetNode=null} to RemoveNodeCommand{fqn=/_BUDDY_BACKUP_/127.0.0.1_2001/test/blah, dataVersion=null, globalTransaction=null, skipSendingNodeEvents=false, parentFqn=null, targetNode=null} 2009-07-30 16:15:25,920 [main] TRACE cache.interceptors.ReplicationInterceptor - Setting call recipients to [127.0.0.1:2000] since the original list of recipients passed in is null. 2009-07-30 16:15:25,921 [main] TRACE jboss.cache.RPCManagerImpl - callRemoteMethods(): valid members are [127.0.0.1:2000] methods: ReplicateCommand{cmds=RemoveNodeCommand{fqn=/_BUDDY_BACKUP_/127.0.0.1_2001/test/blah, dataVersion=null, globalTransaction=null, skipSendingNodeEvents=false, parentFqn=null, targetNode=null}} Using OOB? false 2009-07-30 16:15:25,921 [main] TRACE cache.marshall.CommandAwareRpcDispatcher - dests=[127.0.0.1:2000], command=ReplicateCommand{cmds=RemoveNodeCommand{fqn=/_BUDDY_BACKUP_/127.0.0.1_2001/test/blah, dataVersion=null, globalTransaction=null, skipSendingNodeEvents=false, parentFqn=null, targetNode=null}}, mode=2, timeout=15000 2009-07-30 16:15:25,922 [main] TRACE cache.marshall.CacheMarshaller300 - Marshalling object ReplicateCommand{cmds=RemoveNodeCommand{fqn=/_BUDDY_BACKUP_/127.0.0.1_2001/test/blah, dataVersion=null, globalTransaction=null, skipSendingNodeEvents=false, parentFqn=null, targetNode=null}} 2009-07-30 16:15:25,923 [main] TRACE cache.marshall.CommandAwareRpcDispatcher - real_dests=[127.0.0.1:2000] 2009-07-30 16:15:25,924 [Incoming-1,TestDigitalVault,127.0.0.1:2000] TRACE cache.marshall.CacheMarshaller300 - Unmarshalled object ReplicateCommand{cmds=RemoveNodeCommand{fqn=/_BUDDY_BACKUP_/127.0.0.1_2001/test/blah, dataVersion=null, globalTransaction=null, skipSendingNodeEvents=false, parentFqn=null, targetNode=null}} 2009-07-30 16:15:25,925 [Incoming-1,TestDigitalVault,127.0.0.1:2000] TRACE cache.marshall.CommandAwareRpcDispatcher - Executing command: ReplicateCommand{cmds=RemoveNodeCommand{fqn=/_BUDDY_BACKUP_/127.0.0.1_2001/test/blah, dataVersion=null, globalTransaction=null, skipSendingNodeEvents=false, parentFqn=null, targetNode=null}} [sender=127.0.0.1:2001] 2009-07-30 16:15:25,926 [Incoming-1,TestDigitalVault,127.0.0.1:2000] TRACE cache.marshall.CommandAwareRpcDispatcher - This is a non-visitable command - so performing directly and not via the invoker. 2009-07-30 16:15:25,926 [Incoming-1,TestDigitalVault,127.0.0.1:2000] TRACE cache.factories.ComponentRegistry - Testing if invocations are allowed. 2009-07-30 16:15:25,927 [Incoming-1,TestDigitalVault,127.0.0.1:2000] TRACE commands.remote.ReplicateCommand - Invoking command RemoveNodeCommand{fqn=/_BUDDY_BACKUP_/127.0.0.1_2001/test/blah, dataVersion=null, globalTransaction=null, skipSendingNodeEvents=false, parentFqn=null, targetNode=null}, with originLocal flag set to false. 2009-07-30 16:15:25,927 [Incoming-1,TestDigitalVault,127.0.0.1:2000] TRACE cache.interceptors.InvocationContextInterceptor - Invoked with command RemoveNodeCommand{fqn=/_BUDDY_BACKUP_/127.0.0.1_2001/test/blah, dataVersion=null, globalTransaction=null, skipSendingNodeEvents=false, parentFqn=null, targetNode=null} and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false}, originLocal=false}] 2009-07-30 16:15:25,929 [Incoming-1,TestDigitalVault,127.0.0.1:2000] TRACE cache.interceptors.InvocationContextInterceptor - Setting up transactional context. 2009-07-30 16:15:25,929 [Incoming-1,TestDigitalVault,127.0.0.1:2000] TRACE cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null 2009-07-30 16:15:25,929 [Incoming-1,TestDigitalVault,127.0.0.1:2000] TRACE cache.lock.MVCCLockManager - Attempting to lock /_BUDDY_BACKUP_/127.0.0.1_2001/test/blah 2009-07-30 16:15:25,930 [Incoming-1,TestDigitalVault,127.0.0.1:2000] TRACE commands.write.RemoveNodeCommand - perform(null, /_BUDDY_BACKUP_/127.0.0.1_2001/test/blah) 2009-07-30 16:15:25,930 [Incoming-1,TestDigitalVault,127.0.0.1:2000] TRACE commands.write.RemoveNodeCommand - node /_BUDDY_BACKUP_/127.0.0.1_2001/test/blah not found 2009-07-30 16:15:25,930 [Incoming-1,TestDigitalVault,127.0.0.1:2000] TRACE cache.interceptors.MVCCLockingInterceptor - Releasing lock on [/_BUDDY_BACKUP_/127.0.0.1_2001/test/blah] for owner Thread[Incoming-1,TestDigitalVault,127.0.0.1:2000,5,Thread Pools] 2009-07-30 16:15:25,931 [Incoming-1,TestDigitalVault,127.0.0.1:2000] TRACE cache.lock.MVCCLockManager - Attempting to unlock /_BUDDY_BACKUP_/127.0.0.1_2001/test/blah 2009-07-30 16:15:25,931 [Incoming-1,TestDigitalVault,127.0.0.1:2000] TRACE cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options 2009-07-30 16:15:25,931 [Incoming-1,TestDigitalVault,127.0.0.1:2000] TRACE cache.marshall.CacheMarshaller300 - Marshalling object null 2009-07-30 16:15:25,932 [OOB-2,TestDigitalVault,127.0.0.1:2001] TRACE cache.marshall.CacheMarshaller300 - Unmarshalled object null 2009-07-30 16:15:25,933 [main] TRACE cache.marshall.CommandAwareRpcDispatcher - responses: [sender=127.0.0.1:2000, retval=null, received=true, suspected=false] 2009-07-30 16:15:25,933 [main] TRACE jboss.cache.RPCManagerImpl - (127.0.0.1:2001): responses for method ReplicateCommand: null 2009-07-30 16:15:25,934 [main] TRACE cache.interceptors.ReplicationInterceptor - responses=[] 2009-07-30 16:15:25,934 [main] TRACE cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options 2009-07-30 16:15:25,934 [main] TRACE cache.interceptors.InvocationContextInterceptor - Invoked with command GetNodeCommand{fqn=/test/blah} and InvocationContext [InvocationContext{transaction=null, globalTransaction=null, transactionContext=null, optionOverrides=Option{failSilently=false, cacheModeLocal=false, dataVersion=null, suppressLocking=false, lockAcquisitionTimeout=-1, forceDataGravitation=false, skipDataGravitation=false, forceAsynchronous=false, forceSynchronous=false}, originLocal=true}] 2009-07-30 16:15:25,935 [main] TRACE cache.interceptors.InvocationContextInterceptor - Setting up transactional context. 2009-07-30 16:15:25,936 [main] TRACE cache.interceptors.InvocationContextInterceptor - Setting tx as null and gtx as null 2009-07-30 16:15:25,937 [main] TRACE cache.mvcc.MVCCNodeHelper - Node /test/blah is not in context, fetching from container. 2009-07-30 16:15:25,937 [main] TRACE cache.interceptors.DataGravitatorInterceptor - Checking local existence of requested fqn /test/blah 2009-07-30 16:15:25,937 [main] TRACE cache.interceptors.DataGravitatorInterceptor - No need to gravitate; have this already. 2009-07-30 16:15:25,937 [main] TRACE cache.interceptors.CallInterceptor - Executing command: GetNodeCommand{fqn=/test/blah}. 2009-07-30 16:15:25,939 [main] TRACE commands.read.GetNodeCommand - Found node, returning UnversionedNode[ /test/blah data=[key]] 2009-07-30 16:15:25,939 [main] TRACE cache.interceptors.MVCCLockingInterceptor - Nothing to do since there are no modifications in scope. 2009-07-30 16:15:25,940 [main] TRACE cache.interceptors.InvocationContextInterceptor - Resetting invocation-scope options {code} As you can see first it's tried to delete "/test/blah" in the current instance and then "/_BUDDY_BACKUP_/127.0.0.1_2001/test/blah" in the other intsance .. both operations fail.