[MDEV-24667] LOAD DATA INFILE/inserted rows not written to binlog - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.3.27, 10.5.8, 10.0(EOL), 10.1(EOL), 10.2(EOL), 10.3(EOL), 10.4(EOL), 10.5, 10.6, 10.7(EOL)
Fix Version/s: 10.2.44, 10.3.35, 10.4.25, 10.5.16, 10.6.8, 10.7.4, 10.8.3
Component/s: Data Definition - Temporary, Replication
Labels:
None
Environment:
CentOS 8

Description

Hi,

I found a bug affecting recent MariaDB versions.
Versions tested:

OS repo: MariaDB 5.5.68 (on CentOS 7) - Not affected
OS repo: MariaDB 10.3.27 (On CentOS 8) - Affected
MariaDB repo: MariaDB 10.5.8 (On CentOS 8) - Affected

(All with stock settings, e.g. stock binlog_format)

We have a master, with multiple slaves.
The slaves have log_slave_updates=1, to replicate to more slaves.

Master: MariaDB 5.5.68 on CentOS 7 from OS repository.
Slave #1: MariaDB 10.5.8 On CentOS 8 from MariaDB repository. Also tested 10.3.27 from OS repository.
Slave #2: MariaDB 5.5.68 on CentOS 7 from OS repository.

We run an query on the master to update some table. The query is successfully replicated to slaves #1 and #2. However, slave #1 doesn't write it properly to the binary log, causing the further slaves actually lose rows.

The query we run on the master:

create temporary table tpool like cid_stock;

load data local infile '/root/cidcsv.sql' into table tpool fields terminated by ',' lines terminated by '\n' (cid) set countrycode='IL';

delete from cid_stock where countrycode='IL';

insert into cid_stock select * from tpool where countrycode='IL';

The issue seems related to temporary tables, because it doesn't happen with a static table. With this query i can successfully see the rows in the binary log:

create table pool2 like cid_stock;

load data local infile '/root/cidcsv.sql' into table pool2 fields terminated by ',' lines terminated by '\n' (cid) set countrycode='IL';

delete from cid_stock where countrycode='IL';

insert into cid_stock select * from pool2 where countrycode='IL';

What happens is that slave #1 correctly executes this, however it doesn't write it properly to the binary log. The load data infile statement is missing. I guess its ok for it to be missing because of binlog_format=mixed, however the rows aren't replicated either.
So what happens is that delete works, but the insert inserts 0 rows because the table is empty.
On slave #2 its fine, it correctly writes the load data infile to the binary log.

Binary log emitted by slave #1:

# at 14546

#210124 13:09:38 server id 8  end_log_pos 14588 CRC32 0xdb2fc10d 	GTID 0-8-96 ddl

/*!100001 SET @@session.gtid_seq_no=96*//*!*/;

# at 14588

#210124 13:09:38 server id 8  end_log_pos 14709 CRC32 0x47091aaf 	Query	thread_id=44	exec_time=0	error_code=0

SET TIMESTAMP=1611493778/*!*/;

SET @@session.pseudo_thread_id=44/*!*/;

create temporary table tpool like cid_stock

/*!*/;

# at 14709

#210124 13:09:38 server id 8  end_log_pos 14751 CRC32 0x2e83513f 	GTID 0-8-97 trans

/*!100001 SET @@session.gtid_seq_no=97*//*!*/;

START TRANSACTION

/*!*/;

# at 14751

#210124 13:09:38 server id 8  end_log_pos 14873 CRC32 0xfa6ce3aa 	Query	thread_id=44	exec_time=0	error_code=0

SET TIMESTAMP=1611493778/*!*/;

delete from cid_stock where countrycode='IL'

/*!*/;

# at 14873

#210124 13:09:38 server id 8  end_log_pos 14904 CRC32 0x634c53ca 	Xid = 227

COMMIT/*!*/;

# at 14904

#210124 13:09:38 server id 8  end_log_pos 14946 CRC32 0xad87d017 	GTID 0-8-98

/*!100001 SET @@session.gtid_seq_no=98*//*!*/;

START TRANSACTION

/*!*/;

# at 14946

#210124 13:09:38 server id 8  end_log_pos 15088 CRC32 0xd5b71ed0 	Query	thread_id=44	exec_time=0	error_code=0

SET TIMESTAMP=1611493778/*!*/;

insert into cid_stock select * from tpool where countrycode='IL'

/*!*/;

# at 15088

#210124 13:09:38 server id 8  end_log_pos 15119 CRC32 0xb6ae6dbc 	Xid = 229

COMMIT/*!*/;

DELIMITER ;

# End of log file

Binary log emitted by slave #2:

# at 21828

#210124 13:09:38 server id 8  end_log_pos 21945 	Query	thread_id=44	exec_time=0	error_code=0

SET TIMESTAMP=1611493778/*!*/;

SET @@session.pseudo_thread_id=44/*!*/;

create temporary table tpool like cid_stock

/*!*/;

# at 21945

#210124 13:09:38 server id 8  end_log_pos 22024 	Query	thread_id=44	exec_time=0	error_code=0

SET TIMESTAMP=1611493778/*!*/;

BEGIN

/*!*/;

# at 22024

#210124 13:09:38 server id 8  end_log_pos 22223

#Begin_load_query: file_id: 17  block_len: 176

# at 22223

#210124 13:09:38 server id 8  end_log_pos 22498 	Execute_load_query	thread_id=44	exec_time=0	error_code=0

SET TIMESTAMP=1611493778/*!*/;

LOAD DATA LOCAL INFILE '/tmp/SQL_LOAD_MB-11-1' INTO TABLE `tpool` FIELDS TERMINATED BY ',' ENCLOSED BY '' ESCAPED BY '\\' LINES TERMINATED BY '\n' (`cid`) SET `countrycode`='IL'

/*!*/;

# file_id: 17

# at 22498

#210124 13:09:38 server id 8  end_log_pos 22578 	Query	thread_id=44	exec_time=0	error_code=0

