Bug #96089 row based replication ignores replicate_wild_ignore_table setting
Submitted: 4 Jul 2019 7:01 Modified: 12 Aug 2019 5:12
Reporter: ricky leung Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:5.5.62 OS:Any
Assigned to: Bogdan Kecman CPU Architecture:Any

[4 Jul 2019 7:01] ricky leung
Description:
In a master/slave replication setup, inserting into an updateable view with "on duplicate key update" directive causes the row to be replicated to the slave, even if the view is specified in the "replicate_wild_ignore_table" setting.

I can work around this by setting binlog_format to STATEMENT, but this breaks down some other application logic.  Forcing a SBR in this case is also not desirable I believe.

Upon examining the binary log I found that when the statement is encountered it is deemed unsafe so it was changed to a RBR on the fly, but the underlying table reference was used instead of the originally intended view.  This is not expected.

How to repeat:
Schema in both master and slave:

use defdb;

CREATE TABLE `t` (
  `ID` int(11) NOT NULL AUTO_INCREMENT,
  `NAME` varchar(10) NOT NULL,
  `STR` varchar(20) DEFAULT NULL,
  PRIMARY KEY (`ID`),
  UNIQUE KEY `NAME` (`NAME`)
) ENGINE=InnoDB;

create view view_t as select * from t;

my.cnf:
binlog_format = MIXED
replicate-do-db=defdb
replicate-wild-ignore-table=defdb.view_%

How to repeat:

On master, execute:
insert into view_t(name,str) values ('3','3') on duplicate key update name=values(name),str=values(str);

This row is replicated to the slave, even if the replication is meant to be ignored by "replicate-wild-ignore-table"

Suggested fix:
When switched to an RBR, use the original table or view reference, so that the replication setting of replicate-wild-ignore-table is observed.
[4 Jul 2019 15:17] Bogdan Kecman
master [localhost:20617] {msandbox} ((none)) > use defdb;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
master [localhost:20617] {msandbox} (defdb) > insert into view_t(name,str) values ('3','3') on duplicate key update name=values(name),str=values(str);
Query OK, 1 row affected (0.01 sec)

master [localhost:20617] {msandbox} (defdb) > \q
Bye
1442:master bk$ cd ..
1442:rsandbox_8_0_16 bk$ ./s1 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 13
Server version: 8.0.16 MySQL Community Server - GPL

Copyright (c) 2000, 2019, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

slave1 [localhost:20618] {msandbox} ((none)) > use defdb;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
slave1 [localhost:20618] {msandbox} (defdb) > select * from t;
+----+------+------+
| ID | NAME | STR  |
+----+------+------+
|  1 | 3    | 3    |
+----+------+------+
1 row in set (0.00 sec)

slave1 [localhost:20618] {msandbox} (defdb) >
[4 Jul 2019 15:18] Bogdan Kecman
1442:master bk$ ./my sqlbinlog data/mysql-bin.000002 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#190704 17:10:49 server id 100  end_log_pos 124 CRC32 0x058b662e 	Start: binlog v 4, server v 8.0.16 created 190704 17:10:49 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
+RYeXQ9kAAAAeAAAAHwAAAABAAQAOC4wLjE2AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAD5Fh5dEwANAAgAAAAABAAEAAAAYAAEGggAAAAICAgCAAAACgoKKioAEjQA
CgEuZosF
'/*!*/;
# at 124
#190704 17:10:49 server id 100  end_log_pos 155 CRC32 0x7ffe8bb2 	Previous-GTIDs
# [empty]
# at 155
#190704 17:11:24 server id 100  end_log_pos 234 CRC32 0xe288c93e 	Anonymous_GTID	last_committed=0	sequence_number=1	rbr_only=yes	original_committed_timestamp=1562253084492538	immediate_commit_timestamp=1562253084492538	transaction_length=289
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1562253084492538 (2019-07-04 17:11:24.492538 CEST)
# immediate_commit_timestamp=1562253084492538 (2019-07-04 17:11:24.492538 CEST)
/*!80001 SET @@session.original_commit_timestamp=1562253084492538*//*!*/;
/*!80014 SET @@session.original_server_version=80016*//*!*/;
/*!80014 SET @@session.immediate_server_version=80016*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 234
#190704 17:11:24 server id 100  end_log_pos 310 CRC32 0x50497d53 	Query	thread_id=8	exec_time=0	error_code=0
SET TIMESTAMP=1562253084/*!*/;
SET @@session.pseudo_thread_id=8/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 310
#190704 17:11:24 server id 100  end_log_pos 369 CRC32 0xe8094393 	Table_map: `defdb`.`t` mapped to number 85
# at 369
#190704 17:11:24 server id 100  end_log_pos 413 CRC32 0x41042b32 	Write_rows: table id 85 flags: STMT_END_F

