Bug #93423 binlog_row_image=full not always honored for binlog_format=MIXED

Description:
With:
binlog_row_image='FULL'
binlog_format='MIXED'
set tx_isolation='READ-COMMITTED'

An INSERT INTO table SELECT * FROM anothertable; will be written in row format but it will not write NULL columns to the binary log

How to repeat:
set binlog_format='MIXED';
set binlog-row-image="full";
set tx_isolation='READ-COMMITTED'; 
create database a; 
create database b; 
create table a.test (id int primary key, name varchar(50) default null, age bigint); 
create table b.test (id int primary key, name varchar(50) default null, age bigint); 
insert into a.test(id, age) values (1,5), (2,10); /* This insert event is written with full row image in binary log */ 
insert into b.test(id,age) select id , age from a.test ; /* name column information is not present in row image */

BINLOG '
Trr/WxMBAAAAMAAAAMEMAAAAAOAAAAAAAAEAAWEABHRlc3QAAwMPCAIyAAbYzi1r
Trr/Wx4BAAAAPQAAAP4MAAAAAOAAAAAAAAEAAgAD//oBAAAABQAAAAAAAAD6AgAAAAoAAAAAAAAA
o50iBQ==
'/*!*/;
### INSERT INTO `a`.`test`
### SET
###   @1=1
###   @2=NULL
###   @3=5
### INSERT INTO `a`.`test`
### SET
###   @1=2
###   @2=NULL
###   @3=10
# at 3326
#181129  5:07:10 server id 1  end_log_pos 3357 CRC32 0xc21cc3ba  Xid = 43
COMMIT/*!*/;
# at 3357
#181129  5:07:21 server id 1  end_log_pos 3422 CRC32 0xa82c7878  Anonymous_GTID    last_committed=15    sequence_number=16    rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 3422
#181129  5:07:21 server id 1  end_log_pos 3490 CRC32 0x5efd2acf  Query    thread_id=4    exec_time=0    error_code=0
SET TIMESTAMP=1543486041/*!*/;
BEGIN
/*!*/;
# at 3490
#181129  5:07:21 server id 1  end_log_pos 3538 CRC32 0x3f909882  Table_map: `b`.`test` mapped to number 225
# at 3538
#181129  5:07:21 server id 1  end_log_pos 3599 CRC32 0xa6559a3a  Write_rows: table id 225 flags: STMT_END_F

BINLOG '
Wbr/WxMBAAAAMAAAANINAAAAAOEAAAAAAAEAAWIABHRlc3QAAwMPCAIyAAaCmJA/
Wbr/Wx4BAAAAPQAAAA8OAAAAAOEAAAAAAAEAAgADBfwBAAAABQAAAAAAAAD8AgAAAAoAAAAAAAAA
OppVpg==
'/*!*/;
### INSERT INTO `b`.`test`
### SET
###   @1=1
###   @3=5
### INSERT INTO `b`.`test`
### SET
###   @1=2
###   @3=10
# at 3599

If you try again:
TRUNCATE TABLE a.test;
TRUNCATE TABLE b.test;
SET binlog_format="ROW";
insert into a.test(id, age) values (1,5), (2,10); /* This insert event is written with full row image in binary log */ 
insert into b.test(id,age) select id , age from a.test ; /* name column information is not present in row image */

This time it works as expected:
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#181129  9:18:02 server id 1  end_log_pos 123 CRC32 0x9df266b8 	Start: binlog v 4, server v 5.7.18-log created 181129  9:18:02 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
GvX/Ww8BAAAAdwAAAHsAAAABAAQANS43LjE4LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAa9f9bEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
Abhm8p0=
'/*!*/;
# at 123
#181129  9:18:02 server id 1  end_log_pos 154 CRC32 0x804378b2 	Previous-GTIDs
# [empty]
# at 154
#181129 10:08:22 server id 1  end_log_pos 219 CRC32 0x774ecdfe 	Anonymous_GTID	last_committed=0	sequence_number=1	rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 219
#181129 10:08:22 server id 1  end_log_pos 287 CRC32 0x2cc3d729 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1543504102/*!*/;
SET @@session.pseudo_thread_id=3/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1436549152/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 287
#181129 10:08:22 server id 1  end_log_pos 335 CRC32 0x45948473 	Table_map: `b`.`test` mapped to number 109
# at 335
#181129 10:08:22 server id 1  end_log_pos 397 CRC32 0x97acd9f1 	Update_rows: table id 109 flags: STMT_END_F

BINLOG '
5gAAXBMBAAAAMAAAAE8BAAAAAG0AAAAAAAEAAWIABHRlc3QAAwMPCAIyAAZzhJRF
5gAAXB8BAAAAPgAAAI0BAAAAAG0AAAAAAAEAAgAD///6AgAAAAoAAAAAAAAA+gIAAAAPAAAAAAAA
APHZrJc=
'/*!*/;
### UPDATE `b`.`test`
### WHERE
###   @1=2
###   @2=NULL
###   @3=10
### SET
###   @1=2
###   @2=NULL
###   @3=15
# at 397
#181129 10:08:22 server id 1  end_log_pos 428 CRC32 0x8d8f76f1 	Xid = 18
COMMIT/*!*/;
# at 428
#181129 10:09:07 server id 1  end_log_pos 493 CRC32 0xb76ab4c3 	Anonymous_GTID	last_committed=1	sequence_number=2	rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 493
#181129 10:09:07 server id 1  end_log_pos 561 CRC32 0xad2bd698 	Query	thread_id=3	exec_time=0	error_code=0
SET TIMESTAMP=1543504147/*!*/;
BEGIN
/*!*/;
# at 561
#181129 10:09:07 server id 1  end_log_pos 609 CRC32 0xd0df56be 	Table_map: `a`.`test` mapped to number 108
# at 609
#181129 10:09:07 server id 1  end_log_pos 657 CRC32 0x8c95af6d 	Delete_rows: table id 108 flags: STMT_END_F

BINLOG '
EwEAXBMBAAAAMAAAAGECAAAAAGwAAAAAAAEAAWEABHRlc3QAAwMPCAIyAAa+Vt/Q
EwEAXCABAAAAMAAAAJECAAAAAGwAAAAAAAEAAgAD//oBAAAABQAAAAAAAABtr5WM
'/*!*/;
### DELETE FROM `a`.`test`
### WHERE
###   @1=1
###   @2=NULL
###   @3=5
# at 657
#181129 10:09:07 server id 1  end_log_pos 688 CRC32 0x867067f2 	Xid = 19
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*/;

Tested against several versions of 5.6, 5.7 and 8 (with SET TRANSACTION ISOLATION LEVEL READ COMMITTED;).

It doesn't seem to have the same problem with DELETE FROM or a normal INSERT.

Hello James Lawrie,

Thank you for the report!

regards,
Umesh

5.7.24 - test results

Attachment: 93423_5.7.24.results (application/octet-stream, text), 4.43 KiB.

Test results - 5.7.27

Attachment: 93423_5.7.27.results (application/octet-stream, text), 10.32 KiB.

Test results - 5.6.45

Attachment: 93423_5.6.45.results (application/octet-stream, text), 8.45 KiB.

Posted by developer:
 
Changelog entry added for MySQL 8.0.20, 5.7.30, and 5.6.48:

With the settings binlog_format=MIXED, tx_isolation=READ-COMMITTED, and binlog_row_image=FULL, an INSERT ... SELECT query involving a transactional storage engine omitted any columns with a null value from the row image written to the binary log. This happened because when processing INSERT ... SELECT statements, the columns were marked for inserts before the binary logging format was selected. The issue has now been fixed.