Quanlong Huang created IMPALA-13993:
---------------------------------------
Summary: TestEventSyncWaiting.test_hms_event_sync_basic failed in
DropTable
Key: IMPALA-13993
URL: https://issues.apache.org/jira/browse/IMPALA-13993
Project: IMPALA
Issue Type: Bug
Components: Catalog
Reporter: Quanlong Huang
Assignee: Quanlong Huang
Saw TestEventSyncWaiting.test_hms_event_sync_basic failed after IMPALA-13684
{code:python}
TestEventSyncWaiting.test_hms_event_sync_basic[protocol: beeswax |
table_format: text/none | exec_option: {'test_replan': 1,
'sync_hms_events_wait_time_s': 10, 'batch_size': 0, 'num_nodes': 0,
'disable_codegen_rows_threshold': 5000, 'disable_codegen': False,
'abort_on_error': 1, 'exec_single_node_rows_threshold': 0,
'sync_hms_events_strict_mode': True}]
[gw0] linux2 -- Python 2.7.16
/home/quanlong/workspace/Impala/infra/python/env-gcc10.4.0/bin/python
tests/metadata/test_event_processing.py:369: in test_hms_event_sync_basic
client, "drop table {0}_2.tbl".format(unique_database))
tests/common/impala_test_suite.py:1134: in wrapper
return function(*args, **kwargs)
tests/common/impala_test_suite.py:1144: in execute_query_expect_success
result = cls.__execute_query(impalad_client, query, query_options, user)
tests/common/impala_test_suite.py:1312: in __execute_query
return impalad_client.execute(query, user=user)
tests/common/impala_connection.py:505: in execute
fetch_exec_summary=fetch_exec_summary)
tests/beeswax/impala_beeswax.py:195: in execute
handle = self.__execute_query(query_string.strip(), user=user)
tests/beeswax/impala_beeswax.py:291: in __execute_query
handle = self.execute_query_async(query_string, user=user)
tests/beeswax/impala_beeswax.py:285: in execute_query_async
handle = self.__do_rpc(lambda: self.imp_service.query(query,))
tests/beeswax/impala_beeswax.py:470: in __do_rpc
raise ImpalaBeeswaxException(self.__build_error_message(b), b)
E ImpalaBeeswaxException: Query 7d4b01c2fb5fb3c8:adb779d900000000 failed:
E AnalysisException: Table does not exist:
test_hms_event_sync_basic_7d94d913_2.tbl{code}
stderr
{noformat}
-- 2025-04-25 14:16:22,621 INFO MainThread: -- executing in HiveServer2
create database test_hms_event_sync_basic_7d94d913_2;
create table test_hms_event_sync_basic_7d94d913_2.tbl(i int);
create table test_hms_event_sync_basic_7d94d913_2.tbl_2(i int);
-- 2025-04-25 14:16:24,307 INFO MainThread: beeswax: executing against
localhost:21000
drop table test_hms_event_sync_basic_7d94d913_2.tbl;{noformat}
The test creates a db and two tables under it in Hive. Then drop the table in
Impala but it fails. Checking the catalogd logs, it waits for the
CREATE_DATABASE event to be processed.
{noformat}I0425 14:16:24.308948 109426 JniUtil.java:167]
7d4b01c2fb5fb3c8:adb779d900000000] waitForHmsEvent request: waitForHmsEvent
7d4b01c2fb5fb3c8:adb779d900000000
I0425 14:16:24.309022 109426 CatalogServiceCatalog.java:4341]
7d4b01c2fb5fb3c8:adb779d900000000] waitForHmsEvent request:
want_minimal_response=false, coordinator=quanlong-Precision-3680, timeout_s=10,
want_db_list=false, want_table_list=false,
objects=[TABLE:test_hms_event_sync_basic_7d94d913_2.tbl,
DATABASE:test_hms_event_sync_basic_7d94d913_2], should_expand_views=false
I0425 14:16:24.309767 109426 MetastoreEventsProcessor.java:408]
7d4b01c2fb5fb3c8:adb779d900000000] Fetching
ALTER_DATABASE,CREATE_DATABASE,DROP_DATABASE events started from id 123366 to
123377. Gap: 11
I0425 14:16:24.310648 113084 MetaStoreUtil.java:223] Fetched 1/1 partitions for
table test_hms_event_sync_compute_stats_3d662792.foo
I0425 14:16:24.310675 113084 HdfsTable.java:1306] Fetched partition metadata
from the Metastore: test_hms_event_sync_compute_stats_3d662792.foo
I0425 14:16:24.310709 109426 MetastoreEventsProcessor.java:1855]
7d4b01c2fb5fb3c8:adb779d900000000] Found db
test_hms_event_sync_basic_7d94d913_2 has pending event. EventId:123368
EventType:CREATE_DATABASE
I0425 14:16:24.310739 109426 MetastoreEventsProcessor.java:1631]
7d4b01c2fb5fb3c8:adb779d900000000] Waiting for last synced event id (123366) to
reach 123368
I0425 14:16:24.312629 113084 HdfsTable.java:781] Loaded file and block metadata
for test_hms_event_sync_compute_stats_3d662792.foo partitions: p=0. Time taken:
844.104us
I0425 14:16:24.312776 113084 Table.java:1121] last refreshed event id for
table: test_hms_event_sync_compute_stats_3d662792.foo set to: -1
I0425 14:16:24.312800 113084 TableLoader.java:187] Loaded metadata for:
test_hms_event_sync_compute_stats_3d662792.foo (14ms)
I0425 14:16:24.609163 109031 MetastoreEventsProcessor.java:1195] Latest event
in HMS: id=123378, time=1745561784. Last synced event: id=123366,
time=1745561783.
W0425 14:16:24.609205 109031 MetastoreEventsProcessor.java:1198] Lag: 1s. 12
events pending to be processed.
I0425 14:16:24.610044 109030 MetastoreEventsProcessor.java:1057] Received 8
events. First event id: 123368.
I0425 14:16:24.610121 109030 MetastoreEvents.java:853] EventId: 123368
EventType: CREATE_DATABASE Target: test_hms_event_sync_basic_7d94d913_2.
Creating event 123368 of type CREATE_DATABASE on database
test_hms_event_sync_basic_7d94d913_2
I0425 14:16:24.610263 109030 MetastoreShim.java:857] EventId: 123369 EventType:
COMMIT_TXN transaction id: 6213
I0425 14:16:24.610435 109030 MetastoreShim.java:857] EventId: 123372 EventType:
COMMIT_TXN transaction id: 6207
I0425 14:16:24.610527 109030 MetastoreShim.java:857] EventId: 123374 EventType:
COMMIT_TXN transaction id: 6214
I0425 14:16:24.610601 109030 MetastoreShim.java:857] EventId: 123377 EventType:
COMMIT_TXN transaction id: 6215
I0425 14:16:24.610620 109030 MetastoreEvents.java:304] Total number of events
received: 8 Total number of events filtered out: 0
I0425 14:16:24.610684 109030 Db.java:143] createEventId_ for db:
test_hms_event_sync_basic_7d94d913_2 set to: 123368
I0425 14:16:24.610697 109030 Db.java:155] lastSyncedEventId_ for db:
test_hms_event_sync_basic_7d94d913_2 set from -1 to 123368
I0425 14:16:24.610713 109030 MetastoreEvents.java:842] EventId: 123368
EventType: CREATE_DATABASE Target: test_hms_event_sync_basic_7d94d913_2.
Successfully added database test_hms_event_sync_basic_7d94d913_2
I0425 14:16:24.611009 109426 MetastoreEventsProcessor.java:1651]
7d4b01c2fb5fb3c8:adb779d900000000] Last synced event id (123368) reached 123368
I0425 14:16:24.611114 109426 CatalogServiceCatalog.java:4418]
7d4b01c2fb5fb3c8:adb779d900000000] waitForHmsEvent succeeds.
updated_objects=[DATABASE:test_hms_event_sync_basic_7d94d913_2(2383)],
removed_objects=[TABLE:test_hms_event_sync_basic_7d94d913_2.tbl(2247)]
I0425 14:16:24.611183 109426 JniUtil.java:178]
7d4b01c2fb5fb3c8:adb779d900000000] Finished waitForHmsEvent request:
waitForHmsEvent 7d4b01c2fb5fb3c8:adb779d900000000. Time spent: 303ms{noformat}
The target event id in the log "Waiting for last synced event id (123366) to
reach 123368" is the CREATE_DATABASE event id, indicating by the log "Found db
test_hms_event_sync_basic_7d94d913_2 has pending event. EventId:123368
EventType:CREATE_DATABASE".
However, processing the CREATE_DATABASE event just adds an empty Db object
without any tables in it.
https://github.com/apache/impala/blob/ef8f8ca27b52f7fd842a7a887d5c9a8db9831f79/fe/src/main/java/org/apache/impala/catalog/events/MetastoreEvents.java#L2252
https://github.com/apache/impala/blob/ef8f8ca27b52f7fd842a7a887d5c9a8db9831f79/fe/src/main/java/org/apache/impala/service/CatalogOpExecutor.java#L980
https://github.com/apache/impala/blob/ef8f8ca27b52f7fd842a7a887d5c9a8db9831f79/fe/src/main/java/org/apache/impala/catalog/CatalogServiceCatalog.java#L2384
This breaks out assumption in MetastoreEventsProcessor#getMinEventIdToWaitFor()
to skip checking table events under missing dbs:
https://github.com/apache/impala/blob/ef8f8ca27b52f7fd842a7a887d5c9a8db9831f79/fe/src/main/java/org/apache/impala/catalog/events/MetastoreEventsProcessor.java#L1682-L1685
We do need to check all table events even if their dbs are missing in the cache.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
