[
https://issues.apache.org/jira/browse/HIVE-23437?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Marc Demierre updated HIVE-23437:
---------------------------------
Description:
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 from DB
because it exists. Rollback transaction.
** R2 thinks it created the directory (in fact they both did we do not know
who), 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 in a standalone
metastore (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).
- Another way would be to consider sucessful if the partition already exists,
and in this case not to delete the folder
was:
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 from DB
because it exists. Rollback transaction.
** R2 thinks it created the directory (in fact they both did we do not know
who), 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 in a standalone
metastore (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).
> 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 from DB
> because it exists. Rollback transaction.
> ** R2 thinks it created the directory (in fact they both did we do not know
> who), 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 in a standalone
> metastore (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).
> - Another way would be to consider sucessful if the partition already exists,
> and in this case not to delete the folder
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
