Uploaded image for project: 'Hive'
  1. Hive
  2. HIVE-8850

ObjectStore:: rollbackTransaction() needs to be looked into further.

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 1.1.0
    • Component/s: Metastore
    • Labels:
      None

      Description

      We can run into issues as described below:
      Hive script adds 2800 partitions to a table and during this it can get a SQLState 08S01 [Communication Link Error] and bonecp kill all the connections in the pool. The partitions are added and a create table statement executes (Metering_IngestedData_Compressed). The map job finishes successfully and while moving the table to the hive warehouse the ObjectStore.java commitTransaction() raises the error: commitTransaction was called but openTransactionCalls = 0. This probably indicates that there are unbalanced calls to openTransaction/commitTransaction

      1. HIVE-8850.1.patch
        1 kB
        Hari Sankar Sivarama Subramaniyan
      2. HIVE-8850.2.patch
        4 kB
        Sushanth Sowmyan
      3. HIVE-8850.3.patch
        5 kB
        Sushanth Sowmyan
      4. HIVE-8850.4.patch
        2 kB
        Sushanth Sowmyan

        Issue Links

          Activity

          Hide
          hsubramaniyan Hari Sankar Sivarama Subramaniyan added a comment -

          Stack Trace :

          2014-11-10 15:36:26,041 ERROR [main]: bonecp.ConnectionHandle (ConnectionHandle.java:markPossiblyBroken(388)) - Database access problem. Killing off this connection and all remaining connections in the connection pool. SQL State = 08S01
          2014-11-10 15:36:26,043 WARN [main]: metastore.ObjectStore (ObjectStore.java:getDatabase(504)) - JDODataStoreException using direct sql getting db: 6824349d_5e79_b4d7_aa8a_5e470e12bdd8. Falling back to ORM.
          javax.jdo.JDODataStoreException: Read timed out
          at org.datanucleus.api.jdo.NucleusJDOHelper.getJDOExceptionForNucleusException(NucleusJDOHelper.java:451)
          at org.datanucleus.api.jdo.JDOQuery.executeWithArray(JDOQuery.java:321)
          at org.apache.hadoop.hive.metastore.MetaStoreDirectSql.getDatabase(MetaStoreDirectSql.java:197)
          at org.apache.hadoop.hive.metastore.ObjectStore.getDatabase(ObjectStore.java:500)
          at sun.reflect.GeneratedMethodAccessor16.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:108)
          at com.sun.proxy.$Proxy11.getDatabase(Unknown Source)
          at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_core(HiveMetaStore.java:1248)
          at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_with_environment_context(HiveMetaStore.java:1332)
          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.invoke(RetryingHMSHandler.java:105)
          at com.sun.proxy.$Proxy13.create_table_with_environment_context(Unknown Source)
          at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:558)
          at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:547)
          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.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:89)
          at com.sun.proxy.$Proxy9.createTable(Unknown Source)
          at org.apache.hadoop.hive.ql.metadata.Hive.createTable(Hive.java:613)
          at org.apache.hadoop.hive.ql.exec.DDLTask.createTable(DDLTask.java:4203)
          at org.apache.hadoop.hive.ql.exec.DDLTask.execute(DDLTask.java:281)
          at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:153)
          at org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:85)
          at org.apache.hadoop.hive.ql.Driver.launchTask(Driver.java:1508)
          at org.apache.hadoop.hive.ql.Driver.execute(Driver.java:1275)
          at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:1093)
          at org.apache.hadoop.hive.ql.Driver.run(Driver.java:916)
          at org.apache.hadoop.hive.ql.Driver.run(Driver.java:906)
          at org.apache.hadoop.hive.cli.CliDriver.processLocalCmd(CliDriver.java:268)
          at org.apache.hadoop.hive.cli.CliDriver.processCmd(CliDriver.java:220)
          at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:423)
          at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:359)
          at org.apache.hadoop.hive.cli.CliDriver.processReader(CliDriver.java:456)
          at org.apache.hadoop.hive.cli.CliDriver.processFile(CliDriver.java:466)
          at org.apache.hadoop.hive.cli.CliDriver.executeDriver(CliDriver.java:749)
          at org.apache.hadoop.hive.cli.CliDriver.run(CliDriver.java:686)
          at org.apache.hadoop.hive.cli.CliDriver.main(CliDriver.java:625)
          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.util.RunJar.main(RunJar.java:212)
          NestedThrowablesStackTrace:
          com.microsoft.sqlserver.jdbc.SQLServerException: Read timed out
          at com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:1352)
          at com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:1339)
          at com.microsoft.sqlserver.jdbc.TDSChannel.read(IOBuffer.java:1694)
          at com.microsoft.sqlserver.jdbc.TDSReader.readPacket(IOBuffer.java:3734)
          at com.microsoft.sqlserver.jdbc.TDSCommand.startResponse(IOBuffer.java:5066)
          at com.microsoft.sqlserver.jdbc.TDSCommand.startResponse(IOBuffer.java:5018)
          at com.microsoft.sqlserver.jdbc.SQLServerConnection$1ConnectionCommand.doExecute(SQLServerConnection.java:1441)
          at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:4615)
          at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:1400)
          at com.microsoft.sqlserver.jdbc.SQLServerConnection.connectionCommand(SQLServerConnection.java:1446)
          at com.microsoft.sqlserver.jdbc.SQLServerConnection.setAutoCommit(SQLServerConnection.java:1594)
          at com.jolbox.bonecp.ConnectionHandle.setAutoCommit(ConnectionHandle.java:1292)
          at org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.getConnection(ConnectionFactoryImpl.java:440)
          at org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.getXAResource(ConnectionFactoryImpl.java:378)
          at org.datanucleus.store.connection.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:328)
          at org.datanucleus.store.connection.AbstractConnectionFactory.getConnection(AbstractConnectionFactory.java:94)
          at org.datanucleus.store.AbstractStoreManager.getConnection(AbstractStoreManager.java:430)
          at org.datanucleus.store.AbstractStoreManager.getConnection(AbstractStoreManager.java:396)
          at org.datanucleus.store.rdbms.query.SQLQuery.performExecute(SQLQuery.java:262)
          at org.datanucleus.store.query.Query.executeQuery(Query.java:1786)
          at org.datanucleus.store.query.AbstractSQLQuery.executeWithArray(AbstractSQLQuery.java:339)
          at org.datanucleus.api.jdo.JDOQuery.executeWithArray(JDOQuery.java:312)
          at org.apache.hadoop.hive.metastore.MetaStoreDirectSql.getDatabase(MetaStoreDirectSql.java:197)
          at org.apache.hadoop.hive.metastore.ObjectStore.getDatabase(ObjectStore.java:500)
          at sun.reflect.GeneratedMethodAccessor16.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:108)
          at com.sun.proxy.$Proxy11.getDatabase(Unknown Source)
          at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_core(HiveMetaStore.java:1248)
          at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_with_environment_context(HiveMetaStore.java:1332)
          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.invoke(RetryingHMSHandler.java:105)
          at com.sun.proxy.$Proxy13.create_table_with_environment_context(Unknown Source)
          at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:558)
          at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:547)
          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.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:89)
          at com.sun.proxy.$Proxy9.createTable(Unknown Source)
          at org.apache.hadoop.hive.ql.metadata.Hive.createTable(Hive.java:613)
          at org.apache.hadoop.hive.ql.exec.DDLTask.createTable(DDLTask.java:4203)
          at org.apache.hadoop.hive.ql.exec.DDLTask.execute(DDLTask.java:281)
          at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:153)
          at org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:85)
          at org.apache.hadoop.hive.ql.Driver.launchTask(Driver.java:1508)
          at org.apache.hadoop.hive.ql.Driver.execute(Driver.java:1275)
          at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:1093)
          at org.apache.hadoop.hive.ql.Driver.run(Driver.java:916)
          at org.apache.hadoop.hive.ql.Driver.run(Driver.java:906)
          at org.apache.hadoop.hive.cli.CliDriver.processLocalCmd(CliDriver.java:268)
          at org.apache.hadoop.hive.cli.CliDriver.processCmd(CliDriver.java:220)
          at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:423)
          at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:359)
          at org.apache.hadoop.hive.cli.CliDriver.processReader(CliDriver.java:456)
          at org.apache.hadoop.hive.cli.CliDriver.processFile(CliDriver.java:466)
          at org.apache.hadoop.hive.cli.CliDriver.executeDriver(CliDriver.java:749)
          at org.apache.hadoop.hive.cli.CliDriver.run(CliDriver.java:686)
          at org.apache.hadoop.hive.cli.CliDriver.main(CliDriver.java:625)
          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.util.RunJar.main(RunJar.java:212)
          2014-11-10 15:36:28,876 ERROR [main]: metastore.ObjectStore (ObjectStore.java:commitTransaction(391)) - java.lang.RuntimeException: commitTransaction was called but openTransactionCalls = 0. This probably indicates that there are unbalanced calls to openTransaction/commitTransaction
          2014-11-10 15:36:28,882 ERROR [main]: metastore.RetryingHMSHandler (RetryingHMSHandler.java:invoke(143)) - MetaException(message:java.lang.RuntimeException: commitTransaction was called but openTransactionCalls = 0. This probably indicates that there are unbalanced calls to openTransaction/commitTransaction)
          at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.newMetaException(HiveMetaStore.java:4638)
          at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_with_environment_context(HiveMetaStore.java:1346)
          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.invoke(RetryingHMSHandler.java:105)
          at com.sun.proxy.$Proxy13.create_table_with_environment_context(Unknown Source)
          at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:558)
          at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:547)
          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.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:89)
          at com.sun.proxy.$Proxy9.createTable(Unknown Source)
          at org.apache.hadoop.hive.ql.metadata.Hive.createTable(Hive.java:613)
          at org.apache.hadoop.hive.ql.exec.DDLTask.createTable(DDLTask.java:4203)
          at org.apache.hadoop.hive.ql.exec.DDLTask.execute(DDLTask.java:281)
          at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:153)
          at org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:85)
          at org.apache.hadoop.hive.ql.Driver.launchTask(Driver.java:1508)
          at org.apache.hadoop.hive.ql.Driver.execute(Driver.java:1275)
          at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:1093)
          at org.apache.hadoop.hive.ql.Driver.run(Driver.java:916)
          at org.apache.hadoop.hive.ql.Driver.run(Driver.java:906)
          at org.apache.hadoop.hive.cli.CliDriver.processLocalCmd(CliDriver.java:268)
          at org.apache.hadoop.hive.cli.CliDriver.processCmd(CliDriver.java:220)
          at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:423)
          at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:359)
          at org.apache.hadoop.hive.cli.CliDriver.processReader(CliDriver.java:456)
          at org.apache.hadoop.hive.cli.CliDriver.processFile(CliDriver.java:466)
          at org.apache.hadoop.hive.cli.CliDriver.executeDriver(CliDriver.java:749)
          at org.apache.hadoop.hive.cli.CliDriver.run(CliDriver.java:686)
          at org.apache.hadoop.hive.cli.CliDriver.main(CliDriver.java:625)
          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.util.RunJar.main(RunJar.java:212)
          Caused by: java.lang.RuntimeException: commitTransaction was called but openTransactionCalls = 0. This probably indicates that there are unbalanced calls to openTransaction/commitTransaction
          at org.apache.hadoop.hive.metastore.ObjectStore.commitTransaction(ObjectStore.java:388)
          at sun.reflect.GeneratedMethodAccessor11.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:108)
          at com.sun.proxy.$Proxy11.commitTransaction(Unknown Source)
          at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_core(HiveMetaStore.java:1300)
          at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_with_environment_context(HiveMetaStore.java:1332)
          ... 38 more
          2014-11-10 15:36:28,887 ERROR [main]: exec.DDLTask (DDLTask.java:execute(478)) - org.apache.hadoop.hive.ql.metadata.HiveException: MetaException(message:java.lang.RuntimeException: commitTransaction was called but openTransactionCalls = 0. This probably indicates that there are unbalanced calls to openTransaction/commitTransaction)
          at org.apache.hadoop.hive.ql.metadata.Hive.createTable(Hive.java:619)
          at org.apache.hadoop.hive.ql.exec.DDLTask.createTable(DDLTask.java:4203)
          at org.apache.hadoop.hive.ql.exec.DDLTask.execute(DDLTask.java:281)
          at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:153)
          at org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:85)
          at org.apache.hadoop.hive.ql.Driver.launchTask(Driver.java:1508)
          at org.apache.hadoop.hive.ql.Driver.execute(Driver.java:1275)
          at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:1093)
          at org.apache.hadoop.hive.ql.Driver.run(Driver.java:916)
          at org.apache.hadoop.hive.ql.Driver.run(Driver.java:906)
          at org.apache.hadoop.hive.cli.CliDriver.processLocalCmd(CliDriver.java:268)
          at org.apache.hadoop.hive.cli.CliDriver.processCmd(CliDriver.java:220)
          at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:423)
          at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:359)
          at org.apache.hadoop.hive.cli.CliDriver.processReader(CliDriver.java:456)
          at org.apache.hadoop.hive.cli.CliDriver.processFile(CliDriver.java:466)
          at org.apache.hadoop.hive.cli.CliDriver.executeDriver(CliDriver.java:749)
          at org.apache.hadoop.hive.cli.CliDriver.run(CliDriver.java:686)
          at org.apache.hadoop.hive.cli.CliDriver.main(CliDriver.java:625)
          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.util.RunJar.main(RunJar.java:212)
          Caused by: MetaException(message:java.lang.RuntimeException: commitTransaction was called but openTransactionCalls = 0. This probably indicates that there are unbalanced calls to openTransaction/commitTransaction)
          at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.newMetaException(HiveMetaStore.java:4638)
          at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_with_environment_context(HiveMetaStore.java:1346)
          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.invoke(RetryingHMSHandler.java:105)
          at com.sun.proxy.$Proxy13.create_table_with_environment_context(Unknown Source)
          at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:558)
          at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:547)
          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.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:89)
          at com.sun.proxy.$Proxy9.createTable(Unknown Source)
          at org.apache.hadoop.hive.ql.metadata.Hive.createTable(Hive.java:613)
          ... 23 more
          Caused by: java.lang.RuntimeException: commitTransaction was called but openTransactionCalls = 0. This probably indicates that there are unbalanced calls to openTransaction/commitTransaction
          at org.apache.hadoop.hive.metastore.ObjectStore.commitTransaction(ObjectStore.java:388)
          at sun.reflect.GeneratedMethodAccessor11.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:108)
          at com.sun.proxy.$Proxy11.commitTransaction(Unknown Source)
          at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_core(HiveMetaStore.java:1300)
          at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_with_environment_context(HiveMetaStore.java:1332)
          ... 38 more
          2014-11-10 15:36:28,889 ERROR [main]: ql.Driver (SessionState.java:printError(547)) - FAILED: Execution Error, return code 1 from org.apache.hadoop.hive.ql.exec.DDLTask. MetaException(message:java.lang.RuntimeException: commitTransaction was called but openTransactionCalls = 0. This probably indicates that there are unbalanced calls to openTransaction/commitTransaction)

          Show
          hsubramaniyan Hari Sankar Sivarama Subramaniyan added a comment - Stack Trace : 2014-11-10 15:36:26,041 ERROR [main] : bonecp.ConnectionHandle (ConnectionHandle.java:markPossiblyBroken(388)) - Database access problem. Killing off this connection and all remaining connections in the connection pool. SQL State = 08S01 2014-11-10 15:36:26,043 WARN [main] : metastore.ObjectStore (ObjectStore.java:getDatabase(504)) - JDODataStoreException using direct sql getting db: 6824349d_5e79_b4d7_aa8a_5e470e12bdd8. Falling back to ORM. javax.jdo.JDODataStoreException: Read timed out at org.datanucleus.api.jdo.NucleusJDOHelper.getJDOExceptionForNucleusException(NucleusJDOHelper.java:451) at org.datanucleus.api.jdo.JDOQuery.executeWithArray(JDOQuery.java:321) at org.apache.hadoop.hive.metastore.MetaStoreDirectSql.getDatabase(MetaStoreDirectSql.java:197) at org.apache.hadoop.hive.metastore.ObjectStore.getDatabase(ObjectStore.java:500) at sun.reflect.GeneratedMethodAccessor16.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:108) at com.sun.proxy.$Proxy11.getDatabase(Unknown Source) at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_core(HiveMetaStore.java:1248) at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_with_environment_context(HiveMetaStore.java:1332) 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.invoke(RetryingHMSHandler.java:105) at com.sun.proxy.$Proxy13.create_table_with_environment_context(Unknown Source) at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:558) at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:547) 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.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:89) at com.sun.proxy.$Proxy9.createTable(Unknown Source) at org.apache.hadoop.hive.ql.metadata.Hive.createTable(Hive.java:613) at org.apache.hadoop.hive.ql.exec.DDLTask.createTable(DDLTask.java:4203) at org.apache.hadoop.hive.ql.exec.DDLTask.execute(DDLTask.java:281) at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:153) at org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:85) at org.apache.hadoop.hive.ql.Driver.launchTask(Driver.java:1508) at org.apache.hadoop.hive.ql.Driver.execute(Driver.java:1275) at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:1093) at org.apache.hadoop.hive.ql.Driver.run(Driver.java:916) at org.apache.hadoop.hive.ql.Driver.run(Driver.java:906) at org.apache.hadoop.hive.cli.CliDriver.processLocalCmd(CliDriver.java:268) at org.apache.hadoop.hive.cli.CliDriver.processCmd(CliDriver.java:220) at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:423) at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:359) at org.apache.hadoop.hive.cli.CliDriver.processReader(CliDriver.java:456) at org.apache.hadoop.hive.cli.CliDriver.processFile(CliDriver.java:466) at org.apache.hadoop.hive.cli.CliDriver.executeDriver(CliDriver.java:749) at org.apache.hadoop.hive.cli.CliDriver.run(CliDriver.java:686) at org.apache.hadoop.hive.cli.CliDriver.main(CliDriver.java:625) 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.util.RunJar.main(RunJar.java:212) NestedThrowablesStackTrace: com.microsoft.sqlserver.jdbc.SQLServerException: Read timed out at com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:1352) at com.microsoft.sqlserver.jdbc.SQLServerConnection.terminate(SQLServerConnection.java:1339) at com.microsoft.sqlserver.jdbc.TDSChannel.read(IOBuffer.java:1694) at com.microsoft.sqlserver.jdbc.TDSReader.readPacket(IOBuffer.java:3734) at com.microsoft.sqlserver.jdbc.TDSCommand.startResponse(IOBuffer.java:5066) at com.microsoft.sqlserver.jdbc.TDSCommand.startResponse(IOBuffer.java:5018) at com.microsoft.sqlserver.jdbc.SQLServerConnection$1ConnectionCommand.doExecute(SQLServerConnection.java:1441) at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:4615) at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:1400) at com.microsoft.sqlserver.jdbc.SQLServerConnection.connectionCommand(SQLServerConnection.java:1446) at com.microsoft.sqlserver.jdbc.SQLServerConnection.setAutoCommit(SQLServerConnection.java:1594) at com.jolbox.bonecp.ConnectionHandle.setAutoCommit(ConnectionHandle.java:1292) at org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.getConnection(ConnectionFactoryImpl.java:440) at org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.getXAResource(ConnectionFactoryImpl.java:378) at org.datanucleus.store.connection.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:328) at org.datanucleus.store.connection.AbstractConnectionFactory.getConnection(AbstractConnectionFactory.java:94) at org.datanucleus.store.AbstractStoreManager.getConnection(AbstractStoreManager.java:430) at org.datanucleus.store.AbstractStoreManager.getConnection(AbstractStoreManager.java:396) at org.datanucleus.store.rdbms.query.SQLQuery.performExecute(SQLQuery.java:262) at org.datanucleus.store.query.Query.executeQuery(Query.java:1786) at org.datanucleus.store.query.AbstractSQLQuery.executeWithArray(AbstractSQLQuery.java:339) at org.datanucleus.api.jdo.JDOQuery.executeWithArray(JDOQuery.java:312) at org.apache.hadoop.hive.metastore.MetaStoreDirectSql.getDatabase(MetaStoreDirectSql.java:197) at org.apache.hadoop.hive.metastore.ObjectStore.getDatabase(ObjectStore.java:500) at sun.reflect.GeneratedMethodAccessor16.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:108) at com.sun.proxy.$Proxy11.getDatabase(Unknown Source) at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_core(HiveMetaStore.java:1248) at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_with_environment_context(HiveMetaStore.java:1332) 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.invoke(RetryingHMSHandler.java:105) at com.sun.proxy.$Proxy13.create_table_with_environment_context(Unknown Source) at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:558) at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:547) 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.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:89) at com.sun.proxy.$Proxy9.createTable(Unknown Source) at org.apache.hadoop.hive.ql.metadata.Hive.createTable(Hive.java:613) at org.apache.hadoop.hive.ql.exec.DDLTask.createTable(DDLTask.java:4203) at org.apache.hadoop.hive.ql.exec.DDLTask.execute(DDLTask.java:281) at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:153) at org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:85) at org.apache.hadoop.hive.ql.Driver.launchTask(Driver.java:1508) at org.apache.hadoop.hive.ql.Driver.execute(Driver.java:1275) at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:1093) at org.apache.hadoop.hive.ql.Driver.run(Driver.java:916) at org.apache.hadoop.hive.ql.Driver.run(Driver.java:906) at org.apache.hadoop.hive.cli.CliDriver.processLocalCmd(CliDriver.java:268) at org.apache.hadoop.hive.cli.CliDriver.processCmd(CliDriver.java:220) at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:423) at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:359) at org.apache.hadoop.hive.cli.CliDriver.processReader(CliDriver.java:456) at org.apache.hadoop.hive.cli.CliDriver.processFile(CliDriver.java:466) at org.apache.hadoop.hive.cli.CliDriver.executeDriver(CliDriver.java:749) at org.apache.hadoop.hive.cli.CliDriver.run(CliDriver.java:686) at org.apache.hadoop.hive.cli.CliDriver.main(CliDriver.java:625) 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.util.RunJar.main(RunJar.java:212) 2014-11-10 15:36:28,876 ERROR [main] : metastore.ObjectStore (ObjectStore.java:commitTransaction(391)) - java.lang.RuntimeException: commitTransaction was called but openTransactionCalls = 0. This probably indicates that there are unbalanced calls to openTransaction/commitTransaction 2014-11-10 15:36:28,882 ERROR [main] : metastore.RetryingHMSHandler (RetryingHMSHandler.java:invoke(143)) - MetaException(message:java.lang.RuntimeException: commitTransaction was called but openTransactionCalls = 0. This probably indicates that there are unbalanced calls to openTransaction/commitTransaction) at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.newMetaException(HiveMetaStore.java:4638) at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_with_environment_context(HiveMetaStore.java:1346) 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.invoke(RetryingHMSHandler.java:105) at com.sun.proxy.$Proxy13.create_table_with_environment_context(Unknown Source) at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:558) at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:547) 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.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:89) at com.sun.proxy.$Proxy9.createTable(Unknown Source) at org.apache.hadoop.hive.ql.metadata.Hive.createTable(Hive.java:613) at org.apache.hadoop.hive.ql.exec.DDLTask.createTable(DDLTask.java:4203) at org.apache.hadoop.hive.ql.exec.DDLTask.execute(DDLTask.java:281) at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:153) at org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:85) at org.apache.hadoop.hive.ql.Driver.launchTask(Driver.java:1508) at org.apache.hadoop.hive.ql.Driver.execute(Driver.java:1275) at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:1093) at org.apache.hadoop.hive.ql.Driver.run(Driver.java:916) at org.apache.hadoop.hive.ql.Driver.run(Driver.java:906) at org.apache.hadoop.hive.cli.CliDriver.processLocalCmd(CliDriver.java:268) at org.apache.hadoop.hive.cli.CliDriver.processCmd(CliDriver.java:220) at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:423) at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:359) at org.apache.hadoop.hive.cli.CliDriver.processReader(CliDriver.java:456) at org.apache.hadoop.hive.cli.CliDriver.processFile(CliDriver.java:466) at org.apache.hadoop.hive.cli.CliDriver.executeDriver(CliDriver.java:749) at org.apache.hadoop.hive.cli.CliDriver.run(CliDriver.java:686) at org.apache.hadoop.hive.cli.CliDriver.main(CliDriver.java:625) 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.util.RunJar.main(RunJar.java:212) Caused by: java.lang.RuntimeException: commitTransaction was called but openTransactionCalls = 0. This probably indicates that there are unbalanced calls to openTransaction/commitTransaction at org.apache.hadoop.hive.metastore.ObjectStore.commitTransaction(ObjectStore.java:388) at sun.reflect.GeneratedMethodAccessor11.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:108) at com.sun.proxy.$Proxy11.commitTransaction(Unknown Source) at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_core(HiveMetaStore.java:1300) at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_with_environment_context(HiveMetaStore.java:1332) ... 38 more 2014-11-10 15:36:28,887 ERROR [main] : exec.DDLTask (DDLTask.java:execute(478)) - org.apache.hadoop.hive.ql.metadata.HiveException: MetaException(message:java.lang.RuntimeException: commitTransaction was called but openTransactionCalls = 0. This probably indicates that there are unbalanced calls to openTransaction/commitTransaction) at org.apache.hadoop.hive.ql.metadata.Hive.createTable(Hive.java:619) at org.apache.hadoop.hive.ql.exec.DDLTask.createTable(DDLTask.java:4203) at org.apache.hadoop.hive.ql.exec.DDLTask.execute(DDLTask.java:281) at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:153) at org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:85) at org.apache.hadoop.hive.ql.Driver.launchTask(Driver.java:1508) at org.apache.hadoop.hive.ql.Driver.execute(Driver.java:1275) at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:1093) at org.apache.hadoop.hive.ql.Driver.run(Driver.java:916) at org.apache.hadoop.hive.ql.Driver.run(Driver.java:906) at org.apache.hadoop.hive.cli.CliDriver.processLocalCmd(CliDriver.java:268) at org.apache.hadoop.hive.cli.CliDriver.processCmd(CliDriver.java:220) at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:423) at org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:359) at org.apache.hadoop.hive.cli.CliDriver.processReader(CliDriver.java:456) at org.apache.hadoop.hive.cli.CliDriver.processFile(CliDriver.java:466) at org.apache.hadoop.hive.cli.CliDriver.executeDriver(CliDriver.java:749) at org.apache.hadoop.hive.cli.CliDriver.run(CliDriver.java:686) at org.apache.hadoop.hive.cli.CliDriver.main(CliDriver.java:625) 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.util.RunJar.main(RunJar.java:212) Caused by: MetaException(message:java.lang.RuntimeException: commitTransaction was called but openTransactionCalls = 0. This probably indicates that there are unbalanced calls to openTransaction/commitTransaction) at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.newMetaException(HiveMetaStore.java:4638) at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_with_environment_context(HiveMetaStore.java:1346) 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.invoke(RetryingHMSHandler.java:105) at com.sun.proxy.$Proxy13.create_table_with_environment_context(Unknown Source) at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:558) at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:547) 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.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:89) at com.sun.proxy.$Proxy9.createTable(Unknown Source) at org.apache.hadoop.hive.ql.metadata.Hive.createTable(Hive.java:613) ... 23 more Caused by: java.lang.RuntimeException: commitTransaction was called but openTransactionCalls = 0. This probably indicates that there are unbalanced calls to openTransaction/commitTransaction at org.apache.hadoop.hive.metastore.ObjectStore.commitTransaction(ObjectStore.java:388) at sun.reflect.GeneratedMethodAccessor11.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:108) at com.sun.proxy.$Proxy11.commitTransaction(Unknown Source) at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_core(HiveMetaStore.java:1300) at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_with_environment_context(HiveMetaStore.java:1332) ... 38 more 2014-11-10 15:36:28,889 ERROR [main] : ql.Driver (SessionState.java:printError(547)) - FAILED: Execution Error, return code 1 from org.apache.hadoop.hive.ql.exec.DDLTask. MetaException(message:java.lang.RuntimeException: commitTransaction was called but openTransactionCalls = 0. This probably indicates that there are unbalanced calls to openTransaction/commitTransaction)
          Hide
          hsubramaniyan Hari Sankar Sivarama Subramaniyan added a comment -

          cc-ing Sushanth Sowmyan for review.

          Thanks
          Hari

          Show
          hsubramaniyan Hari Sankar Sivarama Subramaniyan added a comment - cc-ing Sushanth Sowmyan for review. Thanks Hari
          Hide
          hiveqa Hive QA added a comment -

          Overall: -1 at least one tests failed

          Here are the results of testing the latest attachment:
          https://issues.apache.org/jira/secure/attachment/12681204/HIVE-8850.1.patch

          ERROR: -1 due to 1 failed/errored test(s), 6686 tests executed
          Failed tests:

          org.apache.hadoop.hive.cli.TestMiniTezCliDriver.testCliDriver_optimize_nullscan
          

          Test results: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/1769/testReport
          Console output: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/1769/console
          Test logs: http://ec2-174-129-184-35.compute-1.amazonaws.com/logs/PreCommit-HIVE-TRUNK-Build-1769/

          Messages:

          Executing org.apache.hive.ptest.execution.PrepPhase
          Executing org.apache.hive.ptest.execution.ExecutionPhase
          Executing org.apache.hive.ptest.execution.ReportingPhase
          Tests exited with: TestsFailedException: 1 tests failed
          

          This message is automatically generated.

          ATTACHMENT ID: 12681204 - PreCommit-HIVE-TRUNK-Build

          Show
          hiveqa Hive QA added a comment - Overall : -1 at least one tests failed Here are the results of testing the latest attachment: https://issues.apache.org/jira/secure/attachment/12681204/HIVE-8850.1.patch ERROR: -1 due to 1 failed/errored test(s), 6686 tests executed Failed tests: org.apache.hadoop.hive.cli.TestMiniTezCliDriver.testCliDriver_optimize_nullscan Test results: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/1769/testReport Console output: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/1769/console Test logs: http://ec2-174-129-184-35.compute-1.amazonaws.com/logs/PreCommit-HIVE-TRUNK-Build-1769/ Messages: Executing org.apache.hive.ptest.execution.PrepPhase Executing org.apache.hive.ptest.execution.ExecutionPhase Executing org.apache.hive.ptest.execution.ReportingPhase Tests exited with: TestsFailedException: 1 tests failed This message is automatically generated. ATTACHMENT ID: 12681204 - PreCommit-HIVE-TRUNK-Build
          Hide
          sushanth Sushanth Sowmyan added a comment -

          In theory, from analyzing the codeflow path of open and close transactions, this looks like this is important to have. This is how I currently analyze the flow of how the variable openTransactions is affected:

          Methods that interact with openTransactions:
          
          setConf
          	> instantiates it to 0 the very first time we start.
          
          openTransaction
          	> Increments without any checks.
          	> If after incrementing, its value is 1, then sets currentTransaction = pm.currentTransaction(), begins that trnasaction, and sests TXN_STATUS.OPEN
          	> If openTransactionCalls > 1, and current transaction is non-null and active, all's good, returns
          	~ If openTransactionCalls > 1, but current transaction is null or inactive, asserts (disabled in prod) but doesn't really handle anything.
          
          
          rollbackTransaction
          	> If openTransactionCalls < 1, returns saying there's no open transactions - from prior conditions, this can only happen if it's 0. Negative cannot happen.
          	> sets openTransactionCalls to 0.
          	> if current transaction is inactive, does nothing
          	> If current transaction is active, and its status is TXN_STATUS.ROLLBACK, does nothing
          	> If current transaction is active and its status is not TXN_STATUS.ROLLBACK, then does the following:
          		+ sets status to TXN_STATUS.ROLLBACK 
          		+ calls currentTransaction.rollback
          		+ calls pm.evictAll
          	~ If the transaction state goes inactive, we still have a case to evict, and that is what's being done in this patch.
          
          
          commitTransaction
          	> If current state is TXN_STATUS.ROLLBACK, returns false
          	> If openTransactionCalls is <=0, errors out about unbalanced commitTransactions.
          		> Technically, this can never be negative, it can only happen if it is 0.
          		> Also, the only cases that lead to this state are if:
          			a) More commitTransactions are called than the number of openTransactions that were called.
          			b) rollbackTransaction was called, but for whatever reason, did not set TXN_STATUS.ROLLBACK, followed by calling commitTransaction later.
          				- note that this can happen if the current transaction should become invalid for whatever reason before rollback is called. There does seem to be an issue here, in that rollback will not result in a full eviction in this case, but atleast we error here in a valid way.
          	> If current transaction is not active, throws an error identical to the previous case. This is probably not good if we need to ever distinguish between these two cases, and if the current transaction might wind up being inactive for whatever other reason.
          	> decrements if it should apply successfully.
          	> If the result of the decrement gets it to 0, and current transaction is active, then commits the current transaction, and ssets status to TXN_STATUS.COMMITTED
          
          

          So, it would seem that this patch is correct and needed. However, since this is a sensitive area, I'm trying to follow call stacks to rollback and commit transaction to make sure I'm not misreading this.

          Show
          sushanth Sushanth Sowmyan added a comment - In theory, from analyzing the codeflow path of open and close transactions, this looks like this is important to have. This is how I currently analyze the flow of how the variable openTransactions is affected: Methods that interact with openTransactions: setConf > instantiates it to 0 the very first time we start. openTransaction > Increments without any checks. > If after incrementing, its value is 1, then sets currentTransaction = pm.currentTransaction(), begins that trnasaction, and sests TXN_STATUS.OPEN > If openTransactionCalls > 1, and current transaction is non-null and active, all's good, returns ~ If openTransactionCalls > 1, but current transaction is null or inactive, asserts (disabled in prod) but doesn't really handle anything. rollbackTransaction > If openTransactionCalls < 1, returns saying there's no open transactions - from prior conditions, this can only happen if it's 0. Negative cannot happen. > sets openTransactionCalls to 0. > if current transaction is inactive, does nothing > If current transaction is active, and its status is TXN_STATUS.ROLLBACK, does nothing > If current transaction is active and its status is not TXN_STATUS.ROLLBACK, then does the following: + sets status to TXN_STATUS.ROLLBACK + calls currentTransaction.rollback + calls pm.evictAll ~ If the transaction state goes inactive, we still have a case to evict, and that is what's being done in this patch. commitTransaction > If current state is TXN_STATUS.ROLLBACK, returns false > If openTransactionCalls is <=0, errors out about unbalanced commitTransactions. > Technically, this can never be negative, it can only happen if it is 0. > Also, the only cases that lead to this state are if: a) More commitTransactions are called than the number of openTransactions that were called. b) rollbackTransaction was called, but for whatever reason, did not set TXN_STATUS.ROLLBACK, followed by calling commitTransaction later. - note that this can happen if the current transaction should become invalid for whatever reason before rollback is called. There does seem to be an issue here, in that rollback will not result in a full eviction in this case, but atleast we error here in a valid way. > If current transaction is not active, throws an error identical to the previous case. This is probably not good if we need to ever distinguish between these two cases, and if the current transaction might wind up being inactive for whatever other reason. > decrements if it should apply successfully. > If the result of the decrement gets it to 0, and current transaction is active, then commits the current transaction, and ssets status to TXN_STATUS.COMMITTED So, it would seem that this patch is correct and needed. However, since this is a sensitive area, I'm trying to follow call stacks to rollback and commit transaction to make sure I'm not misreading this.
          Hide
          sushanth Sushanth Sowmyan added a comment -

          In addition to the rollback issue here, there's one more nasty interplay here between open and rollback - open after a rollback will simply go ahead and nuke out the txn state and simply increment transaction count. Thus, the following can now happen:

          setConf (count = 0)
          openTransaction (count = 1)
                  openTransaction (count = 2)
                          (... some code that fails ...)
                  rollbackTransaction (count = 0)
                  openTransaction (count = 1)
                          (... some code that succeeds ...)
                  commitTransaction (count = 0)
          commitTransaction (count = -1)
          

          Normally, a rollback makes it so subsequent commits will realize that it's rolling back, so they do nothing, but if there is ever code that tries to call an open again instead of going down the commit chain, we have a problem.

          Again, normally, this shouldn't happen, because the rollback is indicative that this txn should fail, and to roll all the way out. The case where it wouldn't do that, however, is if we are inside a direct sql helper, where we attempt to use direct sql, open a txn, fail, rollback, and then fail back to using jdo, where we open a transaction again, and have that succeed.

          Now, ordinarily, this situation is also protected against, since the directsql portion does not open a new transaction and roll that back if it detects that it's already inside a transaction. However, directsql's detection of whether or not it is in a nested transaction is to simply check if there is already a transaction which is active. This can sometimes not be the case if the transaction got invalidated (set inactive, effectively) by bonecp, etc. In that scenario, we wind up with this behaviour described above, where directsql decides that isInTxn is false (since the current txn is invalid), and then it opens a txn for the directsql part, and if that fails, will rollback.

          Tagging Sergey Shelukhin to share this headache with him as well.

          Show
          sushanth Sushanth Sowmyan added a comment - In addition to the rollback issue here, there's one more nasty interplay here between open and rollback - open after a rollback will simply go ahead and nuke out the txn state and simply increment transaction count. Thus, the following can now happen: setConf (count = 0) openTransaction (count = 1) openTransaction (count = 2) (... some code that fails ...) rollbackTransaction (count = 0) openTransaction (count = 1) (... some code that succeeds ...) commitTransaction (count = 0) commitTransaction (count = -1) Normally, a rollback makes it so subsequent commits will realize that it's rolling back, so they do nothing, but if there is ever code that tries to call an open again instead of going down the commit chain, we have a problem. Again, normally, this shouldn't happen, because the rollback is indicative that this txn should fail, and to roll all the way out. The case where it wouldn't do that, however, is if we are inside a direct sql helper, where we attempt to use direct sql, open a txn, fail, rollback, and then fail back to using jdo, where we open a transaction again, and have that succeed. Now, ordinarily, this situation is also protected against, since the directsql portion does not open a new transaction and roll that back if it detects that it's already inside a transaction. However, directsql's detection of whether or not it is in a nested transaction is to simply check if there is already a transaction which is active. This can sometimes not be the case if the transaction got invalidated (set inactive, effectively) by bonecp, etc. In that scenario, we wind up with this behaviour described above, where directsql decides that isInTxn is false (since the current txn is invalid), and then it opens a txn for the directsql part, and if that fails, will rollback. Tagging Sergey Shelukhin to share this headache with him as well.
          Hide
          sushanth Sushanth Sowmyan added a comment -

          Also tagging Brock Noland and Chaoyu Tang, since they're also hit issues over at HIVE-8891, and I'd like to get some more eyeballs on this.

          Show
          sushanth Sushanth Sowmyan added a comment - Also tagging Brock Noland and Chaoyu Tang , since they're also hit issues over at HIVE-8891 , and I'd like to get some more eyeballs on this.
          Hide
          sushanth Sushanth Sowmyan added a comment -

          (Also, for context, one thing I should explicitly call out here is the reason for the original change here is that the transaction seems to have been invalidated by bonecp, so it does not satisfy the if condition for (currentTransaction.isActive() && transactionStatus != TXN_STATUS.ROLLBACK) when rollback is first called. Thus, as a result of that, we never set TXN_STATUS.ROLLBACK, which then causes commits further on from proceeding without realizing it shouldn't.)

          Show
          sushanth Sushanth Sowmyan added a comment - (Also, for context, one thing I should explicitly call out here is the reason for the original change here is that the transaction seems to have been invalidated by bonecp, so it does not satisfy the if condition for (currentTransaction.isActive() && transactionStatus != TXN_STATUS.ROLLBACK) when rollback is first called. Thus, as a result of that, we never set TXN_STATUS.ROLLBACK, which then causes commits further on from proceeding without realizing it shouldn't.)
          Hide
          ctang.ma Chaoyu Tang added a comment -

          Sushanth Sowmyan Thanks for the deep insight and analysis to the cause of the "unbalanced calls to openTransaction/commitTransaction" issue. I think HIVE-8891 is slightly different from the issue here and it just ensures to clean PersistenceManager cache after rollback to avoid the NucleusObjectNotFoundException and should not involve in the nested txn count issue.
          Because rollbackTransaction always resets the openTransactionCalls to 0, so even if you set the transactionStatus to TXN_STATUS.ROLLBACK regardless in rollbackTrasaction, in the nested transaction example you gave above (e.g. sqldirect fallback to jdo), the nested openTransaction following rollbackTransaction will set it back to TXN_STATUS.OPEN, and patch provided here would still not solve the issue for this example, is it right?

          Show
          ctang.ma Chaoyu Tang added a comment - Sushanth Sowmyan Thanks for the deep insight and analysis to the cause of the "unbalanced calls to openTransaction/commitTransaction" issue. I think HIVE-8891 is slightly different from the issue here and it just ensures to clean PersistenceManager cache after rollback to avoid the NucleusObjectNotFoundException and should not involve in the nested txn count issue. Because rollbackTransaction always resets the openTransactionCalls to 0, so even if you set the transactionStatus to TXN_STATUS.ROLLBACK regardless in rollbackTrasaction, in the nested transaction example you gave above (e.g. sqldirect fallback to jdo), the nested openTransaction following rollbackTransaction will set it back to TXN_STATUS.OPEN, and patch provided here would still not solve the issue for this example, is it right?
          Hide
          sushanth Sushanth Sowmyan added a comment -

          Yeah, I agree HIVE-8891 is different, and is necessary as well - I called you guys in here so that I have more people familiar with this looking at this as well.

          And yes, the patch provided here would still not solve the issue. It's a good first step in that it solves the issue of commitTransaction after a rollbackTransaction where the connection is invalidated in the background by something else, such as bonecp, but it does not yet solve the issue of an openTransaction after a rollbackTransaction in a nested scope.

          Show
          sushanth Sushanth Sowmyan added a comment - Yeah, I agree HIVE-8891 is different, and is necessary as well - I called you guys in here so that I have more people familiar with this looking at this as well. And yes, the patch provided here would still not solve the issue. It's a good first step in that it solves the issue of commitTransaction after a rollbackTransaction where the connection is invalidated in the background by something else, such as bonecp, but it does not yet solve the issue of an openTransaction after a rollbackTransaction in a nested scope.
          Hide
          sushanth Sushanth Sowmyan added a comment -

          Attaching updated patch that I believe solves this issue. (Also incorporates Hari's original patch)

          Show
          sushanth Sushanth Sowmyan added a comment - Attaching updated patch that I believe solves this issue. (Also incorporates Hari's original patch)
          Hide
          sushanth Sushanth Sowmyan added a comment -

          Note also, that the result of this is that the directsql attempt of getDatabase will not have a rollback executed on it if it fails before falling back to jdo, but that is fine, I think, since it's a read-only operation, and thus, does not need rollback.

          Show
          sushanth Sushanth Sowmyan added a comment - Note also, that the result of this is that the directsql attempt of getDatabase will not have a rollback executed on it if it fails before falling back to jdo, but that is fine, I think, since it's a read-only operation, and thus, does not need rollback.
          Hide
          sushanth Sushanth Sowmyan added a comment -

          Cancelling second patch, there is still another issue with this.

          Show
          sushanth Sushanth Sowmyan added a comment - Cancelling second patch, there is still another issue with this.
          Hide
          sushanth Sushanth Sowmyan added a comment -

          Earlier bug fixed.

          Show
          sushanth Sushanth Sowmyan added a comment - Earlier bug fixed.
          Hide
          hiveqa Hive QA added a comment -

          Overall: -1 at least one tests failed

          Here are the results of testing the latest attachment:
          https://issues.apache.org/jira/secure/attachment/12682774/HIVE-8850.3.patch

          ERROR: -1 due to 2 failed/errored test(s), 6666 tests executed
          Failed tests:

          org.apache.hadoop.hive.cli.TestMiniTezCliDriver.testCliDriver_optimize_nullscan
          org.apache.hive.hcatalog.streaming.TestStreaming.testEndpointConnection
          

          Test results: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/1859/testReport
          Console output: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/1859/console
          Test logs: http://ec2-174-129-184-35.compute-1.amazonaws.com/logs/PreCommit-HIVE-TRUNK-Build-1859/

          Messages:

          Executing org.apache.hive.ptest.execution.PrepPhase
          Executing org.apache.hive.ptest.execution.ExecutionPhase
          Executing org.apache.hive.ptest.execution.ReportingPhase
          Tests exited with: TestsFailedException: 2 tests failed
          

          This message is automatically generated.

          ATTACHMENT ID: 12682774 - PreCommit-HIVE-TRUNK-Build

          Show
          hiveqa Hive QA added a comment - Overall : -1 at least one tests failed Here are the results of testing the latest attachment: https://issues.apache.org/jira/secure/attachment/12682774/HIVE-8850.3.patch ERROR: -1 due to 2 failed/errored test(s), 6666 tests executed Failed tests: org.apache.hadoop.hive.cli.TestMiniTezCliDriver.testCliDriver_optimize_nullscan org.apache.hive.hcatalog.streaming.TestStreaming.testEndpointConnection Test results: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/1859/testReport Console output: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/1859/console Test logs: http://ec2-174-129-184-35.compute-1.amazonaws.com/logs/PreCommit-HIVE-TRUNK-Build-1859/ Messages: Executing org.apache.hive.ptest.execution.PrepPhase Executing org.apache.hive.ptest.execution.ExecutionPhase Executing org.apache.hive.ptest.execution.ReportingPhase Tests exited with: TestsFailedException: 2 tests failed This message is automatically generated. ATTACHMENT ID: 12682774 - PreCommit-HIVE-TRUNK-Build
          Hide
          sushanth Sushanth Sowmyan added a comment -
          Show
          sushanth Sushanth Sowmyan added a comment - Sergey Shelukhin , Brock Noland , Chaoyu Tang , can I bug one of you for a review of this? https://reviews.apache.org/r/28408/
          Hide
          brocknoland Brock Noland added a comment -

          Chaoyu Tang I know you've looked at this recently. Let me know what you think.

          Show
          brocknoland Brock Noland added a comment - Chaoyu Tang I know you've looked at this recently. Let me know what you think.
          Hide
          ctang.ma Chaoyu Tang added a comment -

          Sushanth Sowmyan The patch looks good. I left a couple of questions on the RB, could you help clarify them? Thanks.

          Show
          ctang.ma Chaoyu Tang added a comment - Sushanth Sowmyan The patch looks good. I left a couple of questions on the RB, could you help clarify them? Thanks.
          Hide
          sushanth Sushanth Sowmyan added a comment -

          Updated patch per review comments and further testing.

          Show
          sushanth Sushanth Sowmyan added a comment - Updated patch per review comments and further testing.
          Hide
          hiveqa Hive QA added a comment -

          Overall: -1 at least one tests failed

          Here are the results of testing the latest attachment:
          https://issues.apache.org/jira/secure/attachment/12685484/HIVE-8850.4.patch

          ERROR: -1 due to 1 failed/errored test(s), 6696 tests executed
          Failed tests:

          org.apache.hadoop.hive.cli.TestCliDriver.testCliDriver_vector_decimal_aggregate
          

          Test results: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/1978/testReport
          Console output: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/1978/console
          Test logs: http://ec2-174-129-184-35.compute-1.amazonaws.com/logs/PreCommit-HIVE-TRUNK-Build-1978/

          Messages:

          Executing org.apache.hive.ptest.execution.PrepPhase
          Executing org.apache.hive.ptest.execution.ExecutionPhase
          Executing org.apache.hive.ptest.execution.ReportingPhase
          Tests exited with: TestsFailedException: 1 tests failed
          

          This message is automatically generated.

          ATTACHMENT ID: 12685484 - PreCommit-HIVE-TRUNK-Build

          Show
          hiveqa Hive QA added a comment - Overall : -1 at least one tests failed Here are the results of testing the latest attachment: https://issues.apache.org/jira/secure/attachment/12685484/HIVE-8850.4.patch ERROR: -1 due to 1 failed/errored test(s), 6696 tests executed Failed tests: org.apache.hadoop.hive.cli.TestCliDriver.testCliDriver_vector_decimal_aggregate Test results: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/1978/testReport Console output: http://ec2-174-129-184-35.compute-1.amazonaws.com/jenkins/job/PreCommit-HIVE-TRUNK-Build/1978/console Test logs: http://ec2-174-129-184-35.compute-1.amazonaws.com/logs/PreCommit-HIVE-TRUNK-Build-1978/ Messages: Executing org.apache.hive.ptest.execution.PrepPhase Executing org.apache.hive.ptest.execution.ExecutionPhase Executing org.apache.hive.ptest.execution.ReportingPhase Tests exited with: TestsFailedException: 1 tests failed This message is automatically generated. ATTACHMENT ID: 12685484 - PreCommit-HIVE-TRUNK-Build
          Hide
          ctang.ma Chaoyu Tang added a comment -

          Sushanth Sowmyan Thanks for the clarifications to the questions in RB and updating the patch. It looks good to me.

          Show
          ctang.ma Chaoyu Tang added a comment - Sushanth Sowmyan Thanks for the clarifications to the questions in RB and updating the patch. It looks good to me.
          Hide
          sushanth Sushanth Sowmyan added a comment -

          Since the latest patch is very similar in state to what Hari initially came up with except for the change to openTransaction that Chaoyu suggested, I think it's fair to reassign back to Hari for this, doing so, and will commit with my +1 and Chaoyu's.

          Show
          sushanth Sushanth Sowmyan added a comment - Since the latest patch is very similar in state to what Hari initially came up with except for the change to openTransaction that Chaoyu suggested, I think it's fair to reassign back to Hari for this, doing so, and will commit with my +1 and Chaoyu's.
          Hide
          sushanth Sushanth Sowmyan added a comment -

          Committed. Thanks, Hari & Chaoyu.

          Show
          sushanth Sushanth Sowmyan added a comment - Committed. Thanks, Hari & Chaoyu.
          Hide
          sushanth Sushanth Sowmyan added a comment -

          (No documentation required, just a bugfix)

          Show
          sushanth Sushanth Sowmyan added a comment - (No documentation required, just a bugfix)

            People

            • Assignee:
              hsubramaniyan Hari Sankar Sivarama Subramaniyan
              Reporter:
              hsubramaniyan Hari Sankar Sivarama Subramaniyan
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development