Search code examples
ignitenear-cache

Apache Ignite Near Cache Always Missed


When using a near cache everything will work fine until a second client (could be visor) attempts to connect or disconnect to the cluster while a cache operation is in process.

After the second client connects/disconnects, the original client will always miss the near cache until and the original client restarts. Almost as if the cluster informs the client their are issues and to keep the cluster as the source of truth.

We have been able to reproduce this by running our test and connecting/disconnect with visor. During a disconnect we can see a Timeout mentioned in the logs on the original client IgniteTxManager$NodeFailureTimeoutObject.

Below is a snippet of the logs with the org.apache.ignite.internal.processors suppressed.

[2017-10-09 14:26:52.148] boot - 9955 DEBUG [http-nio-8081-exec-8] --- CacheHelper: Total time accessing cache ng-security-service-ORG_SPEC_CACHE for key * | value com.cache.model.PrefixCluster@78475a88: 0 millis [2017-10-09 14:26:52.150] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- GridDiscoveryManager: Daemon node left topology: TcpDiscoveryNode [id=4cc6c321-d9cc-4149-a6ef-cba68877a269, addrs=[10.70.255.8, 127.0.0.1, 172.17.0.1], sockAddrs=[/172.17 .0.1:0, /127.0.0.1:0, /10.70.255.8:0], discPort=0, order=57, intOrder=31, lastExchangeTime=1507577126368, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true] [2017-10-09 14:26:52.150] boot - 9955 DEBUG [http-nio-8081-exec-8] --- OrgSpecCacheImpl: OrgSpec Cache Stats: OrgSpec ObjId: IgniteCacheProxy [delegate=GridNearCacheAdapter [], opCtx=null, restartFut=null] HitCount: 120, MissCount: 50, AvgReadTime: 120, Eviction Count: 0 [2017-10-09 14:26:52.150] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- GridDeploymentPerVersionStore: Processing node departure event: DiscoveryEvent [evtNode=TcpDiscoveryNode [id=4cc6c321-d9cc-4149-a6ef-cba68877a269, addrs=[10.70.255.8, 127.0.0.1, 172.17.0.1], sockAddrs=[/172.17.0.1:0, /127.0.0.1:0, /10.70.255.8:0], discPort=0, order=57, intOrder=31, lastExchangeTime=1507577126368, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], topVer=58, nodeId8=2e573c60, msg=Node left: TcpDiscoveryNode [id=4cc6c321-d9cc-4149-a6ef-cba68877a269, addrs=[10.70.255.8, 127.0.0.1, 172.17.0.1], sockAddrs=[/172.17.0.1:0, /127.0.0.1:0, /10.70.255.8:0], discPort=0, order=57, intOrder=31, lastExchangeTime=1507577126368, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], type=NODE_LEFT, tstamp=1507577212142] [2017-10-09 14:26:52.163] boot - 9955 INFO [exchange-worker-#27%null%] --- time: Started exchange init [topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], crd=false, evt=11, node=TcpDiscoveryNode [id=2e573c60-45f0-4429-a3fa-068489663148, addrs=[0:0:0:0:0:0:0:1%lo, 10.70.242.138, 127.0.0.1], sockAddrs=[port-svc-inc-13.tw-test.net/10.70.242.138:0, /0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0], discPort=0, order=56, intOrder=0, lastExchangeTime=1507576971754, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], evtNode=TcpDiscoveryNode [id=2e573c60-45f0-4429-a3fa-068489663148, addrs=[0:0:0:0:0:0:0:1%lo, 10.70.242.138, 127.0.0.1], sockAddrs=[port-svc-inc-13.tw-test.net/10.70.242.138:0, /0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0], discPort=0, order=56, intOrder=0, lastExchangeTime=1507576971754, loc=true, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], customEvt=null] [2017-10-09 14:26:52.164] boot - 9955 INFO [exchange-worker-#27%null%] --- GridDhtPartitionsExchangeFuture: Snapshot initialization completed [topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], time=0ms] [2017-10-09 14:26:52.164] boot - 9955 INFO [exchange-worker-#27%null%] --- GridDhtPartitionsExchangeFuture: Snapshot initialization completed [topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], time=0ms] [2017-10-09 14:26:52.164] boot - 9955 INFO [exchange-worker-#27%null%] --- time: Finished exchange init [topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], crd=false] [2017-10-09 14:26:52.203] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- GridDeploymentLocalStore: Deployment meta for local deployment: GridDeploymentMetadata [depMode=SHARED, alias=org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1, clsName=org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1, userVer=null, sndNodeId=2e573c60-45f0-4429-a3fa-068489663148, clsLdrId=null, clsLdr=null, participants=null, parentLdr=null, record=true, nodeFilter=null, seqNum=n/a] [2017-10-09 14:26:52.203] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- LocalDeploymentSpi: Registering [ldrRsrcs={org.springframework.boot.loader.LaunchedURLClassLoader@7adf9f5f={org.apache.ignite.internal.util.typedef.T2=org.apache.ignite.internal.util.typedef.T2, org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionHistorySuppliersMap=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionHistorySuppliersMap, org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionFullMap=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionFullMap, java.util.Collections$UnmodifiableList=java.util.Collections$UnmodifiableList, org.apache.ignite.internal.visor.cache.VisorCacheMetricsCollectorTask=org.apache.ignite.internal.visor.cache.VisorCacheMetricsCollectorTask, org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionsToReloadMap=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionsToReloadMap, org.apache.ignite.internal.processors.service.GridServiceProcessor$1=org.apache.ignite.internal.processors.service.GridServiceProcessor$1, org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionMap=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionMap, org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionCountersMap=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionCountersMap}}, ldr=org.springframework.boot.loader.LaunchedURLClassLoader@7adf9f5f, rsrc=class org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1] [2017-10-09 14:26:52.203] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- LocalDeploymentSpi: Resources to register: {org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1=org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1} [2017-10-09 14:26:52.203] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- LocalDeploymentSpi: New resources: {org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1=org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1} [2017-10-09 14:26:52.203] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- LocalDeploymentSpi: Removing resources [clsLdrToIgnore=org.springframework.boot.loader.LaunchedURLClassLoader@7adf9f5f, rsrcs={org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1=org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1}] [2017-10-09 14:26:52.203] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- GridDeploymentLocalStore: Retrieved auto-loaded resource from spi: DeploymentResourceAdapter [name=org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1, rsrcCls=class org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1, clsLdr=org.springframework.boot.loader.LaunchedURLClassLoader@7adf9f5f] [2017-10-09 14:26:52.203] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- GridDeploymentLocalStore: Acquired deployment class: GridDeployment [ts=1507576972855, depMode=SHARED, clsLdr=org.springframework.boot.loader.LaunchedURLClassLoader@7adf9f5f, clsLdrId=6d9e6920f51-2e573c60-45f0-4429-a3fa-068489663148, userVer=0, loc=true, sampleClsName=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionFullMap, pendingUndeploy=false, undeployed=false, usage=0] [2017-10-09 14:26:52.203] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- GridResourceProcessor: Injecting resources [target=org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1@61ea2cff] [2017-10-09 14:26:52.211] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- GridDeploymentLocalStore: Deployment meta for local deployment: GridDeploymentMetadata [depMode=SHARED, alias=org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor$1$1, clsName=org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor$1$1, userVer=null, sndNodeId=2e573c60-45f0-4429-a3fa-068489663148, clsLdrId=null, clsLdr=null, participants=null, parentLdr=null, record=true, nodeFilter=null, seqNum=n/a] [2017-10-09 14:26:52.211] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- LocalDeploymentSpi: Registering [ldrRsrcs={org.springframework.boot.loader.LaunchedURLClassLoader@7adf9f5f={org.apache.ignite.internal.util.typedef.T2=org.apache.ignite.internal.util.typedef.T2, org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionHistorySuppliersMap=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionHistorySuppliersMap, org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionFullMap=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionFullMap, java.util.Collections$UnmodifiableList=java.util.Collections$UnmodifiableList, org.apache.ignite.internal.visor.cache.VisorCacheMetricsCollectorTask=org.apache.ignite.internal.visor.cache.VisorCacheMetricsCollectorTask, org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionsToReloadMap=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionsToReloadMap, org.apache.ignite.internal.processors.service.GridServiceProcessor$1=org.apache.ignite.internal.processors.service.GridServiceProcessor$1, org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionMap=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionMap, org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionCountersMap=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionCountersMap, org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1=org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1}}, ldr=org.springframework.boot.loader.LaunchedURLClassLoader@7adf9f5f, rsrc=class org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor$1$1] [2017-10-09 14:26:52.211] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- LocalDeploymentSpi: Resources to register: {org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor$1$1=org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor$1$1} [2017-10-09 14:26:52.211] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- LocalDeploymentSpi: New resources: {org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor$1$1=org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor$1$1} [2017-10-09 14:26:52.211] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- LocalDeploymentSpi: Removing resources [clsLdrToIgnore=org.springframework.boot.loader.LaunchedURLClassLoader@7adf9f5f, rsrcs={org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor$1$1=org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor$1$1}] [2017-10-09 14:26:52.211] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- GridDeploymentLocalStore: Retrieved auto-loaded resource from spi: DeploymentResourceAdapter [name=org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor$1$1, rsrcCls=class org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor$1$1, clsLdr=org.springframework.boot.loader.LaunchedURLClassLoader@7adf9f5f] [2017-10-09 14:26:52.212] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- GridDeploymentLocalStore: Acquired deployment class: GridDeployment [ts=1507576972855, depMode=SHARED, clsLdr=org.springframework.boot.loader.LaunchedURLClassLoader@7adf9f5f, clsLdrId=6d9e6920f51-2e573c60-45f0-4429-a3fa-068489663148, userVer=0, loc=true, sampleClsName=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionFullMap, pendingUndeploy=false, undeployed=false, usage=0] [2017-10-09 14:26:52.212] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- GridResourceProcessor: Injecting resources [target=org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor$1$1@1ff41d49] [2017-10-09 14:26:52.213] boot - 9955 DEBUG [pub-#34%null%] --- GridClosureProcessor: Grid runnable started: closure-proc-worker [2017-10-09 14:26:52.213] boot - 9955 DEBUG [pub-#34%null%] --- GridClosureProcessor: Grid runnable finished normally: closure-proc-worker [2017-10-09 14:26:52.216] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- TcpCommunicationSpi: Forcing NIO client close since node has left [nodeId=4cc6c321-d9cc-4149-a6ef-cba68877a269, client=GridTcpNioCommunicationClient [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker [super=AbstractNioClientWorker [idx=3, bytesRcvd=714, bytesSent=6799, bytesRcvd0=0, bytesSent0=0, select=true, super=GridWorker [name=grid-nio-worker-tcp-comm-3, igniteInstanceName=null, finished=false, hashCode=1557230104, interrupted=false, runner=grid-nio-worker-tcp-comm-3-#20%null%]]], writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], inRecovery=GridNioRecoveryDescriptor [acked=0, resendCnt=0, rcvCnt=1, sentCnt=1, reserved=true, lastAck=0, nodeLeft=false, node=TcpDiscoveryNode [id=4cc6c321-d9cc-4149-a6ef-cba68877a269, addrs=[10.70.255.8, 127.0.0.1, 172.17.0.1], sockAddrs=[/172.17.0.1:0, /127.0.0.1:0, /10.70.255.8:0], discPort=0, order=57, intOrder=31, lastExchangeTime=1507577126368, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], connected=true, connectCnt=0, queueLimit=4096, reserveCnt=1, pairedConnections=false], outRecovery=GridNioRecoveryDescriptor [acked=0, resendCnt=0, rcvCnt=1, sentCnt=1, reserved=true, lastAck=0, nodeLeft=false, node=TcpDiscoveryNode [id=4cc6c321-d9cc-4149-a6ef-cba68877a269, addrs=[10.70.255.8, 127.0.0.1, 172.17.0.1], sockAddrs=[/172.17.0.1:0, /127.0.0.1:0, /10.70.255.8:0], discPort=0, order=57, intOrder=31, lastExchangeTime=1507577126368, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], connected=true, connectCnt=0, queueLimit=4096, reserveCnt=1, pairedConnections=false], super=GridNioSessionImpl [locAddr=/10.70.242.138:47100, rmtAddr=/10.70.255.8:53916, createTime=1507577162587, closeTime=0, bytesSent=6799, bytesRcvd=714, bytesSent0=0, bytesRcvd0=0, sndSchedTime=1507577162587, lastSndTime=1507577162697, lastRcvTime=1507577162617, readsPaused=false, filterChain=FilterChain[filters=[GridNioCodecFilter [parser=org.apache.ignite.internal.util.nio.GridDirectParser@9573b3b, directMode=true], GridConnectionBytesVerifyFilter], accepted=true]], super=GridAbstractCommunicationClient [lastUsed=1507577162587, closed=false, connIdx=0]]] [2017-10-09 14:26:52.217] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- TcpCommunicationSpi: Offered move [ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker [super=AbstractNioClientWorker [idx=3, bytesRcvd=714, bytesSent=6799, bytesRcvd0=0, bytesSent0=0, select=true, super=GridWorker [name=grid-nio-worker-tcp-comm-3, igniteInstanceName=null, finished=false, hashCode=1557230104, interrupted=false, runner=grid-nio-worker-tcp-comm-3-#20%null%]]], writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], inRecovery=GridNioRecoveryDescriptor [acked=0, resendCnt=0, rcvCnt=1, sentCnt=1, reserved=true, lastAck=0, nodeLeft=false, node=TcpDiscoveryNode [id=4cc6c321-d9cc-4149-a6ef-cba68877a269, addrs=[10.70.255.8, 127.0.0.1, 172.17.0.1], sockAddrs=[/172.17.0.1:0, /127.0.0.1:0, /10.70.255.8:0], discPort=0, order=57, intOrder=31, lastExchangeTime=1507577126368, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], connected=true, connectCnt=0, queueLimit=4096, reserveCnt=1, pairedConnections=false], outRecovery=GridNioRecoveryDescriptor [acked=0, resendCnt=0, rcvCnt=1, sentCnt=1, reserved=true, lastAck=0, nodeLeft=false, node=TcpDiscoveryNode [id=4cc6c321-d9cc-4149-a6ef-cba68877a269, addrs=[10.70.255.8, 127.0.0.1, 172.17.0.1], sockAddrs=[/172.17.0.1:0, /127.0.0.1:0, /10.70.255.8:0], discPort=0, order=57, intOrder=31, lastExchangeTime=1507577126368, loc=false, ver=2.1.0#20170720-sha1:a6ca5c8a, isClient=true], connected=true, connectCnt=0, queueLimit=4096, reserveCnt=1, pairedConnections=false], super=GridNioSessionImpl [locAddr=/10.70.242.138:47100, rmtAddr=/10.70.255.8:53916, createTime=1507577162587, closeTime=0, bytesSent=6799, bytesRcvd=714, bytesSent0=0, bytesRcvd0=0, sndSchedTime=1507577162587, lastSndTime=1507577162697, lastRcvTime=1507577162617, readsPaused=false, filterChain=FilterChain[filters=[GridNioCodecFilter [parser=org.apache.ignite.internal.util.nio.GridDirectParser@9573b3b, directMode=true], GridConnectionBytesVerifyFilter], accepted=true]], fut=NioOperationFuture [op=CLOSE]] [2017-10-09 14:26:52.217] boot - 9955 DEBUG [disco-event-worker-#26%null%] --- GridIoManager: Removed messages from discovery startup delay list (sender node left topology): null [2017-10-09 14:26:52.217] boot - 9955 DEBUG [pub-#35%null%] --- GridClosureProcessor: Grid runnable started: closure-proc-worker [2017-10-09 14:26:52.217] boot - 9955 DEBUG [pub-#35%null%] --- GridClosureProcessor: Grid runnable finished normally: closure-proc-worker [2017-10-09 14:26:52.283] boot - 9955 DEBUG [grid-timeout-worker-#15%null%] --- GridTimeoutProcessor: Timeout has occurred: org.apache.ignite.internal.processors.cache.transactions.IgniteTxManager$NodeFailureTimeoutObject@7ff59c90 [2017-10-09 14:26:52.284] boot - 9955 DEBUG [grid-timeout-worker-#15%null%] --- GridDeploymentLocalStore: Deployment meta for local deployment: GridDeploymentMetadata [depMode=SHARED, alias=org.apache.ignite.internal.processors.cache.transactions.IgniteTxManager$NodeFailureTimeoutObject$2, clsName=org.apache.ignite.internal.processors.cache.transactions.IgniteTxManager$NodeFailureTimeoutObject$2, userVer=null, sndNodeId=2e573c60-45f0-4429-a3fa-068489663148, clsLdrId=null, clsLdr=null, participants=null, parentLdr=null, record=true, nodeFilter=null, seqNum=n/a] [2017-10-09 14:26:52.285] boot - 9955 DEBUG [grid-timeout-worker-#15%null%] --- LocalDeploymentSpi: Registering [ldrRsrcs={org.springframework.boot.loader.LaunchedURLClassLoader@7adf9f5f={org.apache.ignite.internal.util.typedef.T2=org.apache.ignite.internal.util.typedef.T2, org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionHistorySuppliersMap=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionHistorySuppliersMap, org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionFullMap=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionFullMap, java.util.Collections$UnmodifiableList=java.util.Collections$UnmodifiableList, org.apache.ignite.internal.visor.cache.VisorCacheMetricsCollectorTask=org.apache.ignite.internal.visor.cache.VisorCacheMetricsCollectorTask, org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionsToReloadMap=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionsToReloadMap, org.apache.ignite.internal.processors.service.GridServiceProcessor$1=org.apache.ignite.internal.processors.service.GridServiceProcessor$1, org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor$1$1=org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor$1$1, org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionMap=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionMap, org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionCountersMap=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.IgniteDhtPartitionCountersMap, org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1=org.apache.ignite.internal.processors.task.GridTaskProcessor$TaskDiscoveryListener$1}}, ldr=org.springframework.boot.loader.LaunchedURLClassLoader@7adf9f5f, rsrc=class org.apache.ignite.internal.processors.cache.transactions.IgniteTxManager$NodeFailureTimeoutObject$2] 2017-10-09 14:26:52.285] boot - 9955 DEBUG [grid-timeout-worker-#15%null%] --- GridDeploymentLocalStore: Retrieved auto-loaded resource from spi: DeploymentResourceAdapter [name=org.apache.ignite.internal.processors.cache.transactions.IgniteTxManager$NodeFailureTimeoutObject$2, rsrcCls=class org.apache.ignite.internal.processors.cache.transactions.IgniteTxManager$NodeFailureTimeoutObject$2, clsLdr=org.springframework.boot.loader.LaunchedURLClassLoader@7adf9f5f] [2017-10-09 14:26:52.285] boot - 9955 DEBUG [grid-timeout-worker-#15%null%] --- GridDeploymentLocalStore: Acquired deployment class: GridDeployment [ts=1507576972855, depMode=SHARED, clsLdr=org.springframework.boot.loader.LaunchedURLClassLoader@7adf9f5f, clsLdrId=6d9e6920f51-2e573c60-45f0-4429-a3fa-068489663148, userVer=0, loc=true, sampleClsName=org.apache.ignite.internal.processors.cache.distributed.dht.preloader.GridDhtPartitionFullMap, pendingUndeploy=false, undeployed=false, usage=0] [2017-10-09 14:26:52.285] boot - 9955 DEBUG [grid-timeout-worker-#15%null%] --- GridResourceProcessor: Injecting resources [target=org.apache.ignite.internal.processors.cache.transactions.IgniteTxManager$NodeFailureTimeoutObject$2@3f183e4] [2017-10-09 14:26:52.317] boot - 9955 DEBUG [http-nio-8081-exec-8] --- CacheHelper: Total time accessing cache ng-security-service-ORG_SPEC_CACHE for key * | value com.cache.model.PrefixCluster@6954be5d: 167 millis [2017-10-09 14:26:52.319] boot - 9955 DEBUG [http-nio-8081-exec-8] --- OrgSpecCacheImpl: OrgSpec Cache Stats: OrgSpec ObjId: IgniteCacheProxy [delegate=GridNearCacheAdapter [], opCtx=null, restartFut=null] HitCount: 126, MissCount: 53, AvgReadTime: 126, Eviction Count: 0 [2017-10-09 14:26:52.321] boot - 9955 DEBUG [sys-#36%null%] --- GridClosureProcessor: Grid runnable started: closure-proc-worker

My question is, is this expected behavior? Can we get the near cache not be bypassed, or in the least re-establish using the near cache after the bad client disconnects.


Solution

  • It turns out their is a bug with the near cache. When a topology change occurs it can wipe out the topology version on the NearCacheGridEntry which will cause every call to check if the entry is valid to return false.

    Bug has been submitted https://issues.apache.org/jira/browse/IGNITE-6767