Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

com.hazelcast.client.map.ClientIndexStatsTest.shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT] [HZ-4536] #26269

Open
AleksPeychev opened this issue Feb 28, 2024 · 8 comments
Open

com.hazelcast.client.map.ClientIndexStatsTest.shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT] [HZ-4536] #26269

AleksPeychev opened this issue Feb 28, 2024 · 8 comments
Assignees
@k-jamroz
Labels
Module: Query Source: Internal PR or issue was opened by an employee Team: Core to-jira Type: Test-Failure
Milestone
5.4.z

Comments

@AleksPeychev
Copy link
Contributor

master (commit e15b9a35966518d6cbd00ff78b694183fb30f7f8)
Failed on openjdk-21: https://jenkins.hazelcast.com/view/Official%20Builds/job/Hazelcast-master-ZuluJDK21/5/testReport/junit/com.hazelcast.client.map/ClientIndexStatsTest/

com.hazelcast.client.map.ClientIndexStatsTest.shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]

com.hazelcast.client.map.ClientIndexStatsTest.shouldUseIndexFromClient_whenClusterRestartedInPassiveState[format:BINARY]

Stacktrace: 
java.lang.AssertionError: expected:<100> but was:<0>
	at org.junit.Assert.fail(Assert.java:89)
	at org.junit.Assert.failNotEquals(Assert.java:835)
	at org.junit.Assert.assertEquals(Assert.java:647)
	at org.junit.Assert.assertEquals(Assert.java:633)
	at com.hazelcast.client.map.ClientIndexStatsTest.combineStats(ClientIndexStatsTest.java:252)
	at com.hazelcast.client.map.ClientIndexStatsTest.stats(ClientIndexStatsTest.java:232)
	at com.hazelcast.client.map.ClientIndexStatsTest.testIndexWithoutMapProxy(ClientIndexStatsTest.java:203)
	at com.hazelcast.client.map.ClientIndexStatsTest.shouldUseIndexFromClient_whenClusterRestartedInFrozenState(ClientIndexStatsTest.java:172)
	at java.base/java.lang.reflect.Method.invoke(Method.java:580)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:115)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:107)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
	at java.base/java.lang.Thread.run(Thread.java:1583)
Standard output: 
Finished Running Test: testMemoryCostIsNotDrifting[format:OBJECT] in 0.433 seconds.
23:46:59,438  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [LifecycleService] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] [127.0.0.1]:5702 is SHUTTING_DOWN
23:46:59,438 DEBUG |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [JobCoordinationService] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Added a shutting-down member: f6fac1a0-13c6-4e00-afa1-90cc63401a7e
23:46:59,438 DEBUG |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [JobCoordinationService] hz.ClientIndexStatsTest_vibrant_golick.priority-generic-operation.thread-0 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Added a shutting-down member: f6fac1a0-13c6-4e00-afa1-90cc63401a7e
23:46:59,438 DEBUG |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [JetServiceBackend] ForkJoinPool.commonPool-worker-20 - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] All non-master members were informed about the shutdown of member f6fac1a0-13c6-4e00-afa1-90cc63401a7e
23:46:59,438  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MigrationManager] hz.ClientIndexStatsTest_condescending_golick.cached.thread-3 - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Shutdown request of Member [127.0.0.1]:5702 - f6fac1a0-13c6-4e00-afa1-90cc63401a7e this is handled
23:46:59,441  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MigrationManager] hz.ClientIndexStatsTest_condescending_golick.migration - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Repartitioning cluster data. Migration tasks count: 69
23:46:59,455  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MigrationManager] hz.ClientIndexStatsTest_condescending_golick.migration - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] All migration tasks have been completed. (repartitionTime=Tue Feb 27 23:46:59 GMT 2024, plannedMigrations=69, completedMigrations=69, remainingMigrations=0, totalCompletedMigrations=274, elapsedMigrationOperationTime=13ms, totalElapsedMigrationOperationTime=42ms, elapsedDestinationCommitTime=13ms, totalElapsedDestinationCommitTime=43ms, elapsedMigrationTime=13ms, totalElapsedMigrationTime=43ms)
23:46:59,455  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [Node] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Shutting down connection manager...
23:46:59,455  WARN |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [TestClientRegistry$MockedServerConnection] shouldUseIndexFromClient_whenClusterRestarted - Server connection closed: null
23:46:59,455  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MockServer] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Removed connection to endpoint: [address=[127.0.0.1]:40001, uuid=cdbbe667-852b-4676-b278-a89d41fc58ad], connection: MockedNodeConnection{ remoteAddress = [127.0.0.1]:40001, localAddress = [127.0.0.1]:5702, connectionId = 1}
23:46:59,455  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MockServer] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Removed connection to endpoint: [address=[127.0.0.1]:5702, uuid=f6fac1a0-13c6-4e00-afa1-90cc63401a7e], connection: MockConnection{localEndpoint=[address=[127.0.0.1]:5701, uuid=78a76afd-a095-40ce-a695-4ac1ad369bbe], remoteEndpoint=[address=[127.0.0.1]:5702, uuid=f6fac1a0-13c6-4e00-afa1-90cc63401a7e], alive=false}
23:46:59,455  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MockServer] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Removed connection to endpoint: [address=[127.0.0.1]:5701, uuid=78a76afd-a095-40ce-a695-4ac1ad369bbe], connection: MockConnection{localEndpoint=[address=[127.0.0.1]:5702, uuid=f6fac1a0-13c6-4e00-afa1-90cc63401a7e], remoteEndpoint=[address=[127.0.0.1]:5701, uuid=78a76afd-a095-40ce-a695-4ac1ad369bbe], alive=false}
23:46:59,455  WARN |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MembershipManager] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Member [127.0.0.1]:5702 - f6fac1a0-13c6-4e00-afa1-90cc63401a7e is suspected to be dead for reason: Connection manager is stopped on Member [127.0.0.1]:5702 - f6fac1a0-13c6-4e00-afa1-90cc63401a7e this
23:46:59,455  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MembershipManager] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Starting mastership claim process...
23:46:59,455  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MembershipManager] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Local MembersView{version=4, members=[MemberInfo{address=[127.0.0.1]:5702, uuid=f6fac1a0-13c6-4e00-afa1-90cc63401a7e, cpMemberUUID=null, liteMember=false, memberListJoinVersion=2}, MemberInfo{address=[127.0.0.1]:5701, uuid=78a76afd-a095-40ce-a695-4ac1ad369bbe, cpMemberUUID=null, liteMember=false, memberListJoinVersion=4}]} with suspected members: [Member [127.0.0.1]:5702 - f6fac1a0-13c6-4e00-afa1-90cc63401a7e] and initial addresses to ask: []
23:46:59,455  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [Node] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Shutting down node engine...
23:46:59,455  WARN |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [TcpClientConnection] pool-8085-thread-1 - hz.client_2782 [dev] [5.4.0-SNAPSHOT] MockedClientConnection{localAddress=[127.0.0.1]:40001, super=ClientConnection{alive=false, connectionId=1, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2024-02-27 23:46:59.125, lastWriteTime=2024-02-27 23:46:58.520, closedTime=2024-02-27 23:46:59.455}} 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.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[?:?]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[?:?]
	at java.base/java.lang.Thread.run(Thread.java:1583) [?:?]
23:46:59,456  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClusterService] hz.ClientIndexStatsTest_vibrant_golick.cached.thread-1 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] 

Members {size:1, ver:5} [
	Member [127.0.0.1]:5701 - 78a76afd-a095-40ce-a695-4ac1ad369bbe this
]

