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.15k stars 1.84k forks source link

com.hazelcast.jet.sql_slow.SqlSlowIndexTest.test #21866

Closed olukas closed 1 year ago

olukas commented 2 years ago

master (commit 83b2d0306f6bfd9ae8f13299458d8182ed9fc954)

Failed on Sonar build (Oracle JDK 11): https://jenkins.hazelcast.com/view/Official%20Builds/job/Hazelcast-master-sonar/1290/testReport/com.hazelcast.jet.sql_slow/SqlSlowIndexTest/

All tests in all variants in com.hazelcast.jet.sql_slow.SqlSlowIndexTest.test failed.

Stacktrace (for [indexType:SORTED, composite:true, field1:Byte, field2:Byte] as an example): ``` com.hazelcast.sql.HazelcastSqlException: The Jet SQL job failed: Hazelcast instance is not active! at com.hazelcast.sql.impl.QueryUtils.toPublicException(QueryUtils.java:72) at com.hazelcast.jet.sql.impl.SqlResultImpl$RowToSqlRowIterator.hasNext(SqlResultImpl.java:108) at com.hazelcast.jet.sql.impl.connector.map.index.SqlIndexAbstractTest.sqlKeys(SqlIndexAbstractTest.java:630) at com.hazelcast.jet.sql.impl.connector.map.index.SqlIndexAbstractTest.check0(SqlIndexAbstractTest.java:462) at com.hazelcast.jet.sql.impl.connector.map.index.SqlIndexAbstractTest.check0(SqlIndexAbstractTest.java:450) at com.hazelcast.jet.sql.impl.connector.map.index.SqlIndexAbstractTest.check(SqlIndexAbstractTest.java:446) at com.hazelcast.jet.sql.impl.connector.map.index.SqlIndexAbstractTest.checkFirstColumn(SqlIndexAbstractTest.java:255) at com.hazelcast.jet.sql.impl.connector.map.index.SqlIndexAbstractTest.test(SqlIndexAbstractTest.java:122) at jdk.internal.reflect.GeneratedMethodAccessor95.invoke(Unknown Source) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) 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 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:834) Caused by: com.hazelcast.sql.impl.QueryException: The Jet SQL job failed: Hazelcast instance is not active! at com.hazelcast.sql.impl.QueryException.error(QueryException.java:65) at com.hazelcast.jet.sql.impl.PlanExecutor.lambda$execute$2(PlanExecutor.java:351) at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859) at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837) at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088) at com.hazelcast.jet.impl.util.NonCompletableFuture.internalCompleteExceptionally(NonCompletableFuture.java:72) at com.hazelcast.jet.impl.AbstractJobProxy$CallbackBase.accept(AbstractJobProxy.java:363) at com.hazelcast.jet.impl.AbstractJobProxy$CallbackBase.accept(AbstractJobProxy.java:346) at com.hazelcast.spi.impl.AbstractInvocationFuture.lambda$unblockWhenComplete$3(AbstractInvocationFuture.java:914) at com.hazelcast.test.TestLoggingUtils$CustomTestNameAwareForkJoinPool$TestNameAwareRunnable.run(TestLoggingUtils.java:104) at java.base/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1426) at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290) at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020) at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656) at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594) at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183) Caused by: com.hazelcast.core.HazelcastInstanceNotActiveException: Hazelcast instance is not active! at com.hazelcast.spi.impl.operationservice.impl.InvocationRegistry.shutdown(InvocationRegistry.java:229) at com.hazelcast.spi.impl.operationservice.impl.OperationServiceImpl.shutdownInvocations(OperationServiceImpl.java:534) at com.hazelcast.spi.impl.NodeEngineImpl.shutdown(NodeEngineImpl.java:543) at com.hazelcast.instance.impl.Node.shutdownServices(Node.java:605) at com.hazelcast.instance.impl.Node.shutdown(Node.java:541) at com.hazelcast.instance.impl.LifecycleServiceImpl.shutdown(LifecycleServiceImpl.java:101) at com.hazelcast.instance.impl.LifecycleServiceImpl.shutdown(LifecycleServiceImpl.java:84) at com.hazelcast.instance.impl.HazelcastInstanceFactory.shutdownAll(HazelcastInstanceFactory.java:306) at com.hazelcast.instance.impl.HazelcastInstanceFactory.shutdownAll(HazelcastInstanceFactory.java:280) at com.hazelcast.core.Hazelcast.shutdownAll(Hazelcast.java:44) at com.hazelcast.test.AfterClassesStatement.evaluate(AfterClassesStatement.java:45) at com.hazelcast.test.OverridePropertyRule$1.evaluate(OverridePropertyRule.java:66) at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:299) at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:293) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.lang.Thread.run(Thread.java:834) ```
Standard output (for [indexType:SORTED, composite:true, field1:Byte, field2:Byte] as an example): ``` 03:54:43,809 DEBUG || - [JobExecutionService] ForkJoinPool.commonPool-worker-13 - [127.0.0.1]:5702 [dev] [5.2-SNAPSHOT] Completed execution of job '0864-fb2c-514f-0001', execution 0864-fb2c-514f-0001 03:54:43,809 DEBUG || - [JobExecutionService] ForkJoinPool.commonPool-worker-13 - [127.0.0.1]:5702 [dev] [5.2-SNAPSHOT] Execution of job '0864-fb2c-514f-0001', execution 0864-fb2c-514f-0001 completed Finished Running Test: stressTest_noIndex in 53.872 seconds. 03:54:43,809 DEBUG || - [JobExecutionService] ForkJoinPool.commonPool-worker-13 - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Completed execution of job '0864-fb2c-514f-0001', execution 0864-fb2c-514f-0001 03:54:43,809 DEBUG || - [JobExecutionService] ForkJoinPool.commonPool-worker-13 - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Execution of job '0864-fb2c-514f-0001', execution 0864-fb2c-514f-0001 completed 03:54:43,811 INFO || - [LifecycleService] Time-limited test - [127.0.0.1]:5702 [dev] [5.2-SNAPSHOT] [127.0.0.1]:5702 is SHUTTING_DOWN 03:54:43,811 DEBUG || - [JobCoordinationService] hz.nifty_mclean.priority-generic-operation.thread-0 - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Added a shutting-down member: 6c69c7bf-9ba2-4471-b909-9c5734b04ba8 03:54:43,811 INFO || - [MigrationManager] hz.nifty_mclean.priority-generic-operation.thread-0 - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Shutdown request of Member [127.0.0.1]:5702 - 6c69c7bf-9ba2-4471-b909-9c5734b04ba8 is handled 03:54:43,812 INFO || - [MigrationManager] hz.nifty_mclean.migration - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Repartitioning cluster data. Migration tasks count: 5 03:54:43,819 INFO || - [MigrationManager] hz.nifty_mclean.migration - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] All migration tasks have been completed. (repartitionTime=Thu Jul 28 03:54:43 UTC 2022, plannedMigrations=5, completedMigrations=5, remainingMigrations=0, totalCompletedMigrations=5, elapsedMigrationOperationTime=33ms, totalElapsedMigrationOperationTime=33ms, elapsedDestinationCommitTime=0ms, totalElapsedDestinationCommitTime=0ms, elapsedMigrationTime=34ms, totalElapsedMigrationTime=34ms) 03:54:43,820 INFO || - [Node] Time-limited test - [127.0.0.1]:5702 [dev] [5.2-SNAPSHOT] Shutting down connection manager... 03:54:43,820 INFO || - [MockServer] Time-limited test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Removed connection to endpoint: [address=[127.0.0.1]:5702, uuid=6c69c7bf-9ba2-4471-b909-9c5734b04ba8], connection: MockConnection{localEndpoint=[address=[127.0.0.1]:5701, uuid=cfda9f53-6b6b-4cc0-9d9f-97a5af36a326], remoteEndpoint=[address=[127.0.0.1]:5702, uuid=6c69c7bf-9ba2-4471-b909-9c5734b04ba8], alive=false} 03:54:43,820 INFO || - [MockServer] Time-limited test - [127.0.0.1]:5702 [dev] [5.2-SNAPSHOT] Removed connection to endpoint: [address=[127.0.0.1]:5701, uuid=cfda9f53-6b6b-4cc0-9d9f-97a5af36a326], connection: MockConnection{localEndpoint=[address=[127.0.0.1]:5702, uuid=6c69c7bf-9ba2-4471-b909-9c5734b04ba8], remoteEndpoint=[address=[127.0.0.1]:5701, uuid=cfda9f53-6b6b-4cc0-9d9f-97a5af36a326], alive=false} 03:54:43,820 INFO || - [MembershipManager] Time-limited test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Removing Member [127.0.0.1]:5702 - 6c69c7bf-9ba2-4471-b909-9c5734b04ba8 03:54:43,821 INFO || - [MigrationManager] hz.nifty_mclean.migration - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Partition balance is ok, no need to repartition. 03:54:43,821 INFO || - [TransactionManagerService] hz.nifty_mclean.cached.thread-4 - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Committing/rolling-back live transactions of [127.0.0.1]:5702, UUID: 6c69c7bf-9ba2-4471-b909-9c5734b04ba8 03:54:43,821 DEBUG || - [JobCoordinationService] hz.nifty_mclean.cached.thread-4 - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Removed a shutting-down member: 6c69c7bf-9ba2-4471-b909-9c5734b04ba8, now shuttingDownMembers=[] 03:54:43,821 INFO || - [ClusterService] Time-limited test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Members {size:1, ver:3} [ Member [127.0.0.1]:5701 - cfda9f53-6b6b-4cc0-9d9f-97a5af36a326 this ] 03:54:43,821 INFO || - [Node] Time-limited test - [127.0.0.1]:5702 [dev] [5.2-SNAPSHOT] Shutting down node engine... 03:54:43,823 DEBUG |test[indexType:SORTED, composite:true, field1:Byte, field2:Byte]| - [CalciteSqlOptimizer] test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Before logical opt: LogicalCalc(expr#0..4=[{inputs}], expr#5=[Sarg[(-?..2:TINYINT(3)), (4:TINYINT(3)..+?)]:TINYINT(3)], expr#6=[SEARCH($t1, $t5)], expr#7=[CAST($t0):BIGINT(32)], expr#8=[2:BIGINT(32)], expr#9=[/($t7, $t8)], expr#10=[0:BIGINT(32)], expr#11=[=($t9, $t10)], expr#12=[OR($t6, $t11)], __key=[$t0], $condition=[$t12]) LogicalTableScan(table=[[hazelcast, public, map37[projects=[$0, $1, $2, $3, $4]]]]) 03:54:43,824 DEBUG |test[indexType:SORTED, composite:true, field1:Byte, field2:Byte]| - [CalciteSqlOptimizer] test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] After logical opt: FullScanLogicalRel(table=[[hazelcast, public, map37[projects=[$0], filter=OR(SEARCH($1, Sarg[(-?..2:TINYINT(3)), (4:TINYINT(3)..+?)]:TINYINT(3)), =(/(CAST($0):BIGINT(32), 2), 0))]]]) 03:54:43,824 DEBUG |test[indexType:SORTED, composite:true, field1:Byte, field2:Byte]| - [CalciteSqlOptimizer] test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] After physical opt: FullScanPhysicalRel(table=[[hazelcast, public, map37[projects=[$0], filter=OR(SEARCH($1, Sarg[(-?..2:TINYINT(3)), (4:TINYINT(3)..+?)]:TINYINT(3)), =(/(CAST($0):BIGINT(32), 2), 0))]]]) 03:54:43,824 INFO || - [NodeExtension] Time-limited test - [127.0.0.1]:5702 [dev] [5.2-SNAPSHOT] Destroying node NodeExtension. 03:54:43,825 INFO || - [Node] Time-limited test - [127.0.0.1]:5702 [dev] [5.2-SNAPSHOT] Hazelcast Shutdown is completed in 14 ms. 03:54:43,825 INFO || - [LifecycleService] Time-limited test - [127.0.0.1]:5702 [dev] [5.2-SNAPSHOT] [127.0.0.1]:5702 is SHUTDOWN 03:54:43,825 INFO || - [LifecycleService] Time-limited test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] [127.0.0.1]:5701 is SHUTTING_DOWN 03:54:43,825 DEBUG || - [JobCoordinationService] Time-limited test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Added a shutting-down member: cfda9f53-6b6b-4cc0-9d9f-97a5af36a326 03:54:43,825 DEBUG |test[indexType:SORTED, composite:true, field1:Byte, field2:Byte]| - [LightMasterContext] test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Start executing light job 0864-fb2c-5150-0001, execution graph in DOT format: digraph DAG { "IMap[public.map37]" [localParallelism=1]; "Project(IMap[public.map37])" [localParallelism=2]; "ClientSink" [localParallelism=1]; "IMap[public.map37]" -> "Project(IMap[public.map37])" [label="isolated", queueSize=1024]; "Project(IMap[public.map37])" -> "ClientSink" [label="distributed to [127.0.0.1]:5701-partitioned", queueSize=1024]; } HINT: You can use graphviz or http://viz-js.com/ to visualize the printed graph. 03:54:43,825 DEBUG |test[indexType:SORTED, composite:true, field1:Byte, field2:Byte]| - [LightMasterContext] test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Building execution plan for 0864-fb2c-5150-0001 03:54:43,825 INFO || - [MigrationManager] hz.nifty_mclean.cached.thread-4 - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Shutdown request of Member [127.0.0.1]:5701 - cfda9f53-6b6b-4cc0-9d9f-97a5af36a326 this is handled 03:54:43,825 DEBUG |test[indexType:SORTED, composite:true, field1:Byte, field2:Byte]| - [LightMasterContext] test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Built execution plans for 0864-fb2c-5150-0001 03:54:43,825 INFO || - [Node] Time-limited test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Shutting down connection manager... 03:54:43,826 INFO || - [Node] Time-limited test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Shutting down node engine... 03:54:43,828 INFO || - [NodeExtension] Time-limited test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Destroying node NodeExtension. 03:54:43,828 INFO || - [Node] Time-limited test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Hazelcast Shutdown is completed in 3 ms. 03:54:43,829 INFO || - [LifecycleService] Time-limited test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] [127.0.0.1]:5701 is SHUTDOWN 03:54:43,829 WARN |test[indexType:SORTED, composite:true, field1:Byte, field2:Byte]| - [Invocation] test - [127.0.0.1]:5701 [dev] [5.2-SNAPSHOT] Future.complete(Object) on completed future. Request: Invocation{op=com.hazelcast.jet.impl.operation.SubmitJobOperation{serviceName='hz:impl:jetService', identityHash=679074821, partitionId=-1, replicaIndex=0, callId=-1220, invocationTime=1658980483825 (2022-07-28 03:54:43.825), waitTimeout=-1, callTimeout=120000, tenantControl=com.hazelcast.spi.impl.tenantcontrol.NoopTenantControl@0}, tryCount=250, tryPauseMillis=500, invokeCount=1, callTimeoutMillis=120000, firstInvocationTimeMs=1658980483825, firstInvocationTime='2022-07-28 03:54:43.825', lastHeartbeatMillis=0, lastHeartbeatTime='1970-01-01 00:00:00.000', target=[127.0.0.1]:5701, pendingResponse={VOID}, backupsAcksExpected=-1, backupsAcksReceived=0, connection=null}, current value: ExceptionalResult{cause=com.hazelcast.core.HazelcastInstanceNotActiveException: Hazelcast instance is not active!}, offered value: ExceptionalResult{cause=com.hazelcast.core.HazelcastInstanceNotActiveException: Hazelcast instance is not active!} java.lang.Exception: Future.complete(Object) on completed future. Request: Invocation{op=com.hazelcast.jet.impl.operation.SubmitJobOperation{serviceName='hz:impl:jetService', identityHash=679074821, partitionId=-1, replicaIndex=0, callId=-1220, invocationTime=1658980483825 (2022-07-28 03:54:43.825), waitTimeout=-1, callTimeout=120000, tenantControl=com.hazelcast.spi.impl.tenantcontrol.NoopTenantControl@0}, tryCount=250, tryPauseMillis=500, invokeCount=1, callTimeoutMillis=120000, firstInvocationTimeMs=1658980483825, firstInvocationTime='2022-07-28 03:54:43.825', lastHeartbeatMillis=0, lastHeartbeatTime='1970-01-01 00:00:00.000', target=[127.0.0.1]:5701, pendingResponse={VOID}, backupsAcksExpected=-1, backupsAcksReceived=0, connection=null}, current value: ExceptionalResult{cause=com.hazelcast.core.HazelcastInstanceNotActiveException: Hazelcast instance is not active!}, offered value: ExceptionalResult{cause=com.hazelcast.core.HazelcastInstanceNotActiveException: Hazelcast instance is not active!} at com.hazelcast.spi.impl.AbstractInvocationFuture.warnIfSuspiciousDoubleCompletion(AbstractInvocationFuture.java:1256) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.AbstractInvocationFuture.complete0(AbstractInvocationFuture.java:1230) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.AbstractInvocationFuture.completeExceptionallyInternal(AbstractInvocationFuture.java:1223) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationservice.impl.Invocation.completeExceptionally(Invocation.java:680) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationservice.impl.Invocation.notifyThrowable(Invocation.java:386) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationservice.impl.Invocation.notifyError(Invocation.java:330) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationservice.impl.Invocation.sendResponse(Invocation.java:230) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationservice.Operation.sendResponse(Operation.java:483) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.jet.impl.operation.AsyncOperation.doSendResponse(AsyncOperation.java:81) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:57) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:273) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:601) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:580) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:541) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:241) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:61) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.jet.impl.JobProxy.invokeOp(JobProxy.java:201) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.jet.impl.JobProxy.invokeSubmitJob(JobProxy.java:115) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.jet.impl.AbstractJobProxy.doSubmitJob(AbstractJobProxy.java:314) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.jet.impl.AbstractJobProxy.(AbstractJobProxy.java:103) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.jet.impl.JobProxy.(JobProxy.java:65) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.jet.impl.JetInstanceImpl.newJobProxy(JetInstanceImpl.java:155) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.jet.impl.AbstractJetInstance.newJobInt(AbstractJetInstance.java:144) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.jet.impl.AbstractJetInstance.newLightJob(AbstractJetInstance.java:203) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.jet.sql.impl.PlanExecutor.execute(PlanExecutor.java:343) ~[classes/:?] at com.hazelcast.jet.sql.impl.SqlPlanImpl$SelectPlan.execute(SqlPlanImpl.java:849) ~[classes/:?] at com.hazelcast.sql.impl.SqlServiceImpl.query0(SqlServiceImpl.java:252) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.sql.impl.SqlServiceImpl.execute(SqlServiceImpl.java:202) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.sql.impl.SqlServiceImpl.execute(SqlServiceImpl.java:170) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.sql.impl.SqlServiceImpl.execute(SqlServiceImpl.java:166) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.sql.impl.SqlServiceImpl.execute(SqlServiceImpl.java:162) ~[hazelcast-5.2-SNAPSHOT.jar:5.2-SNAPSHOT] at com.hazelcast.jet.sql.impl.connector.map.index.SqlIndexAbstractTest.sqlKeys(SqlIndexAbstractTest.java:629) ~[test-classes/:?] at com.hazelcast.jet.sql.impl.connector.map.index.SqlIndexAbstractTest.check0(SqlIndexAbstractTest.java:462) ~[test-classes/:?] at com.hazelcast.jet.sql.impl.connector.map.index.SqlIndexAbstractTest.check0(SqlIndexAbstractTest.java:450) ~[test-classes/:?] at com.hazelcast.jet.sql.impl.connector.map.index.SqlIndexAbstractTest.check(SqlIndexAbstractTest.java:446) ~[test-classes/:?] at com.hazelcast.jet.sql.impl.connector.map.index.SqlIndexAbstractTest.checkFirstColumn(SqlIndexAbstractTest.java:255) ~[test-classes/:?] at com.hazelcast.jet.sql.impl.connector.map.index.SqlIndexAbstractTest.test(SqlIndexAbstractTest.java:122) ~[test-classes/:?] at jdk.internal.reflect.GeneratedMethodAccessor95.invoke(Unknown Source) ~[?:?] at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?] at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?] at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59) ~[junit-4.13.2.jar:4.13.2] at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) ~[junit-4.13.2.jar:4.13.2] at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56) ~[junit-4.13.2.jar:4.13.2] at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) ~[junit-4.13.2.jar:4.13.2] at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:115) ~[hazelcast-5.2-SNAPSHOT-tests.jar:5.2-SNAPSHOT] at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:107) ~[hazelcast-5.2-SNAPSHOT-tests.jar:5.2-SNAPSHOT] at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?] at java.lang.Thread.run(Thread.java:834) ~[?:?] BuildInfo right after test[indexType:SORTED, composite:true, field1:Byte, field2:Byte](com.hazelcast.jet.sql_slow.SqlSlowIndexTest): BuildInfo{version='5.2-SNAPSHOT', build='20220727', buildNumber=20220727, revision=83b2d03, enterprise=false, serializationVersion=1} Hiccups measured while running test 'test[indexType:SORTED, composite:true, field1:Byte, field2:Byte](com.hazelcast.jet.sql_slow.SqlSlowIndexTest):' 03:54:40, accumulated pauses: 687 ms, max pause: 318 ms, pauses over 1000 ms: 0 ```
Moreover it breaks JUnit XML report (which causes Sonar build to fail): ``` Failed to read test report file /home/jenkins/jenkins_slave/workspace/Hazelcast-master-sonar/hazelcast-sql/target/surefire-reports/TEST-com.hazelcast.jet.sql_slow.MapScanMigrationStressTest.xml org.dom4j.DocumentException: Error on line 94 of document : XML document structures must start and end within the same entity. at org.dom4j.io.SAXReader.read(SAXReader.java:511) at org.dom4j.io.SAXReader.read(SAXReader.java:392) at hudson.tasks.junit.SuiteResult.parse(SuiteResult.java:177) at hudson.tasks.junit.TestResult.parse(TestResult.java:384) at hudson.tasks.junit.TestResult.parsePossiblyEmpty(TestResult.java:314) at hudson.tasks.junit.TestResult.parse(TestResult.java:256) at hudson.tasks.junit.TestResult.parse(TestResult.java:242) at hudson.tasks.junit.TestResult.parse(TestResult.java:220) at hudson.tasks.junit.TestResult.(TestResult.java:174) at hudson.tasks.junit.JUnitParser$ParseResultCallable.invoke(JUnitParser.java:176) at hudson.FilePath$FileCallableWrapper.call(FilePath.java:3502) at hudson.remoting.UserRequest.perform(UserRequest.java:211) at hudson.remoting.UserRequest.perform(UserRequest.java:54) at hudson.remoting.Request$2.run(Request.java:376) at hudson.remoting.InterceptingExecutorService.lambda$wrap$0(InterceptingExecutorService.java:78) at java.util.concurrent.FutureTask.run(FutureTask.java:266) 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:748) Caused by: org.xml.sax.SAXParseException; lineNumber: 94; columnNumber: 26; XML document structures must start and end within the same entity. at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.createSAXParseException(ErrorHandlerWrapper.java:203) at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.fatalError(ErrorHandlerWrapper.java:177) at com.sun.org.apache.xerces.internal.impl.XMLErrorReporter.reportError(XMLErrorReporter.java:400) at com.sun.org.apache.xerces.internal.impl.XMLErrorReporter.reportError(XMLErrorReporter.java:327) at com.sun.org.apache.xerces.internal.impl.XMLScanner.reportFatalError(XMLScanner.java:1473) at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.endEntity(XMLDocumentFragmentScannerImpl.java:899) at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.endEntity(XMLDocumentScannerImpl.java:559) at com.sun.org.apache.xerces.internal.impl.XMLEntityManager.endEntity(XMLEntityManager.java:1410) at com.sun.org.apache.xerces.internal.impl.XMLEntityScanner.load(XMLEntityScanner.java:1925) at com.sun.org.apache.xerces.internal.impl.XMLEntityScanner.scanData(XMLEntityScanner.java:1384) at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanCDATASection(XMLDocumentFragmentScannerImpl.java:1654) at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(XMLDocumentFragmentScannerImpl.java:3014) at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(XMLDocumentScannerImpl.java:602) at com.sun.org.apache.xerces.internal.impl.XMLNSDocumentScannerImpl.next(XMLNSDocumentScannerImpl.java:112) at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(XMLDocumentFragmentScannerImpl.java:505) at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:842) at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:771) at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(XMLParser.java:141) at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1213) at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(SAXParserImpl.java:643) at org.dom4j.io.SAXReader.read(SAXReader.java:494) ... 18 more ```
olukas commented 2 years ago

