Support Questions
Find answers, ask questions, and share your expertise
Announcements
Alert: Welcome to the Unified Cloudera Community. Former HCC members be sure to read and learn how to activate your account here.

Catalog can not work normally after both Catalog and Hive Metastore was restarted.

Highlighted

Catalog can not work normally after both Catalog and Hive Metastore was restarted.

Explorer

Encoutering the following problem during using Impala2.2, any help can be appreciated.
Catalog was restarted at 2:03 on Apr 5, then Hive Metastore also was restarted. But Catalog can not work normally, some log fragments can be referenced as follows:
I0405 02:04:22.680775 95061 HiveMetaStoreClient.java:370] Trying to connect to metastore with URI thrift://*.*.*.*:*
W0405 02:04:22.696897 95061 HiveMetaStoreClient.java:417] Failed to connect to the MetaStore Server...
......
I0405 02:04:22.733120 95061 HiveMetaStoreClient.java:370] Trying to connect to metastore with URI thrift://*.*.*.*:*
W0405 02:04:52.625758 95061 HiveMetaStoreClient.java:417] Failed to connect to the MetaStore Server...
I0405 02:04:52.625*9 95061 HiveMetaStoreClient.java:370] Trying to connect to metastore with URI thrift://*.*.*.*:*
E0405 02:05:02.716311 95061 MetaStoreUtils.java:1109] Got exception: org.apache.hadoop.hive.metastore.api.MetaException javax.jdo.JDODataStoreException: Timed out waiting for a free available connection.
NestedThrowables:
java.sql.SQLException: Timed out waiting for a free available connection.
Java exception follows:
MetaException(message:javax.jdo.JDODataStoreException: Timed out waiting for a free available connection.
NestedThrowables:
java.sql.SQLException: Timed out waiting for a free available connection.)
at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$get_all_databases_result$get_all_databases_resultStandardScheme.read(ThriftHiveMetastore.java:15154)
at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$get_all_databases_result$get_all_databases_resultStandardScheme.read(ThriftHiveMetastore.java:15122)
at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$get_all_databases_result.read(ThriftHiveMetastore.java:15064)
at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:78)
at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_all_databases(ThriftHiveMetastore.java:633)
at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_all_databases(ThriftHiveMetastore.java:621)
at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getAllDatabases(HiveMetaStoreClient.java:920)
at com.cloudera.impala.catalog.CatalogServiceCatalog.reset(CatalogServiceCatalog.java:476)
at com.cloudera.impala.service.JniCatalog.<init>(JniCatalog.java:94)
E0405 02:05:02.716418 95061 MetaStoreUtils.java:1110] Converting exception to MetaException
E0405 02:05:02.719918 95061 CatalogServiceCatalog.java:524] MetaException(message:Got exception: org.apache.hadoop.hive.metastore.api.MetaException javax.jdo.JDODataStoreException: Timed out waiting for a free available connection.
NestedThrowables:
java.sql.SQLException: Timed out waiting for a free available connection.)
E0405 02:05:02.720211 95061 JniCatalog.java:96] Error initialializing Catalog. Please run 'invalidate metadata'
Java exception follows:
com.cloudera.impala.catalog.CatalogException: Error initializing Catalog. Catalog may be empty.
at com.cloudera.impala.catalog.CatalogServiceCatalog.reset(CatalogServiceCatalog.java:525)
at com.cloudera.impala.service.JniCatalog.<init>(JniCatalog.java:94)
Caused by: MetaException(message:Got exception: org.apache.hadoop.hive.metastore.api.MetaException javax.jdo.JDODataStoreException: Timed out waiting for a free available connection.
NestedThrowables:
java.sql.SQLException: Timed out waiting for a free available connection.)
at org.apache.hadoop.hive.metastore.MetaStoreUtils.logAndThrowMetaException(MetaStoreUtils.java:1111)
at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getAllDatabases(HiveMetaStoreClient.java:922)
at com.cloudera.impala.catalog.CatalogServiceCatalog.reset(CatalogServiceCatalog.java:476)
... 1 more
I0405 02:05:02.727511 95061 thrift-server.cc:423] ThriftServer 'StatestoreSubscriber' started on port: *
I0405 02:05:02.727520 95061 statestore-subscriber.cc:207] Registering with statestore
I0405 02:05:02.733942 95061 statestore-subscriber.cc:211] statestore registration successful
I0405 02:05:02.735746 95061 thrift-server.cc:423] ThriftServer 'CatalogService' started on port: *
I0405 02:05:02.735759 95061 catalogd-main.cc:95] CatalogService started on port: *
I0405 02:05:04.011958 194733 catalog-server.cc:269] Catalog Version: 0 Last Catalog Version: 0
......
I0405 02:15:04.073102 194733 catalog-server.cc:269] Catalog Version: 0 Last Catalog Version: 0
......
E0405 03:00:25.278010 241439 catalog-server.cc:78] DatabaseNotFoundException: Database 'test' not found
E0405 03:00:25.363070 241650 catalog-server.cc:78] DatabaseNotFoundException: Database 'test' not found
E0405 03:00:25.441145 241678 catalog-server.cc:78] DatabaseNotFoundException: Database 'test' not found
E0405 03:00:25.890606 240419 catalog-server.cc:78] DatabaseNotFoundException: Database 'test' not found