23:46:59,456  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MembershipManager] hz.ClientIndexStatsTest_vibrant_golick.cached.thread-1 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Mastership is claimed with: MembersView{version=5, members=[MemberInfo{address=[127.0.0.1]:5701, uuid=78a76afd-a095-40ce-a695-4ac1ad369bbe, cpMemberUUID=null, liteMember=false, memberListJoinVersion=4}]}
23:46:59,456  WARN |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [TwoWayBlockableExecutor] pool-8085-thread-1 - Dropping outgoing runnable since other end closed. Client Closed EOF. MockedClientConnection{localAddress=[127.0.0.1]:40001, super=ClientConnection{alive=false, connectionId=1, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2024-02-27 23:46:59.125, lastWriteTime=2024-02-27 23:46:58.520, closedTime=2024-02-27 23:46:59.455}}
23:46:59,456  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [TransactionManagerService] hz.ClientIndexStatsTest_vibrant_golick.cached.thread-4 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Committing/rolling-back live transactions of [127.0.0.1]:5702, UUID: f6fac1a0-13c6-4e00-afa1-90cc63401a7e
23:46:59,456  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClientConnectionManager] pool-8085-thread-1 - hz.client_2782 [dev] [5.4.0-SNAPSHOT] Removed connection to endpoint: [127.0.0.1]:5702:f6fac1a0-13c6-4e00-afa1-90cc63401a7e, connection: MockedClientConnection{localAddress=[127.0.0.1]:40001, super=ClientConnection{alive=false, connectionId=1, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2024-02-27 23:46:59.125, lastWriteTime=2024-02-27 23:46:58.520, closedTime=2024-02-27 23:46:59.455}}
23:46:59,456  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [LifecycleService] pool-8085-thread-1 - hz.client_2782 [dev] [5.4.0-SNAPSHOT] HazelcastClient 5.4.0-SNAPSHOT (20240227) is CLIENT_DISCONNECTED
23:46:59,456 DEBUG |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [JobCoordinationService] hz.ClientIndexStatsTest_vibrant_golick.cached.thread-4 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Removed a shutting-down member: f6fac1a0-13c6-4e00-afa1-90cc63401a7e, now shuttingDownMembers=[]
23:46:59,456  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClientConnectionManager] hz.client_2782.internal-3 - hz.client_2782 [dev] [5.4.0-SNAPSHOT] Trying to connect to cluster: dev
23:46:59,456  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClientConnectionManager] hz.client_2782.internal-3 - hz.client_2782 [dev] [5.4.0-SNAPSHOT] Trying to connect to Member [127.0.0.1]:5702 - f6fac1a0-13c6-4e00-afa1-90cc63401a7e
23:46:59,456  WARN |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClientConnectionManager] hz.client_2782.internal-3 - hz.client_2782 [dev] [5.4.0-SNAPSHOT] Exception during initial connection to Member [127.0.0.1]:5702 - f6fac1a0-13c6-4e00-afa1-90cc63401a7e: com.hazelcast.core.HazelcastException: java.io.IOException: Can not connect to [127.0.0.1]:5702: instance does not exist
23:46:59,456  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClientConnectionManager] hz.client_2782.internal-3 - hz.client_2782 [dev] [5.4.0-SNAPSHOT] Trying to connect to Member [127.0.0.1]:5701 - 78a76afd-a095-40ce-a695-4ac1ad369bbe
23:46:59,456  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [HazelcastClient] hz.client_2782.internal-3 - Created connection to endpoint: [127.0.0.1]:5701, connection: MockedClientConnection{localAddress=[127.0.0.1]:40003, super=ClientConnection{alive=true, connectionId=3, channel=null, remoteAddress=null, lastReadTime=never, lastWriteTime=never, closedTime=never}}
23:46:59,458 DEBUG |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [AuthenticationMessageTask] hz.ClientIndexStatsTest_vibrant_golick.priority-generic-operation.thread-0 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Processing authentication with clientUuid cdbbe667-852b-4676-b278-a89d41fc58ad and clientName hz.client_2782
23:46:59,458  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [AuthenticationMessageTask] hz.ClientIndexStatsTest_vibrant_golick.priority-generic-operation.thread-0 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Received auth from MockedNodeConnection{ remoteAddress = [127.0.0.1]:40003, localAddress = [127.0.0.1]:5701, connectionId = 3}, successfully authenticated, clientUuid: cdbbe667-852b-4676-b278-a89d41fc58ad, client name: hz.client_2782, client version: 5.4.0-SNAPSHOT
23:46:59,458  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [NodeExtension] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Destroying node NodeExtension.
23:46:59,458  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [Node] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Hazelcast Shutdown is completed in 20 ms.
23:46:59,458  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [LifecycleService] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] [127.0.0.1]:5702 is SHUTDOWN
23:46:59,459  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClientClusterService] hz.client_2782.internal-3 - hz.client_2782 [dev] [5.4.0-SNAPSHOT] 

Members [1] {
	Member [127.0.0.1]:5701 - 78a76afd-a095-40ce-a695-4ac1ad369bbe
}

