amend transaction: unique index not compatible with binlog

[you06]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

Start two clusters and connect them with tidb binlog(pump & drainer), execute this from upstream.

/* init */ drop table if exists t;
/* init */ create table t(id int, val int);

/* dml */ begin;
/* ddl */ create unique index u0 on t(val);
/* dml */ insert into t values(10, 2), (20, 2);
/* dml */ update t set val=val/2 where id < 15;
/* dml */ commit;

2. What did you expect to see? (Required)

Upstream and downstream got same result.

MySQL [test]> select * from t;
+------+------+
| id   | val  |
+------+------+
|   10 |    1 |
|   20 |    2 |
+------+------+

3. What did you see instead (Required)

The data in downstream is different from upstream.

There is difference between drainer's safe mode and normal mode

safe mode

Drainer will use safe mode in the start 5 minutes, so we'll got this result.

MySQL [test]> select * from t;
+------+------+
| id   | val  |
+------+------+
|   10 |    1 |
+------+------+

Here is some logs from downstream TiDB

[2020/11/06 12:14:25.786 +00:00] [INFO] [session.go:2166] ["CRUCIAL OPERATION"] [conn=6] [schemaVersion=24] [cur_db=test] [sql="create table t(id int, val int)"] [[email protected]]
...
[2020/11/06 12:14:29.898 +00:00] [INFO] [session.go:2166] ["CRUCIAL OPERATION"] [conn=6] [schemaVersion=25] [cur_db=test] [sql="create unique index u0 on t(val)"] [[email protected]]
...
[2020/11/06 12:14:30.309 +00:00] [INFO] [session.go:2184] [GENERAL_LOG] [conn=6] [[email protected]] [schemaVersion=29] [txnStartTS=0] [forUpdateTS=0] [isReadConsistency=false] [current_db=test] [txn_mode=OPTIMISTIC] [sql="START TRANSACTION"]
[2020/11/06 12:14:30.310 +00:00] [INFO] [session.go:2184] [GENERAL_LOG] [conn=6] [[email protected]] [schemaVersion=29] [txnStartTS=420653267755466754] [forUpdateTS=420653267755466754] [isReadConsistency=false] [current_db=test] [txn_mode=OPTIMISTIC] [sql="REPLACE INTO `test`.`t`(`id`,`val`) VALUES(10,2)"]
[2020/11/06 12:14:30.326 +00:00] [INFO] [session.go:2184] [GENERAL_LOG] [conn=6] [[email protected]] [schemaVersion=29] [txnStartTS=420653267755466754] [forUpdateTS=420653267755466754] [isReadConsistency=false] [current_db=test] [txn_mode=OPTIMISTIC] [sql="REPLACE INTO `test`.`t`(`id`,`val`) VALUES(20,2)"]
[2020/11/06 12:14:30.327 +00:00] [INFO] [session.go:2184] [GENERAL_LOG] [conn=6] [[email protected]] [schemaVersion=29] [txnStartTS=420653267755466754] [forUpdateTS=420653267755466754] [isReadConsistency=false] [current_db=test] [txn_mode=OPTIMISTIC] [sql="DELETE FROM `test`.`t` WHERE `val` = 2 LIMIT 1"]
[2020/11/06 12:14:30.328 +00:00] [INFO] [session.go:2184] [GENERAL_LOG] [conn=6] [[email protected]] [schemaVersion=29] [txnStartTS=420653267755466754] [forUpdateTS=420653267755466754] [isReadConsistency=false] [current_db=test] [txn_mode=OPTIMISTIC] [sql="REPLACE INTO `test`.`t`(`id`,`val`) VALUES(10,1)"]
[2020/11/06 12:14:30.329 +00:00] [INFO] [session.go:2184] [GENERAL_LOG] [conn=6] [[email protected]] [schemaVersion=29] [txnStartTS=420653267755466754] [forUpdateTS=420653267755466754] [isReadConsistency=false] [current_db=test] [txn_mode=OPTIMISTIC] [sql=COMMIT]

