Pavel Slavicek <pslavice@redhat.com> changed the Status of bug 916988 from VERIFIED to CLOSED

Richard Janík <rjanik@redhat.com> changed the Status of bug 916988 from ON_QA to VERIFIED

Paul Ferraro <paul.ferraro@redhat.com> changed the Status of bug 916988 from NEW to ON_QA

Paul Ferraro <paul.ferraro@redhat.com> made a comment on bug 916988

N.B. L1 cache is not enabled by default in DIST caches in EAP 6.1, so this would only affect people who enable it explicitly.

Radim Vansa <rvansa@redhat.com> changed the Status of bug 892565 from ON_QA to VERIFIED

Tristan Tarrant <ttarrant@redhat.com> changed the Status of bug 892565 from MODIFIED to ON_QA

Tristan Tarrant <ttarrant@redhat.com> changed the Status of bug 892565 from ASSIGNED to MODIFIED

Ladislav Thon <lthon@redhat.com> made a comment on bug 916988

Still seeing this with EAP 6.1.0.ER8. For example:

https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-http-session-netDown-repl-sync/11/artifact/report/config/jboss-perf19/server.log
https://jenkins.mw.lab.eng.bos.redhat.com/hudson/job/eap-6x-failover-http-session-netDown-repl-async/11/artifact/report/config/jboss-perf20/server.log

Ladislav Thon <lthon@redhat.com> made a comment on bug 916988

ISPN-2589 affects EAP 6.1.0.ER1:

