MySQL Bugs: #69095: binlog_format=STATEMENT makes execution of BINLOG stmts or ROW events to fail

Bug #69095	binlog_format=STATEMENT makes execution of BINLOG stmts or ROW events to fail
Submitted:	29 Apr 2013 19:01	Modified:	8 Jul 2013 12:09
Reporter:	Giuseppe Maxia	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S1 (Critical)
Version:	5.5	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	binlog_format, mixed, RBR, replication

Description:
In a system using GTID, if the master changes binlog_format from STATEMENT to ROW, replication breaks in the slaves:

                   Last_Errno: 1666
                   Last_Error: Error executing row event: 'Cannot execute statement: impossible to write to binary log since statement is in row format and BINLOG_FORMAT = STATEMENT.'

How to repeat:
1) set replication, with default binlog_format set to either STATEMENT or MIXED
2) enable GTID
# ----------------------
master-info-repository=table
relay-log-info-repository=table
gtid_mode=ON
log-slave-updates
enforce-gtid-consistency
# ----------------------

3) run this script in the master

# ----------------------
use test ;
drop table if exists t1;
set binlog_format=statement;
create table t1 ( i int not null primary key);
insert into t1 values (1);
set binlog_format=row;
insert into t1 values (2);
show binlog events;
# ----------------------

Hello Giuseppe,

Thank you for the report.
Verified as described.

Thanks,
Umesh

Giuseppe,

Thanks for reporting this, but I don't think this is something
specific of GTID, nor specific to 5.6, nor a bug at all. However, I am
also assuming that you are running the slave SQL thread with
binlog_format=STATEMENT. So let me try to explain!