SET TIMESTAMP=1611493778/*!*/;

COMMIT

/*!*/;

# at 22578

#210124 13:09:38 server id 8  end_log_pos 22642 	Query	thread_id=44	exec_time=0	error_code=0

SET TIMESTAMP=1611493778/*!*/;

BEGIN

/*!*/;

# at 22642

#210124 13:09:38 server id 8  end_log_pos 22760 	Query	thread_id=44	exec_time=0	error_code=0

SET TIMESTAMP=1611493778/*!*/;

delete from cid_stock where countrycode='IL'

/*!*/;

# at 22760

#210124 13:09:38 server id 8  end_log_pos 22787 	Xid = 191

COMMIT/*!*/;

# at 22787

#210124 13:09:38 server id 8  end_log_pos 22851 	Query	thread_id=44	exec_time=0	error_code=0

SET TIMESTAMP=1611493778/*!*/;

BEGIN

/*!*/;

# at 22851

#210124 13:09:38 server id 8  end_log_pos 22989 	Query	thread_id=44	exec_time=0	error_code=0

SET TIMESTAMP=1611493778/*!*/;

insert into cid_stock select * from tpool where countrycode='IL'

/*!*/;

# at 22989

#210124 13:09:38 server id 8  end_log_pos 23016 	Xid = 193

COMMIT/*!*/;

DELIMITER ;

# End of log file

Table structure:

CREATE TABLE `cid_stock` (

  `countrycode` varchar(8) NOT NULL DEFAULT '',

  `cid` varchar(32) NOT NULL DEFAULT '',

  PRIMARY KEY (`countrycode`,`cid`),

  KEY `countrycode` (`countrycode`)

) ENGINE=InnoDB DEFAULT CHARSET=latin1

Example CSV file for the load data infile:

4912399313

4912399314

4912399315

4912399316

4912399317

4912399318

Attachments

Activity

Ascending order - Click to sort in descending order

Elena Stepanova added a comment - 2021-01-24 17:57 - edited

Thanks for the report.

I presume you run the servers with the default values of binlog_format, which would be statement on 5.5 and mixed on 10.3/10.5.
Unfortunately, that's the exact combination which appears to be affected by the bug.

Here is a raw MTR test to demonstrate (MTR sets log_slave_updates itself):

--source include/master-slave.inc

--source include/have_binlog_format_mixed.inc

set binlog_format=statement;

create table t1 (a int);

create temporary table tmp like t1;

--write_file $MYSQLTEST_VARDIR/load_data

EOF

eval load data local infile '$MYSQLTEST_VARDIR/load_data' INTO TABLE tmp;

insert into t1 select * from tmp;

show binlog events;

--sync_slave_with_master

show binlog events;

# cleanup

--connection master

drop table t1;

--source include/rpl_end.inc

--remove_file $MYSQLTEST_VARDIR/load_data

10.2 59e6d14c
connection slave;
show binlog events;
Log_name Pos Event_type Server_id End_log_pos Info
slave-bin.000001 4 Format_desc 2 256 Server ver: 10.2.37-MariaDB-debug-log, Binlog ver: 4
slave-bin.000001 256 Gtid_list 2 285 []
slave-bin.000001 285 Binlog_checkpoint 2 328 slave-bin.000001
slave-bin.000001 328 Gtid 1 370 GTID 0-1-1
slave-bin.000001 370 Query 1 460 use `test`; create table t1 (a int)
slave-bin.000001 460 Gtid 1 502 GTID 0-1-2
slave-bin.000001 502 Query 1 603 use `test`; create temporary table tmp like t1
slave-bin.000001 603 Gtid 1 645 BEGIN GTID 0-1-4
slave-bin.000001 645 Query 1 744 use `test`; insert into t1 select * from tmp
slave-bin.000001 744 Query 1 817 COMMIT

In the test case, have_binlog_format_mixed.inc makes the slave run with the mixed format, while for the master we set statement explicitly within the test. It imitates the default combination of binlog formats which happens naturally in 5.5 => 10.3 replication.

If both the master and the slave were running with statement format, LOAD DATA would be replicated.
If the slave were running with row format, it would skip the temporary table completely and write the row events for INSERT. Same would happen on master if it were running with row format.
If the master were running with mixed format, the use of a temporary table would make it switch to row, and further it would behave as above.

But If the master is running in statement format, it writes the statements unchanged (temporary table, load and insert); and the slave running in mixed format writes some, but not all of it. That's the bug.

It was introduced long time ago, in 10.0.5, my best guess is by this commit

commit 2e100cc5a493b6a0f6f907e0483a734c7fee2087 3784432256a30e4d453dde10c875d8446519e7c1

Date:   Mon Oct 14 00:24:05 2013 +0300

    Fixes for parallel slave:

but I didn't check the guess as I can't build it on my machine.

