Return-Path: 
 <dev-return-91225-apmail-hive-dev-archive=hive.apache.org@hive.apache.org>
X-Original-To: apmail-hive-dev-archive@www.apache.org
Delivered-To: apmail-hive-dev-archive@www.apache.org
Received: from mail.apache.org (hermes.apache.org [140.211.11.3])
	by minotaur.apache.org (Postfix) with SMTP id 5B46011DA0
	for <apmail-hive-dev-archive@www.apache.org>;
 Wed, 18 Jun 2014 00:11:20 +0000 (UTC)
Received: (qmail 89031 invoked by uid 500); 18 Jun 2014 00:11:20 -0000
Delivered-To: apmail-hive-dev-archive@hive.apache.org
Received: (qmail 88964 invoked by uid 500); 18 Jun 2014 00:11:20 -0000
Mailing-List: contact dev-help@hive.apache.org; run by ezmlm
Precedence: bulk
List-Help: <mailto:dev-help@hive.apache.org>
List-Unsubscribe: <mailto:dev-unsubscribe@hive.apache.org>
List-Post: <mailto:dev@hive.apache.org>
List-Id: <dev.hive.apache.org>
Reply-To: dev@hive.apache.org
Delivered-To: mailing list dev@hive.apache.org
Received: (qmail 88953 invoked by uid 500); 18 Jun 2014 00:11:19 -0000
Delivered-To: apmail-hadoop-hive-dev@hadoop.apache.org
Received: (qmail 88950 invoked by uid 99); 18 Jun 2014 00:11:19 -0000
Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28)
    by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 18 Jun 2014 00:11:19 +0000