23:46:59,459  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClientConnectionManager] hz.client_2782.internal-3 - hz.client_2782 [dev] [5.4.0-SNAPSHOT] Authenticated with server [127.0.0.1]:5701:78a76afd-a095-40ce-a695-4ac1ad369bbe, server version: 5.4.0-SNAPSHOT, local address: /127.0.0.1:40003
23:46:59,459 TRACE |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClientListenerService] hz.client_2782.internal-7 - hz.client_2782 [dev] [5.4.0-SNAPSHOT] Register attempt of ClusterViewListenerHandler to MockedClientConnection{localAddress=[127.0.0.1]:40003, super=ClientConnection{alive=true, connectionId=3, channel=null, remoteAddress=[127.0.0.1]:5701, lastReadTime=2024-02-27 23:46:59.459, lastWriteTime=2024-02-27 23:46:59.458, closedTime=never}}
23:46:59,460 TRACE |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClientListenerService] hz.client_2782.eventRegistration- - hz.client_2782 [dev] [5.4.0-SNAPSHOT] Register attempt of ClientListenerRegistration{codec=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$1@61c06379, handler=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$BackupEventHandler@3a620761} to MockedClientConnection{localAddress=[127.0.0.1]:40003, super=ClientConnection{alive=true, connectionId=3, channel=null, remoteAddress=[127.0.0.1]:5701, lastReadTime=2024-02-27 23:46:59.459, lastWriteTime=2024-02-27 23:46:59.459, closedTime=never}}
23:46:59,460  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [LifecycleService] hz.client_2782.internal-2 - hz.client_2782 [dev] [5.4.0-SNAPSHOT] HazelcastClient 5.4.0-SNAPSHOT (20240227) is CLIENT_CONNECTED
23:46:59,460 TRACE |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClientListenerService] ForkJoinPool.commonPool-worker-20 - hz.client_2782 [dev] [5.4.0-SNAPSHOT] Registered ClusterViewListenerHandler to MockedClientConnection{localAddress=[127.0.0.1]:40003, super=ClientConnection{alive=true, connectionId=3, channel=null, remoteAddress=[127.0.0.1]:5701, lastReadTime=2024-02-27 23:46:59.460, lastWriteTime=2024-02-27 23:46:59.460, closedTime=never}}
23:46:59,460 TRACE |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClientListenerService] hz.client_2782.eventRegistration- - hz.client_2782 [dev] [5.4.0-SNAPSHOT] Registered ClientListenerRegistration{codec=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$1@61c06379, handler=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$BackupEventHandler@3a620761} to MockedClientConnection{localAddress=[127.0.0.1]:40003, super=ClientConnection{alive=true, connectionId=3, channel=null, remoteAddress=[127.0.0.1]:5701, lastReadTime=2024-02-27 23:46:59.460, lastWriteTime=2024-02-27 23:46:59.460, closedTime=never}}
23:46:59,521  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LockClusterStateOp] shouldUseIndexFromClient_whenClusterRestartedInFrozenState - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Locking cluster state. Initiator: [127.0.0.1]:5701, lease-time: 60000
23:46:59,522  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LockClusterStateOp] hz.ClientIndexStatsTest_hopeful_golick.priority-generic-operation.thread-0 - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Locking cluster state. Initiator: [127.0.0.1]:5701, lease-time: 60000
23:46:59,522  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LockClusterStateOp] shouldUseIndexFromClient_whenClusterRestartedInFrozenState - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Extending cluster state lock. Initiator: [127.0.0.1]:5701, lease-time: 20000
23:46:59,522  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LockClusterStateOp] hz.ClientIndexStatsTest_hopeful_golick.generic-operation.thread-0 - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Extending cluster state lock. Initiator: [127.0.0.1]:5701, lease-time: 20000
23:46:59,522  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [CommitClusterStateOp] shouldUseIndexFromClient_whenClusterRestartedInFrozenState - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Changing cluster state from ClusterState{state=FROZEN, lock=LockGuard{lockOwner=[127.0.0.1]:5701, lockOwnerId='4b00b8e5-4aa9-4aed-9ed4-6e915603b69d', lockExpiryTime=1709077699522}} to ClusterStateChange{type=class com.hazelcast.cluster.ClusterState, newState=ACTIVE}, initiator: [127.0.0.1]:5701, transient: false
23:46:59,522  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [CommitClusterStateOp] hz.ClientIndexStatsTest_hopeful_golick.priority-generic-operation.thread-0 - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Changing cluster state from ClusterState{state=FROZEN, lock=LockGuard{lockOwner=[127.0.0.1]:5701, lockOwnerId='4b00b8e5-4aa9-4aed-9ed4-6e915603b69d', lockExpiryTime=1709077699522}} to ClusterStateChange{type=class com.hazelcast.cluster.ClusterState, newState=ACTIVE}, initiator: [127.0.0.1]:5701, transient: false
23:47:00,347  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [InternalPartitionService] hz.ClientIndexStatsTest_vibrant_golick.migration - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Fetching partition tables from cluster to determine the most recent one... Local stamp: 2232443833288234855
23:47:00,347  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [InternalPartitionService] hz.ClientIndexStatsTest_vibrant_golick.migration - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Most recent partition table is determined.
23:47:00,347  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [InternalPartitionService] hz.ClientIndexStatsTest_vibrant_golick.migration - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Applying the most recent of partition state...
23:47:00,353  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MigrationManager] hz.ClientIndexStatsTest_vibrant_golick.migration - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Partition balance is ok, no need to repartition.
23:47:00,382  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LifecycleService] Thread-22941 - hz.client_2772 [dev] [5.4.0-SNAPSHOT] HazelcastClient 5.4.0-SNAPSHOT (20240227) is SHUTTING_DOWN
23:47:00,384  WARN |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [TestClientRegistry$MockedServerConnection] pool-8068-thread-1 - Server connection closed: null
23:47:00,384  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [ClientConnectionManager] Thread-22941 - hz.client_2772 [dev] [5.4.0-SNAPSHOT] Removed connection to endpoint: [127.0.0.1]:5701:1a143435-0cd1-4224-9861-b5a7d77952a1, connection: MockedClientConnection{localAddress=[127.0.0.1]:40003, super=ClientConnection{alive=false, connectionId=3, channel=null, remoteAddress=[127.0.0.1]:5701, lastReadTime=2024-02-27 23:46:59.559, lastWriteTime=2024-02-27 23:46:59.559, closedTime=2024-02-27 23:47:00.384}}
23:47:00,384  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [MockServer] pool-8068-thread-1 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Removed connection to endpoint: [address=[127.0.0.1]:40003, uuid=c1cf3e21-bfa6-405d-8e46-66d8494b3f75], connection: MockedNodeConnection{ remoteAddress = [127.0.0.1]:40003, localAddress = [127.0.0.1]:5701, connectionId = 3}
23:47:00,384  WARN |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [TestClientRegistry$MockedServerConnection] pool-8108-thread-1 - Server connection closed: null
23:47:00,384  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [ClientEndpointManager] hz.ClientIndexStatsTest_fervent_shtern.event-67682 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Destroying ClientEndpoint{connection=MockedNodeConnection{ remoteAddress = [127.0.0.1]:40003, localAddress = [127.0.0.1]:5701, connectionId = 3}, clientUuid=c1cf3e21-bfa6-405d-8e46-66d8494b3f75, clientName=hz.client_2772, authenticated=true, clientVersion=5.4.0-SNAPSHOT, creationTime=1709077618039, latest clientAttributes=null, labels=[]}
23:47:00,384  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [MockServer] pool-8108-thread-1 - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Removed connection to endpoint: [address=[127.0.0.1]:40004, uuid=c1cf3e21-bfa6-405d-8e46-66d8494b3f75], connection: MockedNodeConnection{ remoteAddress = [127.0.0.1]:40004, localAddress = [127.0.0.1]:5702, connectionId = 4}
23:47:00,384  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [ClientConnectionManager] Thread-22941 - hz.client_2772 [dev] [5.4.0-SNAPSHOT] Removed connection to endpoint: [127.0.0.1]:5702:5b716714-0160-4fa1-8646-fc6fb898fc4e, connection: MockedClientConnection{localAddress=[127.0.0.1]:40004, super=ClientConnection{alive=false, connectionId=4, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2024-02-27 23:46:59.559, lastWriteTime=2024-02-27 23:46:59.559, closedTime=2024-02-27 23:47:00.384}}
23:47:00,384  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LifecycleService] Thread-22941 - hz.client_2772 [dev] [5.4.0-SNAPSHOT] HazelcastClient 5.4.0-SNAPSHOT (20240227) is CLIENT_DISCONNECTED
23:47:00,384  WARN |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [TwoWayBlockableExecutor] pool-8068-thread-1 - Dropping incoming runnable since other end closed. Server Closed EOF. MockedClientConnection{localAddress=[127.0.0.1]:40003, super=ClientConnection{alive=false, connectionId=3, channel=null, remoteAddress=[127.0.0.1]:5701, lastReadTime=2024-02-27 23:46:59.559, lastWriteTime=2024-02-27 23:46:59.559, closedTime=2024-02-27 23:47:00.384}}
23:47:00,384  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [ClientEndpointManager] hz.ClientIndexStatsTest_hopeful_golick.event-67757 - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Destroying ClientEndpoint{connection=MockedNodeConnection{ remoteAddress = [127.0.0.1]:40004, localAddress = [127.0.0.1]:5702, connectionId = 4}, clientUuid=c1cf3e21-bfa6-405d-8e46-66d8494b3f75, clientName=hz.client_2772, authenticated=true, clientVersion=5.4.0-SNAPSHOT, creationTime=1709077619031, latest clientAttributes=null, labels=[]}
23:47:00,384  WARN |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [TwoWayBlockableExecutor] pool-8108-thread-1 - Dropping incoming runnable since other end closed. Server Closed EOF. MockedClientConnection{localAddress=[127.0.0.1]:40004, super=ClientConnection{alive=false, connectionId=4, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2024-02-27 23:46:59.559, lastWriteTime=2024-02-27 23:46:59.559, closedTime=2024-02-27 23:47:00.384}}
23:47:00,385  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LifecycleService] Thread-22941 - hz.client_2772 [dev] [5.4.0-SNAPSHOT] HazelcastClient 5.4.0-SNAPSHOT (20240227) is SHUTDOWN
23:47:00,385  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LifecycleService] Thread-22941 - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] [127.0.0.1]:5702 is SHUTTING_DOWN
23:47:00,386  WARN |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-22941 - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Terminating forcefully...
23:47:00,386  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-22941 - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Shutting down connection manager...
23:47:00,386  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [MockServer] Thread-22941 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Removed connection to endpoint: [address=[127.0.0.1]:5702, uuid=5b716714-0160-4fa1-8646-fc6fb898fc4e], connection: MockConnection{localEndpoint=[address=[127.0.0.1]:5701, uuid=1a143435-0cd1-4224-9861-b5a7d77952a1], remoteEndpoint=[address=[127.0.0.1]:5702, uuid=5b716714-0160-4fa1-8646-fc6fb898fc4e], alive=false}
23:47:00,386  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [MockServer] Thread-22941 - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Removed connection to endpoint: [address=[127.0.0.1]:5701, uuid=1a143435-0cd1-4224-9861-b5a7d77952a1], connection: MockConnection{localEndpoint=[address=[127.0.0.1]:5702, uuid=5b716714-0160-4fa1-8646-fc6fb898fc4e], remoteEndpoint=[address=[127.0.0.1]:5701, uuid=1a143435-0cd1-4224-9861-b5a7d77952a1], alive=false}
23:47:00,386  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [MembershipManager] Thread-22941 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Removing Member [127.0.0.1]:5702 - 5b716714-0160-4fa1-8646-fc6fb898fc4e
23:47:00,386  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [PartitionStateManager] Thread-22941 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Storing snapshot of partition assignments while removing UUID 5b716714-0160-4fa1-8646-fc6fb898fc4e
23:47:00,386  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [ClusterService] Thread-22941 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] 

