Uploaded image for project: 'Sentry (Retired)'
  1. Sentry (Retired)
  2. SENTRY-1586

[unit test] Race condition between metastore server/client could cause connection refused errors

    XMLWordPrintableJSON

    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

        1. SENTRY-1586.v2.patch
          2 kB
          Vamsee K. Yarlagadda
        2. SENTRY-1586.v1.patch
          2 kB
          Vamsee K. Yarlagadda

          Issue Links

            Activity

              People

              • Assignee:
                vamsee Vamsee K. Yarlagadda
                Reporter:
                vamsee Vamsee K. Yarlagadda
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: