[MDEV-16370] row-based binlog events (updates by primary key) can not be applied multiple times to system versioned tables Created: 2018-06-01  Updated: 2021-07-24  Resolved: 2021-07-24

Status: Closed
Project: MariaDB Server
Component/s: Replication, Versioned Tables
Affects Version/s: 10.3.7, 10.3.8
Fix Version/s: N/A

Type: Bug Priority: Minor
Reporter: Valerii Kravchuk Assignee: Sergei Golubchik
Resolution: Won't Fix Votes: 0
Labels: RBR, mysqlbinlog

Issue Links:
Relates
relates to MDEV-16372 ER_BASE64_DECODE_ERROR upon replaying... Closed

 Description   

Normally one can re-apply row-based events from the binary log (at least single row updates of non-key column by the primary key) as many times as needed. Consider this simple scenario:

openxs@ao756:~/dbs/maria10.3$ bin/mysql --socket=/tmp/mariadb.sock -uroot test  Reading table information for completion of table and column names
 
You can turn off this feature to get a quicker startup with -A
 
 
 
Welcome to the MariaDB monitor.  Commands end with ; or \g.
 
Your MariaDB connection id is 9
 
Server version: 10.3.8-MariaDB-log Source distribution
 
 
 
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
 
 
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
 
 
MariaDB [test]> create table tv(id int primary key, val int);
 
Query OK, 0 rows affected (0.400 sec)
 
 
 
MariaDB [test]> insert into tv values (1, 1);
 
Query OK, 1 row affected (0.049 sec)
 
 
 
MariaDB [test]> reset master;
 
Query OK, 0 rows affected (0.166 sec)
 
 
 
MariaDB [test]> show master status;
 
+------------------+----------+--------------+------------------+
 
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB |
 
+------------------+----------+--------------+------------------+
 
| ao756-bin.000001 |      328 |              |                  |
 
+------------------+----------+--------------+------------------+
 
1 row in set (0.000 sec)
 
 
 
MariaDB [test]> select @@binlog_format, @@binlog_row_image;
 
+-----------------+--------------------+
 
| @@binlog_format | @@binlog_row_image |
 
+-----------------+--------------------+
 
| ROW             | FULL               |
 
+-----------------+--------------------+
 
1 row in set (0.000 sec)
 
 
 
MariaDB [test]> update tv set val = 2 where id = 1;
 