Members {size:1, ver:7} [
	Member [127.0.0.1]:5701 - 1a143435-0cd1-4224-9861-b5a7d77952a1 this
]

23:47:00,386  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-22941 - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Shutting down node engine...
23:47:00,386  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [TransactionManagerService] hz.ClientIndexStatsTest_fervent_shtern.cached.thread-2 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Committing/rolling-back live transactions of [127.0.0.1]:5702, UUID: 5b716714-0160-4fa1-8646-fc6fb898fc4e
23:47:00,391  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [NodeExtension] Thread-22941 - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Destroying node NodeExtension.
23:47:00,391  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-22941 - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] Hazelcast Shutdown is completed in 5 ms.
23:47:00,391  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LifecycleService] Thread-22941 - [127.0.0.1]:5702 [dev] [5.4.0-SNAPSHOT] [127.0.0.1]:5702 is SHUTDOWN
23:47:00,391  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LifecycleService] Thread-22941 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] [127.0.0.1]:5701 is SHUTTING_DOWN
23:47:00,391  WARN |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-22941 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Terminating forcefully...
23:47:00,392  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-22941 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Shutting down connection manager...
23:47:00,392  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-22941 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Shutting down node engine...
23:47:00,392  WARN |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Invocation] hz.ClientIndexStatsTest_fervent_shtern.priority-generic-operation.thread-0 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Future.complete(Object) on completed future. Request: Invocation{op=com.hazelcast.internal.partition.operation.PromotionCommitOperation{serviceName='hz:core:partitionService', identityHash=244684454, partitionId=-1, replicaIndex=0, callId=-875, invocationTime=1709077620385 (2024-02-27 23:47:00.385), waitTimeout=-1, callTimeout=60000, tenantControl=com.hazelcast.spi.impl.tenantcontrol.NoopTenantControl@0}, tryCount=2147483647, tryPauseMillis=500, invokeCount=1, callTimeoutMillis=60000, firstInvocationTimeMs=1709077620387, firstInvocationTime='2024-02-27 23:47:00.387', lastHeartbeatMillis=0, lastHeartbeatTime='1970-01-01 00:00:00.000', targetAddress=[127.0.0.1]:5701, targetMember=Member [127.0.0.1]:5701 - 1a143435-0cd1-4224-9861-b5a7d77952a1 this, memberListVersion=7, pendingResponse={VOID}, backupsAcksExpected=-1, backupsAcksReceived=0, connection=null}, current value: ExceptionalResult{cause=com.hazelcast.core.HazelcastInstanceNotActiveException: Hazelcast instance is not active!}, offered value: true
java.lang.Exception: Future.complete(Object) on completed future. Request: Invocation{op=com.hazelcast.internal.partition.operation.PromotionCommitOperation{serviceName='hz:core:partitionService', identityHash=244684454, partitionId=-1, replicaIndex=0, callId=-875, invocationTime=1709077620385 (2024-02-27 23:47:00.385), waitTimeout=-1, callTimeout=60000, tenantControl=com.hazelcast.spi.impl.tenantcontrol.NoopTenantControl@0}, tryCount=2147483647, tryPauseMillis=500, invokeCount=1, callTimeoutMillis=60000, firstInvocationTimeMs=1709077620387, firstInvocationTime='2024-02-27 23:47:00.387', lastHeartbeatMillis=0, lastHeartbeatTime='1970-01-01 00:00:00.000', targetAddress=[127.0.0.1]:5701, targetMember=Member [127.0.0.1]:5701 - 1a143435-0cd1-4224-9861-b5a7d77952a1 this, memberListVersion=7, pendingResponse={VOID}, backupsAcksExpected=-1, backupsAcksReceived=0, connection=null}, current value: ExceptionalResult{cause=com.hazelcast.core.HazelcastInstanceNotActiveException: Hazelcast instance is not active!}, offered value: true
	at com.hazelcast.spi.impl.AbstractInvocationFuture.warnIfSuspiciousDoubleCompletion(AbstractInvocationFuture.java:1262) [classes/:?]
	at com.hazelcast.spi.impl.AbstractInvocationFuture.complete0(AbstractInvocationFuture.java:1236) [classes/:?]
	at com.hazelcast.spi.impl.AbstractInvocationFuture.complete(AbstractInvocationFuture.java:1225) [classes/:?]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.complete(Invocation.java:690) [classes/:?]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.sendResponse(Invocation.java:236) [classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.sendResponse(Operation.java:493) [classes/:?]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:304) [classes/:?]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:265) [classes/:?]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:216) [classes/:?]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:174) [classes/:?]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:143) [classes/:?]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.loop(OperationThread.java:134) [classes/:?]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.executeRun(OperationThread.java:115) [classes/:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:111) [classes/:?]
23:47:00,394  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [NodeExtension] Thread-22941 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Destroying node NodeExtension.
23:47:00,395  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-22941 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Hazelcast Shutdown is completed in 4 ms.
23:47:00,395  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LifecycleService] Thread-22941 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] [127.0.0.1]:5701 is SHUTDOWN
23:47:00,395  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [HazelcastTestSupport] Thread-22941 - Shutting down node factory as @After action
BuildInfo right after shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT](com.hazelcast.client.map.ClientIndexStatsTest): BuildInfo{version='5.4.0-SNAPSHOT', build='20240227', buildNumber=20240227, revision=, enterprise=false, serializationVersion=1}
Hiccups measured while running test 'shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT](com.hazelcast.client.map.ClientIndexStatsTest):'
23:46:55, accumulated pauses: 838 ms, max pause: 771 ms, pauses over 1000 ms: 0
23:47:00, accumulated pauses: 0 ms, max pause: 0 ms, pauses over 1000 ms: 0


No metrics recorded during the test

Standard output can be found here - https://s3.console.aws.amazon.com/s3/buckets/j-artifacts/Hazelcast-master-ZuluJDK21/5/
@AleksPeychev AleksPeychev added Type: Test-Failure Source: Internal PR or issue was opened by an employee labels Feb 28, 2024
@AleksPeychev AleksPeychev added this to the 5.4 Backlog milestone Feb 28, 2024
@AleksPeychev
Copy link
Contributor Author

AleksPeychev commented Mar 1, 2024 •
edited

Failed again on master with

