Hive DELETE/UPDATE/MERGE on ACID/transactional tables produces incorrect results

[findepi]

https://github.com/trinodb/trino/actions/runs/3541969763/jobs/5948031373

2022-11-24T18:22:07.9630199Z tests               | 2022-11-25 00:07:07 INFO: FAILURE     /    io.trino.tests.product.hive.TestHiveMerge.testMergeUpdateWithVariousLayouts [true, ] (Groups: hive_transactional) took 5.2 seconds
2022-11-24T18:22:07.9645101Z tests               | 2022-11-25 00:07:07 SEVERE: Failure cause:
2022-11-24T18:22:07.9645609Z tests               | java.lang.AssertionError: [onTrino] Expected row count to be <3>, but was <4>; rows=[[Joe, jellybeans], [Dave, dates], [Joe, jellybeans], [Carol_Craig, candles]]
2022-11-24T18:22:07.9646265Z tests               | 	at io.trino.tests.product.hive.TestHiveTransactionalTable.verifySelect(TestHiveTransactionalTable.java:2236)
2022-11-24T18:22:07.9647023Z tests               | 	at io.trino.tests.product.hive.TestHiveTransactionalTable.verifySelectForTrinoAndHive(TestHiveTransactionalTable.java:2226)
2022-11-24T18:22:07.9647731Z tests               | 	at io.trino.tests.product.hive.TestHiveMerge.lambda$testMergeUpdateWithVariousLayouts$4(TestHiveMerge.java:128)
2022-11-24T18:22:07.9648325Z tests               | 	at io.trino.tests.product.hive.TestHiveMerge.withTemporaryTable(TestHiveMerge.java:764)
2022-11-24T18:22:07.9648922Z tests               | 	at io.trino.tests.product.hive.TestHiveMerge.lambda$testMergeUpdateWithVariousLayouts$5(TestHiveMerge.java:116)
2022-11-24T18:22:07.9649498Z tests               | 	at io.trino.tests.product.hive.TestHiveMerge.withTemporaryTable(TestHiveMerge.java:764)
2022-11-24T18:22:07.9650099Z tests               | 	at io.trino.tests.product.hive.TestHiveMerge.testMergeUpdateWithVariousLayouts(TestHiveMerge.java:100)
2022-11-24T18:22:07.9650905Z tests               | 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2022-11-24T18:22:07.9651463Z tests               | 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
2022-11-24T18:22:07.9652153Z tests               | 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2022-11-24T18:22:07.9652670Z tests               | 	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
2022-11-24T18:22:07.9653176Z tests               | 	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:104)
2022-11-24T18:22:07.9653847Z tests               | 	at org.testng.internal.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:54)
2022-11-24T18:22:07.9654359Z tests               | 	at org.testng.internal.InvokeMethodRunnable.run(InvokeMethodRunnable.java:44)
2022-11-24T18:22:07.9654842Z tests               | 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
2022-11-24T18:22:07.9655299Z tests               | 	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2022-11-24T18:22:07.9655805Z tests               | 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
2022-11-24T18:22:07.9656341Z tests               | 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
2022-11-24T18:22:07.9656779Z tests               | 	at java.base/java.lang.Thread.run(Thread.java:833)
2022-11-24T18:22:07.9657055Z tests               | 

cc @djsstarburst

[ebyhr]

https://github.com/trinodb/trino/actions/runs/4362853748/jobs/7629375937

[djsagain]

https://github.com/trinodb/trino/actions/runs/4362853748/jobs/7629375937

@ebyhr, I'm not sure if this recent test failure is similar to the case from November. Looking at the logs, the root cause of this failure was some sort of problem writing the orc_acid_version for a delete_delta directory to the HDFS file system:

tests               | 2023-03-08 18:14:35 INFO: [63 of 483] io.trino.tests.product.hive.TestHiveMerge.testMergeUpdateWithVariousLayouts [false, CLUSTERED BY (customer) INTO 3 BUCKETS] (Groups: hive_transactional)
...
presto-master       | 2023-03-08T18:14:39.361+0545	ERROR	SplitRunner-3-95	io.trino.execution.executor.TaskExecutor	Error processing Split 20230308_122938_00294_pv4zw.0.0.0-2  (start = 1015271.616682, wall = 680 ms, cpu = 0 ms, wait = 2 ms, calls = 4): HIVE_FILESYSTEM_ERROR: Exception writing _orc_acid_version file for delta directory: hdfs://hadoop-master:9000/user/hive/warehouse/test_merge_update_with_various_formats_false_bucketed_v2_la8n7elnpz/delete_delta_0000002_0000002_0000
presto-master       | io.trino.spi.TrinoException: Exception writing _orc_acid_version file for delta directory: hdfs://hadoop-master:9000/user/hive/warehouse/test_merge_update_with_various_formats_false_bucketed_v2_la8n7elnpz/delete_delta_0000002_0000002_0000
presto-master       | 	at io.trino.plugin.hive.HiveMetadata.createOrcAcidVersionFile(HiveMetadata.java:2240)
presto-master       | 	at io.trino.plugin.hive.HiveMetadata.lambda$finishMerge$57(HiveMetadata.java:1945)
presto-master       | 	at java.base/java.util.Optional.ifPresent(Optional.java:178)
presto-master       | 	at io.trino.plugin.hive.HiveMetadata.finishMerge(HiveMetadata.java:1945)
presto-master       | 	at io.trino.plugin.base.classloader.ClassLoaderSafeConnectorMetadata.finishMerge(ClassLoaderSafeConnectorMetadata.java:1047)
presto-master       | 	at io.trino.metadata.MetadataManager.finishMerge(MetadataManager.java:1058)
presto-master       | 	at
...
presto-master       | Caused by: org.apache.hadoop.ipc.RemoteException(java.io.IOException): File /user/hive/warehouse/test_merge_update_with_various_formats_false_bucketed_v2_la8n7elnpz/delete_delta_0000002_0000002_0000/_orc_acid_version could only be written to 0 of the 1 minReplication nodes. There are 1 datanode(s) running and no node(s) are excluded in this operation.
presto-master       | 	at org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.chooseTarget4NewBlock(BlockManager.java:2121)
presto-master       | 	at org.apache.hadoop.hdfs.server.namenode.FSDirWriteFileOp.chooseTargetForNewBlock(FSDirWriteFileOp.java:286)
presto-master       | 	at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getAdditionalBlock(FSNamesystem.java:2706)
presto-master       | 	at org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.addBlock(NameNodeRpcServer.java:875)
presto-master       | 	at org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolServerSideTranslatorPB.addBlock(ClientNamenodeProtocolServerSideTranslatorPB.java:561)
presto-master       | 	at org.apache.hadoop.hdfs.protocol.proto.ClientNamenodeProtocolProtos$ClientNamenodeProtocol$2.callBlockingMethod(ClientNamenodeProtocolProtos.java)
presto-master       | 	at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:524)
presto-master       | 	at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:1025)

I'm guessing that the merge result was wrong and the test failed because the orc_acid_version file didn't get written, as showed by the backtrace. If the orc_acid_version file is not found in a delta or a delete_delta directory, files in that directory are ignored.

[findinpath]

https://github.com/trinodb/trino/actions/runs/4371864498/jobs/7648793956

[ebyhr]

TestHiveMerge.testMergeWithDifferentPartitioning failed.

