[IMPALA-10897] TestEventProcessing.test_event_based_replication is flaky

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Fix Version/s: Impala 4.0.1
• Epic Color: ghx-label-5
• Assignee: Vihang Karajgaonkar
• Reporter: Quanlong Huang
• Created: 30/Aug/21 03:28
• Updated: 20/Oct/21 23:16
• Resolved: 20/Oct/21 23:16

Description

Saw this in an ASAN build:

metadata/test_event_processing.py:185: in test_event_based_replication
    self.__run_event_based_replication_tests()
metadata/test_event_processing.py:326: in __run_event_based_replication_tests
    EventProcessorUtils.wait_for_event_processing(self)
util/event_processor_utils.py:61: in wait_for_event_processing
    within {1} seconds".format(current_event_id, timeout))
E   Exception: Event processor did not sync till last known event id 34722           within 10 seconds 

Standard Error

SET client_identifier=metadata/test_event_processing.py::TestEventProcessing::()::test_event_based_replication;
-- connecting to: localhost:21000
-- connecting to localhost:21050 with impyla
-- 2021-08-28 23:43:40,300 INFO     MainThread: Closing active operation
-- connecting to localhost:28000 with impyla
-- 2021-08-28 23:43:40,323 INFO     MainThread: Closing active operation
-- connecting to localhost:11050 with impyla
-- 2021-08-28 23:43:48,026 INFO     MainThread: Waiting until events processor syncs to event id:31451
-- 2021-08-28 23:43:48,759 DEBUG    MainThread: Metric last-synced-event-id has reached the desired value:31455
-- 2021-08-28 23:43:48,790 DEBUG    MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
-- 2021-08-28 23:43:48,820 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:43:48,824 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:43:49,825 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:43:49,829 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:43:50,830 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:43:50,835 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:43:51,836 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:43:51,840 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:43:52,841 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:43:52,846 INFO     MainThread: Metric 'catalog.curr-version' has reached desired value: 2364
-- 2021-08-28 23:43:52,846 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25001
-- 2021-08-28 23:43:52,851 INFO     MainThread: Metric 'catalog.curr-version' has reached desired value: 2364
-- 2021-08-28 23:43:52,851 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25002
-- 2021-08-28 23:43:52,855 INFO     MainThread: Metric 'catalog.curr-version' has reached desired value: 2364
-- executing against localhost:21000

create table repl_source_ugchr.unpart_tbl (a string, b string) stored as parquet tblproperties ('transactional'='true','transactional_properties'='insert_only');

-- 2021-08-28 23:43:52,878 INFO     MainThread: Started query 394339b6db812c59:a5e5039a00000000
-- executing against localhost:21000

create table repl_source_ugchr.part_tbl (id int, bool_col boolean, tinyint_col tinyint, smallint_col smallint, int_col int, bigint_col bigint, float_col float, double_col double, date_string string, string_col string, timestamp_col timestamp) partitioned by (year int, month int) stored as parquet tblproperties ('transactional'='true','transactional_properties'='insert_only');

-- 2021-08-28 23:43:52,900 INFO     MainThread: Started query b74f5e32e4c1790a:4641075000000000
-- executing against localhost:21000

insert into repl_source_ugchr.unpart_tbl select * from functional.tinytable;

-- 2021-08-28 23:43:56,132 INFO     MainThread: Started query ee4b5eb533882fe4:b0d0e77400000000
-- executing against localhost:21000

insert into repl_source_ugchr.part_tbl partition(year,month) select * from functional_parquet.alltypessmall;

-- 2021-08-28 23:44:00,135 INFO     MainThread: Started query 344a832f2c85d754:8cf420d500000000
-- executing against localhost:21000

select count(*) from repl_source_ugchr.unpart_tbl;

-- 2021-08-28 23:44:00,911 INFO     MainThread: Started query a24c567cd4d8ebc3:636ac3be00000000
-- executing against localhost:21000

select count(*) from repl_source_ugchr.part_tbl;

-- 2021-08-28 23:44:01,084 INFO     MainThread: Started query 23484c04b7d1ebab:4d88715000000000
-- executing against localhost:21000

create database repl_target_ggfut;