WARN [org.infinispan.topology.CacheTopologyControlCommand] (OOB-18,shared=udp) ISPN000071: Caught exception when handling command CacheTopologyControlCommand{cache=org.jboss.test.clusterbench.ejb.stateful.RemoteStatefulSBImpl, type=CH_UPDATE, sender=perf21/ejb, joinInfo=null, topologyId=9, currentCH=ReplicatedConsistentHash

, pendingCH=null, throwable=null, viewId=5}: java.lang.NullPointerException
at org.infinispan.commands.write.InvalidateL1Command.perform(InvalidateL1Command.java:109)
at org.infinispan.interceptors.CallInterceptor.handleDefault(CallInterceptor.java:110)
at org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
at org.infinispan.commands.AbstractVisitor.visitInvalidateL1Command(AbstractVisitor.java:146)
at org.infinispan.commands.write.InvalidateL1Command.acceptVisitor(InvalidateL1Command.java:192)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
at org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
at org.infinispan.commands.AbstractVisitor.visitInvalidateL1Command(AbstractVisitor.java:146)
at org.infinispan.commands.write.InvalidateL1Command.acceptVisitor(InvalidateL1Command.java:192)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
at org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
at org.infinispan.commands.AbstractVisitor.visitInvalidateL1Command(AbstractVisitor.java:146)
at org.infinispan.commands.write.InvalidateL1Command.acceptVisitor(InvalidateL1Command.java:192)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
at org.infinispan.interceptors.CacheLoaderInterceptor.visitInvalidateCommand(CacheLoaderInterceptor.java:128)
at org.infinispan.commands.AbstractVisitor.visitInvalidateL1Command(AbstractVisitor.java:146)
at org.infinispan.commands.write.InvalidateL1Command.acceptVisitor(InvalidateL1Command.java:192)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
at org.infinispan.interceptors.EntryWrappingInterceptor.invokeNextAndApplyChanges(EntryWrappingInterceptor.java:275)
at org.infinispan.interceptors.EntryWrappingInterceptor.visitInvalidateL1Command(EntryWrappingInterceptor.java:158)
at org.infinispan.commands.write.InvalidateL1Command.acceptVisitor(InvalidateL1Command.java:192)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitInvalidateL1Command(AbstractLockingInterceptor.java:98)
at org.infinispan.commands.write.InvalidateL1Command.acceptVisitor(InvalidateL1Command.java:192)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
at org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
at org.infinispan.commands.AbstractVisitor.visitInvalidateL1Command(AbstractVisitor.java:146)
at org.infinispan.commands.write.InvalidateL1Command.acceptVisitor(InvalidateL1Command.java:192)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
at org.infinispan.interceptors.MarshalledValueInterceptor.visitInvalidateCommand(MarshalledValueInterceptor.java:296)
at org.infinispan.commands.AbstractVisitor.visitInvalidateL1Command(AbstractVisitor.java:146)
at org.infinispan.commands.write.InvalidateL1Command.acceptVisitor(InvalidateL1Command.java:192)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
at org.infinispan.interceptors.TxInterceptor.enlistWriteAndInvokeNext(TxInterceptor.java:251)
at org.infinispan.interceptors.TxInterceptor.visitInvalidateCommand(TxInterceptor.java:221)
at org.infinispan.commands.AbstractVisitor.visitInvalidateL1Command(AbstractVisitor.java:146)
at org.infinispan.commands.write.InvalidateL1Command.acceptVisitor(InvalidateL1Command.java:192)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
at org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
at org.infinispan.commands.AbstractVisitor.visitInvalidateL1Command(AbstractVisitor.java:146)
at org.infinispan.commands.write.InvalidateL1Command.acceptVisitor(InvalidateL1Command.java:192)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
at org.infinispan.statetransfer.StateTransferInterceptor.visitInvalidateL1Command(StateTransferInterceptor.java:173)
at org.infinispan.commands.write.InvalidateL1Command.acceptVisitor(InvalidateL1Command.java:192)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
at org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
at org.infinispan.commands.AbstractVisitor.visitInvalidateL1Command(AbstractVisitor.java:146)
at org.infinispan.commands.write.InvalidateL1Command.acceptVisitor(InvalidateL1Command.java:192)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
at org.infinispan.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:128)
at org.infinispan.interceptors.InvocationContextInterceptor.handleDefault(InvocationContextInterceptor.java:92)
at org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
at org.infinispan.commands.AbstractVisitor.visitInvalidateL1Command(AbstractVisitor.java:146)
at org.infinispan.commands.write.InvalidateL1Command.acceptVisitor(InvalidateL1Command.java:192)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
at org.infinispan.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:132)
at org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
at org.infinispan.commands.AbstractVisitor.visitInvalidateL1Command(AbstractVisitor.java:146)
at org.infinispan.commands.write.InvalidateL1Command.acceptVisitor(InvalidateL1Command.java:192)
at org.infinispan.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:118)
at org.infinispan.interceptors.BatchingInterceptor.handleDefault(BatchingInterceptor.java:85)
at org.infinispan.commands.AbstractVisitor.visitInvalidateCommand(AbstractVisitor.java:141)
at org.infinispan.commands.AbstractVisitor.visitInvalidateL1Command(AbstractVisitor.java:146)
at org.infinispan.commands.write.InvalidateL1Command.acceptVisitor(InvalidateL1Command.java:192)
at org.infinispan.interceptors.InterceptorChain.invoke(InterceptorChain.java:343)
at org.infinispan.statetransfer.StateConsumerImpl.invalidateSegments(StateConsumerImpl.java:834)
at org.infinispan.statetransfer.StateConsumerImpl.onTopologyUpdate(StateConsumerImpl.java:319)
at org.infinispan.statetransfer.StateTransferManagerImpl.doTopologyUpdate(StateTransferManagerImpl.java:194)
at org.infinispan.statetransfer.StateTransferManagerImpl.access$000(StateTransferManagerImpl.java:60)
at org.infinispan.statetransfer.StateTransferManagerImpl$1.updateConsistentHash(StateTransferManagerImpl.java:120)
at org.infinispan.topology.LocalTopologyManagerImpl.handleConsistentHashUpdate(LocalTopologyManagerImpl.java:194)
at org.infinispan.topology.CacheTopologyControlCommand.doPerform(CacheTopologyControlCommand.java:165)
at org.infinispan.topology.CacheTopologyControlCommand.perform(CacheTopologyControlCommand.java:137)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommandFromLocalCluster(CommandAwareRpcDispatcher.java:253)
at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:220)
at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:484)
at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:391)
at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:249)
at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:598)
at org.jgroups.blocks.mux.MuxUpHandler.up(MuxUpHandler.java:130)
at org.jgroups.JChannel.up(JChannel.java:707)
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:1020)
at org.jgroups.protocols.RSVP.up(RSVP.java:172)
at org.jgroups.protocols.FRAG2.up(FRAG2.java:181)
at org.jgroups.protocols.FlowControl.up(FlowControl.java:400)
at org.jgroups.protocols.FlowControl.up(FlowControl.java:418)
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:896)
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:245)
at org.jgroups.protocols.UNICAST2.up(UNICAST2.java:453)
at org.jgroups.protocols.pbcast.NAKACK2.handleMessage(NAKACK2.java:721)
at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:574)
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:143)
at org.jgroups.protocols.FD.up(FD.java:253)
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:288)
at org.jgroups.protocols.MERGE3.up(MERGE3.java:290)
at org.jgroups.protocols.Discovery.up(Discovery.java:359)
at org.jgroups.protocols.TP$ProtocolAdapter.up(TP.java:2616)
at org.jgroups.protocols.TP.passMessageUp(TP.java:1263)
at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1825)
at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1798)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [rt.jar:1.6.0_38]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [rt.jar:1.6.0_38]
at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_38]

