Bug #88791 Binary log for generated columncontains new value as WHERE clause, not old value
Submitted: 6 Dec 2017 15:38 Modified: 8 Dec 2017 13:05
Reporter: MC Brown Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Row Based Replication ( RBR ) Severity:S2 (Serious)
Version:5.7.20 OS:Ubuntu
Assigned to: CPU Architecture:Any

[6 Dec 2017 15:38] MC Brown 
Description:
If you insert data into a simple table with a generated column and ROW based logging enabled, then update the ROW you have just inserted, the information recorded into the binary log contains the NEW data as the WHERE clause for the generated column, not the old version.

Native replication operates successfully. 

A verbose output from the mysqlbinlog also shows the new value in the WHERE clause, not the old value:

### UPDATE `gctest`.`t`
### WHERE
###   @1=1
###   @2='\x0c\x03abc'
###   @3='\x02\x01\x00\x0b\x00\x0c\x07\x00\x03def'
### SET
###   @1=1
###   @2='\x0c\x03def'
###   @3='\x02\x01\x00\x0b\x00\x0c\x07\x00\x03def'

You can see above that field 3 shows the NEW value in the WHERE clause as well as the SET clause, not the previously generated and stored value.

If you create a table on a slave that stores the values (i.e. no generated column): 

CREATE TABLE t(id INT, j JSON, gc JSON);

And then dump the mysqlbinlog and try applying the output to that table, the update will fail because the stored data does not match the incoming WHERE clause. 

How to repeat:
Flush the binary log, then create a database, table, row, and update statement, then examine the output from mysqlbinlog and optionally try applying tit to another server: 

flush binary logs;
create database gctest;
CREATE TABLE `t` (   `id` int(11) DEFAULT NULL,   `j` json DEFAULT NULL,   `gc` json GENERATED ALWAYS AS (json_array(`j`)) VIRTUAL);
insert into t (id,j) values (1,'"abc"');
update t set j = '"def"' where id = 1;

Now dump the binary log with mysqlbinlog: 

 mysqlbinlog -v /var/log/mysql/mysql-bin.000052 

And then examine the output: 

mysqlbinlog -v /var/log/mysql/mysql-bin.000052
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#171206 15:19:12 server id 366  end_log_pos 123 CRC32 0x691b8441 	Start: binlog v 4, server v 5.7.20-0ubuntu0.17.10.1-log created 171206 15:19:12
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
cAooWg9uAQAAdwAAAHsAAAABAAQANS43LjIwLTB1YnVudHUwLjE3LjEwLjEtbG9nAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AUGEG2k=
'/*!*/;
# at 123
#171206 15:19:12 server id 366  end_log_pos 154 CRC32 0xbf154903 	Previous-GTIDs
# [empty]
# at 154
#171206 15:19:24 server id 366  end_log_pos 219 CRC32 0x0c6984ab 	Anonymous_GTID	last_committed=0	sequence_number=1	rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 219
#171206 15:19:24 server id 366  end_log_pos 319 CRC32 0x8c9a5f89 	Query	thread_id=432	exec_time=0	error_code=0
SET TIMESTAMP=1512573564/*!*/;
SET @@session.pseudo_thread_id=432/*!*/;
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/*!*/;
create database gctest
/*!*/;
# at 319
#171206 15:20:05 server id 366  end_log_pos 384 CRC32 0x81f109b7 	Anonymous_GTID	last_committed=1	sequence_number=2	rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 384
#171206 15:20:05 server id 366  end_log_pos 593 CRC32 0x72e9e418 	Query	thread_id=432	exec_time=1	error_code=0
use `gctest`/*!*/;
SET TIMESTAMP=1512573605/*!*/;
CREATE TABLE `t` (   `id` int(11) DEFAULT NULL,   `j` json DEFAULT NULL,   `gc` json GENERATED ALWAYS AS (json_array(`j`)) VIRTUAL)
/*!*/;
# at 593
#171206 15:20:19 server id 366  end_log_pos 658 CRC32 0x0e705e57 	Anonymous_GTID	last_committed=2	sequence_number=3	rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 658
#171206 15:20:19 server id 366  end_log_pos 732 CRC32 0x7311beb6 	Query	thread_id=432	exec_time=0	error_code=0
SET TIMESTAMP=1512573619/*!*/;
BEGIN
/*!*/;
# at 732
#171206 15:20:19 server id 366  end_log_pos 782 CRC32 0xc9510242 	Table_map: `gctest`.`t` mapped to number 271
# at 782
#171206 15:20:19 server id 366  end_log_pos 847 CRC32 0x19a03d0d 	Write_rows: table id 271 flags: STMT_END_F