Query OK, 1 row affected (0.067 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MariaDB [test]> update tv set val = 3 where id = 1;
 
Query OK, 1 row affected (0.037 sec)
 
Rows matched: 1  Changed: 1  Warnings: 0
 
 
 
MariaDB [test]> select * from tv;
 
+----+------+
 
| id | val  |
 
+----+------+
 
|  1 |    3 |
 
+----+------+
 
1 row in set (0.001 sec)
 
 
 
MariaDB [test]> flush logs;
 
Query OK, 0 rows affected (0.170 sec)
 
 
 
MariaDB [test]> exit
 
Bye

As a result we get a binary log with two row-based updates:

openxs@ao756:~/dbs/maria10.3$ bin/mysqlbinlog -v data/ao756-bin.000001
 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
 
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
 
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
 
DELIMITER /*!*/;
 
# at 4
 
#180601 15:25:54 server id 1  end_log_pos 256 CRC32 0xbde756f2  Start: binlog v 4, server v 10.3.8-MariaDB-log created 180601 15:25:54 at startup
 
ROLLBACK/*!*/;
 
BINLOG '
 
UjsRWw8BAAAA/AAAAAABAAAAAAQAMTAuMy44LU1hcmlhREItbG9nAAAAAAAAAAAAAAAAAAAAAAAA
 
AAAAAAAAAAAAAAAAAABSOxFbEzgNAAgAEgAEBAQEEgAA5AAEGggAAAAICAgCAAAACgoKAAAAAAAA
 
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
 
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
 
AAAAAAAAAAAEEwQADQgICAoKCgHyVue9
 
'/*!*/;
 
# at 256
 
#180601 15:25:54 server id 1  end_log_pos 285 CRC32 0xefe84001  Gtid list []
 
# at 285
 
#180601 15:25:54 server id 1  end_log_pos 328 CRC32 0x77ed5780  Binlog checkpoint ao756-bin.000001
 
# at 328
 
#180601 15:26:31 server id 1  end_log_pos 370 CRC32 0x85964c7e  GTID 0-1-1 trans
 
/*!100101 SET @@session.skip_parallel_replication=0*//*!*/;
 
/*!100001 SET @@session.gtid_domain_id=0*//*!*/;
 
/*!100001 SET @@session.server_id=1*//*!*/;
 
/*!100001 SET @@session.gtid_seq_no=1*//*!*/;
 
BEGIN
 
/*!*/;
 
# at 370
 
# at 427
 
#180601 15:26:31 server id 1  end_log_pos 427 CRC32 0x3404421b  Annotate_rows:
 
#Q> update tv set val = 2 where id = 1
 
#180601 15:26:31 server id 1  end_log_pos 473 CRC32 0xe650f843  Table_map: `test`.`tv` mapped to number 20
 
# at 473
 
#180601 15:26:31 server id 1  end_log_pos 525 CRC32 0x3d3cbe3c  Update_rows: table id 20 flags: STMT_END_F
 
 
 
BINLOG '
 
dzsRWxMBAAAALgAAANkBAAAAABQAAAAAAAEABHRlc3QAAnR2AAIDAwACQ/hQ5g==
 
dzsRWxgBAAAANAAAAA0CAAAAABQAAAAAAAEAAv///AEAAAABAAAA/AEAAAACAAAAPL48PQ==
 
'/*!*/;
 
### UPDATE `test`.`tv`
 
### WHERE
 
###   @1=1
 
###   @2=1
 
### SET
 
###   @1=1
 
###   @2=2
 
# Number of rows: 1
 
# at 525
 
#180601 15:26:31 server id 1  end_log_pos 556 CRC32 0x30719438  Xid = 11
 
COMMIT/*!*/;
 
# at 556
 
#180601 15:26:36 server id 1  end_log_pos 598 CRC32 0xcfc49d29  GTID 0-1-2 trans
 
/*!100001 SET @@session.gtid_seq_no=2*//*!*/;
 
BEGIN
 
/*!*/;
 
# at 598
 
# at 655
 
#180601 15:26:36 server id 1  end_log_pos 655 CRC32 0x5be0a3bd  Annotate_rows:
 
#Q> update tv set val = 3 where id = 1
 
#180601 15:26:36 server id 1  end_log_pos 701 CRC32 0x221100ed  Table_map: `test`.`tv` mapped to number 20
 
# at 701
 
#180601 15:26:36 server id 1  end_log_pos 753 CRC32 0x2c6ee1de  Update_rows: table id 20 flags: STMT_END_F
 
 
 
BINLOG '
 
fDsRWxMBAAAALgAAAL0CAAAAABQAAAAAAAEABHRlc3QAAnR2AAIDAwAC7QARIg==
 
fDsRWxgBAAAANAAAAPECAAAAABQAAAAAAAEAAv///AEAAAACAAAA/AEAAAADAAAA3uFuLA==
 
'/*!*/;
 
### UPDATE `test`.`tv`
 
### WHERE
 
###   @1=1
 
###   @2=2
 
### SET
 
###   @1=1
 
###   @2=3
 
# Number of rows: 1
 
# at 753
 
#180601 15:26:36 server id 1  end_log_pos 784 CRC32 0x17176a74  Xid = 12
 
COMMIT/*!*/;
 
# at 784
 
#180601 15:26:46 server id 1  end_log_pos 831 CRC32 0x9b00b198  Rotate to ao756-bin.000002  pos: 4
 
DELIMITER ;
 
# End of log file
 
ROLLBACK /* added by mysqlbinlog */;
 
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

Normally we can apply it to the table as many times as needed without errors, as long as initial state of data is consistent (row exists):

MariaDB [test]> delete from tv;
 
Query OK, 0 rows affected (0.000 sec)
 
 
 
MariaDB [test]> insert into tv values (1, 1);
 
Query OK, 1 row affected (0.031 sec)
 
 
 
MariaDB [test]> select * from tv;
 
+----+------+
 
| id | val  |
 
+----+------+
 
|  1 |    1 |
 
+----+------+
 
1 row in set (0.001 sec)
 
 
 
MariaDB [test]> exit
 
Bye
 
openxs@ao756:~/dbs/maria10.3$ bin/mysqlbinlog -v data/ao756-bin.000001 |  mysql -uroot --socket=/tmp/mariadb.sock
 
openxs@ao756:~/dbs/maria10.3$ bin/mysqlbinlog -v data/ao756-bin.000001 |  mysql -uroot --socket=/tmp/mariadb.sock
 
openxs@ao756:~/dbs/maria10.3$ bin/mysqlbinlog -v data/ao756-bin.000001 |  mysql -uroot --socket=/tmp/mariadb.sock
 
openxs@ao756:~/dbs/maria10.3$ mysql -uroot --socket=/tmp/mariadb.sock test -e"select * from tv"
 
+----+------+
 
| id | val  |
 
+----+------+
 
|  1 |    3 |
 
+----+------+
 
openxs@ao756:~/dbs/maria10.3$

Now, let's try to re-create the table as a system versioned one:

MariaDB [test]> drop table tv;
 
Query OK, 0 rows affected (0.215 sec)
 
 
 
MariaDB [test]> create table tv(id int primary key, val int) with system versioning;
 
Query OK, 0 rows affected (0.197 sec)
 
 
 
MariaDB [test]> insert into tv values (1, 1);
 
Query OK, 1 row affected (0.037 sec)
 
 
 
MariaDB [test]> select *, row_start, row_end from tv;
 
+----+------+----------------------------+----------------------------+
 
| id | val  | row_start                  | row_end                    |
 
+----+------+----------------------------+----------------------------+
 
|  1 |    1 | 2018-06-01 15:40:35.061322 | 2038-01-19 05:14:07.999999 |
 
+----+------+----------------------------+----------------------------+
 
1 row in set (0.001 sec)
 
 
 
MariaDB [test]> exit
 
Bye

We can successfully apply binary log once and get the result:

openxs@ao756:~/dbs/maria10.3$ bin/mysqlbinlog -v data/ao756-bin.000001 |  mysql -uroot --socket=/tmp/mariadb.sock
 
openxs@ao756:~/dbs/maria10.3$ mysql -uroot --socket=/tmp/mariadb.sock test -e"select *, row_start, row_end from tv"
 
+----+------+----------------------------+----------------------------+
 
| id | val  | row_start                  | row_end                    |
 
+----+------+----------------------------+----------------------------+
 
|  1 |    3 | 2018-06-01 15:26:36.000000 | 2038-01-19 05:14:07.999999 |
 
+----+------+----------------------------+----------------------------+

But if we try again we fail with error:

openxs@ao756:~/dbs/maria10.3$ bin/mysqlbinlog -v data/ao756-bin.000001 |  mysql -uroot --socket=/tmp/mariadb.sock
 
ERROR 1062 (23000) at line 63: Duplicate entry '1' for key 'PRIMARY'
 
openxs@ao756:~/dbs/maria10.3$ mysql -uroot --socket=/tmp/mariadb.sock test -e"select *, row_start, row_end from tv"
 
+----+------+----------------------------+----------------------------+
 
| id | val  | row_start                  | row_end                    |
 
+----+------+----------------------------+----------------------------+
 
|  1 |    2 | 2018-06-01 15:26:31.000000 | 2038-01-19 05:14:07.999999 |
 
+----+------+----------------------------+----------------------------+

Note two things above:

1. The error message is weird and misleading. We do have just one single row with primary key value 1, and we updated other column, not a primary key.

2. We were able to perform the first update, but not the second. So, I'd say data are corrupted.

Probably system versioned tables can not be treated in such a way, but then I'd appreciate proper error messages and documented limitation.

I also strongly suspect that the same problem may happen during replication, in case of retries by SQL thread for example, or in some other, not yet identified cases. At least this my test was created while working on a problem (same error message for some of multiple single row updates) while replicating row-based changes to a more complex table from older 5.5.x MariaDB version into a similar system-versioned table on MariaDB 10.3.7 slave.

 Comments   
Comment by Elena Stepanova [ 2018-06-01 ]

Well, you are applying a log from an essentially different table, which has a different number of columns, different contents and different key structure. I don't know how much obligations we have in this case to make it work transparently.

For ER_DUP_ENTRY, sadly yes, you have a 2-component PK and you do update a part of it, although implicitly.

MariaDB [test]> show index in tv;
 
+-------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
 
| Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |
 
+-------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
 
| tv    |          0 | PRIMARY  |            1 | id          | A         |           1 |     NULL | NULL   |      | BTREE      |         |               |
 
| tv    |          0 | PRIMARY  |            2 | row_end     | A         |           1 |     NULL | NULL   |      | BTREE      |         |               |
 
+-------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
 
2 rows in set (0.00 sec)

I can't argue that the behavior is confusing for a regular user (as many other things about versioning will be), but I don't see a viable alternative, any way we change it, is going to be confusing.
The first replay of the error log creates a historical record for (1,2), with row_end equal the time of the second update (2=>3).
The second replay attempts to do exactly the same and ends up with the PK violation.

What should be done differently? Silently drop the previous history? Avoid creating new history while replaying the binlog? Using current timestamps and not timestamps from the binary log? I think whichever we choose, there will still be opinion that it's wrong.

I'll leave it to serg to decide.

Comment by Valerii Kravchuk [ 2018-06-01 ]

If the decision is not to change the behavior, please, consider at least the change to error message, so that the value of "implicit" row_end part of the primary key is shown. That would be a hint for the user on what exactly is wrong.

Comment by Sergei Golubchik [ 2018-06-01 ]

Note, also, that what you're doing is very fundamentally against the concept of versioning. You cannot update a row from 1 to 2 twice at exactly the same point in time. And it's what you've trying to do.

If you run the slave with --secure-timestamp=YES then the versioning on the slave will use slave system clock, not master event timestamp. Then you should be able to apply row log as many times as you want, every time creating more historical rows with new values for row_start and row_end.

Comment by Sergei Golubchik [ 2018-09-19 ]

On the second thought, let's try to fix the system versioning on the slave to keep row events idempotent

Comment by Aleksey Midenkov [ 2018-11-17 ]

This should be fixed in 10.4 because it introduces important change to versioning algorithm:

UPDATE and DELETE binlog events change `row_start` of historical record if timestamps are applied from binlog (SECURE_TIMESTAMP is off) and binlog timestamp is earlier than `row_start` of existing record. In this case historical record's (row_start, row_end) gets values (binlog timestamp - 1 second, binlog timestamp).

Comment by Aleksey Midenkov [ 2018-11-20 ]

> What should be done differently? Silently drop the previous history? Avoid creating new history while replaying the binlog?

I prefer latter because: 1) history before any binlog is more important; 2) it's faster.