If the your SQL thread is indeed configured with
binlog_format=STATEMENT once it receives a ROW event it will stop. The
reason is that it would be unable to log that ROW event in STATEMENT
format (sometimes we refer to this as ROW injection, which is either a
BINLOG statement or a ROW event executed by the slave's SQL thread).

Furthermore, spinning your test, in 5.5, the SQL thread refuses to
execute the statement as well (as expected and by design).

See: http://dev.mysql.com/doc/refman/5.5/en/binary-log-mixed.html
(in particular the table for 5.5.3, row: "Row Injection" |
STATEMENT | Yes | Yes).

See also: BUG#39934.

I think the following will make your scenario work as expected (in
agreement with the semantics set in the fix for BUG#39934):

SLAVE> STOP SLAVE;
SLAVE> SET GLOBAL binlog_format=MIXED;
SLAVE> START SLAVE;

In this case, we are allowing the SQL thread to log in both STATEMENT
and ROW formats. If this does not work for you, we need to figure out
what is wrong then...

Let me know if I misunderstood something or if my assumption does not 
hold...

Thanks!

Luis,
I ran the test again. Just out of the box, in MySQL 5.5.31 and MySQL 5.6.11 without GTID and crash-safe tables enabled, the data is replicated. All servers are using binlog_format=STATEMENT.
When I enable GTID and crash-safe tables, replication fails.

Hi Giuseppe, 

I tried to successfully run your test case with the server running
with binlog_format=STATEMENT by default (including the slave threads).
I could not (as expected). With binlog_format=MIXED by default, I was
able to replicate correctly (again as expected). Below is the exact 
test case and the result of running it through MTR on a 5.5.31 vanilla
server.

Can you find out what I am missing here?

TEST CASE (Giuseppe's test case)
=========

--source include/master-slave.inc

SELECT version();
SELECT @@global.binlog_format;
--connection slave
SELECT version();
SELECT @@global.binlog_format;
--connection master

set binlog_format=statement;
create table t1 ( i int not null primary key);
insert into t1 values (1);
set binlog_format=row;
insert into t1 values (2);
show binlog events;
CREATE TEMPORARY TABLE t1 (c1 INT);
INSERT INTO t1 VALUES (1);
CREATE TABLE t2 (c1 INT);

--sync_slave_with_master

--source include/rpl_end.inc

RESULTS
=======

  5.5.31 with STATEMENT as default -> Replication stops (as expected!)
  5.5.31 with MIXED as default     -> Succeeds

DETAILS
=======

$ perl mtr --mem --mysqld=--binlog-format=statement rpl_bug69095
[...]
include/master-slave.inc
[connection master]
SELECT version();
version()
5.5.31-log
SELECT @@global.binlog_format;
@@global.binlog_format
STATEMENT
SELECT version();
version()
5.5.31-log
SELECT @@global.binlog_format;
@@global.binlog_format
STATEMENT
set binlog_format=statement;
create table t1 ( i int not null primary key);
insert into t1 values (1);
set binlog_format=row;
insert into t1 values (2);
show binlog events;
[...]
CREATE TEMPORARY TABLE t1 (c1 INT);
INSERT INTO t1 VALUES (1);
CREATE TABLE t2 (c1 INT);
rpl.rpl_x                                [ fail ]

The error:

Last_Error      Error executing row event: 'Cannot execute statement: impossible to write to binary log since statement is in row format and BINLOG_FORMAT = STATEMENT.'

$ perl mtr --mem --mysqld=--binlog-format=mixed rpl_bug69095

[...]
include/master-slave.inc
[connection master]
SELECT version();
version()
5.5.31-log
SELECT @@global.binlog_format;
@@global.binlog_format
MIXED
SELECT version();
version()
5.5.31-log
SELECT @@global.binlog_format;
@@global.binlog_format
MIXED
set binlog_format=statement;
create table t1 ( i int not null primary key);
insert into t1 values (1);
set binlog_format=row;
insert into t1 values (2);
show binlog events;
[...]
CREATE TEMPORARY TABLE t1 (c1 INT);
INSERT INTO t1 VALUES (1);
CREATE TABLE t2 (c1 INT);
include/rpl_end.inc
rpl.rpl_bug69095                          [ pass ]     91

Luis,
I don't use the MySQL test infrastructure, as it has too many shortcomings. 
Instead, I use MySQL Sandbox, which simulates a real world installation, and it is easier to run and test.

Main differences between MYSQL sandbox installation and mysql-test installation: 
1) no anonymous users
2) no users without password
3) direct access to configuration files without using includes.
4) ability to interact manually with the environment and check what's going on.

Here's my set of events that lead to the bug:

$ make_replication_sandbox 5.5.31
installing and starting master
installing slave 1
installing slave 2
starting slave 1
.. sandbox server started
starting slave 2
.. sandbox server started
initializing slave 1
initializing slave 2
replication directory installed in $HOME/sandboxes/rsandbox_5_5_31

$ make_replication_sandbox 5.6.11
installing and starting master
installing slave 1
installing slave 2
starting slave 1
.. sandbox server started
starting slave 2
.. sandbox server started
initializing slave 1
initializing slave 2
replication directory installed in $HOME/sandboxes/rsandbox_5_6_11

### CASE 1 : MySQL 5.5.31

$
$ cat > /tmp/test.sql
use test ;
drop table if exists t1;
set binlog_format=statement;
create table t1 ( i int not null primary key);
insert into t1 values (1);
set binlog_format=row;
insert into t1 values (2);
$
$ cd ~/sandboxes/rsandbox_5_5_31

$ ./use_all 'select @@global.binlog_format'
# master
@@global.binlog_format
STATEMENT
# server: 1:
@@global.binlog_format
STATEMENT
# server: 2:
@@global.binlog_format
STATEMENT

$ ./m < /tmp/test.sql
$ ./check_slaves
master
            File: mysql-bin.000001
        Position: 2656
slave # 1
              Master_Log_File: mysql-bin.000001
          Read_Master_Log_Pos: 2656
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
          Exec_Master_Log_Pos: 2656
slave # 2
              Master_Log_File: mysql-bin.000001
          Read_Master_Log_Pos: 2656
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
          Exec_Master_Log_Pos: 2656
