[HIVE-13869] ObjectStore synchronization issue manifested in db notification listener

• Type: Bug
• Status: Open
• Priority: Blocker
• Resolution: Unresolved
• Affects Version/s: 1.1.1
• Component/s: HCatalog
• Target Version/s: 1.3.0
• Assignee: Unassigned
• Reporter: Nachiket Vaidya
• Created: 26/May/16 22:57
• Updated: 17/Mar/17 20:25

Description

I used pyhs2 python client to create tables/partitions in hive. I was working fine until I moved to multithreaded scripts which created 8 connections and ran DDL queries concurrently.
I got the error as

2016-05-04 17:49:26,226 ERROR org.apache.hadoop.hive.metastore.RetryingHMSHandler: [pool-4-thread-194]: HMSHandler Fatal error: Invalid state. Transaction has already started
org.datanucleus.transaction.NucleusTransactionException: Invalid state. Transaction has already started
        at org.datanucleus.transaction.TransactionManager.begin(TransactionManager.java:47)
        at org.datanucleus.TransactionImpl.begin(TransactionImpl.java:131)
        at org.datanucleus.api.jdo.JDOTransaction.internalBegin(JDOTransaction.java:88)
        at org.datanucleus.api.jdo.JDOTransaction.begin(JDOTransaction.java:80)
        at org.apache.hadoop.hive.metastore.ObjectStore.openTransaction(ObjectStore.java:463)
        at org.apache.hadoop.hive.metastore.ObjectStore.addNotificationEvent(ObjectStore.java:7522)
        at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.apache.hadoop.hive.metastore.RawStoreProxy.invoke(RawStoreProxy.java:114)
        at com.sun.proxy.$Proxy10.addNotificationEvent(Unknown Source)
        at org.apache.hive.hcatalog.listener.DbNotificationListener.enqueue(DbNotificationListener.java:261)
        at org.apache.hive.hcatalog.listener.DbNotificationListener.onCreateTable(DbNotificationListener.java:123)
        at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_core(HiveMetaStore.java:1483)
        at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_with_environment_context(HiveMetaStore.java:1502)
        at sun.reflect.GeneratedMethodAccessor57.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:138)
        at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:99)
        at com.sun.proxy.$Proxy14.create_table_with_environment_context(Unknown Source)
        at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$create_table_with_environment_context.getResult(ThriftHiveMetastore.java:9267)

At one point, I got another stack trace as

2016-05-26 12:32:27,904 ERROR org.apache.hadoop.hive.metastore.RetryingHMSHandler: [pool-4-thread-7]: MetaException(message:java.lang.NullPointerException)
        at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.newMetaException(HiveMetaStore.java:5535)
        at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.add_partitions_req(HiveMetaStore.java:2308)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:138)
        at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:99)
        at com.sun.proxy.$Proxy14.add_partitions_req(Unknown Source)
        at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$add_partitions_req.getResult(ThriftHiveMetastore.java:9723)
        at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$add_partitions_req.getResult(ThriftHiveMetastore.java:9707)
        at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
        at org.apache.hadoop.hive.metastore.TUGIBasedProcessor$1.run(TUGIBasedProcessor.java:110)
        at org.apache.hadoop.hive.metastore.TUGIBasedProcessor$1.run(TUGIBasedProcessor.java:106)
        at java.security.AccessController.doPrivileged(Native Method)
        at javax.security.auth.Subject.doAs(Subject.java:415)
        at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1693)
        at org.apache.hadoop.hive.metastore.TUGIBasedProcessor.process(TUGIBasedProcessor.java:118)
        at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.NullPointerException
        at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1245)
        at com.jolbox.bonecp.StatementHandle.executeBatch(StatementHandle.java:424)
        at org.datanucleus.store.rdbms.ParamLoggingPreparedStatement.executeBatch(ParamLoggingPreparedStatement.java:372)
        at org.datanucleus.store.rdbms.SQLController.processConnectionStatement(SQLController.java:628)
        at org.datanucleus.store.rdbms.SQLController.getStatementForQuery(SQLController.java:324)
        at org.datanucleus.store.rdbms.query.RDBMSQueryUtils.getPreparedStatementForQuery(RDBMSQueryUtils.java:194)
        at org.datanucleus.store.rdbms.query.JDOQLQuery.performExecute(JDOQLQuery.java:640)
        at org.datanucleus.store.query.Query.executeQuery(Query.java:1786)
        at org.datanucleus.store.query.Query.executeWithArray(Query.java:1672)
        at org.datanucleus.store.query.Query.execute(Query.java:1654)
        at org.datanucleus.api.jdo.JDOQuery.execute(JDOQuery.java:221)
        at org.apache.hadoop.hive.metastore.ObjectStore.addNotificationEvent(ObjectStore.java:7534)
        at sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at org.apache.hadoop.hive.metastore.RawStoreProxy.invoke(RawStoreProxy.java:114)
        at com.sun.proxy.$Proxy10.addNotificationEvent(Unknown Source)
        at org.apache.hive.hcatalog.listener.DbNotificationListener.enqueue(DbNotificationListener.java:261)
        at org.apache.hive.hcatalog.listener.DbNotificationListener.onAddPartition(DbNotificationListener.java:168)

It is concurrency issue manifesting in different way.

We need to revisit ObjectStore and db notification listener's use of ObjectStore to understand the issue.

The patch for HIVE-13836 avoids concurrent calls to ObjectStore. But we need to find the root cause of the real issue as ObjectStore should handle concurrent calls.

Issue Links

• duplicates: HIVE-15373 DbNotificationListener should use thread-local RawStore
• is related to: HIVE-13836 DbNotifications giving an error = Invalid state. Transaction has already started