Issue Details (XML | Word | Printable)

Key: NUCRDBMS-716
Type: Bug Bug
Status: Closed Closed
Resolution: Won't Fix
Priority: Testcase Required Testcase Required
Assignee: Unassigned
Reporter: shanyu zhao
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
DataNucleus Store RDBMS

Reconnection to rdbms database failure

Created: 04/Dec/13 04:07 AM   Updated: 01/Mar/14 07:39 PM   Resolved: 18/Feb/14 05:48 PM
Component/s: Connection
Affects Version/s: 3.2.7
Fix Version/s: None

Datastore: Microsoft SQL Server
Severity: Production


 Description  « Hide
When running hive CLI tool, after the a period of idle time, any query will result in SemanticException. The root cause is that the metastore database drops idle connections, and metastore service's reconnection to metastore database failed.

This is a regression because when using 3.0.9, this problem does not exist.

I'm running hive 0.12.0 using datanucleus rdbms 3.2.7 with MS SQL server.

This is the detailed exception:

2013-11-28 19:50:10,159 INFO parse.SemanticAnalyzer (SemanticAnalyzer.java:getMetaData(1060)) - Get metadata for source tables
2013-11-28 19:50:10,186 INFO metastore.HiveMetaStore (HiveMetaStore.java:logInfo(454)) - 4: source:/10.238.142.14 get_table : db=default tbl=hivesampletable
2013-11-28 19:50:10,186 INFO HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(239)) - ugi=hdirdp ip=/10.238.142.14 cmd=source:/10.238.142.14 get_table : db=default tbl=hivesampletable
2013-11-28 19:50:29,625 ERROR bonecp.ConnectionHandle (ConnectionHandle.java:markPossiblyBroken(297)) - Database access problem. Killing off all remaining connections in the connection pool. SQL State = 08S01
2013-11-28 19:50:29,627 ERROR metastore.RetryingHMSHandler (RetryingHMSHandler.java:invoke(155)) - JDO datastore error. Retrying HMSHandler after 1000 ms (attempt 1 of 5)
2013-11-28 19:50:30,627 INFO metastore.HiveMetaStore (HiveMetaStore.java:logInfo(454)) - 4: source:/10.238.142.14 get_table : db=default tbl=hivesampletable
2013-11-28 19:50:30,628 INFO HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(239)) - ugi=hdirdp ip=/10.238.142.14 cmd=source:/10.238.142.14 get_table : db=default tbl=hivesampletable
2013-11-28 19:50:30,738 ERROR metastore.RetryingHMSHandler (RetryingHMSHandler.java:invoke(155)) - JDO datastore error. Retrying HMSHandler after 1000 ms (attempt 2 of 5)
2013-11-28 19:50:31,739 INFO metastore.HiveMetaStore (HiveMetaStore.java:logInfo(454)) - 4: source:/10.238.142.14 get_table : db=default tbl=hivesampletable
2013-11-28 19:50:31,739 INFO HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(239)) - ugi=hdirdp ip=/10.238.142.14 cmd=source:/10.238.142.14 get_table : db=default tbl=hivesampletable
2013-11-28 19:50:31,838 ERROR metastore.RetryingHMSHandler (RetryingHMSHandler.java:invoke(155)) - JDO datastore error. Retrying HMSHandler after 1000 ms (attempt 3 of 5)
2013-11-28 19:50:32,838 INFO metastore.HiveMetaStore (HiveMetaStore.java:logInfo(454)) - 4: source:/10.238.142.14 get_table : db=default tbl=hivesampletable
2013-11-28 19:50:32,838 INFO HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(239)) - ugi=hdirdp ip=/10.238.142.14 cmd=source:/10.238.142.14 get_table : db=default tbl=hivesampletable
2013-11-28 19:50:32,883 ERROR metastore.RetryingHMSHandler (RetryingHMSHandler.java:invoke(155)) - JDO datastore error. Retrying HMSHandler after 1000 ms (attempt 4 of 5)
2013-11-28 19:50:33,883 INFO metastore.HiveMetaStore (HiveMetaStore.java:logInfo(454)) - 4: source:/10.238.142.14 get_table : db=default tbl=hivesampletable
2013-11-28 19:50:33,883 INFO HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(239)) - ugi=hdirdp ip=/10.238.142.14 cmd=source:/10.238.142.14 get_table : db=default tbl=hivesampletable
2013-11-28 19:50:33,923 ERROR metastore.RetryingHMSHandler (RetryingHMSHandler.java:invoke(155)) - JDO datastore error. Retrying HMSHandler after 1000 ms (attempt 5 of 5)
2013-11-28 19:50:34,923 INFO metastore.HiveMetaStore (HiveMetaStore.java:logInfo(454)) - 4: source:/10.238.142.14 get_table : db=default tbl=hivesampletable
2013-11-28 19:50:34,924 INFO HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(239)) - ugi=hdirdp ip=/10.238.142.14 cmd=source:/10.238.142.14 get_table : db=default tbl=hivesampletable
2013-11-28 19:50:34,997 ERROR metastore.RetryingHMSHandler (RetryingHMSHandler.java:invoke(147)) - javax.jdo.JDODataStoreException: The connection is closed.
at org.datanucleus.api.jdo.NucleusJDOHelper.getJDOExceptionForNucleusException(NucleusJDOHelper.java:451)
at org.datanucleus.api.jdo.JDOTransaction.commit(JDOTransaction.java:165)
at org.apache.hadoop.hive.metastore.ObjectStore.commitTransaction(ObjectStore.java:358)
at org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:761)
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:601)
at org.apache.hadoop.hive.metastore.RetryingRawStore.invoke(RetryingRawStore.java:124)
at $Proxy0.getTable(Unknown Source)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.get_table(HiveMetaStore.java:1371)
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:601)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:103)
at $Proxy8.get_table(Unknown Source)
at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$get_table.getResult(ThriftHiveMetastore.java:6547)
at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$get_table.getResult(ThriftHiveMetastore.java:6531)
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:107)
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:1491)
at org.apache.hadoop.hive.shims.HadoopShimsSecure.doAs(HadoopShimsSecure.java:526)
at org.apache.hadoop.hive.metastore.TUGIBasedProcessor.process(TUGIBasedProcessor.java:118)
at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:206)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)
NestedThrowablesStackTrace:
com.microsoft.sqlserver.jdbc.SQLServerException: The connection is closed.
at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:171)
at com.microsoft.sqlserver.jdbc.SQLServerConnection.checkClosed(SQLServerConnection.java:319)
at com.microsoft.sqlserver.jdbc.SQLServerConnection.getAutoCommit(SQLServerConnection.java:1602)
at com.jolbox.bonecp.ConnectionHandle.getAutoCommit(ConnectionHandle.java:587)
at org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.release(ConnectionFactoryImpl.java:329)
at org.datanucleus.store.rdbms.scostore.MapEntrySetStore.iterator(MapEntrySetStore.java:445)
at org.datanucleus.store.types.SCOUtils.populateMapDelegateWithStoreData(SCOUtils.java:952)
at org.datanucleus.store.types.backed.Map.loadFromStore(Map.java:308)
at org.datanucleus.store.types.backed.Map.getValue(Map.java:267)
at org.datanucleus.state.JDOStateManager.unwrapSCOField(JDOStateManager.java:3550)
at org.datanucleus.store.fieldmanager.DetachFieldManager.internalFetchObjectField(DetachFieldManager.java:244)
at org.datanucleus.store.fieldmanager.AbstractFetchDepthFieldManager.fetchObjectField(AbstractFetchDepthFieldManager.java:113)
at org.datanucleus.state.JDOStateManager.detach(JDOStateManager.java:3987)
at org.datanucleus.ExecutionContextImpl.performDetachAllOnTxnEnd(ExecutionContextImpl.java:4590)
at org.datanucleus.ExecutionContextImpl.postCommit(ExecutionContextImpl.java:4689)
at org.datanucleus.ExecutionContextImpl.transactionCommitted(ExecutionContextImpl.java:660)
at org.datanucleus.TransactionImpl.internalPostCommit(TransactionImpl.java:550)
at org.datanucleus.TransactionImpl.commit(TransactionImpl.java:331)
at org.datanucleus.api.jdo.JDOTransaction.commit(JDOTransaction.java:98)
at org.apache.hadoop.hive.metastore.ObjectStore.commitTransaction(ObjectStore.java:358)
at org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:761)
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:601)
at org.apache.hadoop.hive.metastore.RetryingRawStore.invoke(RetryingRawStore.java:124)
at $Proxy0.getTable(Unknown Source)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.get_table(HiveMetaStore.java:1371)
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:601)
at org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:103)
at $Proxy8.get_table(Unknown Source)
at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$get_table.getResult(ThriftHiveMetastore.java:6547)
at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$get_table.getResult(ThriftHiveMetastore.java:6531)
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:107)
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:1491)
at org.apache.hadoop.hive.shims.HadoopShimsSecure.doAs(HadoopShimsSecure.java:526)
at org.apache.hadoop.hive.metastore.TUGIBasedProcessor.process(TUGIBasedProcessor.java:118)
at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:206)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)

Andy Jefferson added a comment - 04/Dec/13 07:06 AM - edited
No way of seeing this here. Suggest you work it out yourself since you're the only person who can see it. Obviously the connection pool is responsible for opening/closing connections *not* DataNucleus, and all pools provide different ways of validating connections before handing them out; beyond the responsibilities of DataNucleus

Andy Jefferson made changes - 04/Dec/13 07:06 AM
Field Original Value New Value
Priority Major [ 3 ] No Testcase [ 6 ]
Andy Jefferson added a comment - 18/Feb/14 05:48 PM
Still can't see how this is related to DataNucleus, and no testcase. Re-post here if you come up with a testcase

Andy Jefferson made changes - 18/Feb/14 05:48 PM
Status Open [ 1 ] Resolved [ 5 ]
Resolution Won't Fix [ 2 ]
Andy Jefferson made changes - 01/Mar/14 07:39 PM
Status Resolved [ 5 ] Closed [ 6 ]