Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Source parameter is null on JCache.loadAll() call #10328

Closed
Donnerbart opened this issue Apr 12, 2017 · 8 comments

Comments

Projects
None yet
5 participants
@Donnerbart
Copy link
Contributor

commented Apr 12, 2017

I'm adding new tests for the loadAll() methods of JCache and IMap: #10326

The ClientCacheNearCacheBasicTest fails on the method whenLoadAllWithListenerIsUsed_thenNearCacheIsInvalidated_onDataAdapter() and creates the following exceptions:

java.lang.NullPointerException
	at com.hazelcast.client.impl.protocol.util.ParameterUtil.calculateDataSize(ParameterUtil.java:32)
	at com.hazelcast.client.impl.protocol.codec.CacheAddNearCacheInvalidationListenerCodec.encodeCacheBatchInvalidationEvent(CacheAddNearCacheInvalidationListenerCodec.java:168)
	at com.hazelcast.client.impl.protocol.task.cache.CacheAddNearCacheInvalidationListenerTask$NearCacheInvalidationListener.encodeBatchInvalidation(CacheAddNearCacheInvalidationListenerTask.java:63)
	at com.hazelcast.internal.nearcache.impl.invalidation.AbstractBaseNearCacheInvalidationListener.sendInvalidation(AbstractBaseNearCacheInvalidationListener.java:54)
	at com.hazelcast.client.impl.protocol.task.cache.AbstractCacheClientNearCacheInvalidationListener.handleEvent(AbstractCacheClientNearCacheInvalidationListener.java:47)
	at com.hazelcast.cache.impl.AbstractCacheService.dispatchEvent(AbstractCacheService.java:465)
	at com.hazelcast.cache.impl.AbstractCacheService.dispatchEvent(AbstractCacheService.java:65)
	at com.hazelcast.spi.impl.eventservice.impl.LocalEventDispatcher.run(LocalEventDispatcher.java:56)
	at com.hazelcast.util.executor.StripedExecutor$Worker.process(StripedExecutor.java:221)
	at com.hazelcast.util.executor.StripedExecutor$Worker.run(StripedExecutor.java:204)

The scenario is a member and client node, both configured with a simple CacheLoader. The client has a Near Cache configured, invalidations are enabled.. The loadAll() is invoked on the member:

ICacheCompletionListener listener = new ICacheCompletionListener();
memberCache.loadAll(allKeys, true, listener);
listener.await();
public class ICacheCacheLoader implements CacheLoader<Integer, String> {

    @Override
    public String load(Integer key) throws CacheLoaderException {
        return "newValue-" + key;
    }

    @Override
    public Map<Integer, String> loadAll(Iterable<? extends Integer> keys)
            throws CacheLoaderException {
        Map<Integer, String> entries = new HashMap<Integer, String>();
        for (Integer key : keys) {
            entries.put(key, "newValue-" + key);
        }
        return entries;
    }
}
public class ICacheCompletionListener implements CompletionListener {

    private final CountDownLatch completed = new CountDownLatch(1);

    private volatile Exception exception;

    @Override
    public void onCompletion() {
        completed.countDown();
    }

    @Override
    public void onException(Exception e) {
        exception = e;
    }

    public void await() {
        HazelcastTestSupport.assertOpenEventually(completed);
        if (exception != null) {
            throw rethrow(exception);
        }
    }
}

@Donnerbart Donnerbart added this to the 3.9 milestone Apr 12, 2017

@Donnerbart

This comment has been minimized.

Copy link
Contributor Author

commented Apr 12, 2017

With the new assertion Ahmet added we have the source of the null:

java.lang.AssertionError
	at com.hazelcast.internal.nearcache.impl.invalidation.Invalidator.invalidateKey(Invalidator.java:70)
	at com.hazelcast.cache.impl.CacheEventHandler.sendInvalidationEvent(CacheEventHandler.java:126)
	at com.hazelcast.cache.impl.AbstractCacheService.sendInvalidationEvent(AbstractCacheService.java:695)
	at com.hazelcast.cache.impl.AbstractCacheRecordStore.invalidateEntry(AbstractCacheRecordStore.java:393)
	at com.hazelcast.cache.impl.AbstractCacheRecordStore.updateRecord(AbstractCacheRecordStore.java:652)
	at com.hazelcast.cache.impl.AbstractCacheRecordStore.updateRecordWithExpiry(AbstractCacheRecordStore.java:675)
	at com.hazelcast.cache.impl.AbstractCacheRecordStore.updateRecordWithExpiry(AbstractCacheRecordStore.java:716)
	at com.hazelcast.cache.impl.AbstractCacheRecordStore.updateRecordWithExpiry(AbstractCacheRecordStore.java:699)
	at com.hazelcast.cache.impl.AbstractCacheRecordStore.put(AbstractCacheRecordStore.java:1007)
	at com.hazelcast.cache.impl.AbstractCacheRecordStore.loadAll(AbstractCacheRecordStore.java:1393)
	at com.hazelcast.cache.impl.operation.CacheLoadAllOperation.run(CacheLoadAllOperation.java:93)