Elena Stepanova added a comment - 2021-01-24 17:57 - edited Thanks for the report. I presume you run the servers with the default values of binlog_format , which would be statement on 5.5 and mixed on 10.3/10.5. Unfortunately, that's the exact combination which appears to be affected by the bug. Here is a raw MTR test to demonstrate (MTR sets log_slave_updates itself): --source include/master-slave.inc --source include/have_binlog_format_mixed.inc set binlog_format=statement; create table t1 (a int ); create temporary table tmp like t1; --write_file $MYSQLTEST_VARDIR/load_data 1 2 EOF eval load data local infile '$MYSQLTEST_VARDIR/load_data' INTO TABLE tmp; insert into t1 select * from tmp; show binlog events; --sync_slave_with_master show binlog events; # cleanup --connection master drop table t1; --source include/rpl_end.inc --remove_file $MYSQLTEST_VARDIR/load_data 10.2 59e6d14c connection slave; show binlog events; Log_name Pos Event_type Server_id End_log_pos Info slave-bin.000001 4 Format_desc 2 256 Server ver: 10.2.37-MariaDB-debug-log, Binlog ver: 4 slave-bin.000001 256 Gtid_list 2 285 [] slave-bin.000001 285 Binlog_checkpoint 2 328 slave-bin.000001 slave-bin.000001 328 Gtid 1 370 GTID 0-1-1 slave-bin.000001 370 Query 1 460 use `test`; create table t1 (a int) slave-bin.000001 460 Gtid 1 502 GTID 0-1-2 slave-bin.000001 502 Query 1 603 use `test`; create temporary table tmp like t1 slave-bin.000001 603 Gtid 1 645 BEGIN GTID 0-1-4 slave-bin.000001 645 Query 1 744 use `test`; insert into t1 select * from tmp slave-bin.000001 744 Query 1 817 COMMIT In the test case, have_binlog_format_mixed.inc makes the slave run with the mixed format, while for the master we set statement explicitly within the test. It imitates the default combination of binlog formats which happens naturally in 5.5 => 10.3 replication. If both the master and the slave were running with statement format, LOAD DATA would be replicated. If the slave were running with row format, it would skip the temporary table completely and write the row events for INSERT. Same would happen on master if it were running with row format. If the master were running with mixed format, the use of a temporary table would make it switch to row, and further it would behave as above. But If the master is running in statement format, it writes the statements unchanged (temporary table, load and insert); and the slave running in mixed format writes some, but not all of it. That's the bug. It was introduced long time ago, in 10.0.5, my best guess is by this commit commit 2e100cc5a493b6a0f6f907e0483a734c7fee2087 3784432256a30e4d453dde10c875d8446519e7c1 Date: Mon Oct 14 00:24:05 2013 +0300 Fixes for parallel slave: but I didn't check the guess as I can't build it on my machine.

Elena Stepanova added a comment - 2021-01-25 00:37

After some consideration, I've raised the priority. The reason for this is that 10.1 was the last version having binlog_format=STATEMENT by default, 10.2+ have MIXED; and 10.1 has recently EOL-ed, so people should start upgrading more actively. The replication topology in this bug is a core of upgrade-through-replication, thus it can become a fairly common problem.

Elena Stepanova added a comment - 2021-01-25 00:37 After some consideration, I've raised the priority. The reason for this is that 10.1 was the last version having binlog_format=STATEMENT by default, 10.2+ have MIXED; and 10.1 has recently EOL-ed, so people should start upgrading more actively. The replication topology in this bug is a core of upgrade-through-replication, thus it can become a fairly common problem.

Kfir Itzhak added a comment - 2021-01-25 10:22

Hello @Elena Stepanova, thank you for the quick response.

Indeed, i noticed the bug after beginning to upgrade production systems running on CentOS 6 (and few CentOS 7) to CentOS 8 with MariaDB 10.3.27 (from OS repo)
Got complaints about mismatching table, and then eventually setting up this test environment to reproduce and troubleshoot the issue.

I have tested what you said, and it looks like you are correct.

STATEMENT -> STATEMENT:

+------------------+------+--------------------+-----------+-------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

| Log_name         | Pos  | Event_type         | Server_id | End_log_pos | Info                                                                                                                                                                                                                 |

+------------------+------+--------------------+-----------+-------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

| mysql-bin.000010 |  358 | Gtid               |         8 |         400 | GTID 0-8-109                                                                                                                                                                                                         |

| mysql-bin.000010 |  400 | Query              |         8 |         521 | use `dialRoutes`; create temporary table tpool like cid_stock                                                                                                                                                        |

| mysql-bin.000010 |  521 | Gtid               |         8 |         563 | BEGIN GTID 0-8-110                                                                                                                                                                                                   |

| mysql-bin.000010 |  563 | Begin_load_query   |         8 |         766 | ;file_id=1;block_len=176                                                                                                                                                                                             |

| mysql-bin.000010 |  766 | Execute_load_query |         8 |        1040 | use `dialRoutes`; LOAD DATA INFILE '/tmp/SQL_LOAD-130-8-1.data' IGNORE INTO TABLE `tpool` FIELDS TERMINATED BY ',' ENCLOSED BY '' ESCAPED BY '\\' LINES TERMINATED BY '\n' (`cid`) SET `countrycode`='IL' ;file_id=1 |

| mysql-bin.000010 | 1040 | Query              |         8 |        1124 | COMMIT                                                                                                                                                                                                               |

| mysql-bin.000010 | 1124 | Gtid               |         8 |        1166 | BEGIN GTID 0-8-111                                                                                                                                                                                                   |

| mysql-bin.000010 | 1166 | Query              |         8 |        1288 | use `dialRoutes`; delete from cid_stock where countrycode='IL'                                                                                                                                                       |

| mysql-bin.000010 | 1288 | Xid                |         8 |        1319 | COMMIT /* xid=6 */                                                                                                                                                                                                   |

| mysql-bin.000010 | 1319 | Gtid               |         8 |        1361 | BEGIN GTID 0-8-112                                                                                                                                                                                                   |

| mysql-bin.000010 | 1361 | Query              |         8 |        1503 | use `dialRoutes`; insert into cid_stock select * from tpool where countrycode='IL'                                                                                                                                   |

| mysql-bin.000010 | 1503 | Xid                |         8 |        1534 | COMMIT /* xid=8 */                                                                                                                                                                                                   |

| mysql-bin.000010 | 1534 | Gtid               |         8 |        1576 | GTID 0-8-113                                                                                                                                                                                                         |

| mysql-bin.000010 | 1576 | Query              |         8 |        1731 | DROP TEMPORARY TABLE IF EXISTS `dialRoutes`.`tpool` /* generated by server */                                                                                                                                        |

+------------------+------+--------------------+-----------+-------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

STATEMENT -> ROW:

+------------------+------+----------------+-----------+-------------+-------------------------------------+

| Log_name         | Pos  | Event_type     | Server_id | End_log_pos | Info                                |

+------------------+------+----------------+-----------+-------------+-------------------------------------+

