[MDEV-16710] Slave SQL: Could not execute Update_rows_v1 event with RocksDB and triggers Created: 2018-07-08  Updated: 2024-01-22

Status: Open
Project: MariaDB Server
Component/s: Storage Engine - RocksDB, Triggers
Affects Version/s: 10.2, 10.3
Fix Version/s: 10.4

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergei Petrunia
Resolution: Unresolved Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-33291 Slave SQL: Could not execute Delete_r... Open

 Description   

Note: Run with --mysqld=--plugin-load-add=ha_rocksdb. Parallel replication and optimistic mode don't make any difference, reproducible with and without them.

--source include/have_binlog_format_row.inc
 
--source include/master-slave.inc
 
 
 
CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=RocksDB;
 
INSERT INTO t1 VALUES (1);
 
 
 
CREATE TABLE t2 (b INT PRIMARY KEY) ENGINE=RocksDB;
 
 
 
CREATE TRIGGER tr AFTER INSERT ON t2 FOR EACH ROW INSERT INTO non_existing_table VALUES (NULL);
 
 
 
BEGIN;
 
DELETE FROM t1;
 
--error 0,ER_NO_SUCH_TABLE
 
INSERT INTO t2 VALUES (1);
 
--error 0,ER_NO_SUCH_TABLE
 
INSERT INTO t2 VALUES (2);
 
REPLACE INTO t1 SELECT * FROM t1;
 
COMMIT;
 
 
 
--sync_slave_with_master
 
 
 
# Cleanup
 
--connection master
 
DROP TABLE t2, t1;
 
--source include/rpl_end.inc

10.2 8b0d4cff076

 
2018-07-08 21:04:28 140091034605312 [ERROR] mysqld: Can't find record in 't1'
 
2018-07-08 21:04:28 140091034605312 [ERROR] Slave SQL: Could not execute Update_rows_v1 event on table test.t1; Can't find record in 't1', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log master-bin.000001, end_log_pos 1407, Gtid 0-1-5, Internal MariaDB error code: 1032
 
2018-07-08 21:04:28 140091034605312 [Warning] Slave: Can't find record in 't1' Error_code: 1032
 
2018-07-08 21:04:28 140091034605312 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'master-bin.000001' position 1101

Also reproducible on bb-10.2-mdev16428 af1568668.
Not reproducible with InnoDB.

 Comments   
Comment by Sergei Petrunia [ 2018-07-12 ]

I have added a SHOW BINLOG EVENTS command after the COMMIT in the test, and ran it with MyRocks and InnoDB:

SHOW BINLOG EVENTS IN 'master-bin.000001';
 
Log_name        Pos     Event_type      Server_id       End_log_pos     Info
 
master-bin.000001       4       Format_desc     1       256     Server ver: 10.2.16-MariaDB-debug-log, Binlog ver: 4
 
master-bin.000001       256     Gtid_list       1       285     []
 
master-bin.000001       285     Binlog_checkpoint       1       329     master-bin.000001
 
master-bin.000001       329     Gtid    1       371     GTID 0-1-1
 
master-bin.000001       371     Query   1       488     use `test`; CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=RocksDB
 
master-bin.000001       488     Gtid    1       530     BEGIN GTID 0-1-2
 
master-bin.000001       530     Annotate_rows   1       578     INSERT INTO t1 VALUES (1)
 
master-bin.000001       578     Table_map       1       623     table_id: 30 (test.t1)
 
master-bin.000001       623     Write_rows_v1   1       661     table_id: 30 flags: STMT_END_F
 
master-bin.000001       661     Xid     1       692     COMMIT /* xid=135 */
 
master-bin.000001       692     Gtid    1       734     GTID 0-1-3
 
master-bin.000001       734     Query   1       851     use `test`; CREATE TABLE t2 (b INT PRIMARY KEY) ENGINE=RocksDB
 
master-bin.000001       851     Gtid    1       893     GTID 0-1-4
 
master-bin.000001       893     Query   1       1101    use `test`; CREATE DEFINER=`root`@`localhost` TRIGGER tr AFTER INSERT ON t2 FOR EACH ROW INSERT INTO non_existing_table VALUES (NULL)
 
master-bin.000001       1101    Gtid    1       1143    BEGIN GTID 0-1-5
 
master-bin.000001       1143    Annotate_rows   1       1180    DELETE FROM t1
 
master-bin.000001       1180    Table_map       1       1225    table_id: 30 (test.t1)
 
master-bin.000001       1225    Delete_rows_v1  1       1263    table_id: 30 flags: STMT_END_F
 
master-bin.000001       1263    Annotate_rows   1       1318    REPLACE INTO t1 SELECT * FROM t1
 
master-bin.000001       1318    Table_map       1       1363    table_id: 30 (test.t1)
 
master-bin.000001       1363    Update_rows_v1  1       1407    table_id: 30 flags: STMT_END_F
 
master-bin.000001       1407    Xid     1       1438    COMMIT /* xid=139 */

InnoDB:

COMMIT;
 
