[
https://issues.apache.org/jira/browse/SENTRY-1630?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16067512#comment-16067512
]
Vamsee Yarlagadda commented on SENTRY-1630:
-------------------------------------------
I was fortunate to hit this bug and was able to find the root cause of the
problem.
It looks like the issue is that we are using the same HiveMetaStoreClient
instance to make multiple thrift calls in parallel and I imagine this access
type is not supported by the API itself.
{code}
private class DbTask extends BaseTask {
private final String dbName;
DbTask(String dbName) {
//Database names are case insensitive
this.dbName = safeIntern(dbName.toLowerCase());
}
@Override
ObjectMapping doTask() throws TException {
Database db = client.getDatabase(dbName);
if (!dbName.equalsIgnoreCase(db.getName())) {
{code}
Here are the errors seen in the log to explain this:
Sentry log reporting threads receiving different Database objects than
requested:
{code}
[systest@vamsee-sentryha-1 ~]$ cat
/var/log/sentry/hadoop-cmf-sentry-SENTRY_SERVER-vamsee-sentryha-1.vpc.cloudera.com.log.out.1
| grep -C 10 -e "does not match"
2017-06-28 12:04:23,039 INFO org.apache.sentry.service.thrift.HMSFollower:
Using kerberos principal:
sentry/[email protected]
2017-06-28 12:04:23,039 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Logging in with new
Context
2017-06-28 12:04:23,042 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Sentry Ticket renewer
thread started
2017-06-28 12:04:23,043 INFO hive.metastore: Trying to connect to metastore
with URI thrift://vamsee-sentryha-1.vpc.cloudera.com:9083
2017-06-28 12:04:23,055 INFO hive.metastore: Opened a connection to metastore,
current connections: 1
2017-06-28 12:04:23,055 INFO hive.metastore: Connected to metastore.
2017-06-28 12:04:23,055 INFO org.apache.sentry.service.thrift.HMSFollower:
Secure connection established with HMS
2017-06-28 12:04:23,055 INFO org.apache.sentry.service.thrift.HMSFollower:
HMSFollower of Sentry successfully connected to HMS
2017-06-28 12:04:23,078 INFO org.apache.sentry.service.thrift.HMSFollower:
Before fetching hive full snapshot, Current NotificationID =
CurrentNotificationEventId(eventId:3263).
2017-06-28 12:04:23,078 INFO org.apache.sentry.service.thrift.HMSFollower:
Request full HMS snapshot
2017-06-28 12:04:23,122 WARN org.apache.sentry.hdfs.FullUpdateInitializer:
Database name test_gr_db_2017_06_27_16_14_30 does not match
test_gr_db_2017_06_27_16_03_44
2017-06-28 12:04:23,935 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Sentry Ticket renewer
thread finished
2017-06-28 12:04:24,087 ERROR org.apache.sentry.hdfs.FullUpdateInitializer:
Failed to execute task
org.apache.thrift.TApplicationException: get_database failed: out of sequence
response
at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:84)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_database(ThriftHiveMetastore.java:670)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_database(ThriftHiveMetastore.java:657)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getDatabase(HiveMetaStoreClient.java:1213)
at
org.apache.sentry.hdfs.FullUpdateInitializer$DbTask.doTask(FullUpdateInitializer.java:347)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
--
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:178)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2017-06-28 12:04:24,089 INFO org.apache.sentry.service.thrift.HMSFollower: Hive
full snapshot is Empty. Perhaps, HMS does not have any data
2017-06-28 12:04:24,095 INFO org.apache.sentry.service.thrift.HMSFollower:
Before fetching hive full snapshot, Current NotificationID =
CurrentNotificationEventId(eventId:3263).
2017-06-28 12:04:24,095 INFO org.apache.sentry.service.thrift.HMSFollower:
Request full HMS snapshot
2017-06-28 12:04:24,130 WARN org.apache.sentry.hdfs.FullUpdateInitializer:
Database name test_gr_db_2017_06_27_16_14_30 does not match
gr_db_2017_06_27_16_32_48
2017-06-28 12:04:25,103 ERROR org.apache.sentry.hdfs.FullUpdateInitializer:
Failed to execute task
org.apache.thrift.TApplicationException: get_database failed: out of sequence
response
at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:84)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_database(ThriftHiveMetastore.java:670)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_database(ThriftHiveMetastore.java:657)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getDatabase(HiveMetaStoreClient.java:1213)
at
org.apache.sentry.hdfs.FullUpdateInitializer$DbTask.doTask(FullUpdateInitializer.java:347)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:178)
--
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:178)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2017-06-28 12:04:25,105 INFO org.apache.sentry.service.thrift.HMSFollower: Hive
full snapshot is Empty. Perhaps, HMS does not have any data
2017-06-28 12:04:25,111 INFO org.apache.sentry.service.thrift.HMSFollower:
Before fetching hive full snapshot, Current NotificationID =
CurrentNotificationEventId(eventId:3263).
2017-06-28 12:04:25,111 INFO org.apache.sentry.service.thrift.HMSFollower:
Request full HMS snapshot
2017-06-28 12:04:25,146 WARN org.apache.sentry.hdfs.FullUpdateInitializer:
Database name test_gr_db_2017_06_27_16_14_30 does not match
gr_db_2017_06_27_16_32_48
2017-06-28 12:04:26,118 ERROR org.apache.sentry.hdfs.FullUpdateInitializer:
Failed to execute task
org.apache.thrift.TApplicationException: get_database failed: out of sequence
response
at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:84)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_database(ThriftHiveMetastore.java:670)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_database(ThriftHiveMetastore.java:657)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getDatabase(HiveMetaStoreClient.java:1213)
at
org.apache.sentry.hdfs.FullUpdateInitializer$DbTask.doTask(FullUpdateInitializer.java:347)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:178)
--
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:178)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2017-06-28 12:04:26,123 INFO org.apache.sentry.service.thrift.HMSFollower: Hive
full snapshot is Empty. Perhaps, HMS does not have any data
2017-06-28 12:04:26,143 INFO org.apache.sentry.service.thrift.HMSFollower:
Before fetching hive full snapshot, Current NotificationID =
CurrentNotificationEventId(eventId:3263).
2017-06-28 12:04:26,143 INFO org.apache.sentry.service.thrift.HMSFollower:
Request full HMS snapshot
2017-06-28 12:04:26,232 WARN org.apache.sentry.hdfs.FullUpdateInitializer:
Database name gr_db_2017_06_27_16_44_47 does not match gr_db_2017_06_27_16_34_13
2017-06-28 12:04:26,277 ERROR hive.log: Got exception:
org.apache.thrift.TApplicationException get_all_tables failed: out of sequence
response
org.apache.thrift.TApplicationException: get_all_tables failed: out of sequence
response
at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:84)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_all_tables(ThriftHiveMetastore.java:1235)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_all_tables(ThriftHiveMetastore.java:1222)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getAllTables(HiveMetaStoreClient.java:1348)
at
org.apache.sentry.hdfs.FullUpdateInitializer$DbTask.doTask(FullUpdateInitializer.java:352)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:178)
--
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getAllTables(HiveMetaStoreClient.java:1348)
at
org.apache.sentry.hdfs.FullUpdateInitializer$DbTask.doTask(FullUpdateInitializer.java:352)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:178)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2017-06-28 12:04:26,344 ERROR hive.log: Converting exception to MetaException
2017-06-28 12:04:26,375 WARN org.apache.sentry.hdfs.FullUpdateInitializer:
Database name test_gr_db_2017_06_27_16_30_50 does not match
test_gr_db_2017_06_27_16_14_30
2017-06-28 12:04:27,216 ERROR org.apache.sentry.hdfs.FullUpdateInitializer:
Failed to execute task
org.apache.thrift.TApplicationException: get_database failed: out of sequence
response
at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:84)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_database(ThriftHiveMetastore.java:670)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_database(ThriftHiveMetastore.java:657)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getDatabase(HiveMetaStoreClient.java:1213)
at
org.apache.sentry.hdfs.FullUpdateInitializer$DbTask.doTask(FullUpdateInitializer.java:347)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:178)
--
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:178)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2017-06-28 12:04:27,218 INFO org.apache.sentry.service.thrift.HMSFollower: Hive
full snapshot is Empty. Perhaps, HMS does not have any data
2017-06-28 12:04:27,224 INFO org.apache.sentry.service.thrift.HMSFollower:
Before fetching hive full snapshot, Current NotificationID =
CurrentNotificationEventId(eventId:3263).
2017-06-28 12:04:27,224 INFO org.apache.sentry.service.thrift.HMSFollower:
Request full HMS snapshot
2017-06-28 12:04:27,258 WARN org.apache.sentry.hdfs.FullUpdateInitializer:
Database name test_gr_db_2017_06_27_16_14_30 does not match
gr_db_2017_06_27_16_32_48
2017-06-28 12:04:28,231 ERROR org.apache.sentry.hdfs.FullUpdateInitializer:
Failed to execute task
org.apache.thrift.TApplicationException: get_database failed: out of sequence
response
at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:84)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_database(ThriftHiveMetastore.java:670)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_database(ThriftHiveMetastore.java:657)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getDatabase(HiveMetaStoreClient.java:1213)
at
org.apache.sentry.hdfs.FullUpdateInitializer$DbTask.doTask(FullUpdateInitializer.java:347)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:178)
--
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:178)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2017-06-28 12:04:28,234 INFO org.apache.sentry.service.thrift.HMSFollower: Hive
full snapshot is Empty. Perhaps, HMS does not have any data
2017-06-28 12:04:28,240 INFO org.apache.sentry.service.thrift.HMSFollower:
Before fetching hive full snapshot, Current NotificationID =
CurrentNotificationEventId(eventId:3263).
2017-06-28 12:04:28,240 INFO org.apache.sentry.service.thrift.HMSFollower:
Request full HMS snapshot
2017-06-28 12:04:28,271 WARN org.apache.sentry.hdfs.FullUpdateInitializer:
Database name test_gr_db_2017_06_27_16_14_30 does not match
gr_db_2017_06_27_16_32_48
2017-06-28 12:04:29,246 ERROR org.apache.sentry.hdfs.FullUpdateInitializer:
Failed to execute task
org.apache.thrift.TApplicationException: get_database failed: out of sequence
response
at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:84)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_database(ThriftHiveMetastore.java:670)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_database(ThriftHiveMetastore.java:657)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getDatabase(HiveMetaStoreClient.java:1213)
at
org.apache.sentry.hdfs.FullUpdateInitializer$DbTask.doTask(FullUpdateInitializer.java:347)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:178)
--
2017-06-28 12:06:39,533 INFO org.apache.sentry.service.thrift.HMSFollower:
Using kerberos principal:
sentry/[email protected]
2017-06-28 12:06:39,534 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Logging in with new
Context
2017-06-28 12:06:39,615 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Sentry Ticket renewer
thread started
2017-06-28 12:06:39,729 INFO hive.metastore: Trying to connect to metastore
with URI thrift://vamsee-sentryha-1.vpc.cloudera.com:9083
2017-06-28 12:06:39,844 INFO hive.metastore: Opened a connection to metastore,
current connections: 1
2017-06-28 12:06:39,844 INFO hive.metastore: Connected to metastore.
2017-06-28 12:06:39,844 INFO org.apache.sentry.service.thrift.HMSFollower:
Secure connection established with HMS
2017-06-28 12:06:39,844 INFO org.apache.sentry.service.thrift.HMSFollower:
HMSFollower of Sentry successfully connected to HMS
2017-06-28 12:06:39,939 INFO org.apache.sentry.service.thrift.HMSFollower:
Before fetching hive full snapshot, Current NotificationID =
CurrentNotificationEventId(eventId:3269).
2017-06-28 12:06:39,939 INFO org.apache.sentry.service.thrift.HMSFollower:
Request full HMS snapshot
2017-06-28 12:06:39,987 WARN org.apache.sentry.hdfs.FullUpdateInitializer:
Database name gr_db_2017_06_27_16_32_48 does not match
test_gr_db_2017_06_27_16_14_30
2017-06-28 12:06:40,143 WARN com.jolbox.bonecp.BoneCPConfig: Max Connections <
1. Setting to 20
2017-06-28 12:06:40,179 WARN com.jolbox.bonecp.BoneCPConfig: Max Connections <
1. Setting to 20
2017-06-28 12:06:40,203 INFO org.apache.sentry.service.thrift.SentryService:
ProcessorFactory being used:
org.apache.sentry.hdfs.SentryHDFSServiceProcessorFactory
2017-06-28 12:06:40,204 INFO
org.apache.sentry.hdfs.SentryHDFSServiceProcessorFactory: Calling
registerProcessor from SentryHDFSServiceProcessorFactory
2017-06-28 12:06:40,215 INFO org.apache.sentry.service.thrift.SentryService:
Serving on vamsee-sentryha-1.vpc.cloudera.com/172.26.23.16:8038
2017-06-28 12:06:40,294 INFO org.eclipse.jetty.server.Server:
jetty-7.6.0.v20120127
2017-06-28 12:06:40,304 INFO org.eclipse.jetty.server.handler.ContextHandler:
started o.e.j.s.h.ContextHandler{/,null}
2017-06-28 12:06:40,311 INFO org.eclipse.jetty.server.handler.ContextHandler:
started o.e.j.s.ServletContextHandler{/,null}
2017-06-28 12:06:40,326 INFO org.eclipse.jetty.server.AbstractConnector:
Started [email protected]:29000
2017-06-28 12:06:40,326 INFO org.apache.sentry.service.thrift.SentryService:
Sentry service is ready to serve client requests
--
2017-06-28 12:07:07,264 INFO org.apache.sentry.service.thrift.HMSFollower:
Using kerberos principal:
sentry/[email protected]
2017-06-28 12:07:07,264 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Logging in with new
Context
2017-06-28 12:07:07,268 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Sentry Ticket renewer
thread started
2017-06-28 12:07:07,269 INFO hive.metastore: Trying to connect to metastore
with URI thrift://vamsee-sentryha-1.vpc.cloudera.com:9083
2017-06-28 12:07:07,280 INFO hive.metastore: Opened a connection to metastore,
current connections: 1
2017-06-28 12:07:07,280 INFO hive.metastore: Connected to metastore.
2017-06-28 12:07:07,280 INFO org.apache.sentry.service.thrift.HMSFollower:
Secure connection established with HMS
2017-06-28 12:07:07,280 INFO org.apache.sentry.service.thrift.HMSFollower:
HMSFollower of Sentry successfully connected to HMS
2017-06-28 12:07:07,293 INFO org.apache.sentry.service.thrift.HMSFollower:
Before fetching hive full snapshot, Current NotificationID =
CurrentNotificationEventId(eventId:3269).
2017-06-28 12:07:07,293 INFO org.apache.sentry.service.thrift.HMSFollower:
Request full HMS snapshot
2017-06-28 12:07:07,328 WARN org.apache.sentry.hdfs.FullUpdateInitializer:
Database name test_gr_db_2017_06_27_16_14_30 does not match
gr_db_2017_06_27_16_32_48
2017-06-28 12:07:08,174 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Sentry Ticket renewer
thread finished
2017-06-28 12:07:08,300 ERROR org.apache.sentry.hdfs.FullUpdateInitializer:
Failed to execute task
org.apache.thrift.TApplicationException: get_database failed: out of sequence
response
at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:84)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_database(ThriftHiveMetastore.java:670)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_database(ThriftHiveMetastore.java:657)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getDatabase(HiveMetaStoreClient.java:1213)
at
org.apache.sentry.hdfs.FullUpdateInitializer$DbTask.doTask(FullUpdateInitializer.java:347)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
--
2017-06-28 12:18:48,569 INFO org.apache.sentry.service.thrift.HMSFollower:
Using kerberos principal:
sentry/[email protected]
2017-06-28 12:18:48,569 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Logging in with new
Context
2017-06-28 12:18:48,574 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Sentry Ticket renewer
thread started
2017-06-28 12:18:48,576 INFO hive.metastore: Trying to connect to metastore
with URI thrift://vamsee-sentryha-1.vpc.cloudera.com:9083
2017-06-28 12:18:48,590 INFO hive.metastore: Opened a connection to metastore,
current connections: 1
2017-06-28 12:18:48,591 INFO hive.metastore: Connected to metastore.
2017-06-28 12:18:48,591 INFO org.apache.sentry.service.thrift.HMSFollower:
Secure connection established with HMS
2017-06-28 12:18:48,591 INFO org.apache.sentry.service.thrift.HMSFollower:
HMSFollower of Sentry successfully connected to HMS
2017-06-28 12:18:48,604 INFO org.apache.sentry.service.thrift.HMSFollower:
Before fetching hive full snapshot, Current NotificationID =
CurrentNotificationEventId(eventId:3276).
2017-06-28 12:18:48,604 INFO org.apache.sentry.service.thrift.HMSFollower:
Request full HMS snapshot
2017-06-28 12:18:48,640 WARN org.apache.sentry.hdfs.FullUpdateInitializer:
Database name test_gr_db_2017_06_27_16_06_19 does not match
cloudera_manager_metastore_canary_test_db_hive_1_hivemetastore_b91e6b8f1ab32b64f5756c9e8362789d
2017-06-28 12:18:49,382 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Sentry Ticket renewer
thread finished
2017-06-28 12:18:49,610 ERROR org.apache.sentry.hdfs.FullUpdateInitializer:
Failed to execute task
org.apache.thrift.TApplicationException: get_database failed: out of sequence
response
at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:84)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_database(ThriftHiveMetastore.java:670)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_database(ThriftHiveMetastore.java:657)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getDatabase(HiveMetaStoreClient.java:1213)
at
org.apache.sentry.hdfs.FullUpdateInitializer$DbTask.doTask(FullUpdateInitializer.java:347)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
--
2017-06-28 12:26:08,053 INFO org.apache.sentry.service.thrift.HMSFollower:
Using kerberos principal:
sentry/[email protected]
2017-06-28 12:26:08,054 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Logging in with new
Context
2017-06-28 12:26:08,058 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Sentry Ticket renewer
thread started
2017-06-28 12:26:08,059 INFO hive.metastore: Trying to connect to metastore
with URI thrift://vamsee-sentryha-1.vpc.cloudera.com:9083
2017-06-28 12:26:08,070 INFO hive.metastore: Opened a connection to metastore,
current connections: 1
2017-06-28 12:26:08,070 INFO hive.metastore: Connected to metastore.
2017-06-28 12:26:08,070 INFO org.apache.sentry.service.thrift.HMSFollower:
Secure connection established with HMS
2017-06-28 12:26:08,070 INFO org.apache.sentry.service.thrift.HMSFollower:
HMSFollower of Sentry successfully connected to HMS
2017-06-28 12:26:08,082 INFO org.apache.sentry.service.thrift.HMSFollower:
Before fetching hive full snapshot, Current NotificationID =
CurrentNotificationEventId(eventId:3283).
2017-06-28 12:26:08,082 INFO org.apache.sentry.service.thrift.HMSFollower:
Request full HMS snapshot
2017-06-28 12:26:08,118 WARN org.apache.sentry.hdfs.FullUpdateInitializer:
Database name test_gr_db_2017_06_27_16_14_30 does not match
gr_db_2017_06_27_16_32_48
2017-06-28 12:26:08,969 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Sentry Ticket renewer
thread finished
2017-06-28 12:26:09,089 ERROR org.apache.sentry.hdfs.FullUpdateInitializer:
Failed to execute task
org.apache.thrift.TApplicationException: get_database failed: out of sequence
response
at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:84)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_database(ThriftHiveMetastore.java:670)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_database(ThriftHiveMetastore.java:657)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getDatabase(HiveMetaStoreClient.java:1213)
at
org.apache.sentry.hdfs.FullUpdateInitializer$DbTask.doTask(FullUpdateInitializer.java:347)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
--
2017-06-28 14:44:57,683 INFO org.apache.sentry.service.thrift.HMSFollower:
Using kerberos principal:
sentry/[email protected]
2017-06-28 14:44:57,684 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Logging in with new
Context
2017-06-28 14:44:57,689 INFO hive.metastore: Trying to connect to metastore
with URI thrift://vamsee-sentryha-1.vpc.cloudera.com:9083
2017-06-28 14:44:57,690 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Sentry Ticket renewer
thread started
2017-06-28 14:44:57,704 INFO hive.metastore: Opened a connection to metastore,
current connections: 1
2017-06-28 14:44:57,704 INFO hive.metastore: Connected to metastore.
2017-06-28 14:44:57,704 INFO org.apache.sentry.service.thrift.HMSFollower:
Secure connection established with HMS
2017-06-28 14:44:57,704 INFO org.apache.sentry.service.thrift.HMSFollower:
HMSFollower of Sentry successfully connected to HMS
2017-06-28 14:44:57,716 INFO org.apache.sentry.service.thrift.HMSFollower:
Before fetching hive full snapshot, Current NotificationID =
CurrentNotificationEventId(eventId:3437).
2017-06-28 14:44:57,716 INFO org.apache.sentry.service.thrift.HMSFollower:
Request full HMS snapshot
2017-06-28 14:44:57,749 WARN org.apache.sentry.hdfs.FullUpdateInitializer:
Database name test_gr_db_2017_06_27_16_14_30 does not match
gr_db_2017_06_27_16_32_48
2017-06-28 14:44:58,530 INFO
org.apache.sentry.service.thrift.SentryKerberosContext: Sentry Ticket renewer
thread finished
2017-06-28 14:44:58,722 ERROR org.apache.sentry.hdfs.FullUpdateInitializer:
Failed to execute task
org.apache.thrift.TApplicationException: get_database failed: out of sequence
response
at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:84)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_database(ThriftHiveMetastore.java:670)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_database(ThriftHiveMetastore.java:657)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getDatabase(HiveMetaStoreClient.java:1213)
at
org.apache.sentry.hdfs.FullUpdateInitializer$DbTask.doTask(FullUpdateInitializer.java:347)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
--
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getDatabase(HiveMetaStoreClient.java:1213)
at
org.apache.sentry.hdfs.FullUpdateInitializer$DbTask.doTask(FullUpdateInitializer.java:347)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:246)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:178)
at java.util.concurrent.FutureTask.run(FutureTask.java:262)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2017-06-28 15:01:10,562 DEBUG org.apache.thrift.transport.TSaslTransport:
CLIENT: reading data length: 200
2017-06-28 15:01:10,571 WARN org.apache.sentry.hdfs.FullUpdateInitializer:
Database name test_gr_db_2017_06_27_16_06_19 does not match default
2017-06-28 15:01:10,572 DEBUG org.apache.thrift.transport.TSaslTransport:
writing data length: 62
2017-06-28 15:01:10,576 DEBUG org.apache.thrift.transport.TSaslTransport:
CLIENT: reading data length: 200
2017-06-28 15:01:10,577 DEBUG org.apache.sentry.hdfs.FullUpdateInitializer:
Failed to execute task on 1 attempts. Sleeping for 1000 ms. Exception:
org.apache.thrift.TApplicationException: get_database failed: out of sequence
response
org.apache.thrift.TApplicationException: get_database failed: out of sequence
response
at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:84)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_database(ThriftHiveMetastore.java:670)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_database(ThriftHiveMetastore.java:657)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getDatabase(HiveMetaStoreClient.java:1213)
at
org.apache.sentry.hdfs.FullUpdateInitializer$DbTask.doTask(FullUpdateInitializer.java:347)
at
org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:210)
[systest@vamsee-sentryha-1 ~]$
{code}
HMS log reporting incomplete data from thrift:
{code}
2017-06-28 16:11:51,329 DEBUG org.apache.hadoop.hive.metastore.ObjectStore:
[pool-5-thread-5]: rolling back transaction: no open transactions: 0 at:
org.apache.hadoop.hive.metastore.ObjectStore.getJDODatabase(ObjectStore.java:657)
2017-06-28 16:11:51,330 ERROR org.apache.hadoop.hive.metastore.ObjectStore:
[pool-5-thread-5]:
javax.jdo.JDOException: Exception thrown when executing query
at
org.datanucleus.api.jdo.NucleusJDOHelper.getJDOExceptionForNucleusException(NucleusJDOHelper.java:596)
at org.datanucleus.api.jdo.JDOQuery.execute(JDOQuery.java:252)
at
org.apache.hadoop.hive.metastore.ObjectStore.getMDatabase(ObjectStore.java:597)
at
org.apache.hadoop.hive.metastore.ObjectStore.getJDODatabase(ObjectStore.java:653)
at
org.apache.hadoop.hive.metastore.ObjectStore$2.getJdoResult(ObjectStore.java:643)
at
org.apache.hadoop.hive.metastore.ObjectStore$2.getJdoResult(ObjectStore.java:635)
at
org.apache.hadoop.hive.metastore.ObjectStore$GetHelper.run(ObjectStore.java:2631)
at
org.apache.hadoop.hive.metastore.ObjectStore.getDatabaseInternal(ObjectStore.java:635)
at
org.apache.hadoop.hive.metastore.ObjectStore.getDatabase(ObjectStore.java:619)
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.RawStoreProxy.invoke(RawStoreProxy.java:103)
at com.sun.proxy.$Proxy12.getDatabase(Unknown Source)
at
org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.get_database_core(HiveMetaStore.java:1043)
at
org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.get_database(HiveMetaStore.java:1017)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:140)
at
org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:99)
at com.sun.proxy.$Proxy16.get_database(Unknown Source)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$get_database.getResult(ThriftHiveMetastore.java:9112)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$get_database.getResult(ThriftHiveMetastore.java:9096)
at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
at
org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:735)
at
org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:730)
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:1917)
at
org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor.process(HadoopThriftAuthBridge.java:730)
at
org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
NestedThrowablesStackTrace:
java.sql.SQLException: Illegal mix of collations (latin1_bin,IMPLICIT) and
(utf8_general_ci,COERCIBLE) for operation '='
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:996)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3887)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3823)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2435)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2582)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2530)
at
com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1907)
at
com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:2030)
at
com.jolbox.bonecp.PreparedStatementHandle.executeQuery(PreparedStatementHandle.java:174)
at
org.datanucleus.store.rdbms.ParamLoggingPreparedStatement.executeQuery(ParamLoggingPreparedStatement.java:381)
at
org.datanucleus.store.rdbms.SQLController.executeStatementQuery(SQLController.java:504)
at
org.datanucleus.store.rdbms.query.JDOQLQuery.performExecute(JDOQLQuery.java:651)
at org.datanucleus.store.query.Query.executeQuery(Query.java:1786)
at org.datanucleus.store.query.Query.executeWithArray(Query.java:1672)
at org.datanucleus.api.jdo.JDOQuery.execute(JDOQuery.java:243)
at
org.apache.hadoop.hive.metastore.ObjectStore.getMDatabase(ObjectStore.java:597)
at
org.apache.hadoop.hive.metastore.ObjectStore.getJDODatabase(ObjectStore.java:653)
at
org.apache.hadoop.hive.metastore.ObjectStore$2.getJdoResult(ObjectStore.java:643)
at
org.apache.hadoop.hive.metastore.ObjectStore$2.getJdoResult(ObjectStore.java:635)
at
org.apache.hadoop.hive.metastore.ObjectStore$GetHelper.run(ObjectStore.java:2631)
at
org.apache.hadoop.hive.metastore.ObjectStore.getDatabaseInternal(ObjectStore.java:635)
at
org.apache.hadoop.hive.metastore.ObjectStore.getDatabase(ObjectStore.java:619)
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.RawStoreProxy.invoke(RawStoreProxy.java:103)
at com.sun.proxy.$Proxy12.getDatabase(Unknown Source)
at
org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.get_database_core(HiveMetaStore.java:1043)
at
org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.get_database(HiveMetaStore.java:1017)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:140)
at
org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:99)
at com.sun.proxy.$Proxy16.get_database(Unknown Source)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$get_database.getResult(ThriftHiveMetastore.java:9112)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$get_database.getResult(ThriftHiveMetastore.java:9096)
at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
at
org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:735)
at
org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:730)
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:1917)
at
org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor.process(HadoopThriftAuthBridge.java:730)
at
org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2017-06-28 16:11:51,331 DEBUG org.apache.hadoop.hive.metastore.ObjectStore:
[pool-5-thread-5]: rolling back transaction: no open transactions: 0 at:
org.apache.hadoop.hive.metastore.ObjectStore$GetHelper.close(ObjectStore.java:2742)
2017-06-28 16:11:51,331 WARN org.apache.hadoop.hive.metastore.ObjectStore:
[pool-5-thread-5]: Failed to get database gr_db_20�
get_datab, returning
NoSuchObjectException
MetaException(message:Exception thrown when executing query)
at
org.apache.hadoop.hive.metastore.ObjectStore$GetHelper.run(ObjectStore.java:2640)
at
org.apache.hadoop.hive.metastore.ObjectStore.getDatabaseInternal(ObjectStore.java:635)
at
org.apache.hadoop.hive.metastore.ObjectStore.getDatabase(ObjectStore.java:619)
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.RawStoreProxy.invoke(RawStoreProxy.java:103)
at com.sun.proxy.$Proxy12.getDatabase(Unknown Source)
at
org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.get_database_core(HiveMetaStore.java:1043)
at
org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.get_database(HiveMetaStore.java:1017)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:140)
at
org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:99)
at com.sun.proxy.$Proxy16.get_database(Unknown Source)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$get_database.getResult(ThriftHiveMetastore.java:9112)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$get_database.getResult(ThriftHiveMetastore.java:9096)
at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
at
org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:735)
at
org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:730)
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:1917)
at
org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor.process(HadoopThriftAuthBridge.java:730)
at
org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2017-06-28 16:11:51,331 INFO org.apache.hadoop.hive.ql.log.PerfLogger:
[pool-5-thread-5]: </PERFLOG method=get_database start=1498691511306
end=1498691511331 duration=25
from=org.apache.hadoop.hive.metastore.RetryingHMSHandler threadId=5
retryCount=-1 error=true>
2017-06-28 16:11:51,331 DEBUG org.apache.thrift.transport.TSaslTransport:
[pool-5-thread-5]: writing data length: 102
2017-06-28 16:11:51,331 DEBUG
org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge: [pool-5-thread-5]: AUTH
ID ======>sentry/[email protected]
2017-06-28 16:11:51,332 DEBUG
org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge: [pool-5-thread-5]: Set
remoteUser :sentry
2017-06-28 16:11:51,332 DEBUG org.apache.hadoop.security.UserGroupInformation:
[pool-5-thread-5]: PrivilegedAction
as:sentry/[email protected] (auth:PROXY) via
hive/[email protected] (auth:KERBEROS)
from:org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor.process(HadoopThriftAuthBridge.java:730)
2017-06-28 16:11:51,332 ERROR org.apache.thrift.server.TThreadPoolServer:
[pool-5-thread-5]: Thrift error occurred during processing of message.
org.apache.thrift.protocol.TProtocolException: Missing version in
readMessageBegin, old client?
at
org.apache.thrift.protocol.TBinaryProtocol.readMessageBegin(TBinaryProtocol.java:228)
at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:27)
at
org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:735)
at
org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor$1.run(HadoopThriftAuthBridge.java:730)
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:1917)
at
org.apache.hadoop.hive.thrift.HadoopThriftAuthBridge$Server$TUGIAssumingProcessor.process(HadoopThriftAuthBridge.java:730)
at
org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
2017-06-28 16:11:51,332 INFO org.apache.hadoop.hive.metastore.HiveMetaStore:
[pool-5-thread-5]: 5: Cleaning up thread local RawStore...
2017-06-28 16:11:51,332 INFO
org.apache.hadoop.hive.metastore.HiveMetaStore.audit: [pool-5-thread-5]:
ugi=hive/[email protected]
ip=/172.26.23.16 cmd=Cleaning up thread local RawStore...
2017-06-28 16:11:51,332 DEBUG org.apache.hadoop.hive.metastore.ObjectStore:
[pool-5-thread-5]: RawStore:
org.apache.hadoop.hive.metastore.ObjectStore@549f5fef, with PersistenceManager:
org.datanucleus.api.jdo.JDOPersistenceManager@174c725c will be shutdown
2017-06-28 16:11:51,332 DEBUG DataNucleus.Cache: [pool-5-thread-5]: Level 1
Cache cleared
{code}
We should ideally modify our FullUpdateInitializer logic to use a different
HiveMetaStoreClient instance for each thread rather than reusing the same
things across all calls.
> out of sequence error in HMSFollower
> ------------------------------------
>
> Key: SENTRY-1630
> URL: https://issues.apache.org/jira/browse/SENTRY-1630
> Project: Sentry
> Issue Type: Sub-task
> Components: Hdfs Plugin
> Affects Versions: sentry-ha-redesign
> Reporter: Hao Hao
> Assignee: Alexander Kolbasov
> Priority: Blocker
> Fix For: sentry-ha-redesign
>
>
> When HMSFollower exits in an abnormal way, for all the following connection
> would encounter out of sequence and SocketTimeoutException: Read timed out.
> Looking at HIVE-6893, it seems to relate to leakage connection problem.
> {noformat}2017-02-15 19:03:42,822 ERROR
> org.apache.sentry.hdfs.FullUpdateInitializer: Task did not complete
> successfully after 0 tries. Exception got:
> org.apache.thrift.TApplicationException: get_database failed: out of sequence
> response
> 2017-02-15 19:03:42,827 ERROR org.apache.sentry.hdfs.FullUpdateInitializer:
> Task did not complete successfully after 0 tries. Exception got:
> MetaException(message:Got exception:
> org.apache.thrift.transport.TTransportException null)
> 2017-02-15 19:03:43,803 INFO hive.metastore: Closed a connection to
> metastore, current connections: 0
> 2017-02-15 19:03:43,803 ERROR org.apache.sentry.service.thrift.HMSFollower:
> Exception occurred persisting Hive full snapshot into DB
> java.lang.RuntimeException: org.apache.thrift.TApplicationException:
> get_database failed: out of sequence response
> at
> org.apache.sentry.hdfs.FullUpdateInitializer.createInitialUpdate(FullUpdateInitializer.java:324)
> at
> org.apache.sentry.service.thrift.HMSFollower.fetchFullUpdate(HMSFollower.java:343)
> at
> org.apache.sentry.service.thrift.HMSFollower.run(HMSFollower.java:244)
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
> at
> java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: org.apache.thrift.TApplicationException: get_database failed: out
> of sequence response
> at
> org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:84)
> at
> org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_database(ThriftHiveMetastore.java:662)
> at
> org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_database(ThriftHiveMetastore.java:649)
> at
> org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getDatabase(HiveMetaStoreClient.java:1213)
> at
> org.apache.sentry.hdfs.FullUpdateInitializer$DbTask.doTask(FullUpdateInitializer.java:256)
> at
> org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask$RetryStrategy.exec(FullUpdateInitializer.java:110)
> at
> org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:150)
> at
> org.apache.sentry.hdfs.FullUpdateInitializer$BaseTask.call(FullUpdateInitializer.java:79)
> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
> ... 3 more
> 2017-02-15 19:03:43,849 INFO org.apache.sentry.service.thrift.HMSFollower:
> Making a kerberos connection to HMS{noformat}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