| mysql-bin.000011 |  358 | Gtid           |         8 |         400 | BEGIN GTID 0-8-114                  |

| mysql-bin.000011 |  400 | Table_map      |         8 |         463 | table_id: 19 (dialRoutes.cid_stock) |

| mysql-bin.000011 |  463 | Delete_rows_v1 |         8 |         740 | table_id: 19 flags: STMT_END_F      |

| mysql-bin.000011 |  740 | Xid            |         8 |         771 | COMMIT /* xid=9 */                  |

| mysql-bin.000011 |  771 | Gtid           |         8 |         813 | BEGIN GTID 0-8-115                  |

| mysql-bin.000011 |  813 | Table_map      |         8 |         876 | table_id: 19 (dialRoutes.cid_stock) |

| mysql-bin.000011 |  876 | Write_rows_v1  |         8 |        1153 | table_id: 19 flags: STMT_END_F      |

| mysql-bin.000011 | 1153 | Xid            |         8 |        1184 | COMMIT /* xid=11 */                 |

+------------------+------+----------------+-----------+-------------+-------------------------------------+

STATEMENT -> MIXED:

+------------------+-----+------------+-----------+-------------+------------------------------------------------------------------------------------+

| Log_name         | Pos | Event_type | Server_id | End_log_pos | Info                                                                               |

+------------------+-----+------------+-----------+-------------+------------------------------------------------------------------------------------+

| mysql-bin.000012 | 358 | Gtid       |         8 |         400 | GTID 0-8-116                                                                       |

| mysql-bin.000012 | 400 | Query      |         8 |         521 | use `dialRoutes`; create temporary table tpool like cid_stock                      |

| mysql-bin.000012 | 521 | Gtid       |         8 |         563 | BEGIN GTID 0-8-117                                                                 |

| mysql-bin.000012 | 563 | Query      |         8 |         685 | use `dialRoutes`; delete from cid_stock where countrycode='IL'                     |

| mysql-bin.000012 | 685 | Xid        |         8 |         716 | COMMIT /* xid=7 */                                                                 |

| mysql-bin.000012 | 716 | Gtid       |         8 |         758 | BEGIN GTID 0-8-118                                                                 |

| mysql-bin.000012 | 758 | Query      |         8 |         900 | use `dialRoutes`; insert into cid_stock select * from tpool where countrycode='IL' |

| mysql-bin.000012 | 900 | Xid        |         8 |         931 | COMMIT /* xid=9 */                                                                 |

| mysql-bin.000012 | 931 | Gtid       |         8 |         973 | GTID 0-8-119                                                                       |

| mysql-bin.000012 | 973 | Query      |         8 |        1128 | DROP TEMPORARY TABLE IF EXISTS `dialRoutes`.`tpool` /* generated by server */      |

+------------------+-----+------------+-----------+-------------+------------------------------------------------------------------------------------+

MIXED -> MIXED:

+------------------+------+----------------+-----------+-------------+-------------------------------------------------------------------------------+

| Log_name         | Pos  | Event_type     | Server_id | End_log_pos | Info                                                                          |

+------------------+------+----------------+-----------+-------------+-------------------------------------------------------------------------------+

| mysql-bin.000009 |  358 | Gtid           |         8 |         400 | GTID 0-8-105                                                                  |

| mysql-bin.000009 |  400 | Query          |         8 |         521 | use `dialRoutes`; create temporary table tpool like cid_stock                 |

| mysql-bin.000009 |  521 | Gtid           |         8 |         563 | BEGIN GTID 0-8-106                                                            |

| mysql-bin.000009 |  563 | Table_map      |         8 |         626 | table_id: 19 (dialRoutes.cid_stock)                                           |

| mysql-bin.000009 |  626 | Delete_rows_v1 |         8 |         903 | table_id: 19 flags: STMT_END_F                                                |

| mysql-bin.000009 |  903 | Xid            |         8 |         934 | COMMIT /* xid=5 */                                                            |

| mysql-bin.000009 |  934 | Gtid           |         8 |         976 | BEGIN GTID 0-8-107                                                            |

| mysql-bin.000009 |  976 | Table_map      |         8 |        1039 | table_id: 19 (dialRoutes.cid_stock)                                           |

| mysql-bin.000009 | 1039 | Write_rows_v1  |         8 |        1316 | table_id: 19 flags: STMT_END_F                                                |

| mysql-bin.000009 | 1316 | Xid            |         8 |        1347 | COMMIT /* xid=7 */                                                            |

| mysql-bin.000009 | 1347 | Gtid           |         8 |        1389 | GTID 0-8-108                                                                  |

| mysql-bin.000009 | 1389 | Query          |         8 |        1544 | DROP TEMPORARY TABLE IF EXISTS `dialRoutes`.`tpool` /* generated by server */ |

+------------------+------+----------------+-----------+-------------+-------------------------------------------------------------------------------+

Thank you.