BINLOG '
HBceXRNkAAAAOwAAAHEBAAAAAFUAAAAAAAEABWRlZmRiAAF0AAMDDw8EKABQAAQBAQACA/z/AJND
Ceg=
HBceXR5kAAAALAAAAJ0BAAAAAFUAAAAAAAEAAgAD/wABAAAAATMBMzIrBEE=
'/*!*/;
# at 413
#190704 17:11:24 server id 100  end_log_pos 444 CRC32 0xac705dd6 	Xid = 11
COMMIT/*!*/;
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*/;
1442:master bk$
[4 Jul 2019 15:19] Bogdan Kecman
BEGIN
/*!*/;
# at 310
#190704 17:11:24 server id 100  end_log_pos 369 CRC32 0xe8094393 	Table_map: `defdb`.`t` mapped to number 85
# at 369
#190704 17:11:24 server id 100  end_log_pos 413 CRC32 0x41042b32 	Write_rows: table id 85 flags: STMT_END_F

BINLOG '
HBceXRNkAAAAOwAAAHEBAAAAAFUAAAAAAAEABWRlZmRiAAF0AAMDDw8EKABQAAQBAQACA/z/AJND
Ceg=
HBceXR5kAAAALAAAAJ0BAAAAAFUAAAAAAAEAAgAD/wABAAAAATMBMzIrBEE=
'/*!*/;
### INSERT INTO `defdb`.`t`
### SET
###   @1=1 /* INT meta=0 nullable=0 is_null=0 */
###   @2='3' /* VARSTRING(40) meta=40 nullable=0 is_null=0 */
###   @3='3' /* VARSTRING(80) meta=80 nullable=1 is_null=0 */
# at 413
#190704 17:11:24 server id 100  end_log_pos 444 CRC32 0xac705dd6 	Xid = 11
COMMIT/*!*/;
[4 Jul 2019 15:23] Bogdan Kecman
switched to statement

master [localhost:20617] {msandbox} (defdb) > select @@version, @@binlog_format;
+-----------+-----------------+
| @@version | @@binlog_format |
+-----------+-----------------+
| 8.0.16    | STATEMENT       |
+-----------+-----------------+
1 row in set (0.00 sec)

master [localhost:20617] {msandbox} (defdb) > insert into view_t(name,str) values ('4','4') on duplicate key update name=values(name),str=values(str);
Query OK, 1 row affected, 1 warning (0.01 sec)

master [localhost:20617] {msandbox} (defdb) > \q
Bye
1442:master bk$ ../s1 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 14
Server version: 8.0.16 MySQL Community Server - GPL

Copyright (c) 2000, 2019, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

slave1 [localhost:20618] {msandbox} ((none)) > use defdb;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
slave1 [localhost:20618] {msandbox} (defdb) > select * from t;
+----+------+------+
| ID | NAME | STR  |
+----+------+------+
|  1 | 3    | 3    |
|  2 | 4    | 4    |
+----+------+------+
2 rows in set (0.00 sec)

slave1 [localhost:20618] {msandbox} (defdb) >
[4 Jul 2019 15:24] Bogdan Kecman
1442:master bk$ ./my sqlbinlog -v --verbose data/mysql-bin.000003
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#190704 17:21:08 server id 100  end_log_pos 124 CRC32 0x90b542f3 	Start: binlog v 4, server v 8.0.16 created 190704 17:21:08 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
ZBkeXQ9kAAAAeAAAAHwAAAABAAQAOC4wLjE2AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAABkGR5dEwANAAgAAAAABAAEAAAAYAAEGggAAAAICAgCAAAACgoKKioAEjQA
CgHzQrWQ
'/*!*/;
# at 124
#190704 17:21:08 server id 100  end_log_pos 155 CRC32 0xff198098 	Previous-GTIDs
# [empty]
# at 155
#190704 17:21:59 server id 100  end_log_pos 234 CRC32 0xd0ac7de3 	Anonymous_GTID	last_committed=0	sequence_number=1	rbr_only=no	original_committed_timestamp=1562253719040799	immediate_commit_timestamp=1562253719040799	transaction_length=408
# original_commit_timestamp=1562253719040799 (2019-07-04 17:21:59.040799 CEST)
# immediate_commit_timestamp=1562253719040799 (2019-07-04 17:21:59.040799 CEST)
/*!80001 SET @@session.original_commit_timestamp=1562253719040799*//*!*/;
/*!80014 SET @@session.original_server_version=80016*//*!*/;
/*!80014 SET @@session.immediate_server_version=80016*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 234
#190704 17:21:59 server id 100  end_log_pos 318 CRC32 0xca22a7c2 	Query	thread_id=8	exec_time=0	error_code=0
SET TIMESTAMP=1562253719/*!*/;
SET @@session.pseudo_thread_id=8/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1168113696/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
/*!80011 SET @@session.default_collation_for_utf8mb4=255*//*!*/;
BEGIN
/*!*/;
# at 318
# at 350
#190704 17:21:59 server id 100  end_log_pos 350 CRC32 0xbde2e849 	Intvar
SET INSERT_ID=2/*!*/;
#190704 17:21:59 server id 100  end_log_pos 532 CRC32 0x3dc1b5cc 	Query	thread_id=8	exec_time=0	error_code=0
use `defdb`/*!*/;
SET TIMESTAMP=1562253719/*!*/;
insert into view_t(name,str) values ('4','4') on duplicate key update name=values(name),str=values(str)
/*!*/;
# at 532
#190704 17:21:59 server id 100  end_log_pos 563 CRC32 0x6b1948c0 	Xid = 35
COMMIT/*!*/;
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*/;
[4 Jul 2019 15:28] Bogdan Kecman
master [localhost:20617] {msandbox} (defdb) > select @@version, @@binlog_format;                                                             +-----------+-----------------+
| @@version | @@binlog_format |
+-----------+-----------------+
| 8.0.16    | STATEMENT       |
+-----------+-----------------+
1 row in set (0.00 sec)

master [localhost:20617] {msandbox} (defdb) > insert into view_t(name,str) values ('5','5') on duplicate key update name=values(name),str=values(str);
Query OK, 1 row affected, 1 warning (0.00 sec)

master [localhost:20617] {msandbox} (defdb) > \q
Bye
1442:master bk$ ../s1 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 15
Server version: 8.0.16 MySQL Community Server - GPL

Copyright (c) 2000, 2019, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

slave1 [localhost:20618] {msandbox} ((none)) > use defdb;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
slave1 [localhost:20618] {msandbox} (defdb) > select * from t;
+----+------+------+
| ID | NAME | STR  |
+----+------+------+
|  1 | 3    | 3    |
|  2 | 4    | 4    |
+----+------+------+
2 rows in set (0.00 sec)

slave1 [localhost:20618] {msandbox} (defdb) >
[4 Jul 2019 15:28] Bogdan Kecman
the ilter is properly applied if config is:

binlog_format = STATEMENT
replicate-wild-ignore-table=defdb.view_%
# replicate-do-db=defdb
[4 Jul 2019 15:30] Bogdan Kecman
with

binlog_format = MIXED
replicate-wild-ignore-table=defdb.view_%
# replicate-do-db=defdb

master [localhost:20617] {msandbox} (defdb) > select @@version, @@binlog_format;
+-----------+-----------------+
| @@version | @@binlog_format |
+-----------+-----------------+
| 8.0.16    | MIXED           |
+-----------+-----------------+
1 row in set (0.00 sec)

master [localhost:20617] {msandbox} (defdb) > insert into view_t(name,str) values ('6','6') on duplicate key update name=values(name),str=values(str);
Query OK, 1 row affected (0.01 sec)

master [localhost:20617] {msandbox} (defdb) > \q
Bye
1442:master bk$ ../s1 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 16
Server version: 8.0.16 MySQL Community Server - GPL

Copyright (c) 2000, 2019, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

slave1 [localhost:20618] {msandbox} ((none)) > use defdb;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
slave1 [localhost:20618] {msandbox} (defdb) > select * from t;
+----+------+------+
| ID | NAME | STR  |
+----+------+------+
|  1 | 3    | 3    |
|  2 | 4    | 4    |
|  3 | 5    | 5    |
|  4 | 6    | 6    |
+----+------+------+
4 rows in set (0.00 sec)

slave1 [localhost:20618] {msandbox} (defdb) >
[4 Jul 2019 15:33] Bogdan Kecman
Hi,

I don't believe this is a bug.

When you are using MIXED format for replication this is logged as RAW and not STATEMENT so the changes to the underlying table are replicated (you are not filtering that table but view only) as expected.

If you switch to STATEMENT so that query is logged as STATEMENT it is properly filtered out if you properly configure the filters (if you first setup do-db it is matched and filter is ignored)

