[IMPALA-3781] JDBC test can fail on the second run for the exhaustive build

• Type: Bug
• Status: Resolved
• Priority: Minor
• Resolution: Cannot Reproduce
• Affects Version/s: Impala 2.6.0
• Component/s: Frontend, Infrastructure
• Labels: broken-build test-infra test_issue
• Environment: impala-ec2 standard
• Assignee: Unassigned
• Reporter: Harrison Sheinblatt
• Created: 23/Jun/16 18:19
• Updated: 23/Oct/17 16:00
• Resolved: 23/Oct/17 16:00

Description

http://sandbox.jenkins.cloudera.com/view/Impala/view/Evergreen-cdh5-2.6.0_5.8.x/job/impala-cdh5-2.6.0_5.8.0-exhaustive/38/

This run failed for the second run of the JdbcTest. The first run is part of the execution of the fe tests and the second run is for the JDBC tests.

The failure is that the second run cannot create the table it uses because it already exists.

The test code should clean up the table after the test is run the first time, and the logs support that it was dropped with no error.

So far I've only seen this fail once. We can exclude this test from one of the runs so that it is only executed once. However, it would be good to figure out why eithe the DROP TABLE failed with no error or the second run still saw the table. I grepped through and didn't see the table name used elsewhere.

Error Message

ImpalaRuntimeException: Error making 'createTable' RPC to Hive Metastore: 
CAUSED BY: AlreadyExistsException: Table jdbc_complex_type_test already exists

Stacktrace

org.apache.hive.service.cli.HiveSQLException: 
ImpalaRuntimeException: Error making 'createTable' RPC to Hive Metastore: 
CAUSED BY: AlreadyExistsException: Table jdbc_complex_type_test already exists

at org.apache.hive.jdbc.Utils.verifySuccess(Utils.java:239)
at org.apache.hive.jdbc.Utils.verifySuccessWithInfo(Utils.java:225)
at org.apache.hive.jdbc.HiveStatement.execute(HiveStatement.java:244)
at com.cloudera.impala.service.JdbcTest.addTestTable(JdbcTest.java:86)
at com.cloudera.impala.service.JdbcTest.testMetaDataGetColumns(JdbcTest.java:357)

Standard Output

16/06/22 00:27:59 INFO testutil.ImpalaJdbcClient: Using JDBC Driver Name: org.apache.hive.jdbc.HiveDriver
16/06/22 00:27:59 INFO testutil.ImpalaJdbcClient: Connecting to: jdbc:hive2://localhost:21050/default;auth=noSasl
16/06/22 00:27:59 INFO jdbc.Utils: Supplied authorities: localhost:21050
16/06/22 00:27:59 INFO jdbc.Utils: Resolved authority: localhost:21050

Standard Error

16/06/22 00:27:59 INFO testutil.ImpalaJdbcClient: Using JDBC Driver Name: org.apache.hive.jdbc.HiveDriver
16/06/22 00:27:59 INFO testutil.ImpalaJdbcClient: Connecting to: jdbc:hive2://localhost:21050/default;auth=noSasl
16/06/22 00:27:59 INFO jdbc.Utils: Supplied authorities: localhost:21050
16/06/22 00:27:59 INFO jdbc.Utils: Resolved authority: localhost:21050

First run catalog log

$ less ee_tests//catalogd.impala-boost-static-burst-slave-1645.vpc.cloudera.com.jenkins.log.INFO.20160621-124034.27911



I0621 12:54:58.933571 32381 CatalogOpExecutor.java:1373] Creating table default.jdbc_complex_type_test

I0621 12:54:58.933728 32381 MetaStoreClientPool.java:56] Creating MetaStoreClient. Pool Size = 0

I0621 12:54:58.934058 32381 HiveMetaStoreClient.java:379] Trying to connect to metastore with URI thrift://localhost:9083

I0621 12:54:58.934720 32381 HiveMetaStoreClient.java:424] Opened a connection to metastore, current connections: 6

I0621 12:54:58.936115 32381 HiveMetaStoreClient.java:476] Connected to metastore.

I0621 12:54:58.981133 32381 HiveMetaStoreClient.java:505] Closed a connection to metastore, current connections: 5

I0621 12:54:59.019060 28049 TableLoadingMgr.java:278] Loading next table. Remaining items in queue: 0

I0621 12:54:59.019623   689 TableLoader.java:56] Loading metadata for: default.jdbc_complex_type_test

I0621 12:54:59.019737   689 MetaStoreClientPool.java:56] Creating MetaStoreClient. Pool Size = 0

I0621 12:54:59.020078   689 HiveMetaStoreClient.java:379] Trying to connect to metastore with URI thrift://localhost:9083

I0621 12:54:59.020752   689 HiveMetaStoreClient.java:424] Opened a connection to metastore, current connections: 6

I0621 12:54:59.022438   689 HiveMetaStoreClient.java:476] Connected to metastore.

I0621 12:54:59.086331   689 Table.java:158] Loading column stats for table: jdbc_complex_type_test

I0621 12:54:59.095988   689 HdfsTable.java:1021] load table from Hive Metastore: default.jdbc_complex_type_test

I0621 12:54:59.106868   689 HiveMetaStoreClient.java:505] Closed a connection to metastore, current connections: 5

I0621 12:55:00.200126 28084 catalog-server.cc:313] Publishing update: TABLE:default.jdbc_complex_type_test@1176

I0621 12:55:00.207197 28084 catalog-server.cc:313] Publishing update: CATALOG:6f7c4a17409c401e:91b4de310afc4452@1176

I0621 12:55:02.782907 32381 CatalogOpExecutor.java:1159] Dropping table/view default.jdbc_complex_type_test

The second run catalog log

$ less ee_tests//catalogd.impala-boost-static-burst-slave-1645.vpc.cloudera.com.jenkins.log.INFO.20160622-002718.12087

I0622 00:28:13.294795 13056 CatalogOpExecutor.java:1373] Creating table default.jdbc_complex_type_test

I0622 00:28:13.294946 13056 MetaStoreClientPool.java:56] Creating MetaStoreClient. Pool Size = 0

I0622 00:28:13.295277 13056 HiveMetaStoreClient.java:379] Trying to connect to metastore with URI thrift://localhost:9083

I0622 00:28:13.295929 13056 HiveMetaStoreClient.java:424] Opened a connection to metastore, current connections: 6

I0622 00:28:13.297229 13056 HiveMetaStoreClient.java:476] Connected to metastore.

I0622 00:28:15.391695 13056 HiveMetaStoreClient.java:505] Closed a connection to metastore, current connections: 5

I0622 00:28:15.392762 13056 jni-util.cc:166] com.cloudera.impala.common.ImpalaRuntimeException: Error making 'createTable' RPC to Hive Metastore: 

        at com.cloudera.impala.service.CatalogOpExecutor.createTable(CatalogOpExecutor.java:1508)

        at com.cloudera.impala.service.CatalogOpExecutor.createTable(CatalogOpExecutor.java:1374)

        at com.cloudera.impala.service.CatalogOpExecutor.execDdlRequest(CatalogOpExecutor.java:249)

        at com.cloudera.impala.service.JniCatalog.execDdl(JniCatalog.java:133)

Caused by: AlreadyExistsException(message:Table jdbc_complex_type_test already exists)

        at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$create_table_with_environment_context_result$create_table_with_environment_context_resultStandardScheme.read(ThriftHiveMetastore.java:30054)

        at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$create_table_with_environment_context_result$create_table_with_environment_context_resultStandardScheme.read(ThriftHiveMetastore.java:30040)

        at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$create_table_with_environment_context_result.read(ThriftHiveMetastore.java:29966)

        at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:86)

        at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_create_table_with_environment_context(ThriftHiveMetastore.java:1079)

        at org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.create_table_with_environment_context(ThriftHiveMetastore.java:1065)

        at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.create_table_with_environment_context(HiveMetaStoreClient.java:2077)

        at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:674)

        at org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:662)

        at com.cloudera.impala.service.CatalogOpExecutor.createTable(CatalogOpExecutor.java:1498)

        ... 3 more

I0622 00:28:15.634531 13056 status.cc:111] ImpalaRuntimeException: Error making 'createTable' RPC to Hive Metastore: 

CAUSED BY: AlreadyExistsException: Table jdbc_complex_type_test already exists

    @          0x10d7197  impala::Status::Status()

    @          0x14bbbcc  impala::JniUtil::GetJniExceptionMsg()

    @          0x10c7aba  impala::JniUtil::CallJniMethod<>()

    @          0x10c6163  impala::Catalog::ExecDdl()

    @          0x1096800  CatalogServiceThriftIf::ExecDdl()

    @          0x110e47e  impala::CatalogServiceProcessor::process_ExecDdl()

    @          0x110e1cc  impala::CatalogServiceProcessor::dispatchCall()

    @          0x108204c  apache::thrift::TDispatchProcessor::process()

    @          0x2790eaf  apache::thrift::server::TThreadedServer::Task::run()

    @          0x124e881  impala::ThriftThread::RunRunnable()

    @          0x124ffd1  boost::_mfi::mf2<>::operator()()

    @          0x124fe67  boost::_bi::list3<>::operator()<>()

    @          0x124fbb3  boost::_bi::bind_t<>::operator()()

    @          0x124fac6  boost::detail::function::void_function_obj_invoker0<>::invoke()

    @          0x126e50c  boost::function0<>::operator()()

    @          0x15084e5  impala::Thread::SuperviseThread()

    @          0x150f048  boost::_bi::list4<>::operator()<>()

    @          0x150ef8b  boost::_bi::bind_t<>::operator()()

    @          0x150ef4e  boost::detail::thread_data<>::run()

    @          0x194a56a  thread_proxy

    @       0x392aa07851  (unknown)

    @       0x392a6e894d  (unknown)

E0622 00:28:15.634553 13056 catalog-server.cc:64] ImpalaRuntimeException: Error making 'createTable' RPC to Hive Metastore: 

CAUSED BY: AlreadyExistsException: Table jdbc_complex_type_test already exists

Impala log first run

ee_tests//impalad.impala-boost-static-burst-slave-1645.vpc.cloudera.com.jenkins.log.INFO.20160621-124035.27968

I0621 12:55:02.775277 28295 Frontend.java:872] analyze query DROP TABLE default.jdbc_complex_type_test
I0621 12:55:02.853785 28295 impala-hs2-server.cc:788] ExecuteStatement(): return_val=TExecuteStatementResp {
  01: status (struct) = TStatus {
    01: statusCode (i32) = 0,
  },
  02: operationHandle (struct) = TOperationHandle {
    01: operationId (struct) = THandleIdentifier {
      01: guid (string) = "\x92\xd6\xda\xcc\xa7@O\x1a\x97\x02\x90N\xd3\xc6m\x89",
      02: secret (string) = "\x92\xd6\xda\xcc\xa7@O\x1a\x97\x02\x90N\xd3\xc6m\x89",
    },
    02: operationType (i32) = 0,
    03: hasResultSet (bool) = false,
  },
}