Binlog events with binlog_format=MIXED are unconditionally logged in ROW format in some cases

Not repeatable with PS 5.1.73, its logging as a STATEMENT for all queries with binlog-format=MIXED.

nil@Dell-XPS:~/sandboxes/rsandbox_Percona-Server-5_1_73/master/data$ mysqlbinlog -v mysql-bin.000002
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
....

# at 266
#140605 11:32:05 server id 1 end_log_pos 497 Query thread_id=1 exec_time=0 error_code=0
use `test`/*!*/;
SET TIMESTAMP=1401948125/*!*/;
CREATE TABLE `t2` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `c` char(32) DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=1018 DEFAULT CHARSET=latin1
/*!*/;
# at 497
#140605 11:32:10 server id 1 end_log_pos 565 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401948130/*!*/;
BEGIN
/*!*/;
# at 565
#140605 11:32:10 server id 1 end_log_pos 715 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401948130/*!*/;
INSERT INTO `t2` VALUES (1, 'dummy'), (2, 'foo'), (3, 'ping'), (4, 'ding'), (5, 'ring')
/*!*/;
# at 715
#140605 11:32:10 server id 1 end_log_pos 742 Xid = 16
COMMIT/*!*/;
# at 742
#140605 11:32:15 server id 1 end_log_pos 899 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401948135/*!*/;
create temporary table t2_temp(`id` int(11) NOT NULL, `c` char(32) DEFAULT NULL) ENGINE=InnoDB
/*!*/;
# at 899
#140605 11:32:20 server id 1 end_log_pos 994 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401948140/*!*/;
create index idx1 on t2_temp(id)
/*!*/;
# at 994
#140605 11:32:25 server id 1 end_log_pos 1062 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401948145/*!*/;
BEGIN
/*!*/;
# at 1062
#140605 11:32:25 server id 1 end_log_pos 1177 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401948145/*!*/;
insert into t2_temp values(4, 'hello'), (5, 'world')
/*!*/;
# at 1177
#140605 11:32:25 server id 1 end_log_pos 1246 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401948145/*!*/;
COMMIT
/*!*/;
# at 1246
#140605 11:33:13 server id 1 end_log_pos 1314 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401948193/*!*/;
BEGIN
/*!*/;
# at 1314
#140605 11:33:13 server id 1 end_log_pos 1446 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401948193/*!*/;
update t2, t2_temp set t2.c='updated' where t2.id=t2_temp.id
/*!*/;
# at 1446
#140605 11:33:13 server id 1 end_log_pos 1473 Xid = 22
COMMIT/*!*/;
# at 1473
#140605 11:33:23 server id 1 end_log_pos 1541 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401948203/*!*/;
BEGIN
/*!*/;
# at 1541
#140605 11:33:23 server id 1 end_log_pos 1645 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401948203/*!*/;
insert into t2 values(6, 'simple_insert')
/*!*/;
# at 1645
#140605 11:33:23 server id 1 end_log_pos 1672 Xid = 23
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
nil@Dell-XPS:~/sandboxes/rsandbox_Percona-Server-5_1_73/master/data$

-------------------------- On slave--------------------------

nil@Dell-XPS:~/sa...

Repeatable with PS 5.6.17

nil@Dell-XPS:~/sandboxes/rsandbox_Percona-Server-5_6_17/master/data$ mysqlbinlog -v mysql-bin.000003
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;

...

# at 510
#140605 16:45:26 server id 1 end_log_pos 752 CRC32 0x07a704f4 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401966926/*!*/;
CREATE TABLE `t2` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `c` char(32) DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=1018 DEFAULT CHARSET=latin1
/*!*/;
# at 752
#140605 16:45:30 server id 1 end_log_pos 831 CRC32 0x3461ce1d Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401966930/*!*/;
BEGIN
/*!*/;
# at 831
#140605 16:45:30 server id 1 end_log_pos 992 CRC32 0xebe4b1af Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401966930/*!*/;
INSERT INTO `t2` VALUES (1, 'dummy'), (2, 'foo'), (3, 'ping'), (4, 'ding'), (5, 'ring')
/*!*/;
# at 992
#140605 16:45:30 server id 1 end_log_pos 1023 CRC32 0xb1233f88 Xid = 34
COMMIT/*!*/;
# at 1023
#140605 16:45:35 server id 1 end_log_pos 1191 CRC32 0x9a2fca98 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401966935/*!*/;
create temporary table t2_temp(`id` int(11) NOT NULL, `c` char(32) DEFAULT NULL) ENGINE=InnoDB
/*!*/;
# at 1191
#140605 16:45:51 server id 1 end_log_pos 1297 CRC32 0xa0c429b6 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401966951/*!*/;
create index idx1 on t2_temp(id)
/*!*/;
# at 1297
#140605 16:45:55 server id 1 end_log_pos 1376 CRC32 0xceaf66ed Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401966955/*!*/;
BEGIN
/*!*/;
# at 1376
#140605 16:45:55 server id 1 end_log_pos 1502 CRC32 0xbf32b6dd Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401966955/*!*/;
insert into t2_temp values(4, 'hello'), (5, 'world')
/*!*/;
# at 1502
#140605 16:45:55 server id 1 end_log_pos 1582 CRC32 0x264c4a5e Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401966955/*!*/;
COMMIT
/*!*/;
# at 1582
#140605 16:46:12 server id 1 end_log_pos 1663 CRC32 0x2fbc5e02 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401966972/*!*/;
BEGIN
/*!*/;
# at 1663
#140605 16:46:12 server id 1 end_log_pos 1711 CRC32 0xed6f2a3b Table_map: `test`.`t2` mapped to number 71
# at 1711
#140605 16:46:12 server id 1 end_log_pos 1793 CRC32 0x6eb2924f Update_rows: table id 71 flags: STMT_END_F

