Hello,
I've got a 6 node grid with maxSize (dataregionconfig) set to 300G each.
The grid seemed to be performing normally until at one point it started logging
"Partition states validation has failed for group" warning - see attached log
file. This kept happening for about 3 minutes and then stopped (see line 85 in
the attached log file). Just then a client seems to have connected (see line
135 where connection was accepted). But soon after, it kept logging the below
exception. After a while (~1 hour), it started showing logging "Partition
states validation has failed for group" again (line 284).
2019-09-19 13:28:28.601 [INFO ] [exchange-worker-#176]
GridDhtPartitionsExchangeFuture - Completed partition exchange
[localNode=0c643dd0-a884-4fd0-acb3-a6d7e2c5e71d,
exchange=GridDhtPartitionsExchangeFuture [topVer
=AffinityTopologyVersion [topVer=126, minorTopVer=0], evt=NODE_JOINED,
evtNode=ZookeeperClusterNode [id=af5f33f4-842a-4691-8e84-da4fb19eafb2,
addrs=[10.126.90.78, 10.115.76.13, 127.0.0.1], order=126, loc=false, clie
nt=true], done=true], topVer=AffinityTopologyVersion [topVer=126,
minorTopVer=0], durationFromInit=0]
2019-09-19 13:28:28.601 [INFO ] [exchange-worker-#176] time - Finished exchange
init [topVer=AffinityTopologyVersion [topVer=126, minorTopVer=0], crd=true]
2019-09-19 13:28:28.602 [INFO ] [exchange-worker-#176]
GridCachePartitionExchangeManager - Skipping rebalancing (nothing scheduled)
[top=AffinityTopologyVersion [topVer=126, minorTopVer=0], force=false,
evt=NODE_JOI
NED, node=af5f33f4-842a-4691-8e84-da4fb19eafb2]
2019-09-19 13:28:29.513 [INFO ] [grid-nio-worker-tcp-comm-14-#130]
TcpCommunicationSpi - Accepted incoming communication connection
[locAddr=/10.115.248.110:12122, rmtAddr=/10.115.76.13:45464]
2019-09-19 13:28:29.540 [INFO ] [grid-nio-worker-tcp-comm-15-#131]
TcpCommunicationSpi - Accepted incoming communication connection
[locAddr=/10.115.248.110:12122, rmtAddr=/10.115.76.13:45466]
2019-09-19 13:28:29.600 [INFO ] [grid-nio-worker-tcp-comm-16-#132]
TcpCommunicationSpi - Accepted incoming communication connection
[locAddr=/10.115.248.110:12122, rmtAddr=/10.115.76.13:45472]
2019-09-19 13:28:51.624 [ERROR] [grid-nio-worker-tcp-comm-17-#133]
TcpCommunicationSpi - Failed to read data from remote connection (will wait for
2000ms).
org.apache.ignite.IgniteCheckedException: Failed to select events on selector.
at
org.apache.ignite.internal.util.nio.GridNioServer$AbstractNioClientWorker.bodyInternal(GridNioServer.java:2182)
~[ignite-core-2.7.5-0-2.jar:2.7.5]
at
org.apache.ignite.internal.util.nio.GridNioServer$AbstractNioClientWorker.body(GridNioServer.java:1794)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:120)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_172]
Caused by: java.nio.channels.ClosedChannelException
at
java.nio.channels.spi.AbstractSelectableChannel.register(AbstractSelectableChannel.java:197)
~[?:1.8.0_172]
at
org.apache.ignite.internal.util.nio.GridNioServer$AbstractNioClientWorker.bodyInternal(GridNioServer.java:1997)
~[ignite-core-2.7.5-0-2.jar:2.7.5]
... 3 more
after a lot of these exceptions and warnings, the node started throwing the
below (client had started ingestion using datastreamer). And the below
exceptions were seen on all the nodes
2019-09-19 15:10:38.922 [ERROR] [grid-timeout-worker-#115] - Critical system
error detected. Will be handled accordingly to configured handler
[hnd=StopNodeOrHaltFailureHandler [tryStop=false, timeout=0, super=Abst
ractFailureHandler [ignoredFailureTypes=[SYSTEM_WORKER_BLOCKED,
SYSTEM_CRITICAL_OPERATION_TIMEOUT]]], failureCtx=FailureContext
[type=SYSTEM_WORKER_BLOCKED, err=class o.a.i.IgniteException: GridWorker
[name=data-str
eamer-stripe-42, igniteInstanceName=null, finished=false,
heartbeatTs=1568920228643]]]
org.apache.ignite.IgniteException: GridWorker [name=data-streamer-stripe-42,
igniteInstanceName=null, finished=false, heartbeatTs=1568920228643]
at
org.apache.ignite.internal.IgnitionEx$IgniteNamedInstance$2.apply(IgnitionEx.java:1831)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at
org.apache.ignite.internal.IgnitionEx$IgniteNamedInstance$2.apply(IgnitionEx.java:1826)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at
org.apache.ignite.internal.worker.WorkersRegistry.onIdle(WorkersRegistry.java:233)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at
org.apache.ignite.internal.util.worker.GridWorker.onIdle(GridWorker.java:297)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at
org.apache.ignite.internal.processors.timeout.GridTimeoutProcessor$TimeoutWorker.body(GridTimeoutProcessor.java:221)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:120)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_172]
There was very high GC activity seen at that time ~ 15:10, so that would
explain the last part. But this kept going on and on until it went into a
tailspin with the below logs
2019-09-19 17:34:27.550 [WARN ] [zk-null-EventThread] ZookeeperClient - Failed
to execute ZooKeeper operation
[err=org.apache.zookeeper.KeeperException$ConnectionLossException:
KeeperErrorCode = ConnectionLoss for /
apacheIgnite/cassgrid-nj/cp/389e297a-e3f5-4735-9194-5caaa14f8eb7:34d021e7-3f7e-4cc8-83aa-adad0de00553:0000,
state=Disconnected]
2019-09-19 17:34:27.550 [WARN ] [zk-null-EventThread] ZookeeperClient -
ZooKeeper operation failed, will retry
[err=org.apache.zookeeper.KeeperException$ConnectionLossException:
KeeperErrorCode = ConnectionLoss for
/apacheIgnite/cassgrid-nj/cp/389e297a-e3f5-4735-9194-5caaa14f8eb7:34d021e7-3f7e-4cc8-83aa-adad0de00553:0000,
retryTimeout=2000, connLossTimeout=30000,
path=/apacheIgnite/cassgrid-nj/cp/389e297a-e3f5-4735-9194-5caaa1
4f8eb7:34d021e7-3f7e-4cc8-83aa-adad0de00553:0000, remainingWaitTime=20335]
2019-09-19 17:34:27.550 [WARN ] [data-streamer-stripe-41-#96] ZookeeperClient -
Failed to execute ZooKeeper operation
[err=org.apache.zookeeper.KeeperException$ConnectionLossException:
KeeperErrorCode = ConnectionLo
ss for
/apacheIgnite/cassgrid-nj/cp/d284ad22-03c4-4281-9221-6eddad9bf313:0c643dd0-a884-4fd0-acb3-a6d7e2c5e71d:0001,
state=Disconnected]
2019-09-19 17:34:27.550 [ERROR] [data-streamer-stripe-41-#96] ZookeeperClient -
Operation failed with unexpected error, close ZooKeeper client:
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErr
orCode = ConnectionLoss for
/apacheIgnite/cassgrid-nj/cp/d284ad22-03c4-4281-9221-6eddad9bf313:0c643dd0-a884-4fd0-acb3-a6d7e2c5e71d:0001
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode =
ConnectionLoss for
/apacheIgnite/cassgrid-nj/cp/d284ad22-03c4-4281-9221-6eddad9bf313:0c643dd0-a884-4fd0-acb3-a6d7e2c5e71d:0001
at
org.apache.zookeeper.KeeperException.create(KeeperException.java:102)
~[zookeeper-3.4.13.jar:3.4.13-2d71af4dbe22557fda74f9a9b4309b15a7487f03]
at org.apache.zookeeper.KeeperException.create(KeeperException.java:54)
~[zookeeper-3.4.13.jar:3.4.13-2d71af4dbe22557fda74f9a9b4309b15a7487f03]
at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:792)
~[zookeeper-3.4.13.jar:3.4.13-2d71af4dbe22557fda74f9a9b4309b15a7487f03]
at
org.apache.ignite.spi.discovery.zk.internal.ZookeeperClient.createIfNeeded(ZookeeperClient.java:443)
[ignite-zookeeper-2.7.5.jar:2.7.5]
at
org.apache.ignite.spi.discovery.zk.internal.ZookeeperDiscoveryImpl.saveMultipleParts(ZookeeperDiscoveryImpl.java:939)
[ignite-zookeeper-2.7.5.jar:2.7.5]
at
org.apache.ignite.spi.discovery.zk.internal.ZookeeperDiscoveryImpl.saveCustomMessage(ZookeeperDiscoveryImpl.java:671)
[ignite-zookeeper-2.7.5.jar:2.7.5]
at
org.apache.ignite.spi.discovery.zk.internal.ZookeeperDiscoveryImpl.sendCustomMessage(ZookeeperDiscoveryImpl.java:629)
[ignite-zookeeper-2.7.5.jar:2.7.5]
at
org.apache.ignite.spi.discovery.zk.ZookeeperDiscoverySpi.sendCustomEvent(ZookeeperDiscoverySpi.java:414)
[ignite-zookeeper-2.7.5.jar:2.7.5]
at
org.apache.ignite.internal.managers.discovery.GridDiscoveryManager.sendCustomEvent(GridDiscoveryManager.java:2207)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at
org.apache.ignite.internal.processors.cache.binary.BinaryMetadataTransport.requestMetadataUpdate(BinaryMetadataTransport.java:170)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at
org.apache.ignite.internal.processors.cache.binary.CacheObjectBinaryProcessorImpl.addMeta(CacheObjectBinaryProcessorImpl.java:469)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at
org.apache.ignite.internal.processors.cache.binary.CacheObjectBinaryProcessorImpl$2.addMeta(CacheObjectBinaryProcessorImpl.java:186)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at
org.apache.ignite.internal.binary.BinaryContext.updateMetadata(BinaryContext.java:1332)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at
org.apache.ignite.internal.binary.builder.BinaryObjectBuilderImpl.serializeTo(BinaryObjectBuilderImpl.java:369)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at
org.apache.ignite.internal.binary.builder.BinaryObjectBuilderImpl.build(BinaryObjectBuilderImpl.java:190)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at
com.bloomberg.fdns.cass.ignition.datareader.CassStreamReceiver.receive(CassStreamReceiver.java:42)
[datagrid-cass-dependencies.jar:?]
at
org.apache.ignite.internal.processors.datastreamer.DataStreamerUpdateJob.call(DataStreamerUpdateJob.java:137)
[ignite-core-2.7.5-0-2.jar:2.7.5]
at
org.apache.ignite.internal.processors.datastreamer.DataStreamProcessor.localUpdate(DataStreamProcessor.java:400)
[ignite-core-2.7.5-0-2.jar:2.7.5]
....
2019-09-19 17:34:27.686 [WARN ] [data-streamer-stripe-41-#96]
ZookeeperDiscoveryImpl - Connection to Zookeeper server is lost, local node
SEGMENTED.
2019-09-19 17:34:27.687 [WARN ] [disco-event-worker-#175] GridDiscoveryManager
- Local node SEGMENTED: ZookeeperClusterNode
[id=0c643dd0-a884-4fd0-acb3-a6d7e2c5e71d, addrs=[10.115.248.110, 10.126.230.37,
127.0.0.1],
order=109, loc=true, client=false]
2019-09-19 17:34:27.688 [ERROR] [disco-event-worker-#175] - Critical system
error detected. Will be handled accordingly to configured handler
[hnd=StopNodeFailureHandler [super=AbstractFailureHandler [ignoredFailur
eTypes=[SYSTEM_WORKER_BLOCKED, SYSTEM_CRITICAL_OPERATION_TIMEOUT]]],
failureCtx=FailureContext [type=SEGMENTATION, err=null]]
Any help in understanding what triggered these series of event will be very
helpful.
Thanks,
Abhishek
