search

trinodb / trino

Official repository of Trino, the distributed SQL query engine for big data, formerly known as PrestoSQL (https://trino.io)
https://trino.io
Apache License 2.0
10.36k stars 2.98k forks source link

Product test launcher hung when stopping #5422

Closed kokosing closed 3 years ago

kokosing commented 4 years ago 
2020-10-05T13:55:37.7833715Z tests               | ===============================================
2020-10-05T13:55:37.7834976Z tests               | tempto-tests
2020-10-05T13:55:37.7835613Z tests               | Total tests run: 9, Failures: 0, Skips: 0
2020-10-05T13:55:37.7836252Z tests               | ===============================================
2020-10-05T13:55:37.7836728Z tests               | 
2020-10-05T13:55:38.0015093Z tests               | (exited)
2020-10-05T13:55:40.5581519Z 2020-10-05T13:55:40.557Z   INFO    container-stats-0   io.prestosql.tests.product.launcher.env.EnvironmentListener solr - cpu: 28.13%, memory: 554.68MB / 62.04GB (0.87%, max 566.04MB), pids: 50, network i/o: 36.31kB / 36.31kB
2020-10-05T13:55:41.5635354Z 2020-10-05T13:55:41.563Z   INFO    container-stats-1   io.prestosql.tests.product.launcher.env.EnvironmentListener ranger-admin - cpu: 2.98%, memory: 1.09GB / 62.04GB (1.75%, max 1.09GB), pids: 47, network i/o: 13.75MB / 13.75MB
2020-10-05T13:55:43.4041011Z 2020-10-05T13:55:43.403Z   INFO    main    io.prestosql.tests.product.launcher.env.Environment Test container fcd35f87ec7528a78d33112e650643ea225b9e75ba574918c22abbf6c36bcccf is exited, with exitCode 0
2020-10-05T13:55:43.4047047Z 2020-10-05T13:55:43.404Z   INFO    environment-listener-1  io.prestosql.tests.product.launcher.env.EnvironmentListener Environment stopping: singlenode-hive-privacera-ranger
2020-10-05T13:55:43.4070263Z 2020-10-05T13:55:43.406Z   INFO    environment-listener-1  io.prestosql.tests.product.launcher.env.EnvironmentListener Container stopping: ranger-admin
2020-10-05T13:55:43.4738318Z 2020-10-05T13:55:43.472Z   ERROR   container-stats-0   io.prestosql.tests.product.launcher.env.StatisticsFetcher   Could not fetch container presto-master statistics: java.lang.RuntimeException: java.lang.InterruptedException
2020-10-05T13:55:43.4742358Z    at com.github.dockerjava.core.InvocationBuilder$AsyncResultCallback.awaitResult(InvocationBuilder.java:88)
2020-10-05T13:55:43.4744008Z    at net.jodah.failsafe.Functions.lambda$get$0(Functions.java:48)
2020-10-05T13:55:43.4745348Z    at net.jodah.failsafe.TimeoutExecutor.lambda$supply$2(TimeoutExecutor.java:91)
2020-10-05T13:55:43.4747126Z    at net.jodah.failsafe.Execution.executeSync(Execution.java:129)
2020-10-05T13:55:43.4749232Z    at net.jodah.failsafe.FailsafeExecutor.call(FailsafeExecutor.java:376)
2020-10-05T13:55:43.4751549Z    at net.jodah.failsafe.FailsafeExecutor.get(FailsafeExecutor.java:67)
2020-10-05T13:55:43.4754894Z    at io.prestosql.tests.product.launcher.env.StatisticsFetcher.lambda$get$0(StatisticsFetcher.java:59)
2020-10-05T13:55:43.4758921Z    at java.base/java.util.concurrent.atomic.AtomicReference.getAndUpdate(AtomicReference.java:187)
2020-10-05T13:55:43.4761781Z    at io.prestosql.tests.product.launcher.env.StatisticsFetcher.get(StatisticsFetcher.java:59)
2020-10-05T13:55:43.4764053Z    at io.prestosql.tests.product.launcher.env.DockerContainer.getStats(DockerContainer.java:286)
2020-10-05T13:55:43.4766383Z    at io.prestosql.tests.product.launcher.env.EnvironmentListener$4.lambda$containerStarting$0(EnvironmentListener.java:226)
2020-10-05T13:55:43.4768137Z    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
2020-10-05T13:55:43.4769401Z    at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
2020-10-05T13:55:43.4771520Z    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
2020-10-05T13:55:43.4773543Z    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
2020-10-05T13:55:43.4775145Z    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
2020-10-05T13:55:43.4776428Z    at java.base/java.lang.Thread.run(Thread.java:834)
2020-10-05T13:55:43.4777828Z    Suppressed: java.lang.IllegalArgumentException: byteCount < 0: -2525
2020-10-05T13:55:43.4779304Z        at org.testcontainers.shaded.okio.RealBufferedSource.read(RealBufferedSource.java:47)
2020-10-05T13:55:43.4781613Z        at org.testcontainers.shaded.okhttp3.internal.http1.Http1ExchangeCodec$AbstractSource.read(Http1ExchangeCodec.java:389)
2020-10-05T13:55:43.4784378Z        at org.testcontainers.shaded.okhttp3.internal.http1.Http1ExchangeCodec$ChunkedSource.read(Http1ExchangeCodec.java:475)
2020-10-05T13:55:43.4786613Z        at org.testcontainers.shaded.okhttp3.internal.Util.skipAll(Util.java:204)
2020-10-05T13:55:43.4788286Z        at org.testcontainers.shaded.okhttp3.internal.Util.discard(Util.java:186)
2020-10-05T13:55:43.4790477Z        at org.testcontainers.shaded.okhttp3.internal.http1.Http1ExchangeCodec$ChunkedSource.close(Http1ExchangeCodec.java:511)
2020-10-05T13:55:43.4792796Z        at org.testcontainers.shaded.okio.ForwardingSource.close(ForwardingSource.java:43)
2020-10-05T13:55:43.4794922Z        at org.testcontainers.shaded.okhttp3.internal.connection.Exchange$ResponseBodySource.close(Exchange.java:313)
2020-10-05T13:55:43.4797135Z        at org.testcontainers.shaded.okio.RealBufferedSource.close(RealBufferedSource.java:476)
2020-10-05T13:55:43.4799102Z        at org.testcontainers.shaded.okhttp3.internal.Util.closeQuietly(Util.java:139)
2020-10-05T13:55:43.4800927Z        at org.testcontainers.shaded.okhttp3.ResponseBody.close(ResponseBody.java:192)
2020-10-05T13:55:43.4802491Z        at org.testcontainers.shaded.okhttp3.Response.close(Response.java:290)
2020-10-05T13:55:43.4804388Z        at com.github.dockerjava.okhttp.OkHttpInvocationBuilder.lambda$null$3(OkHttpInvocationBuilder.java:324)
2020-10-05T13:55:43.4806649Z        at com.github.dockerjava.api.async.ResultCallbackTemplate.close(ResultCallbackTemplate.java:77)
2020-10-05T13:55:43.4808701Z        at com.github.dockerjava.core.InvocationBuilder$AsyncResultCallback.close(InvocationBuilder.java:74)
2020-10-05T13:55:43.4810691Z        at io.prestosql.tests.product.launcher.env.StatisticsFetcher.get(StatisticsFetcher.java:56)
2020-10-05T13:55:43.4811926Z        ... 8 more
2020-10-05T13:55:43.4812615Z Caused by: java.lang.InterruptedException
2020-10-05T13:55:43.4814912Z    at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1040)
2020-10-05T13:55:43.4818853Z    at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1345)
2020-10-05T13:55:43.4821337Z    at java.base/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:232)
2020-10-05T13:55:43.4823033Z    at com.github.dockerjava.core.InvocationBuilder$AsyncResultCallback.awaitResult(InvocationBuilder.java:86)
2020-10-05T13:55:43.4824179Z    ... 16 more
2020-10-05T13:55:43.4824379Z 
2020-10-05T13:55:43.4826081Z 2020-10-05T13:55:43.472Z   INFO    container-stats-0   io.prestosql.tests.product.launcher.env.EnvironmentListener presto-master - cpu: 178.28%, memory: 2.50GB / 62.04GB (4.04%, max 2.54GB), pids: 327, network i/o: 378.48kB / 378.48kB
2020-10-05T13:55:48.4206567Z solr                | 2020-10-05 13:55:48.419 INFO  (commitScheduler-25-thread-1) [   ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
2020-10-05T13:55:48.4210873Z solr                | 2020-10-05 13:55:48.419 INFO  (commitScheduler-25-thread-1) [   ] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@16936813 commitCommandVersion:0
2020-10-05T13:55:48.4621154Z solr                | 2020-10-05 13:55:48.461 INFO  (commitScheduler-25-thread-1) [   ] o.a.s.s.SolrIndexSearcher Opening [Searcher@1cd83d8e[ranger_audits] realtime]
2020-10-05T13:55:48.4622808Z solr                | 2020-10-05 13:55:48.461 INFO  (commitScheduler-25-thread-1) [   ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
2020-10-05T13:56:13.1260336Z presto-master       | 2020-10-05T19:41:13.124+0545 INFO    AsyncAuditProvider1 org.apache.ranger.audit.provider.AsyncAuditProvider AsyncAuditProvider-stats:MySolrAuditProvider: past 01:00.149 minutes: inLogs=3, outLogs=3, dropped=0, currentQueueSize=0
2020-10-05T13:56:13.1263555Z presto-master       | 2020-10-05T19:41:13.125+0545 INFO    AsyncAuditProvider1 org.apache.ranger.audit.provider.AsyncAuditProvider AsyncAuditProvider-stats:MySolrAuditProvider: process lifetime: inLogs=3, outLogs=3, dropped=0
2020-10-05T13:56:13.4077943Z 2020-10-05T13:56:13.407Z   ERROR   docker-container-14 io.prestosql.tests.product.launcher.env.EnvironmentListener Could not invoke listener  due to java.lang.InterruptedException
2020-10-05T13:56:13.4080418Z    at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:385)
2020-10-05T13:56:13.4082007Z    at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1999)
2020-10-05T13:56:13.4084085Z    at io.prestosql.tests.product.launcher.env.EnvironmentListener.lambda$tryInvokeListener$1(EnvironmentListener.java:79)
2020-10-05T13:56:13.4086072Z    at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
2020-10-05T13:56:13.4087417Z    at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:658)
2020-10-05T13:56:13.4093149Z    at io.prestosql.tests.product.launcher.env.EnvironmentListener.tryInvokeListener(EnvironmentListener.java:77)
2020-10-05T13:56:13.4097004Z    at io.prestosql.tests.product.launcher.env.EnvironmentListener$1.containerStopping(EnvironmentListener.java:134)
2020-10-05T13:56:13.4100340Z    at io.prestosql.tests.product.launcher.env.DockerContainer.lambda$containerIsStopping$4(DockerContainer.java:172)
2020-10-05T13:56:13.4101989Z    at java.base/java.util.Optional.ifPresent(Optional.java:183)
2020-10-05T13:56:13.4103894Z    at io.prestosql.tests.product.launcher.env.DockerContainer.containerIsStopping(DockerContainer.java:172)
2020-10-05T13:56:13.4106196Z    at org.testcontainers.containers.GenericContainer.stop(GenericContainer.java:598)
2020-10-05T13:56:13.4107675Z    at net.jodah.failsafe.Functions.lambda$toCtxSupplier$13(Functions.java:261)
2020-10-05T13:56:13.4109111Z    at net.jodah.failsafe.Functions.lambda$getPromise$1(Functions.java:81)
2020-10-05T13:56:13.4110171Z    at net.jodah.failsafe.Functions.lambda$null$3(Functions.java:103)
2020-10-05T13:56:13.4111795Z    at net.jodah.failsafe.internal.util.DelegatingScheduler.lambda$schedule$0(DelegatingScheduler.java:141)
2020-10-05T13:56:13.4113423Z    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2020-10-05T13:56:13.4114856Z    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
2020-10-05T13:56:13.4116476Z    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
2020-10-05T13:56:13.4117527Z    at java.base/java.lang.Thread.run(Thread.java:834)
2020-10-05T13:56:13.4117900Z 
2020-10-05T13:56:17.0401505Z presto-master       | 2020-10-05T19:41:17.039+0545 INFO    AsyncAuditProvider1 org.apache.ranger.audit.provider.AsyncAuditProvider AsyncAuditProvider-stats:MySolrAuditProvider: past 01:00.007 minutes: inLogs=31, outLogs=31, dropped=0, currentQueueSize=0
2020-10-05T13:56:17.0404734Z presto-master       | 2020-10-05T19:41:17.039+0545 INFO    AsyncAuditProvider1 org.apache.ranger.audit.provider.AsyncAuditProvider AsyncAuditProvider-stats:MySolrAuditProvider: process lifetime: inLogs=31, outLogs=31, dropped=0
2020-10-05T14:00:43.4077021Z 2020-10-05T14:00:43.407Z   ERROR   environment-listener-2  io.prestosql.tests.product.launcher.env.EnvironmentListener Could not invoke listener  due to java.lang.InterruptedException
2020-10-05T14:00:43.4080375Z    at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:385)
2020-10-05T14:00:43.4082237Z    at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1999)
2020-10-05T14:00:43.4085123Z    at io.prestosql.tests.product.launcher.env.EnvironmentListener.lambda$tryInvokeListener$1(EnvironmentListener.java:79)
2020-10-05T14:00:43.4087483Z    at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
2020-10-05T14:00:43.4088838Z    at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:658)
2020-10-05T14:00:43.4091777Z    at io.prestosql.tests.product.launcher.env.EnvironmentListener.tryInvokeListener(EnvironmentListener.java:77)
2020-10-05T14:00:43.4096135Z    at io.prestosql.tests.product.launcher.env.EnvironmentListener$1.containerStopping(EnvironmentListener.java:134)
2020-10-05T14:00:43.4098610Z    at io.prestosql.tests.product.launcher.env.EnvironmentListener$1.lambda$containerStopping$6(EnvironmentListener.java:134)
2020-10-05T14:00:43.4101153Z    at io.prestosql.tests.product.launcher.env.EnvironmentListener.lambda$tryInvokeListener$0(EnvironmentListener.java:79)
2020-10-05T14:00:43.4103038Z    at net.jodah.failsafe.Functions.lambda$toCtxSupplier$13(Functions.java:261)
2020-10-05T14:00:43.4104137Z    at net.jodah.failsafe.Functions.lambda$getPromise$1(Functions.java:81)
2020-10-05T14:00:43.4105197Z    at net.jodah.failsafe.Functions.lambda$null$3(Functions.java:103)
2020-10-05T14:00:43.4106841Z    at net.jodah.failsafe.internal.util.DelegatingScheduler.lambda$schedule$0(DelegatingScheduler.java:141)
2020-10-05T14:00:43.4108474Z    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2020-10-05T14:00:43.4109915Z    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
2020-10-05T14:00:43.4111540Z    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
2020-10-05T14:00:43.4112614Z    at java.base/java.lang.Thread.run(Thread.java:834)
2020-10-05T14:00:43.4112990Z 
2020-10-05T14:00:43.4114901Z 2020-10-05T14:00:43.407Z   WARN    main    io.prestosql.tests.product.launcher.env.DockerContainer Could not stop container correctly: java.lang.InterruptedException
2020-10-05T14:00:43.4116923Z    at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:385)
2020-10-05T14:00:43.4118501Z    at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1999)
2020-10-05T14:00:43.4120677Z    at io.prestosql.tests.product.launcher.env.DockerContainer.tryStop(DockerContainer.java:395)
2020-10-05T14:00:43.4122349Z    at net.jodah.failsafe.Functions.lambda$toSupplier$10(Functions.java:240)
2020-10-05T14:00:43.4123387Z    at net.jodah.failsafe.Functions.lambda$get$0(Functions.java:48)
2020-10-05T14:00:43.4124711Z    at net.jodah.failsafe.RetryPolicyExecutor.lambda$supply$0(RetryPolicyExecutor.java:62)
2020-10-05T14:00:43.4126361Z    at net.jodah.failsafe.TimeoutExecutor.lambda$supply$2(TimeoutExecutor.java:91)
2020-10-05T14:00:43.4127608Z    at net.jodah.failsafe.Execution.executeSync(Execution.java:129)
2020-10-05T14:00:43.4128856Z    at net.jodah.failsafe.FailsafeExecutor.call(FailsafeExecutor.java:376)
2020-10-05T14:00:43.4130139Z    at net.jodah.failsafe.FailsafeExecutor.run(FailsafeExecutor.java:210)
2020-10-05T14:00:43.4131744Z    at io.prestosql.tests.product.launcher.env.Environment.lambda$stop$6(Environment.java:169)
2020-10-05T14:00:43.4133223Z    at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
2020-10-05T14:00:43.4134382Z    at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:177)
2020-10-05T14:00:43.4135875Z    at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
2020-10-05T14:00:43.4137285Z    at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
2020-10-05T14:00:43.4138854Z    at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
2020-10-05T14:00:43.4140512Z    at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
2020-10-05T14:00:43.4141801Z    at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
2020-10-05T14:00:43.4143154Z    at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
2020-10-05T14:00:43.4144587Z    at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497)
2020-10-05T14:00:43.4146214Z    at io.prestosql.tests.product.launcher.env.Environment.stop(Environment.java:169)
2020-10-05T14:00:43.4148059Z    at io.prestosql.tests.product.launcher.env.Environment.close(Environment.java:260)
2020-10-05T14:00:43.4149857Z    at io.prestosql.tests.product.launcher.cli.TestRun$Execution.tryExecuteTests(TestRun.java:201)
2020-10-05T14:00:43.4151498Z    at io.prestosql.tests.product.launcher.cli.TestRun$Execution.lambda$call$0(TestRun.java:181)
2020-10-05T14:00:43.4152771Z    at net.jodah.failsafe.Functions.lambda$get$0(Functions.java:48)
2020-10-05T14:00:43.4153969Z    at net.jodah.failsafe.TimeoutExecutor.lambda$supply$2(TimeoutExecutor.java:91)
2020-10-05T14:00:43.4155227Z    at net.jodah.failsafe.Execution.executeSync(Execution.java:129)
2020-10-05T14:00:43.4156460Z    at net.jodah.failsafe.FailsafeExecutor.call(FailsafeExecutor.java:376)
2020-10-05T14:00:43.4157746Z    at net.jodah.failsafe.FailsafeExecutor.get(FailsafeExecutor.java:67)
2020-10-05T14:00:43.4159212Z    at io.prestosql.tests.product.launcher.cli.TestRun$Execution.call(TestRun.java:181)
2020-10-05T14:00:43.4160786Z    at io.prestosql.tests.product.launcher.cli.SuiteRun$Execution.runTest(SuiteRun.java:228)
2020-10-05T14:00:43.4162555Z    at io.prestosql.tests.product.launcher.cli.SuiteRun$Execution.executeSuiteTestRun(SuiteRun.java:220)
2020-10-05T14:00:43.4164277Z    at io.prestosql.tests.product.launcher.cli.SuiteRun$Execution.call(SuiteRun.java:167)
2020-10-05T14:00:43.4165846Z    at io.prestosql.tests.product.launcher.cli.SuiteRun$Execution.call(SuiteRun.java:117)
2020-10-05T14:00:43.4167589Z    at io.prestosql.tests.product.launcher.cli.Commands.runCommand(Commands.java:42)
2020-10-05T14:00:43.4169355Z    at io.prestosql.tests.product.launcher.cli.SuiteRun.call(SuiteRun.java:85)
2020-10-05T14:00:43.4170982Z    at io.prestosql.tests.product.launcher.cli.SuiteRun.call(SuiteRun.java:55)
2020-10-05T14:00:43.4172384Z    at picocli.CommandLine.executeUserObject(CommandLine.java:1933)
2020-10-05T14:00:43.4173371Z    at picocli.CommandLine.access$1100(CommandLine.java:145)
2020-10-05T14:00:43.4174960Z    at picocli.CommandLine$RunLast.executeUserObjectOfLastSubcommandWithSameParent(CommandLine.java:2332)
2020-10-05T14:00:43.4176596Z    at picocli.CommandLine$RunLast.handle(CommandLine.java:2326)
2020-10-05T14:00:43.4177401Z    at picocli.CommandLine$RunLast.handle(CommandLine.java:2291)
2020-10-05T14:00:43.4178452Z    at picocli.CommandLine$AbstractParseResultHandler.execute(CommandLine.java:2159)
2020-10-05T14:00:43.4179515Z    at picocli.CommandLine.execute(CommandLine.java:2058)
2020-10-05T14:00:43.4181405Z    at com.starburstdata.presto.tests.product.launcher.cli.StarburstLauncher.main(StarburstLauncher.java:62)
2020-10-05T14:00:43.4182893Z 
2020-10-05T15:25:24.2789130Z ##[error]The operation was canceled.
kokosing commented 4 years ago