BINLOG '
fFGQUxMBAAAAMAAAAK8GAAAAAEcAAAAAAAEABHRlc3QAAnQyAAID/gL+IAI7Km/t
fFGQUx8BAAAAUgAAAAEHAAAAAEcAAAAAAAEAAgAC///8BAAAAARkaW5n/AQAAAAHdXBkYXRlZPwF
AAAABHJpbmf8BQAAAAd1cGRhdGVkT5Kybg==
'/*!*/;
### UPDATE `test`.`t2`
### WHERE
### @1=4
### @2='ding'
### SET
### @1=4
### @2='updated'
### UPDATE `test`.`t2`
### WHERE
### @1=5
### @2='ring'
### SET
### @1=5
### @2='updated'
# at 1793
#140605 16:46:12 server id 1 end_log_pos 1824 CRC32 0xd08404b8 Xid = 40
COMMIT/*!*/;
# at 1824
#140605 16:46:18 server id 1 end_log_pos 1896 CRC32 0x1160fc18 Query thread_id=1 exec_time=0 error_code=0
SET TIMESTAMP=1401966978/*!*/;
BEGIN
/*!*/;
# at 1896
#140605 16:46:18 server id 1 end_log...

Simplified version of one of the mtr test cases pertinent to this bug

Running the above mtr test case on upstream 5.5.37 produces the following result:

CREATE TABLE t1 (a int);
CREATE TABLE t2 ( i1 INT NOT NULL AUTO_INCREMENT, PRIMARY KEY (i1) );
CREATE TABLE t3 ( i1 INT NOT NULL AUTO_INCREMENT, PRIMARY KEY (i1) );
CREATE TRIGGER tr1 AFTER DELETE ON t2 FOR EACH ROW INSERT INTO t3 () VALUES ();
CREATE TEMPORARY TABLE t1_tmp (i1 int);
ALTER TABLE t1_tmp ADD COLUMN b INT;
DELETE FROM t2;
CREATE TEMPORARY TABLE t2_tmp (a int);
ALTER TABLE t1_tmp ADD COLUMN c INT;
### assertion: assert that slave has no temporary tables opened
SHOW STATUS LIKE 'Slave_open_temp_tables';
Variable_name Value
Slave_open_temp_tables 1
DROP TABLE t1_tmp, t2;
INSERT INTO t2_tmp SELECT CEIL(RAND() * 1000);
INSERT INTO t1 VALUES (1);
INSERT INTO t3 SELECT * FROM t2_tmp;
DROP TEMPORARY TABLE t2_tmp;
INSERT INTO t1 VALUES (2);
### assertion: assert that slave has no temporary tables opened
SHOW STATUS LIKE 'Slave_open_temp_tables';
Variable_name Value
Slave_open_temp_tables 0
DROP TABLE t3, t1;
show binlog events from <binlog_start>;
Log_name Pos Event_type Server_id End_log_pos Info
slave-bin.000001 # Query # # use `test`; CREATE TABLE t1 (a int)
slave-bin.000001 # Query # # use `test`; CREATE TABLE t2 ( i1 INT NOT NULL AUTO_INCREMENT, PRIMARY KEY (i1) )
slave-bin.000001 # Query # # use `test`; CREATE TABLE t3 ( i1 INT NOT NULL AUTO_INCREMENT, PRIMARY KEY (i1) )
slave-bin.000001 # Query # # use `test`; CREATE DEFINER=`root`@`localhost` TRIGGER tr1 AFTER DELETE ON t2 FOR EACH ROW INSERT INTO t3 () VALUES ()
slave-bin.000001 # Query # # use `test`; CREATE TEMPORARY TABLE t1_tmp (i1 int)
slave-bin.000001 # Query # # use `test`; ALTER TABLE t1_tmp ADD COLUMN b INT
slave-bin.000001 # Query # # DROP TEMPORARY TABLE IF EXISTS `test`.`t1_tmp` /* generated by server */
slave-bin.000001 # Query # # use `test`; DROP TABLE `t2` /* generated by server */
slave-bin.000001 # Query # # BEGIN
slave-bin.000001 # Table_map # # table_id: # (test.t1)
slave-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
slave-bin.000001 # Xid # # COMMIT /* XID */
slave-bin.000001 # Query # # BEGIN
slave-bin.000001 # Table_map # # table_id: # (test.t3)
slave-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
slave-bin.000001 # Xid # # COMMIT /* XID */
slave-bin.000001 # Query # # DROP TEMPORARY TABLE IF EXISTS `test`.`t2_tmp` /* generated by server */
slave-bin.000001 # Query # # BEGIN
slave-bin.000001 # Query # # use `test`; INSERT INTO t1 VALUES (2)
slave-bin.000001 # Xid # # COMMIT /* XID */
slave-bin.000001 # Query # # use `test`; DROP TABLE `t3`,`t1` ...