BINLOG '
swooWhNuAQAAMgAAAA4DAAAAAA8BAAAAAAEABmdjdGVzdAABdAADA/X1AgQEB0ICUck=
swooWh5uAQAAQQAAAE8DAAAAAA8BAAAAAAEAAgAD//gBAAAABQAAAAwDYWJjDAAAAAIBAAsADAcA
A2FiYw09oBk=
'/*!*/;
### INSERT INTO `gctest`.`t`
### SET
###   @1=1
###   @2='\x0c\x03abc'
###   @3='\x02\x01\x00\x0b\x00\x0c\x07\x00\x03abc'
# at 847
#171206 15:20:19 server id 366  end_log_pos 878 CRC32 0x785bbf1f 	Xid = 1800
COMMIT/*!*/;
# at 878
#171206 15:20:33 server id 366  end_log_pos 943 CRC32 0xd2235341 	Anonymous_GTID	last_committed=3	sequence_number=4	rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 943
#171206 15:20:33 server id 366  end_log_pos 1017 CRC32 0x519ce086 	Query	thread_id=432	exec_time=0	error_code=0
SET TIMESTAMP=1512573633/*!*/;
BEGIN
/*!*/;
# at 1017
#171206 15:20:33 server id 366  end_log_pos 1067 CRC32 0x4bfa99e5 	Table_map: `gctest`.`t` mapped to number 271
# at 1067
#171206 15:20:33 server id 366  end_log_pos 1163 CRC32 0x6292f564 	Update_rows: table id 271 flags: STMT_END_F

BINLOG '
wQooWhNuAQAAMgAAACsEAAAAAA8BAAAAAAEABmdjdGVzdAABdAADA/X1AgQEB+WZ+ks=
wQooWh9uAQAAYAAAAIsEAAAAAA8BAAAAAAEAAgAD///4AQAAAAUAAAAMA2FiYwwAAAACAQALAAwH
AANkZWb4AQAAAAUAAAAMA2RlZgwAAAACAQALAAwHAANkZWZk9ZJi
'/*!*/;
### UPDATE `gctest`.`t`
### WHERE
###   @1=1
###   @2='\x0c\x03abc'
###   @3='\x02\x01\x00\x0b\x00\x0c\x07\x00\x03def'
### SET
###   @1=1
###   @2='\x0c\x03def'
###   @3='\x02\x01\x00\x0b\x00\x0c\x07\x00\x03def'
# at 1163
#171206 15:20:33 server id 366  end_log_pos 1194 CRC32 0x2a596d3e 	Xid = 1814
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*/;

Suggested fix:
The generated column for the old value is probably being computed at the time the binlog entry is being generated, instead of taking the previously stored and generated value when the data was inserted. 

Instead of re-generating the generated column according to the update statement, the stored value should be used.
[8 Dec 2017 10:22] MySQL Verification Team 
Hello MC Brown,

Thank you for the report and test case.
Observed that @3 is same in both the cases and looks like verbose is computing it wrongly. But haven't seen any issue while restoring from the bin log. 

Thanks,
Umesh
[8 Dec 2017 10:23] MySQL Verification Team 
test results

Attachment: 88791_5.7.20.results (application/octet-stream, text), 5.46 KiB.
[8 Dec 2017 13:05] MC Brown 
Thanks Umesh. 

For the applier test, create a table on the slave: 

CREATE TABLE t(id INT, j JSON, gc JSON);

Then try applying by doing: 

mysqldump BINLOG|mysql -h slave 

Then you will get the record not found error. 

The mysqlbinlog dump is why I flushed the logs before hand to make it easy to see the output.