SHOW BINLOG EVENTS IN 'master-bin.000001';
 
Log_name        Pos     Event_type      Server_id       End_log_pos     Info
 
master-bin.000001       4       Format_desc     1       256     Server ver: 10.2.16-MariaDB-debug-log, Binlog ver: 4
 
master-bin.000001       256     Gtid_list       1       285     []
 
master-bin.000001       285     Binlog_checkpoint       1       329     master-bin.000001
 
master-bin.000001       329     Gtid    1       371     GTID 0-1-1
 
master-bin.000001       371     Query   1       487     use `test`; CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=InnoDB
 
master-bin.000001       487     Gtid    1       529     BEGIN GTID 0-1-2
 
master-bin.000001       529     Annotate_rows   1       577     INSERT INTO t1 VALUES (1)
 
master-bin.000001       577     Table_map       1       622     table_id: 30 (test.t1)
 
master-bin.000001       622     Write_rows_v1   1       660     table_id: 30 flags: STMT_END_F
 
master-bin.000001       660     Xid     1       691     COMMIT /* xid=135 */
 
master-bin.000001       691     Gtid    1       733     GTID 0-1-3
 
master-bin.000001       733     Query   1       849     use `test`; CREATE TABLE t2 (b INT PRIMARY KEY) ENGINE=InnoDB
 
master-bin.000001       849     Gtid    1       891     GTID 0-1-4
 
master-bin.000001       891     Query   1       1099    use `test`; CREATE DEFINER=`root`@`localhost` TRIGGER tr AFTER INSERT ON t2 FOR EACH ROW INSERT INTO non_existing_table VALUES (NULL)
 
master-bin.000001       1099    Gtid    1       1141    BEGIN GTID 0-1-5
 
master-bin.000001       1141    Annotate_rows   1       1178    DELETE FROM t1
 
master-bin.000001       1178    Table_map       1       1223    table_id: 30 (test.t1)
 
master-bin.000001       1223    Delete_rows_v1  1       1261    table_id: 30 flags: STMT_END_F
 
master-bin.000001       1261    Xid     1       1292    COMMIT /* xid=139 */
 
connection slave;
 
connection master;
 
DROP TABLE t2, t1;
 
include/rpl_end.inc

Comment by Sergei Petrunia [ 2018-07-12 ]

Looking at the GTID 0-1-5:
InnoDB's binlog makes sense:

master-bin.000001       1099    Gtid    1       1141    BEGIN GTID 0-1-5
 
master-bin.000001       1141    Annotate_rows   1       1178    DELETE FROM t1
 
master-bin.000001       1178    Table_map       1       1223    table_id: 30 (test.t1)
 
master-bin.000001       1223    Delete_rows_v1  1       1261    table_id: 30 flags: STMT_END_F
 
master-bin.000001       1261    Xid     1       1292    COMMIT /* xid=139 */

MyRocks' binlog looks odd:

master-bin.000001       1101    Gtid    1       1143    BEGIN GTID 0-1-5
 
master-bin.000001       1143    Annotate_rows   1       1180    DELETE FROM t1
 
master-bin.000001       1180    Table_map       1       1225    table_id: 30 (test.t1)
 
master-bin.000001       1225    Delete_rows_v1  1       1263    table_id: 30 flags: STMT_END_F
 
master-bin.000001       1263    Annotate_rows   1       1318    REPLACE INTO t1 SELECT * FROM t1
 
master-bin.000001       1318    Table_map       1       1363    table_id: 30 (test.t1)
 
master-bin.000001       1363    Update_rows_v1  1       1407    table_id: 30 flags: STMT_END_F
 
master-bin.000001       1407    Xid     1       1438    COMMIT /* xid=139 */

Why do we have REPLACE command after we've ran DELETE FROM t1?

Comment by Sergei Petrunia [ 2018-07-12 ]

The issue seems to be on the master, MyRocks has incorrect transactional semantics when statements within a transaction fail with errors:

 MariaDB [j22]> BEGIN;
 
Query OK, 0 rows affected (0.00 sec)
 
 
 
MariaDB [j22]> DELETE FROM t1;
 
Query OK, 1 row affected (29.89 sec)
 
 
 
MariaDB [j22]> INSERT INTO t2 VALUES (1);
 
ERROR 1146 (42S02): Table 'j22.non_existing_table' doesn't exist
 
MariaDB [j22]> INSERT INTO t2 VALUES (2);
 
ERROR 1146 (42S02): Table 'j22.non_existing_table' doesn't exist
 
MariaDB [j22]>  SELECT * FROM t1;
 
+---+
 
| a |
 
+---+
 
| 1 |
 
+---+
 
1 row in set (0.00 sec)

The last SELECT should produce empty result.

Comment by Sergei Petrunia [ 2018-07-13 ]

Affects upstream too, filed as https://github.com/facebook/mysql-5.6/issues/857

Comment by Sergei Petrunia [ 2018-07-13 ]

The patch for this is pushed into bb-10.2-mdev16428 tree.

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