-- 2021-08-28 23:49:06,182 INFO     MainThread: Started query 1848bc953f987711:95ae346800000000
-- 2021-08-28 23:49:12,238 INFO     MainThread: Waiting until events processor syncs to event id:31994
-- 2021-08-28 23:49:12,240 DEBUG    MainThread: Metric last-synced-event-id has reached the desired value:31994
-- 2021-08-28 23:49:12,273 DEBUG    MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
-- 2021-08-28 23:49:12,296 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:49:12,300 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:49:13,301 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:49:13,307 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:49:14,308 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:49:14,315 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:49:15,315 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:49:15,323 INFO     MainThread: Metric 'catalog.curr-version' has reached desired value: 2994
-- 2021-08-28 23:49:15,323 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25001
-- 2021-08-28 23:49:15,329 INFO     MainThread: Metric 'catalog.curr-version' has reached desired value: 2994
-- 2021-08-28 23:49:15,329 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25002
-- 2021-08-28 23:49:15,336 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:49:16,336 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25002
-- 2021-08-28 23:49:16,341 INFO     MainThread: Metric 'catalog.curr-version' has reached desired value: 2994
-- executing against localhost:21000

show tables in repl_target_ggfut;

-- 2021-08-28 23:49:16,349 INFO     MainThread: Started query ec408a6a710ed5e5:829dcc6600000000
-- executing against localhost:21000

show tables in repl_target_ggfut;

-- 2021-08-28 23:49:16,358 INFO     MainThread: Started query 614a91a04602a762:d3a9685900000000
-- executing against localhost:21000

select count(*) from repl_target_ggfut.unpart_tbl;

-- 2021-08-28 23:49:20,928 INFO     MainThread: Started query b64d2a2099ed7a87:b61d380d00000000
-- executing against localhost:21000

select count(*) from repl_target_ggfut.part_tbl;

-- 2021-08-28 23:49:25,032 INFO     MainThread: Started query 4a4f3caf1f814961:a6e7cece00000000
-- executing against localhost:21000

insert into repl_source_ugchr.unpart_tbl select * from functional.tinytable;

-- 2021-08-28 23:49:25,585 INFO     MainThread: Started query 7c4c5910217c3c63:7bd7a6fe00000000
-- executing against localhost:21000

insert into repl_source_ugchr.part_tbl partition(year,month) select * from functional_parquet.alltypessmall;

-- 2021-08-28 23:49:26,079 INFO     MainThread: Started query 1e4d5559508bdc23:bce2a60800000000
-- 2021-08-28 23:49:56,228 INFO     MainThread: Waiting until events processor syncs to event id:32160
-- 2021-08-28 23:49:56,440 DEBUG    MainThread: Metric last-synced-event-id has reached the desired value:32160
-- 2021-08-28 23:49:56,484 DEBUG    MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
-- 2021-08-28 23:49:56,512 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:49:56,518 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:49:57,519 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:49:57,524 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:49:58,524 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:49:58,530 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:49:59,531 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:49:59,539 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:50:00,539 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:50:00,546 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:50:01,547 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:50:01,554 INFO     MainThread: Metric 'catalog.curr-version' has reached desired value: 3122
-- 2021-08-28 23:50:01,555 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25001
-- 2021-08-28 23:50:01,571 INFO     MainThread: Metric 'catalog.curr-version' has reached desired value: 3122
-- 2021-08-28 23:50:01,571 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25002
-- 2021-08-28 23:50:01,578 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:50:02,579 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25002
-- 2021-08-28 23:50:02,589 INFO     MainThread: Metric 'catalog.curr-version' has reached desired value: 3122
-- executing against localhost:21000

select count(*) from repl_target_ggfut.unpart_tbl;

-- 2021-08-28 23:50:02,641 INFO     MainThread: Started query 3f4978dd5f24b4af:558c1b8000000000
-- executing against localhost:21000

select count(*) from repl_target_ggfut.part_tbl;

-- 2021-08-28 23:50:02,934 INFO     MainThread: Started query bc4e464a9fa39221:f9c3f41300000000
-- executing against localhost:21000

insert overwrite table repl_source_ugchr.unpart_tbl select * from functional.tinytable;

-- 2021-08-28 23:50:03,263 INFO     MainThread: Started query a740ee894752df2a:2feb8f3b00000000
-- executing against localhost:21000

insert overwrite table repl_source_ugchr.part_tbl partition(year,month) select * from functional_parquet.alltypessmall;