Kfir Itzhak added a comment - 2021-01-25 10:22 Hello @Elena Stepanova, thank you for the quick response. Indeed, i noticed the bug after beginning to upgrade production systems running on CentOS 6 (and few CentOS 7) to CentOS 8 with MariaDB 10.3.27 (from OS repo) Got complaints about mismatching table, and then eventually setting up this test environment to reproduce and troubleshoot the issue. I have tested what you said, and it looks like you are correct. STATEMENT -> STATEMENT: + ------------------+------+--------------------+-----------+-------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | Log_name | Pos | Event_type | Server_id | End_log_pos | Info | + ------------------+------+--------------------+-----------+-------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | mysql-bin.000010 | 358 | Gtid | 8 | 400 | GTID 0-8-109 | | mysql-bin.000010 | 400 | Query | 8 | 521 | use `dialRoutes`; create temporary table tpool like cid_stock | | mysql-bin.000010 | 521 | Gtid | 8 | 563 | BEGIN GTID 0-8-110 | | mysql-bin.000010 | 563 | Begin_load_query | 8 | 766 | ;file_id=1;block_len=176 | | mysql-bin.000010 | 766 | Execute_load_query | 8 | 1040 | use `dialRoutes`; LOAD DATA INFILE '/tmp/SQL_LOAD-130-8-1.data' IGNORE INTO TABLE `tpool` FIELDS TERMINATED BY ',' ENCLOSED BY '' ESCAPED BY '\\' LINES TERMINATED BY '\n' (`cid`) SET `countrycode`= 'IL' ;file_id=1 | | mysql-bin.000010 | 1040 | Query | 8 | 1124 | COMMIT | | mysql-bin.000010 | 1124 | Gtid | 8 | 1166 | BEGIN GTID 0-8-111 | | mysql-bin.000010 | 1166 | Query | 8 | 1288 | use `dialRoutes`; delete from cid_stock where countrycode= 'IL' | | mysql-bin.000010 | 1288 | Xid | 8 | 1319 | COMMIT /* xid=6 */ | | mysql-bin.000010 | 1319 | Gtid | 8 | 1361 | BEGIN GTID 0-8-112 | | mysql-bin.000010 | 1361 | Query | 8 | 1503 | use `dialRoutes`; insert into cid_stock select * from tpool where countrycode= 'IL' | | mysql-bin.000010 | 1503 | Xid | 8 | 1534 | COMMIT /* xid=8 */ | | mysql-bin.000010 | 1534 | Gtid | 8 | 1576 | GTID 0-8-113 | | mysql-bin.000010 | 1576 | Query | 8 | 1731 | DROP TEMPORARY TABLE IF EXISTS `dialRoutes`.`tpool` /* generated by server */ | + ------------------+------+--------------------+-----------+-------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ STATEMENT -> ROW: + ------------------+------+----------------+-----------+-------------+-------------------------------------+ | Log_name | Pos | Event_type | Server_id | End_log_pos | Info | + ------------------+------+----------------+-----------+-------------+-------------------------------------+ | mysql-bin.000011 | 358 | Gtid | 8 | 400 | BEGIN GTID 0-8-114 | | mysql-bin.000011 | 400 | Table_map | 8 | 463 | table_id: 19 (dialRoutes.cid_stock) | | mysql-bin.000011 | 463 | Delete_rows_v1 | 8 | 740 | table_id: 19 flags: STMT_END_F | | mysql-bin.000011 | 740 | Xid | 8 | 771 | COMMIT /* xid=9 */ | | mysql-bin.000011 | 771 | Gtid | 8 | 813 | BEGIN GTID 0-8-115 | | mysql-bin.000011 | 813 | Table_map | 8 | 876 | table_id: 19 (dialRoutes.cid_stock) | | mysql-bin.000011 | 876 | Write_rows_v1 | 8 | 1153 | table_id: 19 flags: STMT_END_F | | mysql-bin.000011 | 1153 | Xid | 8 | 1184 | COMMIT /* xid=11 */ | + ------------------+------+----------------+-----------+-------------+-------------------------------------+ STATEMENT -> MIXED: + ------------------+-----+------------+-----------+-------------+------------------------------------------------------------------------------------+ | Log_name | Pos | Event_type | Server_id | End_log_pos | Info | + ------------------+-----+------------+-----------+-------------+------------------------------------------------------------------------------------+ | mysql-bin.000012 | 358 | Gtid | 8 | 400 | GTID 0-8-116 | | mysql-bin.000012 | 400 | Query | 8 | 521 | use `dialRoutes`; create temporary table tpool like cid_stock | | mysql-bin.000012 | 521 | Gtid | 8 | 563 | BEGIN GTID 0-8-117 | | mysql-bin.000012 | 563 | Query | 8 | 685 | use `dialRoutes`; delete from cid_stock where countrycode= 'IL' | | mysql-bin.000012 | 685 | Xid | 8 | 716 | COMMIT /* xid=7 */ | | mysql-bin.000012 | 716 | Gtid | 8 | 758 | BEGIN GTID 0-8-118 | | mysql-bin.000012 | 758 | Query | 8 | 900 | use `dialRoutes`; insert into cid_stock select * from tpool where countrycode= 'IL' | | mysql-bin.000012 | 900 | Xid | 8 | 931 | COMMIT /* xid=9 */ | | mysql-bin.000012 | 931 | Gtid | 8 | 973 | GTID 0-8-119 | | mysql-bin.000012 | 973 | Query | 8 | 1128 | DROP TEMPORARY TABLE IF EXISTS `dialRoutes`.`tpool` /* generated by server */ | + ------------------+-----+------------+-----------+-------------+------------------------------------------------------------------------------------+ MIXED -> MIXED: + ------------------+------+----------------+-----------+-------------+-------------------------------------------------------------------------------+ | Log_name | Pos | Event_type | Server_id | End_log_pos | Info | + ------------------+------+----------------+-----------+-------------+-------------------------------------------------------------------------------+ | mysql-bin.000009 | 358 | Gtid | 8 | 400 | GTID 0-8-105 | | mysql-bin.000009 | 400 | Query | 8 | 521 | use `dialRoutes`; create temporary table tpool like cid_stock | | mysql-bin.000009 | 521 | Gtid | 8 | 563 | BEGIN GTID 0-8-106 | | mysql-bin.000009 | 563 | Table_map | 8 | 626 | table_id: 19 (dialRoutes.cid_stock) | | mysql-bin.000009 | 626 | Delete_rows_v1 | 8 | 903 | table_id: 19 flags: STMT_END_F | | mysql-bin.000009 | 903 | Xid | 8 | 934 | COMMIT /* xid=5 */ | | mysql-bin.000009 | 934 | Gtid | 8 | 976 | BEGIN GTID 0-8-107 | | mysql-bin.000009 | 976 | Table_map | 8 | 1039 | table_id: 19 (dialRoutes.cid_stock) | | mysql-bin.000009 | 1039 | Write_rows_v1 | 8 | 1316 | table_id: 19 flags: STMT_END_F | | mysql-bin.000009 | 1316 | Xid | 8 | 1347 | COMMIT /* xid=7 */ | | mysql-bin.000009 | 1347 | Gtid | 8 | 1389 | GTID 0-8-108 | | mysql-bin.000009 | 1389 | Query | 8 | 1544 | DROP TEMPORARY TABLE IF EXISTS `dialRoutes`.`tpool` /* generated by server */ | + ------------------+------+----------------+-----------+-------------+-------------------------------------------------------------------------------+ Thank you.

