Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Fixed
-
None
-
None
-
ghx-label-4
Description
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 process the new events:
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.024389 10065 MetastoreEvents.java:380] EventId: 39962 EventType: DROP_TABLE Creating event 39962 of type DROP_TABLE on table default.insertonly_hiveclient_impalaclient_partitioned_8ff3a1ef_b8a8_4c7a_b1c7_0b8f4c42c61e
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):
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
But the real problem is that event processing stops because of this error, i.e. no further events can be processed:
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 ...