> Using current timestamps and not timestamps from the binary log? I think whichever we choose, there will still be opinion that it's wrong.

As serg suggested: timestamps from binlog are still used, but row_start is corrected. I agree, this is questionable, but it should work for use case of slave initiation and is better than using current timestamps. For better security I would recommend configuration variable as this is one-time operation.

Comment by Aleksey Midenkov [ 2019-04-29 ]

The task is done with the help of new option log_bin_send_microseconds. Along with already mentioned drawbacks of spoof counter the major issue is that multiple slaves will get desynchronised history. This is specific only for unversioned -> versioned replication. Also spoof counter is unstable on binlog replay via mysql client because the counter is affected by RTC and there is no measure to keep sequence of BINLOG commands contiguous (without RTC interference).

serg, Elkin Please, review.

There is no mention of mysqldump use case in the task. valerii please clarify whether this task has something to do with mysqldump. And of so, serg should describe how SET TIMESTAMP injection should work.

Comment by Sergei Golubchik [ 2020-10-02 ]

So, the goal is to make applying of row-based binlog idempotent when applying unversioned events to the versioned table.
It seems possible in some cases, for example, we can make the original case working by ignoring duplicate key error internally.
But it will essentially rely on the primary key, without a primary key there will be no duplicate key error and binlog will continue creating new identical history rows every time it's applied.

