MDEV-4645: Incorrect reads of frozen binlog events; FDE corrupted in relay log

  
  Currently several places use description_event->common_header_len instead of
  LOG_EVENT_MINIMAL_HEADER_LEN when parsing events with "frozen" headers (such
  as Start_event_v3 and its subclasses such as Format_description_log_event, as
  well as Rotate_event). This causes events with extra headers (which would otherwise
  be valid and those headers ignored) to be corrupted due to over-reading or skipping
  into the data portion of the log events.
  
  It is rewritten in some details patch of Jeremy Cole (See MDEV):
  - The virtual function returns length to avoid IFs (and only one call of the virtual function made)
  - Printing function avoids printing strings

1 files changed, 337 insertions, 1 deletions

diff --git a/mysql-test/r/mysqlbinlog.result b/mysql-test/r/mysqlbinlog.result
index 3c8b2ab0a17..007ef38b413 100644
--- a/mysql-test/r/mysqlbinlog.result
+++ b/mysql-test/r/mysqlbinlog.result
@@ -630,7 +630,7 @@ We expect this value to be 2 (one for the INSERT, one for COMMIT).
 The bug being tested was that 'Query' lines were not preceded by '#'
 If the line is in the table, it had to have been preceded by a '#'
 
-SELECT COUNT(*) AS `BUG#28293_expect_2` FROM patch WHERE a LIKE '%Query%';
+SELECT COUNT(*) AS `BUG#28293_expect_2` FROM patch WHERE a LIKE '#%Query%';
 BUG#28293_expect_2
 2
 DROP TABLE patch;
@@ -914,3 +914,339 @@ t1
 SHOW TABLES IN test;
 Tables_in_test
 SET GLOBAL SERVER_ID = 1;