It looks like that Catalog continuously connected Hive Metastore to obtain meta-data from 02:04:22 to 02:04:52, because Hive Metastore did not restore nomrally until 02:06, so these connections failed, and throwed some exceptions.
Catalog never access Hive Metastore later, so DatabaseNotFoundException is throwed when some applications access impala.
I noticed there is keyword "Error initializing Catalog. Catalog may be empty" in Catalog log, it looks like Catalog has realized the abnormal metadata, so i wonder why catalog can not continuously attempt to connect it before Hive Metastore is okay?

4 REPLIES 4

Re: Catalog can not work normally after both Catalog and Hive Metastore was restarted.

Explorer
any ideas?
Highlighted

Re: Catalog can not work normally after both Catalog and Hive Metastore was restarted.

Expert Contributor

here is the code that would throw that error you called out[1]. Based on what i'm seeing, it is likely failing to build the db connection cache and throwing that error. 

 

https://github.com/cloudera/Impala/blob/cdh5-2.2.0_5.4.0/fe/src/main/java/com/cloudera/impala/catalo...

 

looks like that block has changed significantly in later releases, There may be enhancements to fix this as well.

 

you might verify that the database is definately up and able to be connected to/run commands against?

Highlighted

Re: Catalog can not work normally after both Catalog and Hive Metastore was restarted.

Cloudera Employee

Do you see anything in the Hive metastore logs that indicate a problem?

Highlighted

Re: Catalog can not work normally after both Catalog and Hive Metastore was restarted.

Explorer

I am sorry from delay response.

Database was down and could not be connected from 02:04 to 02:05, so Hive MetaStore continuously timed out waiting for a free available connection as follows:

 

2016-04-05 02:05:08,059 | ERROR | main | Failed initialising database. | org.datanucleus.util.Log4JLogger.error(Log4JLogger.java:125)
Timed out waiting for a free available connection.
org.datanucleus.exceptions.NucleusDataStoreException: Timed out waiting for a free available connection.
at org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.getConnection(ConnectionFactoryImpl.java:516)
at org.datanucleus.store.rdbms.RDBMSStoreManager.<init>(RDBMSStoreManager.java:298)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
at org.datanucleus.plugin.NonManagedPluginRegistry.createExecutableExtension(NonManagedPluginRegistry.java:631)
at org.datanucleus.plugin.PluginManager.createExecutableExtension(PluginManager.java:301)
at org.datanucleus.NucleusContext.createStoreManagerForProperties(NucleusContext.java:1187)
at org.datanucleus.NucleusContext.initialise(NucleusContext.java:356)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.freezeConfiguration(JDOPersistenceManagerFactory.java:775)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.createPersistenceManagerFactory(JDOPersistenceManagerFactory.java:333)
at org.datanucleus.api.jdo.JDOPersistenceManagerFactory.getPersistenceManagerFactory(JDOPersistenceManagerFactory.java:202)
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 javax.jdo.JDOHelper$16.run(JDOHelper.java:1965)
at java.security.AccessController.doPrivileged(Native Method)
at javax.jdo.JDOHelper.invoke(JDOHelper.java:1960)
at javax.jdo.JDOHelper.invokeGetPersistenceManagerFactoryOnImplementation(JDOHelper.java:1166)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:808)
at javax.jdo.JDOHelper.getPersistenceManagerFactory(JDOHelper.java:701)
at org.apache.hadoop.hive.metastore.ObjectStore.getPMF(ObjectStore.java:338)
at org.apache.hadoop.hive.metastore.ObjectStore.getPersistenceManager(ObjectStore.java:367)
at org.apache.hadoop.hive.metastore.ObjectStore.initialize(ObjectStore.java:253)
at org.apache.hadoop.hive.metastore.ObjectStore.setConf(ObjectStore.java:228)
at org.apache.hadoop.util.ReflectionUtils.setConf(ReflectionUtils.java:73)
at org.apache.hadoop.util.ReflectionUtils.newInstance(ReflectionUtils.java:133)
at org.apache.hadoop.hive.metastore.RawStoreProxy.<init>(RawStoreProxy.java:58)
at org.apache.hadoop.hive.metastore.RawStoreProxy.getProxy(RawStoreProxy.java:67)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.newRawStore(HiveMetaStore.java:574)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.getMS(HiveMetaStore.java:552)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.createDefaultDB(HiveMetaStore.java:600)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.init(HiveMetaStore.java:473)
at org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.<init>(HiveMetaStore.java:432)
at org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:5739)
at org.apache.hadoop.hive.metastore.HiveMetaStore.main(HiveMetaStore.java:5652)
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.sql.SQLException: Timed out waiting for a free available connection.
at com.jolbox.bonecp.DefaultConnectionStrategy.getConnectionInternal(DefaultConnectionStrategy.java:88)
at com.jolbox.bonecp.AbstractConnectionStrategy.getConnection(AbstractConnectionStrategy.java:90)
at com.jolbox.bonecp.BoneCP.getConnection(BoneCP.java:553)
at com.jolbox.bonecp.BoneCPDataSource.getConnection(BoneCPDataSource.java:131)
at org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.getConnection(ConnectionFactoryImpl.java:501)
... 42 more

 