Standard output: 
01:19:59 [INFO] Results:
01:19:59 [INFO] 
01:19:59 [ERROR] Failures: 
01:19:59 [ERROR] com.hazelcast.client.map.ClientIndexStatsTest.shouldUseIndexFromClient_whenClusterRestartedInFrozenState
01:19:59 [INFO]   Run 1: PASS
01:19:59 [ERROR]   Run 2: ClientIndexStatsTest.shouldUseIndexFromClient_whenClusterRestartedInFrozenState:172->testIndexWithoutMapProxy:203->stats:232->combineStats:252 expected:<100> but was:<0>
01:19:59 [INFO] 
01:19:59 [INFO] 
01:19:59 [ERROR] Tests run: 62620, Failures: 1, Errors: 0, Skipped: 226
01:19:59 [INFO] 
01:19:59 
[ERROR] There are test failures.

@k-jamroz
Copy link
Contributor

k-jamroz commented Mar 4, 2024

Same as https://github.com/hazelcast/hazelcast-enterprise/issues/7063

@k-jamroz k-jamroz self-assigned this Mar 4, 2024
@github-actions github-actions bot changed the title com.hazelcast.client.map.ClientIndexStatsTest.shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT] com.hazelcast.client.map.ClientIndexStatsTest.shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT] [HZ-4536] Mar 4, 2024
@github-actions GitHub Actions
Copy link
Contributor

github-actions bot commented Mar 4, 2024

Internal Jira issue: HZ-4536

@Patras3
Copy link
Contributor

Patras3 commented Mar 4, 2024 •
edited

Failed again on master with:

@k-jamroz k-jamroz closed this as completed Mar 8, 2024
devOpsHazelcast pushed a commit that referenced this issue Mar 8, 2024
@k-jamroz @ihsandemir @actions-user
Fix flaky ClientIndexStatsTest [HZ-4534] [HZ-4536] (#1009)
67e503c 
Avoid race conditions between async (via events) proxy initialization on
other members than the one who got
`InitializeDistributedObjectOperation` and cluster restart. Those races
are unfortunate but are not tested here.

Fixes HZ-4534, HZ-4536
Fixes: https://github.com/hazelcast/hazelcast-enterprise/issues/7063
Fixes: #26269
Fixes part of:
https://github.com/hazelcast/hazelcast-enterprise/issues/6550#issuecomment-1966769964

---------

Co-authored-by: ihsan demir <ihsan@hazelcast.com>
GitOrigin-RevId: c33a2000c268af7ff2d03f67e3e266ad637af3e6
@AyberkSorgun AyberkSorgun modified the milestones: 5.4 Backlog, 5.4.0, 5.5.0 Mar 18, 2024
@olukas
Copy link
Contributor

olukas commented May 6, 2024

Reopening as issue occurred again on: 5.4.z (commit f6ba60a0ddba563c06604704a0c7ac9d6e27260c)
with oracle-17: https://jenkins.hazelcast.com/view/Official%20Builds/job/Hazelcast-5.maintenance-OracleJDK17/112/testReport/com.hazelcast.client.map/ClientIndexStatsTest/shouldUseIndexFromClient_whenClusterRestartedInFrozenState_format_OBJECT_/

@k-jamroz could you please back-port the fix to 5.4.z branch?

Stacktrace: 
java.lang.AssertionError: expected:<100> but was:<0>
	at org.junit.Assert.fail(Assert.java:89)
	at org.junit.Assert.failNotEquals(Assert.java:835)
	at org.junit.Assert.assertEquals(Assert.java:647)
	at org.junit.Assert.assertEquals(Assert.java:633)
	at com.hazelcast.client.map.ClientIndexStatsTest.combineStats(ClientIndexStatsTest.java:253)
	at com.hazelcast.client.map.ClientIndexStatsTest.stats(ClientIndexStatsTest.java:233)
	at com.hazelcast.client.map.ClientIndexStatsTest.testIndexWithoutMapProxy(ClientIndexStatsTest.java:204)
	at com.hazelcast.client.map.ClientIndexStatsTest.shouldUseIndexFromClient_whenClusterRestartedInFrozenState(ClientIndexStatsTest.java:173)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:115)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:107)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.lang.Thread.run(Thread.java:842)
Standard output: 
Finished Running Test: testAverageQuerySelectivityCalculation_WhenAllPartitionsAreHeavilyPopulated[format:OBJECT] in 2.057 seconds.
23:45:15,979  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [InternalPartitionService] hz.ClientIndexStatsTest_suspicious_solomon.migration - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Fetching partition tables from cluster to determine the most recent one... Local stamp: 6061328494663657577
23:45:15,979  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [InternalPartitionService] hz.ClientIndexStatsTest_suspicious_solomon.migration - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Most recent partition table is determined.
23:45:15,979  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [InternalPartitionService] hz.ClientIndexStatsTest_suspicious_solomon.migration - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Applying the most recent of partition state...
23:45:15,981  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MigrationManager] hz.ClientIndexStatsTest_suspicious_solomon.migration - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Partition balance is ok, no need to repartition.
23:45:16,076  INFO |shouldUseIndexFromClient_whenClusterRestartedForcefully[format:OBJECT]| - [HazelcastClient] hz.client_2778.internal-5 - Created connection to endpoint: [127.0.0.1]:5702, connection: MockedClientConnection{localAddress=[127.0.0.1]:40004, super=ClientConnection{alive=true, connectionId=4, channel=null, remoteAddress=null, lastReadTime=never, lastWriteTime=never, closedTime=never}}
23:45:16,076 DEBUG |shouldUseIndexFromClient_whenClusterRestartedForcefully[format:OBJECT]| - [AuthenticationMessageTask] hz.ClientIndexStatsTest_practical_solomon.priority-generic-operation.thread-0 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Processing authentication with clientUuid 9396920c-f580-4a30-afc4-3bfd350862aa and clientName hz.client_2778
23:45:16,076  INFO |shouldUseIndexFromClient_whenClusterRestartedForcefully[format:OBJECT]| - [AuthenticationMessageTask] hz.ClientIndexStatsTest_practical_solomon.priority-generic-operation.thread-0 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Received auth from MockedNodeConnection{ remoteAddress = [127.0.0.1]:40004, localAddress = [127.0.0.1]:5702, connectionId = 4}, successfully authenticated, clientUuid: 9396920c-f580-4a30-afc4-3bfd350862aa, client name: hz.client_2778, client version: 5.4.1-SNAPSHOT
23:45:16,077  INFO |shouldUseIndexFromClient_whenClusterRestartedForcefully[format:OBJECT]| - [ClientConnectionManager] hz.client_2778.internal-5 - hz.client_2778 [dev] [5.4.1-SNAPSHOT] Authenticated with server [127.0.0.1]:5702:88d2c589-77ad-470a-9ef5-ac9dbc468305, server version: 5.4.1-SNAPSHOT, local address: /127.0.0.1:40004
23:45:16,077 TRACE |shouldUseIndexFromClient_whenClusterRestartedForcefully[format:OBJECT]| - [ClientListenerService] hz.client_2778.eventRegistration- - hz.client_2778 [dev] [5.4.1-SNAPSHOT] Register attempt of ClientListenerRegistration{codec=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$1@5f4cf953, handler=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$BackupEventHandler@54473f97} to MockedClientConnection{localAddress=[127.0.0.1]:40004, super=ClientConnection{alive=true, connectionId=4, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2024-05-04 23:45:16.076, lastWriteTime=2024-05-04 23:45:16.076, closedTime=never}}
23:45:16,077 TRACE |shouldUseIndexFromClient_whenClusterRestartedForcefully[format:OBJECT]| - [ClientListenerService] hz.client_2778.eventRegistration- - hz.client_2778 [dev] [5.4.1-SNAPSHOT] Registered ClientListenerRegistration{codec=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$1@5f4cf953, handler=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$BackupEventHandler@54473f97} to MockedClientConnection{localAddress=[127.0.0.1]:40004, super=ClientConnection{alive=true, connectionId=4, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2024-05-04 23:45:16.077, lastWriteTime=2024-05-04 23:45:16.077, closedTime=never}}
23:45:16,131  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MetricsConfigHelper] shouldUseIndexFromClient_whenClusterRestarted - [LOCAL] [dev] [5.4.1-SNAPSHOT] Overridden metrics configuration with system property 'hazelcast.metrics.collection.frequency'='1' -> 'MetricsConfig.collectionFrequencySeconds'='1'
23:45:16,131  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [logo] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.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   
23:45:16,131  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [system] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Copyright (c) 2008-2024, Hazelcast, Inc. All Rights Reserved.
23:45:16,131  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [system] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Hazelcast Platform 5.4.1-SNAPSHOT (20240504) starting at [127.0.0.1]:5702
23:45:16,131  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [system] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Cluster name: dev
23:45:16,131  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [system] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Integrity Checker is disabled. Fail-fast on corrupted executables will not be performed. For more information, see the documentation for Integrity Checker.
23:45:16,131  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [system] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Jet is enabled
23:45:16,133  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MetricsConfigHelper] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Collecting debug metrics and sending to diagnostics is enabled
23:45:16,136  WARN |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [CPSubsystem] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.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.
23:45:16,138  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [JetServiceBackend] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Setting number of cooperative threads and default parallelism to 2
23:45:16,138  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [Diagnostics] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Diagnostics disabled. To enable add -Dhazelcast.diagnostics.enabled=true to the JVM arguments.
23:45:16,138  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [LifecycleService] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] [127.0.0.1]:5702 is STARTING
23:45:16,139  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MockServer] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Created connection to endpoint: [127.0.0.1]:5701-c0bebb4c-0bce-4410-8731-ffb58c618ec6, connection: MockConnection{localEndpoint=[address=[127.0.0.1]:5702, uuid=fa80fd4c-2b6c-4efa-8f23-6464d72f676e], remoteEndpoint=[address=[127.0.0.1]:5701, uuid=c0bebb4c-0bce-4410-8731-ffb58c618ec6], alive=true}
23:45:16,139  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MockServer] hz.ClientIndexStatsTest_suspicious_solomon.priority-generic-operation.thread-0 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Created connection to endpoint: [127.0.0.1]:5702-fa80fd4c-2b6c-4efa-8f23-6464d72f676e, connection: MockConnection{localEndpoint=[address=[127.0.0.1]:5701, uuid=c0bebb4c-0bce-4410-8731-ffb58c618ec6], remoteEndpoint=[address=[127.0.0.1]:5702, uuid=fa80fd4c-2b6c-4efa-8f23-6464d72f676e], alive=true}
23:45:16,139  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClusterService] hz.ClientIndexStatsTest_suspicious_solomon.priority-generic-operation.thread-0 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] 