Failed on Sonar build (Oracle JDK 11): https://jenkins.hazelcast.com/view/Official%20Builds/job/Hazelcast-master-sonar/1331/testReport/com.hazelcast.jet.sql_slow/SqlSlowIndexTest/

olukas commented 2 years ago

Failed on Sonar build (Oracle JDK 11): http://jenkins.hazelcast.com/view/Official%20Builds/job/Hazelcast-master-sonar/1334/testReport/com.hazelcast.jet.sql_slow/SqlSlowIndexTest/

olukas commented 2 years ago

Failed on Sonar build (Oracle JDK 11): https://jenkins.hazelcast.com/view/Official%20Builds/job/Hazelcast-master-sonar/1338/testReport/com.hazelcast.jet.sql_slow/SqlSlowIndexTest/

olukas commented 2 years ago

Failed on Sonar build (Oracle JDK 11): http://jenkins.hazelcast.com/view/Official%20Builds/job/Hazelcast-master-sonar/1341/testReport/com.hazelcast.jet.sql_slow/SqlSlowIndexTest/

olukas commented 2 years ago

Failed on Sonar build (Oracle JDK 11): https://jenkins.hazelcast.com/view/Official%20Builds/job/Hazelcast-master-sonar/1344/testReport/com.hazelcast.jet.sql_slow/SqlSlowIndexTest/