@pschmeltzer

This comment has been minimized.

Copy link

commented Mar 2, 2018

Application notes:

  • Programmatic configured cluster and clients
  • Cluster nodes may have beans which use local cache (without near cache)
  • Clients have near cache configured on jcache instances like so:
for (String cache : caches) {
            NearCacheConfig nearCacheConfig = new NearCacheConfig(cache);
            nearCacheConfig.setInMemoryFormat(InMemoryFormat.OBJECT);
            EvictionConfig evictionConfig = new EvictionConfig();
            evictionConfig.setSize(size);
            config.addNearCacheConfig(nearCacheConfig);
        }
  • Clients retrieve access to cache through jet:
    IStreamCache<K,V> jcache = instance.getCacheManager().getCache(name);
  • Cluster creates cache like:
CachingProvider cachingProvider = Caching.getCachingProvider(JetInstance.class.getClassLoader());
        Properties properties = new Properties();
        properties.put("hazelcast.instance.itself",server.getHazelcastInstance());
        CacheManager cacheManager = cachingProvider.getCacheManager(null, JetInstance.class.getClassLoader(), properties);
.....set other properties .....
jcache = cacheManager.createCache(name, config);
2018-02-28 15:52:01,904 [hz.ttcore.event-3] ERROR c.h.s.i.e.i.EventServiceImpl - [192.168.70.25]:18320 [ttcore] [0.5.1] hz.ttcore.event-3 caught an exception while processing task:com.hazelcast.spi.impl.eventservice.impl.LocalEventDispatcher@74e130af
java.lang.NullPointerException: null
        at com.hazelcast.client.impl.protocol.util.ParameterUtil.calculateDataSize(ParameterUtil.java:32) ~[hazelcast-3.9.1.jar:3.9.1]
        at com.hazelcast.client.impl.protocol.codec.CacheAddNearCacheInvalidationListenerCodec.encodeCacheBatchInvalidationEvent(CacheAddNearCacheInvalidationListenerCodec.java:169) ~[hazelcast-3.9.1.jar:3.9.1]
        at com.hazelcast.client.impl.protocol.task.cache.CacheAddNearCacheInvalidationListenerTask$NearCacheInvalidationListener.encodeBatchInvalidation(CacheAddNearCacheInvalidationListenerTask.java:63) ~[hazelcast-3.9.1.jar:3.9.1]
        at com.hazelcast.internal.nearcache.impl.invalidation.AbstractBaseNearCacheInvalidationListener.sendInvalidation(AbstractBaseNearCacheInvalidationListener.java:54) ~[hazelcast-3.9.1.jar:3.9.1]
        at com.hazelcast.client.impl.protocol.task.cache.AbstractCacheClientNearCacheInvalidationListener.handleEvent(AbstractCacheClientNearCacheInvalidationListener.java:47) ~[hazelcast-3.9.1.jar:3.9.1]
        at com.hazelcast.cache.impl.AbstractCacheService.dispatchEvent(AbstractCacheService.java:460) ~[hazelcast-3.9.1.jar:3.9.1]
        at com.hazelcast.cache.impl.AbstractCacheService.dispatchEvent(AbstractCacheService.java:70) ~[hazelcast-3.9.1.jar:3.9.1]
        at com.hazelcast.spi.impl.eventservice.impl.LocalEventDispatcher.run(LocalEventDispatcher.java:64) ~[hazelcast-3.9.1.jar:3.9.1]
        at com.hazelcast.util.executor.StripedExecutor$Worker.process(StripedExecutor.java:225) [hazelcast-3.9.1.jar:3.9.1]
        at com.hazelcast.util.executor.StripedExecutor$Worker.run(StripedExecutor.java:208) [hazelcast-3.9.1.jar:3.9.1]