Members {size:2, ver:6} [
	Member [127.0.0.1]:5701 - c0bebb4c-0bce-4410-8731-ffb58c618ec6 this
	Member [127.0.0.1]:5702 - fa80fd4c-2b6c-4efa-8f23-6464d72f676e
]

23:45:16,139  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClientClusterService] hz.client_2786.event-67785 - hz.client_2786 [dev] [5.4.1-SNAPSHOT] 

Members [2] {
	Member [127.0.0.1]:5701 - c0bebb4c-0bce-4410-8731-ffb58c618ec6
	Member [127.0.0.1]:5702 - fa80fd4c-2b6c-4efa-8f23-6464d72f676e
}

23:45:16,240  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClusterService] hz.ClientIndexStatsTest_musing_solomon.priority-generic-operation.thread-0 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] 

Members {size:2, ver:6} [
	Member [127.0.0.1]:5701 - c0bebb4c-0bce-4410-8731-ffb58c618ec6
	Member [127.0.0.1]:5702 - fa80fd4c-2b6c-4efa-8f23-6464d72f676e this
]

23:45:16,240  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [JobCoordinationService] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Jet started scanning for jobs
23:45:16,240  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [LifecycleService] shouldUseIndexFromClient_whenClusterRestarted - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] [127.0.0.1]:5702 is STARTED
23:45:16,338  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [HazelcastClient] hz.client_2782.internal-6 - Created connection to endpoint: [127.0.0.1]:5702, connection: MockedClientConnection{localAddress=[127.0.0.1]:40004, super=ClientConnection{alive=true, connectionId=4, channel=null, remoteAddress=null, lastReadTime=never, lastWriteTime=never, closedTime=never}}
23:45:16,338 DEBUG |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [AuthenticationMessageTask] hz.ClientIndexStatsTest_youthful_solomon.priority-generic-operation.thread-0 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Processing authentication with clientUuid a4bcfa1a-9d8b-4f7a-9202-0e1b4a0066e2 and clientName hz.client_2782
23:45:16,338  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [AuthenticationMessageTask] hz.ClientIndexStatsTest_youthful_solomon.priority-generic-operation.thread-0 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Received auth from MockedNodeConnection{ remoteAddress = [127.0.0.1]:40004, localAddress = [127.0.0.1]:5702, connectionId = 4}, successfully authenticated, clientUuid: a4bcfa1a-9d8b-4f7a-9202-0e1b4a0066e2, client name: hz.client_2782, client version: 5.4.1-SNAPSHOT
23:45:16,339  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [ClientConnectionManager] hz.client_2782.internal-6 - hz.client_2782 [dev] [5.4.1-SNAPSHOT] Authenticated with server [127.0.0.1]:5702:486bfc12-512d-4796-8017-073b1e89d0f6, server version: 5.4.1-SNAPSHOT, local address: /127.0.0.1:40004
23:45:16,339 TRACE |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [ClientListenerService] hz.client_2782.eventRegistration- - hz.client_2782 [dev] [5.4.1-SNAPSHOT] Register attempt of ClientListenerRegistration{codec=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$1@5f4cf953, handler=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$BackupEventHandler@70af6181} to MockedClientConnection{localAddress=[127.0.0.1]:40004, super=ClientConnection{alive=true, connectionId=4, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2024-05-04 23:45:16.339, lastWriteTime=2024-05-04 23:45:16.338, closedTime=never}}
23:45:16,340 TRACE |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [ClientListenerService] hz.client_2782.eventRegistration- - hz.client_2782 [dev] [5.4.1-SNAPSHOT] Registered ClientListenerRegistration{codec=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$1@5f4cf953, handler=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$BackupEventHandler@70af6181} to MockedClientConnection{localAddress=[127.0.0.1]:40004, super=ClientConnection{alive=true, connectionId=4, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2024-05-04 23:45:16.340, lastWriteTime=2024-05-04 23:45:16.339, closedTime=never}}
23:45:16,393  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MigrationManager] hz.ClientIndexStatsTest_suspicious_solomon.migration - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Repartitioning cluster data. Migration tasks count: 137
23:45:16,430  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [MigrationManager] hz.ClientIndexStatsTest_suspicious_solomon.migration - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] All migration tasks have been completed. (repartitionTime=Sat May 04 23:45:16 GMT 2024, plannedMigrations=137, completedMigrations=137, remainingMigrations=0, totalCompletedMigrations=345, elapsedMigrationOperationTime=37ms, totalElapsedMigrationOperationTime=37ms, elapsedDestinationCommitTime=37ms, totalElapsedDestinationCommitTime=37ms, elapsedMigrationTime=37ms, totalElapsedMigrationTime=37ms)
23:45:16,708  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LockClusterStateOp] shouldUseIndexFromClient_whenClusterRestartedInFrozenState - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Locking cluster state. Initiator: [127.0.0.1]:5701, lease-time: 60000
23:45:16,708  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LockClusterStateOp] hz.ClientIndexStatsTest_youthful_solomon.priority-generic-operation.thread-0 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Locking cluster state. Initiator: [127.0.0.1]:5701, lease-time: 60000
23:45:16,708  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LockClusterStateOp] shouldUseIndexFromClient_whenClusterRestartedInFrozenState - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Extending cluster state lock. Initiator: [127.0.0.1]:5701, lease-time: 20000
23:45:16,708  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LockClusterStateOp] hz.ClientIndexStatsTest_youthful_solomon.priority-generic-operation.thread-0 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Extending cluster state lock. Initiator: [127.0.0.1]:5701, lease-time: 20000
23:45:16,709  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [CommitClusterStateOp] shouldUseIndexFromClient_whenClusterRestartedInFrozenState - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Changing cluster state from ClusterState{state=FROZEN, lock=LockGuard{lockOwner=[127.0.0.1]:5701, lockOwnerId='f7e83875-78f1-4181-84e3-fc4a59ba8b51', lockExpiryTime=1714866396708}} to ClusterStateChange{type=class com.hazelcast.cluster.ClusterState, newState=ACTIVE}, initiator: [127.0.0.1]:5701, transient: false
23:45:16,709  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [CommitClusterStateOp] hz.ClientIndexStatsTest_youthful_solomon.priority-generic-operation.thread-0 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Changing cluster state from ClusterState{state=FROZEN, lock=LockGuard{lockOwner=[127.0.0.1]:5701, lockOwnerId='f7e83875-78f1-4181-84e3-fc4a59ba8b51', lockExpiryTime=1714866396708}} to ClusterStateChange{type=class com.hazelcast.cluster.ClusterState, newState=ACTIVE}, initiator: [127.0.0.1]:5701, transient: false
23:45:16,732  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [HazelcastClient] hz.client_2786.internal-5 - Created connection to endpoint: [127.0.0.1]:5702, connection: MockedClientConnection{localAddress=[127.0.0.1]:40004, super=ClientConnection{alive=true, connectionId=4, channel=null, remoteAddress=null, lastReadTime=never, lastWriteTime=never, closedTime=never}}
23:45:16,733 DEBUG |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [AuthenticationMessageTask] hz.ClientIndexStatsTest_musing_solomon.priority-generic-operation.thread-0 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Processing authentication with clientUuid b0173c1d-af3c-4326-9dab-47fb3153ed71 and clientName hz.client_2786
23:45:16,733  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [AuthenticationMessageTask] hz.ClientIndexStatsTest_musing_solomon.priority-generic-operation.thread-0 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Received auth from MockedNodeConnection{ remoteAddress = [127.0.0.1]:40004, localAddress = [127.0.0.1]:5702, connectionId = 4}, successfully authenticated, clientUuid: b0173c1d-af3c-4326-9dab-47fb3153ed71, client name: hz.client_2786, client version: 5.4.1-SNAPSHOT
23:45:16,734  INFO |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClientConnectionManager] hz.client_2786.internal-5 - hz.client_2786 [dev] [5.4.1-SNAPSHOT] Authenticated with server [127.0.0.1]:5702:fa80fd4c-2b6c-4efa-8f23-6464d72f676e, server version: 5.4.1-SNAPSHOT, local address: /127.0.0.1:40004
23:45:16,734 TRACE |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClientListenerService] hz.client_2786.eventRegistration- - hz.client_2786 [dev] [5.4.1-SNAPSHOT] Register attempt of ClientListenerRegistration{codec=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$1@5f4cf953, handler=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$BackupEventHandler@35e1a79} to MockedClientConnection{localAddress=[127.0.0.1]:40004, super=ClientConnection{alive=true, connectionId=4, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2024-05-04 23:45:16.733, lastWriteTime=2024-05-04 23:45:16.733, closedTime=never}}
23:45:16,734 TRACE |shouldUseIndexFromClient_whenClusterRestarted[format:OBJECT]| - [ClientListenerService] hz.client_2786.eventRegistration- - hz.client_2786 [dev] [5.4.1-SNAPSHOT] Registered ClientListenerRegistration{codec=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$1@5f4cf953, handler=com.hazelcast.client.impl.spi.impl.ClientInvocationServiceImpl$BackupEventHandler@35e1a79} to MockedClientConnection{localAddress=[127.0.0.1]:40004, super=ClientConnection{alive=true, connectionId=4, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2024-05-04 23:45:16.734, lastWriteTime=2024-05-04 23:45:16.734, closedTime=never}}
23:45:17,589  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LifecycleService] Thread-23155 - hz.client_2782 [dev] [5.4.1-SNAPSHOT] HazelcastClient 5.4.1-SNAPSHOT (20240504) is SHUTTING_DOWN
23:45:17,590  WARN |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [TestClientRegistry$MockedServerConnection] pool-8122-thread-1 - Server connection closed: null
23:45:17,590  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [ClientConnectionManager] Thread-23155 - hz.client_2782 [dev] [5.4.1-SNAPSHOT] Removed connection to endpoint: [127.0.0.1]:5702:486bfc12-512d-4796-8017-073b1e89d0f6, connection: MockedClientConnection{localAddress=[127.0.0.1]:40004, super=ClientConnection{alive=false, connectionId=4, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2024-05-04 23:45:16.778, lastWriteTime=2024-05-04 23:45:16.778, closedTime=2024-05-04 23:45:17.590}}
23:45:17,591  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [MockServer] pool-8122-thread-1 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Removed connection to endpoint: [address=[127.0.0.1]:40004, uuid=a4bcfa1a-9d8b-4f7a-9202-0e1b4a0066e2], connection: MockedNodeConnection{ remoteAddress = [127.0.0.1]:40004, localAddress = [127.0.0.1]:5702, connectionId = 4}
23:45:17,591  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [ClientConnectionManager] Thread-23155 - hz.client_2782 [dev] [5.4.1-SNAPSHOT] Removed connection to endpoint: [127.0.0.1]:5701:5a15f123-7a0b-487d-9672-58cd2e2c2f26, connection: MockedClientConnection{localAddress=[127.0.0.1]:40003, super=ClientConnection{alive=false, connectionId=3, channel=null, remoteAddress=[127.0.0.1]:5701, lastReadTime=2024-05-04 23:45:16.779, lastWriteTime=2024-05-04 23:45:16.778, closedTime=2024-05-04 23:45:17.591}}
23:45:17,591  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LifecycleService] Thread-23155 - hz.client_2782 [dev] [5.4.1-SNAPSHOT] HazelcastClient 5.4.1-SNAPSHOT (20240504) is CLIENT_DISCONNECTED
23:45:17,591  WARN |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [TestClientRegistry$MockedServerConnection] pool-8116-thread-1 - Server connection closed: null
23:45:17,591  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [MockServer] pool-8116-thread-1 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Removed connection to endpoint: [address=[127.0.0.1]:40003, uuid=a4bcfa1a-9d8b-4f7a-9202-0e1b4a0066e2], connection: MockedNodeConnection{ remoteAddress = [127.0.0.1]:40003, localAddress = [127.0.0.1]:5701, connectionId = 3}
23:45:17,591  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [ClientEndpointManager] hz.ClientIndexStatsTest_youthful_solomon.event-67793 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Destroying ClientEndpoint{connection=MockedNodeConnection{ remoteAddress = [127.0.0.1]:40004, localAddress = [127.0.0.1]:5702, connectionId = 4}, clientUuid=a4bcfa1a-9d8b-4f7a-9202-0e1b4a0066e2, clientName=hz.client_2782, authenticated=true, clientVersion=5.4.1-SNAPSHOT, creationTime=1714866316338, latest clientAttributes=null, labels=[]}
23:45:17,591  WARN |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [TwoWayBlockableExecutor] pool-8122-thread-1 - Dropping incoming runnable since other end closed. Server Closed EOF. MockedClientConnection{localAddress=[127.0.0.1]:40004, super=ClientConnection{alive=false, connectionId=4, channel=null, remoteAddress=[127.0.0.1]:5702, lastReadTime=2024-05-04 23:45:16.778, lastWriteTime=2024-05-04 23:45:16.778, closedTime=2024-05-04 23:45:17.590}}
23:45:17,591  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [ClientEndpointManager] hz.ClientIndexStatsTest_priceless_solomon.event-67758 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Destroying ClientEndpoint{connection=MockedNodeConnection{ remoteAddress = [127.0.0.1]:40003, localAddress = [127.0.0.1]:5701, connectionId = 3}, clientUuid=a4bcfa1a-9d8b-4f7a-9202-0e1b4a0066e2, clientName=hz.client_2782, authenticated=true, clientVersion=5.4.1-SNAPSHOT, creationTime=1714866315338, latest clientAttributes=null, labels=[]}
23:45:17,591  WARN |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [TwoWayBlockableExecutor] pool-8116-thread-1 - Dropping incoming runnable since other end closed. Server Closed EOF. MockedClientConnection{localAddress=[127.0.0.1]:40003, super=ClientConnection{alive=false, connectionId=3, channel=null, remoteAddress=[127.0.0.1]:5701, lastReadTime=2024-05-04 23:45:16.779, lastWriteTime=2024-05-04 23:45:16.778, closedTime=2024-05-04 23:45:17.591}}
23:45:17,592  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LifecycleService] Thread-23155 - hz.client_2782 [dev] [5.4.1-SNAPSHOT] HazelcastClient 5.4.1-SNAPSHOT (20240504) is SHUTDOWN
23:45:17,592  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LifecycleService] Thread-23155 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] [127.0.0.1]:5702 is SHUTTING_DOWN
23:45:17,592  WARN |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-23155 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Terminating forcefully...
23:45:17,592  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-23155 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Shutting down connection manager...
23:45:17,592  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [MockServer] Thread-23155 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Removed connection to endpoint: [address=[127.0.0.1]:5702, uuid=486bfc12-512d-4796-8017-073b1e89d0f6], connection: MockConnection{localEndpoint=[address=[127.0.0.1]:5701, uuid=5a15f123-7a0b-487d-9672-58cd2e2c2f26], remoteEndpoint=[address=[127.0.0.1]:5702, uuid=486bfc12-512d-4796-8017-073b1e89d0f6], alive=false}
23:45:17,592  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [MockServer] Thread-23155 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Removed connection to endpoint: [address=[127.0.0.1]:5701, uuid=5a15f123-7a0b-487d-9672-58cd2e2c2f26], connection: MockConnection{localEndpoint=[address=[127.0.0.1]:5702, uuid=486bfc12-512d-4796-8017-073b1e89d0f6], remoteEndpoint=[address=[127.0.0.1]:5701, uuid=5a15f123-7a0b-487d-9672-58cd2e2c2f26], alive=false}
23:45:17,592  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [MembershipManager] Thread-23155 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Removing Member [127.0.0.1]:5702 - 486bfc12-512d-4796-8017-073b1e89d0f6
23:45:17,592  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [PartitionStateManager] Thread-23155 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Storing snapshot of partition assignments while removing UUID 486bfc12-512d-4796-8017-073b1e89d0f6
23:45:17,592  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [ClusterService] Thread-23155 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] 