Sachin Setiya (Inactive) added a comment - 2021-05-04 16:00

Analysis :-
(Assuming master have stmt format and slave mixed format, And test case provided by elena)

On Master:- We are sent data into stmt format (We are already hitting https://bugs.mysql.com/bug.php?id=34283)

On Slave:- We have mixed format so because of https://bugs.mysql.com/bug.php?id=34283 we will shift the binlog format to rows.
Since it is temp table it will not be written into binlog. Rest of the statements are safe so they will be written in stmt format.
So that is we have issue of different master slave binlogs

Possible Solution:-
1. https://bugs.mysql.com/bug.php?id=34283 to me this fix does not seem correct (It is based on assumption that statement format will be deprecated ), But so far it has not happened , So one way would be to implement 34283 differently

2. easy solution, Slave anyways follows the master binlog format(for log_slave_updates)

diff --git a/sql/sql_load.cc b/sql/sql_load.cc

index 09af120e6cf..255ab416935 100644

--- a/sql/sql_load.cc

+++ b/sql/sql_load.cc

@@ -380,7 +380,8 @@ int mysql_load(THD *thd, const sql_exchange *ex, TABLE_LIST *table_list,

     load data infile, so in mixed mode we go to row-based for

     avoiding the problem.

*/

-  thd->set_current_stmt_binlog_format_row_if_mixed();

+  if(!thd->slave_thread)

+    thd->set_current_stmt_binlog_format_row_if_mixed();

 #ifdef EMBEDDED_LIBRARY

   read_file_from_client  = 0; //server is always in the same process

if we are on slave thread we will not change the binlog format. One side effect would be that we have a tmp file to worry about on slave(34283), But master also have the same tmp file.

Sachin Setiya (Inactive) added a comment - 2021-05-04 16:00 Analysis :- (Assuming master have stmt format and slave mixed format, And test case provided by elena) On Master:- We are sent data into stmt format (We are already hitting https://bugs.mysql.com/bug.php?id=34283 ) On Slave:- We have mixed format so because of https://bugs.mysql.com/bug.php?id=34283 we will shift the binlog format to rows. Since it is temp table it will not be written into binlog. Rest of the statements are safe so they will be written in stmt format. So that is we have issue of different master slave binlogs Possible Solution:- 1. https://bugs.mysql.com/bug.php?id=34283 to me this fix does not seem correct (It is based on assumption that statement format will be deprecated ), But so far it has not happened , So one way would be to implement 34283 differently 2. easy solution, Slave anyways follows the master binlog format(for log_slave_updates) diff --git a/sql/sql_load.cc b/sql/sql_load.cc index 09af120e6cf..255ab416935 100644 --- a/sql/sql_load.cc +++ b/sql/sql_load.cc @@ -380,7 +380,8 @@ int mysql_load(THD *thd, const sql_exchange *ex, TABLE_LIST *table_list, load data infile, so in mixed mode we go to row-based for avoiding the problem. */ - thd->set_current_stmt_binlog_format_row_if_mixed(); + if(!thd->slave_thread) + thd->set_current_stmt_binlog_format_row_if_mixed(); #ifdef EMBEDDED_LIBRARY read_file_from_client = 0; //server is always in the same process if we are on slave thread we will not change the binlog format. One side effect would be that we have a tmp file to worry about on slave(34283), But master also have the same tmp file.

Andrei Elkin added a comment - 2021-05-14 17:45 - edited

My verification confirms nicely structured (thanks, mastertheknife) https://jira.mariadb.org/browse/MDEV-24667?focusedCommentId=178177&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-178177. In M(STATEMENT) -> S(MIXED), slave loses in its binary log LOAD DATA for tmp or its effect to insert into t1 select * from tmp.
The M(MIXED) behaves correctly. So the problem must be in execution of INSERT-SELECT query by S(MIXED) which must
follow the master pattern, that is to produce ROWs format events, not reproduce the Query_log_event, sachin.setiya.007.
That is the fixes must make sure MIXED picks INSERT..SELECT ROW format-binlogging on the very same background as master does.

Andrei Elkin added a comment - 2021-05-14 17:45 - edited My verification confirms nicely structured (thanks, mastertheknife ) https://jira.mariadb.org/browse/MDEV-24667?focusedCommentId=178177&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-178177 . In M(STATEMENT) -> S(MIXED), slave loses in its binary log LOAD DATA for tmp or its effect to insert into t1 select * from tmp . The M(MIXED) behaves correctly. So the problem must be in execution of INSERT-SELECT query by S(MIXED) which must follow the master pattern, that is to produce ROWs format events, not reproduce the Query_log_event, sachin.setiya.007 . That is the fixes must make sure MIXED picks INSERT..SELECT ROW format-binlogging on the very same background as master does.

Sachin Setiya (Inactive) added a comment - 2021-05-26 13:55

Few Observations:-
So in master in Mixed format if we get a tmp table we change the binlog format to row , till tmp table is dropped
So on master THD::reset_for_next_command() , calls this function , reset_current_stmt_binlog_format_row
this checks if thd->temporary_tables is true or not, If it is true it skips the rest to the statement , And whole session binlog format will remain row till tmp table is dropped

But on slave , temporary table are stored in rgi_slave->rli->save_temporary_tables , not in the thd->temporray_tables
So this cause slave to shift back to stmt format , And then this insert into t1 select * from tmp is logged into the stmt format
since tmp table is empty , we have a data loss

I tried Some another case to simulate the same bug , where we get binlog loss on slave , without using infile

--source include/have_binlog_format_mixed.inc

--source include/master-slave.inc

--connection master

set binlog_format=statement;

create table t1 (a int);

insert into t1 values(10);

create temporary table tmp like t1;

insert into tmp values(10);

update tmp set a = 20 limit 1;

insert into t1 select * from tmp;

show binlog events;

select * from t1;

--sync_slave_with_master

#insert into t1 values(30);

show binlog events;

select * from t1;

# cleanup

--connection master

drop table t1, tmp;

--source include/rpl_end.inc

And if we look at the result

Logging: ./mtr  mdev_24667_2

vardir: /home/sachin/10.2/mysql-test/var

Checking leftover processes...

Removing old var directory...

Creating var directory '/home/sachin/10.2/mysql-test/var'...

Checking supported features...

MariaDB Version 10.2.39-MariaDB

 - SSL connections supported

 - binaries built with wsrep patch

Collecting tests...

Installing system database...

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT

--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019

include/master-slave.inc

[connection master]

connection master;

set binlog_format=statement;

create table t1 (a int);

insert into t1 values(10);

create temporary table tmp like t1;

insert into tmp values(10);

update tmp set a = 20 limit 1;

Warnings:

Note	1592	Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. The statement is unsafe because it uses a LIMIT clause. This is unsafe because the set of rows included cannot be predicted

insert into t1 select * from tmp;

show binlog events;

Log_name	Pos	Event_type	Server_id	End_log_pos	Info

master-bin.000001	4	Format_desc	1	256	Server ver: 10.2.39-MariaDB-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	461	use `test`; create table t1 (a int)

master-bin.000001	461	Gtid	1	503	BEGIN GTID 0-1-2

master-bin.000001	503	Query	1	595	use `test`; insert into t1 values(10)

master-bin.000001	595	Query	1	668	COMMIT

master-bin.000001	668	Gtid	1	710	GTID 0-1-3

master-bin.000001	710	Query	1	811	use `test`; create temporary table tmp like t1

master-bin.000001	811	Gtid	1	853	BEGIN GTID 0-1-4

master-bin.000001	853	Query	1	946	use `test`; insert into tmp values(10)

master-bin.000001	946	Query	1	1019	COMMIT

master-bin.000001	1019	Gtid	1	1061	BEGIN GTID 0-1-5

master-bin.000001	1061	Query	1	1157	use `test`; update tmp set a = 20 limit 1

master-bin.000001	1157	Query	1	1230	COMMIT

master-bin.000001	1230	Gtid	1	1272	BEGIN GTID 0-1-6

master-bin.000001	1272	Query	1	1371	use `test`; insert into t1 select * from tmp

master-bin.000001	1371	Query	1	1444	COMMIT

select * from t1;

connection slave;

show binlog events;

Log_name	Pos	Event_type	Server_id	End_log_pos	Info

slave-bin.000001	4	Format_desc	2	256	Server ver: 10.2.39-MariaDB-log, Binlog ver: 4

slave-bin.000001	256	Gtid_list	2	285	[]

slave-bin.000001	285	Binlog_checkpoint	2	328	slave-bin.000001

slave-bin.000001	328	Gtid	1	370	GTID 0-1-1

slave-bin.000001	370	Query	1	460	use `test`; create table t1 (a int)

slave-bin.000001	460	Gtid	1	502	BEGIN GTID 0-1-2

slave-bin.000001	502	Query	1	594	use `test`; insert into t1 values(10)

slave-bin.000001	594	Query	1	667	COMMIT

slave-bin.000001	667	Gtid	1	709	GTID 0-1-3

slave-bin.000001	709	Query	1	810	use `test`; create temporary table tmp like t1

slave-bin.000001	810	Gtid	1	852	BEGIN GTID 0-1-4

slave-bin.000001	852	Query	1	945	use `test`; insert into tmp values(10)

slave-bin.000001	945	Query	1	1018	COMMIT

slave-bin.000001	1018	Gtid	1	1060	BEGIN GTID 0-1-6

slave-bin.000001	1060	Query	1	1159	use `test`; insert into t1 select * from tmp

slave-bin.000001	1159	Query	1	1232	COMMIT

select * from t1;

connection master;

drop table t1, tmp;

include/rpl_end.inc

rpl.mdev_24667_2 'mix'                   [ fail ]  Found warnings/errors in server log file!

        Test ended at 2021-05-26 14:51:39

line

2021-05-26 14:51:38 139903397185088 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. The statement is unsafe because it uses a LIMIT clause. This is unsafe because the set of rows included cannot be predicted Statement: update tmp set a = 20 limit 1

^ Found warnings in /home/sachin/10.2/mysql-test/var/log/mysqld.1.err

ok

 - saving '/home/sachin/10.2/mysql-test/var/log/rpl.mdev_24667_2-mix/' to '/home/sachin/10.2/mysql-test/var/log/rpl.mdev_24667_2-mix/'

--------------------------------------------------------------------------

The servers were restarted 0 times

Spent 0.000 of 5 seconds executing testcases

Failure: Failed 1/1 tests, 0.00% were successful.

Failing test(s): rpl.mdev_24667_2

The log files in var/log may give you some hint of what went wrong.

If you want to report this error, please read first the documentation

at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html

I am using this statement update tmp set a = 20 limit 1; which is unsafe
And on the slave binlog we can see that GTID 0-1-5 is lost (edited)

Sachin Setiya (Inactive) added a comment - 2021-05-26 13:55 Few Observations:- So in master in Mixed format if we get a tmp table we change the binlog format to row , till tmp table is dropped So on master THD::reset_for_next_command() , calls this function , reset_current_stmt_binlog_format_row this checks if thd->temporary_tables is true or not, If it is true it skips the rest to the statement , And whole session binlog format will remain row till tmp table is dropped But on slave , temporary table are stored in rgi_slave->rli->save_temporary_tables , not in the thd->temporray_tables So this cause slave to shift back to stmt format , And then this insert into t1 select * from tmp is logged into the stmt format since tmp table is empty , we have a data loss I tried Some another case to simulate the same bug , where we get binlog loss on slave , without using infile --source include/have_binlog_format_mixed.inc --source include/master-slave.inc --connection master set binlog_format=statement; create table t1 (a int); insert into t1 values(10); create temporary table tmp like t1; insert into tmp values(10); update tmp set a = 20 limit 1; insert into t1 select * from tmp; show binlog events; select * from t1; --sync_slave_with_master #insert into t1 values(30); show binlog events; select * from t1; # cleanup --connection master drop table t1, tmp; --source include/rpl_end.inc And if we look at the result Logging: ./mtr mdev_24667_2 vardir: /home/sachin/10.2/mysql-test/var Checking leftover processes... Removing old var directory... Creating var directory '/home/sachin/10.2/mysql-test/var'... Checking supported features... MariaDB Version 10.2.39-MariaDB - SSL connections supported - binaries built with wsrep patch Collecting tests... Installing system database... ============================================================================== TEST RESULT TIME (ms) or COMMENT -------------------------------------------------------------------------- worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019 include/master-slave.inc [connection master] connection master; set binlog_format=statement; create table t1 (a int); insert into t1 values(10); create temporary table tmp like t1; insert into tmp values(10); update tmp set a = 20 limit 1; Warnings: Note 1592 Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. The statement is unsafe because it uses a LIMIT clause. This is unsafe because the set of rows included cannot be predicted insert into t1 select * from tmp; show binlog events; Log_name Pos Event_type Server_id End_log_pos Info master-bin.000001 4 Format_desc 1 256 Server ver: 10.2.39-MariaDB-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 461 use `test`; create table t1 (a int) master-bin.000001 461 Gtid 1 503 BEGIN GTID 0-1-2 master-bin.000001 503 Query 1 595 use `test`; insert into t1 values(10) master-bin.000001 595 Query 1 668 COMMIT master-bin.000001 668 Gtid 1 710 GTID 0-1-3 master-bin.000001 710 Query 1 811 use `test`; create temporary table tmp like t1 master-bin.000001 811 Gtid 1 853 BEGIN GTID 0-1-4 master-bin.000001 853 Query 1 946 use `test`; insert into tmp values(10) master-bin.000001 946 Query 1 1019 COMMIT master-bin.000001 1019 Gtid 1 1061 BEGIN GTID 0-1-5 master-bin.000001 1061 Query 1 1157 use `test`; update tmp set a = 20 limit 1 master-bin.000001 1157 Query 1 1230 COMMIT master-bin.000001 1230 Gtid 1 1272 BEGIN GTID 0-1-6 master-bin.000001 1272 Query 1 1371 use `test`; insert into t1 select * from tmp master-bin.000001 1371 Query 1 1444 COMMIT select * from t1; a 10 20 connection slave; show binlog events; Log_name Pos Event_type Server_id End_log_pos Info slave-bin.000001 4 Format_desc 2 256 Server ver: 10.2.39-MariaDB-log, Binlog ver: 4 slave-bin.000001 256 Gtid_list 2 285 [] slave-bin.000001 285 Binlog_checkpoint 2 328 slave-bin.000001 slave-bin.000001 328 Gtid 1 370 GTID 0-1-1 slave-bin.000001 370 Query 1 460 use `test`; create table t1 (a int) slave-bin.000001 460 Gtid 1 502 BEGIN GTID 0-1-2 slave-bin.000001 502 Query 1 594 use `test`; insert into t1 values(10) slave-bin.000001 594 Query 1 667 COMMIT slave-bin.000001 667 Gtid 1 709 GTID 0-1-3 slave-bin.000001 709 Query 1 810 use `test`; create temporary table tmp like t1 slave-bin.000001 810 Gtid 1 852 BEGIN GTID 0-1-4 slave-bin.000001 852 Query 1 945 use `test`; insert into tmp values(10) slave-bin.000001 945 Query 1 1018 COMMIT slave-bin.000001 1018 Gtid 1 1060 BEGIN GTID 0-1-6 slave-bin.000001 1060 Query 1 1159 use `test`; insert into t1 select * from tmp slave-bin.000001 1159 Query 1 1232 COMMIT select * from t1; a 10 20 connection master; drop table t1, tmp; include/rpl_end.inc rpl.mdev_24667_2 'mix' [ fail ] Found warnings/errors in server log file! Test ended at 2021-05-26 14:51:39 line 2021-05-26 14:51:38 139903397185088 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. The statement is unsafe because it uses a LIMIT clause. This is unsafe because the set of rows included cannot be predicted Statement: update tmp set a = 20 limit 1 ^ Found warnings in /home/sachin/10.2/mysql-test/var/log/mysqld.1.err ok - saving '/home/sachin/10.2/mysql-test/var/log/rpl.mdev_24667_2-mix/' to '/home/sachin/10.2/mysql-test/var/log/rpl.mdev_24667_2-mix/' -------------------------------------------------------------------------- The servers were restarted 0 times Spent 0.000 of 5 seconds executing testcases Failure: Failed 1/1 tests, 0.00% were successful. Failing test(s): rpl.mdev_24667_2 The log files in var/log may give you some hint of what went wrong. If you want to report this error, please read first the documentation at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html I am using this statement update tmp set a = 20 limit 1; which is unsafe And on the slave binlog we can see that GTID 0-1-5 is lost (edited)

Sachin Setiya (Inactive) added a comment - 2021-05-27 05:37

Patch branch bb-10.2-24667

Sachin Setiya (Inactive) added a comment - 2021-05-27 05:37 Patch branch bb-10.2-24667

People

Assignee:: Andrei Elkin

Reporter:: Kfir Itzhak

Votes:: 0 Vote for this issue

Watchers:: 5 Start watching this issue

Dates

Created:: 2021-01-24 12:58

Updated:: 2022-03-29 12:30

Resolved:: 2022-03-29 12:30

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server