@vbekiaris

This comment has been minimized.

Copy link
Contributor

commented Mar 2, 2018

It seems the issue (or another way to trigger it) still exists in 3.9.3. Reopening this issue to investigate further.

@vbekiaris vbekiaris reopened this Mar 2, 2018

@vbekiaris

This comment has been minimized.

Copy link
Contributor

commented Mar 2, 2018

thanks @pschmeltzer for reporting this

@Donnerbart Donnerbart removed their assignment Mar 2, 2018

@degerhz degerhz modified the milestones: 3.9, 3.9.4 Mar 6, 2018

@pschmeltzer

This comment has been minimized.

Copy link

commented Mar 6, 2018

Some notes on observing application logs.
Application doesn't replace cache values very often, so they only expire from the near cache when it hits the max local size?
It seems like this null pointer might be getting thrown in the cluster when a client has a miss on near cache and makes a call to the cluster.

Stack traces of client make it also appear that the cluster is calling cache loader.

Client:

"main" #1 prio=5 os_prio=0 tid=0x00007f8f9c00b000 nid=0x2f2c waiting on condition [0x00007f8fa5277000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
        at com.hazelcast.spi.impl.AbstractInvocationFuture.get(AbstractInvocationFuture.java:179)
        at com.hazelcast.client.util.ClientDelegatingFuture.get(ClientDelegatingFuture.java:137)
        at com.hazelcast.client.util.ClientDelegatingFuture.get(ClientDelegatingFuture.java:128)
        at com.hazelcast.client.cache.impl.AbstractClientCacheProxy.getSyncInternal(AbstractClientCacheProxy.java:88)
        at com.hazelcast.client.cache.impl.NearCachedClientCacheProxy.getSyncInternal(NearCachedClientCacheProxy.java:129)
        at com.hazelcast.client.cache.impl.AbstractClientCacheProxy.get(AbstractClientCacheProxy.java:212)
        at com.hazelcast.client.cache.impl.ClientCacheProxy.get(ClientCacheProxy.java:94)
        at com.hazelcast.client.cache.impl.ClientCacheProxy.get(ClientCacheProxy.java:130)
        at com.hazelcast.jet.stream.impl.CacheDecorator.get(CacheDecorator.java:226)
        at com.ttcore.caching.client.GenericHZClientCache.get(GenericHZClientCache.java:44)
      .... omitted ...

Cluster side:

"hz.ttcore.partition-operation.thread-2" #21 prio=5 os_prio=0 tid=0x00007f2e51143000 nid=0x2c34 runnable [0x00007f2df69ef000]
   java.lang.Thread.State: RUNNABLE
.... omitted ....
        at com.ttcore.caching.distributed.jcache.AccountCacheLoader.load(AccountCacheLoader.java:15)
        at com.hazelcast.cache.impl.AbstractCacheRecordStore.readThroughCache(AbstractCacheRecordStore.java:803)
        at com.hazelcast.cache.impl.AbstractCacheRecordStore.get(AbstractCacheRecordStore.java:966)
        at com.hazelcast.cache.impl.operation.CacheGetOperation.run(CacheGetOperation.java:50)
        at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:194)
        at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:406)
        at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:433)
        at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:569)
        at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:554)
        at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:513)
        at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:207)
        at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:60)
        at com.hazelcast.client.impl.protocol.task.AbstractPartitionMessageTask.processMessage(AbstractPartitionMessageTask.java:67)
        at com.hazelcast.client.impl.protocol.task.AbstractMessageTask.initializeAndProcessMessage(AbstractMessageTask.java:123)
        at com.hazelcast.client.impl.protocol.task.AbstractMessageTask.run(AbstractMessageTask.java:103)
        at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:154)
        at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:125)
        at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.run(OperationThread.java:100)

Please advise if this type of commentary isn't appropriate for this github project.
Perhaps these findings are irrelevant.

@mdogan

This comment has been minimized.

Copy link
Member

commented Mar 26, 2018

I'm not able to reproduce the issue. But here what I found by just inspecting the code:

I don't know exactly which path leads to a null sourceUuid in an Invalidation event.

@pschmeltzer

This comment has been minimized.

Copy link

commented Mar 26, 2018

I am using a cache loader.
Dataset was larger than eviction size.
After increasing cache size to be larger than the underlying dataset size, errors are gone.
I can't do this indefinitely though.