Seen in https://jenkins.mw.lab.eng.bos.redhat.com/hudson/view/EAP6/view/EAP6-Clustering/view/EAP6-Failover/job/eap-6x-failover-ejb-ejbremote-netDown-repl-async/10/console-perf19/

On cache leave (shutdown) the node sometimes receives the new CH in which all its data segments are removed and it will (needlessly) attempt to discard that data (or move it to L1 if enabled) but fails due to NPE because some cache components are already shut down (DistributionManager). This affects both DIST and REPL caches because the state transfer code is common but it was never expected that segments are ever removed in a REPL cache (can happen only during shutdown). This last CH update is irrelevant and is not always received, thus not always reproducible and failing to process it is just logged as a warning. The best way to fix this is to ensure LocalTopologyManager does not deliver CH updates after leave.

It seems this exception is actually a warning logged during cache shutdown. The exception is benign and is never propagated to user code. All we can do about it is add a simple check to prevent it happening.

And one more occurence in 5.2.0.CR2 with DIST_SYNC mode, now originating in JGroups stack:
https://jenkins.mw.lab.eng.bos.redhat.com/hudson/view/EDG6/view/EDG-REPORTS-PERF/job/jdg-cs-perf-client-stress-test-hotrod/3/artifact/report/size8/loganalysis/server/categories/cat8_entry0.txt

Works. Thanks!

No probs. Does the link http://dev39.mw.lab.eng.bos.redhat.com/~mlinhard/hyperion3/run0037-startup-ER9/report/loganalysis/server/categories/cat8_entry0.txt work for you ? if not I'll paste here

And the NPE is thrown from exactly the same line from InvalidateL1Command? (sorry to ask so many details - cannot access the qa machine for logs)

from attached file standalone_node0001.xml:

      <subsystem default-cache-container="default" xmlns="urn:jboss:datagrid:infinispan:6.1">
         <cache-container default-cache="testCache" name="default">
            <transport executor="infinispan-transport" lock-timeout="600000"/>

            <distributed-cache batching="false" indexing="NONE" l1-lifespan="0" mode="SYNC" name="testCache" owners="2" remote-timeout="60000" segments="40" start="EAGER">
               <locking acquire-timeout="3000" concurrency-level="1000" isolation="REPEATABLE_READ" striping="false"/>
               <transaction mode="NONE"/>
               <state-transfer enabled="true" timeout="600000"/>
               <eviction max-entries="-1" strategy="NONE"/>
            </distributed-cache>
         </cache-container>
      </subsystem>

Can't access www.qa.jboss.com even with the vpn. So what cache mode is it if not REPL_SYNC?

This is my config: http://www.qa.jboss.com/~mlinhard/hyperion3/run0037-startup-ER9/report/configs.zip
added standalone_node0001.xml

sorry this is not REPL_SYNC case, should this be a new JIRA ?

Occurence in JDG 6.1.0.ER9 (infinispan 5.2.0.CR2):
http://www.qa.jboss.com/~mlinhard/hyperion3/run0037-startup-ER9/report/loganalysis/server/categories/cat8_entry0.txt

Indeed, this being a repl cache there should be no L1 logic. But even if L1 invalidation logic exist (and it's there because same code is used for dist mode) it should be harmless because that code path should never be reached since in repl mode no segments are ever removed. So I'm thinking the whole issue is an anomaly that disappears after we solve ISPN-2691.

this is a replicated cache though, L1 logic should not be present at all.

This can happen if the node already has some keys in the container, although it is not a member of current CH. See ISPN-2691.