olukas commented 2 years ago

Failed on 5.1.z on ZuluJDK17: https://jenkins.hazelcast.com/view/Official%20Builds/job/Hazelcast-5.maintenance-ZuluJDK17-nightly/31/testReport/com.hazelcast.jet.sql_slow/SqlSlowIndexTest/

olukas commented 2 years ago

Failed on master on Sonar build (Oracle JDK 11): https://jenkins.hazelcast.com/view/Official%20Builds/job/Hazelcast-master-sonar/1365/testReport/com.hazelcast.jet.sql_slow/SqlSlowIndexTest/

Stacktrace is different: ``` java.lang.IllegalArgumentException: The given HazelcastInstance is not an active HazelcastInstanceImpl: class com.hazelcast.instance.impl.HazelcastInstanceProxy at com.hazelcast.instance.impl.TestUtil.getHazelcastInstanceImpl(TestUtil.java:109) at com.hazelcast.instance.impl.TestUtil.getNode(TestUtil.java:83) at com.hazelcast.test.Accessors.getNode(Accessors.java:64) at com.hazelcast.test.Accessors.getNodeEngineImpl(Accessors.java:72) at com.hazelcast.jet.sql.SqlTestSupport.nodeEngine(SqlTestSupport.java:583) at com.hazelcast.jet.sql.SqlTestSupport.planCache(SqlTestSupport.java:575) at com.hazelcast.jet.sql.SqlTestSupport.tearDown(SqlTestSupport.java:110) at jdk.internal.reflect.GeneratedMethodAccessor77.invoke(Unknown Source) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) 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 com.hazelcast.test.AbstractHazelcastClassRunner$ThreadDumpAwareRunAfters.evaluate(AbstractHazelcastClassRunner.java:381) at com.hazelcast.test.DumpBuildInfoOnFailureRule$1.evaluate(DumpBuildInfoOnFailureRule.java:37) at com.hazelcast.test.jitter.JitterRule$1.evaluate(JitterRule.java:104) at com.hazelcast.test.metrics.MetricsRule$1.evaluate(MetricsRule.java:63) at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306) at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103) at com.hazelcast.test.HazelcastSerialClassRunner.runChild(HazelcastSerialClassRunner.java:50) at com.hazelcast.test.HazelcastSerialClassRunner.runChild(HazelcastSerialClassRunner.java:29) at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329) at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293) at org.junit.runners.ParentRunner.run(ParentRunner.java:413) at org.junit.runners.Suite.runChild(Suite.java:128) at org.junit.runners.Suite.runChild(Suite.java:27) at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329) at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) at com.hazelcast.test.AfterClassesStatement.evaluate(AfterClassesStatement.java:39) at com.hazelcast.test.OverridePropertyRule$1.evaluate(OverridePropertyRule.java:66) at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:299) at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:293) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.lang.Thread.run(Thread.java:834) ```
krzysztofslusarski commented 2 years ago

