Flood of null pointer exceptions (ISPN000136) reports for a period of time

[ajheres]

In our setup with two clusters, both running an Infinispan server managed by the Infinispan operator, we are suffering from a flood of reports, like this:

09:35:44,959 ERROR (jgroups-17365,xsite,_distributed-grid-0-39162:AccB)
[org.infinispan.interceptors.impl.InvocationContextInterceptor]
ISPN000136: Error executing command IracPutKeyValueCommand on Cache 'track-local',
writing keys [WrappedByteArray[\0\0\0\0\3\e\e\0-\0\0\0\0-\4\0\0\0-\8\0\e\c-\9\c\2\5\6\8\5\d\0\2\0\0 (36 bytes)]] java.lang.NullPointerException

The reports contain a number of keys, but the errors for these keys are repeated many times (hundreds per second). This happens during a few minutes.

The cache is configured as replicated with backup:

  clusterName: distributed-grid
  name: track-local
  template: |
    replicatedCache:
      backups:
        AccA:
          backup:
            strategy: "ASYNC"
              stateTransfer:
                chunkSize: "512"
                timeout: "2400000"
                maxRetries: "30"
                waitTime: "2000"
                mode: "AUTO"
      mode: "SYNC"
      statistics: "true"
      encoding:
        key:
          mediaType: "text/plain"
        value:
          mediaType: "application/octet-stream"
      expiration:
        lifespan: "-1"
        maxIdle: "1200000"
  updates:
    strategy: retain

The key/values in the store are continuously updated. +/- 1000 items in store. +/- 50 updates/s. One side is writing. Writing bandwidth is +/- 1KB/s.
I have the impression that it has to do with the backup. Tried all kind of cache and server settings, but the errors keep coming with intervals.
Can anyone help me further to solve this problem?

Server version: 15.2.1.Final.

[pruivo]

@ajheres Can you provide the full stack trace, please?

[pruivo]

Look up the other nodes. The node where the exception is originated has the stack traces and the other nodes don't.

[ajheres]

Couldn't find. Two servers are running. One on cluster A and one on cluster B. Only B is reporting (THE report).
Just to explain the names and numbers the report starts with (jgroups-21175,xsite,_distributed-grid-0-39162:AccB), here grid-0-39162 is the server on cluster B, and AccB is location name for cluster B.

Not a single log report on cluster A.

[pruivo]

Did you check the other site too? It makes it harder to fix without a stack trace 😱

[ajheres]

Finally I found the stack trace. It is most of the time obfuscated in the container log. I hope it helps, many thanks already for your interest.

