[JBoss JIRA] (ISPN-7135) ClusterListenerReplTest.testPrimaryOwnerGoesDownBeforeBackupRaisesEvent random failures
by William Burns (JIRA)
[ https://issues.jboss.org/browse/ISPN-7135?page=com.atlassian.jira.plugin.... ]
William Burns updated ISPN-7135:
--------------------------------
Status: Pull Request Sent (was: Coding In Progress)
Git Pull Request: https://github.com/infinispan/infinispan/pull/4915
> ClusterListenerReplTest.testPrimaryOwnerGoesDownBeforeBackupRaisesEvent random failures
> ---------------------------------------------------------------------------------------
>
> Key: ISPN-7135
> URL: https://issues.jboss.org/browse/ISPN-7135
> Project: Infinispan
> Issue Type: Bug
> Components: Test Suite - Core
> Affects Versions: 9.0.0.Alpha4
> Reporter: Dan Berindei
> Assignee: William Burns
> Priority: Critical
> Labels: testsuite_stability
> Fix For: 9.0.0.Final
>
>
> The test assumes that because the primary owner is killed before the backups updated the entry, the clustered listener will only receive one {{CACHE_ENTRY_CREATED}} event.
> However, the crash and the following rebalance require 3 topology updates, meaning the command could be retried a second time, after the backup already applied the new value. In the log below, {{NodeDS}} retries with topology {{7}}, the primary {{NodeDU}} forwards it to the backup (also {{NodeDS}}), but then sees topology {{8}} and triggers a retry. The clustered listener on {{NodeDS}} receives both a {{CACHE_ENTRY_CREATED}} event and a {{CACHE_ENTRY_MODIFIED}} event.
> {noformat}
> 10:35:47,429 TRACE (ForkThread-2,Test:[]) [BaseDistributionInterceptor] Command topology id is 5, current topology id is 5, successful? true
> 10:35:47,429 TRACE (ForkThread-2,Test:[]) [BaseDistributionInterceptor] I'm not the primary owner, so sending the command to the primary owner(Test-NodeDT-11194) in order to be forwarded
> 10:35:47,496 DEBUG (remote-thread-Test-NodeDS-p31418-t6:[cluster-listener]) [ClusterTopologyManagerImpl] Updating cluster-wide current topology for cache cluster-listener, topology = CacheTopology{id=6, rebalanceId=3, currentCH=ReplicatedConsistentHash{ns = 256, owners = (2)[Test-NodeDS-11906: 133, Test-NodeDU-38945: 123]}, pendingCH=null, unionCH=null, actualMembers=[Test-NodeDS-11906, Test-NodeDU-38945], persistentUUIDs=[7ddc513a-2a94-4dc5-9918-7fb90a6510bb, cd827dd6-62d9-4f78-a28e-4d10dc77a862]}, availability mode = AVAILABLE
> 10:35:47,502 TRACE (transport-thread-Test-NodeDS-p31420-t1:[Topology-cluster-listener]) [StateConsumerImpl] Received new topology for cache cluster-listener, isRebalance = false, isMember = true, topology = CacheTopology{id=6, rebalanceId=3, currentCH=PartitionerConsistentHash:ReplicatedConsistentHash{ns = 256, owners = (2)[Test-NodeDS-11906: 133, Test-NodeDU-38945: 123]}, pendingCH=null, unionCH=null, actualMembers=[Test-NodeDS-11906, Test-NodeDU-38945], persistentUUIDs=[7ddc513a-2a94-4dc5-9918-7fb90a6510bb, cd827dd6-62d9-4f78-a28e-4d10dc77a862]}
> 10:35:47,514 INFO (remote-thread-Test-NodeDS-p31418-t6:[cluster-listener]) [CLUSTER] ISPN000310: Starting cluster-wide rebalance for cache cluster-listener, topology CacheTopology{id=7, rebalanceId=4, currentCH=ReplicatedConsistentHash{ns = 256, owners = (2)[Test-NodeDS-11906: 133, Test-NodeDU-38945: 123]}, pendingCH=ReplicatedConsistentHash{ns = 256, owners = (2)[Test-NodeDS-11906: 134, Test-NodeDU-38945: 122]}, unionCH=null, actualMembers=[Test-NodeDS-11906, Test-NodeDU-38945], persistentUUIDs=[7ddc513a-2a94-4dc5-9918-7fb90a6510bb, cd827dd6-62d9-4f78-a28e-4d10dc77a862]}
> 10:35:47,526 TRACE (transport-thread-Test-NodeDS-p31420-t2:[Topology-cluster-listener]) [StateConsumerImpl] Received new topology for cache cluster-listener, isRebalance = true, isMember = true, topology = CacheTopology{id=7, rebalanceId=4, currentCH=PartitionerConsistentHash:ReplicatedConsistentHash{ns = 256, owners = (2)[Test-NodeDS-11906: 133, Test-NodeDU-38945: 123]}, pendingCH=PartitionerConsistentHash:ReplicatedConsistentHash{ns = 256, owners = (2)[Test-NodeDS-11906: 134, Test-NodeDU-38945: 122]}, unionCH=PartitionerConsistentHash:ReplicatedConsistentHash{ns = 256, owners = (2)[Test-NodeDS-11906: 133, Test-NodeDU-38945: 123]}, actualMembers=[Test-NodeDS-11906, Test-NodeDU-38945], persistentUUIDs=[7ddc513a-2a94-4dc5-9918-7fb90a6510bb, cd827dd6-62d9-4f78-a28e-4d10dc77a862]}
> 10:35:47,527 TRACE (transport-thread-Test-NodeDU-p31480-t5:[Topology-cluster-listener]) [StateConsumerImpl] Received new topology for cache cluster-listener, isRebalance = false, isMember = true, topology = CacheTopology{id=6, rebalanceId=3, currentCH=PartitionerConsistentHash:ReplicatedConsistentHash{ns = 256, owners = (2)[Test-NodeDS-11906: 133, Test-NodeDU-38945: 123]}, pendingCH=null, unionCH=null, actualMembers=[Test-NodeDS-11906, Test-NodeDU-38945], persistentUUIDs=[7ddc513a-2a94-4dc5-9918-7fb90a6510bb, cd827dd6-62d9-4f78-a28e-4d10dc77a862]}
> *** 10:35:47,555 TRACE (remote-thread-Test-NodeDS-p31418-t6:[]) [StateTransferInterceptor] Retrying command because of topology change, current topology is 7: PutKeyValueCommand{key=MagicKey{1088/5C01D0B5/73@Test-NodeDT-11194}, value=first-value, flags=[], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}
> 10:35:47,555 TRACE (remote-thread-Test-NodeDS-p31418-t6:[]) [BaseDistributionInterceptor] I'm not the primary owner, so sending the command to the primary owner(Test-NodeDU-38945) in order to be forwarded
> 10:35:47,558 TRACE (transport-thread-Test-NodeDU-p31480-t5:[Topology-cluster-listener]) [StateConsumerImpl] Received new topology for cache cluster-listener, isRebalance = true, isMember = true, topology = CacheTopology{id=7, rebalanceId=4, currentCH=PartitionerConsistentHash:ReplicatedConsistentHash{ns = 256, owners = (2)[Test-NodeDS-11906: 133, Test-NodeDU-38945: 123]}, pendingCH=PartitionerConsistentHash:ReplicatedConsistentHash{ns = 256, owners = (2)[Test-NodeDS-11906: 134, Test-NodeDU-38945: 122]}, unionCH=PartitionerConsistentHash:ReplicatedConsistentHash{ns = 256, owners = (2)[Test-NodeDS-11906: 133, Test-NodeDU-38945: 123]}, actualMembers=[Test-NodeDS-11906, Test-NodeDU-38945], persistentUUIDs=[7ddc513a-2a94-4dc5-9918-7fb90a6510bb, cd827dd6-62d9-4f78-a28e-4d10dc77a862]}
> 10:35:47,600 DEBUG (remote-thread-Test-NodeDS-p31418-t5:[cluster-listener]) [ClusterTopologyManagerImpl] Updating cluster-wide current topology for cache cluster-listener, topology = CacheTopology{id=8, rebalanceId=4, currentCH=ReplicatedConsistentHash{ns = 256, owners = (2)[Test-NodeDS-11906: 134, Test-NodeDU-38945: 122]}, pendingCH=null, unionCH=null, actualMembers=[Test-NodeDS-11906, Test-NodeDU-38945], persistentUUIDs=[7ddc513a-2a94-4dc5-9918-7fb90a6510bb, cd827dd6-62d9-4f78-a28e-4d10dc77a862]}, availability mode = AVAILABLE
> 10:35:47,603 TRACE (remote-thread-Test-NodeDS-p31418-t6:[]) [ReadCommittedEntry] Updating entry (key=MagicKey{1088/5C01D0B5/73@Test-NodeDT-11194} removed=false valid=true changed=true created=true value=first-value metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, providedMetadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null})
> 10:35:47,603 TRACE (transport-thread-Test-NodeDS-p31420-t6:[Topology-cluster-listener]) [StateConsumerImpl] Received new topology for cache cluster-listener, isRebalance = false, isMember = true, topology = CacheTopology{id=8, rebalanceId=4, currentCH=PartitionerConsistentHash:ReplicatedConsistentHash{ns = 256, owners = (2)[Test-NodeDS-11906: 134, Test-NodeDU-38945: 122]}, pendingCH=null, unionCH=null, actualMembers=[Test-NodeDS-11906, Test-NodeDU-38945], persistentUUIDs=[7ddc513a-2a94-4dc5-9918-7fb90a6510bb, cd827dd6-62d9-4f78-a28e-4d10dc77a862]}
> 10:35:47,611 DEBUG (remote-thread-Test-NodeDS-p31418-t6:[]) [Test] Adding new cluster event EventImpl{type=CACHE_ENTRY_CREATED, pre=false, cache=Cache 'cluster-listener'@Test-NodeDS-11906, key=MagicKey{1088/5C01D0B5/73@Test-NodeDT-11194}, value=first-value, oldValue=null, transaction=null, originLocal=false, transactionSuccessful=false, entries=null, created=false}
> 10:35:47,614 TRACE (transport-thread-Test-NodeDU-p31480-t1:[Topology-cluster-listener]) [StateConsumerImpl] Received new topology for cache cluster-listener, isRebalance = false, isMember = true, topology = CacheTopology{id=8, rebalanceId=4, currentCH=PartitionerConsistentHash:ReplicatedConsistentHash{ns = 256, owners = (2)[Test-NodeDS-11906: 134, Test-NodeDU-38945: 122]}, pendingCH=null, unionCH=null, actualMembers=[Test-NodeDS-11906, Test-NodeDU-38945], persistentUUIDs=[7ddc513a-2a94-4dc5-9918-7fb90a6510bb, cd827dd6-62d9-4f78-a28e-4d10dc77a862]}
> 10:35:47,660 TRACE (OOB-1,Test-NodeDS-11906:[]) [AsyncInvocationStage] Exception from invocation handler
> org.infinispan.statetransfer.OutdatedTopologyException: Cache topology changed while the command was executing: expected 7, got 8
> *** 10:35:47,661 TRACE (OOB-1,Test-NodeDS-11906:[]) [StateTransferInterceptor] Retrying command because of topology change, current topology is 8: PutKeyValueCommand{key=MagicKey{1088/5C01D0B5/73@Test-NodeDT-11194}, value=first-value, flags=[COMMAND_RETRY], putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, successful=true}
> 10:35:47,661 TRACE (OOB-1,Test-NodeDS-11906:[]) [BaseDistributionInterceptor] I'm not the primary owner, so sending the command to the primary owner(Test-NodeDU-38945) in order to be forwarded
> 10:35:47,745 TRACE (remote-thread-Test-NodeDS-p31418-t6:[]) [ReadCommittedEntry] Updating entry (key=MagicKey{1088/5C01D0B5/73@Test-NodeDT-11194} removed=false valid=true changed=true created=false value=first-value metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, providedMetadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null})
> 10:35:47,746 DEBUG (remote-thread-Test-NodeDS-p31418-t6:[]) [Test] Adding new cluster event EventImpl{type=CACHE_ENTRY_MODIFIED, pre=false, cache=Cache 'cluster-listener'@Test-NodeDS-11906, key=MagicKey{1088/5C01D0B5/73@Test-NodeDT-11194}, value=first-value, oldValue=first-value, transaction=null, originLocal=false, transactionSuccessful=false, entries=null, created=false}
> 10:35:47,771 TRACE (OOB-2,Test-NodeDU-38945:[]) [ReadCommittedEntry] Updating entry (key=MagicKey{1088/5C01D0B5/73@Test-NodeDT-11194} removed=false valid=true changed=true created=true value=first-value metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, providedMetadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null})
> {noformat}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
9 years, 1 month
[JBoss JIRA] (ISPN-7070) CacheNotifierImplInitialTransferDistTest.testIterationBeganAndSegmentNotComplete random failures
by William Burns (JIRA)
[ https://issues.jboss.org/browse/ISPN-7070?page=com.atlassian.jira.plugin.... ]
William Burns updated ISPN-7070:
--------------------------------
Status: Pull Request Sent (was: Coding In Progress)
Git Pull Request: https://github.com/infinispan/infinispan/pull/4914
> CacheNotifierImplInitialTransferDistTest.testIterationBeganAndSegmentNotComplete random failures
> ------------------------------------------------------------------------------------------------
>
> Key: ISPN-7070
> URL: https://issues.jboss.org/browse/ISPN-7070
> Project: Infinispan
> Issue Type: Bug
> Components: Core, Test Suite - Core
> Affects Versions: 9.0.0.Alpha4
> Reporter: Dan Berindei
> Assignee: William Burns
> Priority: Critical
> Labels: testsuite_stability
> Fix For: 9.0.0.Final
>
> Attachments: CacheNotifierImplInitialTransferDistTest_ISPN-5467_CompletableFuture-like_API_20161003.log
>
>
> Looks like sometimes the originator listener ignores the CACHE_ENTRY_REMOVED notification:
> {noformat}
> 09:58:57,877 INFO (testng-Test:[]) [TestSuiteProgress] Test starting: org.infinispan.notifications.cachelistener.CacheNotifierImplInitialTransferDistTest.testRemoveAfterIterationBeganAndSegmentNotCompleteValueNonOwnerClustered
> 09:58:58,913 DEBUG (testng-Test:[]) [Test] Found key key-to-change-0 with primary owner != Test-NodeA-7051, segment 60
> 09:58:58,930 TRACE (remote-thread-Test-NodeA-p23726-t6:[]) [ReadCommittedEntry] Updating entry (key=key-to-change-0 removed=false valid=true changed=true created=true value=initial-value metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, providedMetadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null})
> 09:58:58,972 TRACE (remote-thread-Test-NodeC-p23887-t6:[]) [ReadCommittedEntry] Updating entry (key=key-to-change-0 removed=false valid=true changed=true created=true value=initial-value metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, providedMetadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null})
> 09:58:59,014 TRACE (ForkThread-1,Test:[]) [Test] Adding segment listener 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1 : org.infinispan.notifications.cachelistener.DistributedQueueingSegmentListener@68007f8
> 09:58:59,014 TRACE (ForkThread-1,Test:[]) [CacheNotifierImpl] Replicating cluster listener to other nodes [Test-NodeA-7051, Test-NodeB-10318, Test-NodeC-52778] for cluster listener with id 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1
> 09:58:58,998 TRACE (testng-Test:[]) [CheckPoint] Waiting for event pre_complete_segment_invoked * 1
> 09:58:59,063 TRACE (remote-thread-Test-NodeC-p23887-t6:[]) [ClusterListenerReplicateCallable] Registered local cluster listener for remote cluster listener from origin Test-NodeA-7051 with id 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1
> 09:58:59,098 TRACE (remote-thread-Test-NodeB-p23775-t6:[]) [ClusterListenerReplicateCallable] Registered local cluster listener for remote cluster listener from origin Test-NodeA-7051 with id 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1
> 09:58:59,145 TRACE (ForkThread-1,Test:[]) [CacheNotifierImpl] Listener 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1 requests initial state for cache
> 09:58:59,373 TRACE (ForkThread-1,Test:[]) [Test] Completed segments [48, 2, 229, 118, 71, 72, 233, 60]
> 09:58:59,373 TRACE (ForkThread-1,Test:[]) [Test] Listener received event EventImpl{type=CACHE_ENTRY_CREATED, pre=false, cache=Cache 'DistInitialTransferListener'@Test-NodeA-7051, key=key-to-change-0, value=initial-value, oldValue=null, transaction=null, originLocal=true, transactionSuccessful=false, entries=null, created=false}
> 09:58:59,373 TRACE (ForkThread-1,Test:[]) [Test] Notified for key key-to-change-0
> 09:58:59,373 TRACE (ForkThread-1,Test:[]) [CheckPoint] Triggering event pre_complete_segment_invoked * 1 (available = 1, total = 1)
> 09:58:59,373 TRACE (ForkThread-1,Test:[]) [CheckPoint] Waiting for event pre_complete_segment_released * 1
> 09:58:59,373 TRACE (testng-Test:[]) [CheckPoint] Received event pre_complete_segment_invoked * 1 (available = 0, total = 1)
> 09:58:59,577 TRACE (remote-thread-Test-NodeA-p23726-t6:[]) [ReadCommittedEntry] Updating entry (key=key-to-change-0 removed=true valid=false changed=true created=false value=initial-value metadata=EmbeddedMetadata{version=null}, providedMetadata=null)
> 09:58:59,661 TRACE (remote-thread-Test-NodeC-p23887-t5:[]) [ReadCommittedEntry] Updating entry (key=key-to-change-0 removed=true valid=false changed=true created=false value=initial-value metadata=EmbeddedMetadata{version=null}, providedMetadata=null)
> 09:58:59,661 TRACE (remote-thread-Test-NodeC-p23887-t5:[]) [RequestCorrelator] Test-NodeC-52778: invoking unicast RPC [req-id=91126] on Test-NodeA-7051
> 09:58:59,684 TRACE (OOB-2,Test-NodeA-7051:[]) [RequestCorrelator] calling (org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher) with request 91126
> 09:58:59,779 TRACE (remote-thread-Test-NodeA-p23726-t6:[]) [NonTotalOrderPerCacheInboundInvocationHandler] Calling perform() on DistributedExecuteCommand [cache=Cache 'DistInitialTransferListener'@Test-NodeA-7051, keys=[], callable=org.infinispan.notifications.cachelistener.cluster.ClusterEventCallable@640b0234]
> 09:58:59,780 TRACE (remote-thread-Test-NodeA-p23726-t6:[]) [ClusterEventCallable] Received cluster event(s) [ClusterEvent {type=CACHE_ENTRY_REMOVED, cache=Cache 'DistInitialTransferListener'@Test-NodeA-7051, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, retryCommand=false, origin=Test-NodeC-52778}], notifying cluster listener with id 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1
> 09:58:59,837 TRACE (testng-Test:[]) [CheckPoint] Triggering event pre_complete_segment_released * 999999999 (available = 999999999, total = 999999999)
> 09:58:59,837 TRACE (ForkThread-1,Test:[]) [CheckPoint] Received event pre_complete_segment_released * 1 (available = 999999998, total = 999999999)
> 09:58:59,898 TRACE (ForkThread-1,Test:[]) [CacheNotifierImpl] Listener 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1 initial state for cache completed
> 09:58:59,916 TRACE (remote-thread-Test-NodeB-p23775-t6:[]) [ClusterListenerRemoveCallable] Removing local cluster listener due to parent cluster listener was removed : 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1
> 09:58:59,921 TRACE (remote-thread-Test-NodeC-p23887-t5:[]) [ClusterListenerRemoveCallable] Removing local cluster listener due to parent cluster listener was removed : 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1
> 09:58:59,943 ERROR (testng-Test:[]) [TestSuiteProgress] Test failed: org.infinispan.notifications.cachelistener.CacheNotifierImplInitialTransferDistTest.testRemoveAfterIterationBeganAndSegmentNotCompleteValueNonOwnerClustered
> java.lang.AssertionError: expected [12] but found [11]
> {noformat}
> {{CacheNotifierImplInitialTransferDistTest}} also had a different problem: it replaced the {{CacheNotifier}} component with a clone before adding the listener, but replaced it again with the original before removing the listener. Because the listener's uuid was only registered in the clone, {{removeListener}} couldn't find the uuid and disn't try to remove the listener on the other nodes. This meant the listener was leaked, resulting in logs like this:
> {noformat}
> 20:12:04,098 TRACE (remote-thread-Test-NodeB-p24127-t6:[]) [ReadCommittedEntry] Updating entry (key=key-to-change-0 removed=true valid=false changed=true created=false value=initial-value metadata=EmbeddedMetadata{version=null}, providedMetadata=null)
> 20:12:04,099 TRACE (remote-thread-Test-NodeB-p24127-t6:[]) [RemoteClusterListener] Passing Event to manager EventImpl{type=CACHE_ENTRY_REMOVED, pre=false, cache=Cache 'DistInitialTransferListener'@Test-NodeB-56142, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, originLocal=false, transactionSuccessful=false, entries=null, created=false} to send to Test-NodeA-38047
> 20:12:04,100 TRACE (remote-thread-Test-NodeB-p24127-t6:[]) [RemoteClusterListener] Passing Event to manager EventImpl{type=CACHE_ENTRY_REMOVED, pre=false, cache=Cache 'DistInitialTransferListener'@Test-NodeB-56142, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, originLocal=false, transactionSuccessful=false, entries=null, created=false} to send to Test-NodeA-38047
> 20:12:04,100 TRACE (remote-thread-Test-NodeB-p24127-t6:[]) [RemoteClusterListener] Passing Event to manager EventImpl{type=CACHE_ENTRY_REMOVED, pre=false, cache=Cache 'DistInitialTransferListener'@Test-NodeB-56142, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, originLocal=false, transactionSuccessful=false, entries=null, created=false} to send to Test-NodeA-38047
> 20:12:04,100 TRACE (remote-thread-Test-NodeB-p24127-t6:[]) [RemoteClusterListener] Passing Event to manager EventImpl{type=CACHE_ENTRY_REMOVED, pre=false, cache=Cache 'DistInitialTransferListener'@Test-NodeB-56142, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, originLocal=false, transactionSuccessful=false, entries=null, created=false} to send to Test-NodeA-38047
> 20:12:04,100 TRACE (remote-thread-Test-NodeB-p24127-t6:[]) [RemoteClusterListener] Passing Event to manager EventImpl{type=CACHE_ENTRY_REMOVED, pre=false, cache=Cache 'DistInitialTransferListener'@Test-NodeB-56142, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, originLocal=false, transactionSuccessful=false, entries=null, created=false} to send to Test-NodeA-38047
> 20:12:04,106 TRACE (remote-thread-Test-NodeA-p24103-t6:[]) [MultiClusterEventCallable] Received multiple cluster event(s) {86f77630-b1bb-4a21-97bb-b03efeae39d6=[ClusterEvent {type=CACHE_ENTRY_REMOVED, cache=Cache 'DistInitialTransferListener'@Test-NodeA-38047, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, retryCommand=false, origin=Test-NodeB-56142}], 91d05a50-4a35-4e37-8c5c-bffbabc6154b=[ClusterEvent {type=CACHE_ENTRY_REMOVED, cache=Cache 'DistInitialTransferListener'@Test-NodeA-38047, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, retryCommand=false, origin=Test-NodeB-56142}], ba09480f-c698-431b-8fe6-213f1bdefc7b=[ClusterEvent {type=CACHE_ENTRY_REMOVED, cache=Cache 'DistInitialTransferListener'@Test-NodeA-38047, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, retryCommand=false, origin=Test-NodeB-56142}], 992da014-0516-4f2a-8093-50ba3b1f358a=[ClusterEvent {type=CACHE_ENTRY_REMOVED, cache=Cache 'DistInitialTransferListener'@Test-NodeA-38047, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, retryCommand=false, origin=Test-NodeB-56142}], b4eeb9b3-85c4-4ff9-865e-076b7cf93faa=[ClusterEvent {type=CACHE_ENTRY_REMOVED, cache=Cache 'DistInitialTransferListener'@Test-NodeA-38047, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, retryCommand=false, origin=Test-NodeB-56142}]}
> {noformat}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
9 years, 1 month
[JBoss JIRA] (ISPN-7517) Investigate Netty's "Too many open files" exception in testing of infinispan-compatibility-mode-it
by Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-7517?page=com.atlassian.jira.plugin.... ]
Dan Berindei reassigned ISPN-7517:
----------------------------------
Assignee: Dan Berindei
> Investigate Netty's "Too many open files" exception in testing of infinispan-compatibility-mode-it
> --------------------------------------------------------------------------------------------------
>
> Key: ISPN-7517
> URL: https://issues.jboss.org/browse/ISPN-7517
> Project: Infinispan
> Issue Type: Task
> Components: Test Suite - Server
> Reporter: Sanne Grinovero
> Assignee: Dan Berindei
> Fix For: 9.0.0.Final
>
>
> See also discussion on ML:
> - http://lists.jboss.org/pipermail/infinispan-dev/2017-February/017232.html
> Running:
> {noformat}
> mci -rf :infinispan-compatibility-mode-it
> {noformat}
> {noformat}
> Failed tests:
> ByteArrayKeyDistEmbeddedHotRodTest.setup:27 » IllegalState failed to create a ...
> ByteArrayKeyReplEmbeddedHotRodTest.setup:87 » IllegalState failed to create a ...
> ByteArrayValueDistEmbeddedHotRodTest.setup:27 » IllegalState failed to create ...
> ByteArrayValueReplEmbeddedHotRodTest.setup:87 » IllegalState failed to create ...
> DistEmbeddedRestHotRodTest.setup:25 » IllegalState failed to create a child ev...
> DistL1EmbeddedHotRodTest.setup:30 » IllegalState failed to create a child even...
> DistMemcachedEmbeddedTest.setup:39 » IllegalState failed to create a child eve...
> org.infinispan.it.compatibility.EmbeddedHotRodCacheListenerTest.setup(org.infinispan.it.compatibility.EmbeddedHotRodCacheListenerTest)
> Run 1: EmbeddedHotRodCacheListenerTest.setup:36 » IllegalState failed to create a chi...
> Run 2: PASS
> Run 3: PASS
> EmbeddedHotRodTest.testEventFilteringStatic:274->lambda$testEventFilteringStatic$4:276 » Transport
> EmbeddedMemcachedCacheListenerTest.setup:39 » IllegalState failed to create a ...
> EmbeddedRestMemcachedHotRodTest.setup:50 » IllegalState failed to create a chi...
> ReplEmbeddedRestHotRodTest.setup:38 » IllegalState failed to create a child ev...
> Tests run: 101, Failures: 12, Errors: 0, Skipped: 47
> {noformat}
> Errors are all about a similar stacktrace.
> {noformat}
> java.lang.IllegalStateException: failed to create a child event loop
> at io.netty.util.concurrent.MultithreadEventExecutorGroup.<init>(MultithreadEventExecutorGroup.java:88)
> at io.netty.util.concurrent.MultithreadEventExecutorGroup.<init>(MultithreadEventExecutorGroup.java:58)
> at io.netty.channel.MultithreadEventLoopGroup.<init>(MultithreadEventLoopGroup.java:51)
> at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:87)
> at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:82)
> at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:63)
> at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:51)
> at org.jboss.resteasy.plugins.server.netty.NettyJaxrsServer.start(NettyJaxrsServer.java:239)
> at org.infinispan.rest.NettyRestServer.start(NettyRestServer.java:81)
> at org.infinispan.it.compatibility.CompatibilityCacheFactory.createRestCache(CompatibilityCacheFactory.java:199)
> at org.infinispan.it.compatibility.CompatibilityCacheFactory.createRestMemcachedCaches(CompatibilityCacheFactory.java:137)
> at org.infinispan.it.compatibility.CompatibilityCacheFactory.setup(CompatibilityCacheFactory.java:123)
> at org.infinispan.it.compatibility.DistMemcachedEmbeddedTest.setup(DistMemcachedEmbeddedTest.java:39)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:84)
> at org.testng.internal.Invoker.invokeConfigurationMethod(Invoker.java:564)
> at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:213)
> at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:138)
> at org.testng.internal.TestMethodWorker.invokeBeforeClassMethods(TestMethodWorker.java:175)
> at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:107)
> at org.testng.TestRunner.privateRun(TestRunner.java:767)
> at org.testng.TestRunner.run(TestRunner.java:617)
> at org.testng.SuiteRunner.runTest(SuiteRunner.java:348)
> at org.testng.SuiteRunner.access$000(SuiteRunner.java:38)
> at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:382)
> at org.testng.internal.thread.ThreadUtil$2.call(ThreadUtil.java:64)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: io.netty.channel.ChannelException: failed to open a new selector
> at io.netty.channel.nio.NioEventLoop.openSelector(NioEventLoop.java:157)
> at io.netty.channel.nio.NioEventLoop.<init>(NioEventLoop.java:148)
> at io.netty.channel.nio.NioEventLoopGroup.newChild(NioEventLoopGroup.java:126)
> at io.netty.channel.nio.NioEventLoopGroup.newChild(NioEventLoopGroup.java:36)
> at io.netty.util.concurrent.MultithreadEventExecutorGroup.<init>(MultithreadEventExecutorGroup.java:84)
> ... 32 more
> Caused by: java.io.IOException: Too many open files
> at sun.nio.ch.EPollArrayWrapper.epollCreate(Native Method)
> at sun.nio.ch.EPollArrayWrapper.<init>(EPollArrayWrapper.java:130)
> at sun.nio.ch.EPollSelectorImpl.<init>(EPollSelectorImpl.java:69)
> at sun.nio.ch.EPollSelectorProvider.openSelector(EPollSelectorProvider.java:36)
> at io.netty.channel.nio.NioEventLoop.openSelector(NioEventLoop.java:155)
> ... 36 more
> {noformat}
> N.B.
> The failure is quite consistent on my workstation, almost always results in the same tests failing. Yet occasionally they all pass.
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
9 years, 1 month
[JBoss JIRA] (ISPN-7517) Investigate Netty's "Too many open files" exception in testing of infinispan-compatibility-mode-it
by Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-7517?page=com.atlassian.jira.plugin.... ]
Dan Berindei updated ISPN-7517:
-------------------------------
Status: Open (was: New)
> Investigate Netty's "Too many open files" exception in testing of infinispan-compatibility-mode-it
> --------------------------------------------------------------------------------------------------
>
> Key: ISPN-7517
> URL: https://issues.jboss.org/browse/ISPN-7517
> Project: Infinispan
> Issue Type: Task
> Components: Test Suite - Server
> Reporter: Sanne Grinovero
> Assignee: Dan Berindei
> Fix For: 9.0.0.Final
>
>
> See also discussion on ML:
> - http://lists.jboss.org/pipermail/infinispan-dev/2017-February/017232.html
> Running:
> {noformat}
> mci -rf :infinispan-compatibility-mode-it
> {noformat}
> {noformat}
> Failed tests:
> ByteArrayKeyDistEmbeddedHotRodTest.setup:27 » IllegalState failed to create a ...
> ByteArrayKeyReplEmbeddedHotRodTest.setup:87 » IllegalState failed to create a ...
> ByteArrayValueDistEmbeddedHotRodTest.setup:27 » IllegalState failed to create ...
> ByteArrayValueReplEmbeddedHotRodTest.setup:87 » IllegalState failed to create ...
> DistEmbeddedRestHotRodTest.setup:25 » IllegalState failed to create a child ev...
> DistL1EmbeddedHotRodTest.setup:30 » IllegalState failed to create a child even...
> DistMemcachedEmbeddedTest.setup:39 » IllegalState failed to create a child eve...
> org.infinispan.it.compatibility.EmbeddedHotRodCacheListenerTest.setup(org.infinispan.it.compatibility.EmbeddedHotRodCacheListenerTest)
> Run 1: EmbeddedHotRodCacheListenerTest.setup:36 » IllegalState failed to create a chi...
> Run 2: PASS
> Run 3: PASS
> EmbeddedHotRodTest.testEventFilteringStatic:274->lambda$testEventFilteringStatic$4:276 » Transport
> EmbeddedMemcachedCacheListenerTest.setup:39 » IllegalState failed to create a ...
> EmbeddedRestMemcachedHotRodTest.setup:50 » IllegalState failed to create a chi...
> ReplEmbeddedRestHotRodTest.setup:38 » IllegalState failed to create a child ev...
> Tests run: 101, Failures: 12, Errors: 0, Skipped: 47
> {noformat}
> Errors are all about a similar stacktrace.
> {noformat}
> java.lang.IllegalStateException: failed to create a child event loop
> at io.netty.util.concurrent.MultithreadEventExecutorGroup.<init>(MultithreadEventExecutorGroup.java:88)
> at io.netty.util.concurrent.MultithreadEventExecutorGroup.<init>(MultithreadEventExecutorGroup.java:58)
> at io.netty.channel.MultithreadEventLoopGroup.<init>(MultithreadEventLoopGroup.java:51)
> at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:87)
> at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:82)
> at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:63)
> at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:51)
> at org.jboss.resteasy.plugins.server.netty.NettyJaxrsServer.start(NettyJaxrsServer.java:239)
> at org.infinispan.rest.NettyRestServer.start(NettyRestServer.java:81)
> at org.infinispan.it.compatibility.CompatibilityCacheFactory.createRestCache(CompatibilityCacheFactory.java:199)
> at org.infinispan.it.compatibility.CompatibilityCacheFactory.createRestMemcachedCaches(CompatibilityCacheFactory.java:137)
> at org.infinispan.it.compatibility.CompatibilityCacheFactory.setup(CompatibilityCacheFactory.java:123)
> at org.infinispan.it.compatibility.DistMemcachedEmbeddedTest.setup(DistMemcachedEmbeddedTest.java:39)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:84)
> at org.testng.internal.Invoker.invokeConfigurationMethod(Invoker.java:564)
> at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:213)
> at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:138)
> at org.testng.internal.TestMethodWorker.invokeBeforeClassMethods(TestMethodWorker.java:175)
> at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:107)
> at org.testng.TestRunner.privateRun(TestRunner.java:767)
> at org.testng.TestRunner.run(TestRunner.java:617)
> at org.testng.SuiteRunner.runTest(SuiteRunner.java:348)
> at org.testng.SuiteRunner.access$000(SuiteRunner.java:38)
> at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:382)
> at org.testng.internal.thread.ThreadUtil$2.call(ThreadUtil.java:64)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: io.netty.channel.ChannelException: failed to open a new selector
> at io.netty.channel.nio.NioEventLoop.openSelector(NioEventLoop.java:157)
> at io.netty.channel.nio.NioEventLoop.<init>(NioEventLoop.java:148)
> at io.netty.channel.nio.NioEventLoopGroup.newChild(NioEventLoopGroup.java:126)
> at io.netty.channel.nio.NioEventLoopGroup.newChild(NioEventLoopGroup.java:36)
> at io.netty.util.concurrent.MultithreadEventExecutorGroup.<init>(MultithreadEventExecutorGroup.java:84)
> ... 32 more
> Caused by: java.io.IOException: Too many open files
> at sun.nio.ch.EPollArrayWrapper.epollCreate(Native Method)
> at sun.nio.ch.EPollArrayWrapper.<init>(EPollArrayWrapper.java:130)
> at sun.nio.ch.EPollSelectorImpl.<init>(EPollSelectorImpl.java:69)
> at sun.nio.ch.EPollSelectorProvider.openSelector(EPollSelectorProvider.java:36)
> at io.netty.channel.nio.NioEventLoop.openSelector(NioEventLoop.java:155)
> ... 36 more
> {noformat}
> N.B.
> The failure is quite consistent on my workstation, almost always results in the same tests failing. Yet occasionally they all pass.
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
9 years, 1 month
[JBoss JIRA] (ISPN-7517) Investigate Netty's "Too many open files" exception in testing of infinispan-compatibility-mode-it
by Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-7517?page=com.atlassian.jira.plugin.... ]
Dan Berindei updated ISPN-7517:
-------------------------------
Status: Pull Request Sent (was: Open)
Git Pull Request: https://github.com/infinispan/infinispan/pull/4913
> Investigate Netty's "Too many open files" exception in testing of infinispan-compatibility-mode-it
> --------------------------------------------------------------------------------------------------
>
> Key: ISPN-7517
> URL: https://issues.jboss.org/browse/ISPN-7517
> Project: Infinispan
> Issue Type: Task
> Components: Test Suite - Server
> Reporter: Sanne Grinovero
> Assignee: Dan Berindei
> Fix For: 9.0.0.Final
>
>
> See also discussion on ML:
> - http://lists.jboss.org/pipermail/infinispan-dev/2017-February/017232.html
> Running:
> {noformat}
> mci -rf :infinispan-compatibility-mode-it
> {noformat}
> {noformat}
> Failed tests:
> ByteArrayKeyDistEmbeddedHotRodTest.setup:27 » IllegalState failed to create a ...
> ByteArrayKeyReplEmbeddedHotRodTest.setup:87 » IllegalState failed to create a ...
> ByteArrayValueDistEmbeddedHotRodTest.setup:27 » IllegalState failed to create ...
> ByteArrayValueReplEmbeddedHotRodTest.setup:87 » IllegalState failed to create ...
> DistEmbeddedRestHotRodTest.setup:25 » IllegalState failed to create a child ev...
> DistL1EmbeddedHotRodTest.setup:30 » IllegalState failed to create a child even...
> DistMemcachedEmbeddedTest.setup:39 » IllegalState failed to create a child eve...
> org.infinispan.it.compatibility.EmbeddedHotRodCacheListenerTest.setup(org.infinispan.it.compatibility.EmbeddedHotRodCacheListenerTest)
> Run 1: EmbeddedHotRodCacheListenerTest.setup:36 » IllegalState failed to create a chi...
> Run 2: PASS
> Run 3: PASS
> EmbeddedHotRodTest.testEventFilteringStatic:274->lambda$testEventFilteringStatic$4:276 » Transport
> EmbeddedMemcachedCacheListenerTest.setup:39 » IllegalState failed to create a ...
> EmbeddedRestMemcachedHotRodTest.setup:50 » IllegalState failed to create a chi...
> ReplEmbeddedRestHotRodTest.setup:38 » IllegalState failed to create a child ev...
> Tests run: 101, Failures: 12, Errors: 0, Skipped: 47
> {noformat}
> Errors are all about a similar stacktrace.
> {noformat}
> java.lang.IllegalStateException: failed to create a child event loop
> at io.netty.util.concurrent.MultithreadEventExecutorGroup.<init>(MultithreadEventExecutorGroup.java:88)
> at io.netty.util.concurrent.MultithreadEventExecutorGroup.<init>(MultithreadEventExecutorGroup.java:58)
> at io.netty.channel.MultithreadEventLoopGroup.<init>(MultithreadEventLoopGroup.java:51)
> at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:87)
> at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:82)
> at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:63)
> at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:51)
> at org.jboss.resteasy.plugins.server.netty.NettyJaxrsServer.start(NettyJaxrsServer.java:239)
> at org.infinispan.rest.NettyRestServer.start(NettyRestServer.java:81)
> at org.infinispan.it.compatibility.CompatibilityCacheFactory.createRestCache(CompatibilityCacheFactory.java:199)
> at org.infinispan.it.compatibility.CompatibilityCacheFactory.createRestMemcachedCaches(CompatibilityCacheFactory.java:137)
> at org.infinispan.it.compatibility.CompatibilityCacheFactory.setup(CompatibilityCacheFactory.java:123)
> at org.infinispan.it.compatibility.DistMemcachedEmbeddedTest.setup(DistMemcachedEmbeddedTest.java:39)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:84)
> at org.testng.internal.Invoker.invokeConfigurationMethod(Invoker.java:564)
> at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:213)
> at org.testng.internal.Invoker.invokeConfigurations(Invoker.java:138)
> at org.testng.internal.TestMethodWorker.invokeBeforeClassMethods(TestMethodWorker.java:175)
> at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:107)
> at org.testng.TestRunner.privateRun(TestRunner.java:767)
> at org.testng.TestRunner.run(TestRunner.java:617)
> at org.testng.SuiteRunner.runTest(SuiteRunner.java:348)
> at org.testng.SuiteRunner.access$000(SuiteRunner.java:38)
> at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:382)
> at org.testng.internal.thread.ThreadUtil$2.call(ThreadUtil.java:64)
> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: io.netty.channel.ChannelException: failed to open a new selector
> at io.netty.channel.nio.NioEventLoop.openSelector(NioEventLoop.java:157)
> at io.netty.channel.nio.NioEventLoop.<init>(NioEventLoop.java:148)
> at io.netty.channel.nio.NioEventLoopGroup.newChild(NioEventLoopGroup.java:126)
> at io.netty.channel.nio.NioEventLoopGroup.newChild(NioEventLoopGroup.java:36)
> at io.netty.util.concurrent.MultithreadEventExecutorGroup.<init>(MultithreadEventExecutorGroup.java:84)
> ... 32 more
> Caused by: java.io.IOException: Too many open files
> at sun.nio.ch.EPollArrayWrapper.epollCreate(Native Method)
> at sun.nio.ch.EPollArrayWrapper.<init>(EPollArrayWrapper.java:130)
> at sun.nio.ch.EPollSelectorImpl.<init>(EPollSelectorImpl.java:69)
> at sun.nio.ch.EPollSelectorProvider.openSelector(EPollSelectorProvider.java:36)
> at io.netty.channel.nio.NioEventLoop.openSelector(NioEventLoop.java:155)
> ... 36 more
> {noformat}
> N.B.
> The failure is quite consistent on my workstation, almost always results in the same tests failing. Yet occasionally they all pass.
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
9 years, 1 month
[JBoss JIRA] (ISPN-7070) CacheNotifierImplInitialTransferDistTest.testIterationBeganAndSegmentNotComplete random failures
by William Burns (JIRA)
[ https://issues.jboss.org/browse/ISPN-7070?page=com.atlassian.jira.plugin.... ]
Work on ISPN-7070 started by William Burns.
-------------------------------------------
> CacheNotifierImplInitialTransferDistTest.testIterationBeganAndSegmentNotComplete random failures
> ------------------------------------------------------------------------------------------------
>
> Key: ISPN-7070
> URL: https://issues.jboss.org/browse/ISPN-7070
> Project: Infinispan
> Issue Type: Bug
> Components: Core, Test Suite - Core
> Affects Versions: 9.0.0.Alpha4
> Reporter: Dan Berindei
> Assignee: William Burns
> Priority: Critical
> Labels: testsuite_stability
> Fix For: 9.0.0.Final
>
> Attachments: CacheNotifierImplInitialTransferDistTest_ISPN-5467_CompletableFuture-like_API_20161003.log
>
>
> Looks like sometimes the originator listener ignores the CACHE_ENTRY_REMOVED notification:
> {noformat}
> 09:58:57,877 INFO (testng-Test:[]) [TestSuiteProgress] Test starting: org.infinispan.notifications.cachelistener.CacheNotifierImplInitialTransferDistTest.testRemoveAfterIterationBeganAndSegmentNotCompleteValueNonOwnerClustered
> 09:58:58,913 DEBUG (testng-Test:[]) [Test] Found key key-to-change-0 with primary owner != Test-NodeA-7051, segment 60
> 09:58:58,930 TRACE (remote-thread-Test-NodeA-p23726-t6:[]) [ReadCommittedEntry] Updating entry (key=key-to-change-0 removed=false valid=true changed=true created=true value=initial-value metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, providedMetadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null})
> 09:58:58,972 TRACE (remote-thread-Test-NodeC-p23887-t6:[]) [ReadCommittedEntry] Updating entry (key=key-to-change-0 removed=false valid=true changed=true created=true value=initial-value metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null}, providedMetadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=null})
> 09:58:59,014 TRACE (ForkThread-1,Test:[]) [Test] Adding segment listener 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1 : org.infinispan.notifications.cachelistener.DistributedQueueingSegmentListener@68007f8
> 09:58:59,014 TRACE (ForkThread-1,Test:[]) [CacheNotifierImpl] Replicating cluster listener to other nodes [Test-NodeA-7051, Test-NodeB-10318, Test-NodeC-52778] for cluster listener with id 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1
> 09:58:58,998 TRACE (testng-Test:[]) [CheckPoint] Waiting for event pre_complete_segment_invoked * 1
> 09:58:59,063 TRACE (remote-thread-Test-NodeC-p23887-t6:[]) [ClusterListenerReplicateCallable] Registered local cluster listener for remote cluster listener from origin Test-NodeA-7051 with id 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1
> 09:58:59,098 TRACE (remote-thread-Test-NodeB-p23775-t6:[]) [ClusterListenerReplicateCallable] Registered local cluster listener for remote cluster listener from origin Test-NodeA-7051 with id 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1
> 09:58:59,145 TRACE (ForkThread-1,Test:[]) [CacheNotifierImpl] Listener 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1 requests initial state for cache
> 09:58:59,373 TRACE (ForkThread-1,Test:[]) [Test] Completed segments [48, 2, 229, 118, 71, 72, 233, 60]
> 09:58:59,373 TRACE (ForkThread-1,Test:[]) [Test] Listener received event EventImpl{type=CACHE_ENTRY_CREATED, pre=false, cache=Cache 'DistInitialTransferListener'@Test-NodeA-7051, key=key-to-change-0, value=initial-value, oldValue=null, transaction=null, originLocal=true, transactionSuccessful=false, entries=null, created=false}
> 09:58:59,373 TRACE (ForkThread-1,Test:[]) [Test] Notified for key key-to-change-0
> 09:58:59,373 TRACE (ForkThread-1,Test:[]) [CheckPoint] Triggering event pre_complete_segment_invoked * 1 (available = 1, total = 1)
> 09:58:59,373 TRACE (ForkThread-1,Test:[]) [CheckPoint] Waiting for event pre_complete_segment_released * 1
> 09:58:59,373 TRACE (testng-Test:[]) [CheckPoint] Received event pre_complete_segment_invoked * 1 (available = 0, total = 1)
> 09:58:59,577 TRACE (remote-thread-Test-NodeA-p23726-t6:[]) [ReadCommittedEntry] Updating entry (key=key-to-change-0 removed=true valid=false changed=true created=false value=initial-value metadata=EmbeddedMetadata{version=null}, providedMetadata=null)
> 09:58:59,661 TRACE (remote-thread-Test-NodeC-p23887-t5:[]) [ReadCommittedEntry] Updating entry (key=key-to-change-0 removed=true valid=false changed=true created=false value=initial-value metadata=EmbeddedMetadata{version=null}, providedMetadata=null)
> 09:58:59,661 TRACE (remote-thread-Test-NodeC-p23887-t5:[]) [RequestCorrelator] Test-NodeC-52778: invoking unicast RPC [req-id=91126] on Test-NodeA-7051
> 09:58:59,684 TRACE (OOB-2,Test-NodeA-7051:[]) [RequestCorrelator] calling (org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher) with request 91126
> 09:58:59,779 TRACE (remote-thread-Test-NodeA-p23726-t6:[]) [NonTotalOrderPerCacheInboundInvocationHandler] Calling perform() on DistributedExecuteCommand [cache=Cache 'DistInitialTransferListener'@Test-NodeA-7051, keys=[], callable=org.infinispan.notifications.cachelistener.cluster.ClusterEventCallable@640b0234]
> 09:58:59,780 TRACE (remote-thread-Test-NodeA-p23726-t6:[]) [ClusterEventCallable] Received cluster event(s) [ClusterEvent {type=CACHE_ENTRY_REMOVED, cache=Cache 'DistInitialTransferListener'@Test-NodeA-7051, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, retryCommand=false, origin=Test-NodeC-52778}], notifying cluster listener with id 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1
> 09:58:59,837 TRACE (testng-Test:[]) [CheckPoint] Triggering event pre_complete_segment_released * 999999999 (available = 999999999, total = 999999999)
> 09:58:59,837 TRACE (ForkThread-1,Test:[]) [CheckPoint] Received event pre_complete_segment_released * 1 (available = 999999998, total = 999999999)
> 09:58:59,898 TRACE (ForkThread-1,Test:[]) [CacheNotifierImpl] Listener 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1 initial state for cache completed
> 09:58:59,916 TRACE (remote-thread-Test-NodeB-p23775-t6:[]) [ClusterListenerRemoveCallable] Removing local cluster listener due to parent cluster listener was removed : 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1
> 09:58:59,921 TRACE (remote-thread-Test-NodeC-p23887-t5:[]) [ClusterListenerRemoveCallable] Removing local cluster listener due to parent cluster listener was removed : 2a41ec3f-c79f-4b7d-bd0e-8754170d8fc1
> 09:58:59,943 ERROR (testng-Test:[]) [TestSuiteProgress] Test failed: org.infinispan.notifications.cachelistener.CacheNotifierImplInitialTransferDistTest.testRemoveAfterIterationBeganAndSegmentNotCompleteValueNonOwnerClustered
> java.lang.AssertionError: expected [12] but found [11]
> {noformat}
> {{CacheNotifierImplInitialTransferDistTest}} also had a different problem: it replaced the {{CacheNotifier}} component with a clone before adding the listener, but replaced it again with the original before removing the listener. Because the listener's uuid was only registered in the clone, {{removeListener}} couldn't find the uuid and disn't try to remove the listener on the other nodes. This meant the listener was leaked, resulting in logs like this:
> {noformat}
> 20:12:04,098 TRACE (remote-thread-Test-NodeB-p24127-t6:[]) [ReadCommittedEntry] Updating entry (key=key-to-change-0 removed=true valid=false changed=true created=false value=initial-value metadata=EmbeddedMetadata{version=null}, providedMetadata=null)
> 20:12:04,099 TRACE (remote-thread-Test-NodeB-p24127-t6:[]) [RemoteClusterListener] Passing Event to manager EventImpl{type=CACHE_ENTRY_REMOVED, pre=false, cache=Cache 'DistInitialTransferListener'@Test-NodeB-56142, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, originLocal=false, transactionSuccessful=false, entries=null, created=false} to send to Test-NodeA-38047
> 20:12:04,100 TRACE (remote-thread-Test-NodeB-p24127-t6:[]) [RemoteClusterListener] Passing Event to manager EventImpl{type=CACHE_ENTRY_REMOVED, pre=false, cache=Cache 'DistInitialTransferListener'@Test-NodeB-56142, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, originLocal=false, transactionSuccessful=false, entries=null, created=false} to send to Test-NodeA-38047
> 20:12:04,100 TRACE (remote-thread-Test-NodeB-p24127-t6:[]) [RemoteClusterListener] Passing Event to manager EventImpl{type=CACHE_ENTRY_REMOVED, pre=false, cache=Cache 'DistInitialTransferListener'@Test-NodeB-56142, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, originLocal=false, transactionSuccessful=false, entries=null, created=false} to send to Test-NodeA-38047
> 20:12:04,100 TRACE (remote-thread-Test-NodeB-p24127-t6:[]) [RemoteClusterListener] Passing Event to manager EventImpl{type=CACHE_ENTRY_REMOVED, pre=false, cache=Cache 'DistInitialTransferListener'@Test-NodeB-56142, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, originLocal=false, transactionSuccessful=false, entries=null, created=false} to send to Test-NodeA-38047
> 20:12:04,100 TRACE (remote-thread-Test-NodeB-p24127-t6:[]) [RemoteClusterListener] Passing Event to manager EventImpl{type=CACHE_ENTRY_REMOVED, pre=false, cache=Cache 'DistInitialTransferListener'@Test-NodeB-56142, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, originLocal=false, transactionSuccessful=false, entries=null, created=false} to send to Test-NodeA-38047
> 20:12:04,106 TRACE (remote-thread-Test-NodeA-p24103-t6:[]) [MultiClusterEventCallable] Received multiple cluster event(s) {86f77630-b1bb-4a21-97bb-b03efeae39d6=[ClusterEvent {type=CACHE_ENTRY_REMOVED, cache=Cache 'DistInitialTransferListener'@Test-NodeA-38047, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, retryCommand=false, origin=Test-NodeB-56142}], 91d05a50-4a35-4e37-8c5c-bffbabc6154b=[ClusterEvent {type=CACHE_ENTRY_REMOVED, cache=Cache 'DistInitialTransferListener'@Test-NodeA-38047, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, retryCommand=false, origin=Test-NodeB-56142}], ba09480f-c698-431b-8fe6-213f1bdefc7b=[ClusterEvent {type=CACHE_ENTRY_REMOVED, cache=Cache 'DistInitialTransferListener'@Test-NodeA-38047, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, retryCommand=false, origin=Test-NodeB-56142}], 992da014-0516-4f2a-8093-50ba3b1f358a=[ClusterEvent {type=CACHE_ENTRY_REMOVED, cache=Cache 'DistInitialTransferListener'@Test-NodeA-38047, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, retryCommand=false, origin=Test-NodeB-56142}], b4eeb9b3-85c4-4ff9-865e-076b7cf93faa=[ClusterEvent {type=CACHE_ENTRY_REMOVED, cache=Cache 'DistInitialTransferListener'@Test-NodeA-38047, key=key-to-change-0, value=null, oldValue=initial-value, transaction=null, retryCommand=false, origin=Test-NodeB-56142}]}
> {noformat}
--
This message was sent by Atlassian JIRA
(v7.2.3#72005)
9 years, 1 month