hazelcast / hazelcast

Hazelcast is a unified real-time data platform combining stream processing with a fast data store, allowing customers to act instantly on data-in-motion for real-time insights.
https://www.hazelcast.com
Other
6.12k stars 1.84k forks source link

ClientPNCounterTest.testClusterRestart [API-1654] #22474

Closed frant-hartm closed 1 year ago

frant-hartm commented 2 years ago

PR to 5.2.z (commit ae1418f)

Failed on Jenkins (https://jenkins.hazelcast.com/job/Hazelcast-pr-builder/13681/testReport/junit/com.hazelcast.client.pncounter/ClientPNCounterTest/testClusterRestart/)

https://github.com/hazelcast/hazelcast/pull/22470#issuecomment-1277490142

Stacktrace: ``` java.lang.Exception: Unexpected exception, expected but was at org.junit.internal.runners.statements.ExpectException.evaluate(ExpectException.java:30) at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:115) at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:107) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.lang.Thread.run(Thread.java:750) Caused by: com.hazelcast.spi.exception.TargetNotMemberException: Member with uuid(638680be-633c-43e5-bdcd-2782483d2914) is not in member list at com.hazelcast.client.impl.protocol.task.AbstractTargetMessageTask.processInternal(AbstractTargetMessageTask.java:45) at com.hazelcast.client.impl.protocol.task.AbstractAsyncMessageTask.processMessage(AbstractAsyncMessageTask.java:71) at com.hazelcast.client.impl.protocol.task.AbstractMessageTask.initializeAndProcessMessage(AbstractMessageTask.java:153) at com.hazelcast.client.impl.protocol.task.AbstractMessageTask.run(AbstractMessageTask.java:116) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:750) at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) at ------ submitted from ------.() at com.hazelcast.internal.util.ExceptionUtil.cloneExceptionWithFixedAsyncStackTrace(ExceptionUtil.java:348) at com.hazelcast.spi.impl.operationservice.impl.InvocationFuture.returnOrThrowWithGetConventions(InvocationFuture.java:112) at com.hazelcast.client.impl.spi.impl.ClientInvocationFuture.resolveAndThrowIfException(ClientInvocationFuture.java:95) at com.hazelcast.client.impl.spi.impl.ClientInvocationFuture.resolveAndThrowIfException(ClientInvocationFuture.java:40) at com.hazelcast.spi.impl.AbstractInvocationFuture.get(AbstractInvocationFuture.java:617) at com.hazelcast.client.impl.spi.ClientProxy.invokeOnMember(ClientProxy.java:197) at com.hazelcast.client.impl.proxy.ClientPNCounterProxy.invokeAddInternal(ClientPNCounterProxy.java:258) at com.hazelcast.client.impl.proxy.ClientPNCounterProxy.incrementAndGet(ClientPNCounterProxy.java:169) at com.hazelcast.client.pncounter.ClientPNCounterTest.testClusterRestart(ClientPNCounterTest.java:54) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.internal.runners.statements.ExpectException.evaluate(ExpectException.java:19) ... 4 more ```
Standard output: ``` Started Running Test: testClusterRestart 11:10:20,554 INFO |testClusterRestart| - [MetricsConfigHelper] testClusterRestart - [LOCAL] [dev] [5.2.1-SNAPSHOT] Overridden metrics configuration with system property 'hazelcast.metrics.collection.frequency'='1' -> 'MetricsConfig.collectionFrequencySeconds'='1' 11:10:20,555 INFO |testClusterRestart| - [logo] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] + + o o o o---o o----o o o---o o o----o o--o--o + + + + | | / \ / | | / / \ | | + + + + + o----o o o o o----o | o o o o----o | + + + + | | / \ / | | \ / \ | | + + o o o o o---o o----o o----o o---o o o o----o o 11:10:20,555 INFO |testClusterRestart| - [system] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Copyright (c) 2008-2022, Hazelcast, Inc. All Rights Reserved. 11:10:20,555 INFO |testClusterRestart| - [system] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Hazelcast Platform 5.2.1-SNAPSHOT (20221013 - 3b4f02c) starting at [127.0.0.1]:5701 11:10:20,555 INFO |testClusterRestart| - [system] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Cluster name: dev 11:10:20,555 INFO |testClusterRestart| - [system] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Integrity Checker is disabled. Fail-fast on corrupted executables will not be performed. For more information, see the documentation for Integrity Checker. 11:10:20,555 INFO |testClusterRestart| - [system] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Jet is enabled 11:10:20,561 INFO |testClusterRestart| - [MetricsConfigHelper] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Collecting debug metrics and sending to diagnostics is enabled 11:10:20,567 WARN |testClusterRestart| - [CPSubsystem] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] CP Subsystem is not enabled. CP data structures will operate in UNSAFE mode! Please note that UNSAFE mode will not provide strong consistency guarantees. 11:10:20,575 INFO |testClusterRestart| - [JetServiceBackend] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Setting number of cooperative threads and default parallelism to 16 11:10:20,580 INFO |testClusterRestart| - [Diagnostics] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Diagnostics disabled. To enable add -Dhazelcast.diagnostics.enabled=true to the JVM arguments. 11:10:20,580 INFO |testClusterRestart| - [LifecycleService] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] [127.0.0.1]:5701 is STARTING 11:10:20,580 INFO |testClusterRestart| - [ClusterService] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Members {size:1, ver:1} [ Member [127.0.0.1]:5701 - 638680be-633c-43e5-bdcd-2782483d2914 this ] 11:10:20,581 INFO |testClusterRestart| - [JobCoordinationService] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Jet started scanning for jobs 11:10:20,581 DEBUG |testClusterRestart| - [JobCoordinationService] hz.frosty_lumiere.cached.thread-1 - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Not starting jobs because partitions are not yet initialized. 11:10:20,581 INFO |testClusterRestart| - [LifecycleService] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] [127.0.0.1]:5701 is STARTED 11:10:20,600 INFO |testClusterRestart| - [ClientInvocationService] testClusterRestart - hz.client_250 [dev] [5.2.1-SNAPSHOT] Running with 2 response threads, dynamic=true 11:10:20,601 INFO |testClusterRestart| - [LifecycleService] testClusterRestart - hz.client_250 [dev] [5.2.1-SNAPSHOT] HazelcastClient 5.2.1-SNAPSHOT (20221013 - 3b4f02c) is STARTING 11:10:20,601 INFO |testClusterRestart| - [LifecycleService] testClusterRestart - hz.client_250 [dev] [5.2.1-SNAPSHOT] HazelcastClient 5.2.1-SNAPSHOT (20221013 - 3b4f02c) is STARTED 11:10:20,602 INFO |testClusterRestart| - [ClientConnectionManager] testClusterRestart - hz.client_250 [dev] [5.2.1-SNAPSHOT] Trying to connect to cluster: dev 11:10:20,602 INFO |testClusterRestart| - [ClientConnectionManager] testClusterRestart - hz.client_250 [dev] [5.2.1-SNAPSHOT] Trying to connect to [127.0.0.1]:5701 11:10:20,603 DEBUG |testClusterRestart| - [AuthenticationMessageTask] hz.frosty_lumiere.generic-operation.thread-0 - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Processing authentication with clientUuid 2b869442-5823-4a5a-8ee5-292126aac970 and clientName hz.client_250 11:10:20,603 INFO |testClusterRestart| - [AuthenticationMessageTask] hz.frosty_lumiere.generic-operation.thread-0 - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Received auth from MockedNodeConnection{ remoteAddress = [127.0.0.1]:40001, localAddress = [127.0.0.1]:5701, connectionId = 1}, successfully authenticated, clientUuid: 2b869442-5823-4a5a-8ee5-292126aac970, client name: hz.client_250, client version: 5.2.1-SNAPSHOT 11:10:20,603 INFO |testClusterRestart| - [LifecycleService] testClusterRestart - hz.client_250 [dev] [5.2.1-SNAPSHOT] HazelcastClient 5.2.1-SNAPSHOT (20221013 - 3b4f02c) is CLIENT_CONNECTED 11:10:20,603 INFO |testClusterRestart| - [ClientConnectionManager] testClusterRestart - hz.client_250 [dev] [5.2.1-SNAPSHOT] Authenticated with server [127.0.0.1]:5701:638680be-633c-43e5-bdcd-2782483d2914, server version: 5.2.1-SNAPSHOT, local address: /127.0.0.1:40001 11:10:20,603 INFO |testClusterRestart| - [Diagnostics] testClusterRestart - hz.client_250 [dev] [5.2.1-SNAPSHOT] Diagnostics disabled. To enable add -Dhazelcast.diagnostics.enabled=true to the JVM arguments. 11:10:20,603 TRACE |testClusterRestart| - [ClientListenerService] hz.client_250.internal-1 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Register attempt of ClusterViewListenerHandler to MockedClientConnection{localAddress=[127.0.0.1]:40001, super=ClientConnection{alive=true, connectionId=1, channel=null, remoteAddress=[127.0.0.1]:5701, lastReadTime=2022-10-13 11:10:20.603, lastWriteTime=2022-10-13 11:10:20.602, closedTime=never, connected server version=null}} 11:10:20,604 TRACE |testClusterRestart| - [ClientListenerService] ForkJoinPool.commonPool-worker-11 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Registered ClusterViewListenerHandler to MockedClientConnection{localAddress=[127.0.0.1]:40001, super=ClientConnection{alive=true, connectionId=1, channel=null, remoteAddress=[127.0.0.1]:5701, lastReadTime=2022-10-13 11:10:20.604, lastWriteTime=2022-10-13 11:10:20.603, closedTime=never, connected server version=null}} 11:10:20,604 INFO |testClusterRestart| - [ClientClusterService] hz.client_250.event-1715 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Members [1] { Member [127.0.0.1]:5701 - 638680be-633c-43e5-bdcd-2782483d2914 } 11:10:20,605 TRACE |testClusterRestart| - [ClientListenerService] hz.client_250.eventRegistration- - hz.client_250 [dev] [5.2.1-SNAPSHOT] Register attempt of ClientListenerRegistration{codec=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$1@789e8fa0, handler=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$BackupEventHandler@446625f3} to MockedClientConnection{localAddress=[127.0.0.1]:40001, super=ClientConnection{alive=true, connectionId=1, channel=null, remoteAddress=[127.0.0.1]:5701, lastReadTime=2022-10-13 11:10:20.604, lastWriteTime=2022-10-13 11:10:20.603, closedTime=never, connected server version=null}} 11:10:20,605 TRACE |testClusterRestart| - [ClientListenerService] hz.client_250.eventRegistration- - hz.client_250 [dev] [5.2.1-SNAPSHOT] Registered ClientListenerRegistration{codec=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$1@789e8fa0, handler=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$BackupEventHandler@446625f3} to MockedClientConnection{localAddress=[127.0.0.1]:40001, super=ClientConnection{alive=true, connectionId=1, channel=null, remoteAddress=[127.0.0.1]:5701, lastReadTime=2022-10-13 11:10:20.605, lastWriteTime=2022-10-13 11:10:20.605, closedTime=never, connected server version=null}} 11:10:20,613 INFO |testClusterRestart| - [LifecycleService] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] [127.0.0.1]:5701 is SHUTTING_DOWN 11:10:20,613 DEBUG |testClusterRestart| - [JobCoordinationService] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Added a shutting-down member: 638680be-633c-43e5-bdcd-2782483d2914 11:10:20,614 WARN |testClusterRestart| - [CRDTReplicationMigrationService] hz.frosty_lumiere.cached.thread-1 - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Failed replication of CRDTs for hz:impl:PNCounterService. CRDT state may be lost. 11:10:20,614 INFO |testClusterRestart| - [Node] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Shutting down connection manager... 11:10:20,614 INFO |testClusterRestart| - [MockServer] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Removed connection to endpoint: [address=[127.0.0.1]:40001, uuid=2b869442-5823-4a5a-8ee5-292126aac970], connection: MockedNodeConnection{ remoteAddress = [127.0.0.1]:40001, localAddress = [127.0.0.1]:5701, connectionId = 1} 11:10:20,615 INFO |testClusterRestart| - [Node] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Shutting down node engine... 11:10:20,615 WARN |testClusterRestart| - [TcpClientConnection] pool-538-thread-1 - hz.client_250 [dev] [5.2.1-SNAPSHOT] MockedClientConnection{localAddress=[127.0.0.1]:40001, super=ClientConnection{alive=false, connectionId=1, channel=null, remoteAddress=[127.0.0.1]:5701, lastReadTime=2022-10-13 11:10:20.613, lastWriteTime=2022-10-13 11:10:20.612, closedTime=2022-10-13 11:10:20.615, connected server version=null}} closed. Reason: com.hazelcast.spi.exception.TargetDisconnectedException[Mocked Remote socket closed] com.hazelcast.spi.exception.TargetDisconnectedException: Mocked Remote socket closed at com.hazelcast.client.test.TestClientRegistry$MockedTcpClientConnection$4.run(TestClientRegistry.java:332) ~[test-classes/:?] at com.hazelcast.client.test.TwoWayBlockableExecutor$BlockableRunnable.run(TwoWayBlockableExecutor.java:98) ~[test-classes/:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_341] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_341] at java.lang.Thread.run(Thread.java:750) ~[?:1.8.0_341] 11:10:20,615 INFO |testClusterRestart| - [ClientConnectionManager] pool-538-thread-1 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Removed connection to endpoint: [127.0.0.1]:5701:638680be-633c-43e5-bdcd-2782483d2914, connection: MockedClientConnection{localAddress=[127.0.0.1]:40001, super=ClientConnection{alive=false, connectionId=1, channel=null, remoteAddress=[127.0.0.1]:5701, lastReadTime=2022-10-13 11:10:20.613, lastWriteTime=2022-10-13 11:10:20.612, closedTime=2022-10-13 11:10:20.615, connected server version=null}} 11:10:20,615 INFO |testClusterRestart| - [LifecycleService] pool-538-thread-1 - hz.client_250 [dev] [5.2.1-SNAPSHOT] HazelcastClient 5.2.1-SNAPSHOT (20221013 - 3b4f02c) is CLIENT_DISCONNECTED 11:10:20,615 INFO |testClusterRestart| - [ClientConnectionManager] hz.client_250.internal-1 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Trying to connect to cluster: dev 11:10:20,615 INFO |testClusterRestart| - [ClientConnectionManager] hz.client_250.internal-1 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Trying to connect to Member [127.0.0.1]:5701 - 638680be-633c-43e5-bdcd-2782483d2914 11:10:20,615 WARN |testClusterRestart| - [ClientConnectionManager] hz.client_250.internal-1 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Exception during initial connection to Member [127.0.0.1]:5701 - 638680be-633c-43e5-bdcd-2782483d2914: com.hazelcast.core.HazelcastException: java.io.IOException: Can not connect to [127.0.0.1]:5701: instance does not exist 11:10:20,615 WARN |testClusterRestart| - [ClientConnectionManager] hz.client_250.internal-1 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Unable to get live cluster connection, retry in 1000 ms, attempt: 1, cluster connect timeout: INFINITE, max backoff: 30000 ms 11:10:20,619 INFO |testClusterRestart| - [NodeExtension] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Destroying node NodeExtension. 11:10:20,619 INFO |testClusterRestart| - [Node] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Hazelcast Shutdown is completed in 6 ms. 11:10:20,619 INFO |testClusterRestart| - [LifecycleService] testClusterRestart - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] [127.0.0.1]:5701 is SHUTDOWN 11:10:20,638 INFO |testClusterRestart| - [MetricsConfigHelper] testClusterRestart - [LOCAL] [dev] [5.2.1-SNAPSHOT] Overridden metrics configuration with system property 'hazelcast.metrics.collection.frequency'='1' -> 'MetricsConfig.collectionFrequencySeconds'='1' 11:10:20,639 INFO |testClusterRestart| - [logo] testClusterRestart - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] + + o o o o---o o----o o o---o o o----o o--o--o + + + + | | / \ / | | / / \ | | + + + + + o----o o o o o----o | o o o o----o | + + + + | | / \ / | | \ / \ | | + + o o o o o---o o----o o----o o---o o o o----o o 11:10:20,639 INFO |testClusterRestart| - [system] testClusterRestart - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Copyright (c) 2008-2022, Hazelcast, Inc. All Rights Reserved. 11:10:20,639 INFO |testClusterRestart| - [system] testClusterRestart - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Hazelcast Platform 5.2.1-SNAPSHOT (20221013 - 3b4f02c) starting at [127.0.0.1]:5702 11:10:20,639 INFO |testClusterRestart| - [system] testClusterRestart - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Cluster name: dev 11:10:20,639 INFO |testClusterRestart| - [system] testClusterRestart - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Integrity Checker is disabled. Fail-fast on corrupted executables will not be performed. For more information, see the documentation for Integrity Checker. 11:10:20,639 INFO |testClusterRestart| - [system] testClusterRestart - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Jet is enabled 11:10:20,644 INFO |testClusterRestart| - [MetricsConfigHelper] testClusterRestart - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Collecting debug metrics and sending to diagnostics is enabled 11:10:20,652 WARN |testClusterRestart| - [CPSubsystem] testClusterRestart - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] CP Subsystem is not enabled. CP data structures will operate in UNSAFE mode! Please note that UNSAFE mode will not provide strong consistency guarantees. 11:10:20,670 INFO |testClusterRestart| - [JetServiceBackend] testClusterRestart - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Setting number of cooperative threads and default parallelism to 16 11:10:20,674 INFO |testClusterRestart| - [Diagnostics] testClusterRestart - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Diagnostics disabled. To enable add -Dhazelcast.diagnostics.enabled=true to the JVM arguments. 11:10:20,675 INFO |testClusterRestart| - [LifecycleService] testClusterRestart - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] [127.0.0.1]:5702 is STARTING 11:10:20,675 INFO |testClusterRestart| - [ClusterService] testClusterRestart - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Members {size:1, ver:1} [ Member [127.0.0.1]:5702 - b395da65-b722-4cf6-bd38-a88ed8e9e606 this ] 11:10:20,675 WARN |testClusterRestart| - [Node] testClusterRestart - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Config seed port is 5701 and cluster size is 1. Some of the ports seem occupied! 11:10:20,675 INFO |testClusterRestart| - [JobCoordinationService] testClusterRestart - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Jet started scanning for jobs 11:10:20,675 DEBUG |testClusterRestart| - [JobCoordinationService] hz.awesome_lumiere.cached.thread-1 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Not starting jobs because partitions are not yet initialized. 11:10:20,677 INFO |testClusterRestart| - [LifecycleService] testClusterRestart - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] [127.0.0.1]:5702 is STARTED 11:10:20,775 DEBUG |testClusterRestart| - [JobCoordinationService] hz.awesome_lumiere.cached.thread-1 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Not starting jobs because partitions are not yet initialized. 11:10:20,876 DEBUG |testClusterRestart| - [JobCoordinationService] hz.awesome_lumiere.cached.thread-1 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Not starting jobs because partitions are not yet initialized. 11:10:20,976 DEBUG |testClusterRestart| - [JobCoordinationService] hz.awesome_lumiere.cached.thread-1 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Not starting jobs because partitions are not yet initialized. 11:10:21,076 DEBUG |testClusterRestart| - [JobCoordinationService] hz.awesome_lumiere.cached.thread-1 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Not starting jobs because partitions are not yet initialized. 11:10:21,176 DEBUG |testClusterRestart| - [JobCoordinationService] hz.awesome_lumiere.cached.thread-2 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Not starting jobs because partitions are not yet initialized. 11:10:21,276 DEBUG |testClusterRestart| - [JobCoordinationService] hz.awesome_lumiere.cached.thread-2 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Not starting jobs because partitions are not yet initialized. 11:10:21,377 DEBUG |testClusterRestart| - [JobCoordinationService] hz.awesome_lumiere.cached.thread-2 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Not starting jobs because partitions are not yet initialized. 11:10:21,508 DEBUG |testClusterRestart| - [JobCoordinationService] hz.awesome_lumiere.cached.thread-2 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Not starting jobs because partitions are not yet initialized. 11:10:21,607 DEBUG |testClusterRestart| - [JobCoordinationService] hz.awesome_lumiere.cached.thread-2 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Not starting jobs because partitions are not yet initialized. 11:10:21,616 INFO |testClusterRestart| - [ClientConnectionManager] hz.client_250.internal-1 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Trying to connect to Member [127.0.0.1]:5701 - 638680be-633c-43e5-bdcd-2782483d2914 11:10:21,617 WARN |testClusterRestart| - [ClientConnectionManager] hz.client_250.internal-1 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Exception during initial connection to Member [127.0.0.1]:5701 - 638680be-633c-43e5-bdcd-2782483d2914: com.hazelcast.core.HazelcastException: java.io.IOException: Can not connect to [127.0.0.1]:5701: instance does not exist 11:10:21,618 INFO |testClusterRestart| - [ClientConnectionManager] hz.client_250.internal-1 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Trying to connect to [127.0.0.1]:5702 11:10:21,628 DEBUG |testClusterRestart| - [AuthenticationMessageTask] hz.awesome_lumiere.priority-generic-operation.thread-0 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Processing authentication with clientUuid 2b869442-5823-4a5a-8ee5-292126aac970 and clientName hz.client_250 11:10:21,632 INFO |testClusterRestart| - [AuthenticationMessageTask] hz.awesome_lumiere.priority-generic-operation.thread-0 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Received auth from MockedNodeConnection{ remoteAddress = [127.0.0.1]:40002, localAddress = [127.0.0.1]:5702, connectionId = 2}, successfully authenticated, clientUuid: 2b869442-5823-4a5a-8ee5-292126aac970, client name: hz.client_250, client version: 5.2.1-SNAPSHOT 11:10:21,659 WARN |testClusterRestart| - [ClientConnectionManager] hz.client_250.internal-1 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Switching from current cluster: a6a36398-09df-489d-b562-7dbe923c6900 to new cluster: 606a0aa0-fe6f-48e4-9672-d2e3961100dd 11:10:21,660 INFO |testClusterRestart| - [HazelcastInstance] hz.client_250.internal-1 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Clearing local state of the client, because of a cluster restart. 11:10:21,668 INFO |testClusterRestart| - [ClientConnectionManager] hz.client_250.internal-1 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Authenticated with server [127.0.0.1]:5702:b395da65-b722-4cf6-bd38-a88ed8e9e606, server version: 5.2.1-SNAPSHOT, local address: /127.0.0.1:40002 11:10:21,669 TRACE |testClusterRestart| - [ClientListenerService] hz.client_250.internal-2 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Register attempt of ClusterViewListenerHandler to MockedClientConnection{localAddress=[127.0.0.1]:40002, super=ClientConnection{alive=true, connectionId=2, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2022-10-13 11:10:21.658, lastWriteTime=2022-10-13 11:10:21.626, closedTime=never, connected server version=null}} 11:10:21,670 TRACE |testClusterRestart| - [ClientListenerService] hz.client_250.eventRegistration- - hz.client_250 [dev] [5.2.1-SNAPSHOT] Register attempt of ClientListenerRegistration{codec=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$1@789e8fa0, handler=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$BackupEventHandler@446625f3} to MockedClientConnection{localAddress=[127.0.0.1]:40002, super=ClientConnection{alive=true, connectionId=2, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2022-10-13 11:10:21.658, lastWriteTime=2022-10-13 11:10:21.670, closedTime=never, connected server version=null}} 11:10:21,671 INFO |testClusterRestart| - [LifecycleService] hz.client_250.internal-4 - hz.client_250 [dev] [5.2.1-SNAPSHOT] HazelcastClient 5.2.1-SNAPSHOT (20221013 - 3b4f02c) is CLIENT_CONNECTED 11:10:21,703 TRACE |testClusterRestart| - [ClientListenerService] hz.client_250.eventRegistration- - hz.client_250 [dev] [5.2.1-SNAPSHOT] Registered ClientListenerRegistration{codec=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$1@789e8fa0, handler=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$BackupEventHandler@446625f3} to MockedClientConnection{localAddress=[127.0.0.1]:40002, super=ClientConnection{alive=true, connectionId=2, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2022-10-13 11:10:21.703, lastWriteTime=2022-10-13 11:10:21.703, closedTime=never, connected server version=null}} 11:10:21,712 DEBUG |testClusterRestart| - [JobCoordinationService] hz.awesome_lumiere.cached.thread-6 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Not starting jobs because partitions are not yet initialized. 11:10:21,717 TRACE |testClusterRestart| - [ClientListenerService] ForkJoinPool.commonPool-worker-11 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Registered ClusterViewListenerHandler to MockedClientConnection{localAddress=[127.0.0.1]:40002, super=ClientConnection{alive=true, connectionId=2, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2022-10-13 11:10:21.716, lastWriteTime=2022-10-13 11:10:21.703, closedTime=never, connected server version=null}} 11:10:21,781 INFO |testClusterRestart| - [ClientClusterService] hz.client_250.event-1713 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Members [1] { Member [127.0.0.1]:5702 - b395da65-b722-4cf6-bd38-a88ed8e9e606 } 11:10:21,788 INFO |testClusterRestart| - [LifecycleService] Thread-4050 - hz.client_250 [dev] [5.2.1-SNAPSHOT] HazelcastClient 5.2.1-SNAPSHOT (20221013 - 3b4f02c) is SHUTTING_DOWN 11:10:21,789 INFO |testClusterRestart| - [ClientConnectionManager] Thread-4050 - hz.client_250 [dev] [5.2.1-SNAPSHOT] Removed connection to endpoint: [127.0.0.1]:5702:b395da65-b722-4cf6-bd38-a88ed8e9e606, connection: MockedClientConnection{localAddress=[127.0.0.1]:40002, super=ClientConnection{alive=false, connectionId=2, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2022-10-13 11:10:21.781, lastWriteTime=2022-10-13 11:10:21.781, closedTime=2022-10-13 11:10:21.789, connected server version=null}} 11:10:21,789 INFO |testClusterRestart| - [LifecycleService] Thread-4050 - hz.client_250 [dev] [5.2.1-SNAPSHOT] HazelcastClient 5.2.1-SNAPSHOT (20221013 - 3b4f02c) is CLIENT_DISCONNECTED 11:10:21,789 INFO |testClusterRestart| - [MockServer] pool-541-thread-1 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Removed connection to endpoint: [address=[127.0.0.1]:40002, uuid=2b869442-5823-4a5a-8ee5-292126aac970], connection: MockedNodeConnection{ remoteAddress = [127.0.0.1]:40002, localAddress = [127.0.0.1]:5702, connectionId = 2} 11:10:21,789 INFO |testClusterRestart| - [ClientEndpointManager] hz.awesome_lumiere.event-1721 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Destroying ClientEndpoint{connection=MockedNodeConnection{ remoteAddress = [127.0.0.1]:40002, localAddress = [127.0.0.1]:5702, connectionId = 2}, clientUuid=2b869442-5823-4a5a-8ee5-292126aac970, clientName=hz.client_250, authenticated=true, clientVersion=5.2.1-SNAPSHOT, creationTime=1665659421627, latest clientAttributes=lastStatisticsCollectionTime=1665659421694,enterprise=false,clientType=JVM,clientVersion=5.2.1-SNAPSHOT,clusterConnectionTimestamp=1665659421624,clientAddress=127.0.0.1,clientName=hz.client_250,credentials.principal=null,os.committedVirtualMemorySize=42494627840,os.freePhysicalMemorySize=130105995264,os.freeSwapSpaceSize=7212679168,os.maxFileDescriptorCount=1048576,os.openFileDescriptorCount=307,os.processCpuTime=308610000000,os.systemLoadAverage=81.23,os.totalPhysicalMemorySize=405609000960,os.totalSwapSpaceSize=8589930496,runtime.availableProcessors=16,runtime.freeMemory=1055407808,runtime.maxMemory=1908932608,runtime.totalMemory=1212153856,runtime.uptime=269134,runtime.usedMemory=156746048, labels=[]} 11:10:21,790 INFO |testClusterRestart| - [LifecycleService] Thread-4050 - hz.client_250 [dev] [5.2.1-SNAPSHOT] HazelcastClient 5.2.1-SNAPSHOT (20221013 - 3b4f02c) is SHUTDOWN 11:10:21,790 INFO |testClusterRestart| - [LifecycleService] Thread-4050 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] [127.0.0.1]:5702 is SHUTTING_DOWN 11:10:21,790 WARN |testClusterRestart| - [Node] Thread-4050 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Terminating forcefully... 11:10:21,790 INFO |testClusterRestart| - [Node] Thread-4050 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Shutting down connection manager... 11:10:21,790 INFO |testClusterRestart| - [Node] Thread-4050 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Shutting down node engine... 11:10:21,793 INFO |testClusterRestart| - [NodeExtension] Thread-4050 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Destroying node NodeExtension. 11:10:21,793 INFO |testClusterRestart| - [Node] Thread-4050 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] Hazelcast Shutdown is completed in 3 ms. 11:10:21,793 INFO |testClusterRestart| - [LifecycleService] Thread-4050 - [127.0.0.1]:5702 [dev] [5.2.1-SNAPSHOT] [127.0.0.1]:5702 is SHUTDOWN 11:10:21,793 INFO |testClusterRestart| - [LifecycleService] Thread-4050 - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] [127.0.0.1]:5701 is SHUTTING_DOWN 11:10:21,793 INFO |testClusterRestart| - [Node] Thread-4050 - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] Node is already shutting down... Waiting for shutdown process to complete... 11:10:21,793 INFO |testClusterRestart| - [LifecycleService] Thread-4050 - [127.0.0.1]:5701 [dev] [5.2.1-SNAPSHOT] [127.0.0.1]:5701 is SHUTDOWN ```
github-actions[bot] commented 1 year ago

Internal Jira issue: API-1654