10:11:07,354 ERROR (jgroups-2424,xsite,_distributed-grid-0-16496:AccA) [org.infinispan.interceptors.impl.InvocationContextInterceptor] ISPN000136: Error executing command IracPutKeyValueCommand on Cache 'track-fusion-fused', writing keys [WrappedByteArray[\a\4\0\d\2\c\9\6\-\9\2\1\2\-\4\7\0\5\-\9\d\9\b\-\4\3\7\d\4\d\4\f\5\4\a\e (36 bytes)]] java.lang.NullPointerException: Cannot invoke "org.infinispan.metadata.impl.IracMetadata.getVersion()" because "remoteMetadata" is null at org.infinispan.interceptors.impl.NonTxIracRemoteSiteInterceptor.validateRemoteUpdate(NonTxIracRemoteSiteInterceptor.java:153) at org.infinispan.interceptors.impl.NonTxIracRemoteSiteInterceptor.validateOnPrimary(NonTxIracRemoteSiteInterceptor.java:129) at org.infinispan.interceptors.impl.NonTxIracRemoteSiteInterceptor.visitIracPutKeyValueCommand(NonTxIracRemoteSiteInterceptor.java:75) at org.infinispan.commands.write.IracPutKeyValueCommand.acceptVisitor(IracPutKeyValueCommand.java:109) at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNextThenApply(BaseAsyncInterceptor.java:78) at org.infinispan.interceptors.distribution.BaseDistributionInterceptor.handleNonTxWriteCommand(BaseDistributionInterceptor.java:222) at org.infinispan.interceptors.distribution.NonTxDistributionInterceptor.visitIracPutKeyValueCommand(NonTxDistributionInterceptor.java:118) at org.infinispan.commands.write.IracPutKeyValueCommand.acceptVisitor(IracPutKeyValueCommand.java:109) at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNext(BaseAsyncInterceptor.java:58) at org.infinispan.interceptors.DDAsyncInterceptor.handleDefault(DDAsyncInterceptor.java:54) at org.infinispan.interceptors.DDAsyncInterceptor.visitIracPutKeyValueCommand(DDAsyncInterceptor.java:105) at org.infinispan.commands.write.IracPutKeyValueCommand.acceptVisitor(IracPutKeyValueCommand.java:109) at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNext(BaseAsyncInterceptor.java:58) at org.infinispan.interceptors.BaseAsyncInterceptor.asyncInvokeNext(BaseAsyncInterceptor.java:231) at org.infinispan.interceptors.impl.EntryWrappingInterceptor.setSkipRemoteGetsAndInvokeNextForDataCommand(EntryWrappingInterceptor.java:732) at org.infinispan.interceptors.impl.EntryWrappingInterceptor.visitIracPutKeyValueCommand(EntryWrappingInterceptor.java:342) at org.infinispan.commands.write.IracPutKeyValueCommand.acceptVisitor(IracPutKeyValueCommand.java:109) at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNext(BaseAsyncInterceptor.java:58) at org.infinispan.interceptors.DDAsyncInterceptor.handleDefault(DDAsyncInterceptor.java:54) at org.infinispan.interceptors.DDAsyncInterceptor.visitIracPutKeyValueCommand(DDAsyncInterceptor.java:105) at org.infinispan.commands.write.IracPutKeyValueCommand.acceptVisitor(IracPutKeyValueCommand.java:109) at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNextAndFinally(BaseAsyncInterceptor.java:154) at org.infinispan.interceptors.locking.AbstractLockingInterceptor.lambda$nonTxLockAndInvokeNext$0(AbstractLockingInterceptor.java:318) at org.infinispan.interceptors.SyncInvocationStage.andHandle(SyncInvocationStage.java:71) at org.infinispan.interceptors.locking.AbstractLockingInterceptor.nonTxLockAndInvokeNext(AbstractLockingInterceptor.java:313) at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitNonTxDataWriteCommand(AbstractLockingInterceptor.java:138) at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitIracPutKeyValueCommand(AbstractLockingInterceptor.java:112) at org.infinispan.commands.write.IracPutKeyValueCommand.acceptVisitor(IracPutKeyValueCommand.java:109) at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNextAndHandle(BaseAsyncInterceptor.java:187) at org.infinispan.statetransfer.StateTransferInterceptor.handleNonTxWriteCommand(StateTransferInterceptor.java:312) at org.infinispan.statetransfer.StateTransferInterceptor.visitIracPutKeyValueCommand(StateTransferInterceptor.java:101) at org.infinispan.commands.write.IracPutKeyValueCommand.acceptVisitor(IracPutKeyValueCommand.java:109) at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNextAndFinally(BaseAsyncInterceptor.java:154) at org.infinispan.interceptors.impl.CacheMgmtInterceptor.updateStoreStatistics(CacheMgmtInterceptor.java:236) at org.infinispan.interceptors.impl.CacheMgmtInterceptor.visitIracPutKeyValueCommand(CacheMgmtInterceptor.java:201) at org.infinispan.commands.write.IracPutKeyValueCommand.acceptVisitor(IracPutKeyValueCommand.java:109) at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNext(BaseAsyncInterceptor.java:58) at org.infinispan.interceptors.DDAsyncInterceptor.handleDefault(DDAsyncInterceptor.java:54) at org.infinispan.interceptors.DDAsyncInterceptor.visitIracPutKeyValueCommand(DDAsyncInterceptor.java:105) at org.infinispan.commands.write.IracPutKeyValueCommand.acceptVisitor(IracPutKeyValueCommand.java:109) at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNextAndExceptionally(BaseAsyncInterceptor.java:127) at org.infinispan.interceptors.impl.InvocationContextInterceptor.visitCommand(InvocationContextInterceptor.java:90) at org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invokeAsync(AsyncInterceptorChainImpl.java:211) at org.infinispan.cache.impl.InvocationHelper.doInvokeAsync(InvocationHelper.java:324) at org.infinispan.cache.impl.InvocationHelper.invokeAsync(InvocationHelper.java:157) at org.infinispan.xsite.ClusteredCacheBackupReceiver.removeKey(ClusteredCacheBackupReceiver.java:224) at org.infinispan.xsite.commands.remote.IracPutManyRequest$Expire.execute(IracPutManyRequest.java:186) at org.infinispan.xsite.commands.remote.IracPutManyRequest.executeOperation(IracPutManyRequest.java:61) at org.infinispan.xsite.commands.remote.IracUpdateKeyRequest.invokeInLocalCache(IracUpdateKeyRequest.java:24) at org.infinispan.xsite.commands.remote.XSiteCacheRequest.invokeInLocalSite(XSiteCacheRequest.java:55) at org.infinispan.remoting.inboundhandler.GlobalInboundInvocationHandler.handleFromRemoteSite(GlobalInboundInvocationHandler.java:100) at org.infinispan.remoting.transport.jgroups.JGroupsTransport.processRequest(JGroupsTransport.java:1539) at org.infinispan.remoting.transport.jgroups.JGroupsTransport.processMessage(JGroupsTransport.java:1461) at org.infinispan.remoting.transport.jgroups.JGroupsTransport$ChannelCallbacks.up(JGroupsTransport.java:1632) at org.jgroups.JChannel.up(JChannel.java:626) at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:939) at org.jgroups.protocols.relay.RELAY2.deliver(RELAY2.java:465) at org.jgroups.protocols.relay.RELAY2.route(RELAY2.java:356) at org.jgroups.protocols.relay.RELAY2.handleMessage(RELAY2.java:336) at org.jgroups.protocols.relay.RELAY2.handleRelayMessage(RELAY2.java:289) at org.jgroups.protocols.relay.Relayer2$Bridge.receive(Relayer2.java:143) at org.jgroups.JChannel.up(JChannel.java:629) at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:939) at org.jgroups.protocols.FRAG2.up(FRAG2.java:137) at org.jgroups.protocols.FlowControl.up(FlowControl.java:253) at org.jgroups.protocols.FlowControl.up(FlowControl.java:261) at org.jgroups.protocols.pbcast.GMS.up(GMS.java:783) at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:235) at org.jgroups.protocols.UNICAST3.deliverMessage(UNICAST3.java:1165) at org.jgroups.protocols.UNICAST3.addMessage(UNICAST3.java:896) at org.jgroups.protocols.UNICAST3.handleDataReceived(UNICAST3.java:878) at org.jgroups.protocols.UNICAST3.up(UNICAST3.java:489) at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:642) at org.jgroups.protocols.VERIFY_SUSPECT2.up(VERIFY_SUSPECT2.java:105) at org.jgroups.protocols.FailureDetection.up(FailureDetection.java:180) at org.jgroups.protocols.MERGE3.up(MERGE3.java:272) at org.jgroups.protocols.Discovery.up(Discovery.java:296) at org.jgroups.stack.Protocol.up(Protocol.java:360) at org.jgroups.protocols.TP.passMessageUp(TP.java:1146) at org.jgroups.util.SubmitToThreadPool$SingleMessageHandler.run(SubmitToThreadPool.java:105) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) at java.base/java.lang.Thread.run(Thread.java:1583)

[pruivo]

It helps. Created infinispan/infinispan#14865 to track this bug.