Members {size:1, ver:7} [
	Member [127.0.0.1]:5701 - 5a15f123-7a0b-487d-9672-58cd2e2c2f26 this
]

23:45:17,592  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-23155 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Shutting down node engine...
23:45:17,592  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [TransactionManagerService] hz.ClientIndexStatsTest_priceless_solomon.cached.thread-15 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Committing/rolling-back live transactions of [127.0.0.1]:5702, UUID: 486bfc12-512d-4796-8017-073b1e89d0f6
23:45:17,606  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [MigrationManager] hz.ClientIndexStatsTest_priceless_solomon.migration - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Partition balance is ok, no need to repartition.
23:45:17,607  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [NodeExtension] Thread-23155 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Destroying node NodeExtension.
23:45:17,607  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-23155 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] Hazelcast Shutdown is completed in 15 ms.
23:45:17,607  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LifecycleService] Thread-23155 - [127.0.0.1]:5702 [dev] [5.4.1-SNAPSHOT] [127.0.0.1]:5702 is SHUTDOWN
23:45:17,607  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LifecycleService] Thread-23155 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] [127.0.0.1]:5701 is SHUTTING_DOWN
23:45:17,607  WARN |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-23155 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Terminating forcefully...
23:45:17,607  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-23155 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Shutting down connection manager...
23:45:17,607  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-23155 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Shutting down node engine...
23:45:17,610  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [NodeExtension] Thread-23155 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Destroying node NodeExtension.
23:45:17,610  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [Node] Thread-23155 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] Hazelcast Shutdown is completed in 3 ms.
23:45:17,610  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [LifecycleService] Thread-23155 - [127.0.0.1]:5701 [dev] [5.4.1-SNAPSHOT] [127.0.0.1]:5701 is SHUTDOWN
23:45:17,610  INFO |shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT]| - [HazelcastTestSupport] Thread-23155 - Shutting down node factory as @After action
BuildInfo right after shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT](com.hazelcast.client.map.ClientIndexStatsTest): BuildInfo{version='5.4.1-SNAPSHOT', build='20240504', buildNumber=20240504, revision=, enterprise=false, serializationVersion=1}
Hiccups measured while running test 'shouldUseIndexFromClient_whenClusterRestartedInFrozenState[format:OBJECT](com.hazelcast.client.map.ClientIndexStatsTest):'
23:45:10, accumulated pauses: 51 ms, max pause: 3 ms, pauses over 1000 ms: 0
23:45:15, accumulated pauses: 808 ms, max pause: 766 ms, pauses over 1000 ms: 0


