Details
-
Bug
-
Status: Closed (View Workflow)
-
Minor
-
Resolution: Won't Fix
-
10.3.7, 10.3.8
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.
Attachments
Issue Links
- relates to
-
-
- Closed
-