Delete not applied correctly when restoring cdclog

[dveeden]

1. What did you do?

tidb 5.7.25-TiDB-v5.0.1 > create table cdctest (id int primary key, c1 varchar(255));
Query OK, 0 rows affected (0.64 sec)

tidb 5.7.25-TiDB-v5.0.1 > insert into cdctest values (1, 'test 1');
Query OK, 1 row affected (0.12 sec)

tidb 5.7.25-TiDB-v5.0.1 > insert into cdctest values (2, 'test 2');
Query OK, 1 row affected (0.09 sec)

tidb 5.7.25-TiDB-v5.0.1 > insert into cdctest values (3, 'test 3');
Query OK, 1 row affected (0.12 sec)

tidb 5.7.25-TiDB-v5.0.1 > update cdctest set c1='update 3' where id=3;
Query OK, 1 row affected (0.14 sec)
Rows matched: 1  Changed: 1  Warnings: 0

tidb 5.7.25-TiDB-v5.0.1 > delete from cdctest where id=2;
Query OK, 1 row affected (0.13 sec)

tidb 5.7.25-TiDB-v5.0.1 > begin; select @@tidb_current_ts; rollback;
Query OK, 0 rows affected (0.00 sec)

+--------------------+
| @@tidb_current_ts  |
+--------------------+
| 424528095772147713 |
+--------------------+
1 row in set (0.03 sec)

tiup br restore cdclog --pd=192.168.122.50:2379 --storage=/tmp/cdclog --start-ts=424527916452806657 --end-ts=424528095772147713 --log-level=debug

tidb 5.7.25-TiDB-v5.0.1 > select * from cdctest;
+----+----------+
| id | c1       |
+----+----------+
|  1 | test 1   |
|  2 | NULL     |
|  3 | update 3 |
+----+----------+
3 rows in set (0.00 sec)

2. What did you expect to see?

tidb 5.7.25-TiDB-v5.0.1 > select * from cdctest;
+----+----------+
| id | c1       |
+----+----------+
|  1 | test 1   |
|  3 | update 3 |
+----+----------+
2 rows in set (0.00 sec)

3. What did you see instead?

tidb 5.7.25-TiDB-v5.0.1 > select * from cdctest;
+----+----------+
| id | c1       |
+----+----------+
|  1 | test 1   |
|  2 | NULL     |
|  3 | update 3 |
+----+----------+
3 rows in set (0.00 sec)

4. What version of BR and TiDB/TiKV/PD are you using?

[dvaneeden@dve-carbon ~]$ tiup br -V
Starting component `br`: /home/dvaneeden/.tiup/components/br/v5.0.1/br -V
Release Version: v5.0.1
Git Commit Hash: b3bd5495369244cfb1d3f2c49763a7fdb55d4ecd
Git Branch: heads/refs/tags/v5.0.1
Go Version: go1.13
UTC Build Time: 2021-04-23 06:02:57
Race Enabled: false

tidb 5.7.25-TiDB-v5.0.1 > select tidb_version()\G
*************************** 1. row ***************************
tidb_version(): Release Version: v5.0.1
Edition: Community
Git Commit Hash: 1145e347d3469d8e89f88dce86f6926ca44b3cd8
Git Branch: heads/refs/tags/v5.0.1
UTC Build Time: 2021-04-23 05:51:17
GoVersion: go1.13
Race Enabled: false
TiKV Min Version: v3.0.0-60965b006877ca7234adaced7890d7b029ed1306
Check Table Before Drop: false
1 row in set (0.01 sec)

5. Operation logs

brlog.zip

[2021/04/26 16:10:40.215 +02:00] [DEBUG] [buffer.go:192] ["process delete event"] [row="{\"d\":{\"c1\":{\"t\":15,\"f\":64,\"v\":\"test 2\"},\"id\":{\"t\":3,\"h\":true,\"f\":11,\"
v\":2}}}"]

[3pointer]

I found this PR #645 lost the delete logic..., and it didn't cherry-pick to release-4.0 branch. so 4.0 br has no such problem. anyway I fixed it in #1069... Thanks for report.

[dveeden]

Can we add unittests or integration tests to avoid this happening again? Maybe some cdclog that creates a table, inserts, updates and deletes records and then verify against a known good state?

[dveeden]

cc @xinghua0123

[cyliu0]

Fixed by #1069