thanks
Bogdan
[5 Jul 2019 4:16] ricky leung
>> When you are using MIXED format for replication this is logged as RAW and not STATEMENT so the changes to the underlying table are replicated (you are not filtering that table but view only) as expected.
>> If you switch to STATEMENT so that query is logged as STATEMENT it is properly filtered out if you properly configure the filters (if you first setup do-db it is matched and filter is ignored)

Yes it is the behaviour that was observed but it should be a bug.  Consider the situations:
1. binlog_format = MIXED. When I execute the "insert...on duplicate key" statement on the view_t, it is changed on-the-fly to a RBR but it also changes to reference the underlying table t.  Why changed the table reference?  There is no reason for this change.  This change of table reference caused the "replicate-wild-ignore-table" setting to fail.
2. Yes I can explicitly change the binlog_format to STATEMENT, but it is not secure isn't it? There are 2 unique keys in the table which may cause ambiguity with a statement-based replication.

I can confirm that this problem still exists having modified the replication-* settings per your instruction:
#replicate-to-db= (this line is commented out)
replicate-wild-ignore-table=ccnb.view_%
[5 Jul 2019 14:13] Bogdan Kecman
Hi,

>  it is changed on-the-fly to a RBR

There is nothing "changed" here on the fly! When running in MIXED logging format, the server automatically switches from statement-based to row-based logging. For conditions check our manual:
https://dev.mysql.com/doc/refman/8.0/en/binary-log-mixed.html

This insert is logged as ROW 

For the ROW, the STATEMENT is irrelevant, the changes are what is relevant and this stement changes data in T and that change is logged. As you can see in the documentation when event is looged ROW

"ROW.  Carry out the remaining steps for each update of a table row."

so it's checking filters based on a table row that's being updated, what statement used to finally get there is irrelevant.

Make sure you read how the filtering rules are applied:
https://dev.mysql.com/doc/refman/8.0/en/replication-rules.html

and especially
https://dev.mysql.com/doc/refman/8.0/en/replication-rules-table-options.html

With regards to config issue we do mention in documentation that 
"To make it easier to determine what effect an option set will have, it is recommended that you avoid mixing “do” and “ignore” options, or wildcard and nonwildcard options."

furthermore
" --replicate-wild-do-table options are checked if and only if there are no database-level options that apply." (same works for ignore, so since you had database-level the table level was ignored)

all best
bogdan
[7 Jul 2019 9:20] ricky leung
Sadly, it seems you did not understand what I have described.
Let me restart and describe the situation a bit more clearly:

Both MASTER and SLAVE:

my.cnf:
replicate-wild-do-table=ccnb.view_% ### << notice the replicate-wild-do-table setting this time

schema:

CREATE TABLE `tbl_t` (
  `ID` int(11) NOT NULL AUTO_INCREMENT,
  `NAME` varchar(10) NOT NULL,
  `STR` varchar(20) DEFAULT NULL,
  PRIMARY KEY (`ID`),
  UNIQUE KEY `NAME` (`NAME`)
) ENGINE=InnoDB;
CREATE ALGORITHM=UNDEFINED DEFINER=`root`@`localhost` SQL SECURITY DEFINER VIEW `view_t` AS select `tbl_t`.`ID` AS `ID`,`tbl_t`.`NAME` AS `NAME`,`tbl_t`.`STR` AS `STR` from `tbl_t`;

sql:
MASTER> select @@binlog_format;
+-----------------+
| @@binlog_format |
+-----------------+
| MIXED           |
+-----------------+
1 row in set (0.00 sec)

MASTER> insert into view_t(name,str) values ('1','1') on duplicate key update name=values(name),str=values(str);
Query OK, 1 row affected (0.03 sec)

MASTER> select * from view_t;
+----+------+------+
| ID | NAME | STR  |
+----+------+------+
|  1 | 1    | 1    |
+----+------+------+
1 row in set (0.00 sec)

SLAVE> select * from view_t;
Empty set (0.00 sec)

From the above, it shows that:
1. replicate-wild-do-table is set to ccnb.view_%
2. binlog_format is MIXED
3. Execute a sql on master to insert to view_t "insert into view_t(name,str) values ('1','1') on duplicate key update name=values(name),str=values(str)"
4. Record is NOT replicated to slave

According to the document, with the above settings replication should work, but the data did not get replicated.

Conclusion: a bug
[12 Aug 2019 5:12] Bogdan Kecman
Hi,

Sorry, but not a bug.

all best