I hope #5421 fixed this. Please reopen if I am wrong.

kokosing commented 4 years ago

Now it hangs differenty.

pt (config-hdp3, suite-2):

2020-10-18T09:20:05.8830136Z tests               | Total tests run: 96, Failures: 0, Skips: 0
2020-10-18T09:20:05.8830508Z tests               | ===============================================
2020-10-18T09:20:05.8830910Z tests               | 
2020-10-18T09:20:06.7130690Z tests               | (exited)
2020-10-18T09:20:43.1863596Z presto-master       | 2020-10-18T15:05:43.184+0545 INFO    HttpServerScheduler org.eclipse.jetty.util.ssl.SslContextFactory    x509=X509@222cd945(docker.cluster,h=[],w=[docker.cluster]) for Server@356ff881[provider=null,keyStore=file:///docker/presto-product-tests/conf/presto/etc/docker.cluster.jks,trustStore=null]
2020-10-18T09:21:43.1921137Z presto-master       | 2020-10-18T15:06:43.191+0545 INFO    HttpServerScheduler org.eclipse.jetty.util.ssl.SslContextFactory    x509=X509@6b968dda(docker.cluster,h=[],w=[docker.cluster]) for Server@4f93c948[provider=null,keyStore=file:///docker/presto-product-tests/conf/presto/etc/docker.cluster.jks,trustStore=null]
2020-10-18T09:22:43.1968105Z presto-master       | 2020-10-18T15:07:43.195+0545 INFO    HttpServerScheduler org.eclipse.jetty.util.ssl.SslContextFactory    x509=X509@bb1d70e(docker.cluster,h=[],w=[docker.cluster]) for Server@41509d09[provider=null,keyStore=file:///docker/presto-product-tests/conf/presto/etc/docker.cluster.jks,trustStore=null]
2020-10-18T09:23:43.2000934Z presto-master       | 2020-10-18T15:08:43.199+0545 INFO    HttpServerScheduler org.eclipse.jetty.util.ssl.SslContextFactory    x509=X509@1e7720a4(docker.cluster,h=[],w=[docker.cluster]) for Server@4f7f73ab[provider=null,keyStore=file:///docker/presto-product-tests/conf/presto/etc/docker.cluster.jks,trustStore=null]
2020-10-18T09:24:43.2040003Z presto-master       | 2020-10-18T15:09:43.202+0545 INFO    HttpServerScheduler org.eclipse.jetty.util.ssl.SslContextFactory    x509=X509@4a73c4ed(docker.cluster,h=[],w=[docker.cluster]) for Server@f8eb07f[provider=null,keyStore=file:///docker/presto-product-tests/conf/presto/etc/docker.cluster.jks,trustStore=null]
...
2020-10-18T14:42:44.2012071Z presto-master       | 2020-10-18T20:27:44.193+0545 INFO    HttpServerScheduler org.eclipse.jetty.util.ssl.SslContextFactory    x509=X509@61de454f(docker.cluster,h=[],w=[docker.cluster]) for Server@464d50df[provider=null,keyStore=file:///docker/presto-product-tests/conf/presto/etc/docker.cluster.jks,trustStore=null]
2020-10-18T14:43:44.1974853Z presto-master       | 2020-10-18T20:28:44.195+0545 INFO    HttpServerScheduler org.eclipse.jetty.util.ssl.SslContextFactory    x509=X509@69e4329(docker.cluster,h=[],w=[docker.cluster]) for Server@14b4f987[provider=null,keyStore=file:///docker/presto-product-tests/conf/presto/etc/docker.cluster.jks,trustStore=null]
2020-10-18T14:44:23.8768086Z ##[error]The operation was canceled.
findepi commented 3 years ago

https://github.com/prestosql/presto/runs/1348767770?check_suite_focus=true 

2020-11-03T17:42:16.4558264Z tests               | ===============================================
2020-11-03T17:42:16.4559653Z tests               | tempto-tests
2020-11-03T17:42:16.4560155Z tests               | Total tests run: 1, Failures: 0, Skips: 0
2020-11-03T17:42:16.4560545Z tests               | ===============================================
2020-11-03T17:42:16.4560879Z tests               | 
2020-11-03T17:42:16.7282494Z tests               | (exited)
2020-11-03T17:42:20.7207069Z 2020-11-03T17:42:20.720Z   INFO    container-stats-0   io.prestosql.tests.product.launcher.env.EnvironmentListener presto-master - cpu: 56.43%, memory: 1.83GB / 6.79GB (26.92%, max 1.83GB), pids: 236, network i/o: 13.70kB / 13.70kB
2020-11-03T17:42:23.5484018Z 2020-11-03T17:42:23.547Z   INFO    main    io.prestosql.tests.product.launcher.env.Environment Test container 551ca19f7014d49116cb64a1feabbd3e13b11fa7cc2226cfb4b6a1a851ecead7 is exited, with exitCode 0
2020-11-03T17:42:23.5540554Z 2020-11-03T17:42:23.548Z   INFO    environment-listener-1  io.prestosql.tests.product.launcher.env.EnvironmentListener Environment stopping: singlenode
2020-11-03T17:42:23.5690510Z 2020-11-03T17:42:23.568Z   INFO    environment-listener-1  io.prestosql.tests.product.launcher.env.EnvironmentListener Container stopping: presto-master
2020-11-03T17:42:53.5693330Z 2020-11-03T17:42:53.568Z   WARN    main    io.prestosql.tests.product.launcher.env.DockerContainer Could not stop container correctly: java.util.concurrent.ExecutionException: net.jodah.failsafe.TimeoutExceededException
2020-11-03T17:42:53.5697991Z    at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395)
2020-11-03T17:42:53.5699793Z    at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1999)
2020-11-03T17:42:53.5701933Z    at io.prestosql.tests.product.launcher.env.DockerContainer.tryStop(DockerContainer.java:398)
2020-11-03T17:42:53.5703918Z    at net.jodah.failsafe.Functions.lambda$toSupplier$10(Functions.java:240)
2020-11-03T17:42:53.5705079Z    at net.jodah.failsafe.Functions.lambda$get$0(Functions.java:48)
2020-11-03T17:42:53.5706548Z    at net.jodah.failsafe.RetryPolicyExecutor.lambda$supply$0(RetryPolicyExecutor.java:62)
2020-11-03T17:42:53.5708242Z    at net.jodah.failsafe.TimeoutExecutor.lambda$supply$2(TimeoutExecutor.java:91)
2020-11-03T17:42:53.5709641Z    at net.jodah.failsafe.Execution.executeSync(Execution.java:129)
2020-11-03T17:42:53.5711251Z    at net.jodah.failsafe.FailsafeExecutor.call(FailsafeExecutor.java:376)
2020-11-03T17:42:53.5712692Z    at net.jodah.failsafe.FailsafeExecutor.run(FailsafeExecutor.java:210)
2020-11-03T17:42:53.5714505Z    at io.prestosql.tests.product.launcher.env.Environment.lambda$stop$6(Environment.java:177)
2020-11-03T17:42:53.5716165Z    at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
2020-11-03T17:42:53.5717434Z    at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:177)
2020-11-03T17:42:53.5718894Z    at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
2020-11-03T17:42:53.5720553Z    at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484)
2020-11-03T17:42:53.5722357Z    at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474)
2020-11-03T17:42:53.5724050Z    at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
2020-11-03T17:42:53.5725478Z    at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
2020-11-03T17:42:53.5728670Z    at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
2020-11-03T17:42:53.5730322Z    at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:497)
2020-11-03T17:42:53.5732187Z    at io.prestosql.tests.product.launcher.env.Environment.stop(Environment.java:177)
2020-11-03T17:42:53.5734301Z    at io.prestosql.tests.product.launcher.env.Environment.close(Environment.java:273)
2020-11-03T17:42:53.5736467Z    at io.prestosql.tests.product.launcher.cli.TestRun$Execution.tryExecuteTests(TestRun.java:198)
2020-11-03T17:42:53.5738351Z    at io.prestosql.tests.product.launcher.cli.TestRun$Execution.lambda$call$0(TestRun.java:178)
2020-11-03T17:42:53.5739773Z    at net.jodah.failsafe.Functions.lambda$get$0(Functions.java:48)
2020-11-03T17:42:53.5741090Z    at net.jodah.failsafe.TimeoutExecutor.lambda$supply$2(TimeoutExecutor.java:91)
2020-11-03T17:42:53.5742482Z    at net.jodah.failsafe.Execution.executeSync(Execution.java:129)
2020-11-03T17:42:53.5743860Z    at net.jodah.failsafe.FailsafeExecutor.call(FailsafeExecutor.java:376)
2020-11-03T17:42:53.5745299Z    at net.jodah.failsafe.FailsafeExecutor.get(FailsafeExecutor.java:67)
2020-11-03T17:42:53.5746851Z    at io.prestosql.tests.product.launcher.cli.TestRun$Execution.call(TestRun.java:178)
2020-11-03T17:42:53.5748636Z    at io.prestosql.tests.product.launcher.cli.SuiteRun$Execution.runTest(SuiteRun.java:228)
2020-11-03T17:42:53.5750633Z    at io.prestosql.tests.product.launcher.cli.SuiteRun$Execution.executeSuiteTestRun(SuiteRun.java:220)
2020-11-03T17:42:53.5752603Z    at io.prestosql.tests.product.launcher.cli.SuiteRun$Execution.call(SuiteRun.java:167)
2020-11-03T17:42:53.5754367Z    at io.prestosql.tests.product.launcher.cli.SuiteRun$Execution.call(SuiteRun.java:117)
2020-11-03T17:42:53.5756865Z    at io.prestosql.tests.product.launcher.cli.Commands.runCommand(Commands.java:42)
2020-11-03T17:42:53.5758921Z    at io.prestosql.tests.product.launcher.cli.SuiteRun.call(SuiteRun.java:85)
2020-11-03T17:42:53.5760785Z    at io.prestosql.tests.product.launcher.cli.SuiteRun.call(SuiteRun.java:55)
2020-11-03T17:42:53.5762341Z    at picocli.CommandLine.executeUserObject(CommandLine.java:1933)
2020-11-03T17:42:53.5763408Z    at picocli.CommandLine.access$1100(CommandLine.java:145)
2020-11-03T17:42:53.5765089Z    at picocli.CommandLine$RunLast.executeUserObjectOfLastSubcommandWithSameParent(CommandLine.java:2332)
2020-11-03T17:42:53.5766751Z    at picocli.CommandLine$RunLast.handle(CommandLine.java:2326)
2020-11-03T17:42:53.5767591Z    at picocli.CommandLine$RunLast.handle(CommandLine.java:2291)
2020-11-03T17:42:53.5768737Z    at picocli.CommandLine$AbstractParseResultHandler.execute(CommandLine.java:2159)
2020-11-03T17:42:53.5769905Z    at picocli.CommandLine.execute(CommandLine.java:2058)
2020-11-03T17:42:53.5771261Z    at io.prestosql.tests.product.launcher.cli.Launcher.run(Launcher.java:68)
2020-11-03T17:42:53.5773213Z    at io.prestosql.tests.product.launcher.cli.Launcher.main(Launcher.java:60)
2020-11-03T17:42:53.5774958Z Caused by: net.jodah.failsafe.TimeoutExceededException
2020-11-03T17:42:53.5776642Z    at net.jodah.failsafe.TimeoutExecutor.lambda$null$3(TimeoutExecutor.java:119)
2020-11-03T17:42:53.5778696Z    at net.jodah.failsafe.internal.util.DelegatingScheduler.lambda$schedule$0(DelegatingScheduler.java:141)
2020-11-03T17:42:53.5780580Z    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2020-11-03T17:42:53.5782199Z    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
2020-11-03T17:42:53.5784041Z    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
2020-11-03T17:42:53.5785283Z    at java.base/java.lang.Thread.run(Thread.java:834)
2020-11-03T17:42:53.5785670Z 
2020-11-03T19:04:26.9988808Z ##[error]The operation was canceled.
2020-11-03T19:04:27.0278584Z Post job cleanup.
2020-11-03T19:04:27.4635904Z Post job cleanup.
kokosing commented 3 years ago

Another similar case:

2020-11-09T22:12:59.1211372Z presto-master       | 2020-11-10T03:57:59.119+0545 INFO    dispatcher-query-142    io.prestosql.event.QueryMonitor TIMELINE: Query 20201109_221258_02901_qf26d :: Transaction:[ea0e9702-6cc3-41d2-8036-cd1b7057bbe0] :: elapsed 112ms :: planning 16ms :: waiting 22ms :: scheduling 35ms :: running 33ms :: finishing 28ms :: begin 2020-11-10T03:57:58.969+05:45 :: end 2020-11-10T03:57:59.081+05:45
2020-11-09T22:12:59.1353623Z tests               | 2020-11-10 03:57:59 INFO: 
2020-11-09T22:12:59.1354416Z tests               | 2020-11-10 03:57:59 INFO: Completed 557 tests
2020-11-09T22:12:59.1355143Z tests               | 2020-11-10 03:57:59 INFO: 493 SUCCEEDED      /      0 FAILED      /      64 SKIPPED
2020-11-09T22:12:59.1355916Z tests               | 2020-11-10 03:57:59 INFO: Tests execution took 27 minutes and 43 seconds
2020-11-09T22:12:59.8170674Z tests               | 
2020-11-09T22:12:59.8171273Z tests               | ===============================================
2020-11-09T22:12:59.8173124Z tests               | tempto-tests
2020-11-09T22:12:59.8173722Z tests               | Total tests run: 557, Failures: 0, Skips: 64
2020-11-09T22:12:59.8174154Z tests               | ===============================================
2020-11-09T22:12:59.8174592Z tests               | 
2020-11-09T22:13:04.1003913Z tests               | (exited)
2020-11-09T23:31:46.6777120Z ##[error]The operation was canceled.
2020-11-09T23:31:46.7190343Z Post job cleanup.
2020-11-09T23:31:47.1412797Z Post job cleanup.
2020-11-09T23:31:47.6273106Z [command]/usr/bin/git version

This happened for: