Zoltán Borók-Nagy created IMPALA-10187:
------------------------------------------
Summary: Event processing fails on multiple events + DROP TABLE
Key: IMPALA-10187
URL: https://issues.apache.org/jira/browse/IMPALA-10187
Project: IMPALA
Issue Type: Bug
Reporter: Zoltán Borók-Nagy
I've seen the following during interop testing:
Some DDL statements (ALTER TABLE + DROP) were executed via Hive on the same
table.
Then CatalogD's event processor tried to refresh the table in its cache:
{noformat}
I0922 14:32:56.590229 13611 HdfsTable.java:709] Loaded file and block metadata
for
default.insertonly_hiveclient_impalaclient_partitioned_8ff3a1ef_b8a8_4c7a_b1c7_0b8f4c42c61e
partitions: category=cat1, category=cat2, category=cat3, and 1 others. Time
taken: 55.145ms I0922 14:32:56.591078 13611 TableLoader.java:103] Loaded
metadata for:
default.insertonly_hiveclient_impalaclient_partitioned_8ff3a1ef_b8a8_4c7a_b1c7_0b8f4c42c61e
(303ms) I0922 14:32:58.022068 10065 MetastoreEventsProcessor.java:482]
Received 41 events. Start event id : 39948 I0922 14:32:58.022266 10065
MetastoreEvents.java:380] EventId: 39949 EventType: ALTER_PARTITION Creating
event 39949 of type ALTER_PARTITION on table
default.insertonly_hiveclient_impalaclient_partitioned_8ff3a1ef_b8a8_4c7a_b1c7_0b8f4c42c61e
I0922 14:32:58.022769 10065 MetastoreEvents.java:380] EventId: 39950
EventType: ALTER_PARTITION Creating event 39950 of type ALTER_PARTITION on
table
default.insertonly_hiveclient_impalaclient_partitioned_8ff3a1ef_b8a8_4c7a_b1c7_0b8f4c42c61e
I0922 14:32:58.023175 10065 MetastoreEvents.java:380] EventId: 39951
EventType: ALTER_PARTITION Creating event 39951 of type ALTER_PARTITION on
table
default.insertonly_hiveclient_impalaclient_partitioned_8ff3a1ef_b8a8_4c7a_b1c7_0b8f4c42c61e
I0922 14:32:58.023567 10065 MetastoreEvents.java:380] EventId: 39952
EventType: ALTER_PARTITION Creating event 39952 of type ALTER_PARTITION on
table
default.insertonly_hiveclient_impalaclient_partitioned_8ff3a1ef_b8a8_4c7a_b1c7_0b8f4c42c61e
I0922 14:32:58.024046 10065 MetastoreEvents.java:380] EventId: 39959
EventType: DROP_TABLE Creating event 39959 of type DROP_TABLE on table
default.insertonly_hiveclient_impalaclient_partitioned_8ff3a1ef_b8a8_4c7a_b1c7_0b8f4c42c61e_imp_a273e31c_f6bb_4433_9164_44762d599f8a
{noformat}
Impala tried to refresh the table on the first ALTER TABLE event, but since
it's been already dropped we get a TableLoadingException (caused by
NoSuchObjectException from HMS):
{noformat}
I0922 14:32:58.028852 10065 MetastoreEvents.java:234] Total number of events
received: 41 Total number of events filtered out: 0 I0922 14:32:58.028962 10065
CatalogServiceCatalog.java:862] Not a self-event since the given version is -1
and service id is I0922 14:32:58.029369 10065 CatalogServiceCatalog.java:2142]
Refreshing table metadata:
default.insertonly_hiveclient_impalaclient_partitioned_8ff3a1ef_b8a8_4c7a_b1c7_0b8f4c42c61e
E0922 14:32:58.038627 10065 MetastoreEventsProcessor.java:527] Unexpected
exception received while processing event Java exception follows:
org.apache.impala.catalog.events.MetastoreNotificationException: Unable to
process event 39949 of type ALTER_PARTITION. Event processing will be stopped.
at
org.apache.impala.catalog.events.MetastoreEventsProcessor.processEvents(MetastoreEventsProcessor.java:620)
at
org.apache.impala.catalog.events.MetastoreEventsProcessor.processEvents(MetastoreEventsProcessor.java:513)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at
java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at
java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748) Caused by:
org.apache.impala.catalog.TableLoadingException: Error loading metadata for
table:
default.insertonly_hiveclient_impalaclient_partitioned_8ff3a1ef_b8a8_4c7a_b1c7_0b8f4c42c61e
at
org.apache.impala.catalog.CatalogServiceCatalog.reloadTable(CatalogServiceCatalog.java:2160)
at
org.apache.impala.catalog.CatalogServiceCatalog.reloadTableIfExists(CatalogServiceCatalog.java:2365)
at
org.apache.impala.catalog.events.MetastoreEvents$MetastoreTableEvent.reloadTableFromCatalog(MetastoreEvents.java:563)
at
org.apache.impala.catalog.events.MetastoreEvents$AlterPartitionEvent.process(MetastoreEvents.java:1454)
at
org.apache.impala.catalog.events.MetastoreEvents$MetastoreEvent.processIfEnabled(MetastoreEvents.java:314)
at
org.apache.impala.catalog.events.MetastoreEventsProcessor.processEvents(MetastoreEventsProcessor.java:615)
... 8 more Caused by:
NoSuchObjectException(message:hive.default.insertonly_hiveclient_impalaclient_partitioned_8ff3a1ef_b8a8_4c7a_b1c7_0b8f4c42c61e
table not found) at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$get_table_req_result$get_table_req_resultStandardScheme.read(ThriftHiveMetastore.java)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$get_table_req_result$get_table_req_resultStandardScheme.read(ThriftHiveMetastore.java)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$get_table_req_result.read(ThriftHiveMetastore.java)
at org.apache.thrift.TServiceClient.receiveBase(TServiceClient.java:86) at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.recv_get_table_req(ThriftHiveMetastore.java:2350)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Client.get_table_req(ThriftHiveMetastore.java:2337)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getTable(HiveMetaStoreClient.java:2030)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getTable(HiveMetaStoreClient.java:2013)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getTable(HiveMetaStoreClient.java:2003)
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:498) at
org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:208)
at com.sun.proxy.$Proxy11.getTable(Unknown Source) at
org.apache.impala.catalog.CatalogServiceCatalog.reloadTable(CatalogServiceCatalog.java:2158)
... 13 more
{noformat}
But the real problem is that event processing stops because of this error, i.e.
no further events can be processed:
{noformat}
W0922 14:33:02.039422 10065 MetastoreEventsProcessor.java:506] Event processing
is skipped since status is ERROR. Last synced event id is 39948 W0922
14:33:04.039711 10065 MetastoreEventsProcessor.java:506] Event processing is
skipped since status is ERROR. Last synced event id is 39948 W0922
14:33:06.040015 10065 MetastoreEventsProcessor.java:506] Event processing is
skipped since status is ERROR. Last synced event id is 39948 W0922
14:33:08.045881 10065 MetastoreEventsProcessor.java:506] Event processing is
skipped since status is ERROR. Last synced event id is 39948
...
{noformat}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