So the exception of catalog  during the period should be clear, but both database and Hive MetaStore had recovered normally after 02:06(can reference the following log fragments),   why Catalog can not counitue to connect them?

 

2016-04-05 02:06:00,868 | INFO | pool-6-thread-6 | Creating password for identifier: owner=*, renewer=*, realUser=test@HADOOP.COM, issueDate=1459793160868, maxDate=1460397960868, sequenceNumber=2, masterKeyId=832 | org.apache.hadoop.security.token.delegation.AbstractDelegationTokenSecretManager.createPassword(AbstractDelegationTokenSecretManager.java:284)
2016-04-05 02:06:00,868 | INFO | pool-6-thread-6 | 6: Opening raw store with implemenation class:org.apache.hadoop.hive.metastore.ObjectStore | org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.newRawStore(HiveMetaStore.java:570)
2016-04-05 02:06:00,870 | INFO | pool-6-thread-6 | ObjectStore, initialize called | org.apache.hadoop.hive.metastore.ObjectStore.initialize(ObjectStore.java:251)
2016-04-05 02:06:00,876 | INFO | pool-6-thread-6 | Initialized ObjectStore | org.apache.hadoop.hive.metastore.ObjectStore.setConf(ObjectStore.java:234)
2016-04-05 02:06:00,913 | INFO | pool-6-thread-6 | Adding metastore authorization provider: org.apache.hadoop.hive.ql.security.authorization.StorageBasedAuthorizationProvider | org.apache.hadoop.hive.ql.metadata.HiveUtils.getMetaStoreAuthorizeProviderManagers(HiveUtils.java:352)
2016-04-05 02:06:00,995 | INFO | pool-6-thread-7 | 7: Opening raw store with implemenation class:org.apache.hadoop.hive.metastore.ObjectStore | org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.newRawStore(HiveMetaStore.java:570)
2016-04-05 02:06:00,998 | INFO | pool-6-thread-7 | ObjectStore, initialize called | org.apache.hadoop.hive.metastore.ObjectStore.initialize(ObjectStore.java:251)
2016-04-05 02:06:01,003 | INFO | pool-6-thread-7 | Initialized ObjectStore | org.apache.hadoop.hive.metastore.ObjectStore.setConf(ObjectStore.java:234)
2016-04-05 02:06:01,024 | INFO | pool-6-thread-8 | 8: Opening raw store with implemenation class:org.apache.hadoop.hive.metastore.ObjectStore | org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.newRawStore(HiveMetaStore.java:570)
2016-04-05 02:06:01,026 | INFO | pool-6-thread-8 | ObjectStore, initialize called | org.apache.hadoop.hive.metastore.ObjectStore.initialize(ObjectStore.java:251)
2016-04-05 02:06:01,030 | INFO | pool-6-thread-8 | Initialized ObjectStore | org.apache.hadoop.hive.metastore.ObjectStore.setConf(ObjectStore.java:234)
2016-04-05 02:06:01,892 | INFO | pool-6-thread-9 | Creating password for identifier: owner=*, renewer=*, realUser=test@HADOOP.COM, issueDate=1459793161891, maxDate=1460397961891, sequenceNumber=3, masterKeyId=832 | org.apache.hadoop.security.token.delegation.AbstractDelegationTokenSecretManager.createPassword(AbstractDelegationTokenSecretManager.java:284)
2016-04-05 02:06:01,893 | INFO | pool-6-thread-9 | 9: Opening raw store with implemenation class:org.apache.hadoop.hive.metastore.ObjectStore | org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.newRawStore(HiveMetaStore.java:570)
2016-04-05 02:06:01,895 | INFO | pool-6-thread-9 | ObjectStore, initialize called | org.apache.hadoop.hive.metastore.ObjectStore.initialize(ObjectStore.java:251)
2016-04-05 02:06:01,900 | INFO | pool-6-thread-9 | Initialized ObjectStore | org.apache.hadoop.hive.metastore.ObjectStore.setConf(ObjectStore.java:234)
2016-04-05 02:06:02,006 | INFO | pool-6-thread-7 | Adding metastore authorization provider: org.apache.hadoop.hive.ql.security.authorization.StorageBasedAuthorizationProvider | org.apache.hadoop.hive.ql.metadata.HiveUtils.getMetaStoreAuthorizeProviderManagers(HiveUtils.java:352)
2016-04-05 02:06:02,014 | INFO | pool-6-thread-9 | Adding metastore authorization provider: org.apache.hadoop.hive.ql.security.authorization.StorageBasedAuthorizationProvider | org.apache.hadoop.hive.ql.metadata.HiveUtils.getMetaStoreAuthorizeProviderManagers(HiveUtils.java:352)

Don't have an account?
Coming from Hortonworks? Activate your account here