It seems to be a combination perhaps of:

  • Near cache on clients
  • Dataset bigger than eviction size
  • (Maybe) with a cache loader
@mdogan

This comment has been minimized.

Copy link
Member

commented Mar 27, 2018

@pschmeltzer: I'm able to reproduce the issue with your combination.

11:46:52,039 ERROR - [EventServiceImpl] hz._hzInstance_1_dev.event-2 - [127.0.0.1]:5701 [dev] [3.10-SNAPSHOT] hz._hzInstance_1_dev.event-2 caught an exception while processing task:com.hazelcast.spi.impl.eventservice.impl.LocalEventDispatcher@2097b08
java.lang.NullPointerException: null
	at com.hazelcast.client.impl.protocol.util.ParameterUtil.calculateDataSize(ParameterUtil.java:32) ~[classes/:?]
	at com.hazelcast.client.impl.protocol.codec.CacheAddNearCacheInvalidationListenerCodec.encodeCacheBatchInvalidationEvent(CacheAddNearCacheInvalidationListenerCodec.java:169) ~[hazelcast-client-protocol-1.6.0-10.jar:1.6.0-10]
	at com.hazelcast.client.impl.protocol.task.cache.CacheAddNearCacheInvalidationListenerTask$NearCacheInvalidationListener.encodeBatchInvalidation(CacheAddNearCacheInvalidationListenerTask.java:63) ~[classes/:?]
	at com.hazelcast.internal.nearcache.impl.invalidation.AbstractBaseNearCacheInvalidationListener.sendInvalidation(AbstractBaseNearCacheInvalidationListener.java:54) ~[classes/:?]
	at com.hazelcast.client.impl.protocol.task.cache.AbstractCacheClientNearCacheInvalidationListener.handleEvent(AbstractCacheClientNearCacheInvalidationListener.java:47) ~[classes/:?]
	at com.hazelcast.cache.impl.AbstractCacheService.dispatchEvent(AbstractCacheService.java:490) ~[classes/:?]
	at com.hazelcast.cache.impl.AbstractCacheService.dispatchEvent(AbstractCacheService.java:75) ~[classes/:?]
	at com.hazelcast.spi.impl.eventservice.impl.LocalEventDispatcher.run(LocalEventDispatcher.java:64) ~[classes/:?]

With assertions enabled, it fails earlier on assertion assert sourceUuid != null, which validates my assumption.

11:49:05,426 ERROR - [CacheGetOperation] hz._hzInstance_1_dev.partition-operation.thread-6 - [127.0.0.1]:5701 [dev] [3.10-SNAPSHOT] null
java.lang.AssertionError: null
	at com.hazelcast.internal.nearcache.impl.invalidation.Invalidator.invalidateKey(Invalidator.java:69) ~[classes/:?]
	at com.hazelcast.cache.impl.CacheEventHandler.sendInvalidationEvent(CacheEventHandler.java:127) ~[classes/:?]
	at com.hazelcast.cache.impl.AbstractCacheService.sendInvalidationEvent(AbstractCacheService.java:727) ~[classes/:?]
	at com.hazelcast.cache.impl.AbstractCacheRecordStore.invalidateEntry(AbstractCacheRecordStore.java:423) ~[classes/:?]
	at com.hazelcast.cache.impl.AbstractCacheRecordStore.doPutRecord(AbstractCacheRecordStore.java:938) ~[classes/:?]
	at com.hazelcast.cache.impl.AbstractCacheRecordStore.createRecord(AbstractCacheRecordStore.java:563) ~[classes/:?]
	at com.hazelcast.cache.impl.AbstractCacheRecordStore.createRecordWithExpiry(AbstractCacheRecordStore.java:595) ~[classes/:?]
	at com.hazelcast.cache.impl.AbstractCacheRecordStore.createRecordWithExpiry(AbstractCacheRecordStore.java:624) ~[classes/:?]
	at com.hazelcast.cache.impl.AbstractCacheRecordStore.createRecordWithExpiry(AbstractCacheRecordStore.java:611) ~[classes/:?]
	at com.hazelcast.cache.impl.AbstractCacheRecordStore.get(AbstractCacheRecordStore.java:983) ~[classes/:?]
	at com.hazelcast.cache.impl.operation.CacheGetOperation.run(CacheGetOperation.java:50) ~[classes/:?]
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.