Another possible approach would be to completely ignore all updates where now() is less than the row start_time. It won't help inserts, though, inserts will still create duplicate rows, but it's the same without versioning, so it's ok.

In general, there are many cases when an rbr-binlog cannot be applied many times. As far as I understand, the goal is to be able to re-apply rbr-binlog in the unversioned->versioned mode in all cases where it's possible in the unversioned->unversioned mode. What are these cases?

  • idempotent changes (cyclic update 1→2→1, insert+delete, etc)
  • non-idempotent changes, but a table has a PK, only updates of non-PK columns
  • anything else?
Comment by Andrei Elkin [ 2020-10-02 ]

serg: to complete with all cases where it's possible in the unversioned->unversioned mode,

  • also when there's no PK, but an UNIQUE constraint is defined and the lookup key does not change in update
  • then, also (insert,insert) or (delete,delete) on the table with at least UNIQUE constraint
  • or (in principle, not implemented) the table has at least UNIQUE constraint and an update binlogged as two insert + delete events, or processed as the two events.
Comment by Andrei Elkin [ 2020-10-02 ]

serg, midenok: apologies if I shooting too wildly, but could historical record be perceived as a constraint? Think of FK constraint that can be controlled as a parallel.

Comment by Sergei Golubchik [ 2020-10-08 ]

As far as I can see it, to solve "non-idempotent update with UNIQUE" use case it is, indeed, enough to ignore duplicate key errors. Here "ignore" means — not to insert the row that causes a dup key error and not to abort the statement either. It could be made safer only to ignore them if it's the history column that's duplicate.

In a case of "idempotent pair of insert+delete", the duplicate key error will be caused by an update, so the above becomes "delete the row that causes an dup key error on update".

Now can this ignoring of errors break some other use cases? It generates corrupted inconsistent history when in the binlog is being applied for the second time. I'm not sure it's a good idea. AS OF queries don't expect that (and shouldn't really)

Generated at Thu Feb 08 08:28:24 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.