$ ./use_all 'select * from test.t1'
# master
i
1
2
# server: 1:
i
1
2
# server: 2:
i
1
2
$

# 5.5.31 : replication works

### CASE 2 : MySQL 5.6.11 without GTID

$ cd ~/sandboxes/rsandbox_5_6_11/
$
$ ./use_all 'select @@global.binlog_format'
# master
@@global.binlog_format
STATEMENT
# server: 1:
@@global.binlog_format
STATEMENT
# server: 2:
@@global.binlog_format
STATEMENT
$ ./check_slaves
master
             File: mysql-bin.000001
         Position: 2590
slave # 1
              Master_Log_File: mysql-bin.000001
          Read_Master_Log_Pos: 2590
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
          Exec_Master_Log_Pos: 2590
slave # 2
              Master_Log_File: mysql-bin.000001
          Read_Master_Log_Pos: 2590
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
          Exec_Master_Log_Pos: 2590
$ ./m < /tmp/test.sql
$ ./check_slaves
master
             File: mysql-bin.000001
         Position: 3231
slave # 1
              Master_Log_File: mysql-bin.000001
          Read_Master_Log_Pos: 3231
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
          Exec_Master_Log_Pos: 3231
slave # 2
              Master_Log_File: mysql-bin.000001
          Read_Master_Log_Pos: 3231
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
          Exec_Master_Log_Pos: 3231
$ ./use_all 'select * from test.t1'
# master
i
1
2
# server: 1:
i
1
2
# server: 2:
i
1
2

# 5.6.11 without GTID: replication works

### CASE 3 - MySQL 5.6.11 with GTID enabled

$ cat enable_gtid
#!/bin/bash
cd /Users/gmax/sandboxes/rsandbox_5_6_11
OPTIONS="master-info-repository=table "
OPTIONS="$OPTIONS relay-log-info-repository=table"
OPTIONS="$OPTIONS gtid_mode=ON"
OPTIONS="$OPTIONS log-slave-updates enforce-gtid-consistency"
CHANGED=""
for NODE in master node1 node2
do
    for OPTION in $OPTIONS
    do
        option_exists=$(grep $OPTION $NODE/my.sandbox.cnf)
        if [ -z "$option_exists" ]
        then
            echo "$OPTION" >> $NODE/my.sandbox.cnf
            echo "# option '$OPTION' added to $NODE configuration file"
            CHANGED=1
        else
            echo "# option '$OPTION' already exists in $NODE configuration file"
        fi
    done
done
if [ -n "$CHANGED" ]
then
    ./restart_all
fi

$ ./enable_gtid
# option 'master-info-repository=table' added to master configuration file
# option 'relay-log-info-repository=table' added to master configuration file
# option 'gtid_mode=ON' added to master configuration file
# option 'log-slave-updates' added to master configuration file
# option 'enforce-gtid-consistency' added to master configuration file
# option 'master-info-repository=table' added to node1 configuration file
# option 'relay-log-info-repository=table' added to node1 configuration file
# option 'gtid_mode=ON' added to node1 configuration file
# option 'log-slave-updates' added to node1 configuration file
# option 'enforce-gtid-consistency' added to node1 configuration file
# option 'master-info-repository=table' added to node2 configuration file
# option 'relay-log-info-repository=table' added to node2 configuration file
# option 'gtid_mode=ON' added to node2 configuration file
# option 'log-slave-updates' added to node2 configuration file
# option 'enforce-gtid-consistency' added to node2 configuration file
# executing "stop" on /Users/gmax/sandboxes/rsandbox_5_6_11
executing "stop" on slave 1
executing "stop" on slave 2
executing "stop" on master
# executing "start" on /Users/gmax/sandboxes/rsandbox_5_6_11
executing "start" on master
. sandbox server started
executing "start" on slave 1
. sandbox server started
executing "start" on slave 2
. sandbox server started
$ ./use_all 'select @@global.binlog_format'
# master
@@global.binlog_format
STATEMENT
# server: 1:
@@global.binlog_format
STATEMENT
# server: 2:
@@global.binlog_format
STATEMENT
$ ./check_slaves
master
             File: mysql-bin.000002
         Position: 151
