[JBoss JIRA] (ISPN-7070) CacheNotifierImplInitialTransferDistTest.testIterationBeganAndSegmentNotComplete random failures
by Dan Berindei (JIRA)
Dan Berindei created ISPN-7070:
----------------------------------
Summary: 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
Fix For: 9.0.0.Beta1
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
(v6.4.11#64026)
9 years, 6 months
[JBoss JIRA] (ISPN-7069) OOM on PutKeyValueCommand in invalidation mode with Redis cache store
by Vladimir Dzhuvinov (JIRA)
[ https://issues.jboss.org/browse/ISPN-7069?page=com.atlassian.jira.plugin.... ]
Vladimir Dzhuvinov updated ISPN-7069:
-------------------------------------
Description:
We've been working on isolating the cause of an exception we got last week with a Redis cache store (reported here [1]) when we started getting this OOM exception in the automated test trying to reproduce the exception:
{{3217 [ERROR] InvocationContextInterceptor: ISPN000136: Error executing command PutKeyValueCommand, writing keys [["f-P6nC1W28lLgXGzg6YZY5emzxvIjhsrAJjnpz9MIzE",1]]
org.infinispan.remoting.RemoteException: ISPN000217: Received exception from reload-43448, see cause for remote stack trace
at org.infinispan.remoting.transport.AbstractTransport.checkResponse(AbstractTransport.java:44) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
at org.infinispan.remoting.transport.jgroups.JGroupsTransport.checkRsp(JGroupsTransport.java:795) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
at org.infinispan.remoting.transport.jgroups.JGroupsTransport.lambda$invokeRemotelyAsync$1(JGroupsTransport.java:642) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602) ~[?:1.8.0_91]
at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577) ~[?:1.8.0_91]
at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[?:1.8.0_91]
at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962) ~[?:1.8.0_91]
at org.infinispan.remoting.transport.jgroups.RspListFuture.futureDone(RspListFuture.java:31) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
at org.jgroups.blocks.Request.checkCompletion(Request.java:162) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.GroupRequest.receiveResponse(GroupRequest.java:136) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:373) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:237) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:695) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.JChannel.up(JChannel.java:738) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1030) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FRAG2.up(FRAG2.java:165) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:392) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:381) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:1043) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.UNICAST3.deliverMessage(UNICAST3.java:1064) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.UNICAST3.handleDataReceived(UNICAST3.java:779) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.UNICAST3.up(UNICAST3.java:426) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:652) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:155) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:200) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:310) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.MERGE3.up(MERGE3.java:285) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.Discovery.up(Discovery.java:296) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.TP.passMessageUp(TP.java:1590) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.TP$SingleMessageHandler.run(TP.java:1802) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[?:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[?:1.8.0_91]
at java.lang.Thread.run(Thread.java:745) ~[?:1.8.0_91]
Caused by: org.infinispan.commons.CacheException: Problems invoking command.
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:189) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:402) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:352) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:237) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:695) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.JChannel.up(JChannel.java:738) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1030) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FRAG2.up(FRAG2.java:165) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:381) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:392) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:1043) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.UNICAST3.up(UNICAST3.java:435) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.NAKACK2.deliver(NAKACK2.java:961) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.NAKACK2.handleMessage(NAKACK2.java:843) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:618) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
... 10 more
Caused by: java.lang.OutOfMemoryError: Java heap space}}
The cache is configured in invalidation mode, with eviction enabled. The OOM exception occurs immediately on cache start. The Redis store is empty, and preload is disabled.
[1] https://github.com/infinispan/infinispan-cachestore-redis/issues/2
was:
We've been working on isolating the cause of an exception we got last week with a Redis cache store (reported here [1]) when we started getting this OOM exception in the automated test:
{{3217 [ERROR] InvocationContextInterceptor: ISPN000136: Error executing command PutKeyValueCommand, writing keys [["f-P6nC1W28lLgXGzg6YZY5emzxvIjhsrAJjnpz9MIzE",1]]
org.infinispan.remoting.RemoteException: ISPN000217: Received exception from reload-43448, see cause for remote stack trace
at org.infinispan.remoting.transport.AbstractTransport.checkResponse(AbstractTransport.java:44) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
at org.infinispan.remoting.transport.jgroups.JGroupsTransport.checkRsp(JGroupsTransport.java:795) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
at org.infinispan.remoting.transport.jgroups.JGroupsTransport.lambda$invokeRemotelyAsync$1(JGroupsTransport.java:642) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602) ~[?:1.8.0_91]
at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577) ~[?:1.8.0_91]
at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[?:1.8.0_91]
at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962) ~[?:1.8.0_91]
at org.infinispan.remoting.transport.jgroups.RspListFuture.futureDone(RspListFuture.java:31) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
at org.jgroups.blocks.Request.checkCompletion(Request.java:162) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.GroupRequest.receiveResponse(GroupRequest.java:136) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:373) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:237) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:695) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.JChannel.up(JChannel.java:738) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1030) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FRAG2.up(FRAG2.java:165) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:392) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:381) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:1043) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.UNICAST3.deliverMessage(UNICAST3.java:1064) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.UNICAST3.handleDataReceived(UNICAST3.java:779) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.UNICAST3.up(UNICAST3.java:426) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:652) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:155) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:200) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:310) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.MERGE3.up(MERGE3.java:285) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.Discovery.up(Discovery.java:296) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.TP.passMessageUp(TP.java:1590) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.TP$SingleMessageHandler.run(TP.java:1802) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[?:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[?:1.8.0_91]
at java.lang.Thread.run(Thread.java:745) ~[?:1.8.0_91]
Caused by: org.infinispan.commons.CacheException: Problems invoking command.
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:189) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:402) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:352) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:237) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:695) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.JChannel.up(JChannel.java:738) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1030) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FRAG2.up(FRAG2.java:165) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:381) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:392) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:1043) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.UNICAST3.up(UNICAST3.java:435) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.NAKACK2.deliver(NAKACK2.java:961) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.NAKACK2.handleMessage(NAKACK2.java:843) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:618) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
... 10 more
Caused by: java.lang.OutOfMemoryError: Java heap space}}
The cache is configured in invalidation mode, with eviction enabled. The OOM exception occurs immediately on cache start. The Redis store is empty, and preload is disabled.
[1] https://github.com/infinispan/infinispan-cachestore-redis/issues/2
> OOM on PutKeyValueCommand in invalidation mode with Redis cache store
> ---------------------------------------------------------------------
>
> Key: ISPN-7069
> URL: https://issues.jboss.org/browse/ISPN-7069
> Project: Infinispan
> Issue Type: Bug
> Affects Versions: 8.2.4.Final
> Reporter: Vladimir Dzhuvinov
>
> We've been working on isolating the cause of an exception we got last week with a Redis cache store (reported here [1]) when we started getting this OOM exception in the automated test trying to reproduce the exception:
> {{3217 [ERROR] InvocationContextInterceptor: ISPN000136: Error executing command PutKeyValueCommand, writing keys [["f-P6nC1W28lLgXGzg6YZY5emzxvIjhsrAJjnpz9MIzE",1]]
> org.infinispan.remoting.RemoteException: ISPN000217: Received exception from reload-43448, see cause for remote stack trace
> at org.infinispan.remoting.transport.AbstractTransport.checkResponse(AbstractTransport.java:44) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
> at org.infinispan.remoting.transport.jgroups.JGroupsTransport.checkRsp(JGroupsTransport.java:795) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
> at org.infinispan.remoting.transport.jgroups.JGroupsTransport.lambda$invokeRemotelyAsync$1(JGroupsTransport.java:642) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
> at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602) ~[?:1.8.0_91]
> at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577) ~[?:1.8.0_91]
> at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[?:1.8.0_91]
> at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962) ~[?:1.8.0_91]
> at org.infinispan.remoting.transport.jgroups.RspListFuture.futureDone(RspListFuture.java:31) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
> at org.jgroups.blocks.Request.checkCompletion(Request.java:162) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.blocks.GroupRequest.receiveResponse(GroupRequest.java:136) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:373) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:237) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:695) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.JChannel.up(JChannel.java:738) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1030) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.FRAG2.up(FRAG2.java:165) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.FlowControl.up(FlowControl.java:392) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.FlowControl.up(FlowControl.java:381) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.pbcast.GMS.up(GMS.java:1043) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.UNICAST3.deliverMessage(UNICAST3.java:1064) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.UNICAST3.handleDataReceived(UNICAST3.java:779) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.UNICAST3.up(UNICAST3.java:426) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:652) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:155) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:200) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:310) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.MERGE3.up(MERGE3.java:285) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.Discovery.up(Discovery.java:296) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.TP.passMessageUp(TP.java:1590) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.TP$SingleMessageHandler.run(TP.java:1802) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[?:1.8.0_91]
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[?:1.8.0_91]
> at java.lang.Thread.run(Thread.java:745) ~[?:1.8.0_91]
> Caused by: org.infinispan.commons.CacheException: Problems invoking command.
> at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:189) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
> at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:402) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:352) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:237) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:695) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.JChannel.up(JChannel.java:738) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1030) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.FRAG2.up(FRAG2.java:165) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.FlowControl.up(FlowControl.java:381) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.FlowControl.up(FlowControl.java:392) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.pbcast.GMS.up(GMS.java:1043) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.UNICAST3.up(UNICAST3.java:435) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.pbcast.NAKACK2.deliver(NAKACK2.java:961) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.pbcast.NAKACK2.handleMessage(NAKACK2.java:843) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:618) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
> ... 10 more
> Caused by: java.lang.OutOfMemoryError: Java heap space}}
> The cache is configured in invalidation mode, with eviction enabled. The OOM exception occurs immediately on cache start. The Redis store is empty, and preload is disabled.
> [1] https://github.com/infinispan/infinispan-cachestore-redis/issues/2
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 6 months
[JBoss JIRA] (ISPN-7069) OOM on PutKeyValueCommand in invalidation mode with Redis cache store
by Vladimir Dzhuvinov (JIRA)
Vladimir Dzhuvinov created ISPN-7069:
----------------------------------------
Summary: OOM on PutKeyValueCommand in invalidation mode with Redis cache store
Key: ISPN-7069
URL: https://issues.jboss.org/browse/ISPN-7069
Project: Infinispan
Issue Type: Bug
Affects Versions: 8.2.4.Final
Reporter: Vladimir Dzhuvinov
We've been working on isolating the cause of an exception we got last week with a Redis cache store (reported here [1]) when we started getting this OOM exception in the automated test:
{{3217 [ERROR] InvocationContextInterceptor: ISPN000136: Error executing command PutKeyValueCommand, writing keys [["f-P6nC1W28lLgXGzg6YZY5emzxvIjhsrAJjnpz9MIzE",1]]
org.infinispan.remoting.RemoteException: ISPN000217: Received exception from reload-43448, see cause for remote stack trace
at org.infinispan.remoting.transport.AbstractTransport.checkResponse(AbstractTransport.java:44) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
at org.infinispan.remoting.transport.jgroups.JGroupsTransport.checkRsp(JGroupsTransport.java:795) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
at org.infinispan.remoting.transport.jgroups.JGroupsTransport.lambda$invokeRemotelyAsync$1(JGroupsTransport.java:642) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:602) ~[?:1.8.0_91]
at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577) ~[?:1.8.0_91]
at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[?:1.8.0_91]
at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962) ~[?:1.8.0_91]
at org.infinispan.remoting.transport.jgroups.RspListFuture.futureDone(RspListFuture.java:31) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
at org.jgroups.blocks.Request.checkCompletion(Request.java:162) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.GroupRequest.receiveResponse(GroupRequest.java:136) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:373) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:237) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:695) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.JChannel.up(JChannel.java:738) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1030) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FRAG2.up(FRAG2.java:165) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:392) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:381) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:1043) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.UNICAST3.deliverMessage(UNICAST3.java:1064) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.UNICAST3.handleDataReceived(UNICAST3.java:779) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.UNICAST3.up(UNICAST3.java:426) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:652) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:155) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:200) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:310) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.MERGE3.up(MERGE3.java:285) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.Discovery.up(Discovery.java:296) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.TP.passMessageUp(TP.java:1590) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.TP$SingleMessageHandler.run(TP.java:1802) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[?:1.8.0_91]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[?:1.8.0_91]
at java.lang.Thread.run(Thread.java:745) ~[?:1.8.0_91]
Caused by: org.infinispan.commons.CacheException: Problems invoking command.
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:189) ~[infinispan-core-8.2.4.Final.jar:8.2.4.Final]
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:402) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:352) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:237) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:695) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.JChannel.up(JChannel.java:738) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1030) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FRAG2.up(FRAG2.java:165) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:381) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.FlowControl.up(FlowControl.java:392) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:1043) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.UNICAST3.up(UNICAST3.java:435) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.NAKACK2.deliver(NAKACK2.java:961) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.NAKACK2.handleMessage(NAKACK2.java:843) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:618) ~[jgroups-3.6.7.Final.jar:3.6.7.Final]
... 10 more
Caused by: java.lang.OutOfMemoryError: Java heap space}}
The cache is configured in invalidation mode, with eviction enabled. The OOM exception occurs immediately on cache start. The Redis store is empty, and preload is disabled.
[1] https://github.com/infinispan/infinispan-cachestore-redis/issues/2
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
9 years, 6 months