Date: Wed, 18 Jun 2014 00:11:19 +0000 (UTC)
From: "Eugene Koifman (JIRA)" <jira@apache.org>
To: hive-dev@hadoop.apache.org
Message-ID: <JIRA.12721820.1403050182983.150601.1403050279715@arcas>
In-Reply-To: <JIRA.12721820.1403050182983@arcas>
References: <JIRA.12721820.1403050182983@arcas>
Subject: [jira] [Updated] (HIVE-7249) HiveTxnManager.closeTxnManger() throws
 if called after commitTxn()
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394


     [ https://issues.apache.org/jira/browse/HIVE-7249?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Eugene Koifman updated HIVE-7249:
---------------------------------

    Description: 
 I openTxn() and acquireLocks() for a query that looks like "INSERT INTO T PARTITION(p) SELECT * FROM T".
Then I call commitTxn().  Then I call closeTxnManger() I get an exception saying lock not found (the only lock in this txn).  So it seems TxnMgr doesn't know that commit released the locks.

Here is the stack trace and some log output which maybe useful:
{noformat}
2014-06-17 15:54:40,771 DEBUG mapreduce.TransactionContext (TransactionContext.java:onCommitJob(128)) - onCommitJob(job_local557130041_0001). this=46719652
2014-06-17 15:54:40,771 DEBUG lockmgr.DbTxnManager (DbTxnManager.java:commitTxn(205)) - Committing txn 1
2014-06-17 15:54:40,771 DEBUG txn.TxnHandler (TxnHandler.java:getDbTime(872)) - Going to execute query <values current_timestamp>
2014-06-17 15:54:40,772 DEBUG txn.TxnHandler (TxnHandler.java:heartbeatTxn(1423)) - Going to execute query <select txn_state from TXNS where txn_id = 1 for\
 update>
2014-06-17 15:54:40,773 DEBUG txn.TxnHandler (TxnHandler.java:heartbeatTxn(1438)) - Going to execute update <update TXNS set txn_last_heartbeat = 140304568\
0772 where txn_id = 1>
2014-06-17 15:54:40,778 DEBUG txn.TxnHandler (TxnHandler.java:heartbeatTxn(1440)) - Going to commit
2014-06-17 15:54:40,779 DEBUG txn.TxnHandler (TxnHandler.java:commitTxn(344)) - Going to execute insert <insert into COMPLETED_TXN_COMPONENTS select tc_txn\
id, tc_database, tc_table, tc_partition from TXN_COMPONENTS where tc_txnid = 1>
2014-06-17 15:54:40,784 DEBUG txn.TxnHandler (TxnHandler.java:commitTxn(352)) - Going to execute update <delete from TXN_COMPONENTS where tc_txnid = 1>
2014-06-17 15:54:40,788 DEBUG txn.TxnHandler (TxnHandler.java:commitTxn(356)) - Going to execute update <delete from HIVE_LOCKS where hl_txnid = 1>
2014-06-17 15:54:40,791 DEBUG txn.TxnHandler (TxnHandler.java:commitTxn(359)) - Going to execute update <delete from TXNS where txn_id = 1>
2014-06-17 15:54:40,794 DEBUG txn.TxnHandler (TxnHandler.java:commitTxn(361)) - Going to commit
2014-06-17 15:54:40,795 WARN  mapreduce.TransactionContext (TransactionContext.java:cleanup(317)) - cleanupJob(JobID=job_local557130041_0001)this=46719652
2014-06-17 15:54:40,795 DEBUG lockmgr.DbLockManager (DbLockManager.java:unlock(109)) - Unlocking id:1
2014-06-17 15:54:40,796 DEBUG txn.TxnHandler (TxnHandler.java:getDbTime(872)) - Going to execute query <values current_timestamp>
2014-06-17 15:54:40,796 DEBUG txn.TxnHandler (TxnHandler.java:heartbeatLock(1402)) - Going to execute update <update HIVE_LOCKS set hl_last_heartbeat = 140\
3045680796 where hl_lock_ext_id = 1>
2014-06-17 15:54:40,800 DEBUG txn.TxnHandler (TxnHandler.java:heartbeatLock(1405)) - Going to rollback
2014-06-17 15:54:40,804 ERROR metastore.RetryingHMSHandler (RetryingHMSHandler.java:invoke(143)) - NoSuchLockException(message:No such lock: 1)
        at org.apache.hadoop.hive.metastore.txn.TxnHandler.heartbeatLock(TxnHandler.java:1407)
        at org.apache.hadoop.hive.metastore.txn.TxnHandler.unlock(TxnHandler.java:477)
        at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.unlock(HiveMetaStore.java:4817)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:105)
        at com.sun.proxy.$Proxy14.unlock(Unknown Source)
        at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.unlock(HiveMetaStoreClient.java:1598)
        at org.apache.hadoop.hive.ql.lockmgr.DbLockManager.unlock(DbLockManager.java:110)
        at org.apache.hadoop.hive.ql.lockmgr.DbLockManager.close(DbLockManager.java:162)
        at org.apache.hadoop.hive.ql.lockmgr.DbTxnManager.destruct(DbTxnManager.java:300)
        at org.apache.hadoop.hive.ql.lockmgr.HiveTxnManagerImpl.closeTxnManager(HiveTxnManagerImpl.java:39)
        at org.apache.hadoop.hive.ql.lockmgr.DbTxnManager.closeTxnManager(DbTxnManager.java:43)
        at org.apache.hive.hcatalog.mapreduce.TransactionContext.cleanup(TransactionContext.java:327)
        at org.apache.hive.hcatalog.mapreduce.TransactionContext.onCommitJob(TransactionContext.java:142)
        at org.apache.hive.hcatalog.mapreduce.OutputCommitterContainer.commitJob(OutputCommitterContainer.java:61)
        at org.apache.hive.hcatalog.mapreduce.FileOutputCommitterContainer.commitJob(FileOutputCommitterContainer.java:251)
        at org.apache.hadoop.mapred.LocalJobRunner$Job.run(LocalJobRunner.java:537)

2014-06-17 15:54:40,804 ERROR lockmgr.DbLockManager (DbLockManager.java:unlock(114)) - Metastore could find no record of lock 1
2014-06-17 15:54:40,810 INFO  mapreduce.FileOutputCommitterContainer (FileOutputCommitterContainer.java:cancelDelegationTokens(976)) - Cancelling delegation token for the job.
{noformat}

  was:
 I openTxn() and acquireLocks() for a query that looks like "INSERT INTO T PARTITION(p) SELECT * FROM T".