slave # 1
              Master_Log_File: mysql-bin.000002
          Read_Master_Log_Pos: 151
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
          Exec_Master_Log_Pos: 151
slave # 2
              Master_Log_File: mysql-bin.000002
          Read_Master_Log_Pos: 151
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
          Exec_Master_Log_Pos: 151

## Until now, replication is working. Now we run the test:

$ ./m < /tmp/test.sql
$ ./check_slaves
master
             File: mysql-bin.000002
         Position: 984
slave # 1
              Master_Log_File: mysql-bin.000002
          Read_Master_Log_Pos: 984
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
          Exec_Master_Log_Pos: 748
slave # 2
              Master_Log_File: mysql-bin.000002
          Read_Master_Log_Pos: 984
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
          Exec_Master_Log_Pos: 748
$ ./use_all 'select * from test.t1'
# master
i
1
2
# server: 1:
i
1
# server: 2:
i
1

# MySQL 5.6.11 with GTID: replication is broken

The same output goes for MySQL 5.6.12

Giuseppe, just to be clear, aren't you missing log-slave-updates on your 
5.5.31 test? I think you are. You need to make the slave SQL thread to 
write its own updates to trigger a ROW injection.

Luis,
Indeed, if I use log-slave-updates, the test fails also in 5.5.31.
But, you know what? The test that fails is what we regularly do to test Tungsten Replicator, and with that, replication does not fail when you switch between binlog formats.

Hi Giuseppe, 

We are closing this as not a bug. The current semantics are clear:

  1. Master shall not log ROW events when binlog_format=STATEMENT, not
     even if issuing BINLOG '' statements. If a BINLOG statement is
     issued, the master will refuse to execute it;

  2. Slave shall not log ROW events if its binlog_format=STATEMENT
     (for instance, when processing a ROW event coming from the
     master). The slave will refuse to execute the statement.

Both of these rules are set, among other reasons, to protect against
ROW injections and were enforced by the fix for BUG#39934, which was
pushed to 5.5.3, over 3 years ago and is documented in the manual, as
stated above:

  http://dev.mysql.com/doc/refman/5.5/en/binary-log-mixed.html

As such, in the event that the slave thread is logging its own updates
and that there is a chance that the master is capable of logging both
STATEMENT and ROW events, then binlog_format, on the slave thread,
should be set to MIXED or ROW. That way, the user is aware of this
change and the slave will be able to log the events coming from the
master.

Some of the reasons for enforcing these semantics are:

1. Should the slave thread operate with binlog_format=STATEMENT
   (default for binlog_format) and be able to log ROW events (even if
   relayed from the master), then this would likely cause confusion;

2. Alternatively, should the slave thread be *hardcoded* to *always*
   run with binlog_format=MIXED, then:

   - unsafe statements logged on the master would lead to slave
     logging them as ROWs. Probably not intended by the user and yet
     again would cause confusion;

   - Replaying slave's binary logs could make the user face unexpected
     BINLOG statements in mysqlbinlog's output. Moreover, these
     statements require SUPER privileges to be replayed;

   - Deploying binlog filters on the slave could be challenging since
     there are some differences on how the filters operate under
     different binlog formats;

   - Semantics on the slaves would break. Users might expect
     STATEMENTs on the binary logs of the slaves even for those that
     may be unsafe for whatever reason.

   It is better to let the user set it himself knowing the implications
   and adjust the slave behavior to his or her effective needs.

I have also changed the version (since you have acknowledged that 
you have seen this behavior in 5.5 as well) and the synopsis of the 
report to more accurately reflect the behavior you mention.