[SENTRY-1586] [unit test] Race condition between metastore server/client could cause connection refused errors - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: None
Fix Version/s: 1.8.0, 2.0.0
Component/s: Test
Labels:
None

Description

Test failure:

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)

I was able to repro the issue by running the test multiple times

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...

It looks like Hive Metastore startup is having a race issue with metastore client trying to connect to it.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending

SENTRY-1586.v2.patch
05/Jan/17 02:48
2 kB
Vamsee K. Yarlagadda
SENTRY-1586.v1.patch
05/Jan/17 01:19
2 kB
Vamsee K. Yarlagadda

Issue Links

links to

Review board

Activity

People

Assignee:: Vamsee K. Yarlagadda

Reporter:: Vamsee K. Yarlagadda

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 05/Jan/17 01:00

Updated:: 24/Jul/17 15:36

Resolved:: 05/Jan/17 03:00