consistent_replicate_gbk losing data after applying redolog

[zhaoxinyu]

Which jobs are flaking?

cdc_ghpr_integration_test

Which test(s) are flaking?

consistent_replicate_gbk

Jenkins logs or GitHub Actions link

[2022-04-01T16:36:43.146Z] [2022/04/02 00:36:43.133 +08:00] [INFO] [redo.go:103] ["apply redo log starts"] [checkpointTs=432231149290913799] [resolvedTs=432231153485217794]

[2022-04-01T16:36:43.146Z] [2022/04/02 00:36:43.141 +08:00] [INFO] [mysql_params.go:314] ["sink uri is configured"] [dsn="normal:******@tcp(127.0.0.1:3306)/?interpolateParams=true&multiStatements=true&allow_auto_random_explicit_insert=1&charset=utf8mb4&readTimeout=2m&sql_mode=%22IGNORE_SPACE%2CALLOW_INVALID_DATES%2CNO_ENGINE_SUBSTITUTION%2CONLY_FULL_GROUP_BY%2CNO_AUTO_VALUE_ON_ZERO%22&tidb_placement_mode=%22ignore%22&tidb_txn_mode=optimistic&time_zone=%22UTC%22&timeout=2m&transaction_isolation=%22READ-COMMITTED%22&writeTimeout=2m"]

[2022-04-01T16:36:43.428Z] [2022/04/02 00:36:43.145 +08:00] [INFO] [mysql.go:180] ["Start mysql sink"]

[2022-04-01T16:36:43.428Z] Apply redo log successfully

[2022-04-01T16:36:43.693Z] check diff failed 1-th time, retry later

[2022-04-01T16:36:46.316Z] check diff failed 2-th time, retry later

[2022-04-01T16:36:48.280Z] check diff failed 3-th time, retry later

[2022-04-01T16:36:50.226Z] check diff failed 4-th time, retry later

[2022-04-01T16:36:52.848Z] check diff failed 5-th time, retry later

[2022-04-01T16:36:54.775Z] check diff failed 6-th time, retry later

[2022-04-01T16:36:57.353Z] check diff failed 7-th time, retry later

[2022-04-01T16:36:59.333Z] check diff failed 8-th time, retry later

[2022-04-01T16:37:01.921Z] check diff failed 9-th time, retry later

https://ci.pingcap.net/blue/organizations/jenkins/cdc_ghpr_integration_test/detail/cdc_ghpr_integration_test/2595/pipeline/

Anything else we need to know

• Does this test exist for other branches as well?

• Has there been a high frequency of failure lately?

[zhaoxinyu]

1. The checkpointTs fetched from metadata is 432231149290913799
2. The commitTs parsed from redolog file '127.0.0.1/8300_d849f3b8-52b4-44ae-ad36-31440feef610_1648830988_row_432231149290913799.log' is also 432231149290913799.
3. In https://github.com/pingcap/tiflow/blob/master/cdc/redo/reader/file.go#L366, since startTs equals to commitTs, shouldOpen() returns false and the redolog file is not opened. As a result, the DML event in redolog file is not executed.

[zhaoxinyu]

After checking the commitTs of the RedoRowChangedEvent in redolog, it equals to the commitTs recorded in redolog file name. So this problem is due to advancing CheckpointTs errorneously.

[Rustin170506]

another case: https://ci2.pingcap.net/blue/organizations/jenkins/cdc_ghpr_integration_test/detail/cdc_ghpr_integration_test/11207/pipeline

[Rustin170506]

another case: https://ci2.pingcap.net/blue/organizations/jenkins/cdc_ghpr_integration_test/detail/cdc_ghpr_integration_test/11811/pipeline

[nongfushanquan]

/label affects-5.3

[asddongmen]

https://ci2.pingcap.net/blue/organizations/jenkins/cdc_ghpr_integration_test/detail/cdc_ghpr_integration_test/13629/pipeline another case
log-consistent_replicate_gbk-ddl_puller_lag.tar.gz