[IMPALA-4955] Insert overwrite into partitioned table started failing with IllegalStateException: null

• Type: Bug
• Status: Resolved
• Priority: Blocker
• Resolution: Fixed
• Affects Version/s: Impala 2.9.0
• Fix Version/s: Impala 2.9.0
• Component/s: Catalog
• Assignee: Bharath Vissapragada
• Reporter: Mostafa Mokhtar
• Created: 19/Feb/17 17:11
• Updated: 24/Feb/17 17:47
• Resolved: 24/Feb/17 17:47

Description

Exception from Catalog log

W0219 05:11:26.419569 56286 MetaStoreUtils.java:342] Updated size to 4825
I0219 05:11:26.557984 56286 HdfsTable.java:1140] Incrementally loading table metadata for: tpcds_1000_parquet.store_sales_insert
I0219 05:11:27.935978 56286 jni-util.cc:169] org.apache.impala.catalog.TableLoadingException: Failed to load metadata for table: store_sales_insert
        at org.apache.impala.catalog.HdfsTable.load(HdfsTable.java:1163)
        at org.apache.impala.service.CatalogOpExecutor.loadTableMetadata(CatalogOpExecutor.java:602)
        at org.apache.impala.service.CatalogOpExecutor.updateCatalog(CatalogOpExecutor.java:3315)
        at org.apache.impala.service.JniCatalog.updateCatalog(JniCatalog.java:258)
Caused by: java.lang.IllegalStateException
        at com.google.common.base.Preconditions.checkState(Preconditions.java:129)
        at org.apache.impala.catalog.HdfsTable.loadPartitionFileMetadata(HdfsTable.java:1572)
        at org.apache.impala.catalog.HdfsTable.loadPartitionFileMetadata(HdfsTable.java:1550)
        at org.apache.impala.catalog.HdfsTable.updatePartitionsFromHms(HdfsTable.java:1284)
        at org.apache.impala.catalog.HdfsTable.load(HdfsTable.java:1146)
        ... 3 more
I0219 05:11:27.944391 56286 status.cc:114] TableLoadingException: Failed to load metadata for table: store_sales_insert
CAUSED BY: IllegalStateException: null
    @           0x82eaf9  impala::Status::Status()
    @           0xb710c0  impala::JniUtil::GetJniExceptionMsg()
    @           0x82195b  impala::Catalog::UpdateCatalog()
    @           0x814a79  CatalogServiceThriftIf::UpdateCatalog()
    @           0x8e50f7  impala::CatalogServiceProcessor::process_UpdateCatalog()
    @           0x8dccb9  impala::CatalogServiceProcessor::dispatchCall()
    @           0x7ffeac  apache::thrift::TDispatchProcessor::process()
    @           0x9ec9ef  apache::thrift::server::TAcceptQueueServer::Task::run()
    @           0x9e7099  impala::ThriftThread::RunRunnable()
    @           0x9e7af2  boost::detail::function::void_function_obj_invoker0<>::invoke()
    @           0xbc42f4  impala::Thread::SuperviseThread()
    @           0xbc4cd4  boost::detail::thread_data<>::run()
    @           0xe1808a  thread_proxy
    @       0x3ea58079d1  (unknown)
    @       0x3ea54e88fd  (unknown)
E0219 05:11:27.944409 56286 catalog-server.cc:92] TableLoadingException: Failed to load metadata for table: store_sales_insert
CAUSED BY: IllegalStateException: null
I0219 05:11:28.038583 54825 catalog-server.cc:316] Publishing update: CATALOG:979ca07f963d46ea:99c95c70539e7291@723

HMS log at time of failure

2017-02-19 05:11:26,420 INFO  org.apache.hadoop.hive.ql.log.PerfLogger: [pool-5-thread-78]: <PERFLOG method=add_partitions_req from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2017-02-19 05:11:26,420 INFO  org.apache.hadoop.hive.metastore.HiveMetaStore: [pool-5-thread-78]: 78: add_partitions
2017-02-19 05:11:26,420 INFO  org.apache.hadoop.hive.metastore.HiveMetaStore.audit: [pool-5-thread-78]: ugi=impala	ip=10.17.193.6	cmd=add_partitions
2017-02-19 05:11:26,442 INFO  org.apache.hadoop.hive.ql.log.PerfLogger: [pool-5-thread-78]: </PERFLOG method=add_partitions_req start=1487509886420 end=1487509886442 duration=22 from=org.apache.hadoop.hive.metastore.RetryingHMSHandler threadId=78 retryCount=0 error=false>
2017-02-19 05:11:26,543 INFO  org.apache.hadoop.hive.ql.log.PerfLogger: [pool-5-thread-78]: <PERFLOG method=alter_table_with_environment_context from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2017-02-19 05:11:26,543 INFO  org.apache.hadoop.hive.metastore.HiveMetaStore: [pool-5-thread-78]: 78: source:10.17.193.6 alter_table: db=tpcds_1000_parquet tbl=store_sales_insert newtbl=store_sales_insert
2017-02-19 05:11:26,543 INFO  org.apache.hadoop.hive.metastore.HiveMetaStore.audit: [pool-5-thread-78]: ugi=impala	ip=10.17.193.6	cmd=source:10.17.193.6 alter_table: db=tpcds_1000_parquet tbl=store_sales_insert newtbl=store_sales_insert
2017-02-19 05:11:26,554 INFO  org.apache.hadoop.hive.ql.log.PerfLogger: [pool-5-thread-78]: </PERFLOG method=alter_table_with_environment_context start=1487509886543 end=1487509886554 duration=11 from=org.apache.hadoop.hive.metastore.RetryingHMSHandler threadId=78 retryCount=0 error=false>
2017-02-19 05:11:26,554 INFO  org.apache.hadoop.hive.ql.log.PerfLogger: [pool-5-thread-77]: <PERFLOG method=get_table from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2017-02-19 05:11:26,554 INFO  org.apache.hadoop.hive.metastore.HiveMetaStore: [pool-5-thread-77]: 77: source:10.17.193.6 get_table : db=tpcds_1000_parquet tbl=store_sales_insert
2017-02-19 05:11:26,554 INFO  org.apache.hadoop.hive.metastore.HiveMetaStore.audit: [pool-5-thread-77]: ugi=impala	ip=10.17.193.6	cmd=source:10.17.193.6 get_table : db=tpcds_1000_parquet tbl=store_sales_insert
2017-02-19 05:11:26,557 INFO  org.apache.hadoop.hive.ql.log.PerfLogger: [pool-5-thread-77]: </PERFLOG method=get_table start=1487509886554 end=1487509886557 duration=3 from=org.apache.hadoop.hive.metastore.RetryingHMSHandler threadId=77 retryCount=0 error=false>
2017-02-19 05:11:26,558 INFO  org.apache.hadoop.hive.ql.log.PerfLogger: [pool-5-thread-77]: <PERFLOG method=get_partition_names from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2017-02-19 05:11:26,558 INFO  org.apache.hadoop.hive.metastore.HiveMetaStore: [pool-5-thread-77]: 77: source:10.17.193.6 get_partition_names : db=tpcds_1000_parquet tbl=store_sales_insert
2017-02-19 05:11:26,558 INFO  org.apache.hadoop.hive.metastore.HiveMetaStore.audit: [pool-5-thread-77]: ugi=impala	ip=10.17.193.6	cmd=source:10.17.193.6 get_partition_names : db=tpcds_1000_parquet tbl=store_sales_insert
2017-02-19 05:11:26,567 INFO  org.apache.hadoop.hive.ql.log.PerfLogger: [pool-5-thread-77]: </PERFLOG method=get_partition_names start=1487509886558 end=1487509886567 duration=9 from=org.apache.hadoop.hive.metastore.RetryingHMSHandler threadId=77 retryCount=0 error=false>
2017-02-19 05:11:26,573 INFO  org.apache.hadoop.hive.ql.log.PerfLogger: [pool-5-thread-77]: <PERFLOG method=get_partitions_by_names from=org.apache.hadoop.hive.metastore.RetryingHMSHandler>
2017-02-19 05:11:26,573 INFO  org.apache.hadoop.hive.metastore.HiveMetaStore: [pool-5-thread-77]: 77: source:10.17.193.6 get_partitions_by_names : db=tpcds_1000_parquet tbl=store_sales_insert
2017-02-19 05:11:26,573 INFO  org.apache.hadoop.hive.metastore.HiveMetaStore.audit: [pool-5-thread-77]: ugi=impala	ip=10.17.193.6	cmd=source:10.17.193.6 get_partitions_by_names : db=tpcds_1000_parquet tbl=store_sales_insert
2017-02-19 05:11:26,578 INFO  org.apache.hadoop.hive.ql.log.PerfLogger: [pool-5-thread-77]: </PERFLOG method=get_partitions_by_names start=1487509886573 end=1487509886578 duration=5 from=org.apache.hadoop.hive.metastore.RetryingHMSHandler threadId=77 retryCount=0 error=false>

Repro

DROP TABLE IF EXISTS store_sales_insert;
CREATE TABLE store_sales_insert LIKE store_sales;
INSERT OVERWRITE TABLE store_sales_insert PARTITION (ss_sold_date_sk)
SELECT * FROM store_sales;
[RUN attached query 05-TPCDS-SS-INSERT-OVERWRITE-SINGLE-ROW ]

The test started failing after https://github.com/apache/incubator-impala/commit/26eaa266092a5d8b37e21fd19dfbae81a952ac74
version 2.9.0-SNAPSHOT RELEASE (build ab098e72f94fb5406b2137b6a7cda42cf6a6c986) from CDH.