Then I call commitTxn().  Then I call closeTxnManger() I get an exception saying lock not found (the only lock in this txn).  So it seems TxnMgr doesn't know that commit released the locks.

Here is the stack trace and some log output which maybe useful:
2014-06-17 15:54:40,771 DEBUG mapreduce.TransactionContext (TransactionContext.java:onCommitJob(128)) - onCommitJob(job_local557130041_0001). this=46719652
2014-06-17 15:54:40,771 DEBUG lockmgr.DbTxnManager (DbTxnManager.java:commitTxn(205)) - Committing txn 1
2014-06-17 15:54:40,771 DEBUG txn.TxnHandler (TxnHandler.java:getDbTime(872)) - Going to execute query <values current_timestamp>
2014-06-17 15:54:40,772 DEBUG txn.TxnHandler (TxnHandler.java:heartbeatTxn(1423)) - Going to execute query <select txn_state from TXNS where txn_id = 1 for\
 update>
2014-06-17 15:54:40,773 DEBUG txn.TxnHandler (TxnHandler.java:heartbeatTxn(1438)) - Going to execute update <update TXNS set txn_last_heartbeat = 140304568\
0772 where txn_id = 1>
2014-06-17 15:54:40,778 DEBUG txn.TxnHandler (TxnHandler.java:heartbeatTxn(1440)) - Going to commit
2014-06-17 15:54:40,779 DEBUG txn.TxnHandler (TxnHandler.java:commitTxn(344)) - Going to execute insert <insert into COMPLETED_TXN_COMPONENTS select tc_txn\
id, tc_database, tc_table, tc_partition from TXN_COMPONENTS where tc_txnid = 1>
2014-06-17 15:54:40,784 DEBUG txn.TxnHandler (TxnHandler.java:commitTxn(352)) - Going to execute update <delete from TXN_COMPONENTS where tc_txnid = 1>
2014-06-17 15:54:40,788 DEBUG txn.TxnHandler (TxnHandler.java:commitTxn(356)) - Going to execute update <delete from HIVE_LOCKS where hl_txnid = 1>
2014-06-17 15:54:40,791 DEBUG txn.TxnHandler (TxnHandler.java:commitTxn(359)) - Going to execute update <delete from TXNS where txn_id = 1>
2014-06-17 15:54:40,794 DEBUG txn.TxnHandler (TxnHandler.java:commitTxn(361)) - Going to commit
2014-06-17 15:54:40,795 WARN  mapreduce.TransactionContext (TransactionContext.java:cleanup(317)) - cleanupJob(JobID=job_local557130041_0001)this=46719652
2014-06-17 15:54:40,795 DEBUG lockmgr.DbLockManager (DbLockManager.java:unlock(109)) - Unlocking id:1
2014-06-17 15:54:40,796 DEBUG txn.TxnHandler (TxnHandler.java:getDbTime(872)) - Going to execute query <values current_timestamp>
2014-06-17 15:54:40,796 DEBUG txn.TxnHandler (TxnHandler.java:heartbeatLock(1402)) - Going to execute update <update HIVE_LOCKS set hl_last_heartbeat = 140\
3045680796 where hl_lock_ext_id = 1>
2014-06-17 15:54:40,800 DEBUG txn.TxnHandler (TxnHandler.java:heartbeatLock(1405)) - Going to rollback
2014-06-17 15:54:40,804 ERROR metastore.RetryingHMSHandler (RetryingHMSHandler.java:invoke(143)) - NoSuchLockException(message:No such lock: 1)
        at org.apache.hadoop.hive.metastore.txn.TxnHandler.heartbeatLock(TxnHandler.java:1407)
        at org.apache.hadoop.hive.metastore.txn.TxnHandler.unlock(TxnHandler.java:477)
        at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.unlock(HiveMetaStore.java:4817)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:105)
        at com.sun.proxy.$Proxy14.unlock(Unknown Source)
        at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.unlock(HiveMetaStoreClient.java:1598)
        at org.apache.hadoop.hive.ql.lockmgr.DbLockManager.unlock(DbLockManager.java:110)
        at org.apache.hadoop.hive.ql.lockmgr.DbLockManager.close(DbLockManager.java:162)
        at org.apache.hadoop.hive.ql.lockmgr.DbTxnManager.destruct(DbTxnManager.java:300)
        at org.apache.hadoop.hive.ql.lockmgr.HiveTxnManagerImpl.closeTxnManager(HiveTxnManagerImpl.java:39)
        at org.apache.hadoop.hive.ql.lockmgr.DbTxnManager.closeTxnManager(DbTxnManager.java:43)
        at org.apache.hive.hcatalog.mapreduce.TransactionContext.cleanup(TransactionContext.java:327)
        at org.apache.hive.hcatalog.mapreduce.TransactionContext.onCommitJob(TransactionContext.java:142)
        at org.apache.hive.hcatalog.mapreduce.OutputCommitterContainer.commitJob(OutputCommitterContainer.java:61)
        at org.apache.hive.hcatalog.mapreduce.FileOutputCommitterContainer.commitJob(FileOutputCommitterContainer.java:251)
        at org.apache.hadoop.mapred.LocalJobRunner$Job.run(LocalJobRunner.java:537)

2014-06-17 15:54:40,804 ERROR lockmgr.DbLockManager (DbLockManager.java:unlock(114)) - Metastore could find no record of lock 1
2014-06-17 15:54:40,810 INFO  mapreduce.FileOutputCommitterContainer (FileOutputCommitterContainer.java:cancelDelegationTokens(976)) - Cancelling delegatio\
n token for the job.


> HiveTxnManager.closeTxnManger() throws if called after commitTxn()
> ------------------------------------------------------------------
>
>                 Key: HIVE-7249
>                 URL: https://issues.apache.org/jira/browse/HIVE-7249
>             Project: Hive
>          Issue Type: Bug
>          Components: Locking
>    Affects Versions: 0.13.1
>            Reporter: Eugene Koifman
>            Assignee: Alan Gates
>
>  I openTxn() and acquireLocks() for a query that looks like "INSERT INTO T PARTITION(p) SELECT * FROM T".
> Then I call commitTxn().  Then I call closeTxnManger() I get an exception saying lock not found (the only lock in this txn).  So it seems TxnMgr doesn't know that commit released the locks.
> Here is the stack trace and some log output which maybe useful:
> {noformat}
> 2014-06-17 15:54:40,771 DEBUG mapreduce.TransactionContext (TransactionContext.java:onCommitJob(128)) - onCommitJob(job_local557130041_0001). this=46719652
> 2014-06-17 15:54:40,771 DEBUG lockmgr.DbTxnManager (DbTxnManager.java:commitTxn(205)) - Committing txn 1
> 2014-06-17 15:54:40,771 DEBUG txn.TxnHandler (TxnHandler.java:getDbTime(872)) - Going to execute query <values current_timestamp>
> 2014-06-17 15:54:40,772 DEBUG txn.TxnHandler (TxnHandler.java:heartbeatTxn(1423)) - Going to execute query <select txn_state from TXNS where txn_id = 1 for\
>  update>
> 2014-06-17 15:54:40,773 DEBUG txn.TxnHandler (TxnHandler.java:heartbeatTxn(1438)) - Going to execute update <update TXNS set txn_last_heartbeat = 140304568\
> 0772 where txn_id = 1>
> 2014-06-17 15:54:40,778 DEBUG txn.TxnHandler (TxnHandler.java:heartbeatTxn(1440)) - Going to commit
> 2014-06-17 15:54:40,779 DEBUG txn.TxnHandler (TxnHandler.java:commitTxn(344)) - Going to execute insert <insert into COMPLETED_TXN_COMPONENTS select tc_txn\
> id, tc_database, tc_table, tc_partition from TXN_COMPONENTS where tc_txnid = 1>
> 2014-06-17 15:54:40,784 DEBUG txn.TxnHandler (TxnHandler.java:commitTxn(352)) - Going to execute update <delete from TXN_COMPONENTS where tc_txnid = 1>
> 2014-06-17 15:54:40,788 DEBUG txn.TxnHandler (TxnHandler.java:commitTxn(356)) - Going to execute update <delete from HIVE_LOCKS where hl_txnid = 1>
> 2014-06-17 15:54:40,791 DEBUG txn.TxnHandler (TxnHandler.java:commitTxn(359)) - Going to execute update <delete from TXNS where txn_id = 1>
> 2014-06-17 15:54:40,794 DEBUG txn.TxnHandler (TxnHandler.java:commitTxn(361)) - Going to commit
> 2014-06-17 15:54:40,795 WARN  mapreduce.TransactionContext (TransactionContext.java:cleanup(317)) - cleanupJob(JobID=job_local557130041_0001)this=46719652
> 2014-06-17 15:54:40,795 DEBUG lockmgr.DbLockManager (DbLockManager.java:unlock(109)) - Unlocking id:1
> 2014-06-17 15:54:40,796 DEBUG txn.TxnHandler (TxnHandler.java:getDbTime(872)) - Going to execute query <values current_timestamp>
> 2014-06-17 15:54:40,796 DEBUG txn.TxnHandler (TxnHandler.java:heartbeatLock(1402)) - Going to execute update <update HIVE_LOCKS set hl_last_heartbeat = 140\
> 3045680796 where hl_lock_ext_id = 1>
> 2014-06-17 15:54:40,800 DEBUG txn.TxnHandler (TxnHandler.java:heartbeatLock(1405)) - Going to rollback
> 2014-06-17 15:54:40,804 ERROR metastore.RetryingHMSHandler (RetryingHMSHandler.java:invoke(143)) - NoSuchLockException(message:No such lock: 1)
>         at org.apache.hadoop.hive.metastore.txn.TxnHandler.heartbeatLock(TxnHandler.java:1407)
>         at org.apache.hadoop.hive.metastore.txn.TxnHandler.unlock(TxnHandler.java:477)
>         at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.unlock(HiveMetaStore.java:4817)
>         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
>         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
>         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>         at java.lang.reflect.Method.invoke(Method.java:597)
>         at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:105)
>         at com.sun.proxy.$Proxy14.unlock(Unknown Source)
>         at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.unlock(HiveMetaStoreClient.java:1598)
>         at org.apache.hadoop.hive.ql.lockmgr.DbLockManager.unlock(DbLockManager.java:110)
>         at org.apache.hadoop.hive.ql.lockmgr.DbLockManager.close(DbLockManager.java:162)
>         at org.apache.hadoop.hive.ql.lockmgr.DbTxnManager.destruct(DbTxnManager.java:300)
>         at org.apache.hadoop.hive.ql.lockmgr.HiveTxnManagerImpl.closeTxnManager(HiveTxnManagerImpl.java:39)
>         at org.apache.hadoop.hive.ql.lockmgr.DbTxnManager.closeTxnManager(DbTxnManager.java:43)
>         at org.apache.hive.hcatalog.mapreduce.TransactionContext.cleanup(TransactionContext.java:327)
>         at org.apache.hive.hcatalog.mapreduce.TransactionContext.onCommitJob(TransactionContext.java:142)
>         at org.apache.hive.hcatalog.mapreduce.OutputCommitterContainer.commitJob(OutputCommitterContainer.java:61)
>         at org.apache.hive.hcatalog.mapreduce.FileOutputCommitterContainer.commitJob(FileOutputCommitterContainer.java:251)
>         at org.apache.hadoop.mapred.LocalJobRunner$Job.run(LocalJobRunner.java:537)
> 2014-06-17 15:54:40,804 ERROR lockmgr.DbLockManager (DbLockManager.java:unlock(114)) - Metastore could find no record of lock 1
> 2014-06-17 15:54:40,810 INFO  mapreduce.FileOutputCommitterContainer (FileOutputCommitterContainer.java:cancelDelegationTokens(976)) - Cancelling delegation token for the job.
> {noformat}



--
This message was sent by Atlassian JIRA
(v6.2#6252)