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

Flaky Iceberg product test TestIcebergInsert.testIcebergConcurrentInsert #16652

Closed
findepi opened this issue Mar 21, 2023 · 4 comments · Fixed by #16692
Closed

Flaky Iceberg product test TestIcebergInsert.testIcebergConcurrentInsert #16652

findepi opened this issue Mar 21, 2023 · 4 comments · Fixed by #16692
Assignees
@findepi
Labels
bug Something isn't working

Comments

@findepi
Copy link
Member

findepi commented Mar 21, 2023

https://github.com/trinodb/trino/actions/runs/4477556468/jobs/7869807813?pr=16637

2023-03-21T10:32:19.7522104Z presto-master       | 
2023-03-21T10:32:20.1912183Z presto-master       | 2023-03-21T16:17:20.190+0545	INFO	dispatcher-query-5	io.trino.event.QueryMonitor	TIMELINE: Query 20230321_103217_00021_vy3b4 :: FINISHED :: elapsed 2775ms :: planning 619ms :: waiting 156ms :: scheduling 330ms :: running 20ms :: finishing 1806ms :: begin 2023-03-21T16:17:17.387+05:45 :: end 2023-03-21T16:17:20.162+05:45
2023-03-21T10:32:20.2791595Z presto-master       | 2023-03-21T16:17:20.276+0545	WARN	20230321_103217_00019_vy3b4.0.0.0-2-92	org.apache.iceberg.util.Tasks	Retrying task after failure: Metadata location [hdfs://hadoop-master:9000/user/hive/warehouse/test_insert_concurrent_hnfkmo7wch-301c39c69015406893c9374937d39ae9/metadata/00038-a21ba75a-e302-439a-bac0-d00e0ad9d117.metadata.json] is not same as table metadata location [hdfs://hadoop-master:9000/user/hive/warehouse/test_insert_concurrent_hnfkmo7wch-301c39c69015406893c9374937d39ae9/metadata/00039-ac995477-96a6-466f-b8c7-81669b8d2964.metadata.json] for default.test_insert_concurrent_hnfkmo7wch
2023-03-21T10:32:20.2795846Z presto-master       | org.apache.iceberg.exceptions.CommitFailedException: Metadata location [hdfs://hadoop-master:9000/user/hive/warehouse/test_insert_concurrent_hnfkmo7wch-301c39c69015406893c9374937d39ae9/metadata/00038-a21ba75a-e302-439a-bac0-d00e0ad9d117.metadata.json] is not same as table metadata location [hdfs://hadoop-master:9000/user/hive/warehouse/test_insert_concurrent_hnfkmo7wch-301c39c69015406893c9374937d39ae9/metadata/00039-ac995477-96a6-466f-b8c7-81669b8d2964.metadata.json] for default.test_insert_concurrent_hnfkmo7wch
2023-03-21T10:32:20.2798089Z presto-master       | 	at io.trino.plugin.iceberg.catalog.hms.HiveMetastoreTableOperations.commitToExistingTable(HiveMetastoreTableOperations.java:81)
2023-03-21T10:32:20.2799929Z presto-master       | 	at io.trino.plugin.iceberg.catalog.AbstractIcebergTableOperations.commit(AbstractIcebergTableOperations.java:162)
2023-03-21T10:32:20.2801255Z presto-master       | 	at org.apache.iceberg.BaseTransaction.lambda$commitSimpleTransaction$5(BaseTransaction.java:403)
2023-03-21T10:32:20.2803204Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.runTaskWithRetry(Tasks.java:402)
2023-03-21T10:32:20.2804263Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.runSingleThreaded(Tasks.java:212)
2023-03-21T10:32:20.2805196Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.run(Tasks.java:196)
2023-03-21T10:32:20.2808324Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.run(Tasks.java:189)
2023-03-21T10:32:20.2809593Z presto-master       | 	at org.apache.iceberg.BaseTransaction.commitSimpleTransaction(BaseTransaction.java:394)
2023-03-21T10:32:20.2810713Z presto-master       | 	at org.apache.iceberg.BaseTransaction.commitTransaction(BaseTransaction.java:277)
2023-03-21T10:32:20.2812004Z presto-master       | 	at io.trino.plugin.iceberg.IcebergMetadata.finishInsert(IcebergMetadata.java:914)
2023-03-21T10:32:20.2813444Z presto-master       | 	at io.trino.plugin.base.classloader.ClassLoaderSafeConnectorMetadata.finishInsert(ClassLoaderSafeConnectorMetadata.java:528)
2023-03-21T10:32:20.2814628Z presto-master       | 	at io.trino.metadata.MetadataManager.finishInsert(MetadataManager.java:933)
2023-03-21T10:32:20.2815862Z presto-master       | 	at io.trino.sql.planner.LocalExecutionPlanner.lambda$createTableFinisher$4(LocalExecutionPlanner.java:4133)
2023-03-21T10:32:20.2817131Z presto-master       | 	at io.trino.operator.TableFinishOperator.getOutput(TableFinishOperator.java:319)
2023-03-21T10:32:20.2818110Z presto-master       | 	at io.trino.operator.Driver.processInternal(Driver.java:402)
2023-03-21T10:32:20.2818973Z presto-master       | 	at io.trino.operator.Driver.lambda$process$8(Driver.java:305)
2023-03-21T10:32:20.2819677Z presto-master       | 	at io.trino.operator.Driver.tryWithLock(Driver.java:701)
2023-03-21T10:32:20.2820323Z presto-master       | 	at io.trino.operator.Driver.process(Driver.java:297)
2023-03-21T10:32:20.2821751Z presto-master       | 	at io.trino.operator.Driver.processForDuration(Driver.java:268)
2023-03-21T10:32:20.2822629Z presto-master       | 	at io.trino.execution.SqlTaskExecution$DriverSplitRunner.processFor(SqlTaskExecution.java:838)
2023-03-21T10:32:20.2823546Z presto-master       | 	at io.trino.execution.executor.PrioritizedSplitRunner.process(PrioritizedSplitRunner.java:165)
2023-03-21T10:32:20.2825513Z presto-master       | 	at io.trino.execution.executor.TaskExecutor$TaskRunner.run(TaskExecutor.java:537)
2023-03-21T10:32:20.2826705Z presto-master       | 	at io.trino.$gen.Trino_410_182_gbc1c6d1____20230321_102928_2.run(Unknown Source)
2023-03-21T10:32:20.2827728Z presto-master       | 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
2023-03-21T10:32:20.2829012Z presto-master       | 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2023-03-21T10:32:20.2830802Z presto-master       | 	at java.base/java.lang.Thread.run(Thread.java:833)
2023-03-21T10:32:20.2831531Z presto-master       | 
2023-03-21T10:32:20.2832328Z presto-master       | 
2023-03-21T10:32:20.3593832Z presto-master       | 2023-03-21T16:17:20.358+0545	INFO	20230321_103217_00020_vy3b4.0.0.0-2-95	org.apache.iceberg.SnapshotProducer	Committed snapshot 484776559327023648 (MergeAppend)
2023-03-21T10:32:20.4680476Z presto-master       | 2023-03-21T16:17:20.465+0545	WARN	20230321_103217_00020_vy3b4.0.0.0-2-95	org.apache.iceberg.util.Tasks	Retrying task after failure: Metadata location [hdfs://hadoop-master:9000/user/hive/warehouse/test_insert_concurrent_hnfkmo7wch-301c39c69015406893c9374937d39ae9/metadata/00038-a21ba75a-e302-439a-bac0-d00e0ad9d117.metadata.json] is not same as table metadata location [hdfs://hadoop-master:9000/user/hive/warehouse/test_insert_concurrent_hnfkmo7wch-301c39c69015406893c9374937d39ae9/metadata/00039-ac995477-96a6-466f-b8c7-81669b8d2964.metadata.json] for default.test_insert_concurrent_hnfkmo7wch
2023-03-21T10:32:20.4684451Z presto-master       | org.apache.iceberg.exceptions.CommitFailedException: Metadata location [hdfs://hadoop-master:9000/user/hive/warehouse/test_insert_concurrent_hnfkmo7wch-301c39c69015406893c9374937d39ae9/metadata/00038-a21ba75a-e302-439a-bac0-d00e0ad9d117.metadata.json] is not same as table metadata location [hdfs://hadoop-master:9000/user/hive/warehouse/test_insert_concurrent_hnfkmo7wch-301c39c69015406893c9374937d39ae9/metadata/00039-ac995477-96a6-466f-b8c7-81669b8d2964.metadata.json] for default.test_insert_concurrent_hnfkmo7wch
2023-03-21T10:32:20.4686820Z presto-master       | 	at io.trino.plugin.iceberg.catalog.hms.HiveMetastoreTableOperations.commitToExistingTable(HiveMetastoreTableOperations.java:81)
2023-03-21T10:32:20.4688466Z presto-master       | 	at io.trino.plugin.iceberg.catalog.AbstractIcebergTableOperations.commit(AbstractIcebergTableOperations.java:162)
2023-03-21T10:32:20.4689929Z presto-master       | 	at org.apache.iceberg.BaseTransaction.lambda$commitSimpleTransaction$5(BaseTransaction.java:403)
2023-03-21T10:32:20.4691044Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.runTaskWithRetry(Tasks.java:402)
2023-03-21T10:32:20.4692410Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.runSingleThreaded(Tasks.java:212)
2023-03-21T10:32:20.4693397Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.run(Tasks.java:196)
2023-03-21T10:32:20.4694324Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.run(Tasks.java:189)
2023-03-21T10:32:20.4695766Z presto-master       | 	at org.apache.iceberg.BaseTransaction.commitSimpleTransaction(BaseTransaction.java:394)
2023-03-21T10:32:20.4697408Z presto-master       | 	at org.apache.iceberg.BaseTransaction.commitTransaction(BaseTransaction.java:277)
2023-03-21T10:32:20.4699118Z presto-master       | 	at io.trino.plugin.iceberg.IcebergMetadata.finishInsert(IcebergMetadata.java:890)
2023-03-21T10:32:20.4700807Z presto-master       | 	at io.trino.plugin.base.classloader.ClassLoaderSafeConnectorMetadata.finishInsert(ClassLoaderSafeConnectorMetadata.java:528)
2023-03-21T10:32:20.4702174Z presto-master       | 	at io.trino.metadata.MetadataManager.finishInsert(MetadataManager.java:933)
2023-03-21T10:32:20.4703527Z presto-master       | 	at io.trino.sql.planner.LocalExecutionPlanner.lambda$createTableFinisher$4(LocalExecutionPlanner.java:4133)
2023-03-21T10:32:20.4704656Z presto-master       | 	at io.trino.operator.TableFinishOperator.getOutput(TableFinishOperator.java:319)
2023-03-21T10:32:20.4705460Z presto-master       | 	at io.trino.operator.Driver.processInternal(Driver.java:402)
2023-03-21T10:32:20.4706588Z presto-master       | 	at io.trino.operator.Driver.lambda$process$8(Driver.java:305)
2023-03-21T10:32:20.4707288Z presto-master       | 	at io.trino.operator.Driver.tryWithLock(Driver.java:701)
2023-03-21T10:32:20.4709256Z presto-master       | 	at io.trino.operator.Driver.process(Driver.java:297)
2023-03-21T10:32:20.4710482Z presto-master       | 	at io.trino.operator.Driver.processForDuration(Driver.java:268)
2023-03-21T10:32:20.4711368Z presto-master       | 	at io.trino.execution.SqlTaskExecution$DriverSplitRunner.processFor(SqlTaskExecution.java:838)
2023-03-21T10:32:20.4712658Z presto-master       | 	at io.trino.execution.executor.PrioritizedSplitRunner.process(PrioritizedSplitRunner.java:165)
2023-03-21T10:32:20.4713648Z presto-master       | 	at io.trino.execution.executor.TaskExecutor$TaskRunner.run(TaskExecutor.java:537)
2023-03-21T10:32:20.4714432Z presto-master       | 	at io.trino.$gen.Trino_410_182_gbc1c6d1____20230321_102928_2.run(Unknown Source)
2023-03-21T10:32:20.4715243Z presto-master       | 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
2023-03-21T10:32:20.4716370Z presto-master       | 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2023-03-21T10:32:20.4717136Z presto-master       | 	at java.base/java.lang.Thread.run(Thread.java:833)
2023-03-21T10:32:20.4717635Z presto-master       | 
2023-03-21T10:32:20.4718017Z presto-master       | 
2023-03-21T10:32:20.7606121Z presto-master       | 2023-03-21T16:17:20.759+0545	INFO	20230321_103217_00020_vy3b4.0.0.0-2-95	org.apache.iceberg.SnapshotProducer	Committed snapshot 484776559327023648 (MergeAppend)
2023-03-21T10:32:20.9116459Z tests               | 2023-03-21 16:17:20 INFO: not retrying; @Flaky annotation not present
2023-03-21T10:32:20.9128471Z tests               | 2023-03-21 16:17:20 INFO: Test io.trino.tests.product.iceberg.TestIcebergInsert.testIcebergConcurrentInsert took 1.00m
2023-03-21T10:32:20.9218661Z tests               | 2023-03-21 16:17:20 INFO: FAILURE     /    io.trino.tests.product.iceberg.TestIcebergInsert.testIcebergConcurrentInsert (Groups: hms_only, storage_formats_detailed, iceberg) took 60.0 seconds
2023-03-21T10:32:20.9234953Z tests               | 2023-03-21 16:17:20 SEVERE: Failure cause:
2023-03-21T10:32:20.9236087Z tests               | org.testng.internal.thread.ThreadTimeoutException: Method io.trino.tests.product.iceberg.TestIcebergInsert.testIcebergConcurrentInsert() didn't finish within the time-out 60000
2023-03-21T10:32:20.9237452Z tests               | 	at java.base@17.0.5/java.lang.Thread.interrupted(Thread.java:1026)
2023-03-21T10:32:20.9238343Z tests               | 	at java.base@17.0.5/java.util.concurrent.FutureTask.awaitDone(FutureTask.java:416)
2023-03-21T10:32:20.9239009Z tests               | 	at java.base@17.0.5/java.util.concurrent.FutureTask.get(FutureTask.java:190)
2023-03-21T10:32:20.9239751Z tests               | 	at java.base@17.0.5/java.util.concurrent.AbstractExecutorService.invokeAll(AbstractExecutorService.java:252)
2023-03-21T10:32:20.9244839Z tests               | 	at app//io.trino.tests.product.iceberg.TestIcebergInsert.testIcebergConcurrentInsert(TestIcebergInsert.java:62)
2023-03-21T10:32:20.9245947Z tests               | 	at java.base@17.0.5/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2023-03-21T10:32:20.9246916Z tests               | 	at java.base@17.0.5/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
2023-03-21T10:32:20.9258841Z tests               | 	at java.base@17.0.5/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2023-03-21T10:32:20.9259675Z tests               | 	at java.base@17.0.5/java.lang.reflect.Method.invoke(Method.java:568)
2023-03-21T10:32:20.9260529Z tests               | 	at app//org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:104)
2023-03-21T10:32:20.9261337Z tests               | 	at app//org.testng.internal.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:54)
2023-03-21T10:32:20.9262075Z tests               | 	at app//org.testng.internal.InvokeMethodRunnable.run(InvokeMethodRunnable.java:44)
2023-03-21T10:32:20.9262786Z tests               | 	at java.base@17.0.5/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
2023-03-21T10:32:20.9263897Z tests               | 	at java.base@17.0.5/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2023-03-21T10:32:20.9264604Z tests               | 	at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
2023-03-21T10:32:20.9265382Z tests               | 	at java.base@17.0.5/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2023-03-21T10:32:20.9265995Z tests               | 	at java.base@17.0.5/java.lang.Thread.run(Thread.java:833)
2023-03-21T10:32:20.9266419Z tests               | 
2023-03-21T10:32:20.9305155Z tests               | 2023-03-21 16:17:20 WARNING: Tests from io.trino.tests.product.iceberg.TestIcebergInsert took 1.02m
2023-03-21T10:32:21.2238486Z presto-master       | 2023-03-21T16:17:21.221+0545	WARN	20230321_103217_00020_vy3b4.0.0.0-2-95	org.apache.iceberg.BaseTransaction	Failed to load committed metadata, skipping clean-up
2023-03-21T10:32:21.2239448Z presto-master       | dev.failsafe.FailsafeException: java.lang.InterruptedException: sleep interrupted
2023-03-21T10:32:21.2240225Z presto-master       | 	at dev.failsafe.SyncExecutionImpl.executeSync(SyncExecutionImpl.java:196)
2023-03-21T10:32:21.2241011Z presto-master       | 	at dev.failsafe.FailsafeExecutor.call(FailsafeExecutor.java:376)
2023-03-21T10:32:21.2241676Z presto-master       | 	at dev.failsafe.FailsafeExecutor.get(FailsafeExecutor.java:112)
2023-03-21T10:32:21.2242698Z presto-master       | 	at io.trino.plugin.iceberg.catalog.AbstractIcebergTableOperations.refreshFromMetadataLocation(AbstractIcebergTableOperations.java:235)
2023-03-21T10:32:21.2243847Z presto-master       | 	at io.trino.plugin.iceberg.catalog.AbstractIcebergTableOperations.refresh(AbstractIcebergTableOperations.java:131)
2023-03-21T10:32:21.2244922Z presto-master       | 	at io.trino.plugin.iceberg.catalog.AbstractIcebergTableOperations.current(AbstractIcebergTableOperations.java:114)
2023-03-21T10:32:21.2245843Z presto-master       | 	at org.apache.iceberg.BaseTransaction.committedFiles(BaseTransaction.java:495)
2023-03-21T10:32:21.2246676Z presto-master       | 	at org.apache.iceberg.BaseTransaction.commitSimpleTransaction(BaseTransaction.java:430)
2023-03-21T10:32:21.2247516Z presto-master       | 	at org.apache.iceberg.BaseTransaction.commitTransaction(BaseTransaction.java:277)
2023-03-21T10:32:21.2248313Z presto-master       | 	at io.trino.plugin.iceberg.IcebergMetadata.finishInsert(IcebergMetadata.java:890)
2023-03-21T10:32:21.2249324Z presto-master       | 	at io.trino.plugin.base.classloader.ClassLoaderSafeConnectorMetadata.finishInsert(ClassLoaderSafeConnectorMetadata.java:528)
2023-03-21T10:32:21.2250237Z presto-master       | 	at io.trino.metadata.MetadataManager.finishInsert(MetadataManager.java:933)
2023-03-21T10:32:21.2251099Z presto-master       | 	at io.trino.sql.planner.LocalExecutionPlanner.lambda$createTableFinisher$4(LocalExecutionPlanner.java:4133)
2023-03-21T10:32:21.2251933Z presto-master       | 	at io.trino.operator.TableFinishOperator.getOutput(TableFinishOperator.java:319)
2023-03-21T10:32:21.2252679Z presto-master       | 	at io.trino.operator.Driver.processInternal(Driver.java:402)
2023-03-21T10:32:21.2253323Z presto-master       | 	at io.trino.operator.Driver.lambda$process$8(Driver.java:305)
2023-03-21T10:32:21.2253964Z presto-master       | 	at io.trino.operator.Driver.tryWithLock(Driver.java:701)
2023-03-21T10:32:21.2254575Z presto-master       | 	at io.trino.operator.Driver.process(Driver.java:297)
2023-03-21T10:32:21.2255435Z presto-master       | 	at io.trino.operator.Driver.processForDuration(Driver.java:268)
2023-03-21T10:32:21.2256654Z presto-master       | 	at io.trino.execution.SqlTaskExecution$DriverSplitRunner.processFor(SqlTaskExecution.java:838)
2023-03-21T10:32:21.2257927Z presto-master       | 	at io.trino.execution.executor.PrioritizedSplitRunner.process(PrioritizedSplitRunner.java:165)
2023-03-21T10:32:21.2259133Z presto-master       | 	at io.trino.execution.executor.TaskExecutor$TaskRunner.run(TaskExecutor.java:537)
2023-03-21T10:32:21.2260084Z presto-master       | 	at io.trino.$gen.Trino_410_182_gbc1c6d1____20230321_102928_2.run(Unknown Source)
2023-03-21T10:32:21.2260806Z presto-master       | 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
2023-03-21T10:32:21.2261594Z presto-master       | 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2023-03-21T10:32:21.2262242Z presto-master       | 	at java.base/java.lang.Thread.run(Thread.java:833)
2023-03-21T10:32:21.2262829Z presto-master       | Caused by: java.lang.InterruptedException: sleep interrupted
2023-03-21T10:32:21.2263419Z presto-master       | 	at java.base/java.lang.Thread.sleep(Native Method)
2023-03-21T10:32:21.2264292Z presto-master       | 	at dev.failsafe.internal.RetryPolicyExecutor.lambda$apply$0(RetryPolicyExecutor.java:89)
2023-03-21T10:32:21.2265323Z presto-master       | 	at dev.failsafe.SyncExecutionImpl.executeSync(SyncExecutionImpl.java:187)
2023-03-21T10:32:21.2265892Z presto-master       | 	... 25 more
2023-03-21T10:32:21.2266281Z presto-master       | 
2023-03-21T10:32:21.2266624Z presto-master       | 
2023-03-21T10:32:21.2441489Z presto-master       | 2023-03-21T16:17:21.242+0545	WARN	20230321_103217_00019_vy3b4.0.0.0-2-92	org.apache.iceberg.util.Tasks	Retrying task after failure: Metadata location [hdfs://hadoop-master:9000/user/hive/warehouse/test_insert_concurrent_hnfkmo7wch-301c39c69015406893c9374937d39ae9/metadata/00039-ac995477-96a6-466f-b8c7-81669b8d2964.metadata.json] is not same as table metadata location [hdfs://hadoop-master:9000/user/hive/warehouse/test_insert_concurrent_hnfkmo7wch-301c39c69015406893c9374937d39ae9/metadata/00040-a07e2fc3-3319-4c8d-9b08-f93d437e0f71.metadata.json] for default.test_insert_concurrent_hnfkmo7wch
2023-03-21T10:32:21.2443965Z presto-master       | org.apache.iceberg.exceptions.CommitFailedException: Metadata location [hdfs://hadoop-master:9000/user/hive/warehouse/test_insert_concurrent_hnfkmo7wch-301c39c69015406893c9374937d39ae9/metadata/00039-ac995477-96a6-466f-b8c7-81669b8d2964.metadata.json] is not same as table metadata location [hdfs://hadoop-master:9000/user/hive/warehouse/test_insert_concurrent_hnfkmo7wch-301c39c69015406893c9374937d39ae9/metadata/00040-a07e2fc3-3319-4c8d-9b08-f93d437e0f71.metadata.json] for default.test_insert_concurrent_hnfkmo7wch
2023-03-21T10:32:21.2445770Z presto-master       | 	at io.trino.plugin.iceberg.catalog.hms.HiveMetastoreTableOperations.commitToExistingTable(HiveMetastoreTableOperations.java:81)
2023-03-21T10:32:21.2447021Z presto-master       | 	at io.trino.plugin.iceberg.catalog.AbstractIcebergTableOperations.commit(AbstractIcebergTableOperations.java:162)
2023-03-21T10:32:21.2447953Z presto-master       | 	at org.apache.iceberg.BaseTransaction.lambda$commitSimpleTransaction$5(BaseTransaction.java:403)
2023-03-21T10:32:21.2448706Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.runTaskWithRetry(Tasks.java:402)
2023-03-21T10:32:21.2449410Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.runSingleThreaded(Tasks.java:212)
2023-03-21T10:32:21.2450050Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.run(Tasks.java:196)
2023-03-21T10:32:21.2450672Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.run(Tasks.java:189)
2023-03-21T10:32:21.2451419Z presto-master       | 	at org.apache.iceberg.BaseTransaction.commitSimpleTransaction(BaseTransaction.java:394)
2023-03-21T10:32:21.2452220Z presto-master       | 	at org.apache.iceberg.BaseTransaction.commitTransaction(BaseTransaction.java:277)
2023-03-21T10:32:21.2453010Z presto-master       | 	at io.trino.plugin.iceberg.IcebergMetadata.finishInsert(IcebergMetadata.java:914)
2023-03-21T10:32:21.2454128Z presto-master       | 	at io.trino.plugin.base.classloader.ClassLoaderSafeConnectorMetadata.finishInsert(ClassLoaderSafeConnectorMetadata.java:528)
2023-03-21T10:32:21.2455193Z presto-master       | 	at io.trino.metadata.MetadataManager.finishInsert(MetadataManager.java:933)
2023-03-21T10:32:21.2456778Z presto-master       | 	at io.trino.sql.planner.LocalExecutionPlanner.lambda$createTableFinisher$4(LocalExecutionPlanner.java:4133)
2023-03-21T10:32:21.2458213Z presto-master       | 	at io.trino.operator.TableFinishOperator.getOutput(TableFinishOperator.java:319)
2023-03-21T10:32:21.2459090Z presto-master       | 	at io.trino.operator.Driver.processInternal(Driver.java:402)
2023-03-21T10:32:21.2459728Z presto-master       | 	at io.trino.operator.Driver.lambda$process$8(Driver.java:305)
2023-03-21T10:32:21.2460485Z presto-master       | 	at io.trino.operator.Driver.tryWithLock(Driver.java:701)
2023-03-21T10:32:21.2461069Z presto-master       | 	at io.trino.operator.Driver.process(Driver.java:297)
2023-03-21T10:32:21.2461899Z presto-master       | 	at io.trino.operator.Driver.processForDuration(Driver.java:268)
2023-03-21T10:32:21.2463068Z presto-master       | 	at io.trino.execution.SqlTaskExecution$DriverSplitRunner.processFor(SqlTaskExecution.java:838)
2023-03-21T10:32:21.2464212Z presto-master       | 	at io.trino.execution.executor.PrioritizedSplitRunner.process(PrioritizedSplitRunner.java:165)
2023-03-21T10:32:21.2465082Z presto-master       | 	at io.trino.execution.executor.TaskExecutor$TaskRunner.run(TaskExecutor.java:537)
2023-03-21T10:32:21.2466229Z presto-master       | 	at io.trino.$gen.Trino_410_182_gbc1c6d1____20230321_102928_2.run(Unknown Source)
2023-03-21T10:32:21.2466976Z presto-master       | 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
2023-03-21T10:32:21.2467990Z presto-master       | 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2023-03-21T10:32:21.2468641Z presto-master       | 	at java.base/java.lang.Thread.run(Thread.java:833)
2023-03-21T10:32:21.2469245Z presto-master       | 
2023-03-21T10:32:21.2469579Z presto-master       | 
2023-03-21T10:32:21.2494765Z presto-master       | 2023-03-21T16:17:21.248+0545	ERROR	20230321_103217_00019_vy3b4.0.0.0-2-92	io.trino.plugin.iceberg.IcebergMetadata	Failed to save table statistics
2023-03-21T10:32:21.2495565Z presto-master       | java.lang.RuntimeException: java.lang.InterruptedException: sleep interrupted
2023-03-21T10:32:21.2496544Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.runTaskWithRetry(Tasks.java:451)
2023-03-21T10:32:21.2497301Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.runSingleThreaded(Tasks.java:212)
2023-03-21T10:32:21.2497962Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.run(Tasks.java:196)
2023-03-21T10:32:21.2498599Z presto-master       | 	at org.apache.iceberg.util.Tasks$Builder.run(Tasks.java:189)
2023-03-21T10:32:21.2499363Z presto-master       | 	at org.apache.iceberg.BaseTransaction.commitSimpleTransaction(BaseTransaction.java:394)
2023-03-21T10:32:21.2500751Z presto-master       | 	at org.apache.iceberg.BaseTransaction.commitTransaction(BaseTransaction.java:277)
2023-03-21T10:32:21.2501890Z presto-master       | 	at io.trino.plugin.iceberg.IcebergMetadata.finishInsert(IcebergMetadata.java:914)
2023-03-21T10:32:21.2503417Z presto-master       | 	at io.trino.plugin.base.classloader.ClassLoaderSafeConnectorMetadata.finishInsert(ClassLoaderSafeConnectorMetadata.java:528)
2023-03-21T10:32:21.2504796Z presto-master       | 	at io.trino.metadata.MetadataManager.finishInsert(MetadataManager.java:933)
2023-03-21T10:32:21.2505758Z presto-master       | 	at io.trino.sql.planner.Loca
@findepi findepi added the bug Something isn't working label Mar 21, 2023
@findepi findepi mentioned this issue Mar 21, 2023
Merged
@findepi
Copy link
Member Author

findepi commented Mar 21, 2023

https://github.com/trinodb/trino/actions/runs/4479729229/jobs/7874385405?pr=16644

@findepi findepi mentioned this issue Mar 21, 2023
Merged
@findepi
Copy link
Member Author

findepi commented Mar 22, 2023

https://github.com/trinodb/trino/actions/runs/4488966780/jobs/7896061512?pr=16644

@ebyhr
Copy link
Member

ebyhr commented Mar 23, 2023

https://github.com/trinodb/trino/actions/runs/4497438041/jobs/7913164866?pr=16321

@ebyhr
Copy link
Member

ebyhr commented Mar 23, 2023

This might be a regression due to the recent change. Perhaps, bf04a72?

@ebyhr ebyhr mentioned this issue Mar 23, 2023
Merged
@findepi findepi self-assigned this Mar 23, 2023
This was referenced Mar 23, 2023
Draft
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@findepi findepi

Labels
bug Something isn't working
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix TestIcebergInsert.testIcebergConcurrentInsert timeout on CI findepi/trino
2 participants
@findepi @ebyhr