MySQL Bugs: #111027: Multi-column indexes with writest will cause HA_ERR_FOUND_DUPP

Bug #111027	Multi-column indexes with writest will cause HA_ERR_FOUND_DUPP_KEY
Submitted:	15 May 2023 10:49	Modified:	9 Oct 2023 15:42
Reporter:	Shun Yi (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.7.42, 8.0.33	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
Replication does use write-sets to detect dependencies and/or conflicts among transactions.  The write-set is extracted from primary, not null unique and not null foreign keys when the binary log format is ROW and the option`transaction_write_set_extraction` is enabled, both options are enabled by default.

For string columns, indexes can be created that use only the leading part of column values, using col_name(length) syntax to specify an index prefix length.

It was discovered that multi-column unique key write-sets were not properly generated, more precisely it was considering that unique keys could only refer the leading part of column values, while the whole values of referenced key columns are added to writeset.

How to repeat:
=============================================================================
1. SQL
=============================================================================

-- ############ 1. INITIALIZE ############
SET SESSION transaction_write_set_extraction = XXHASH64;
SET GLOBAL binlog_transaction_dependency_tracking = WRITESET;

CREATE database test;
USE test;

DROP TABLE IF EXISTS test_table;

-- ############ 2. CREATE TABLE ############
CREATE TABLE `test_table` (
  `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `t_id` varchar(64) NOT NULL,
  `s_id` varchar(64) NOT NULL,
  `a_type` varchar(64) NOT NULL,
  `a_no` varchar(1800) NOT NULL DEFAULT '',
  PRIMARY KEY (`id`),
  UNIQUE KEY `uniq_idx_t` (`s_id`(3),`a_type`(3),`a_no`(3),`t_id`(3))
) ENGINE=InnoDB;

-- key: 3 4 5 2

-- ############ 3. INSERT rows ############

-- insert row1: unique key: (aaa-bbb-2-1)
INSERT INTO test_table VALUES (1, 1, 'aaabbb', 'bbbccc', 2);

-- delete row1: unique key: (aaa-bbb-2-1)
DELETE FROM test_table WHERE id = 1;

-- insert row2: unique key: (aaa-bbb-2-1)
-- This transaction should conflict with 'delete row1'.
INSERT INTO test_table VALUES (2, 1, 'aaaddd', 'bbbeee', 2);

=============================================================================
2. Binary log
=============================================================================

-- =========== insert row1: ===========
#230515 17:28:38 server id 11  end_log_pos 1127 CRC32 0x783810e8        GTID    last_committed=3        sequence_number=4       rbr_only=yes    

### INSERT INTO `test`.`test_table`
### SET
###   @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='1' /* VARSTRING(192) meta=192 nullable=0 is_null=0 */
###   @3='aaabbb' /* VARSTRING(192) meta=192 nullable=0 is_null=0 */
###   @4='bbbccc' /* VARSTRING(192) meta=192 nullable=0 is_null=0 */
###   @5='2' /* VARSTRING(5400) meta=5400 nullable=0 is_null=0 */

-- =========== delete row1: ===========
#230515 17:28:42 server id 11  end_log_pos 1446 CRC32 0x134d242b        GTID    last_committed=4        sequence_number=5       rbr_only=yes    

### DELETE FROM `test`.`test_table`
### WHERE
###   @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='1' /* VARSTRING(192) meta=192 nullable=0 is_null=0 */
###   @3='aaabbb' /* VARSTRING(192) meta=192 nullable=0 is_null=0 */
###   @4='bbbccc' /* VARSTRING(192) meta=192 nullable=0 is_null=0 */
###   @5='2' /* VARSTRING(5400) meta=5400 nullable=0 is_null=0 */

-- =========== insert row2: ===========
#230515 17:28:45 server id 11  end_log_pos 1765 CRC32 0xf65ec357        GTID    last_committed=3        sequence_number=6       rbr_only=yes    

### INSERT INTO `test`.`test_table`
### SET
###   @1=2 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='1' /* VARSTRING(192) meta=192 nullable=0 is_null=0 */
###   @3='aaaddd' /* VARSTRING(192) meta=192 nullable=0 is_null=0 */
###   @4='bbbeee' /* VARSTRING(192) meta=192 nullable=0 is_null=0 */
###   @5='2' /* VARSTRING(5400) meta=5400 nullable=0 is_null=0 */

=============================================================================
3. Analysis
=============================================================================
SQL: 'INSERT INTO test_table VALUES (2, 1, 'aaaddd', 'bbbeee', 2);' 

Its 'last_committed' is equal to 3 which should greater than 4.

=============================================================================
4. master-error.log
=============================================================================
[ERROR] Slave SQL for channel '': Worker 3 failed executing transaction '1b9e5a6f-eed7-11ed-88b6-7cd30ac416c4:6' at master log mysql-bin.000001
Could not execute Write_rows_v1 event on table test.test_table; Duplicate entry 'aaa-bbb-2-1' for key 'uniq_idx_t', Error_code: 1062;
handler error HA_ERR_FOUND_DUPP_KEY;

Suggested fix:
In add_pke(), the values of the columns related to the multi-column key should not be added to the writeset without truncation. Only the specified width should be added.

For example:

INSERT INTO test_table values (4, 1, 'aahdde', 'bbbeee', 2);

The unique key is "aah-bbb-2-1".

However, the value added to writset is: 

(gdb) p pke
$3 = "uniq_idx_t½test½4test_table½10\000A\000A\000H\000D\000D\000E\000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 \000 ½130
\000B\000B\000B\000E\000E\000E\000 "...

The values of the columns related to the multi-column key is added to the writeset without truncation.

In fact, for the string columns, if an index created that use only the leading part of column values, the last_committed value calculated by the writeset may be problematic, leading to Duplicate entry issues.

For example, a primary key on a string column:

=================
1. SQL
=================

SET SESSION transaction_write_set_extraction = XXHASH64;
SET GLOBAL binlog_transaction_dependency_tracking = WRITESET;

CREATE database test;
USE test;

DROP TABLE IF EXISTS test2;

CREATE TABLE `test2` (
  `id` varchar(64) NOT NULL,
  `did` int DEFAULT NULL,
  PRIMARY KEY (`id`(3))
) ENGINE=InnoDB;

--------- last_committed=3 sequence_number=4
INSERT INTO test2 VALUES ('aaabbb', 1);

-- last_committed=4 sequence_number=5
DELETE FROM test2 WHERE did = 1;

--------- last_committed=3 sequence_number=6
INSERT INTO test2 VALUES ('aaabbc', 2);

-- last_committed=6 sequence_number=7
DELETE FROM test2 WHERE did = 2;

--------- last_committed=3 sequence_number=8
INSERT INTO test2 VALUES ('aaabbf', 3);

-- last_committed=8 sequence_number=9
DELETE FROM test2 WHERE did = 3;

=================
2. Analysis
=================

For all the insert statements above, last_committed is 3, indicating that writeset considers these 3 statements to be non-conflicting and can be executed in parallel on the replica. 

However, these three insert statements do conflict with each other because they all have the same primary key 'aaa'.

Why?
Because what is added to the writeset is ('id' varchar(64)), not ('id' varchar(3)).
('id' varchar(3)) is the primary key.

Hello Shun Yi,

Thank you for the report and test case.

regards,
Umesh

- 8.0.33

### INSERT INTO `test`.`test_table`
### SET
###   @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='1' /* VARSTRING(256) meta=256 nullable=0 is_null=0 */
###   @3='aaabbb' /* VARSTRING(256) meta=256 nullable=0 is_null=0 */
###   @4='bbbccc' /* VARSTRING(256) meta=256 nullable=0 is_null=0 */
###   @5='2' /* VARSTRING(7200) meta=7200 nullable=0 is_null=0 */
# at 1333
#230518  9:17:37 server id 1  end_log_pos 1333 CRC32 0x40682a01         Xid = 13
COMMIT/*!*/;
# End of compressed events!
# at 1333
#230518  9:17:37 server id 1  end_log_pos 1412 CRC32 0xaba16eba         GTID    last_committed=4        sequence_number=5       rbr_only=yes    original_committed_timestamp=1684394257333815   immediate_commit_timestamp=1684394257333815       transaction_length=281
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1684394257333815 (2023-05-18 09:17:37.333815 CEST)
# immediate_commit_timestamp=1684394257333815 (2023-05-18 09:17:37.333815 CEST)
/*!80001 SET @@session.original_commit_timestamp=1684394257333815*//*!*/;
/*!80014 SET @@session.original_server_version=80033*//*!*/;
/*!80014 SET @@session.immediate_server_version=80033*//*!*/;
SET @@SESSION.GTID_NEXT= 'e31eeae8-f54b-11ed-8927-020017078e24:5'/*!*/;
# at 1412
#230518  9:17:37 server id 1  end_log_pos 1614 CRC32 0x1b1b9d75         Transaction_Payload             payload_size=169        compression_type=ZSTD   uncompressed_size=229
# Start of compressed events!
# at 1614
#230518  9:17:37 server id 1  end_log_pos 1614 CRC32 0x4e9d5414         Query   thread_id=7     exec_time=0     error_code=0
SET TIMESTAMP=1684394257/*!*/;
BEGIN
/*!*/;
# at 1614
#230518  9:17:37 server id 1  end_log_pos 1614 CRC32 0x54098ef3         Table_map: `test`.`test_table` mapped to number 112
# has_generated_invisible_primary_key=0
# at 1614
#230518  9:17:37 server id 1  end_log_pos 1614 CRC32 0xdd5f8ef2         Delete_rows: table id 112 flags: STMT_END_F

BINLOG '
EdFlZBMBAAAASQAAAAAAAAAAAHAAAAAAAAEABHRlc3QACnRlc3RfdGFibGUABQgPDw8PCAABAAEA
ASAcAAEBgAID/P8A844JVA==
EdFlZCABAAAAQgAAAAAAAAAAAHAAAAAAAAEAAgAF/wABAAAAAAAAAAEAMQYAYWFhYmJiBgBiYmJj
Y2MBADLyjl/d
'/*!*/;
### DELETE FROM `test`.`test_table`
### WHERE
###   @1=1 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='1' /* VARSTRING(256) meta=256 nullable=0 is_null=0 */
###   @3='aaabbb' /* VARSTRING(256) meta=256 nullable=0 is_null=0 */
###   @4='bbbccc' /* VARSTRING(256) meta=256 nullable=0 is_null=0 */
###   @5='2' /* VARSTRING(7200) meta=7200 nullable=0 is_null=0 */
# at 1614
#230518  9:17:37 server id 1  end_log_pos 1614 CRC32 0xcee72de2         Xid = 14
COMMIT/*!*/;
# End of compressed events!
# at 1614
#230518  9:17:39 server id 1  end_log_pos 1693 CRC32 0xbd9901b8         GTID    last_committed=3        sequence_number=6       rbr_only=yes    original_committed_timestamp=1684394259458738   immediate_commit_timestamp=1684394259458738       transaction_length=281
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1684394259458738 (2023-05-18 09:17:39.458738 CEST)
# immediate_commit_timestamp=1684394259458738 (2023-05-18 09:17:39.458738 CEST)
/*!80001 SET @@session.original_commit_timestamp=1684394259458738*//*!*/;
/*!80014 SET @@session.original_server_version=80033*//*!*/;
/*!80014 SET @@session.immediate_server_version=80033*//*!*/;
SET @@SESSION.GTID_NEXT= 'e31eeae8-f54b-11ed-8927-020017078e24:6'/*!*/;
# at 1693
#230518  9:17:39 server id 1  end_log_pos 1895 CRC32 0x41795533         Transaction_Payload             payload_size=169        compression_type=ZSTD   uncompressed_size=229
# Start of compressed events!
# at 1895
#230518  9:17:39 server id 1  end_log_pos 1895 CRC32 0x219fef85         Query   thread_id=7     exec_time=0     error_code=0
SET TIMESTAMP=1684394259/*!*/;
BEGIN
/*!*/;
# at 1895
#230518  9:17:39 server id 1  end_log_pos 1895 CRC32 0x2572704a         Table_map: `test`.`test_table` mapped to number 112
# has_generated_invisible_primary_key=0
# at 1895
#230518  9:17:39 server id 1  end_log_pos 1895 CRC32 0x2263710b         Write_rows: table id 112 flags: STMT_END_F

BINLOG '
E9FlZBMBAAAASQAAAAAAAAAAAHAAAAAAAAEABHRlc3QACnRlc3RfdGFibGUABQgPDw8PCAABAAEA
ASAcAAEBgAID/P8ASnByJQ==
E9FlZB4BAAAAQgAAAAAAAAAAAHAAAAAAAAEAAgAF/wACAAAAAAAAAAEAMQYAYWFhZGRkBgBiYmJl
ZWUBADILcWMi
'/*!*/;
### INSERT INTO `test`.`test_table`
### SET
###   @1=2 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='1' /* VARSTRING(256) meta=256 nullable=0 is_null=0 */
###   @3='aaaddd' /* VARSTRING(256) meta=256 nullable=0 is_null=0 */
###   @4='bbbeee' /* VARSTRING(256) meta=256 nullable=0 is_null=0 */
###   @5='2' /* VARSTRING(7200) meta=7200 nullable=0 is_null=0 */
# at 1895
#230518  9:17:39 server id 1  end_log_pos 1895 CRC32 0xdf551bfe         Xid = 15
COMMIT/*!*/;
# End of compressed events!
# at 1895
#230518  9:33:18 server id 1  end_log_pos 1954 CRC32 0xe9954ef3         Rotate to support-cluster03-bin.000002  pos: 4
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

Documented fix as follows in the MySQL 8.0.35 and 8.2.0 changelogs, as follows:

  To detect dependencies and conflicts among transactions, MySQL
  Replication uses writesets which are extracted from keys that
  are NOT NULL (primary keys by definition, as well as unique and
  foreign keys which are NOT NULL) whenever binlog_format is ROW
  and the transaction_write_set_extraction is enabled (the default
  in both cases). In the case of multi-column unique keys using
  only the leading parts of column values (see "Column Prefix Key
  Parts"
  [https://dev.mysql.com/doc/refman/en/create-index.html#create-index-column-prefixes]),
  the writesets were not properly generated; this was due to the
  fact that the whole values of referenced key columns were added
  to the writeset in such cases, even though the keys themselves
  referenced only the column prefixes.
 

Closed.

This is marked as fixed in 8.0.35 and 8.2, but nothing about 5.7.

It is advertised that 5.7.44 is the last release of 5.7, so it looks this bug will never get fixed in 5.7.  Am I understanding things correctly ?