-- 2021-08-28 23:50:03,704 INFO     MainThread: Started query 884052c65ecd5fdc:b892b7f300000000
-- 2021-08-28 23:50:23,074 INFO     MainThread: Waiting until events processor syncs to event id:32344
-- 2021-08-28 23:50:23,808 DEBUG    MainThread: Metric last-synced-event-id has reached the desired value:32349
-- 2021-08-28 23:50:23,855 DEBUG    MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
-- 2021-08-28 23:50:23,885 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:50:23,890 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:50:24,890 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:50:24,896 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:50:25,897 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:50:25,905 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:50:26,906 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:50:26,913 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:50:27,914 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:50:27,921 INFO     MainThread: Metric 'catalog.curr-version' has reached desired value: 3255
-- 2021-08-28 23:50:27,921 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25001
-- 2021-08-28 23:50:27,926 INFO     MainThread: Metric 'catalog.curr-version' has reached desired value: 3255
-- 2021-08-28 23:50:27,926 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25002
-- 2021-08-28 23:50:27,931 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:50:28,931 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25002
-- 2021-08-28 23:50:28,938 INFO     MainThread: Metric 'catalog.curr-version' has reached desired value: 3255
-- executing against localhost:21000

select count(*) from repl_target_ggfut.unpart_tbl;

-- 2021-08-28 23:50:28,946 INFO     MainThread: Started query a44c2b14b5ce1be9:d98ecd5100000000
-- executing against localhost:21000

select count(*) from repl_target_ggfut.part_tbl;

-- 2021-08-28 23:50:29,178 INFO     MainThread: Started query 9a42fc19d507d8d3:da6eb99e00000000
-- executing against localhost:21000

create table repl_source_ugchr.insertonly_nopart_ctas tblproperties ('transactional'='true','transactional_properties'='insert_only') as select * from repl_source_ugchr.unpart_tbl;

-- 2021-08-28 23:50:29,564 INFO     MainThread: Started query fa471f8363e57a20:d4bc21f000000000
-- executing against localhost:21000

create table repl_source_ugchr.insertonly_part_ctas partitioned by (year, month) tblproperties ('transactional'='true','transactional_properties'='insert_only') as select * from repl_source_ugchr.part_tbl;

-- 2021-08-28 23:50:29,925 INFO     MainThread: Started query a147d6e6c4cb7498:4f0d50ab00000000
-- 2021-08-28 23:50:44,729 INFO     MainThread: Waiting until events processor syncs to event id:32625
-- 2021-08-28 23:50:44,940 DEBUG    MainThread: Metric last-synced-event-id has reached the desired value:32625
-- 2021-08-28 23:50:44,989 DEBUG    MainThread: Found 3 impalad/1 statestored/1 catalogd process(es)
-- 2021-08-28 23:50:45,017 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:50:45,023 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:50:46,024 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:50:46,030 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:50:47,031 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:50:47,037 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:50:48,038 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:50:48,045 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:50:49,045 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:50:49,051 INFO     MainThread: Sleeping 1s before next retry.
-- 2021-08-28 23:50:50,053 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25000
-- 2021-08-28 23:50:50,060 INFO     MainThread: Metric 'catalog.curr-version' has reached desired value: 3448
-- 2021-08-28 23:50:50,060 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25001
-- 2021-08-28 23:50:50,064 INFO     MainThread: Metric 'catalog.curr-version' has reached desired value: 3448
-- 2021-08-28 23:50:50,065 INFO     MainThread: Getting metric: catalog.curr-version from impala-ec2-centos74-m5-4xlarge-ondemand-1787.vpc.cloudera.com:25002
-- 2021-08-28 23:50:50,070 INFO     MainThread: Metric 'catalog.curr-version' has reached desired value: 3448
-- executing against localhost:21000

select count(*) from repl_source_ugchr.insertonly_nopart_ctas;

-- 2021-08-28 23:50:50,080 INFO     MainThread: Started query 7a4e918888e0f7b8:dee3360f00000000
-- executing against localhost:21000

select count(*) from repl_target_ggfut.insertonly_nopart_ctas;

-- 2021-08-28 23:50:53,149 INFO     MainThread: Started query 524d8ef3b6baf55e:efafcdf700000000
-- executing against localhost:21000

select count(*) from repl_source_ugchr.insertonly_part_ctas;

-- 2021-08-28 23:50:53,324 INFO     MainThread: Started query 58449b031b3e1e2b:fe00988a00000000
-- executing against localhost:21000

select count(*) from repl_target_ggfut.insertonly_part_ctas;

-- 2021-08-28 23:50:57,154 INFO     MainThread: Started query f4415892ac775fe0:c6ed79be00000000
-- executing against localhost:21000

truncate table repl_source_ugchr.unpart_tbl;

-- 2021-08-28 23:50:57,501 INFO     MainThread: Started query 174e9849e4194f73:a4bf3a2c00000000
-- executing against localhost:21000

truncate table repl_source_ugchr.part_tbl;

-- 2021-08-28 23:50:57,641 INFO     MainThread: Started query ba42b9e471b16479:02bee03300000000
-- 2021-08-28 23:51:16,369 INFO     MainThread: Waiting until events processor syncs to event id:34722