tests               | 2023-04-21 10:58:44 INFO: FAILURE     /    io.trino.tests.product.hive.TestHiveMerge.testMergeWithDifferentPartitioning [target_partitioned_source_and_target_partitioned_and_bucketed, CREATE TABLE %s (customer STRING, purchases INT) PARTITIONED BY (address STRING) CLUSTERED BY (customer) INTO 3 BUCKETS STORED AS ORC TBLPROPERTIES ('transactional'='true'), CREATE TABLE %s (customer STRING, purchases INT) PARTITIONED BY (address STRING) CLUSTERED BY (customer) INTO 3 BUCKETS STORED AS ORC TBLPROPERTIES ('transactional'='true')] (Groups: hive_transactional) took 7.0 seconds
tests               | 2023-04-21 10:58:44 SEVERE: Failure cause:
tests               | java.lang.AssertionError: [onTrino] Expected row count to be <4>, but was <5>; rows=[[Carol, 9, Centreville], [Bill, 7, Buena], [Aaron, 17, Arches], [Dave, 33, Darbyshire], [Ed, 14, Etherville]]
tests               | 	at io.trino.tests.product.hive.TestHiveTransactionalTable.verifySelect(TestHiveTransactionalTable.java:2300)
tests               | 	at io.trino.tests.product.hive.TestHiveTransactionalTable.verifySelectForTrinoAndHive(TestHiveTransactionalTable.java:2292)
tests               | 	at io.trino.tests.product.hive.TestHiveMerge.lambda$testMergeWithDifferentPartitioningInternal$31(TestHiveMerge.java:460)
tests               | 	at io.trino.tests.product.hive.TestHiveMerge.withTemporaryTable(TestHiveMerge.java:764)
tests               | 	at io.trino.tests.product.hive.TestHiveMerge.lambda$testMergeWithDifferentPartitioningInternal$32(TestHiveMerge.java:448)
tests               | 	at io.trino.tests.product.hive.TestHiveMerge.withTemporaryTable(TestHiveMerge.java:764)
tests               | 	at io.trino.tests.product.hive.TestHiveMerge.testMergeWithDifferentPartitioningInternal(TestHiveMerge.java:443)
tests               | 	at io.trino.tests.product.hive.TestHiveMerge.testMergeWithDifferentPartitioning(TestHiveMerge.java:438)
tests               | 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
tests               | 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
tests               | 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
tests               | 	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
tests               | 	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:104)
tests               | 	at org.testng.internal.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:54)
tests               | 	at org.testng.internal.InvokeMethodRunnable.run(InvokeMethodRunnable.java:44)
tests               | 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
tests               | 	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
tests               | 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
tests               | 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
tests               | 	at java.base/java.lang.Thread.run(Thread.java:833)

https://github.com/trinodb/trino/actions/runs/4759236874/jobs/8459764590?pr=17137

[findepi]

https://github.com/trinodb/trino/pull/17365/checks?check_run_id=13425054315