Maybe correlated to failing MapScanMigrationStressTest.

sumnerib commented 1 year ago

Reopening as issue occurred again on: master (commit d82080ee8bf60f903f9ade20df3d0a58a83e1841) with OpenJDK11: https://jenkins.hazelcast.com/job/Hazelcast-master-OpenJDK11-arm64-nightly/7/testReport/junit/com.hazelcast.jet.sql_slow/SqlSlowIndexTest/ Standard output can be found here - https://s3.console.aws.amazon.com/s3/buckets/j-artifacts/Hazelcast-master-OpenJDK11-arm64-nightly/7/

Stacktrace: ``` com.hazelcast.core.HazelcastInstanceNotActiveException: Hazelcast instance is not active! at com.hazelcast.spi.impl.operationservice.impl.InvocationRegistry.register(InvocationRegistry.java:140) at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:587) at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:558) at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:241) at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:71) at com.hazelcast.spi.impl.operationservice.impl.InvokeOnPartitions.retryPartition(InvokeOnPartitions.java:140) at com.hazelcast.spi.impl.operationservice.impl.InvokeOnPartitions$FirstAttemptExecutionCallback.accept(InvokeOnPartitions.java:217) at com.hazelcast.spi.impl.operationservice.impl.InvokeOnPartitions$FirstAttemptExecutionCallback.accept(InvokeOnPartitions.java:175) at com.hazelcast.spi.impl.AbstractInvocationFuture$WhenCompleteNode.lambda$execute$0(AbstractInvocationFuture.java:1570) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829) at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:111) ```
Standard output: ``` 20:25:00,109 INFO || - [Node] Thread-187 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] Hazelcast Shutdown is completed in 923 ms. 20:25:00,109 INFO || - [LifecycleService] Thread-187 - [127.0.0.1]:5701 [dev] [5.4.0-SNAPSHOT] [127.0.0.1]:5701 is SHUTDOWN ```
k-jamroz commented 1 year ago

Duplicate of #25726