Running the attached mtr test case on binary with the potential fix by George, produces the following result:

CREATE TABLE t1 (a int);
CREATE TABLE t2 ( i1 INT NOT NULL AUTO_INCREMENT, PRIMARY KEY (i1) );
CREATE TABLE t3 ( i1 INT NOT NULL AUTO_INCREMENT, PRIMARY KEY (i1) );
CREATE TRIGGER tr1 AFTER DELETE ON t2 FOR EACH ROW INSERT INTO t3 () VALUES ();
CREATE TEMPORARY TABLE t1_tmp (i1 int);
ALTER TABLE t1_tmp ADD COLUMN b INT;
DELETE FROM t2;
CREATE TEMPORARY TABLE t2_tmp (a int);
ALTER TABLE t1_tmp ADD COLUMN c INT;
### assertion: assert that slave has no temporary tables opened
SHOW STATUS LIKE 'Slave_open_temp_tables';
Variable_name Value
Slave_open_temp_tables 0
DROP TABLE t1_tmp, t2;
INSERT INTO t2_tmp SELECT CEIL(RAND() * 1000);
INSERT INTO t1 VALUES (1);
INSERT INTO t3 SELECT * FROM t2_tmp;
DROP TEMPORARY TABLE t2_tmp;
INSERT INTO t1 VALUES (2);
### assertion: assert that slave has no temporary tables opened
SHOW STATUS LIKE 'Slave_open_temp_tables';
Variable_name Value
Slave_open_temp_tables 0
DROP TABLE t3, t1;
show binlog events from <binlog_start>;
Log_name Pos Event_type Server_id End_log_pos Info
slave-bin.000001 # Query # # use `test`; CREATE TABLE t1 (a int)
slave-bin.000001 # Query # # use `test`; CREATE TABLE t2 ( i1 INT NOT NULL AUTO_INCREMENT, PRIMARY KEY (i1) )
slave-bin.000001 # Query # # use `test`; CREATE TABLE t3 ( i1 INT NOT NULL AUTO_INCREMENT, PRIMARY KEY (i1) )
slave-bin.000001 # Query # # use `test`; CREATE DEFINER=`root`@`localhost` TRIGGER tr1 AFTER DELETE ON t2 FOR EACH ROW INSERT INTO t3 () VALUES ()
slave-bin.000001 # Query # # DROP TEMPORARY TABLE IF EXISTS `test`.`t1_tmp` /* generated by server */
slave-bin.000001 # Query # # use `test`; DROP TABLE `t2` /* generated by server */
slave-bin.000001 # Query # # BEGIN
slave-bin.000001 # Query # # use `test`; INSERT INTO t1 VALUES (1)
slave-bin.000001 # Xid # # COMMIT /* XID */
slave-bin.000001 # Query # # BEGIN
slave-bin.000001 # Table_map # # table_id: # (test.t3)
slave-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
slave-bin.000001 # Xid # # COMMIT /* XID */
slave-bin.000001 # Query # # DROP TEMPORARY TABLE IF EXISTS `test`.`t2_tmp` /* generated by server */
slave-bin.000001 # Query # # BEGIN
slave-bin.000001 # Query # # use `test`; INSERT INTO t1 VALUES (2)
slave-bin.000001 # Xid # # COMMIT /* XID */
slave-bin.000001 # Query # # use `test`; DROP TABLE `t3`,`t1` /* generated by server */

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