The data is incorrect, but all SQL statements are executed successfully.

normal mode

Drainer will automatically turned into normal mode 5 minutes after starting.

MySQL [test]> select * from t;
Empty set (0.290 sec)

[2020/11/06 12:25:44.607 +00:00] [INFO] [session.go:2166] ["CRUCIAL OPERATION"] [conn=6] [schemaVersion=32] [cur_db=test] [sql="create table t(id int, val int)"] [[email protected]]
...
[2020/11/06 12:25:48.816 +00:00] [INFO] [session.go:2166] ["CRUCIAL OPERATION"] [conn=6] [schemaVersion=33] [cur_db=test] [sql="create unique index u0 on t(val)"] [[email protected]]
...
[2020/11/06 12:25:49.196 +00:00] [INFO] [session.go:2184] [GENERAL_LOG] [conn=6] [[email protected]] [schemaVersion=37] [txnStartTS=0] [forUpdateTS=0] [isReadConsistency=false] [current_db=test] [txn_mode=OPTIMISTIC] [sql="START TRANSACTION"]
[2020/11/06 12:25:49.198 +00:00] [INFO] [session.go:2184] [GENERAL_LOG] [conn=6] [[email protected]] [schemaVersion=37] [txnStartTS=420653445725028354] [forUpdateTS=420653445725028354] [isReadConsistency=false] [current_db=test] [txn_mode=OPTIMISTIC] [sql="INSERT INTO `test`.`t`(`id`,`val`) VALUES(10,2)"]
[2020/11/06 12:25:49.211 +00:00] [INFO] [session.go:2184] [GENERAL_LOG] [conn=6] [[email protected]] [schemaVersion=37] [txnStartTS=420653445725028354] [forUpdateTS=420653445725028354] [isReadConsistency=false] [current_db=test] [txn_mode=OPTIMISTIC] [sql="INSERT INTO `test`.`t`(`id`,`val`) VALUES(20,2)"]
[2020/11/06 12:25:49.211 +00:00] [INFO] [conn.go:787] ["command dispatched failed"] [conn=6] [connInfo="id:6, addr:172.16.4.170:52680 status:11, collation:utf8_general_ci, user:root"] [command=Query] [status="inTxn:1, autocommit:1"] [sql="INSERT INTO `test`.`t`(`id`,`val`) VALUES(20,2)"] [txn_mode=OPTIMISTIC] [err="[kv:1062]Duplicate entry '2' for key 'u0'"]
[2020/11/06 12:25:49.212 +00:00] [INFO] [session.go:2184] [GENERAL_LOG] [conn=6] [[email protected]] [schemaVersion=37] [txnStartTS=420653445725028354] [forUpdateTS=420653445725028354] [isReadConsistency=false] [current_db=test] [txn_mode=OPTIMISTIC] [sql=ROLLBACK]

Besides, drainer will quit due to this error.

[2020/11/06 12:25:49.212 +00:00] [ERROR] [executor.go:111] ["Exec fail, will rollback"] [query="INSERT INTO `test`.`t`(`id`,`val`) VALUES(?,?)"] [args="[20,2]"] [error="Error 1062: Duplicate entry '2' for key 'u0'"]

4. What is your TiDB version? (Required)

Release Version: v4.0.8-21-g08da7a0c4
Edition: Community
Git Commit Hash: 08da7a0c4d5b71fc8a41ddaa892d6af7248a1d51
Git Branch: fix_amend_dup_mut
UTC Build Time: 2020-11-06 09:35:55
GoVersion: go1.15.2
Race Enabled: false
TiKV Min Version: v3.0.0-60965b006877ca7234adaced7890d7b029ed1306
Check Table Before Drop: false

[cfzjywxk]

Currently, it's difficult to make them comptatible for such scenerios, we'll document about this.

[cfzjywxk]

Change it to part of feature request in #20996