TestHiveMerge > testMergeWithDifferentPartitioning(0: target_partitioned_target_partitioned_and_bucketed, 1: CREATE TABLE %s (customer STRING, purchases INT) PARTITIONED BY (address STRING) CLUSTERED BY (customer) INTO 3 BUCKETS STORED AS ORC TBLPROPERTIES ('transactional'='true'), 2: CREATE TABLE %s (purchases INT, address STRING) PARTITIONED BY (customer STRING) STORED AS ORC TBLPROPERTIES ('transactional'='true')) [groups: hive_transactional]
java.sql.SQLException: Query failed (#20230512_030913_00186_buged): One MERGE target table row matched more than one source row

[findepi]

tests               | 2023-06-01 02:49:15 INFO: not retrying; @Flaky annotation not present
tests               | 2023-06-01 02:49:15 INFO: FAILURE     /    io.trino.tests.product.hive.TestHiveMerge.testMergeMultipleOperationsUnbucketedPartitioned (Groups: hive_transactional) took 28.5 seconds
tests               | 2023-06-01 02:49:15 SEVERE: Failure cause:
tests               | java.lang.AssertionError: Could not find rows:
tests               | [joe_32, 5000, 85000, jen_32, 32 Poe Ct]
tests               | [joe_33, 5000, 85000, jen_33, 33 Poe Ct]
tests               | [joe_34, 5000, 85000, jen_34, 34 Poe Ct]
tests               | [joe_35, 5000, 85000, jen_35, 35 Poe Ct]
tests               | [joe_36, 5000, 85000, jen_36, 36 Poe Ct]
tests               | [joe_37, 5000, 85000, jen_37, 37 Poe Ct]
tests               | [joe_38, 5000, 85000, jen_38, 38 Poe Ct]
tests               | [joe_39, 5000, 85000, jen_39, 39 Poe Ct]
tests               | [joe_40, 5000, 85000, jen_40, 40 Poe Ct]
tests               | [joe_41, 5000, 85000, jen_41, 41 Poe Ct]
tests               | [joe_42, 5000, 85000, jen_42, 42 Poe Ct]
tests               | [joe_43, 5000, 85000, jen_43, 43 Poe Ct]
tests               | [joe_44, 5000, 85000, jen_44, 44 Poe Ct]
tests               | [joe_45, 5000, 85000, jen_45, 45 Poe Ct]
tests               | [joe_46, 5000, 85000, jen_46, 46 Poe Ct]
tests               | [joe_47, 5000, 85000, jen_47, 47 Poe Ct]
tests               | 
tests               | actual rows:
tests               | [jack_47, 4000, 74000, jan_47, 47 Poe Ct]
tests               | [joe_10, 5000, 85000, jen_10, 10 Poe Ct]
tests               | [joe_7, 5000, 85000, jen_7, 7 Poe Ct]
tests               | [joe_29, 3000, 60000, jill_29, 29 Eop Ct]
tests               | [jack_38, 4000, 74000, jan_38, 38 Poe Ct]
tests               | [joe_5, 5000, 85000, jen_5, 5 Poe Ct]
tests               | [joe_43, 5000, 60000, jen_43, 43 Poe Ct]
tests               | [joe_38, 5000, 60000, jen_38, 38 Poe Ct]
tests               | [joe_45, 5000, 60000, jen_45, 45 Poe Ct]
tests               | [joe_32, 5000, 60000, jen_32, 32 Poe Ct]
tests               | [joe_23, 3000, 60000, jill_23, 23 Eop Ct]
tests               | [jack_46, 4000, 74000, jan_46, 46 Poe Ct]
tests               | [joe_2, 5000, 85000, jen_2, 2 Poe Ct]
tests               | [joe_37, 5000, 60000, jen_37, 37 Poe Ct]
tests               | [joe_26, 3000, 60000, jill_26, 26 Eop Ct]
tests               | [joe_11, 5000, 85000, jen_11, 11 Poe Ct]
tests               | [jack_39, 4000, 74000, jan_39, 39 Poe Ct]
tests               | [joe_40, 5000, 60000, jen_40, 40 Poe Ct]
tests               | [joe_42, 5000, 60000, jen_42, 42 Poe Ct]
tests               | [joe_16, 3000, 60000, jill_16, 16 Eop Ct]
tests               | [jack_43, 4000, 74000, jan_43, 43 Poe Ct]
tests               | [joe_4, 5000, 85000, jen_4, 4 Poe Ct]
tests               | [jack_37, 4000, 74000, jan_37, 37 Poe Ct]
tests               | [joe_6, 5000, 85000, jen_6, 6 Poe Ct]
tests               | [jack_44, 4000, 74000, jan_44, 44 Poe Ct]
tests               | [joe_22, 3000, 60000, jill_22, 22 Eop Ct]
tests               | [joe_20, 3000, 60000, jill_20, 20 Eop Ct]
tests               | [joe_28, 3000, 60000, jill_28, 28 Eop Ct]
tests               | [jack_35, 4000, 74000, jan_35, 35 Poe Ct]
tests               | [joe_19, 3000, 60000, jill_19, 19 Eop Ct]
tests               | [joe_46, 5000, 60000, jen_46, 46 Poe Ct]
tests               | [joe_3, 5000, 85000, jen_3, 3 Poe Ct]
tests               | [jack_40, 4000, 74000, jan_40, 40 Poe Ct]
tests               | [joe_15, 5000, 85000, jen_15, 15 Poe Ct]
tests               | [joe_13, 5000, 85000, jen_13, 13 Poe Ct]
tests               | [joe_17, 3000, 60000, jill_17, 17 Eop Ct]
tests               | [joe_30, 3000, 60000, jill_30, 30 Eop Ct]
tests               | [joe_31, 3000, 60000, jill_31, 31 Eop Ct]
tests               | [jack_41, 4000, 74000, jan_41, 41 Poe Ct]
tests               | [joe_33, 5000, 60000, jen_33, 33 Poe Ct]
tests               | [joe_1, 5000, 85000, jen_1, 1 Poe Ct]
tests               | [jack_42, 4000, 74000, jan_42, 42 Poe Ct]
tests               | [joe_12, 5000, 85000, jen_12, 12 Poe Ct]
tests               | [jack_32, 4000, 74000, jan_32, 32 Poe Ct]
tests               | [joe_18, 3000, 60000, jill_18, 18 Eop Ct]
tests               | [joe_14, 5000, 85000, jen_14, 14 Poe Ct]
tests               | [joe_44, 5000, 60000, jen_44, 44 Poe Ct]
tests               | [joe_47, 5000, 60000, jen_47, 47 Poe Ct]
tests               | [joe_8, 5000, 85000, jen_8, 8 Poe Ct]
tests               | [joe_35, 5000, 60000, jen_35, 35 Poe Ct]
tests               | [jack_33, 4000, 74000, jan_33, 33 Poe Ct]
tests               | [joe_21, 3000, 60000, jill_21, 21 Eop Ct]
tests               | [joe_24, 3000, 60000, jill_24, 24 Eop Ct]
tests               | [joe_36, 5000, 60000, jen_36, 36 Poe Ct]
tests               | [jack_36, 4000, 74000, jan_36, 36 Poe Ct]
tests               | [joe_39, 5000, 60000, jen_39, 39 Poe Ct]
tests               | [joe_27, 3000, 60000, jill_27, 27 Eop Ct]
tests               | [joe_34, 5000, 60000, jen_34, 34 Poe Ct]
tests               | [jack_45, 4000, 74000, jan_45, 45 Poe Ct]
tests               | [joe_25, 3000, 60000, jill_25, 25 Eop Ct]
tests               | [jack_34, 4000, 74000, jan_34, 34 Poe Ct]
tests               | [joe_41, 5000, 60000, jen_41, 41 Poe Ct]
tests               | [joe_9, 5000, 85000, jen_9, 9 Poe Ct]
tests               | 	at io.trino.tests.product.hive.TestHiveMerge.verifyOnTrinoAndHiveFromQueryResults(TestHiveMerge.java:253)
tests               | 	at io.trino.tests.product.hive.TestHiveMerge.testMergeMultipleOperationsInternal(TestHiveMerge.java:247)
tests               | 	at io.trino.tests.product.hive.TestHiveMerge.lambda$testMergeMultipleOperationsUnbucketedPartitioned$9(TestHiveMerge.java:184)
tests               | 	at io.trino.tests.product.hive.TestHiveMerge.withTemporaryTable(TestHiveMerge.java:764)
tests               | 	at io.trino.tests.product.hive.TestHiveMerge.testMergeMultipleOperationsUnbucketedPartitioned(TestHiveMerge.java:182)
tests               | 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
tests               | 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
tests               | 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
tests               | 	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
tests               | 	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:104)
tests               | 	at org.testng.internal.InvokeMethodRunnable.runOne(InvokeMethodRunnable.java:54)
tests               | 	at org.testng.internal.InvokeMethodRunnable.run(InvokeMethodRunnable.java:44)
tests               | 	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
tests               | 	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
tests               | 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
tests               | 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
tests               | 	at java.base/java.lang.Thread.run(Thread.java:833)