[15:58:09,484][WARNING][main][G] Ignite work directory is not provided, automatically resolved to: /usr/share/apache-ignite/work[15:58:09,491][WARNING][main][G] Consistent ID is not set, it is recommended to set consistent ID for production clusters (use IgniteConfiguration.setConsistentId property)[15:58:09,556][INFO][main][IgniteKernal] >>> __________ ________________ >>> / _/ ___/ |/ / _/_ __/ __/ >>> _/ // (7 7 // / / / / _/ >>> /___/\___/_/|_/___/ /_/ /___/ >>> >>> ver. 2.13.0#20220420-sha1:551f6ece>>> 2022 Copyright(C) Apache Software Foundation>>> >>> Ignite documentation: https://ignite.apache.org [15:58:09,563][INFO][main][IgniteKernal] Config URL: file:/etc/apache-ignite/b2bi-config.xml[15:58:09,580][INFO][main][IgniteKernal] IgniteConfiguration [igniteInstanceName=null, pubPoolSize=8, svcPoolSize=8, callbackPoolSize=8, stripedPoolSize=8, sysPoolSize=8, mgmtPoolSize=4, dataStreamerPoolSize=8, utilityCachePoolSize=8, utilityCacheKeepAliveTime=60000, p2pPoolSize=2, qryPoolSize=8, buildIdxPoolSize=1, igniteHome=/usr/share/apache-ignite, igniteWorkDir=/usr/share/apache-ignite/work, mbeanSrv=com.sun.jmx.mbeanserver.JmxMBeanServer@68b32e3e, nodeId=65622274-1387-415c-aed1-8a7ea2d0c09c, marsh=BinaryMarshaller [], marshLocJobs=false, daemon=false, p2pEnabled=false, netTimeout=5000, netCompressionLevel=1, sndRetryDelay=1000, sndRetryCnt=3, metricsHistSize=10000, metricsUpdateFreq=1000, metricsExpTime=9223372036854775807, discoSpi=TcpDiscoverySpi [addrRslvr=null, addressFilter=null, sockTimeout=0, ackTimeout=0, marsh=null, reconCnt=10, reconDelay=2000, maxAckTimeout=600000, soLinger=0, forceSrvMode=false, clientReconnectDisabled=false, internalLsnr=null, skipAddrsRandomization=false], segPlc=STOP, segResolveAttempts=2, waitForSegOnStart=true, allResolversPassReq=true, segChkFreq=10000, commSpi=TcpCommunicationSpi [connectGate=org.apache.ignite.spi.communication.tcp.internal.ConnectGateway@5e63cad, ctxInitLatch=java.util.concurrent.CountDownLatch@6759f091[Count = 1], stopping=false, clientPool=null, nioSrvWrapper=null, stateProvider=null], evtSpi=org.apache.ignite.spi.eventstorage.NoopEventStorageSpi@33a053d, colSpi=NoopCollisionSpi [], deploySpi=LocalDeploymentSpi [], indexingSpi=org.apache.ignite.spi.indexing.noop.NoopIndexingSpi@2a3a299, addrRslvr=null, encryptionSpi=org.apache.ignite.spi.encryption.noop.NoopEncryptionSpi@7da10b5b, tracingSpi=org.apache.ignite.spi.tracing.NoopTracingSpi@219f4597, clientMode=false, rebalanceThreadPoolSize=1, rebalanceTimeout=10000, rebalanceBatchesPrefetchCnt=3, rebalanceThrottle=0, rebalanceBatchSize=524288, txCfg=TransactionConfiguration [txSerEnabled=false, dfltIsolation=REPEATABLE_READ, dfltConcurrency=PESSIMISTIC, dfltTxTimeout=0, txTimeoutOnPartitionMapExchange=0, deadlockTimeout=10000, pessimisticTxLogSize=0, pessimisticTxLogLinger=10000, tmLookupClsName=null, txManagerFactory=null, useJtaSync=false], cacheSanityCheckEnabled=true, discoStartupDelay=60000, deployMode=SHARED, p2pMissedCacheSize=100, locHost=null, timeSrvPortBase=31100, timeSrvPortRange=100, failureDetectionTimeout=60000, sysWorkerBlockedTimeout=180000, clientFailureDetectionTimeout=60000, metricsLogFreq=60000, connectorCfg=ConnectorConfiguration [jettyPath=null, host=null, port=11211, noDelay=true, directBuf=false, sndBufSize=32768, rcvBufSize=32768, idleQryCurTimeout=600000, idleQryCurCheckFreq=60000, sndQueueLimit=0, selectorCnt=4, idleTimeout=7000, sslEnabled=false, sslClientAuth=false, sslCtxFactory=null, sslFactory=null, portRange=100, threadPoolSize=8, msgInterceptor=null], odbcCfg=null, warmupClos=null, atomicCfg=AtomicConfiguration [seqReserveSize=1000, cacheMode=PARTITIONED, backups=1, aff=null, grpName=null], classLdr=null, sslCtxFactory=SslContextFactory[keyStoreType=JKS, proto=TLS, keyStoreFile=/etc/apache-ignite/serverign3.domain.name.removed.net.jks, trustStoreFile=/etc/apache-ignite/truststore.jks], platformCfg=null, binaryCfg=null, memCfg=null, pstCfg=null, dsCfg=DataStorageConfiguration [pageSize=0, concLvl=0, sysDataRegConf=org.apache.ignite.configuration.SystemDataRegionConfiguration@1d269ed7, dfltDataRegConf=DataRegionConfiguration [name=default, maxSize=3221932441, initSize=268435456, swapPath=null, pageEvictionMode=DISABLED, pageReplacementMode=CLOCK, evictionThreshold=0.9, emptyPagesPoolSize=100, metricsEnabled=false, metricsSubIntervalCount=5, metricsRateTimeInterval=60000, persistenceEnabled=true, checkpointPageBufSize=0, lazyMemoryAllocation=true, warmUpCfg=null, memoryAllocator=null, cdcEnabled=false], dataRegions=null, storagePath=null, checkpointFreq=180000, lockWaitTime=30000, checkpointThreads=4, checkpointWriteOrder=SEQUENTIAL, walHistSize=20, maxWalArchiveSize=1073741824, walSegments=10, walSegmentSize=67108864, walPath=db/wal, walArchivePath=db/wal/archive, cdcWalPath=db/wal/cdc, metricsEnabled=false, walMode=LOG_ONLY, walTlbSize=131072, walBuffSize=0, walFlushFreq=2000, walFsyncDelay=1000, walRecordIterBuffSize=67108864, alwaysWriteFullPages=false, fileIOFactory=org.apache.ignite.internal.processors.cache.persistence.file.AsyncFileIOFactory@71154f21, metricsSubIntervalCnt=5, metricsRateTimeInterval=60000, walAutoArchiveAfterInactivity=-1, walForceArchiveTimeout=-1, writeThrottlingEnabled=false, walCompactionEnabled=false, walCompactionLevel=1, checkpointReadLockTimeout=null, walPageCompression=DISABLED, walPageCompressionLevel=null, dfltWarmUpCfg=null, encCfg=org.apache.ignite.configuration.EncryptionConfiguration@2516fc68, defragmentationThreadPoolSize=4, minWalArchiveSize=-1, memoryAllocator=null], snapshotPath=snapshots, snapshotThreadPoolSize=4, activeOnStart=true, activeOnStartPropSetFlag=false, autoActivation=true, autoActivationPropSetFlag=false, clusterStateOnStart=null, sqlConnCfg=null, cliConnCfg=ClientConnectorConfiguration [host=null, port=10800, portRange=100, sockSndBufSize=0, sockRcvBufSize=0, tcpNoDelay=true, maxOpenCursorsPerConn=128, threadPoolSize=8, selectorCnt=4, idleTimeout=0, handshakeTimeout=10000, jdbcEnabled=true, odbcEnabled=true, thinCliEnabled=true, sslEnabled=true, useIgniteSslCtxFactory=true, sslClientAuth=true, sslCtxFactory=null, thinCliCfg=ThinClientConfiguration [maxActiveTxPerConn=100, maxActiveComputeTasksPerConn=0, sendServerExcStackTraceToClient=false]], mvccVacuumThreadCnt=2, mvccVacuumFreq=5000, authEnabled=true, failureHnd=null, commFailureRslvr=null, sqlCfg=SqlConfiguration [longQryWarnTimeout=3000, dfltQryTimeout=0, sqlQryHistSize=1000, validationEnabled=false], asyncContinuationExecutor=null][15:58:09,580][INFO][main][IgniteKernal] Daemon mode: off[15:58:09,580][INFO][main][IgniteKernal] OS: Linux 4.18.0-372.26.1.el8_6.x86_64 amd64[15:58:09,580][INFO][main][IgniteKernal] OS user: ignite[15:58:09,586][INFO][main][IgniteKernal] PID: 360359[15:58:09,587][INFO][main][IgniteKernal] Language runtime: Java Platform API Specification ver. 11[15:58:09,587][INFO][main][IgniteKernal] VM information: OpenJDK Runtime Environment 11.0.13+8-LTS Azul Systems, Inc. OpenJDK 64-Bit Server VM 11.0.13+8-LTS[15:58:09,588][INFO][main][IgniteKernal] VM total memory: 6.0GB[15:58:09,588][INFO][main][IgniteKernal] Remote Management [restart: on, REST: on, JMX (remote: off)][15:58:09,588][INFO][main][IgniteKernal] Logger: JavaLogger [quiet=true, config=null][15:58:09,588][INFO][main][IgniteKernal] IGNITE_HOME=/usr/share/apache-ignite[15:58:09,589][INFO][main][IgniteKernal] VM arguments: [--add-exports=java.base/jdk.internal.misc=ALL-UNNAMED, --add-exports=java.base/sun.nio.ch=ALL-UNNAMED, --add-exports=java.management/com.sun.jmx.mbeanserver=ALL-UNNAMED, --add-exports=jdk.internal.jvmstat/sun.jvmstat.monitor=ALL-UNNAMED, --add-exports=java.base/sun.reflect.generics.reflectiveObjects=ALL-UNNAMED, --add-opens=jdk.management/com.sun.management.internal=ALL-UNNAMED, --illegal-access=permit, -Xms6g, -Xmx6g, -XX:MaxMetaspaceSize=256m, -Djdk.tls.server.protocols="TLSv1.2", -Djdk.tls.client.protocols="TLSv1.2", -Djava.net.preferIPv4Stack=true, -Dfile.encoding=UTF-8, -DIGNITE_QUIET=true, -DIGNITE_SUCCESS_FILE=/usr/share/apache-ignite/work/ignite_success_3a811543-f125-4f02-b5b0-3636234ccf5d, -DIGNITE_HOME=/usr/share/apache-ignite, -DIGNITE_PROG_NAME=/usr/share/apache-ignite/bin/ignite.sh][15:58:09,589][INFO][main][IgniteKernal] System cache's DataRegion size is configured to 40 MB. Use DataStorageConfiguration.systemRegionInitialSize property to change the setting.[15:58:09,589][INFO][main][IgniteKernal] Configured caches [in 'sysMemPlc' dataRegion: ['ignite-sys-cache'], in 'default' dataRegion: ['CacheRosettaNet2MessageCorrelation', 'CacheOftpReceiptsCorrelation', 'CacheAs2ReceiptsCorrelation', 'table', 'uniqueid', 'timers', 'B2BiClusterStatusCache']][15:58:09,589][INFO][main][IgniteKernal] 3-rd party licenses can be found at: /usr/share/apache-ignite/libs/licenses[15:58:09,667][INFO][main][IgnitePluginProcessor] Configured plugins:[15:58:09,668][INFO][main][IgnitePluginProcessor] ^-- None[15:58:09,668][INFO][main][IgnitePluginProcessor] [15:58:09,671][INFO][main][FailureProcessor] Configured failure handler: [hnd=StopNodeOrHaltFailureHandler [tryStop=false, timeout=0, super=AbstractFailureHandler [ignoredFailureTypes=UnmodifiableSet [SYSTEM_WORKER_BLOCKED, SYSTEM_CRITICAL_OPERATION_TIMEOUT]]]][15:58:10,032][INFO][main][TcpCommunicationSpi] Successfully bound communication NIO server to TCP port [port=49100, locHost=0.0.0.0/0.0.0.0, selectorsCnt=4, selectorSpins=0, pairedConn=false][15:58:10,076][INFO][main][GridCollisionManager] Collision resolution is disabled (all jobs will be activated upon arrival).[15:58:10,171][INFO][main][TcpDiscoverySpi] Successfully bound to TCP port [port=49500, localHost=0.0.0.0/0.0.0.0, locNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c][15:58:10,175][INFO][main][PdsFoldersResolver] Successfully locked persistence storage folder [/usr/share/apache-ignite/work/db/node00-59d50ff1-b50d-4491-88da-e03b485598bf][15:58:10,175][INFO][main][PdsFoldersResolver] Consistent ID used for local node is [59d50ff1-b50d-4491-88da-e03b485598bf] according to persistence data storage folders[15:58:10,175][INFO][main][MaintenanceProcessor] Resolved store directory for node persistent data: /usr/share/apache-ignite/work/db/node00-59d50ff1-b50d-4491-88da-e03b485598bf[15:58:10,203][INFO][main][CacheObjectBinaryProcessorImpl] Resolved directory for serialized binary metadata: /usr/share/apache-ignite/work/db/binary_meta/node00-59d50ff1-b50d-4491-88da-e03b485598bf[15:58:10,404][INFO][main][FilePageStoreManager] Resolved page store work directory: /usr/share/apache-ignite/work/db/node00-59d50ff1-b50d-4491-88da-e03b485598bf[15:58:10,410][INFO][main][FileWriteAheadLogManager] Resolved write ahead log work directory: /usr/share/apache-ignite/work/db/wal/node00-59d50ff1-b50d-4491-88da-e03b485598bf[15:58:10,410][INFO][main][FileWriteAheadLogManager] Resolved write ahead log archive directory: /usr/share/apache-ignite/work/db/wal/archive/node00-59d50ff1-b50d-4491-88da-e03b485598bf[15:58:10,439][INFO][main][FileHandleManagerImpl] Initialized write-ahead log manager [mode=LOG_ONLY][15:58:10,470][INFO][main][GridCacheDatabaseSharedManager] Configured data regions initialized successfully [total=5][15:58:10,492][INFO][main][IgniteSnapshotManager] Resolved snapshot work directory: /usr/share/apache-ignite/work/snapshots[15:58:10,492][INFO][main][IgniteSnapshotManager] Resolved temp directory for snapshot creation: /usr/share/apache-ignite/work/db/node00-59d50ff1-b50d-4491-88da-e03b485598bf/snp[15:58:10,550][WARNING][main][IgniteH2Indexing] Serialization of Java objects in H2 was enabled.[15:58:10,756][INFO][main][ClientListenerProcessor] Client connector processor has started on TCP port 10800[15:58:10,811][INFO][main][GridTcpRestProtocol] Command protocol successfully started [name=TCP binary, host=0.0.0.0/0.0.0.0, port=11211][15:58:10,863][INFO][main][IgniteKernal] Non-loopback local IPs: 10.x.x.x[15:58:10,863][INFO][main][IgniteKernal] Enabled local MACs: 0228462B54B4[15:58:10,874][INFO][main][CheckpointMarkersStorage] Read checkpoint status [startMarker=/usr/share/apache-ignite/work/db/node00-59d50ff1-b50d-4491-88da-e03b485598bf/cp/1665583087606-9cb9b48a-ff36-4d45-8012-b0c9db0fa103-START.bin, endMarker=/usr/share/apache-ignite/work/db/node00-59d50ff1-b50d-4491-88da-e03b485598bf/cp/1665582882679-abb46ebd-aad4-42f5-8026-5619b86e7dfc-END.bin][15:58:10,881][INFO][main][PageMemoryImpl] Started page memory [memoryAllocated=100.0 MiB, pages=24812, tableSize=1.9 MiB, replacementSize=3.0 KiB, checkpointBuffer=100.0 MiB][15:58:10,882][INFO][main][GridCacheDatabaseSharedManager] Checking memory state [lastValidPos=WALPointer [idx=347, fileOff=22633648, len=209777], lastMarked=WALPointer [idx=348, fileOff=6916543, len=209777], lastCheckpointId=9cb9b48a-ff36-4d45-8012-b0c9db0fa103][15:58:11,057][INFO][main][GridCacheDatabaseSharedManager] Found last checkpoint marker [cpId=9cb9b48a-ff36-4d45-8012-b0c9db0fa103, pos=WALPointer [idx=348, fileOff=6916543, len=209777]][15:58:11,101][INFO][main][GridCacheDatabaseSharedManager] Applying lost metastore updates since last checkpoint record [lastMarked=WALPointer [idx=348, fileOff=6916543, len=209777], lastCheckpointId=9cb9b48a-ff36-4d45-8012-b0c9db0fa103][15:58:11,124][INFO][main][GridCacheDatabaseSharedManager] Finished applying WAL changes [updatesApplied=0, time=20 ms][15:58:11,124][INFO][main][GridCacheProcessor] Restoring partition state for local groups.[15:58:11,128][INFO][main][GridCacheProcessor] Finished restoring partition state for local groups [groupsProcessed=0, partitionsProcessed=0, time=10ms][15:58:11,160][INFO][main][GridEncryptionManager] Encryption keys loaded from metastore. [grps=, masterKeyName=null][15:58:11,188][INFO][main][GridClusterStateProcessor] Restoring history for BaselineTopology[id=14][15:58:11,262][WARNING][main][GridLocalConfigManager] Static configuration for the following caches will be ignored because a persistent cache with the same name already exist (see https://apacheignite.readme.io/docs/cache-configuration for more information): [CacheAs2ReceiptsCorrelation, B2BiClusterStatusCache, timers, CacheOftpReceiptsCorrelation, CacheRosettaNet2MessageCorrelation, table, uniqueid][15:58:11,279][INFO][main][ClusterProcessor] Cluster ID and tag has been read from metastorage: ClusterIdAndTag [id=37a19cd4-f930-4a62-970d-91e003ea4648, tag=awesome_einstein][15:58:11,285][INFO][main][IgniteClusterImpl] Shutdown policy was updated [oldVal=null, newVal=null][15:58:11,288][INFO][main][DistributedBaselineConfiguration] Baseline parameter 'baselineAutoAdjustEnabled' was changed from 'null' to 'true'[15:58:11,288][INFO][main][DistributedBaselineConfiguration] Baseline parameter 'baselineAutoAdjustTimeout' was changed from 'null' to '30000'[15:58:11,289][INFO][main][IgniteTxManager] Transactions parameter 'txOwnerDumpRequestsAllowed' was changed from 'null' to 'true'[15:58:11,289][INFO][main][IgniteTxManager] Transactions parameter 'longOperationsDumpTimeout' was changed from 'null' to '60000'[15:58:11,289][INFO][main][IgniteTxManager] Transactions parameter 'longTransactionTimeDumpThreshold' was changed from 'null' to '0'[15:58:11,290][INFO][main][IgniteTxManager] Transactions parameter 'transactionTimeDumpSamplesCoefficient' was changed from 'null' to '0.0'[15:58:11,291][INFO][main][IgniteTxManager] Transactions parameter 'longTransactionTimeDumpSamplesPerSecondLimit' was changed from 'null' to '5'[15:58:11,291][INFO][main][IgniteTxManager] Transactions parameter 'collisionsDumpInterval' was changed from 'null' to '1000'[15:58:11,291][INFO][main][GridCacheDatabaseSharedManager] Historical rebalance WAL threshold changed [property=historical.rebalance.threshold, oldVal=null, newVal=500][15:58:11,292][INFO][main][GridCacheDatabaseSharedManager] Checkpoint frequency deviation changed [oldVal=null, newVal=null][15:58:11,292][INFO][main][IgniteSnapshotManager] The snapshot transfer rate is not limited.[15:58:11,293][INFO][main][IgniteStatisticsManagerImpl] Statistics usage state was changed from null to null[15:58:11,293][INFO][main][IgniteH2Indexing] SQL parameter 'sql.disabledFunctions' was changed from 'null' to '[FILE_WRITE, CANCEL_SESSION, MEMORY_USED, CSVREAD, LINK_SCHEMA, MEMORY_FREE, FILE_READ, CSVWRITE, SESSION_ID, LOCK_MODE]'[15:58:11,294][INFO][main][IgniteH2Indexing] SQL parameter 'sql.defaultQueryTimeout' was changed from 'null' to '0'[15:58:11,298][INFO][main][FilePageStoreManager] Cleanup cache stores [total=1, left=0, cleanFiles=false][15:58:11,306][INFO][main][PageMemoryImpl] Started page memory [memoryAllocated=100.0 MiB, pages=24812, tableSize=1.9 MiB, replacementSize=3.0 KiB, checkpointBuffer=100.0 MiB][15:58:11,307][INFO][main][PageMemoryImpl] Started page memory [memoryAllocated=100.0 MiB, pages=24812, tableSize=1.9 MiB, replacementSize=3.0 KiB, checkpointBuffer=100.0 MiB][15:58:11,309][INFO][main][PageMemoryImpl] Started page memory [memoryAllocated=100.0 MiB, pages=24812, tableSize=1.9 MiB, replacementSize=3.0 KiB, checkpointBuffer=100.0 MiB][15:58:11,310][INFO][main][GridCacheDatabaseSharedManager] Data Regions Started: 5[15:58:11,311][INFO][main][GridCacheDatabaseSharedManager] Starting binary memory restore for: [577364201, -252123144, 839693645, -873668146, 680913872, 1656333392, -252395107, -1139151374, -727941769, -1329635437, -2100569601, -2016072032, -1365813811, 110115790, -294459220][15:58:12,590][INFO][main][CheckpointMarkersStorage] Read checkpoint status [startMarker=/usr/share/apache-ignite/work/db/node00-59d50ff1-b50d-4491-88da-e03b485598bf/cp/1665583087606-9cb9b48a-ff36-4d45-8012-b0c9db0fa103-START.bin, endMarker=/usr/share/apache-ignite/work/db/node00-59d50ff1-b50d-4491-88da-e03b485598bf/cp/1665582882679-abb46ebd-aad4-42f5-8026-5619b86e7dfc-END.bin][15:58:12,590][INFO][main][GridCacheDatabaseSharedManager] Checking memory state [lastValidPos=WALPointer [idx=347, fileOff=22633648, len=209777], lastMarked=WALPointer [idx=348, fileOff=6916543, len=209777], lastCheckpointId=9cb9b48a-ff36-4d45-8012-b0c9db0fa103][15:58:12,612][WARNING][main][GridCacheDatabaseSharedManager] Ignite node stopped in the middle of checkpoint. Will restore memory state and finish checkpoint on node start.[15:58:12,628][INFO][main][PageMemoryImpl] Started page memory [memoryAllocated=3.0 GiB, pages=762460, tableSize=59.3 MiB, replacementSize=93.1 KiB, checkpointBuffer=768.2 MiB][15:58:13,049][INFO][main][GridCacheDatabaseSharedManager] Found last checkpoint marker [cpId=9cb9b48a-ff36-4d45-8012-b0c9db0fa103, pos=WALPointer [idx=348, fileOff=6916543, len=209777]][15:58:13,059][INFO][main][GridCacheDatabaseSharedManager] Finished applying memory changes [changesApplied=23071, time=426 ms][15:58:13,588][INFO][main][CheckpointWorkflow] Checkpoint finished [cpId=9cb9b48a-ff36-4d45-8012-b0c9db0fa103, pages=8918, markPos=WALPointer [idx=348, fileOff=6916543, len=209777], pagesWrite=419ms, fsync=101ms, total=520ms][15:58:13,596][INFO][main][GridCacheDatabaseSharedManager] Binary memory state restored at node startup [restoredPtr=WALPointer [idx=348, fileOff=7126320, len=0]][15:58:13,600][INFO][main][FileWriteAheadLogManager] Resuming logging to WAL segment [file=/usr/share/apache-ignite/work/db/wal/node00-59d50ff1-b50d-4491-88da-e03b485598bf/0000000000000008.wal, offset=7126320, ver=2][15:58:13,699][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=CacheAs2ReceiptsCorrelation, id=577364201, dataRegionName=default, mode=PARTITIONED, atomicity=TRANSACTIONAL, backups=2, mvcc=false][15:58:13,786][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=SQL_PUBLIC_RELATIONAL_META, id=-252123144, dataRegionName=default, mode=REPLICATED, atomicity=ATOMIC, backups=2147483647, mvcc=false][15:58:13,790][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=B2BiClusterStatusCache, id=839693645, dataRegionName=default, mode=PARTITIONED, atomicity=ATOMIC, backups=2, mvcc=false][15:58:13,794][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=timers, id=-873668146, dataRegionName=default, mode=PARTITIONED, atomicity=TRANSACTIONAL, backups=2, mvcc=false][15:58:13,801][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=SQL_PUBLIC_RELATIONAL_CHANGES, id=680913872, dataRegionName=default, mode=REPLICATED, atomicity=ATOMIC, backups=2147483647, mvcc=false][15:58:13,807][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=datastructures_ATOMIC_PARTITIONED_1@default-ds-group, id=-522736207, group=default-ds-group, dataRegionName=default, mode=PARTITIONED, atomicity=ATOMIC, backups=1, mvcc=false][15:58:13,812][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=SQL_PUBLIC_B2BICLUSTERSTATUS, id=1656333392, dataRegionName=default, mode=REPLICATED, atomicity=TRANSACTIONAL, backups=2147483647, mvcc=false][15:58:13,817][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=SQL_PUBLIC_RELATIONAL_DATA, id=-252395107, dataRegionName=default, mode=REPLICATED, atomicity=ATOMIC, backups=2147483647, mvcc=false][15:58:13,821][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=CacheOftpReceiptsCorrelation, id=-1139151374, dataRegionName=default, mode=PARTITIONED, atomicity=TRANSACTIONAL, backups=2, mvcc=false][15:58:13,826][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=SQL_PUBLIC_TABLEINFO, id=-727941769, dataRegionName=default, mode=REPLICATED, atomicity=TRANSACTIONAL, backups=2147483647, mvcc=false][15:58:13,834][WARNING][main][GridH2Table] Index with the given set or subset of columns already exists (consider dropping either new or existing index) [cacheName=SQL_PUBLIC_TIMERS, schemaName=PUBLIC, tableName=TIMERS, newIndexName=TIMERS_QI_IDX, existingIndexName=_key_PK, existingIndexColumns=[QUALIFIER, IDENTIFIER]][15:58:13,835][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=SQL_PUBLIC_TIMERS, id=-1329635437, dataRegionName=default, mode=REPLICATED, atomicity=ATOMIC, backups=2147483647, mvcc=false][15:58:13,838][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=ignite-sys-atomic-cache@default-ds-group, id=1481046058, group=default-ds-group, dataRegionName=default, mode=PARTITIONED, atomicity=TRANSACTIONAL, backups=1, mvcc=false][15:58:13,840][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=ignite-sys-cache, id=-2100569601, dataRegionName=sysMemPlc, mode=REPLICATED, atomicity=TRANSACTIONAL, backups=2147483647, mvcc=false][15:58:13,843][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=CacheRosettaNet2MessageCorrelation, id=-2016072032, dataRegionName=default, mode=PARTITIONED, atomicity=TRANSACTIONAL, backups=2, mvcc=false][15:58:13,845][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=datastructures_ATOMIC_PARTITIONED_1@default-ds-group#SET_ASYNC_PROTO_QUEUES_NAMES, id=661484788, group=default-ds-group, dataRegionName=default, mode=PARTITIONED, atomicity=ATOMIC, backups=1, mvcc=false][15:58:13,848][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=table, id=110115790, dataRegionName=default, mode=PARTITIONED, atomicity=TRANSACTIONAL, backups=2, mvcc=false][15:58:13,852][INFO][main][GridCacheProcessor] Started cache in recovery mode [name=uniqueid, id=-294459220, dataRegionName=default, mode=PARTITIONED, atomicity=TRANSACTIONAL, backups=2, mvcc=false][15:58:13,855][INFO][main][GridCacheDatabaseSharedManager] Binary recovery performed in 2544 ms.[15:58:13,855][INFO][main][CheckpointMarkersStorage] Read checkpoint status [startMarker=/usr/share/apache-ignite/work/db/node00-59d50ff1-b50d-4491-88da-e03b485598bf/cp/1665583087606-9cb9b48a-ff36-4d45-8012-b0c9db0fa103-START.bin, endMarker=/usr/share/apache-ignite/work/db/node00-59d50ff1-b50d-4491-88da-e03b485598bf/cp/1665583087606-9cb9b48a-ff36-4d45-8012-b0c9db0fa103-END.bin][15:58:13,856][INFO][main][GridCacheDatabaseSharedManager] Applying lost cache updates since last checkpoint record [lastMarked=WALPointer [idx=348, fileOff=6916543, len=209777], lastCheckpointId=9cb9b48a-ff36-4d45-8012-b0c9db0fa103][15:58:13,882][WARNING][main][FileWriteAheadLogManager] WAL segment tail reached. [idx=348, isWorkDir=true, serVer=org.apache.ignite.internal.processors.cache.persistence.wal.serializer.RecordV2Serializer@774d8276, actualFilePtr=WALPointer [idx=348, fileOff=7126349, len=0]][15:58:13,886][INFO][main][GridCacheDatabaseSharedManager] Finished applying WAL changes [updatesApplied=0, time=33 ms][15:58:13,886][INFO][main][GridCacheProcessor] Restoring partition state for local groups.[15:58:16,743][INFO][main][GridCacheProcessor] Finished restoring partition state for local groups [groupsProcessed=15, partitionsProcessed=11364, time=2s][15:58:16,983][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=57634][15:58:16,988][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=57634][15:58:16,989][INFO][tcp-disco-sock-reader-[]-#4-#59][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:57634, rmtPort=57634][15:58:17,050][INFO][tcp-disco-sock-reader-[]-#4-#59][TcpDiscoverySpi] Received ping request from the remote node [rmtNodeId=291ffb11-da63-4ed7-80fd-0659e7f51dab, rmtAddr=/10.x.x.x:57634, rmtPort=57634][15:58:17,051][INFO][tcp-disco-sock-reader-[]-#4-#59][TcpDiscoverySpi] Finished writing ping response [rmtNodeId=291ffb11-da63-4ed7-80fd-0659e7f51dab, rmtAddr=/10.x.x.x:57634, rmtPort=57634][15:58:17,052][WARNING][tcp-disco-sock-reader-[]-#4-#59][TcpDiscoverySpi] Failed to shutdown socket: closing inbound before receiving peer's close_notifyjavax.net.ssl.SSLException: closing inbound before receiving peer's close_notify at java.base/sun.security.ssl.SSLSocketImpl.shutdownInput(SSLSocketImpl.java:763) at java.base/sun.security.ssl.SSLSocketImpl.shutdownInput(SSLSocketImpl.java:742) at org.apache.ignite.internal.util.IgniteUtils.close(IgniteUtils.java:4285) at org.apache.ignite.spi.discovery.tcp.ServerImpl$SocketReader.body(ServerImpl.java:7321) at org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:58)[15:58:17,053][INFO][tcp-disco-sock-reader-[]-#4-#59][TcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/10.x.x.x:57634, rmtPort=57634, rmtNodeId=null][15:58:17,111][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=41080][15:58:17,111][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=41080][15:58:17,112][INFO][tcp-disco-sock-reader-[]-#5-#60][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:41080, rmtPort=41080][15:58:17,119][INFO][tcp-disco-sock-reader-[291ffb11 10.x.x.x:41080]-#5-#60][TcpDiscoverySpi] Initialized connection with remote server node [nodeId=291ffb11-da63-4ed7-80fd-0659e7f51dab, rmtAddr=/10.x.x.x:41080][15:58:17,285][INFO][tcp-disco-msg-worker-[]-#2-#57][TcpDiscoverySpi] New next node [newNext=TcpDiscoveryNode [id=cf53e0f7-2552-491f-ae6e-3195ac331525, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, serverign1.domain.name.removed.net/10.x.x.x:49500], discPort=49500, order=1, intOrder=1, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false]][15:58:17,419][WARNING][main][GridDiscoveryManager] Local node's value of 'java.net.preferIPv4Stack' system property differs from remote node's (all nodes in topology should have identical value) [locPreferIpV4=true, rmtPreferIpV4=null, locId8=65622274, rmtId8=e128f204, rmtAddrs=[serverapp6.domain.name.removed.net/0:0:0:0:0:0:0:1%lo, /10.x.x.x, /127.0.0.1], rmtNode=ClusterNode [id=e128f204-dac2-4944-8d39-7ed1f4388b97, order=4, addr=[0:0:0:0:0:0:0:1%lo, 10.x.x.x, 127.0.0.1], daemon=false]][15:58:17,419][INFO][disco-notifier-worker-#56][MvccProcessorImpl] Assigned mvcc coordinator [crd=MvccCoordinator [topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], nodeId=cf53e0f7-2552-491f-ae6e-3195ac331525, ver=1665496530664, local=false, initialized=false]][15:58:17,437][INFO][sys-#55][ClusterProcessor] Writing cluster ID and tag to metastorage on ready for write ClusterIdAndTag [id=37a19cd4-f930-4a62-970d-91e003ea4648, tag=awesome_einstein][15:58:17,675][INFO][exchange-worker-#65][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=65622274-1387-415c-aed1-8a7ea2d0c09c, customEvt=null, allowMerge=true, exchangeFreeSwitch=false][15:58:17,676][INFO][exchange-worker-#65][FilePageStoreManager] Resolved page store work directory: /usr/share/apache-ignite/work/db/node00-59d50ff1-b50d-4491-88da-e03b485598bf[15:58:17,686][INFO][exchange-worker-#65][FileWriteAheadLogManager] Resuming logging to WAL segment [file=/usr/share/apache-ignite/work/db/wal/node00-59d50ff1-b50d-4491-88da-e03b485598bf/0000000000000008.wal, offset=7126349, ver=2][15:58:17,688][INFO][exchange-worker-#65][GridClusterStateProcessor] Writing BaselineTopology[id=14][15:58:17,710][INFO][exchange-worker-#65][GridCacheDatabaseSharedManager] Finish recovery performed in 25 ms.[15:58:17,711][INFO][exchange-worker-#65][msg] Components activation performed in 35 ms.[15:58:17,723][INFO][sys-#49][GridCacheProcessor] Finished recovery for cache [cache=datastructures_ATOMIC_PARTITIONED_1@default-ds-group#SET_ASYNC_PROTO_QUEUES_NAMES, grp=default-ds-group, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,742][INFO][exchange-worker-#65][GridCacheProcessor] Finished recovery for cache [cache=datastructures_ATOMIC_PARTITIONED_1@default-ds-group, grp=default-ds-group, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,743][INFO][exchange-worker-#65][GridCacheProcessor] Finished recovery for cache [cache=SQL_PUBLIC_RELATIONAL_META, grp=SQL_PUBLIC_RELATIONAL_META, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,743][INFO][exchange-worker-#65][GridCacheProcessor] Finished recovery for cache [cache=SQL_PUBLIC_TIMERS, grp=SQL_PUBLIC_TIMERS, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,743][INFO][sys-#55][GridCacheProcessor] Finished recovery for cache [cache=uniqueid, grp=uniqueid, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,743][INFO][sys-#55][GridCacheProcessor] Finished recovery for cache [cache=SQL_PUBLIC_RELATIONAL_DATA, grp=SQL_PUBLIC_RELATIONAL_DATA, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,743][INFO][sys-#55][GridCacheProcessor] Finished recovery for cache [cache=ignite-sys-cache, grp=ignite-sys-cache, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,744][INFO][sys-#54][GridCacheProcessor] Finished recovery for cache [cache=SQL_PUBLIC_B2BICLUSTERSTATUS, grp=SQL_PUBLIC_B2BICLUSTERSTATUS, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,744][INFO][sys-#53][GridCacheProcessor] Finished recovery for cache [cache=SQL_PUBLIC_TABLEINFO, grp=SQL_PUBLIC_TABLEINFO, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,744][INFO][sys-#54][GridCacheProcessor] Finished recovery for cache [cache=CacheRosettaNet2MessageCorrelation, grp=CacheRosettaNet2MessageCorrelation, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,744][INFO][sys-#54][GridCacheProcessor] Finished recovery for cache [cache=table, grp=table, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,743][INFO][sys-#48][GridCacheProcessor] Finished recovery for cache [cache=B2BiClusterStatusCache, grp=B2BiClusterStatusCache, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,744][INFO][sys-#53][GridCacheProcessor] Finished recovery for cache [cache=ignite-sys-atomic-cache@default-ds-group, grp=default-ds-group, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,744][INFO][sys-#49][GridCacheProcessor] Finished recovery for cache [cache=CacheAs2ReceiptsCorrelation, grp=CacheAs2ReceiptsCorrelation, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,745][INFO][sys-#48][GridCacheProcessor] Finished recovery for cache [cache=SQL_PUBLIC_RELATIONAL_CHANGES, grp=SQL_PUBLIC_RELATIONAL_CHANGES, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,745][INFO][sys-#49][GridCacheProcessor] Finished recovery for cache [cache=timers, grp=timers, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,745][INFO][sys-#48][GridCacheProcessor] Finished recovery for cache [cache=CacheOftpReceiptsCorrelation, grp=CacheOftpReceiptsCorrelation, startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:17,745][INFO][exchange-worker-#65][GridCacheProcessor] Starting caches on local join performed in 31 ms.[15:58:17,752][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Skipped waiting for partitions release future (local node is joining) [topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:18,101][INFO][db-checkpoint-thread-#70][Checkpointer] Checkpoint started [checkpointId=45430ff8-d073-4c12-b303-c6686302a72e, startPtr=WALPointer [idx=348, fileOff=31597576, len=209793], checkpointBeforeLockTime=195ms, checkpointLockWait=0ms, checkpointListenersExecuteTime=45ms, checkpointLockHoldTime=62ms, walCpRecordFsyncDuration=53ms, writeCheckpointEntryDuration=9ms, splitAndSortCpPagesDuration=8ms, pages=5914, reason='node started'][15:58:18,243][INFO][exchange-worker-#65][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], crd=false][15:58:18,347][INFO][grid-nio-worker-tcp-comm-1-#24%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:52185][15:58:18,391][INFO][grid-nio-worker-tcp-comm-2-#25%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:39979][15:58:18,397][INFO][sys-#50][GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=cf53e0f7-2552-491f-ae6e-3195ac331525, resVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:18,472][INFO][grid-nio-worker-tcp-comm-3-#26%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:56541][15:58:18,518][INFO][sys-#50][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], err=null, rebalanced=false, wasRebalanced=false][15:58:18,578][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=CacheAs2ReceiptsCorrelation, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=SQL_PUBLIC_RELATIONAL_META, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=B2BiClusterStatusCache, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=timers, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=SQL_PUBLIC_RELATIONAL_CHANGES, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=datastructures_ATOMIC_PARTITIONED_1@default-ds-group, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=SQL_PUBLIC_B2BICLUSTERSTATUS, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=SQL_PUBLIC_RELATIONAL_DATA, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=CacheOftpReceiptsCorrelation, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=SQL_PUBLIC_TABLEINFO, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=SQL_PUBLIC_TIMERS, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=ignite-sys-atomic-cache@default-ds-group, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=ignite-sys-cache, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=CacheRosettaNet2MessageCorrelation, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=datastructures_ATOMIC_PARTITIONED_1@default-ds-group#SET_ASYNC_PROTO_QUEUES_NAMES, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=table, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,579][INFO][sys-#50][GridCacheProcessor] Finish proxy initialization, cacheName=uniqueid, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,580][INFO][pub-#82][GridCacheProcessor] Failed to wait proxy initialization, cache=uniqueid, localNodeId=65622274-1387-415c-aed1-8a7ea2d0c09c[15:58:18,584][INFO][sys-#50][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=65622274-1387-415c-aed1-8a7ea2d0c09c, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=65622274-1387-415c-aed1-8a7ea2d0c09c, consistentId=59d50ff1-b50d-4491-88da-e03b485598bf, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign3.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=58, intOrder=42, lastExchangeTime=1665583098411, loc=true, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], rebalanced=false, done=true, newCrdFut=null], topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0]][15:58:18,584][INFO][sys-#50][GridDhtPartitionsExchangeFuture] Exchange timings [startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], stage="Waiting in exchange queue" (241 ms), stage="Exchange parameters initialization" (3 ms), stage="Components activation" (35 ms), stage="Determine exchange type" (38 ms), stage="Preloading notification" (0 ms), stage="Restore partition states" (1 ms), stage="After states restored callback" (276 ms), stage="WAL history reservation" (13 ms), stage="Waiting for Full message" (354 ms), stage="Affinity recalculation" (75 ms), stage="Full map updating" (45 ms), stage="Exchange done" (66 ms), stage="Total time" (1147 ms)][15:58:18,584][INFO][sys-#50][GridDhtPartitionsExchangeFuture] Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], stage="Affinity fetch" (35 ms) (parent=Determine exchange type), stage="Restore partition states [grp=table]" (1 ms) (parent=Restore partition states), stage="Restore partition states [grp=uniqueid]" (0 ms) (parent=Restore partition states), stage="Restore partition states [grp=timers]" (0 ms) (parent=Restore partition states), stage="Affinity initialization (local join) [grp=CacheAs2ReceiptsCorrelation]" (75 ms) (parent=Affinity recalculation), stage="Affinity initialization (local join) [grp=B2BiClusterStatusCache]" (72 ms) (parent=Affinity recalculation), stage="Affinity initialization (local join) [grp=table]" (70 ms) (parent=Affinity recalculation)][15:58:18,668][INFO][exchange-worker-#65][GridCachePartitionExchangeManager] Rebalancing scheduled [order=[ignite-sys-cache, default-ds-group, B2BiClusterStatusCache, CacheAs2ReceiptsCorrelation, CacheOftpReceiptsCorrelation, CacheRosettaNet2MessageCorrelation, SQL_PUBLIC_B2BICLUSTERSTATUS, SQL_PUBLIC_RELATIONAL_CHANGES, SQL_PUBLIC_RELATIONAL_DATA, SQL_PUBLIC_RELATIONAL_META, SQL_PUBLIC_TABLEINFO, SQL_PUBLIC_TIMERS, table, timers, uniqueid], top=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1, evt=NODE_JOINED, node=65622274-1387-415c-aed1-8a7ea2d0c09c][15:58:18,669][INFO][exchange-worker-#65][GridDhtPartitionDemander] Prepared rebalancing [grp=default-ds-group, mode=SYNC, supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, partitionsCount=3, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1][15:58:18,691][INFO][grid-nio-worker-tcp-comm-0-#23%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:56543][15:58:18,695][INFO][exchange-worker-#65][PartitionsEvictManager] Eviction in progress [groups=1, remainingPartsToEvict=0][15:58:18,698][INFO][exchange-worker-#65][PartitionsEvictManager] Group eviction in progress [grpName=default-ds-group, grpId=-1365813811, remainingPartsToEvict=1, partsEvictInProgress=0, totalParts=694][15:58:18,700][INFO][exchange-worker-#65][PartitionsEvictManager] Partitions have been scheduled for eviction: [grpId=-1365813811, grpName=default-ds-group, clearing=[210]][15:58:18,701][INFO][exchange-worker-#65][GridDhtPartitionDemander] Prepared rebalancing [grp=default-ds-group, mode=SYNC, supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, partitionsCount=9, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1][15:58:18,725][INFO][sys-#49][GridDhtPartitionDemander] Starting rebalance routine [default-ds-group, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, fullPartitions=[210, 930, 1001], histPartitions=[], rebalanceId=1][15:58:18,737][INFO][sys-#54][GridDhtPartitionDemander] Starting rebalance routine [default-ds-group, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, fullPartitions=[208, 221, 237, 239, 522, 565, 817, 823, 876], histPartitions=[], rebalanceId=1][15:58:19,012][INFO][rebalance-#86][GridDhtPartitionDemander] Completed rebalancing [rebalanceId=1, grp=default-ds-group, supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, partitions=9, entries=3, duration=343ms, bytesRcvd=860.0 B, bandwidth=860.0 B/sec, histPartitions=0, histEntries=0, histBytesRcvd=0.0 B, fullPartitions=9, fullEntries=3, fullBytesRcvd=860.0 B, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], progress=1/2][15:58:19,025][INFO][rebalance-#86][GridDhtPartitionDemander] Completed (final) rebalancing [rebalanceId=1, grp=default-ds-group, supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, partitions=3, entries=6, duration=356ms, bytesRcvd=1.7 KB, bandwidth=1.7 KB/sec, histPartitions=0, histEntries=0, histBytesRcvd=0.0 B, fullPartitions=3, fullEntries=6, fullBytesRcvd=1.7 KB, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], progress=2/2][15:58:19,026][INFO][rebalance-#86][GridDhtPartitionDemander] Completed rebalance future: RebalanceFuture [state=STARTED, grp=CacheGroupContext [grp=default-ds-group], topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1, routines=2, receivedBytes=2736, receivedKeys=9, partitionsLeft=0, partitionsTotal=12, startTime=1665583098669, endTime=1665583099026, lastCancelledTime=-1, result=true][15:58:19,026][INFO][rebalance-#86][GridDhtPartitionDemander] Prepared rebalancing [grp=CacheAs2ReceiptsCorrelation, mode=ASYNC, supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, partitionsCount=8, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1][15:58:19,027][INFO][rebalance-#86][GridDhtPartitionDemander] Prepared rebalancing [grp=CacheAs2ReceiptsCorrelation, mode=ASYNC, supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, partitionsCount=13, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1][15:58:19,143][INFO][main][IgniteKernal] Security status [authentication=on, sandbox=off, tls/ssl=on][15:58:19,143][INFO][main][IgniteKernal] Performance suggestions for grid (fix if possible)[15:58:19,143][INFO][main][IgniteKernal] To disable, set -DIGNITE_PERFORMANCE_SUGGESTIONS_DISABLED=true[15:58:19,144][INFO][main][IgniteKernal] ^-- Set max direct memory size if getting 'OOME: Direct buffer memory' (add '-XX:MaxDirectMemorySize=<size>[g|G|m|M|k|K]' to JVM options)[15:58:19,144][INFO][main][IgniteKernal] ^-- Speed up flushing of dirty pages by OS (alter vm.dirty_expire_centisecs parameter by setting to 500)[15:58:19,144][INFO][main][IgniteKernal] Refer to this page for more performance suggestions: https://ignite.apache.org/docs/latest/perf-and-troubleshooting/memory-tuning[15:58:19,144][INFO][main][IgniteKernal] [15:58:19,145][INFO][main][IgniteKernal] To start Console Management & Monitoring run ignitevisorcmd.{sh|bat}[15:58:19,146][INFO][main][IgniteKernal] >>> +-----------------------------------------------------------------------+>>> Ignite ver. 2.13.0#20220420-sha1:551f6ece4c308f4da5f9f3900aa4c7374adc36b4>>> +-----------------------------------------------------------------------+>>> OS name: Linux 4.18.0-372.26.1.el8_6.x86_64 amd64>>> CPU(s): 4>>> Heap: 6.0GB>>> VM name: [email protected]>>> Local node [ID=65622274-1387-415C-AED1-8A7EA2D0C09C, order=58, clientMode=false]>>> Local node addresses: [serverign3.domain.name.removed.net/10.x.x.x, /127.0.0.1]>>> Local ports: TCP:10800 TCP:11211 TCP:49100 TCP:49500 >>> +-----------------------------------------------------------------------+ [15:58:19,148][INFO][main][GridDiscoveryManager] Topology snapshot [ver=58, locNode=65622274, servers=3, clients=23, state=ACTIVE, CPUs=144, offheap=9.1GB, heap=420.0GB, aliveNodes=[TcpDiscoveryNode [id=cf53e0f7-2552-491f-ae6e-3195ac331525, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, isClient=false, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=291ffb11-da63-4ed7-80fd-0659e7f51dab, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, isClient=false, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=e128f204-dac2-4944-8d39-7ed1f4388b97, consistentId=e128f204-dac2-4944-8d39-7ed1f4388b97, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=f7c47309-2b66-44dc-b7bc-85c8ab1a7e7c, consistentId=f7c47309-2b66-44dc-b7bc-85c8ab1a7e7c, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=37e6c7ca-f952-405e-80e1-190c5e56dec3, consistentId=37e6c7ca-f952-405e-80e1-190c5e56dec3, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=9acb59e9-767a-4090-873f-d59b06e853a5, consistentId=9acb59e9-767a-4090-873f-d59b06e853a5, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=b26d62c3-74ce-4506-992a-f1058f9d0812, consistentId=b26d62c3-74ce-4506-992a-f1058f9d0812, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=2bd42e76-77cf-49ae-b158-a0f9ebaa0b86, consistentId=2bd42e76-77cf-49ae-b158-a0f9ebaa0b86, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=188d0a7f-aad4-49d6-970a-9482fee5729e, consistentId=188d0a7f-aad4-49d6-970a-9482fee5729e, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=57d59b10-e3b9-430f-88a8-3fd9e29d34b2, consistentId=57d59b10-e3b9-430f-88a8-3fd9e29d34b2, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=1f0120e9-ace7-43bf-ad09-a33f342783f6, consistentId=1f0120e9-ace7-43bf-ad09-a33f342783f6, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=0b916b5f-efba-48d8-9f3c-ffeadd6fbfa3, consistentId=0b916b5f-efba-48d8-9f3c-ffeadd6fbfa3, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=016fbaec-02c5-4c5c-88b9-f3ffc560266e, consistentId=016fbaec-02c5-4c5c-88b9-f3ffc560266e, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=5aa67ca8-d9b4-4476-90a3-cbb0dfb70ce9, consistentId=5aa67ca8-d9b4-4476-90a3-cbb0dfb70ce9, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=1555b296-b6b7-435b-aca0-802112ce9a31, consistentId=1555b296-b6b7-435b-aca0-802112ce9a31, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=0371ff67-3feb-4dae-8e47-786bb797e404, consistentId=0371ff67-3feb-4dae-8e47-786bb797e404, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=770bae5c-b8eb-44c1-b3da-31797ef0e5f2, consistentId=770bae5c-b8eb-44c1-b3da-31797ef0e5f2, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=5e325592-ff16-4485-8bc5-29cf280568d4, consistentId=5e325592-ff16-4485-8bc5-29cf280568d4, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=ce747e3a-cbae-417e-8b3b-079e099791a7, consistentId=ce747e3a-cbae-417e-8b3b-079e099791a7, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=48bcb95e-b229-436a-8cbe-236a83c5bd63, consistentId=48bcb95e-b229-436a-8cbe-236a83c5bd63, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=b95ba755-a3f3-4914-82b8-087442850aa3, consistentId=b95ba755-a3f3-4914-82b8-087442850aa3, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=0c1b9e3b-4ec1-4684-a5ca-5f3e84e76078, consistentId=0c1b9e3b-4ec1-4684-a5ca-5f3e84e76078, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=8b6b785d-9b47-4df4-b8c8-63aab02503a2, consistentId=8b6b785d-9b47-4df4-b8c8-63aab02503a2, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=127d727a-779a-47e1-8f9b-6a98d4e70629, consistentId=127d727a-779a-47e1-8f9b-6a98d4e70629, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=f0b0d5e3-4946-4819-b277-9ffd4b2d01df, consistentId=f0b0d5e3-4946-4819-b277-9ffd4b2d01df, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=65622274-1387-415c-aed1-8a7ea2d0c09c, consistentId=59d50ff1-b50d-4491-88da-e03b485598bf, isClient=false, ver=2.13.0#20220420-sha1:551f6ece]]][15:58:19,149][INFO][main][GridDiscoveryManager] ^-- Baseline [id=14, size=3, online=3, offline=0][15:58:19,149][INFO][main][G] Node started : [stage="Configure system pool" (40 ms),stage="Start managers" (650 ms),stage="Configure binary metadata" (57 ms),stage="Start processors" (604 ms),stage="Init metastore" (438 ms),stage="Init and start regions" (12 ms),stage="Restore binary memory" (2543 ms),stage="Restore logical state" (2888 ms),stage="Finish recovery" (0 ms),stage="Join topology" (675 ms),stage="Await transition" (28 ms),stage="Await exchange" (1700 ms),stage="Total time" (9635 ms)][15:58:19,266][INFO][db-checkpoint-thread-#70][Checkpointer] Checkpoint finished [cpId=45430ff8-d073-4c12-b303-c6686302a72e, pages=5914, markPos=WALPointer [idx=348, fileOff=31597576, len=209793], walSegmentsCovered=[], markDuration=136ms, pagesWrite=252ms, fsync=911ms, total=1494ms][15:58:19,307][INFO][sys-#52][GridDhtPartitionDemander] Starting rebalance routine [CacheAs2ReceiptsCorrelation, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, fullPartitions=[111, 337, 437, 469, 645, 759, 761, 807], histPartitions=[], rebalanceId=1][15:58:19,429][INFO][sys-#49][GridDhtPartitionDemander] Starting rebalance routine [CacheAs2ReceiptsCorrelation, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, fullPartitions=[62, 102, 144, 384, 442, 552, 558, 738, 892, 898, 950, 974, 976], histPartitions=[], rebalanceId=1][15:58:19,572][INFO][rebalance-#86][GridDhtPartitionDemander] Completed rebalancing [rebalanceId=1, grp=CacheAs2ReceiptsCorrelation, supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, partitions=8, entries=1476, duration=546ms, bytesRcvd=551.9 KB, bandwidth=551.9 KB/sec, histPartitions=0, histEntries=0, histBytesRcvd=0.0 B, fullPartitions=8, fullEntries=1476, fullBytesRcvd=551.9 KB, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], progress=1/2][15:58:19,652][INFO][rebalance-#86][GridDhtPartitionDemander] Completed (final) rebalancing [rebalanceId=1, grp=CacheAs2ReceiptsCorrelation, supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, partitions=13, entries=2534, duration=625ms, bytesRcvd=947.5 KB, bandwidth=947.5 KB/sec, histPartitions=0, histEntries=0, histBytesRcvd=0.0 B, fullPartitions=13, fullEntries=2534, fullBytesRcvd=947.5 KB, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], progress=2/2][15:58:19,652][INFO][rebalance-#86][GridDhtPartitionDemander] Completed rebalance future: RebalanceFuture [state=STARTED, grp=CacheGroupContext [grp=CacheAs2ReceiptsCorrelation], topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1, routines=2, receivedBytes=1535826, receivedKeys=4010, partitionsLeft=0, partitionsTotal=21, startTime=1665583099026, endTime=1665583099652, lastCancelledTime=-1, result=true][15:58:19,652][INFO][rebalance-#86][GridDhtPartitionDemander] Prepared rebalancing [grp=SQL_PUBLIC_B2BICLUSTERSTATUS, mode=ASYNC, supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, partitionsCount=1, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1][15:58:19,666][INFO][sys-#48][GridDhtPartitionDemander] Starting rebalance routine [SQL_PUBLIC_B2BICLUSTERSTATUS, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, fullPartitions=[17], histPartitions=[], rebalanceId=1][15:58:19,670][INFO][rebalance-#86][GridDhtPartitionDemander] Completed (final) rebalancing [rebalanceId=1, grp=SQL_PUBLIC_B2BICLUSTERSTATUS, supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, partitions=1, entries=1, duration=18ms, bytesRcvd=242.0 B, bandwidth=242.0 B/sec, histPartitions=0, histEntries=0, histBytesRcvd=0.0 B, fullPartitions=1, fullEntries=1, fullBytesRcvd=242.0 B, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], progress=1/1][15:58:19,670][INFO][rebalance-#86][GridDhtPartitionDemander] Completed rebalance future: RebalanceFuture [state=STARTED, grp=CacheGroupContext [grp=SQL_PUBLIC_B2BICLUSTERSTATUS], topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1, routines=1, receivedBytes=258, receivedKeys=1, partitionsLeft=0, partitionsTotal=1, startTime=1665583099652, endTime=1665583099670, lastCancelledTime=-1, result=true][15:58:19,670][INFO][rebalance-#86][GridDhtPartitionDemander] Prepared rebalancing [grp=SQL_PUBLIC_RELATIONAL_META, mode=ASYNC, supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, partitionsCount=1, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1][15:58:19,673][INFO][sys-#52][GridDhtPartitionDemander] Starting rebalance routine [SQL_PUBLIC_RELATIONAL_META, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, fullPartitions=[180], histPartitions=[], rebalanceId=1][15:58:19,676][INFO][rebalance-#86][GridDhtPartitionDemander] Completed (final) rebalancing [rebalanceId=1, grp=SQL_PUBLIC_RELATIONAL_META, supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, partitions=1, entries=1, duration=5ms, bytesRcvd=231.0 B, bandwidth=231.0 B/sec, histPartitions=0, histEntries=0, histBytesRcvd=0.0 B, fullPartitions=1, fullEntries=1, fullBytesRcvd=231.0 B, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], progress=1/1][15:58:19,676][INFO][rebalance-#86][GridDhtPartitionDemander] Completed rebalance future: RebalanceFuture [state=STARTED, grp=CacheGroupContext [grp=SQL_PUBLIC_RELATIONAL_META], topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1, routines=1, receivedBytes=247, receivedKeys=1, partitionsLeft=0, partitionsTotal=1, startTime=1665583099670, endTime=1665583099676, lastCancelledTime=-1, result=true][15:58:19,676][INFO][rebalance-#86][GridDhtPartitionDemander] Prepared rebalancing [grp=SQL_PUBLIC_TIMERS, mode=ASYNC, supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, partitionsCount=4, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1][15:58:19,676][INFO][rebalance-#86][GridDhtPartitionDemander] Prepared rebalancing [grp=SQL_PUBLIC_TIMERS, mode=ASYNC, supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, partitionsCount=3, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1][15:58:19,738][INFO][sys-#53][GridDhtPartitionDemander] Starting rebalance routine [SQL_PUBLIC_TIMERS, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, fullPartitions=[45, 89, 99, 229], histPartitions=[], rebalanceId=1][15:58:19,774][INFO][sys-#54][GridDhtPartitionDemander] Starting rebalance routine [SQL_PUBLIC_TIMERS, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, fullPartitions=[44, 114, 278], histPartitions=[], rebalanceId=1][15:58:19,801][INFO][rebalance-#86][GridDhtPartitionDemander] Completed rebalancing [rebalanceId=1, grp=SQL_PUBLIC_TIMERS, supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, partitions=4, entries=56, duration=124ms, bytesRcvd=76.8 KB, bandwidth=76.8 KB/sec, histPartitions=0, histEntries=0, histBytesRcvd=0.0 B, fullPartitions=4, fullEntries=56, fullBytesRcvd=76.8 KB, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], progress=1/2][15:58:19,813][INFO][rebalance-#86][GridDhtPartitionDemander] Completed (final) rebalancing [rebalanceId=1, grp=SQL_PUBLIC_TIMERS, supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, partitions=3, entries=48, duration=137ms, bytesRcvd=81.5 KB, bandwidth=81.5 KB/sec, histPartitions=0, histEntries=0, histBytesRcvd=0.0 B, fullPartitions=3, fullEntries=48, fullBytesRcvd=81.5 KB, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], progress=2/2][15:58:19,814][INFO][rebalance-#86][GridDhtPartitionDemander] Completed rebalance future: RebalanceFuture [state=STARTED, grp=CacheGroupContext [grp=SQL_PUBLIC_TIMERS], topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1, routines=2, receivedBytes=162225, receivedKeys=104, partitionsLeft=0, partitionsTotal=7, startTime=1665583099676, endTime=1665583099814, lastCancelledTime=-1, result=true][15:58:19,814][INFO][rebalance-#86][GridDhtPartitionDemander] Prepared rebalancing [grp=table, mode=ASYNC, supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, partitionsCount=4, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1][15:58:19,814][INFO][rebalance-#86][GridDhtPartitionDemander] Prepared rebalancing [grp=table, mode=ASYNC, supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, partitionsCount=3, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1][15:58:19,835][INFO][sys-#48][GridDhtPartitionDemander] Starting rebalance routine [table, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, fullPartitions=[51, 127, 235, 313], histPartitions=[], rebalanceId=1][15:58:19,843][INFO][sys-#51][GridDhtPartitionDemander] Starting rebalance routine [table, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, fullPartitions=[142, 382, 1002], histPartitions=[], rebalanceId=1][15:58:19,865][INFO][rebalance-#86][GridDhtPartitionDemander] Completed rebalancing [rebalanceId=1, grp=table, supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, partitions=3, entries=16, duration=51ms, bytesRcvd=263.0 KB, bandwidth=263.0 KB/sec, histPartitions=0, histEntries=0, histBytesRcvd=0.0 B, fullPartitions=3, fullEntries=16, fullBytesRcvd=263.0 KB, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], progress=1/2][15:58:19,878][INFO][rebalance-#86][GridDhtPartitionDemander] Completed (final) rebalancing [rebalanceId=1, grp=table, supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, partitions=4, entries=27, duration=63ms, bytesRcvd=392.9 KB, bandwidth=392.9 KB/sec, histPartitions=0, histEntries=0, histBytesRcvd=0.0 B, fullPartitions=4, fullEntries=27, fullBytesRcvd=392.9 KB, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], progress=2/2][15:58:19,878][INFO][rebalance-#86][GridDhtPartitionDemander] Completed rebalance future: RebalanceFuture [state=STARTED, grp=CacheGroupContext [grp=table], topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1, routines=2, receivedBytes=671774, receivedKeys=43, partitionsLeft=0, partitionsTotal=7, startTime=1665583099814, endTime=1665583099878, lastCancelledTime=-1, result=true][15:58:19,878][INFO][rebalance-#86][GridDhtPartitionDemander] Prepared rebalancing [grp=uniqueid, mode=ASYNC, supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, partitionsCount=2, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1][15:58:19,878][INFO][rebalance-#86][GridDhtPartitionDemander] Prepared rebalancing [grp=uniqueid, mode=ASYNC, supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, partitionsCount=2, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1][15:58:19,884][INFO][sys-#53][GridDhtPartitionDemander] Starting rebalance routine [uniqueid, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, fullPartitions=[795, 867], histPartitions=[], rebalanceId=1][15:58:19,885][INFO][sys-#53][GridDhtPartitionDemander] Starting rebalance routine [uniqueid, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, fullPartitions=[102, 398], histPartitions=[], rebalanceId=1][15:58:19,888][INFO][rebalance-#86][GridDhtPartitionDemander] Completed rebalancing [rebalanceId=1, grp=uniqueid, supplier=291ffb11-da63-4ed7-80fd-0659e7f51dab, partitions=2, entries=2, duration=10ms, bytesRcvd=379.0 B, bandwidth=379.0 B/sec, histPartitions=0, histEntries=0, histBytesRcvd=0.0 B, fullPartitions=2, fullEntries=2, fullBytesRcvd=379.0 B, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], progress=1/2][15:58:19,889][INFO][rebalance-#86][GridDhtPartitionDemander] Completed (final) rebalancing [rebalanceId=1, grp=uniqueid, supplier=cf53e0f7-2552-491f-ae6e-3195ac331525, partitions=2, entries=2, duration=11ms, bytesRcvd=373.0 B, bandwidth=373.0 B/sec, histPartitions=0, histEntries=0, histBytesRcvd=0.0 B, fullPartitions=2, fullEntries=2, fullBytesRcvd=373.0 B, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], progress=2/2][15:58:19,892][INFO][rebalance-#86][GridDhtPartitionDemander] Completed rebalance future: RebalanceFuture [state=STARTED, grp=CacheGroupContext [grp=uniqueid], topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], rebalanceId=1, routines=2, receivedBytes=816, receivedKeys=4, partitionsLeft=0, partitionsTotal=4, startTime=1665583099878, endTime=1665583099889, lastCancelledTime=-1, result=true][15:58:19,895][INFO][rebalance-#86][GridDhtPartitionDemander] Completed rebalance chain: [rebalanceId=1, partitions=53, entries=4172, duration=1s, bytesRcvd=2.3 MB][15:58:19,905][INFO][exchange-worker-#65][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=58, minorTopVer=1], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=cf53e0f7-2552-491f-ae6e-3195ac331525, customEvt=CacheAffinityChangeMessage [id=8426fb7c381-22e42b79-79fa-4d8b-a11a-efa1d1acfd55, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], allowMerge=false, exchangeFreeSwitch=false][15:58:19,929][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=58, minorTopVer=1], waitTime=0ms, futInfo=NA, mode=DISTRIBUTED][15:58:19,933][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ClientLatch [coordinator=TcpDiscoveryNode [id=cf53e0f7-2552-491f-ae6e-3195ac331525, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, serverign1.domain.name.removed.net/10.x.x.x:49500], discPort=49500, order=1, intOrder=1, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], ackSent=true, super=CompletableLatch [id=CompletableLatchUid [id=exchange, topVer=AffinityTopologyVersion [topVer=58, minorTopVer=1]]]][15:58:19,933][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=58, minorTopVer=1], waitTime=0ms, futInfo=NA, mode=LOCAL][15:58:19,982][INFO][grid-nio-worker-tcp-comm-1-#24%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:39345][15:58:20,012][INFO][exchange-worker-#65][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=58, minorTopVer=1], crd=false][15:58:20,050][INFO][sys-#53][GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=cf53e0f7-2552-491f-ae6e-3195ac331525, resVer=AffinityTopologyVersion [topVer=58, minorTopVer=1]][15:58:20,067][INFO][sys-#53][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=58, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=58, minorTopVer=1], err=null, rebalanced=true, wasRebalanced=false][15:58:20,104][INFO][sys-#53][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=65622274-1387-415c-aed1-8a7ea2d0c09c, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=58, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=cf53e0f7-2552-491f-ae6e-3195ac331525, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, serverign1.domain.name.removed.net/10.x.x.x:49500], discPort=49500, order=1, intOrder=1, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], rebalanced=true, done=true, newCrdFut=null], topVer=AffinityTopologyVersion [topVer=58, minorTopVer=1]][15:58:20,104][INFO][sys-#53][GridDhtPartitionsExchangeFuture] Exchange timings [startVer=AffinityTopologyVersion [topVer=58, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=58, minorTopVer=1], stage="Waiting in exchange queue" (0 ms), stage="Exchange parameters initialization" (0 ms), stage="Determine exchange type" (20 ms), stage="Preloading notification" (0 ms), stage="Wait partitions release [latch=exchange]" (4 ms), stage="Wait partitions release latch [latch=exchange]" (3 ms), stage="Wait partitions release [latch=exchange]" (0 ms), stage="After states restored callback" (36 ms), stage="WAL history reservation" (7 ms), stage="Waiting for Full message" (73 ms), stage="Affinity recalculation" (0 ms), stage="Full map updating" (16 ms), stage="Exchange done" (36 ms), stage="Total time" (195 ms)][15:58:20,104][INFO][sys-#53][GridDhtPartitionsExchangeFuture] Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=58, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=58, minorTopVer=1], stage="Affinity change by custom message [grp=CacheAs2ReceiptsCorrelation]" (11 ms) (parent=Determine exchange type), stage="Affinity change by custom message [grp=SQL_PUBLIC_RELATIONAL_META]" (10 ms) (parent=Determine exchange type), stage="Affinity change by custom message [grp=table]" (6 ms) (parent=Determine exchange type)][15:58:20,117][INFO][exchange-worker-#65][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=58, minorTopVer=1], force=false, evt=DISCOVERY_CUSTOM_EVT, node=cf53e0f7-2552-491f-ae6e-3195ac331525][15:58:20,123][INFO][grid-nio-worker-tcp-comm-2-#25%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:39351][15:58:21,107][INFO][grid-nio-worker-tcp-comm-3-#26%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:31259][15:58:21,257][INFO][grid-nio-worker-tcp-comm-0-#23%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:31263][15:58:21,300][INFO][grid-nio-worker-tcp-comm-1-#24%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:39072][15:58:22,146][INFO][grid-nio-worker-tcp-comm-2-#25%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:42055][15:58:22,179][INFO][grid-nio-worker-tcp-comm-3-#26%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:39084][15:58:22,344][INFO][grid-nio-worker-tcp-comm-0-#23%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:42065][15:58:23,176][INFO][grid-nio-worker-tcp-comm-1-#24%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:39096][15:58:24,757][INFO][grid-nio-worker-tcp-comm-2-#25%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:49371][15:58:26,295][INFO][grid-nio-worker-tcp-comm-3-#26%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:31271][15:58:26,469][INFO][grid-nio-worker-tcp-comm-0-#23%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:33499][15:58:28,302][INFO][wal-file-archiver%null-#66][FileWriteAheadLogManager] Starting to copy WAL segment [absIdx=348, segIdx=8, origFile=/usr/share/apache-ignite/work/db/wal/node00-59d50ff1-b50d-4491-88da-e03b485598bf/0000000000000008.wal, dstFile=/usr/share/apache-ignite/work/db/wal/archive/node00-59d50ff1-b50d-4491-88da-e03b485598bf/0000000000000348.wal][15:58:28,303][INFO][wal-file-cleaner%null-#67][FileWriteAheadLogManager] Starting to clean WAL archive [highIdx=341, currSize=512.0 MB, maxSize=1.0 GB][15:58:28,318][INFO][wal-file-cleaner%null-#67][FileWriteAheadLogManager] Finish clean WAL archive [cleanCnt=1, currSize=448.0 MB, maxSize=1.0 GB][15:58:28,411][INFO][wal-file-archiver%null-#66][FileWriteAheadLogManager] Copied file [src=/usr/share/apache-ignite/work/db/wal/node00-59d50ff1-b50d-4491-88da-e03b485598bf/0000000000000008.wal, dst=/usr/share/apache-ignite/work/db/wal/archive/node00-59d50ff1-b50d-4491-88da-e03b485598bf/0000000000000348.wal][15:59:19,141][INFO][grid-timeout-worker-#22][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=65622274, uptime=00:01:00.001] ^-- Cluster [hosts=8, CPUs=144, servers=3, clients=23, topVer=58, minorTopVer=1] ^-- Network [addrs=[10.x.x.x, 127.0.0.1], discoPort=49500, commPort=49100] ^-- CPU [CPUs=4, curLoad=1.9%, avgLoad=5.82%, GC=0%] ^-- Heap [used=505MB, free=91.78%, comm=6144MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=1, qSize=0] ^-- System thread pool [active=0, idle=8, qSize=0] ^-- Striped thread pool [active=0, idle=8, qSize=0][15:59:27,632][INFO][ignite-update-notifier-timer][GridUpdateNotifier] Update status is not available.[16:00:19,143][INFO][grid-timeout-worker-#22][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=65622274, uptime=00:02:00.009] ^-- Cluster [hosts=8, CPUs=144, servers=3, clients=23, topVer=58, minorTopVer=1] ^-- Network [addrs=[10.x.x.x, 127.0.0.1], discoPort=49500, commPort=49100] ^-- CPU [CPUs=4, curLoad=3.07%, avgLoad=5.13%, GC=0%] ^-- Heap [used=478MB, free=92.21%, comm=6144MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=8, qSize=0] ^-- Striped thread pool [active=0, idle=8, qSize=0][16:00:41,223][INFO][grid-nio-worker-tcp-comm-1-#24%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:41164][16:01:12,450][INFO][grid-nio-worker-tcp-comm-2-#25%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:53218][16:01:12,720][INFO][tcp-comm-worker-#1-#28][TcpCommunicationSpi] TCP client created [client=null, node addrs=[servercfg1.domain.name.removed.net/10.x.x.x:49100, /127.0.0.1:49100, 0:0:0:0:0:0:0:1%lo:49100], duration=509ms][16:01:19,152][INFO][grid-timeout-worker-#22][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=65622274, uptime=00:03:00.017] ^-- Cluster [hosts=8, CPUs=144, servers=3, clients=23, topVer=58, minorTopVer=1] ^-- Network [addrs=[10.x.x.x, 127.0.0.1], discoPort=49500, commPort=49100] ^-- CPU [CPUs=4, curLoad=1.83%, avgLoad=4.47%, GC=0%] ^-- Heap [used=417MB, free=93.2%, comm=6144MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=8, qSize=0] ^-- Striped thread pool [active=0, idle=8, qSize=0][16:01:20,085][INFO][db-checkpoint-thread-#70][Checkpointer] Checkpoint started [checkpointId=83c1a5cd-cc71-48cc-9deb-d8cff052d4d4, startPtr=WALPointer [idx=349, fileOff=31414056, len=209777], checkpointBeforeLockTime=60ms, checkpointLockWait=0ms, checkpointListenersExecuteTime=21ms, checkpointLockHoldTime=29ms, walCpRecordFsyncDuration=16ms, writeCheckpointEntryDuration=4ms, splitAndSortCpPagesDuration=11ms, pages=10646, reason='timeout'][16:01:20,415][INFO][db-checkpoint-thread-#70][Checkpointer] Checkpoint finished [cpId=83c1a5cd-cc71-48cc-9deb-d8cff052d4d4, pages=10646, markPos=WALPointer [idx=349, fileOff=31414056, len=209777], walSegmentsCovered=[348], markDuration=60ms, pagesWrite=224ms, fsync=106ms, total=450ms][16:01:55,567][INFO][grid-nio-worker-tcp-comm-1-#24%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:47949][16:02:00,476][INFO][grid-nio-worker-tcp-comm-2-#25%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:44606][16:02:19,157][INFO][grid-timeout-worker-#22][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=65622274, uptime=00:04:00.021] ^-- Cluster [hosts=8, CPUs=144, servers=3, clients=23, topVer=58, minorTopVer=1] ^-- Network [addrs=[10.x.x.x, 127.0.0.1], discoPort=49500, commPort=49100] ^-- CPU [CPUs=4, curLoad=1.83%, avgLoad=4.68%, GC=0%] ^-- Heap [used=848MB, free=86.2%, comm=6144MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=8, qSize=0] ^-- Striped thread pool [active=0, idle=8, qSize=0][16:02:25,003][INFO][grid-nio-worker-tcp-comm-3-#26%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:33084][16:02:25,486][INFO][tcp-comm-worker-#1-#28][TcpCommunicationSpi] TCP client created [client=null, node addrs=[servercfg1.domain.name.removed.net/10.x.x.x:49100, /127.0.0.1:49100, 0:0:0:0:0:0:0:1%lo:49100], duration=503ms][16:02:26,734][INFO][grid-nio-worker-tcp-comm-1-#24%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:33107][16:02:49,056][INFO][grid-nio-worker-tcp-comm-2-#25%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:58310][16:03:01,077][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=33928][16:03:01,077][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=33928][16:03:01,078][INFO][tcp-disco-sock-reader-[]-#7-#134][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:33928, rmtPort=33928][16:03:01,091][INFO][tcp-disco-sock-reader-[cf53e0f7 10.x.x.x:33928]-#7-#134][TcpDiscoverySpi] Initialized connection with remote server node [nodeId=cf53e0f7-2552-491f-ae6e-3195ac331525, rmtAddr=/10.x.x.x:33928][16:03:01,095][INFO][disco-event-worker-#62][GridDiscoveryManager] Node left topology: TcpDiscoveryNode [id=291ffb11-da63-4ed7-80fd-0659e7f51dab, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign2.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=2, intOrder=2, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false][16:03:01,096][INFO][disco-event-worker-#62][GridDiscoveryManager] Topology snapshot [ver=59, locNode=65622274, servers=2, clients=23, state=ACTIVE, CPUs=140, offheap=6.0GB, heap=420.0GB, aliveNodes=[TcpDiscoveryNode [id=cf53e0f7-2552-491f-ae6e-3195ac331525, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, isClient=false, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=e128f204-dac2-4944-8d39-7ed1f4388b97, consistentId=e128f204-dac2-4944-8d39-7ed1f4388b97, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=f7c47309-2b66-44dc-b7bc-85c8ab1a7e7c, consistentId=f7c47309-2b66-44dc-b7bc-85c8ab1a7e7c, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=37e6c7ca-f952-405e-80e1-190c5e56dec3, consistentId=37e6c7ca-f952-405e-80e1-190c5e56dec3, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=9acb59e9-767a-4090-873f-d59b06e853a5, consistentId=9acb59e9-767a-4090-873f-d59b06e853a5, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=b26d62c3-74ce-4506-992a-f1058f9d0812, consistentId=b26d62c3-74ce-4506-992a-f1058f9d0812, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=2bd42e76-77cf-49ae-b158-a0f9ebaa0b86, consistentId=2bd42e76-77cf-49ae-b158-a0f9ebaa0b86, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=188d0a7f-aad4-49d6-970a-9482fee5729e, consistentId=188d0a7f-aad4-49d6-970a-9482fee5729e, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=57d59b10-e3b9-430f-88a8-3fd9e29d34b2, consistentId=57d59b10-e3b9-430f-88a8-3fd9e29d34b2, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=1f0120e9-ace7-43bf-ad09-a33f342783f6, consistentId=1f0120e9-ace7-43bf-ad09-a33f342783f6, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=0b916b5f-efba-48d8-9f3c-ffeadd6fbfa3, consistentId=0b916b5f-efba-48d8-9f3c-ffeadd6fbfa3, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=016fbaec-02c5-4c5c-88b9-f3ffc560266e, consistentId=016fbaec-02c5-4c5c-88b9-f3ffc560266e, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=5aa67ca8-d9b4-4476-90a3-cbb0dfb70ce9, consistentId=5aa67ca8-d9b4-4476-90a3-cbb0dfb70ce9, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=1555b296-b6b7-435b-aca0-802112ce9a31, consistentId=1555b296-b6b7-435b-aca0-802112ce9a31, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=0371ff67-3feb-4dae-8e47-786bb797e404, consistentId=0371ff67-3feb-4dae-8e47-786bb797e404, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=770bae5c-b8eb-44c1-b3da-31797ef0e5f2, consistentId=770bae5c-b8eb-44c1-b3da-31797ef0e5f2, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=5e325592-ff16-4485-8bc5-29cf280568d4, consistentId=5e325592-ff16-4485-8bc5-29cf280568d4, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=ce747e3a-cbae-417e-8b3b-079e099791a7, consistentId=ce747e3a-cbae-417e-8b3b-079e099791a7, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=48bcb95e-b229-436a-8cbe-236a83c5bd63, consistentId=48bcb95e-b229-436a-8cbe-236a83c5bd63, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=b95ba755-a3f3-4914-82b8-087442850aa3, consistentId=b95ba755-a3f3-4914-82b8-087442850aa3, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=0c1b9e3b-4ec1-4684-a5ca-5f3e84e76078, consistentId=0c1b9e3b-4ec1-4684-a5ca-5f3e84e76078, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=8b6b785d-9b47-4df4-b8c8-63aab02503a2, consistentId=8b6b785d-9b47-4df4-b8c8-63aab02503a2, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=127d727a-779a-47e1-8f9b-6a98d4e70629, consistentId=127d727a-779a-47e1-8f9b-6a98d4e70629, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=f0b0d5e3-4946-4819-b277-9ffd4b2d01df, consistentId=f0b0d5e3-4946-4819-b277-9ffd4b2d01df, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=65622274-1387-415c-aed1-8a7ea2d0c09c, consistentId=59d50ff1-b50d-4491-88da-e03b485598bf, isClient=false, ver=2.13.0#20220420-sha1:551f6ece]]][16:03:01,096][INFO][disco-event-worker-#62][GridDiscoveryManager] ^-- Baseline [id=14, size=3, online=2, offline=1][16:03:01,105][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=47618][16:03:01,106][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=47618][16:03:01,106][INFO][tcp-disco-sock-reader-[]-#8-#136][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:47618, rmtPort=47618][16:03:01,107][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=49326][16:03:01,108][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=49326][16:03:01,108][INFO][exchange-worker-#65][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=59, minorTopVer=0], crd=false, evt=NODE_LEFT, evtNode=291ffb11-da63-4ed7-80fd-0659e7f51dab, customEvt=null, allowMerge=false, exchangeFreeSwitch=true][16:03:01,119][INFO][tcp-disco-sock-reader-[]-#9-#137][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:49326, rmtPort=49326][16:03:01,119][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=50592][16:03:01,119][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=50592][16:03:01,120][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=56596][16:03:01,120][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=56596][16:03:01,120][INFO][tcp-disco-sock-reader-[]-#10-#139][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:50592, rmtPort=50592][16:03:01,121][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=60692][16:03:01,121][INFO][tcp-disco-sock-reader-[]-#11-#140][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:56596, rmtPort=56596][16:03:01,121][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=60692][16:03:01,124][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=34503][16:03:01,124][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=34503][16:03:01,110][INFO][exchange-worker-#65][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=timers, expectedPrimary=512.00, actualPrimary=538, expectedBackups=1024.00, actualBackups=486, warningThreshold=50.00%][16:03:01,125][INFO][tcp-disco-sock-reader-[]-#13-#143][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:34503, rmtPort=34503][16:03:01,124][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=52852][16:03:01,125][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=52852][16:03:01,124][INFO][tcp-disco-sock-reader-[]-#12-#141][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:60692, rmtPort=60692][16:03:01,111][INFO][sys-#129][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=CacheAs2ReceiptsCorrelation, expectedPrimary=512.00, actualPrimary=538, expectedBackups=1024.00, actualBackups=486, warningThreshold=50.00%][16:03:01,115][INFO][sys-#135][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=CacheOftpReceiptsCorrelation, expectedPrimary=512.00, actualPrimary=538, expectedBackups=1024.00, actualBackups=486, warningThreshold=50.00%][16:03:01,113][INFO][sys-#131][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=B2BiClusterStatusCache, expectedPrimary=512.00, actualPrimary=538, expectedBackups=1024.00, actualBackups=486, warningThreshold=50.00%][16:03:01,117][INFO][sys-#126][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=CacheRosettaNet2MessageCorrelation, expectedPrimary=512.00, actualPrimary=538, expectedBackups=1024.00, actualBackups=486, warningThreshold=50.00%][16:03:01,118][INFO][sys-#133][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=table, expectedPrimary=512.00, actualPrimary=538, expectedBackups=1024.00, actualBackups=486, warningThreshold=50.00%][16:03:01,119][INFO][sys-#132][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=uniqueid, expectedPrimary=512.00, actualPrimary=538, expectedBackups=1024.00, actualBackups=486, warningThreshold=50.00%][16:03:01,135][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=59, minorTopVer=0], waitTime=0ms, futInfo=NA, mode=LOCAL][16:03:01,136][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=52454][16:03:01,137][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=52454][16:03:01,137][INFO][tcp-disco-sock-reader-[]-#14-#144][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:52852, rmtPort=52852][16:03:01,137][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=43676][16:03:01,137][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=43676][16:03:01,137][INFO][tcp-disco-sock-reader-[]-#15-#145][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:52454, rmtPort=52454][16:03:01,138][INFO][tcp-disco-sock-reader-[]-#16-#146][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:43676, rmtPort=43676][16:03:01,138][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=52092][16:03:01,138][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=52092][16:03:01,141][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=58448][16:03:01,141][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=58448][16:03:01,141][INFO][tcp-disco-sock-reader-[]-#17-#147][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:52092, rmtPort=52092][16:03:01,142][INFO][tcp-disco-sock-reader-[]-#18-#148][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:58448, rmtPort=58448][16:03:01,193][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=59, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=59, minorTopVer=0], err=null, rebalanced=true, wasRebalanced=true][16:03:01,233][INFO][tcp-disco-sock-reader-[016fbaec 10.x.x.x:47618 client]-#8-#136][TcpDiscoverySpi] Initialized connection with remote client node [nodeId=016fbaec-02c5-4c5c-88b9-f3ffc560266e, rmtAddr=/10.x.x.x:47618][16:03:01,238][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=65622274-1387-415c-aed1-8a7ea2d0c09c, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=59, minorTopVer=0], evt=NODE_LEFT, evtNode=TcpDiscoveryNode [id=291ffb11-da63-4ed7-80fd-0659e7f51dab, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign2.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=2, intOrder=2, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], rebalanced=true, done=true, newCrdFut=null], topVer=AffinityTopologyVersion [topVer=59, minorTopVer=0]][16:03:01,239][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Exchange timings [startVer=AffinityTopologyVersion [topVer=59, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=59, minorTopVer=0], stage="Waiting in exchange queue" (1 ms), stage="Exchange parameters initialization" (0 ms), stage="Determine exchange type" (26 ms), stage="Preloading notification" (0 ms), stage="After states restored callback" (0 ms), stage="WAL history reservation" (10 ms), stage="Finalize update counters" (15 ms), stage="Detect lost partitions" (42 ms), stage="Exchange done" (34 ms), stage="Total time" (128 ms)][16:03:01,239][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=59, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=59, minorTopVer=0], stage="Affinity initialization (exchange-free switch on fully-rebalanced topology) [grp=CacheOftpReceiptsCorrelation]" (26 ms) (parent=Determine exchange type), stage="Affinity initialization (exchange-free switch on fully-rebalanced topology) [grp=B2BiClusterStatusCache]" (21 ms) (parent=Determine exchange type), stage="Affinity initialization (exchange-free switch on fully-rebalanced topology) [grp=CacheAs2ReceiptsCorrelation]" (19 ms) (parent=Determine exchange type)][16:03:01,239][INFO][exchange-worker-#65][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=59, minorTopVer=0], crd=false][16:03:01,260][INFO][tcp-disco-sock-reader-[e128f204 10.x.x.x:50592 client]-#10-#139][TcpDiscoverySpi] Initialized connection with remote client node [nodeId=e128f204-dac2-4944-8d39-7ed1f4388b97, rmtAddr=/10.x.x.x:50592][16:03:01,260][INFO][tcp-disco-sock-reader-[48bcb95e 10.x.x.x:60692 client]-#12-#141][TcpDiscoverySpi] Initialized connection with remote client node [nodeId=48bcb95e-b229-436a-8cbe-236a83c5bd63, rmtAddr=/10.x.x.x:60692][16:03:01,261][INFO][tcp-disco-sock-reader-[f0b0d5e3 10.x.x.x:34503 client]-#13-#143][TcpDiscoverySpi] Initialized connection with remote client node [nodeId=f0b0d5e3-4946-4819-b277-9ffd4b2d01df, rmtAddr=/10.x.x.x:34503][16:03:01,260][INFO][tcp-disco-sock-reader-[5aa67ca8 10.x.x.x:56596 client]-#11-#140][TcpDiscoverySpi] Initialized connection with remote client node [nodeId=5aa67ca8-d9b4-4476-90a3-cbb0dfb70ce9, rmtAddr=/10.x.x.x:56596][16:03:01,261][INFO][tcp-disco-sock-reader-[ce747e3a 10.x.x.x:58448 client]-#18-#148][TcpDiscoverySpi] Initialized connection with remote client node [nodeId=ce747e3a-cbae-417e-8b3b-079e099791a7, rmtAddr=/10.x.x.x:58448][16:03:01,263][INFO][exchange-worker-#65][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=59, minorTopVer=0], force=false, evt=NODE_LEFT, node=291ffb11-da63-4ed7-80fd-0659e7f51dab][16:03:01,264][INFO][tcp-disco-sock-reader-[37e6c7ca 10.x.x.x:52852 client]-#14-#144][TcpDiscoverySpi] Initialized connection with remote client node [nodeId=37e6c7ca-f952-405e-80e1-190c5e56dec3, rmtAddr=/10.x.x.x:52852][16:03:01,267][INFO][tcp-disco-sock-reader-[770bae5c 10.x.x.x:43676 client]-#16-#146][TcpDiscoverySpi] Initialized connection with remote client node [nodeId=770bae5c-b8eb-44c1-b3da-31797ef0e5f2, rmtAddr=/10.x.x.x:43676][16:03:01,271][INFO][tcp-disco-sock-reader-[9acb59e9 10.x.x.x:49326 client]-#9-#137][TcpDiscoverySpi] Initialized connection with remote client node [nodeId=9acb59e9-767a-4090-873f-d59b06e853a5, rmtAddr=/10.x.x.x:49326][16:03:01,271][INFO][tcp-disco-sock-reader-[f7c47309 10.x.x.x:52092 client]-#17-#147][TcpDiscoverySpi] Initialized connection with remote client node [nodeId=f7c47309-2b66-44dc-b7bc-85c8ab1a7e7c, rmtAddr=/10.x.x.x:52092][16:03:01,271][INFO][tcp-disco-sock-reader-[0b916b5f 10.x.x.x:52454 client]-#15-#145][TcpDiscoverySpi] Initialized connection with remote client node [nodeId=0b916b5f-efba-48d8-9f3c-ffeadd6fbfa3, rmtAddr=/10.x.x.x:52454][16:03:01,514][WARNING][tcp-disco-sock-reader-[291ffb11 10.x.x.x:41080]-#5-#60][TcpDiscoverySpi] Failed to shutdown socketjava.net.SocketException: Socket is closed at java.base/java.net.Socket.shutdownOutput(Socket.java:1569) at java.base/sun.security.ssl.BaseSSLSocketImpl.shutdownOutput(BaseSSLSocketImpl.java:232) at java.base/sun.security.ssl.SSLSocketImpl.shutdownOutput(SSLSocketImpl.java:794) at org.apache.ignite.internal.util.IgniteUtils.close(IgniteUtils.java:4283) at org.apache.ignite.spi.discovery.tcp.ServerImpl$SocketReader.body(ServerImpl.java:7321) at org.apache.ignite.spi.IgniteSpiThread.run(IgniteSpiThread.java:58)[16:03:01,514][INFO][tcp-disco-sock-reader-[291ffb11 10.x.x.x:41080]-#5-#60][TcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/10.x.x.x:41080, rmtPort=41080, rmtNodeId=291ffb11-da63-4ed7-80fd-0659e7f51dab][16:03:11,745][INFO][tcp-disco-msg-worker-[cf53e0f7 10.x.x.x:49500]-#2-#57][TcpDiscoverySpi] New next node [newNext=TcpDiscoveryNode [id=afa9f790-0fcd-4c1d-86bd-7e4c99731e44, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign2.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=0, intOrder=43, lastExchangeTime=1665583391733, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false]][16:03:11,977][INFO][disco-event-worker-#62][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=afa9f790-0fcd-4c1d-86bd-7e4c99731e44, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign2.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=60, intOrder=43, lastExchangeTime=1665583391733, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false][16:03:11,979][INFO][disco-event-worker-#62][GridDiscoveryManager] Topology snapshot [ver=60, locNode=65622274, servers=3, clients=23, state=ACTIVE, CPUs=144, offheap=9.1GB, heap=420.0GB, aliveNodes=[TcpDiscoveryNode [id=cf53e0f7-2552-491f-ae6e-3195ac331525, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, isClient=false, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=e128f204-dac2-4944-8d39-7ed1f4388b97, consistentId=e128f204-dac2-4944-8d39-7ed1f4388b97, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=f7c47309-2b66-44dc-b7bc-85c8ab1a7e7c, consistentId=f7c47309-2b66-44dc-b7bc-85c8ab1a7e7c, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=37e6c7ca-f952-405e-80e1-190c5e56dec3, consistentId=37e6c7ca-f952-405e-80e1-190c5e56dec3, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=9acb59e9-767a-4090-873f-d59b06e853a5, consistentId=9acb59e9-767a-4090-873f-d59b06e853a5, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=b26d62c3-74ce-4506-992a-f1058f9d0812, consistentId=b26d62c3-74ce-4506-992a-f1058f9d0812, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=2bd42e76-77cf-49ae-b158-a0f9ebaa0b86, consistentId=2bd42e76-77cf-49ae-b158-a0f9ebaa0b86, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=188d0a7f-aad4-49d6-970a-9482fee5729e, consistentId=188d0a7f-aad4-49d6-970a-9482fee5729e, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=57d59b10-e3b9-430f-88a8-3fd9e29d34b2, consistentId=57d59b10-e3b9-430f-88a8-3fd9e29d34b2, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=1f0120e9-ace7-43bf-ad09-a33f342783f6, consistentId=1f0120e9-ace7-43bf-ad09-a33f342783f6, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=0b916b5f-efba-48d8-9f3c-ffeadd6fbfa3, consistentId=0b916b5f-efba-48d8-9f3c-ffeadd6fbfa3, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=016fbaec-02c5-4c5c-88b9-f3ffc560266e, consistentId=016fbaec-02c5-4c5c-88b9-f3ffc560266e, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=5aa67ca8-d9b4-4476-90a3-cbb0dfb70ce9, consistentId=5aa67ca8-d9b4-4476-90a3-cbb0dfb70ce9, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=1555b296-b6b7-435b-aca0-802112ce9a31, consistentId=1555b296-b6b7-435b-aca0-802112ce9a31, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=0371ff67-3feb-4dae-8e47-786bb797e404, consistentId=0371ff67-3feb-4dae-8e47-786bb797e404, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=770bae5c-b8eb-44c1-b3da-31797ef0e5f2, consistentId=770bae5c-b8eb-44c1-b3da-31797ef0e5f2, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=5e325592-ff16-4485-8bc5-29cf280568d4, consistentId=5e325592-ff16-4485-8bc5-29cf280568d4, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=ce747e3a-cbae-417e-8b3b-079e099791a7, consistentId=ce747e3a-cbae-417e-8b3b-079e099791a7, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=48bcb95e-b229-436a-8cbe-236a83c5bd63, consistentId=48bcb95e-b229-436a-8cbe-236a83c5bd63, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=b95ba755-a3f3-4914-82b8-087442850aa3, consistentId=b95ba755-a3f3-4914-82b8-087442850aa3, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=0c1b9e3b-4ec1-4684-a5ca-5f3e84e76078, consistentId=0c1b9e3b-4ec1-4684-a5ca-5f3e84e76078, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=8b6b785d-9b47-4df4-b8c8-63aab02503a2, consistentId=8b6b785d-9b47-4df4-b8c8-63aab02503a2, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=127d727a-779a-47e1-8f9b-6a98d4e70629, consistentId=127d727a-779a-47e1-8f9b-6a98d4e70629, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=f0b0d5e3-4946-4819-b277-9ffd4b2d01df, consistentId=f0b0d5e3-4946-4819-b277-9ffd4b2d01df, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=65622274-1387-415c-aed1-8a7ea2d0c09c, consistentId=59d50ff1-b50d-4491-88da-e03b485598bf, isClient=false, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=afa9f790-0fcd-4c1d-86bd-7e4c99731e44, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, isClient=false, ver=2.13.0#20220420-sha1:551f6ece]]][16:03:11,979][INFO][disco-event-worker-#62][GridDiscoveryManager] ^-- Baseline [id=14, size=3, online=3, offline=0][16:03:11,980][INFO][exchange-worker-#65][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=60, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=afa9f790-0fcd-4c1d-86bd-7e4c99731e44, customEvt=null, allowMerge=true, exchangeFreeSwitch=false][16:03:11,982][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=60, minorTopVer=0], waitTime=0ms, futInfo=NA, mode=DISTRIBUTED][16:03:12,486][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ClientLatch [coordinator=TcpDiscoveryNode [id=cf53e0f7-2552-491f-ae6e-3195ac331525, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, serverign1.domain.name.removed.net/10.x.x.x:49500], discPort=49500, order=1, intOrder=1, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], ackSent=true, super=CompletableLatch [id=CompletableLatchUid [id=exchange, topVer=AffinityTopologyVersion [topVer=60, minorTopVer=0]]]][16:03:12,486][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=60, minorTopVer=0], waitTime=0ms, futInfo=NA, mode=LOCAL][16:03:12,518][INFO][exchange-worker-#65][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=60, minorTopVer=0], crd=false][16:03:13,009][INFO][sys-#133][GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=cf53e0f7-2552-491f-ae6e-3195ac331525, resVer=AffinityTopologyVersion [topVer=60, minorTopVer=0]][16:03:13,066][INFO][sys-#133][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=60, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=60, minorTopVer=0], err=null, rebalanced=false, wasRebalanced=true][16:03:13,097][INFO][sys-#133][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=65622274-1387-415c-aed1-8a7ea2d0c09c, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=60, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=afa9f790-0fcd-4c1d-86bd-7e4c99731e44, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign2.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=60, intOrder=43, lastExchangeTime=1665583391733, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], rebalanced=false, done=true, newCrdFut=null], topVer=AffinityTopologyVersion [topVer=60, minorTopVer=0]][16:03:13,097][INFO][sys-#133][GridDhtPartitionsExchangeFuture] Exchange timings [startVer=AffinityTopologyVersion [topVer=60, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=60, minorTopVer=0], stage="Waiting in exchange queue" (0 ms), stage="Exchange parameters initialization" (0 ms), stage="Determine exchange type" (1 ms), stage="Preloading notification" (0 ms), stage="Wait partitions release [latch=exchange]" (0 ms), stage="Wait partitions release latch [latch=exchange]" (503 ms), stage="Wait partitions release [latch=exchange]" (0 ms), stage="After states restored callback" (0 ms), stage="WAL history reservation" (4 ms), stage="Waiting for Full message" (517 ms), stage="Affinity recalculation" (40 ms), stage="Full map updating" (16 ms), stage="Exchange done" (30 ms), stage="Total time" (1111 ms)][16:03:13,097][INFO][sys-#133][GridDhtPartitionsExchangeFuture] Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=60, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=60, minorTopVer=0], stage="Affinity initialization (node join) [grp=CacheAs2ReceiptsCorrelation, crd=false]" (19 ms) (parent=Affinity recalculation), stage="Affinity initialization (node join) [grp=uniqueid, crd=false]" (16 ms) (parent=Affinity recalculation), stage="Affinity initialization (node join) [grp=SQL_PUBLIC_RELATIONAL_CHANGES, crd=false]" (8 ms) (parent=Affinity recalculation)][16:03:13,118][INFO][exchange-worker-#65][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=60, minorTopVer=0], force=false, evt=NODE_JOINED, node=afa9f790-0fcd-4c1d-86bd-7e4c99731e44][16:03:13,459][INFO][grid-nio-worker-tcp-comm-3-#26%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:31531][16:03:13,671][INFO][rebalance-striped-#179][GridDhtPartitionSupplier] Finished supplying rebalancing [grp=SQL_PUBLIC_B2BICLUSTERSTATUS, demander=afa9f790-0fcd-4c1d-86bd-7e4c99731e44, topVer=AffinityTopologyVersion [topVer=60, minorTopVer=0]][16:03:13,911][INFO][exchange-worker-#65][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=60, minorTopVer=1], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=cf53e0f7-2552-491f-ae6e-3195ac331525, customEvt=CacheAffinityChangeMessage [id=16cafb7c381-22e42b79-79fa-4d8b-a11a-efa1d1acfd55, topVer=AffinityTopologyVersion [topVer=60, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], allowMerge=false, exchangeFreeSwitch=false][16:03:13,921][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=60, minorTopVer=1], waitTime=0ms, futInfo=NA, mode=DISTRIBUTED][16:03:13,972][WARNING][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Failed to wait for locks release future. Dumping pending objects that might be the cause: 65622274-1387-415c-aed1-8a7ea2d0c09c[16:03:13,972][WARNING][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Locked keys:[16:03:13,973][WARNING][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Locked key: IgniteTxKey [key=KeyCacheObjectImpl [part=867, val=edifactid.unq::NESTSJCUST, hasValBytes=true], cacheId=-294459220][16:03:13,974][WARNING][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Awaited locked entry [key=IgniteTxKey [key=KeyCacheObjectImpl [part=867, val=edifactid.unq::NESTSJCUST, hasValBytes=true], cacheId=-294459220], mvcc=[GridCacheMvccCandidate [nodeId=65622274-1387-415c-aed1-8a7ea2d0c09c, ver=GridCacheVersion [topVer=276976590, order=1665583383889, nodeOrder=13, dataCenterId=0], threadId=281, id=2435, topVer=AffinityTopologyVersion [topVer=60, minorTopVer=0], reentry=null, otherNodeId=1f0120e9-ace7-43bf-ad09-a33f342783f6, otherVer=GridCacheVersion [topVer=276976590, order=1665583383889, nodeOrder=13, dataCenterId=0], mappedDhtNodes=ArrayList [TcpDiscoveryNode [id=afa9f790-0fcd-4c1d-86bd-7e4c99731e44, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign2.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=60, intOrder=43, lastExchangeTime=1665583391733, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], TcpDiscoveryNode [id=cf53e0f7-2552-491f-ae6e-3195ac331525, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, serverign1.domain.name.removed.net/10.x.x.x:49500], discPort=49500, order=1, intOrder=1, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false]], mappedNearNodes=null, ownerVer=GridCacheVersion [topVer=276976590, order=1665583383889, nodeOrder=20, dataCenterId=0], serOrder=null, key=KeyCacheObjectImpl [part=867, val=edifactid.unq::NESTSJCUST, hasValBytes=true], masks=local=1|owner=1|ready=1|reentry=0|used=0|tx=0|single_implicit=0|dht_local=1|near_local=0|removed=0|read=0, prevVer=null, nextVer=null], GridCacheMvccCandidate [nodeId=65622274-1387-415c-aed1-8a7ea2d0c09c, ver=GridCacheVersion [topVer=276976590, order=1665583383889, nodeOrder=23, dataCenterId=0], threadId=269, id=2434, topVer=AffinityTopologyVersion [topVer=60, minorTopVer=0], reentry=null, otherNodeId=b95ba755-a3f3-4914-82b8-087442850aa3, otherVer=GridCacheVersion [topVer=276976590, order=1665583383889, nodeOrder=23, dataCenterId=0], mappedDhtNodes=null, mappedNearNodes=null, ownerVer=GridCacheVersion [topVer=276976590, order=1665583383889, nodeOrder=20, dataCenterId=0], serOrder=null, key=KeyCacheObjectImpl [part=867, val=edifactid.unq::NESTSJCUST, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=0|single_implicit=0|dht_local=1|near_local=0|removed=0|read=0, prevVer=null, nextVer=null], GridCacheMvccCandidate [nodeId=65622274-1387-415c-aed1-8a7ea2d0c09c, ver=GridCacheVersion [topVer=276976590, order=1665583383893, nodeOrder=20, dataCenterId=0], threadId=306, id=2436, topVer=AffinityTopologyVersion [topVer=60, minorTopVer=0], reentry=null, otherNodeId=5e325592-ff16-4485-8bc5-29cf280568d4, otherVer=GridCacheVersion [topVer=276976590, order=1665583383893, nodeOrder=20, dataCenterId=0], mappedDhtNodes=null, mappedNearNodes=null, ownerVer=GridCacheVersion [topVer=276976590, order=1665583383889, nodeOrder=13, dataCenterId=0], serOrder=null, key=KeyCacheObjectImpl [part=867, val=edifactid.unq::NESTSJCUST, hasValBytes=true], masks=local=1|owner=0|ready=1|reentry=0|used=0|tx=0|single_implicit=0|dht_local=1|near_local=0|removed=0|read=0, prevVer=null, nextVer=null]]][16:03:14,179][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ClientLatch [coordinator=TcpDiscoveryNode [id=cf53e0f7-2552-491f-ae6e-3195ac331525, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, serverign1.domain.name.removed.net/10.x.x.x:49500], discPort=49500, order=1, intOrder=1, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], ackSent=true, super=CompletableLatch [id=CompletableLatchUid [id=exchange, topVer=AffinityTopologyVersion [topVer=60, minorTopVer=1]]]][16:03:14,179][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=60, minorTopVer=1], waitTime=0ms, futInfo=NA, mode=LOCAL][16:03:14,209][INFO][exchange-worker-#65][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=60, minorTopVer=1], crd=false][16:03:14,316][INFO][sys-#131][GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=cf53e0f7-2552-491f-ae6e-3195ac331525, resVer=AffinityTopologyVersion [topVer=60, minorTopVer=1]][16:03:14,328][INFO][sys-#131][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=60, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=60, minorTopVer=1], err=null, rebalanced=true, wasRebalanced=false][16:03:14,344][INFO][sys-#131][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=65622274-1387-415c-aed1-8a7ea2d0c09c, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=60, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=cf53e0f7-2552-491f-ae6e-3195ac331525, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, serverign1.domain.name.removed.net/10.x.x.x:49500], discPort=49500, order=1, intOrder=1, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], rebalanced=true, done=true, newCrdFut=null], topVer=AffinityTopologyVersion [topVer=60, minorTopVer=1]][16:03:14,344][INFO][sys-#131][GridDhtPartitionsExchangeFuture] Exchange timings [startVer=AffinityTopologyVersion [topVer=60, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=60, minorTopVer=1], stage="Waiting in exchange queue" (0 ms), stage="Exchange parameters initialization" (0 ms), stage="Determine exchange type" (9 ms), stage="Preloading notification" (0 ms), stage="Wait partitions release [latch=exchange]" (256 ms), stage="Wait partitions release latch [latch=exchange]" (1 ms), stage="Wait partitions release [latch=exchange]" (0 ms), stage="After states restored callback" (5 ms), stage="WAL history reservation" (4 ms), stage="Waiting for Full message" (125 ms), stage="Affinity recalculation" (0 ms), stage="Full map updating" (12 ms), stage="Exchange done" (16 ms), stage="Total time" (428 ms)][16:03:14,345][INFO][sys-#131][GridDhtPartitionsExchangeFuture] Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=60, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=60, minorTopVer=1], stage="Affinity change by custom message [grp=CacheRosettaNet2MessageCorrelation]" (4 ms) (parent=Determine exchange type), stage="Affinity change by custom message [grp=CacheOftpReceiptsCorrelation]" (4 ms) (parent=Determine exchange type), stage="Affinity change by custom message [grp=uniqueid]" (2 ms) (parent=Determine exchange type)][16:03:14,359][INFO][exchange-worker-#65][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=60, minorTopVer=1], force=false, evt=DISCOVERY_CUSTOM_EVT, node=cf53e0f7-2552-491f-ae6e-3195ac331525][16:03:19,162][INFO][grid-timeout-worker-#22][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=65622274, uptime=00:05:00.026] ^-- Cluster [hosts=8, CPUs=144, servers=3, clients=23, topVer=60, minorTopVer=1] ^-- Network [addrs=[10.x.x.x, 127.0.0.1], discoPort=49500, commPort=49100] ^-- CPU [CPUs=4, curLoad=5.9%, avgLoad=4.7%, GC=0%] ^-- Heap [used=971MB, free=84.2%, comm=6144MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=2, qSize=0] ^-- System thread pool [active=0, idle=8, qSize=0] ^-- Striped thread pool [active=0, idle=8, qSize=0][16:03:20,258][INFO][grid-nio-worker-tcp-comm-0-#23%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:38812][16:03:20,771][INFO][grid-nio-worker-tcp-comm-1-#24%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:38818][16:03:20,775][INFO][tcp-comm-worker-#1-#28][TcpCommunicationSpi] TCP client created [client=null, node addrs=[servercfg1.domain.name.removed.net/10.x.x.x:49100, /127.0.0.1:49100, 0:0:0:0:0:0:0:1%lo:49100], duration=532ms][16:03:35,881][SEVERE][sys-#130][TcpCommunicationSpi] Failed to send message to remote node [node=TcpDiscoveryNode [id=291ffb11-da63-4ed7-80fd-0659e7f51dab, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign2.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=2, intOrder=2, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], msg=GridIoMessage [plc=2, topic=TOPIC_CACHE, topicOrd=8, ordered=false, timeout=0, skipOnTimeout=false, msg=CacheContinuousQueryBatchAck [routineId=b77958e2-ee4b-419c-96c7-83f68d2be1ac, updateCntrs=HashMap {1001=2335671, 930=3083726, 876=0}]]]class org.apache.ignite.internal.cluster.ClusterTopologyCheckedException: Failed to send message (node left topology): TcpDiscoveryNode [id=291ffb11-da63-4ed7-80fd-0659e7f51dab, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign2.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=2, intOrder=2, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false] at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createNioSession(GridNioServerWrapper.java:417) at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createTcpClient(GridNioServerWrapper.java:693) at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:1174) at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createTcpClient(GridNioServerWrapper.java:691) at org.apache.ignite.spi.communication.tcp.internal.ConnectionClientPool.createCommunicationClient(ConnectionClientPool.java:441) at org.apache.ignite.spi.communication.tcp.internal.ConnectionClientPool.reserveClient(ConnectionClientPool.java:230) at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:1105) at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:1052) at org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:2102) at org.apache.ignite.internal.managers.communication.GridIoManager.sendToGridTopic(GridIoManager.java:2195) at org.apache.ignite.internal.processors.cache.GridCacheIoManager.send(GridCacheIoManager.java:1266) at org.apache.ignite.internal.processors.cache.query.continuous.CacheContinuousQueryHandler$5.run(CacheContinuousQueryHandler.java:1392) at org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.java:7422) at org.apache.ignite.internal.processors.closure.GridClosureProcessor$1.body(GridClosureProcessor.java:827) at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:125) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)[16:03:38,812][SEVERE][sys-#128][TcpCommunicationSpi] Failed to send message to remote node [node=TcpDiscoveryNode [id=291ffb11-da63-4ed7-80fd-0659e7f51dab, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign2.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=2, intOrder=2, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], msg=GridIoMessage [plc=2, topic=TOPIC_CACHE, topicOrd=8, ordered=false, timeout=0, skipOnTimeout=false, msg=CacheContinuousQueryBatchAck [routineId=61b72cbc-57ac-4292-828a-a1169e7037ff, updateCntrs=HashMap {1001=2335671, 930=3083726, 876=0}]]]class org.apache.ignite.internal.cluster.ClusterTopologyCheckedException: Failed to send message (node left topology): TcpDiscoveryNode [id=291ffb11-da63-4ed7-80fd-0659e7f51dab, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign2.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=2, intOrder=2, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false] at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createNioSession(GridNioServerWrapper.java:417) at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createTcpClient(GridNioServerWrapper.java:693) at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:1174) at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createTcpClient(GridNioServerWrapper.java:691) at org.apache.ignite.spi.communication.tcp.internal.ConnectionClientPool.createCommunicationClient(ConnectionClientPool.java:441) at org.apache.ignite.spi.communication.tcp.internal.ConnectionClientPool.reserveClient(ConnectionClientPool.java:230) at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:1105) at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:1052) at org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:2102) at org.apache.ignite.internal.managers.communication.GridIoManager.sendToGridTopic(GridIoManager.java:2195) at org.apache.ignite.internal.processors.cache.GridCacheIoManager.send(GridCacheIoManager.java:1266) at org.apache.ignite.internal.processors.cache.query.continuous.CacheContinuousQueryHandler$5.run(CacheContinuousQueryHandler.java:1392) at org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.java:7422) at org.apache.ignite.internal.processors.closure.GridClosureProcessor$1.body(GridClosureProcessor.java:827) at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:125) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)[16:03:38,877][SEVERE][sys-#131][TcpCommunicationSpi] Failed to send message to remote node [node=TcpDiscoveryNode [id=291ffb11-da63-4ed7-80fd-0659e7f51dab, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign2.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=2, intOrder=2, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], msg=GridIoMessage [plc=2, topic=TOPIC_CACHE, topicOrd=8, ordered=false, timeout=0, skipOnTimeout=false, msg=CacheContinuousQueryBatchAck [routineId=ead8ecca-ce78-4bbd-b781-6fcda52f5ac8, updateCntrs=HashMap {1001=2335671, 930=3083726, 876=0}]]]class org.apache.ignite.internal.cluster.ClusterTopologyCheckedException: Failed to send message (node left topology): TcpDiscoveryNode [id=291ffb11-da63-4ed7-80fd-0659e7f51dab, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign2.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=2, intOrder=2, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false] at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createNioSession(GridNioServerWrapper.java:417) at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createTcpClient(GridNioServerWrapper.java:693) at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:1174) at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createTcpClient(GridNioServerWrapper.java:691) at org.apache.ignite.spi.communication.tcp.internal.ConnectionClientPool.createCommunicationClient(ConnectionClientPool.java:441) at org.apache.ignite.spi.communication.tcp.internal.ConnectionClientPool.reserveClient(ConnectionClientPool.java:230) at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:1105) at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:1052) at org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:2102) at org.apache.ignite.internal.managers.communication.GridIoManager.sendToGridTopic(GridIoManager.java:2195) at org.apache.ignite.internal.processors.cache.GridCacheIoManager.send(GridCacheIoManager.java:1266) at org.apache.ignite.internal.processors.cache.query.continuous.CacheContinuousQueryHandler$5.run(CacheContinuousQueryHandler.java:1392) at org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.java:7422) at org.apache.ignite.internal.processors.closure.GridClosureProcessor$1.body(GridClosureProcessor.java:827) at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:125) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)[16:03:41,309][SEVERE][sys-#133][TcpCommunicationSpi] Failed to send message to remote node [node=TcpDiscoveryNode [id=291ffb11-da63-4ed7-80fd-0659e7f51dab, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign2.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=2, intOrder=2, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], msg=GridIoMessage [plc=2, topic=TOPIC_CACHE, topicOrd=8, ordered=false, timeout=0, skipOnTimeout=false, msg=CacheContinuousQueryBatchAck [routineId=73499190-360f-4bc2-8926-3468504931a3, updateCntrs=HashMap {1001=2335671, 930=3083726, 876=0}]]]class org.apache.ignite.internal.cluster.ClusterTopologyCheckedException: Failed to send message (node left topology): TcpDiscoveryNode [id=291ffb11-da63-4ed7-80fd-0659e7f51dab, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign2.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=2, intOrder=2, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false] at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createNioSession(GridNioServerWrapper.java:417) at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createTcpClient(GridNioServerWrapper.java:693) at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:1174) at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createTcpClient(GridNioServerWrapper.java:691) at org.apache.ignite.spi.communication.tcp.internal.ConnectionClientPool.createCommunicationClient(ConnectionClientPool.java:441) at org.apache.ignite.spi.communication.tcp.internal.ConnectionClientPool.reserveClient(ConnectionClientPool.java:230) at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:1105) at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:1052) at org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:2102) at org.apache.ignite.internal.managers.communication.GridIoManager.sendToGridTopic(GridIoManager.java:2195) at org.apache.ignite.internal.processors.cache.GridCacheIoManager.send(GridCacheIoManager.java:1266) at org.apache.ignite.internal.processors.cache.query.continuous.CacheContinuousQueryHandler$5.run(CacheContinuousQueryHandler.java:1392) at org.apache.ignite.internal.util.IgniteUtils.wrapThreadLoader(IgniteUtils.java:7422) at org.apache.ignite.internal.processors.closure.GridClosureProcessor$1.body(GridClosureProcessor.java:827) at org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:125) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829)[16:04:19,165][INFO][grid-timeout-worker-#22][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=65622274, uptime=00:06:00.028] ^-- Cluster [hosts=8, CPUs=144, servers=3, clients=23, topVer=60, minorTopVer=1] ^-- Network [addrs=[10.x.x.x, 127.0.0.1], discoPort=49500, commPort=49100] ^-- CPU [CPUs=4, curLoad=1.83%, avgLoad=4.65%, GC=0%] ^-- Heap [used=1074MB, free=82.52%, comm=6144MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=8, qSize=0] ^-- Striped thread pool [active=0, idle=8, qSize=0][16:04:30,844][INFO][wal-file-archiver%null-#66][FileWriteAheadLogManager] Starting to copy WAL segment [absIdx=349, segIdx=9, origFile=/usr/share/apache-ignite/work/db/wal/node00-59d50ff1-b50d-4491-88da-e03b485598bf/0000000000000009.wal, dstFile=/usr/share/apache-ignite/work/db/wal/archive/node00-59d50ff1-b50d-4491-88da-e03b485598bf/0000000000000349.wal][16:04:30,855][INFO][wal-file-cleaner%null-#67][FileWriteAheadLogManager] Starting to clean WAL archive [highIdx=342, currSize=512.0 MB, maxSize=1.0 GB][16:04:30,868][INFO][wal-file-cleaner%null-#67][FileWriteAheadLogManager] Finish clean WAL archive [cleanCnt=1, currSize=448.0 MB, maxSize=1.0 GB][16:04:30,952][INFO][wal-file-archiver%null-#66][FileWriteAheadLogManager] Copied file [src=/usr/share/apache-ignite/work/db/wal/node00-59d50ff1-b50d-4491-88da-e03b485598bf/0000000000000009.wal, dst=/usr/share/apache-ignite/work/db/wal/archive/node00-59d50ff1-b50d-4491-88da-e03b485598bf/0000000000000349.wal][16:04:30,961][INFO][db-checkpoint-thread-#70][Checkpointer] Checkpoint started [checkpointId=b7f89819-3bbb-4aa1-8045-55a574ee2e97, startPtr=WALPointer [idx=350, fileOff=3169550, len=209777], checkpointBeforeLockTime=73ms, checkpointLockWait=0ms, checkpointListenersExecuteTime=29ms, checkpointLockHoldTime=39ms, walCpRecordFsyncDuration=16ms, writeCheckpointEntryDuration=10ms, splitAndSortCpPagesDuration=14ms, pages=7276, reason='timeout'][16:04:31,182][INFO][db-checkpoint-thread-#70][Checkpointer] Checkpoint finished [cpId=b7f89819-3bbb-4aa1-8045-55a574ee2e97, pages=7276, markPos=WALPointer [idx=350, fileOff=3169550, len=209777], walSegmentsCovered=[349], markDuration=79ms, pagesWrite=136ms, fsync=85ms, total=373ms][16:04:39,016][INFO][grid-nio-worker-tcp-comm-3-#26%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:34173][16:05:19,170][INFO][grid-timeout-worker-#22][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=65622274, uptime=00:07:00.030] ^-- Cluster [hosts=8, CPUs=144, servers=3, clients=23, topVer=60, minorTopVer=1] ^-- Network [addrs=[10.x.x.x, 127.0.0.1], discoPort=49500, commPort=49100] ^-- CPU [CPUs=4, curLoad=13.4%, avgLoad=4.63%, GC=0%] ^-- Heap [used=1520MB, free=75.26%, comm=6144MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=8, qSize=0] ^-- Striped thread pool [active=0, idle=8, qSize=0][16:06:00,803][INFO][disco-event-worker-#62][GridDiscoveryManager] Node left topology: TcpDiscoveryNode [id=cf53e0f7-2552-491f-ae6e-3195ac331525, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, serverign1.domain.name.removed.net/10.x.x.x:49500], discPort=49500, order=1, intOrder=1, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false][16:06:00,804][INFO][disco-event-worker-#62][GridDiscoveryManager] Topology snapshot [ver=61, locNode=65622274, servers=2, clients=23, state=ACTIVE, CPUs=140, offheap=6.0GB, heap=420.0GB, aliveNodes=[TcpDiscoveryNode [id=e128f204-dac2-4944-8d39-7ed1f4388b97, consistentId=e128f204-dac2-4944-8d39-7ed1f4388b97, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=f7c47309-2b66-44dc-b7bc-85c8ab1a7e7c, consistentId=f7c47309-2b66-44dc-b7bc-85c8ab1a7e7c, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=37e6c7ca-f952-405e-80e1-190c5e56dec3, consistentId=37e6c7ca-f952-405e-80e1-190c5e56dec3, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=9acb59e9-767a-4090-873f-d59b06e853a5, consistentId=9acb59e9-767a-4090-873f-d59b06e853a5, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=b26d62c3-74ce-4506-992a-f1058f9d0812, consistentId=b26d62c3-74ce-4506-992a-f1058f9d0812, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=2bd42e76-77cf-49ae-b158-a0f9ebaa0b86, consistentId=2bd42e76-77cf-49ae-b158-a0f9ebaa0b86, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=188d0a7f-aad4-49d6-970a-9482fee5729e, consistentId=188d0a7f-aad4-49d6-970a-9482fee5729e, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=57d59b10-e3b9-430f-88a8-3fd9e29d34b2, consistentId=57d59b10-e3b9-430f-88a8-3fd9e29d34b2, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=1f0120e9-ace7-43bf-ad09-a33f342783f6, consistentId=1f0120e9-ace7-43bf-ad09-a33f342783f6, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=0b916b5f-efba-48d8-9f3c-ffeadd6fbfa3, consistentId=0b916b5f-efba-48d8-9f3c-ffeadd6fbfa3, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=016fbaec-02c5-4c5c-88b9-f3ffc560266e, consistentId=016fbaec-02c5-4c5c-88b9-f3ffc560266e, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=5aa67ca8-d9b4-4476-90a3-cbb0dfb70ce9, consistentId=5aa67ca8-d9b4-4476-90a3-cbb0dfb70ce9, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=1555b296-b6b7-435b-aca0-802112ce9a31, consistentId=1555b296-b6b7-435b-aca0-802112ce9a31, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=0371ff67-3feb-4dae-8e47-786bb797e404, consistentId=0371ff67-3feb-4dae-8e47-786bb797e404, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=770bae5c-b8eb-44c1-b3da-31797ef0e5f2, consistentId=770bae5c-b8eb-44c1-b3da-31797ef0e5f2, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=5e325592-ff16-4485-8bc5-29cf280568d4, consistentId=5e325592-ff16-4485-8bc5-29cf280568d4, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=ce747e3a-cbae-417e-8b3b-079e099791a7, consistentId=ce747e3a-cbae-417e-8b3b-079e099791a7, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=48bcb95e-b229-436a-8cbe-236a83c5bd63, consistentId=48bcb95e-b229-436a-8cbe-236a83c5bd63, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=b95ba755-a3f3-4914-82b8-087442850aa3, consistentId=b95ba755-a3f3-4914-82b8-087442850aa3, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=0c1b9e3b-4ec1-4684-a5ca-5f3e84e76078, consistentId=0c1b9e3b-4ec1-4684-a5ca-5f3e84e76078, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=8b6b785d-9b47-4df4-b8c8-63aab02503a2, consistentId=8b6b785d-9b47-4df4-b8c8-63aab02503a2, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=127d727a-779a-47e1-8f9b-6a98d4e70629, consistentId=127d727a-779a-47e1-8f9b-6a98d4e70629, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=f0b0d5e3-4946-4819-b277-9ffd4b2d01df, consistentId=f0b0d5e3-4946-4819-b277-9ffd4b2d01df, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=65622274-1387-415c-aed1-8a7ea2d0c09c, consistentId=59d50ff1-b50d-4491-88da-e03b485598bf, isClient=false, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=afa9f790-0fcd-4c1d-86bd-7e4c99731e44, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, isClient=false, ver=2.13.0#20220420-sha1:551f6ece]]][16:06:00,804][INFO][disco-event-worker-#62][GridDiscoveryManager] Coordinator changed [prev=TcpDiscoveryNode [id=cf53e0f7-2552-491f-ae6e-3195ac331525, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, serverign1.domain.name.removed.net/10.x.x.x:49500], discPort=49500, order=1, intOrder=1, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], cur=TcpDiscoveryNode [id=65622274-1387-415c-aed1-8a7ea2d0c09c, consistentId=59d50ff1-b50d-4491-88da-e03b485598bf, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign3.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=58, intOrder=42, lastExchangeTime=1665583560802, loc=true, ver=2.13.0#20220420-sha1:551f6ece, isClient=false]][16:06:00,804][INFO][disco-event-worker-#62][GridDiscoveryManager] ^-- Baseline [id=14, size=3, online=2, offline=1][16:06:00,805][INFO][disco-event-worker-#62][MvccProcessorImpl] Assigned mvcc coordinator [crd=MvccCoordinator [topVer=AffinityTopologyVersion [topVer=61, minorTopVer=0], nodeId=65622274-1387-415c-aed1-8a7ea2d0c09c, ver=1665496530721, local=true, initialized=false]][16:06:00,806][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=32468][16:06:00,806][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=32468][16:06:00,807][INFO][tcp-disco-sock-reader-[]-#30-#206][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:32468, rmtPort=32468][16:06:00,814][INFO][sys-#132][ExchangeLatchManager] Become new coordinator 65622274-1387-415c-aed1-8a7ea2d0c09c[16:06:00,815][INFO][exchange-worker-#65][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=61, minorTopVer=0], crd=true, evt=NODE_LEFT, evtNode=cf53e0f7-2552-491f-ae6e-3195ac331525, customEvt=null, allowMerge=false, exchangeFreeSwitch=true][16:06:00,816][INFO][sys-#130][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=CacheAs2ReceiptsCorrelation, expectedPrimary=512.00, actualPrimary=530, expectedBackups=1024.00, actualBackups=494, warningThreshold=50.00%][16:06:00,817][INFO][exchange-worker-#65][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=timers, expectedPrimary=512.00, actualPrimary=530, expectedBackups=1024.00, actualBackups=494, warningThreshold=50.00%][16:06:00,819][INFO][exchange-worker-#65][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=CacheRosettaNet2MessageCorrelation, expectedPrimary=512.00, actualPrimary=530, expectedBackups=1024.00, actualBackups=494, warningThreshold=50.00%][16:06:00,819][INFO][sys-#130][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=B2BiClusterStatusCache, expectedPrimary=512.00, actualPrimary=530, expectedBackups=1024.00, actualBackups=494, warningThreshold=50.00%][16:06:00,823][INFO][sys-#129][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=table, expectedPrimary=512.00, actualPrimary=530, expectedBackups=1024.00, actualBackups=494, warningThreshold=50.00%][16:06:00,824][INFO][sys-#128][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=uniqueid, expectedPrimary=512.00, actualPrimary=530, expectedBackups=1024.00, actualBackups=494, warningThreshold=50.00%][16:06:00,824][INFO][exchange-worker-#65][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=CacheOftpReceiptsCorrelation, expectedPrimary=512.00, actualPrimary=530, expectedBackups=1024.00, actualBackups=494, warningThreshold=50.00%][16:06:00,825][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=61, minorTopVer=0], waitTime=0ms, futInfo=NA, mode=LOCAL][16:06:00,828][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=55896][16:06:00,828][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=55896][16:06:00,829][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=42168][16:06:00,829][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=42168][16:06:00,830][INFO][tcp-disco-sock-reader-[]-#31-#208][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:55896, rmtPort=55896][16:06:00,830][INFO][tcp-disco-sock-reader-[]-#32-#210][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:42168, rmtPort=42168][16:06:00,838][INFO][grid-nio-worker-tcp-comm-0-#23%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:60333][16:06:00,849][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=61, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=61, minorTopVer=0], err=null, rebalanced=true, wasRebalanced=true][16:06:00,858][INFO][tcp-disco-sock-reader-[afa9f790 10.x.x.x:32468]-#30-#206][TcpDiscoverySpi] Initialized connection with remote server node [nodeId=afa9f790-0fcd-4c1d-86bd-7e4c99731e44, rmtAddr=/10.x.x.x:32468][16:06:00,866][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=58230][16:06:00,866][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=58230][16:06:00,872][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=42320][16:06:00,872][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=42320][16:06:00,873][INFO][tcp-disco-sock-reader-[]-#33-#211][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:58230, rmtPort=58230][16:06:00,877][INFO][tcp-disco-sock-reader-[]-#34-#212][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:42320, rmtPort=42320][16:06:00,879][WARNING][exchange-worker-#65][BaselineTopologyUpdater] Baseline auto-adjust will be executed in '30000' ms[16:06:00,880][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=65622274-1387-415c-aed1-8a7ea2d0c09c, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=61, minorTopVer=0], evt=NODE_LEFT, evtNode=TcpDiscoveryNode [id=cf53e0f7-2552-491f-ae6e-3195ac331525, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, serverign1.domain.name.removed.net/10.x.x.x:49500], discPort=49500, order=1, intOrder=1, lastExchangeTime=1665583097185, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], rebalanced=true, done=true, newCrdFut=null], topVer=AffinityTopologyVersion [topVer=61, minorTopVer=0]][16:06:00,880][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Exchange timings [startVer=AffinityTopologyVersion [topVer=61, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=61, minorTopVer=0], stage="Waiting in exchange queue" (0 ms), stage="Exchange parameters initialization" (0 ms), stage="Determine exchange type" (10 ms), stage="Preloading notification" (0 ms), stage="After states restored callback" (0 ms), stage="WAL history reservation" (6 ms), stage="Finalize update counters" (3 ms), stage="Detect lost partitions" (18 ms), stage="Exchange done" (26 ms), stage="Total time" (63 ms)][16:06:00,880][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=61, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=61, minorTopVer=0], stage="Affinity initialization (exchange-free switch on fully-rebalanced topology) [grp=SQL_PUBLIC_TABLEINFO]" (7 ms) (parent=Determine exchange type), stage="Affinity initialization (exchange-free switch on fully-rebalanced topology) [grp=SQL_PUBLIC_RELATIONAL_DATA]" (7 ms) (parent=Determine exchange type), stage="Affinity initialization (exchange-free switch on fully-rebalanced topology) [grp=CacheOftpReceiptsCorrelation]" (5 ms) (parent=Determine exchange type)][16:06:00,880][INFO][exchange-worker-#65][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=61, minorTopVer=0], crd=true][16:06:00,881][INFO][tcp-disco-sock-reader-[2bd42e76 10.x.x.x:55896 client]-#31-#208][TcpDiscoverySpi] Initialized connection with remote client node [nodeId=2bd42e76-77cf-49ae-b158-a0f9ebaa0b86, rmtAddr=/10.x.x.x:55896][16:06:00,884][INFO][tcp-disco-sock-reader-[b95ba755 10.x.x.x:42168 client]-#32-#210][TcpDiscoverySpi] Initialized connection with remote client node [nodeId=b95ba755-a3f3-4914-82b8-087442850aa3, rmtAddr=/10.x.x.x:42168][16:06:00,896][INFO][exchange-worker-#65][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=61, minorTopVer=0], force=false, evt=NODE_LEFT, node=cf53e0f7-2552-491f-ae6e-3195ac331525][16:06:00,909][INFO][grid-nio-worker-tcp-comm-1-#24%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:50677][16:06:00,927][INFO][tcp-disco-sock-reader-[b26d62c3 10.x.x.x:58230 client]-#33-#211][TcpDiscoverySpi] Initialized connection with remote client node [nodeId=b26d62c3-74ce-4506-992a-f1058f9d0812, rmtAddr=/10.x.x.x:58230][16:06:00,931][INFO][tcp-disco-sock-reader-[5e325592 10.x.x.x:42320 client]-#34-#212][TcpDiscoverySpi] Initialized connection with remote client node [nodeId=5e325592-ff16-4485-8bc5-29cf280568d4, rmtAddr=/10.x.x.x:42320][16:06:00,954][INFO][grid-nio-worker-tcp-comm-2-#25%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:29139][16:06:01,234][INFO][tcp-disco-sock-reader-[cf53e0f7 10.x.x.x:33928]-#7-#134][TcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/10.x.x.x:33928, rmtPort=33928, rmtNodeId=cf53e0f7-2552-491f-ae6e-3195ac331525][16:06:11,431][INFO][tcp-disco-msg-worker-[afa9f790 10.x.x.x:49500 crd]-#2-#57][GridEncryptionManager] Joining node doesn't have stored group keys [node=24971b88-cfda-4953-b83b-4c077b567652][16:06:11,462][INFO][tcp-disco-sock-reader-[afa9f790 10.x.x.x:32468]-#30-#206][TcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/10.x.x.x:32468, rmtPort=32468, rmtNodeId=afa9f790-0fcd-4c1d-86bd-7e4c99731e44][16:06:11,641][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/10.x.x.x, rmtPort=49588][16:06:11,641][INFO][tcp-disco-srvr-[:49500]-#3-#58][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/10.x.x.x, rmtPort=49588][16:06:11,642][INFO][tcp-disco-sock-reader-[]-#39-#228][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/10.x.x.x:49588, rmtPort=49588][16:06:11,672][INFO][tcp-disco-sock-reader-[24971b88 10.x.x.x:49588]-#39-#228][TcpDiscoverySpi] Initialized connection with remote server node [nodeId=24971b88-cfda-4953-b83b-4c077b567652, rmtAddr=/10.x.x.x:49588][16:06:11,696][INFO][disco-event-worker-#62][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=24971b88-cfda-4953-b83b-4c077b567652, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, serverign1.domain.name.removed.net/10.x.x.x:49500], discPort=49500, order=62, intOrder=44, lastExchangeTime=1665583571422, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false][16:06:11,697][INFO][disco-event-worker-#62][GridDiscoveryManager] Topology snapshot [ver=62, locNode=65622274, servers=3, clients=23, state=ACTIVE, CPUs=144, offheap=9.1GB, heap=420.0GB, aliveNodes=[TcpDiscoveryNode [id=e128f204-dac2-4944-8d39-7ed1f4388b97, consistentId=e128f204-dac2-4944-8d39-7ed1f4388b97, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=f7c47309-2b66-44dc-b7bc-85c8ab1a7e7c, consistentId=f7c47309-2b66-44dc-b7bc-85c8ab1a7e7c, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=37e6c7ca-f952-405e-80e1-190c5e56dec3, consistentId=37e6c7ca-f952-405e-80e1-190c5e56dec3, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=9acb59e9-767a-4090-873f-d59b06e853a5, consistentId=9acb59e9-767a-4090-873f-d59b06e853a5, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=b26d62c3-74ce-4506-992a-f1058f9d0812, consistentId=b26d62c3-74ce-4506-992a-f1058f9d0812, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=2bd42e76-77cf-49ae-b158-a0f9ebaa0b86, consistentId=2bd42e76-77cf-49ae-b158-a0f9ebaa0b86, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=188d0a7f-aad4-49d6-970a-9482fee5729e, consistentId=188d0a7f-aad4-49d6-970a-9482fee5729e, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=57d59b10-e3b9-430f-88a8-3fd9e29d34b2, consistentId=57d59b10-e3b9-430f-88a8-3fd9e29d34b2, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=1f0120e9-ace7-43bf-ad09-a33f342783f6, consistentId=1f0120e9-ace7-43bf-ad09-a33f342783f6, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=0b916b5f-efba-48d8-9f3c-ffeadd6fbfa3, consistentId=0b916b5f-efba-48d8-9f3c-ffeadd6fbfa3, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=016fbaec-02c5-4c5c-88b9-f3ffc560266e, consistentId=016fbaec-02c5-4c5c-88b9-f3ffc560266e, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=5aa67ca8-d9b4-4476-90a3-cbb0dfb70ce9, consistentId=5aa67ca8-d9b4-4476-90a3-cbb0dfb70ce9, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=1555b296-b6b7-435b-aca0-802112ce9a31, consistentId=1555b296-b6b7-435b-aca0-802112ce9a31, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=0371ff67-3feb-4dae-8e47-786bb797e404, consistentId=0371ff67-3feb-4dae-8e47-786bb797e404, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=770bae5c-b8eb-44c1-b3da-31797ef0e5f2, consistentId=770bae5c-b8eb-44c1-b3da-31797ef0e5f2, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=5e325592-ff16-4485-8bc5-29cf280568d4, consistentId=5e325592-ff16-4485-8bc5-29cf280568d4, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=ce747e3a-cbae-417e-8b3b-079e099791a7, consistentId=ce747e3a-cbae-417e-8b3b-079e099791a7, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=48bcb95e-b229-436a-8cbe-236a83c5bd63, consistentId=48bcb95e-b229-436a-8cbe-236a83c5bd63, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=b95ba755-a3f3-4914-82b8-087442850aa3, consistentId=b95ba755-a3f3-4914-82b8-087442850aa3, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=0c1b9e3b-4ec1-4684-a5ca-5f3e84e76078, consistentId=0c1b9e3b-4ec1-4684-a5ca-5f3e84e76078, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=8b6b785d-9b47-4df4-b8c8-63aab02503a2, consistentId=8b6b785d-9b47-4df4-b8c8-63aab02503a2, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=127d727a-779a-47e1-8f9b-6a98d4e70629, consistentId=127d727a-779a-47e1-8f9b-6a98d4e70629, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=f0b0d5e3-4946-4819-b277-9ffd4b2d01df, consistentId=f0b0d5e3-4946-4819-b277-9ffd4b2d01df, isClient=true, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=65622274-1387-415c-aed1-8a7ea2d0c09c, consistentId=59d50ff1-b50d-4491-88da-e03b485598bf, isClient=false, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=afa9f790-0fcd-4c1d-86bd-7e4c99731e44, consistentId=ef018f5d-0e4c-444e-ad1e-3cef1d758db7, isClient=false, ver=2.13.0#20220420-sha1:551f6ece], TcpDiscoveryNode [id=24971b88-cfda-4953-b83b-4c077b567652, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, isClient=false, ver=2.13.0#20220420-sha1:551f6ece]]][16:06:11,698][INFO][disco-event-worker-#62][GridDiscoveryManager] ^-- Baseline [id=14, size=3, online=3, offline=0][16:06:11,698][INFO][exchange-worker-#65][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], crd=true, evt=NODE_JOINED, evtNode=24971b88-cfda-4953-b83b-4c077b567652, customEvt=null, allowMerge=true, exchangeFreeSwitch=false][16:06:11,701][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], waitTime=0ms, futInfo=NA, mode=DISTRIBUTED][16:06:11,703][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ServerLatch [permits=0, pendingAcks=HashSet [], super=CompletableLatch [id=CompletableLatchUid [id=exchange, topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0]]]][16:06:11,704][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], waitTime=0ms, futInfo=NA, mode=LOCAL][16:06:11,711][INFO][exchange-worker-#65][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], crd=true][16:06:11,746][INFO][sys-#135][GridDhtPartitionsExchangeFuture] Coordinator received single message [ver=AffinityTopologyVersion [topVer=62, minorTopVer=0], node=afa9f790-0fcd-4c1d-86bd-7e4c99731e44, remainingNodes=1, allReceived=false][16:06:12,564][INFO][grid-nio-worker-tcp-comm-3-#26%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:32535][16:06:12,602][INFO][sys-#126][GridDhtPartitionsExchangeFuture] Coordinator received single message [ver=AffinityTopologyVersion [topVer=62, minorTopVer=0], node=24971b88-cfda-4953-b83b-4c077b567652, allReceived=true][16:06:12,602][INFO][sys-#126][GridDhtPartitionsExchangeFuture] Coordinator received all messages, try merge [ver=AffinityTopologyVersion [topVer=62, minorTopVer=0]][16:06:12,602][INFO][sys-#126][GridDhtPartitionsExchangeFuture] finishExchangeOnCoordinator [topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=62, minorTopVer=0]][16:06:12,664][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Partitions have been scheduled for rebalancing due to outdated update counter [grp=SQL_PUBLIC_RELATIONAL_META, readyTopVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], nodeId=24971b88-cfda-4953-b83b-4c077b567652, partsFull=[180], partsHistorical=[]][16:06:12,677][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Partitions have been scheduled for rebalancing due to outdated update counter [grp=SQL_PUBLIC_B2BICLUSTERSTATUS, readyTopVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], nodeId=24971b88-cfda-4953-b83b-4c077b567652, partsFull=[268], partsHistorical=[]][16:06:12,678][WARNING][sys-#128][GridDhtPartitionTopologyImpl] Partitions have been scheduled for rebalancing due to outdated update counter [grp=CacheAs2ReceiptsCorrelation, readyTopVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], nodeId=24971b88-cfda-4953-b83b-4c077b567652, partsFull=[368], partsHistorical=[]][16:06:12,699][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Partitions have been scheduled for rebalancing due to outdated update counter [grp=table, readyTopVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], nodeId=24971b88-cfda-4953-b83b-4c077b567652, partsFull=[43, 266, 307, 703, 744, 931], partsHistorical=[]][16:06:12,702][WARNING][sys-#130][GridDhtPartitionTopologyImpl] Partitions have been scheduled for rebalancing due to outdated update counter [grp=uniqueid, readyTopVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], nodeId=24971b88-cfda-4953-b83b-4c077b567652, partsFull=[172], partsHistorical=[]][16:06:12,703][INFO][sys-#126][GridDhtPartitionsExchangeFuture] Partitions weren't present in any history reservation: [[grp=SQL_PUBLIC_RELATIONAL_META part=[[180]]], [grp=CacheAs2ReceiptsCorrelation part=[[368]]], [grp=SQL_PUBLIC_B2BICLUSTERSTATUS part=[[268]]], [grp=table part=[[43, 266, 307, 703, 744, 931]]], [grp=uniqueid part=[[172]]]][16:06:12,744][INFO][sys-#126][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], err=null, rebalanced=false, wasRebalanced=true][16:06:12,762][WARNING][sys-#126][BaselineTopologyUpdater] Baseline auto-adjust will be executed in '30000' ms[16:06:12,775][INFO][sys-#126][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=65622274-1387-415c-aed1-8a7ea2d0c09c, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode [id=24971b88-cfda-4953-b83b-4c077b567652, consistentId=f78194bf-56e2-4ba2-96ad-3a567b967152, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, serverign1.domain.name.removed.net/10.x.x.x:49500], discPort=49500, order=62, intOrder=44, lastExchangeTime=1665583571422, loc=false, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], rebalanced=false, done=true, newCrdFut=null], topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0]][16:06:12,775][INFO][sys-#126][GridDhtPartitionsExchangeFuture] Exchange timings [startVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], stage="Waiting in exchange queue" (0 ms), stage="Exchange parameters initialization" (0 ms), stage="Determine exchange type" (0 ms), stage="Preloading notification" (0 ms), stage="Wait partitions release [latch=exchange]" (2 ms), stage="Wait partitions release latch [latch=exchange]" (2 ms), stage="Wait partitions release [latch=exchange]" (0 ms), stage="After states restored callback" (0 ms), stage="WAL history reservation" (5 ms), stage="Waiting for all single messages" (892 ms), stage="Exchanges merge" (0 ms), stage="Affinity recalculation (crd)" (39 ms), stage="Collect update counters and create affinity messages" (13 ms), stage="Assign partitions states" (48 ms), stage="Validate partitions states" (12 ms), stage="Apply update counters" (7 ms), stage="Full message preparing" (17 ms), stage="Full message sending" (2 ms), stage="Exchange done" (31 ms), stage="Total time" (1070 ms), Discovery lag=73 ms, Latest started node id=24971b88-cfda-4953-b83b-4c077b567652][16:06:12,776][INFO][sys-#126][GridDhtPartitionsExchangeFuture] Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], stage="Affinity initialization (node join) [grp=B2BiClusterStatusCache, crd=true]" (18 ms) (parent=Affinity recalculation (crd)), stage="Affinity initialization (node join) [grp=ignite-sys-cache, crd=true]" (17 ms) (parent=Affinity recalculation (crd)), stage="Affinity initialization (node join) [grp=SQL_PUBLIC_RELATIONAL_DATA, crd=true]" (15 ms) (parent=Affinity recalculation (crd))][16:06:12,787][INFO][exchange-worker-#65][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=62, minorTopVer=0], force=false, evt=NODE_JOINED, node=24971b88-cfda-4953-b83b-4c077b567652][16:06:13,519][INFO][rebalance-striped-#230][GridDhtPartitionSupplier] Finished supplying rebalancing [grp=CacheAs2ReceiptsCorrelation, demander=24971b88-cfda-4953-b83b-4c077b567652, topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0]][16:06:13,828][INFO][rebalance-striped-#230][GridDhtPartitionSupplier] Finished supplying rebalancing [grp=SQL_PUBLIC_B2BICLUSTERSTATUS, demander=24971b88-cfda-4953-b83b-4c077b567652, topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0]][16:06:13,918][INFO][rebalance-striped-#230][GridDhtPartitionSupplier] Finished supplying rebalancing [grp=SQL_PUBLIC_RELATIONAL_META, demander=24971b88-cfda-4953-b83b-4c077b567652, topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0]][16:06:14,043][INFO][rebalance-striped-#230][GridDhtPartitionSupplier] Finished supplying rebalancing [grp=table, demander=24971b88-cfda-4953-b83b-4c077b567652, topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0]][16:06:14,211][INFO][rebalance-striped-#230][GridDhtPartitionSupplier] Finished supplying rebalancing [grp=uniqueid, demander=24971b88-cfda-4953-b83b-4c077b567652, topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0]][16:06:14,227][INFO][exchange-worker-#65][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=62, minorTopVer=1], crd=true, evt=DISCOVERY_CUSTOM_EVT, evtNode=65622274-1387-415c-aed1-8a7ea2d0c09c, customEvt=CacheAffinityChangeMessage [id=6448d7cc381-ca4b2e30-289f-42c4-bbef-f2e6bd86115a, topVer=AffinityTopologyVersion [topVer=62, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], allowMerge=false, exchangeFreeSwitch=false][16:06:14,614][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=62, minorTopVer=1], waitTime=385ms, futInfo=NA, mode=DISTRIBUTED][16:06:14,615][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ServerLatch [permits=0, pendingAcks=HashSet [], super=CompletableLatch [id=CompletableLatchUid [id=exchange, topVer=AffinityTopologyVersion [topVer=62, minorTopVer=1]]]][16:06:14,615][INFO][exchange-worker-#65][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=62, minorTopVer=1], waitTime=0ms, futInfo=NA, mode=LOCAL][16:06:14,629][INFO][exchange-worker-#65][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=62, minorTopVer=1], crd=true][16:06:14,660][INFO][sys-#132][GridDhtPartitionsExchangeFuture] Coordinator received single message [ver=AffinityTopologyVersion [topVer=62, minorTopVer=1], node=afa9f790-0fcd-4c1d-86bd-7e4c99731e44, remainingNodes=1, allReceived=false][16:06:14,679][INFO][sys-#131][GridDhtPartitionsExchangeFuture] Coordinator received single message [ver=AffinityTopologyVersion [topVer=62, minorTopVer=1], node=24971b88-cfda-4953-b83b-4c077b567652, allReceived=true][16:06:14,679][INFO][sys-#131][GridDhtPartitionsExchangeFuture] finishExchangeOnCoordinator [topVer=AffinityTopologyVersion [topVer=62, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=62, minorTopVer=1]][16:06:14,716][INFO][sys-#131][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=62, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=62, minorTopVer=1], err=null, rebalanced=true, wasRebalanced=false][16:06:14,725][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Stale update for single partition map update (will ignore) [nodeId=24971b88-cfda-4953-b83b-4c077b567652, grp=CacheAs2ReceiptsCorrelation, exchId=null, curMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=1], updateSeq=6, size=1024], newMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=0], updateSeq=5, size=1024]][16:06:14,726][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Stale update for single partition map update (will ignore) [nodeId=24971b88-cfda-4953-b83b-4c077b567652, grp=SQL_PUBLIC_RELATIONAL_META, exchId=null, curMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=1], updateSeq=6, size=512], newMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=0], updateSeq=5, size=512]][16:06:14,727][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Stale update for single partition map update (will ignore) [nodeId=24971b88-cfda-4953-b83b-4c077b567652, grp=B2BiClusterStatusCache, exchId=null, curMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=1], updateSeq=5, size=1024], newMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=4, size=1024]][16:06:14,727][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Stale update for single partition map update (will ignore) [nodeId=24971b88-cfda-4953-b83b-4c077b567652, grp=timers, exchId=null, curMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=1], updateSeq=5, size=1024], newMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=4, size=1024]][16:06:14,727][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Stale update for single partition map update (will ignore) [nodeId=24971b88-cfda-4953-b83b-4c077b567652, grp=SQL_PUBLIC_RELATIONAL_CHANGES, exchId=null, curMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=1], updateSeq=5, size=512], newMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=4, size=512]][16:06:14,727][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Stale update for single partition map update (will ignore) [nodeId=24971b88-cfda-4953-b83b-4c077b567652, grp=SQL_PUBLIC_B2BICLUSTERSTATUS, exchId=null, curMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=1], updateSeq=6, size=512], newMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=0], updateSeq=5, size=512]][16:06:14,728][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Stale update for single partition map update (will ignore) [nodeId=24971b88-cfda-4953-b83b-4c077b567652, grp=SQL_PUBLIC_RELATIONAL_DATA, exchId=null, curMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=1], updateSeq=5, size=512], newMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=4, size=512]][16:06:14,728][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Stale update for single partition map update (will ignore) [nodeId=24971b88-cfda-4953-b83b-4c077b567652, grp=CacheOftpReceiptsCorrelation, exchId=null, curMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=1], updateSeq=5, size=1024], newMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=4, size=1024]][16:06:14,729][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Stale update for single partition map update (will ignore) [nodeId=24971b88-cfda-4953-b83b-4c077b567652, grp=SQL_PUBLIC_TABLEINFO, exchId=null, curMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=1], updateSeq=5, size=512], newMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=4, size=512]][16:06:14,729][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Stale update for single partition map update (will ignore) [nodeId=24971b88-cfda-4953-b83b-4c077b567652, grp=SQL_PUBLIC_TIMERS, exchId=null, curMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=1], updateSeq=5, size=512], newMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=4, size=512]][16:06:14,729][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Stale update for single partition map update (will ignore) [nodeId=24971b88-cfda-4953-b83b-4c077b567652, grp=ignite-sys-cache, exchId=null, curMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=1], updateSeq=5, size=100], newMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=4, size=100]][16:06:14,730][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Stale update for single partition map update (will ignore) [nodeId=24971b88-cfda-4953-b83b-4c077b567652, grp=CacheRosettaNet2MessageCorrelation, exchId=null, curMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=1], updateSeq=5, size=1024], newMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=4, size=1024]][16:06:14,730][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Stale update for single partition map update (will ignore) [nodeId=24971b88-cfda-4953-b83b-4c077b567652, grp=default-ds-group, exchId=null, curMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=1], updateSeq=5, size=669], newMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=-1, minorTopVer=0], updateSeq=4, size=669]][16:06:14,731][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Stale update for single partition map update (will ignore) [nodeId=24971b88-cfda-4953-b83b-4c077b567652, grp=table, exchId=null, curMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=1], updateSeq=16, size=1024], newMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=0], updateSeq=15, size=1024]][16:06:14,732][WARNING][sys-#131][GridDhtPartitionTopologyImpl] Stale update for single partition map update (will ignore) [nodeId=24971b88-cfda-4953-b83b-4c077b567652, grp=uniqueid, exchId=null, curMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=1], updateSeq=6, size=1024], newMap=GridDhtPartitionMap [moving=0, top=AffinityTopologyVersion [topVer=62, minorTopVer=0], updateSeq=5, size=1024]][16:06:14,732][INFO][sys-#131][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=65622274-1387-415c-aed1-8a7ea2d0c09c, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=62, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode [id=65622274-1387-415c-aed1-8a7ea2d0c09c, consistentId=59d50ff1-b50d-4491-88da-e03b485598bf, addrs=ArrayList [10.x.x.x, 127.0.0.1], sockAddrs=HashSet [serverign3.domain.name.removed.net/10.x.x.x:49500, /127.0.0.1:49500], discPort=49500, order=58, intOrder=42, lastExchangeTime=1665583574258, loc=true, ver=2.13.0#20220420-sha1:551f6ece, isClient=false], rebalanced=true, done=true, newCrdFut=null], topVer=AffinityTopologyVersion [topVer=62, minorTopVer=1]][16:06:14,732][INFO][sys-#131][GridDhtPartitionsExchangeFuture] Exchange timings [startVer=AffinityTopologyVersion [topVer=62, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=62, minorTopVer=1], stage="Waiting in exchange queue" (0 ms), stage="Exchange parameters initialization" (0 ms), stage="Determine exchange type" (1 ms), stage="Preloading notification" (0 ms), stage="Wait partitions release [latch=exchange]" (385 ms), stage="Wait partitions release latch [latch=exchange]" (0 ms), stage="Wait partitions release [latch=exchange]" (0 ms), stage="After states restored callback" (9 ms), stage="WAL history reservation" (4 ms), stage="Waiting for all single messages" (50 ms), stage="Affinity recalculation (crd)" (0 ms), stage="Collect update counters and create affinity messages" (2 ms), stage="Validate partitions states" (15 ms), stage="Apply update counters" (7 ms), stage="Full message preparing" (11 ms), stage="Full message sending" (0 ms), stage="Exchange done" (15 ms), stage="Total time" (499 ms), Discovery lag=12 ms, Latest started node id=24971b88-cfda-4953-b83b-4c077b567652][16:06:14,732][INFO][sys-#131][GridDhtPartitionsExchangeFuture] Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=62, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=62, minorTopVer=1], stage="Affinity change by custom message [grp=uniqueid]" (0 ms) (parent=Determine exchange type), stage="Affinity change by custom message [grp=timers]" (0 ms) (parent=Determine exchange type), stage="Affinity change by custom message [grp=table]" (0 ms) (parent=Determine exchange type)][16:06:14,735][INFO][exchange-worker-#65][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=62, minorTopVer=1], force=false, evt=DISCOVERY_CUSTOM_EVT, node=65622274-1387-415c-aed1-8a7ea2d0c09c][16:06:17,356][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,357][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,358][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,359][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,361][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,362][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,363][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,363][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,364][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,365][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,366][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,367][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,368][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,369][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,370][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,371][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,372][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,373][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,374][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,375][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,376][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,377][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,378][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,379][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,380][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,381][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,382][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,382][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,383][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,384][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,385][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,386][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,387][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,388][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,389][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,390][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,391][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,392][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,392][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,392][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,393][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,393][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,393][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,394][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,394][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,394][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,394][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,395][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,395][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,395][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,395][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,396][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,396][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,396][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,397][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,397][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:17,397][WARNING][tcp-disco-ip-finder-cleaner-#6-#61][TcpDiscoverySpi] Failed to ping node [nodeId=null]. Reached the timeout 60000ms. Cause: Connection refused (Connection refused)[16:06:19,167][INFO][grid-timeout-worker-#22][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=65622274, uptime=00:08:00.030] ^-- Cluster [hosts=8, CPUs=144, servers=3, clients=23, topVer=62, minorTopVer=1] ^-- Network [addrs=[10.x.x.x, 127.0.0.1], discoPort=49500, commPort=49100] ^-- CPU [CPUs=4, curLoad=4.5%, avgLoad=4.67%, GC=0%] ^-- Heap [used=2050MB, free=66.63%, comm=6144MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=2, qSize=0] ^-- System thread pool [active=0, idle=8, qSize=0] ^-- Striped thread pool [active=0, idle=8, qSize=0][16:06:39,154][INFO][grid-nio-worker-tcp-comm-0-#23%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:59508][16:06:39,641][INFO][tcp-comm-worker-#1-#28][TcpCommunicationSpi] TCP client created [client=null, node addrs=[servercfg1.domain.name.removed.net/10.x.x.x:49102, /127.0.0.1:49102, 0:0:0:0:0:0:0:1%lo:49102], duration=506ms][16:06:39,653][INFO][grid-nio-worker-tcp-comm-1-#24%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.x.x.x:49100, rmtAddr=/10.x.x.x:59520][16:06:42,762][INFO][grid-timeout-worker-#22][BaselineAutoAdjustScheduler] Baseline auto-adjust will be executed right now.
Comments