No metrics recorded during the test

Standard output can be found here - https://s3.console.aws.amazon.com/s3/buckets/j-artifacts/Hazelcast-5.maintenance-OracleJDK17/112/

@olukas olukas reopened this May 6, 2024
@olukas olukas modified the milestones: 5.5.0, 5.4.z May 6, 2024
@olukas
Copy link
Contributor

olukas commented May 6, 2024

Failed again on 5.4.z with oracle-17 (force-offload): https://jenkins.hazelcast.com/view/Official%20Builds/job/Hazelcast-5.maintenance-force-offload/76/testReport/com.hazelcast.client.map/ClientIndexStatsTest/shouldUseIndexFromClient_whenClusterRestartedInFrozenState_format_BINARY_/

@ldziedziul ldziedziul reopened this May 8, 2024
@sumnerib
Copy link
Contributor

sumnerib commented May 13, 2024 •
edited

Failed again on 5.4.z with:

@Patras3
Copy link
Contributor

Patras3 commented May 21, 2024

Failed again on 5.4.z with oracle-17 (force-offload): https://jenkins.hazelcast.com/job/Hazelcast-5.maintenance-force-offload/78/testReport/junit/com.hazelcast.client.map/ClientIndexStatsTest/

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@k-jamroz k-jamroz

Labels
Module: Query Source: Internal PR or issue was opened by an employee Team: Core to-jira Type: Test-Failure
Projects
None yet
Milestone
5.4.z
Development

No branches or pull requests
7 participants
@ldziedziul @olukas @AyberkSorgun @sumnerib @Patras3 @k-jamroz @AleksPeychev