Vamsee Yarlagadda created SENTRY-1586:
-----------------------------------------
Summary: [unit test] Race condition between metastore
server/client could cause connection refused errors
Key: SENTRY-1586
URL: https://issues.apache.org/jira/browse/SENTRY-1586
Project: Sentry
Issue Type: Bug
Components: Test
Reporter: Vamsee Yarlagadda
Assignee: Vamsee Yarlagadda
Test failure:
{code}
Running org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationEnd2End
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 10.778 sec <<<
FAILURE! - in org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationEnd2End
org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationEnd2End Time elapsed:
10.776 sec <<< ERROR!
java.lang.reflect.UndeclaredThrowableException: null
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1809)
at
org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationBase.startHiveAndMetastore(TestHDFSIntegrationBase.java:462)
at
org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationBase.startHiveAndMetastore(TestHDFSIntegrationBase.java:458)
at
org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationBase.setup(TestHDFSIntegrationBase.java:435)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:27)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30)
at
org.junit.internal.runners.statements.FailOnTimeout$StatementThread.run(FailOnTimeout.java:62)
Caused by: org.apache.hadoop.hive.metastore.api.MetaException: Could not
connect to meta store using any of the URIs provided. Most recent failure:
org.apache.thrift.transport.TTransportException: java.net.ConnectException:
Connection refused
at org.apache.thrift.transport.TSocket.open(TSocket.java:226)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:462)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.<init>(HiveMetaStoreClient.java:242)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.<init>(HiveMetaStoreClient.java:187)
at
org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationBase$3.run(TestHDFSIntegrationBase.java:551)
at
org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationBase$3.run(TestHDFSIntegrationBase.java:462)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:422)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1796)
at
org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationBase.startHiveAndMetastore(TestHDFSIntegrationBase.java:462)
at
org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationBase.startHiveAndMetastore(TestHDFSIntegrationBase.java:458)
at
org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationBase.setup(TestHDFSIntegrationBase.java:435)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:27)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30)
at
org.junit.internal.runners.statements.FailOnTimeout$StatementThread.run(FailOnTimeout.java:62)
Caused by: java.net.ConnectException: Connection refused
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:345)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at org.apache.thrift.transport.TSocket.open(TSocket.java:221)
... 21 more
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:510)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.<init>(HiveMetaStoreClient.java:242)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.<init>(HiveMetaStoreClient.java:187)
at
org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationBase$3.run(TestHDFSIntegrationBase.java:551)
at
org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationBase$3.run(TestHDFSIntegrationBase.java:462)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:422)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1796)
at
org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationBase.startHiveAndMetastore(TestHDFSIntegrationBase.java:462)
at
org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationBase.startHiveAndMetastore(TestHDFSIntegrationBase.java:458)
at
org.apache.sentry.tests.e2e.hdfs.TestHDFSIntegrationBase.setup(TestHDFSIntegrationBase.java:435)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:27)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30)
at
org.junit.internal.runners.statements.FailOnTimeout$StatementThread.run(FailOnTimeout.java:62)
{code}
I was able to repro the issue by running the test multiple times
{code}
2017-01-03 17:15:41,648 (main) [WARN -
org.apache.hadoop.hive.conf.HiveConf.initialize(HiveConf.java:2811)] HiveConf
of name hive.sentry.conf.url does not exist
2017-01-03 17:15:41,653 (main) [INFO -
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:389)]
Trying to connect to metastore with URI thrift://localhost:64116
2017-01-03 17:15:41,680 (main) [WARN -
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:472)]
Failed to connect to the MetaStore Server...
2017-01-03 17:15:41,681 (main) [INFO -
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:503)]
Waiting 1 seconds before next connection attempt.
2017-01-03 17:15:42,682 (main) [INFO -
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:389)]
Trying to connect to metastore with URI thrift://localhost:64116
2017-01-03 17:15:42,683 (main) [WARN -
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:472)]
Failed to connect to the MetaStore Server...
2017-01-03 17:15:42,684 (main) [INFO -
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:503)]
Waiting 1 seconds before next connection attempt.
2017-01-03 17:15:43,688 (main) [INFO -
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:389)]
Trying to connect to metastore with URI thrift://localhost:64116
2017-01-03 17:15:43,689 (main) [WARN -
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:472)]
Failed to connect to the MetaStore Server...
2017-01-03 17:15:43,689 (main) [INFO -
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:503)]
Waiting 1 seconds before next connection attempt.
2017-01-03 17:15:43,784 (pool-25-thread-1) [INFO -
org.apache.hadoop.hive.metastore.MetaStoreDirectSql.<init>(MetaStoreDirectSql.java:135)]
Using direct SQL, underlying DB is DERBY
2017-01-03 17:15:43,785 (pool-25-thread-1) [INFO -
org.apache.hadoop.hive.metastore.ObjectStore.setConf(ObjectStore.java:316)]
Initialized ObjectStore
2017-01-03 17:15:43,911 (pool-25-thread-1) [WARN -
org.apache.hadoop.hive.metastore.ObjectStore.checkSchema(ObjectStore.java:7207)]
Version information not found in metastore. hive.metastore.schema.verification
is not enabled so recording the schema version 1.1.0
2017-01-03 17:15:43,981 (pool-25-thread-1) [WARN -
org.apache.hadoop.hive.metastore.ObjectStore.getDatabase(ObjectStore.java:621)]
Failed to get database default, returning NoSuchObjectException
2017-01-03 17:15:44,091 (pool-25-thread-1) [INFO -
org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.createDefaultRoles_core(HiveMetaStore.java:726)]
Added admin role in metastore
2017-01-03 17:15:44,094 (pool-25-thread-1) [INFO -
org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.createDefaultRoles_core(HiveMetaStore.java:735)]
Added public role in metastore
2017-01-03 17:15:44,177 (pool-25-thread-1) [INFO -
org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.addAdminUsers_core(HiveMetaStore.java:775)]
No user is added in admin role, since config is empty
2017-01-03 17:15:44,206 (pool-25-thread-1) [INFO -
org.apache.sentry.binding.hive.conf.HiveAuthzConf.<init>(HiveAuthzConf.java:159)]
DefaultFS: file:///
2017-01-03 17:15:44,233 (pool-25-thread-1) [INFO -
org.apache.sentry.binding.hive.conf.HiveAuthzConf.<init>(HiveAuthzConf.java:162)]
DefaultFS: file:///
2017-01-03 17:15:44,303 (pool-25-thread-1) [WARN -
org.apache.hadoop.hive.conf.HiveConf.initialize(HiveConf.java:2811)] HiveConf
of name hive.sentry.conf.url does not exist
2017-01-03 17:15:44,329 (pool-25-thread-1) [INFO -
org.apache.sentry.binding.hive.conf.HiveAuthzConf.<init>(HiveAuthzConf.java:159)]
DefaultFS: file:///
2017-01-03 17:15:44,361 (pool-25-thread-1) [INFO -
org.apache.sentry.binding.hive.conf.HiveAuthzConf.<init>(HiveAuthzConf.java:162)]
DefaultFS: file:///
2017-01-03 17:15:44,580 (pool-25-thread-1) [INFO -
org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:6411)]
Starting DB backed MetaStore Server with SetUGI enabled
2017-01-03 17:15:44,583 (pool-25-thread-1) [INFO -
org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:6491)]
Started the new metaserver on port [64116]...
2017-01-03 17:15:44,583 (pool-25-thread-1) [INFO -
org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:6493)]
Options.minWorkerThreads = 5
2017-01-03 17:15:44,583 (pool-25-thread-1) [INFO -
org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:6495)]
Options.maxWorkerThreads = 1000
2017-01-03 17:15:44,583 (pool-25-thread-1) [INFO -
org.apache.hadoop.hive.metastore.HiveMetaStore.startMetaStore(HiveMetaStore.java:6497)]
TCP keepalive = true
2017-01-03 17:15:44,692 (main) [WARN -
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1799)]
PriviledgedActionException as:admin1 (auth:SIMPLE)
cause:MetaException(message:Could not connect to meta store using any of the
URIs provided. Most recent failure:
org.apache.thrift.transport.TTransportException: java.net.ConnectException:
Connection refused
at org.apache.thrift.transport.TSocket.open(TSocket.java:226)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.open(HiveMetaStoreClient.java:462)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.<init>(HiveMetaStoreClient.java:242)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.<init>(HiveMetaStoreClient.java:187)
at org.apache.sentry.tests.e2e.hive.Context$1.run(Context.java:266)
at org.apache.sentry.tests.e2e.hive.Context$1.run(Context.java:263)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:422)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1796)
at
org.apache.sentry.tests.e2e.hive.Context.getMetaStoreClient(Context.java:263)
at
org.apache.sentry.tests.e2e.metastore.TestAuthorizingObjectStore.setup(TestAuthorizingObjectStore.java:71)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:483)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:45)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:42)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:27)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:263)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:68)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:30)
at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
at
org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:275)
at
org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:173)
at
org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:149)
at
org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:128)
at
org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:203)
at
org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:155)
at
org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:103)
Caused by: java.net.ConnectException: Connection refused
at java.net.PlainSocketImpl.socketConnect(Native Method)
at
java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:345)
at
java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at
java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
at org.apache.thrift.transport.TSocket.open(TSocket.java:221)
... 37 more
)
2017-01-03 17:15:44,693 (main) [INFO -
org.apache.sentry.tests.e2e.hive.AbstractTestWithStaticConfiguration.clearAfterPerTest(AbstractTestWithStaticConfiguration.java:592)]
AbstractTestStaticConfiguration clearAfterPerTest
2017-01-03 17:15:44,708 (main) [INFO -
org.apache.sentry.service.thrift.SentryService.stop(SentryService.java:277)]
Attempting to stop...
2017-01-03 17:15:44,708 (main) [INFO -
org.apache.sentry.service.thrift.SentryService.stop(SentryService.java:279)]
Attempting to stop sentry thrift service...
2017-01-03 17:15:44,709 (main) [INFO -
org.apache.sentry.service.thrift.SentryService.stop(SentryService.java:302)]
Sentry web service is already stopped...
2017-01-03 17:15:44,709 (main) [INFO -
org.apache.sentry.service.thrift.SentryService.stop(SentryService.java:307)]
Stopped...
{code}
It looks like Hive Metastore startup is having a race issue with metastore
client trying to connect to it.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
