[
https://issues.apache.org/jira/browse/HIVE-23437?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Marc Demierre updated HIVE-23437:
---------------------------------
Summary: Concurrent partition creation requests cause underlying HDFS
folder to be deleted (was: Concurrent partition creation requests cause HDFS
folder to be deleted)
> Concurrent partition creation requests cause underlying HDFS folder to be
> deleted
> ---------------------------------------------------------------------------------
>
> Key: HIVE-23437
> URL: https://issues.apache.org/jira/browse/HIVE-23437
> Project: Hive
> Issue Type: Bug
> Components: HiveServer2, Standalone Metastore
> Affects Versions: 2.1.0, 3.1.2
> Environment: * Hive version: 1.2.1000.2.6.5.0-292 (HDP 2.6.5)
> * HDFS version: 2.7.3.2.6.5.0-292 (HDP 2.6.5)
> Reporter: Marc Demierre
> Priority: Major
>
> There seems to be a race condition in Hive Metasore when issuing several
> concurrent partition creation requests for the same new partition.
> In our case, this triggered due to Kafka Connect Hive integration, which
> fires simultaneous partition creation requests from all its tasks when
> syncing to Hive.
> We are running HDP 2.6.5 but a quick survey of the upstream code still shows
> the same in 3.1.2 (latest Hive release).
> Our investigation pointed to the following code (here in Hive 2.1.0, the base
> for HDP 2.6.5):
> [https://github.com/apache/hive/blob/rel/release-2.1.0/metastore/src/java/org/apache/hadoop/hive/metastore/HiveMetaStore.java#L2127]
> Same code in 3.1.2:
> https://github.com/apache/hive/blob/rel/release-3.1.2/standalone-metastore/src/main/java/org/apache/hadoop/hive/metastore/HiveMetaStore.java#L3202
> The generic scenario is the following:
> # T1 (time period 1):
> ** R1 (request 1) creates the HDFS dir
> ** R2 also tries creating the HDFS dir
> ** Both succeed (as if it already exists it succeeds, R1/R2 could be
> interverted)
> # T2:
> ** R1 creates the partition in metastore DB, all OK
> # T3:
> ** R2 tries to create partition in metastore DB, gets exception because it
> exists. Rollback transaction.
> ** R2 thinks it created the directory, so it removes it
> # T4: State is invalid:
> ## Partition exists
> ## HDFS folder does not exist
> ## Some Hive/Spark queries fail when trying to use the folder
> Here are some logs of the issue happening on our cluster (R1 = thread 2303,
> R2 = thread 2302):
> {code:java}
> 2020-05-11 13:43:46,379 INFO [pool-7-thread-2303]: metastore.HiveMetaStore
> (HiveMetaStore.java:logInfo(775)) - 2303: append_partition_by_name:
> db=sbd_dev_autodump tbl=sbd_dev_debug_hive_4 part=time=ingestion/buc
> ket=hourly/date=2020-05-11/hour=11
> 2020-05-11 13:43:46,379 INFO [pool-7-thread-2302]: metastore.HiveMetaStore
> (HiveMetaStore.java:logInfo(775)) - 2302: append_partition_by_name:
> db=sbd_dev_autodump tbl=sbd_dev_debug_hive_4 part=time=ingestion/buc
> ket=hourly/date=2020-05-11/hour=11
> 2020-05-11 13:43:46,379 INFO [pool-7-thread-2303]: HiveMetaStore.audit
> (HiveMetaStore.java:logAuditEvent(319)) -
> [email protected] ip=10.222.76.1
> cmd=append_partition_by_name
> : db=sbd_dev_autodump tbl=sbd_dev_debug_hive_4
> part=time=ingestion/bucket=hourly/date=2020-05-11/hour=11
> 2020-05-11 13:43:46,379 INFO [pool-7-thread-2302]: HiveMetaStore.audit
> (HiveMetaStore.java:logAuditEvent(319)) -
> [email protected] ip=10.222.76.1
> cmd=append_partition_by_name
> : db=sbd_dev_autodump tbl=sbd_dev_debug_hive_4
> part=time=ingestion/bucket=hourly/date=2020-05-11/hour=11
> 2020-05-11 13:43:47,953 INFO [pool-7-thread-2302]: common.FileUtils
> (FileUtils.java:mkdir(573)) - Creating directory if it doesn't exist:
> hdfs://sbd/data/sbd/dev/sbd.dev.debug-hive-4/time=ingestion/bucket=hourly
> /date=2020-05-11/hour=11
> 2020-05-11 13:43:47,957 INFO [pool-7-thread-2303]: common.FileUtils
> (FileUtils.java:mkdir(573)) - Creating directory if it doesn't exist:
> hdfs://sbd/data/sbd/dev/sbd.dev.debug-hive-4/time=ingestion/bucket=hourly
> /date=2020-05-11/hour=11
> 2020-05-11 13:43:47,986 INFO [pool-7-thread-2302]:
> metastore.hivemetastoressimpl (HiveMetaStoreFsImpl.java:deleteDir(41)) -
> deleting
> hdfs://sbd/data/sbd/dev/sbd.dev.debug-hive-4/time=ingestion/bucket=hourly/dat
> e=2020-05-11/hour=11
> 2020-05-11 13:43:47,992 INFO [pool-7-thread-2302]: fs.TrashPolicyDefault
> (TrashPolicyDefault.java:moveToTrash(168)) - Moved:
> 'hdfs://sbd/data/sbd/dev/sbd.dev.debug-hive-4/time=ingestion/bucket=hourly/date=2020-05-11/hour=11'
> to trash at:
> hdfs://sbd/user/sbd-fh-connect-autodumphdfs/.Trash/Current/data/sbd/dev/sbd.dev.debug-hive-4/time=ingestion/bucket=hourly/date=2020-05-11/hour=11
> 2020-05-11 13:43:47,993 INFO [pool-7-thread-2302]:
> metastore.hivemetastoressimpl (HiveMetaStoreFsImpl.java:deleteDir(48)) -
> Moved to trash:
> hdfs://sbd/data/sbd/dev/sbd.dev.debug-hive-4/time=ingestion/bucket=hourly/date=2020-05-11/hour=11
> 2020-05-11 13:43:47,993 ERROR [pool-7-thread-2302]:
> metastore.RetryingHMSHandler (RetryingHMSHandler.java:invokeInternal(217)) -
> Retrying HMSHandler after 2000 ms (attempt 1 of 10) with error:
> javax.jdo.JDODataStoreException: Insert of object
> "org.apache.hadoop.hive.metastore.model.MPartition@548a5b6c" using statement
> "INSERT INTO "PARTITIONS"
> ("PART_ID","CREATE_TIME","LAST_ACCESS_TIME","PART_NAME","SD_ID","TBL_ID")
> VALUES (?,?,?,?,?,?)" failed : ERROR: duplicate key value violates unique
> constraint "UNIQUEPARTITION"
> Detail: Key ("PART_NAME",
> "TBL_ID")=(time=ingestion/bucket=hourly/date=2020-05-11/hour=11, 6015512)
> already exists.
> at
> org.datanucleus.api.jdo.NucleusJDOHelper.getJDOExceptionForNucleusException(NucleusJDOHelper.java:543)
> at
> org.datanucleus.api.jdo.JDOPersistenceManager.jdoMakePersistent(JDOPersistenceManager.java:720)
> at
> org.datanucleus.api.jdo.JDOPersistenceManager.makePersistent(JDOPersistenceManager.java:740)
> at
> org.apache.hadoop.hive.metastore.ObjectStore.addPartition(ObjectStore.java:1626)
> at sun.reflect.GeneratedMethodAccessor255.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> org.apache.hadoop.hive.metastore.RawStoreProxy.invoke(RawStoreProxy.java:103)
> at com.sun.proxy.$Proxy11.addPartition(Unknown Source)
> at
> org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.append_partition_common(HiveMetaStore.java:2247)
> at
> org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.append_partition_by_name_with_environment_context(HiveMetaStore.java:4294)
> at sun.reflect.GeneratedMethodAccessor214.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:147)
> at
> org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:105)
> at
> com.sun.proxy.$Proxy13.append_partition_by_name_with_environment_context(Unknown
> Source)
> at
> org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$append_partition_by_name_with_environment_context.getResult(ThriftHiveMetastore.java:10192)
> at
> org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$append_partition_by_name_with_environment_context.getResult(ThriftHiveMetastore.java:10176)
> at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
> at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
> at
> org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:551)
> at
> org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:546)
> at java.security.AccessController.doPrivileged(Native Method)
> at javax.security.auth.Subject.doAs(Subject.java:422)
> at
> org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1869)
> at
> org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor.process(HadoopThriftAuthBridge.java:546)
> at
> org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286)
> 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)
> NestedThrowablesStackTrace:
> org.postgresql.util.PSQLException: ERROR: duplicate key value violates unique
> constraint "UNIQUEPARTITION"
> Detail: Key ("PART_NAME",
> "TBL_ID")=(time=ingestion/bucket=hourly/date=2020-05-11/hour=11, 6015512)
> already exists.
> at
> org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2440)
> at
> org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2183)
> at
> org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:308)
> at
> org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:441)
> at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:365)
> at
> org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:150)
> at
> org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:127)
> at
> com.jolbox.bonecp.PreparedStatementHandle.executeUpdate(PreparedStatementHandle.java:205)
> at
> org.datanucleus.store.rdbms.ParamLoggingPreparedStatement.executeUpdate(ParamLoggingPreparedStatement.java:393)
> at
> org.datanucleus.store.rdbms.SQLController.executeStatementUpdate(SQLController.java:431)
> at
> org.datanucleus.store.rdbms.request.InsertRequest.execute(InsertRequest.java:413)
> at
> org.datanucleus.store.rdbms.RDBMSPersistenceHandler.insertObjectInTable(RDBMSPersistenceHandler.java:162)
> at
> org.datanucleus.store.rdbms.RDBMSPersistenceHandler.insertObject(RDBMSPersistenceHandler.java:138)
> at
> org.datanucleus.state.StateManagerImpl.internalMakePersistent(StateManagerImpl.java:3363)
> at
> org.datanucleus.state.StateManagerImpl.makePersistent(StateManagerImpl.java:3339)
> at
> org.datanucleus.ExecutionContextImpl.persistObjectInternal(ExecutionContextImpl.java:2079)
> at
> org.datanucleus.ExecutionContextImpl.persistObjectWork(ExecutionContextImpl.java:1922)
> at
> org.datanucleus.ExecutionContextImpl.persistObject(ExecutionContextImpl.java:1777)
> at
> org.datanucleus.ExecutionContextThreadedImpl.persistObject(ExecutionContextThreadedImpl.java:217)
> at
> org.datanucleus.api.jdo.JDOPersistenceManager.jdoMakePersistent(JDOPersistenceManager.java:715)
> at
> org.datanucleus.api.jdo.JDOPersistenceManager.makePersistent(JDOPersistenceManager.java:740)
> at
> org.apache.hadoop.hive.metastore.ObjectStore.addPartition(ObjectStore.java:1626)
> at sun.reflect.GeneratedMethodAccessor255.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> org.apache.hadoop.hive.metastore.RawStoreProxy.invoke(RawStoreProxy.java:103)
> at com.sun.proxy.$Proxy11.addPartition(Unknown Source)
> at
> org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.append_partition_common(HiveMetaStore.java:2247)
> at
> org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.append_partition_by_name_with_environment_context(HiveMetaStore.java:4294)
> at sun.reflect.GeneratedMethodAccessor214.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:147)
> at
> org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:105)
> at
> com.sun.proxy.$Proxy13.append_partition_by_name_with_environment_context(Unknown
> Source)
> at
> org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$append_partition_by_name_with_environment_context.getResult(ThriftHiveMetastore.java:10192)
> at
> org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$append_partition_by_name_with_environment_context.getResult(ThriftHiveMetastore.java:10176)
> at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
> at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
> at
> org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:551)
> at
> org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:546)
> at java.security.AccessController.doPrivileged(Native Method)
> at javax.security.auth.Subject.doAs(Subject.java:422)
> at
> org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1869)
> at
> org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor.process(HadoopThriftAuthBridge.java:546)
> at
> org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286)
> 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)
> 2020-05-11 13:43:49,994 INFO [pool-7-thread-2302]: metastore.HiveMetaStore
> (HiveMetaStore.java:logInfo(775)) - 2302: append_partition_by_name:
> db=sbd_dev_autodump tbl=sbd_dev_debug_hive_4
> part=time=ingestion/bucket=hourly/date=2020-05-11/hour=11
> 2020-05-11 13:43:49,994 INFO [pool-7-thread-2302]: HiveMetaStore.audit
> (HiveMetaStore.java:logAuditEvent(319)) -
> [email protected] ip=10.222.76.1
> cmd=append_partition_by_name: db=sbd_dev_autodump tbl=sbd_dev_debug_hive_4
> part=time=ingestion/bucket=hourly/date=2020-05-11/hour=11
> 2020-05-11 13:43:50,039 ERROR [pool-7-thread-2302]:
> metastore.RetryingHMSHandler (RetryingHMSHandler.java:invokeInternal(203)) -
> AlreadyExistsException(message:Partition already
> exists:Partition(values:[ingestion, hourly, 2020-05-11, 11],
> dbName:sbd_dev_autodump, tableName:sbd_dev_debug_hive_4, createTime:0,
> lastAccessTime:0, sd:StorageDescriptor(cols:[FieldSchema(name:name,
> type:string, comment:null), FieldSchema(name:age, type:int, comment:null),
> FieldSchema(name:salary, type:int, comment:null)],
> location:hdfs://sbd/data/sbd/dev/sbd.dev.debug-hive-4/time=ingestion/bucket=hourly/date=2020-05-11/hour=11,
> inputFormat:org.apache.hadoop.hive.ql.io.avro.AvroContainerInputFormat,
> outputFormat:org.apache.hadoop.hive.ql.io.avro.AvroContainerOutputFormat,
> compressed:false, numBuckets:-1, serdeInfo:SerDeInfo(name:null,
> serializationLib:org.apache.hadoop.hive.serde2.avro.AvroSerDe,
> parameters:{serialization.format=1}), bucketCols:[], sortCols:[],
> parameters:{}, skewedInfo:SkewedInfo(skewedColNames:[], skewedColValues:[],
> skewedColValueLocationMaps:{}), storedAsSubDirectories:false),
> parameters:null))
> at
> org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.append_partition_common(HiveMetaStore.java:2226)
> at
> org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.append_partition_by_name_with_environment_context(HiveMetaStore.java:4294)
> at sun.reflect.GeneratedMethodAccessor214.invoke(Unknown Source)
> at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.lang.reflect.Method.invoke(Method.java:498)
> at
> org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:147)
> at
> org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:105)
> at
> com.sun.proxy.$Proxy13.append_partition_by_name_with_environment_context(Unknown
> Source)
> at
> org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$append_partition_by_name_with_environment_context.getResult(ThriftHiveMetastore.java:10192)
> at
> org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$append_partition_by_name_with_environment_context.getResult(ThriftHiveMetastore.java:10176)
> at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
> at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
> at
> org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:551)
> at
> org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:546)
> at java.security.AccessController.doPrivileged(Native Method)
> at javax.security.auth.Subject.doAs(Subject.java:422)
> at
> org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1869)
> at
> org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor.process(HadoopThriftAuthBridge.java:546)
> at
> org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286)
> 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) {code}
>
> We're not sure on the best way to solve it. The obvious would be to not
> delete the folder on rollback but we do not know if it would have side
> effects (other than a useless folder in some cases).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