+#
+# MDEV-4645: Incorrect reads of frozen binlog events;
+# FDE corrupted in relay log
+#
+/*!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 4
+#130807 23:29:20 server id 1  end_log_pos 106 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#        4  |20 ae 02 52 |0f   |01 00 00 00 |66 00 00 00 |6a 00 00 00 |00 01
+#
+#       17  04 00 35 2e 31 2e 36 33  2d 67 6f 6f 67 6c 65 2d  |..5.1.63-google-|
+#       27  64 65 62 75 67 2d 6c 6f  67 00 00 00 00 00 00 00  |debug-log.......|
+#       37  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
+#       47  00 00 00 00 20 ae 02 52  17 38 0d 00 08 00 12 00  |.... ..R.8......|
+#       57  04 04 04 04 12 00 00 53  00 04 1a 08 00 00 00 08  |.......S........|
+#       67  08 08 02                                          |...|
+#
+# Event: 	Start: binlog v 4, server v 5.1.63-google-debug-log created 130807 23:29:20 at startup
+ROLLBACK/*!*/;
+BINLOG '
+IK4CUg8BAAAAZgAAAGoAAAAAAQQANS4xLjYzLWdvb2dsZS1kZWJ1Zy1sb2cAAAAAAAAAAAAAAAAA
+AAAAAAAAAAAAAAAAAAAgrgJSFzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
+'/*!*/;
+# at 106
+#130807 23:29:24 server id 1  end_log_pos 207 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#       6a  |24 ae 02 52 |02   |01 00 00 00 |65 00 00 00 |cf 00 00 00 |00 00
+#
+#       81  01 00 00 00 00 00 00 00  00 00 00 1a 00 00 00 40  |...............@|
+#       91  00 00 01 00 00 00 00 00  00 00 00 06 03 73 74 64  |.............std|
+#       a1  04 08 00 08 00 08 00 00  63 72 65 61 74 65 20 74  |........create t|
+#       b1  61 62 6c 65 20 74 65 73  74 2e 74 31 20 28 69 64  |able test.t1 (id|
+#       c1  20 69 6e 74 20 6e 6f 74  20 6e 75 6c 6c 29        | int not null)|
+#
+# Event: 	Query	thread_id=1	exec_time=0	error_code=0
+SET TIMESTAMP=1375907364/*!*/;
+SET @@session.pseudo_thread_id=1/*!*/;
+SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
+SET @@session.sql_mode=0/*!*/;
+SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
+/*!\C latin1 *//*!*/;
+SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
+SET @@session.lc_time_names=0/*!*/;
+SET @@session.collation_database=DEFAULT/*!*/;
+create table test.t1 (id int not null)
+/*!*/;
+# at 207
+#130807 23:29:26 server id 1  end_log_pos 305 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#       cf  |26 ae 02 52 |02   |01 00 00 00 |62 00 00 00 |31 01 00 00 |00 00
+#
+#       e6  01 00 00 00 00 00 00 00  00 00 00 1a 00 00 00 40  |...............@|
+#       f6  00 00 01 00 00 00 00 00  00 00 00 06 03 73 74 64  |.............std|
+#      106  04 08 00 08 00 08 00 00  69 6e 73 65 72 74 20 69  |........insert i|
+#      116  6e 74 6f 20 74 65 73 74  2e 74 31 20 28 69 64 29  |nto test.t1 (id)|
+#      126  20 76 61 6c 75 65 73 20  28 31 29                 | values (1)|
+#
+# Event: 	Query	thread_id=1	exec_time=0	error_code=0
+SET TIMESTAMP=1375907366/*!*/;
+insert into test.t1 (id) values (1)
+/*!*/;
+# at 305
+#130807 23:29:28 server id 1  end_log_pos 386 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#      131  |28 ae 02 52 |02   |01 00 00 00 |51 00 00 00 |82 01 00 00 |00 00
+#
+#      148  01 00 00 00 00 00 00 00  00 00 00 1a 00 00 00 40  |...............@|
+#      158  00 00 01 00 00 00 00 00  00 00 00 06 03 73 74 64  |.............std|
+#      168  04 08 00 08 00 08 00 00  64 72 6f 70 20 74 61 62  |........drop tab|
+#      178  6c 65 20 74 65 73 74 2e  74 31                    |le test.t1|
+#
+# Event: 	Query	thread_id=1	exec_time=0	error_code=0
+SET TIMESTAMP=1375907368/*!*/;
+drop table test.t1
+/*!*/;
+DELIMITER ;
+# End of log file
+ROLLBACK /* added by mysqlbinlog */;
+/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
+/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
+/*!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 4
+#130807 23:25:35 server id 1  end_log_pos 106 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#        4  |3f ad 02 52 |0f   |01 00 00 00 |66 00 00 00 |6a 00 00 00 |00 00
+#
+#       17  04 00 35 2e 31 2e 36 33  2d 67 6f 6f 67 6c 65 2d  |..5.1.63-google-|
+#       27  64 65 62 75 67 2d 6c 6f  67 00 00 00 00 00 00 00  |debug-log.......|
+#       37  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
+#       47  00 00 00 00 3f ad 02 52  1b 38 0d 00 08 00 12 00  |....?..R.8......|
+#       57  04 04 04 04 12 00 00 53  00 04 1a 08 00 00 00 08  |.......S........|
+#       67  08 08 02                                          |...|
+#
+# Event: 	Start: binlog v 4, server v 5.1.63-google-debug-log created 130807 23:25:35 at startup
+ROLLBACK/*!*/;
+BINLOG '
+P60CUg8BAAAAZgAAAGoAAAAAAAQANS4xLjYzLWdvb2dsZS1kZWJ1Zy1sb2cAAAAAAAAAAAAAAAAA
+AAAAAAAAAAAAAAAAAAA/rQJSGzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
+'/*!*/;
+# at 106
+#130807 23:25:41 server id 1  end_log_pos 211 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#       6a  |45 ad 02 52 |02   |01 00 00 00 |69 00 00 00 |d3 00 00 00 |00 00
+#
+#       85  01 00 00 00 01 00 00 00  00 00 00 1a 00 00 00 40  |...............@|
+#       95  00 00 01 00 00 00 00 00  00 00 00 06 03 73 74 64  |.............std|
+#       a5  04 08 00 08 00 08 00 00  63 72 65 61 74 65 20 74  |........create t|
+#       b5  61 62 6c 65 20 74 65 73  74 2e 74 31 20 28 69 64  |able test.t1 (id|
+#       c5  20 69 6e 74 20 6e 6f 74  20 6e 75 6c 6c 29        | int not null)|
+#
+# Event: 	Query	thread_id=1	exec_time=1	error_code=0
+SET TIMESTAMP=1375907141/*!*/;
+SET @@session.pseudo_thread_id=1/*!*/;
+SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
+SET @@session.sql_mode=0/*!*/;
+SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
+/*!\C latin1 *//*!*/;
+SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
+SET @@session.lc_time_names=0/*!*/;
+SET @@session.collation_database=DEFAULT/*!*/;
+create table test.t1 (id int not null)
+/*!*/;
+# at 211
+#130807 23:25:44 server id 1  end_log_pos 313 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#       d3  |48 ad 02 52 |02   |01 00 00 00 |66 00 00 00 |39 01 00 00 |00 00
+#
+#       ee  01 00 00 00 00 00 00 00  00 00 00 1a 00 00 00 40  |...............@|
+#       fe  00 00 01 00 00 00 00 00  00 00 00 06 03 73 74 64  |.............std|
+#      10e  04 08 00 08 00 08 00 00  69 6e 73 65 72 74 20 69  |........insert i|
+#      11e  6e 74 6f 20 74 65 73 74  2e 74 31 20 28 69 64 29  |nto test.t1 (id)|
+#      12e  20 76 61 6c 75 65 73 20  28 31 29                 | values (1)|
+#
+# Event: 	Query	thread_id=1	exec_time=0	error_code=0
+SET TIMESTAMP=1375907144/*!*/;
+insert into test.t1 (id) values (1)
+/*!*/;
+# at 313
+#130807 23:25:48 server id 1  end_log_pos 398 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#      139  |4c ad 02 52 |02   |01 00 00 00 |55 00 00 00 |8e 01 00 00 |00 00
+#
+#      154  01 00 00 00 00 00 00 00  00 00 00 1a 00 00 00 40  |...............@|
+#      164  00 00 01 00 00 00 00 00  00 00 00 06 03 73 74 64  |.............std|
+#      174  04 08 00 08 00 08 00 00  64 72 6f 70 20 74 61 62  |........drop tab|
+#      184  6c 65 20 74 65 73 74 2e  74 31                    |le test.t1|
+#
+# Event: 	Query	thread_id=1	exec_time=0	error_code=0
+SET TIMESTAMP=1375907148/*!*/;
+drop table test.t1
+/*!*/;
+DELIMITER ;
+# End of log file
+ROLLBACK /* added by mysqlbinlog */;
+/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
+/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
+/*!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 4
+#130807 23:20:55 server id 1  end_log_pos 106 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#        4  |27 ac 02 52 |0f   |01 00 00 00 |66 00 00 00 |6a 00 00 00 |00 01
+#
+#       17  04 00 35 2e 31 2e 36 33  2d 67 6f 6f 67 6c 65 2d  |..5.1.63-google-|
+#       27  64 65 62 75 67 2d 6c 6f  67 00 00 00 00 00 00 00  |debug-log.......|
+#       37  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
+#       47  00 00 00 00 27 ac 02 52  1f 38 0d 00 08 00 12 00  |....'..R.8......|
+#       57  04 04 04 04 12 00 00 53  00 04 1a 08 00 00 00 08  |.......S........|
+#       67  08 08 02                                          |...|
+#
+# Event: 	Start: binlog v 4, server v 5.1.63-google-debug-log created 130807 23:20:55 at startup
+ROLLBACK/*!*/;
+BINLOG '
+J6wCUg8BAAAAZgAAAGoAAAAAAQQANS4xLjYzLWdvb2dsZS1kZWJ1Zy1sb2cAAAAAAAAAAAAAAAAA
+AAAAAAAAAAAAAAAAAAAnrAJSHzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
+'/*!*/;
+# at 106
+#130807 23:21:19 server id 1  end_log_pos 215 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#       6a  |3f ac 02 52 |02   |01 00 00 00 |6d 00 00 00 |d7 00 00 00 |00 00
+#
+#       89  01 00 00 00 00 00 00 00  00 00 00 1a 00 00 00 40  |...............@|
+#       99  00 00 01 00 00 00 00 00  00 00 00 06 03 73 74 64  |.............std|
+#       a9  04 08 00 08 00 08 00 00  63 72 65 61 74 65 20 74  |........create t|
+#       b9  61 62 6c 65 20 74 65 73  74 2e 74 31 20 28 69 64  |able test.t1 (id|
+#       c9  20 69 6e 74 20 6e 6f 74  20 6e 75 6c 6c 29        | int not null)|
+#
+# Event: 	Query	thread_id=1	exec_time=0	error_code=0
+SET TIMESTAMP=1375906879/*!*/;
+SET @@session.pseudo_thread_id=1/*!*/;
+SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
+SET @@session.sql_mode=0/*!*/;
+SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
+/*!\C latin1 *//*!*/;
+SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
+SET @@session.lc_time_names=0/*!*/;
+SET @@session.collation_database=DEFAULT/*!*/;
+create table test.t1 (id int not null)
+/*!*/;
+# at 215
+#130807 23:21:31 server id 1  end_log_pos 321 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#       d7  |4b ac 02 52 |02   |01 00 00 00 |6a 00 00 00 |41 01 00 00 |00 00
+#
+#       f6  01 00 00 00 00 00 00 00  00 00 00 1a 00 00 00 40  |...............@|
+#      106  00 00 01 00 00 00 00 00  00 00 00 06 03 73 74 64  |.............std|
+#      116  04 08 00 08 00 08 00 00  69 6e 73 65 72 74 20 69  |........insert i|
+#      126  6e 74 6f 20 74 65 73 74  2e 74 31 20 28 69 64 29  |nto test.t1 (id)|
+#      136  20 76 61 6c 75 65 73 20  28 31 29                 | values (1)|
+#
+# Event: 	Query	thread_id=1	exec_time=0	error_code=0
+SET TIMESTAMP=1375906891/*!*/;
+insert into test.t1 (id) values (1)
+/*!*/;
+# at 321
+#130807 23:21:41 server id 1  end_log_pos 410 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#      141  |55 ac 02 52 |02   |01 00 00 00 |59 00 00 00 |9a 01 00 00 |00 00
+#
+#      160  01 00 00 00 00 00 00 00  00 00 00 1a 00 00 00 40  |...............@|
+#      170  00 00 01 00 00 00 00 00  00 00 00 06 03 73 74 64  |.............std|
+#      180  04 08 00 08 00 08 00 00  64 72 6f 70 20 74 61 62  |........drop tab|
+#      190  6c 65 20 74 65 73 74 2e  74 31                    |le test.t1|
+#
+# Event: 	Query	thread_id=1	exec_time=0	error_code=0
+SET TIMESTAMP=1375906901/*!*/;
+drop table test.t1
+/*!*/;
+DELIMITER ;
+# End of log file
+ROLLBACK /* added by mysqlbinlog */;
+/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
+/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
+/*!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 4
+#130807 23:38:51 server id 1  end_log_pos 106 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#        4  |5b b0 02 52 |0f   |01 00 00 00 |66 00 00 00 |6a 00 00 00 |00 00
+#
+#       17  04 00 35 2e 31 2e 36 33  2d 67 6f 6f 67 6c 65 2d  |..5.1.63-google-|
+#       27  64 65 62 75 67 2d 6c 6f  67 00 00 00 00 00 00 00  |debug-log.......|
+#       37  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
+#       47  00 00 00 00 5b b0 02 52  13 38 0d 00 08 00 12 00  |....[..R.8......|
+#       57  04 04 04 04 12 00 00 53  00 04 1a 08 00 00 00 08  |.......S........|
+#       67  08 08 02                                          |...|
+#
+# Event: 	Start: binlog v 4, server v 5.1.63-google-debug-log created 130807 23:38:51 at startup
+ROLLBACK/*!*/;
+BINLOG '
+W7ACUg8BAAAAZgAAAGoAAAAAAAQANS4xLjYzLWdvb2dsZS1kZWJ1Zy1sb2cAAAAAAAAAAAAAAAAA
+AAAAAAAAAAAAAAAAAABbsAJSEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC
+'/*!*/;
+# at 106
+#130807 23:38:53 server id 1  end_log_pos 203 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#       6a  |5d b0 02 52 |02   |01 00 00 00 |61 00 00 00 |cb 00 00 00 |00 00
+#
+#       7d  01 00 00 00 00 00 00 00  00 00 00 1a 00 00 00 40  |...............@|
+#       8d  00 00 01 00 00 00 00 00  00 00 00 06 03 73 74 64  |.............std|
+#       9d  04 08 00 08 00 08 00 00  63 72 65 61 74 65 20 74  |........create t|
+#       ad  61 62 6c 65 20 74 65 73  74 2e 74 31 20 28 69 64  |able test.t1 (id|
+#       bd  20 69 6e 74 20 6e 6f 74  20 6e 75 6c 6c 29        | int not null)|
+#
+# Event: 	Query	thread_id=1	exec_time=0	error_code=0
+SET TIMESTAMP=1375907933/*!*/;
+SET @@session.pseudo_thread_id=1/*!*/;
+SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
+SET @@session.sql_mode=0/*!*/;
+SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
+/*!\C latin1 *//*!*/;
+SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
+SET @@session.lc_time_names=0/*!*/;
+SET @@session.collation_database=DEFAULT/*!*/;
+create table test.t1 (id int not null)
+/*!*/;
+# at 203
+#130807 23:38:55 server id 1  end_log_pos 297 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#       cb  |5f b0 02 52 |02   |01 00 00 00 |5e 00 00 00 |29 01 00 00 |00 00
+#
+#       de  01 00 00 00 00 00 00 00  00 00 00 1a 00 00 00 40  |...............@|
+#       ee  00 00 01 00 00 00 00 00  00 00 00 06 03 73 74 64  |.............std|
+#       fe  04 08 00 08 00 08 00 00  69 6e 73 65 72 74 20 69  |........insert i|
+#      10e  6e 74 6f 20 74 65 73 74  2e 74 31 20 28 69 64 29  |nto test.t1 (id)|
+#      11e  20 76 61 6c 75 65 73 20  28 31 29                 | values (1)|
+#
+# Event: 	Query	thread_id=1	exec_time=0	error_code=0
+SET TIMESTAMP=1375907935/*!*/;
+insert into test.t1 (id) values (1)
+/*!*/;
+# at 297
+#130807 23:38:57 server id 1  end_log_pos 374 
+# Position
+#           |Timestamp   |Type |Master ID   |Size        |Master Pos  |Flags
+#      129  |61 b0 02 52 |02   |01 00 00 00 |4d 00 00 00 |76 01 00 00 |00 00
+#
+#      13c  01 00 00 00 00 00 00 00  00 00 00 1a 00 00 00 40  |...............@|
+#      14c  00 00 01 00 00 00 00 00  00 00 00 06 03 73 74 64  |.............std|
+#      15c  04 08 00 08 00 08 00 00  64 72 6f 70 20 74 61 62  |........drop tab|
+#      16c  6c 65 20 74 65 73 74 2e  74 31                    |le test.t1|
+#
+# Event: 	Query	thread_id=1	exec_time=0	error_code=0
+SET TIMESTAMP=1375907937/*!*/;
+drop table test.t1
+/*!*/;
+DELIMITER ;
+# End of log file
+ROLLBACK /* added by mysqlbinlog */;
+/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
+/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;