Marc Demierre created HIVE-23437: ------------------------------------ Summary: Concurrent partition creation requests cause 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 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
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 it in 3.1.2 (latest Hive release). Our investigation pointed to the following code: [https://github.com/apache/hive/blob/rel/release-2.1.0/metastore/src/java/org/apache/hadoop/hive/metastore/HiveMetaStore.java#L2127] 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)) - ugi=sbd-fh-connect-autodumph...@sbd.corproot.net 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)) - ugi=sbd-fh-connect-autodumph...@sbd.corproot.net 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)) - ugi=sbd-fh-connect-autodumph...@sbd.corproot.net 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)