Replication slave from PXC can crash if wsrep_forced_binlog_format=ROW

[Vyacheslav Gritsenko]

Unfortunately, I didn't have much time to dig into it more deeper.
I have the following setup:

- 3 nodes in PXC setup (server names are "db1,db2,db3"), version is the same for all PXC nodes.
Server version: 5.5.31-23.7.5 Percona XtraDB Cluster (GPL) 5.5.31-23.7.5, Revision 438, wsrep_23.7.5.r3880

- 1 replication slave (server name is "s1"), which is using node db3 as a master.
Server version: 5.5.32-rel31.0-log Percona Server with XtraDB (GPL), Release rel31.0, Revision 549

db3 has the following option enabled:
wsrep_forced_binlog_format='row'

Now let's create test procedure on one of the nodes in our PXC:

mysql> delimiter //
mysql> create procedure test_proc() BEGIN INSERT INTO test VALUES(1);end//
Query OK, 0 rows affected (0.01 sec)
mysql> delimiter ;

Then go to s1 server and check slave status, I left only important info from this output:

mysql> show slave status\G
...
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
...
                   Last_Error: Could not execute Write_rows event on table mysql.proc; Duplicate entry 'test-test_proc-PROCEDURE' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log db3-bin.000018, end_log_pos 2687
...
               Last_SQL_Error: Could not execute Write_rows event on table mysql.proc; Duplicate entry 'test-test_proc-PROCEDURE' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log db3-bin.000018, end_log_pos 2687

That's it. We just corrupted our slave (s1). Skipping an error will fix this.
Looks like PXC was trying to create this procedure twice and at the second time it failed because of duplicate record on s1 in mysql.proc (b/c of primary key).
I didn't find any duplicate records in binary log, commands counter was increased by 1 as required, so probably the problem is somewhere is Galera library.
Btw, dropping this procedure leads to the same issue.

This issue can be fixed if we set wsrep_forced_binlog_format to NONE (or STATEMENT).

[Nilnandan Joshi (nilnandan-joshi)]

Verified with PXC 5.5 (Master node) and PS 5.5 (async slave)

On Master:

mysql> show global variables like 'wsrep_forced%';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| wsrep_forced_binlog_format | ROW |
+----------------------------+-------+
1 row in set (0.00 sec)

mysql> delimiter //
mysql> use nil
Database changed
mysql>
mysql> create procedure test_proc() BEGIN INSERT INTO test VALUES(1);end//
Query OK, 0 rows affected (0.00 sec)

mysql> delimiter ;
mysql> quit

On Slave:

mysql> show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 192.168.43.58
                  Master_User: root
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000002
          Read_Master_Log_Pos: 759
               Relay_Log_File: mysql_sandbox5535-relay-bin.000004
                Relay_Log_Pos: 425
        Relay_Master_Log_File: mysql-bin.000002
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
...
Last_Errno: 1062
                   Last_Error: Could not execute Write_rows event on table mysql.proc; Duplicate entry 'nil-test_proc-PROCEDURE' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log mysql-bin.000002, end_log_pos 675
...
Last_SQL_Errno: 1062
               Last_SQL_Error: Could not execute Write_rows event on table mysql.proc; Duplicate entry 'nil-test_proc-PROCEDURE' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log mysql-bin.000002, end_log_pos 675

[Nilnandan Joshi (nilnandan-joshi)]

Same with PXC 5.6 and PS 5.6

mysql> show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 192.168.43.58
                  Master_User: root
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000004
          Read_Master_Log_Pos: 778
               Relay_Log_File: mysql_sandbox5617-relay-bin.000002
                Relay_Log_Pos: 283
        Relay_Master_Log_File: mysql-bin.000004
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
...
                   Last_Errno: 1062
                   Last_Error: Could not execute Write_rows event on table mysql.proc; Duplicate entry 'nil-test_proc2-PROCEDURE' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log mysql-bin.000004, end_log_pos 520

...
               Last_SQL_Errno: 1062
               Last_SQL_Error: Could not execute Write_rows event on table mysql.proc; Duplicate entry 'nil-test_proc2-PROCEDURE' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log mysql-bin.000004, end_log_pos 520
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
                  Master_UUID: d2ea6c67-fb2b-11e3-abb3-0800273cb9cd
             Master_Info_File: /home/nilnandan/sandboxes/msb_5_6_17/data/master.info

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-512