#At file:///home/daogangqu/mysql/bzrwork1/bug55790/mysql-next-mr-bugfixing/ based on revid:dao-gang.qu@stripped
3324 Dao-Gang.Qu@stripped 2010-10-19
Bug #55790 Read_Master_Log_Pos is wrong after Slave_IO_Error= ER_NET_PACKET_TOO_LARGE
When logging in row format, DML is written as a Table_map_event
followed by its row events. The Table_map_event is written to
the relay log by slave I/O thread even if its rows events are
discarded. But it is not displayed by MYSQLBINLOG. However,
the Read_Master_Log_Pos displayed by SHOW SLAVE STATUS is
at the end of the Table_map_Log_event.
After the patch, the Table_map_log_event will be displayed by
MYSQLBINLOG so long as it was written to the relay log even
if its rows events are discarded. To multi rows events in one
statement, the headers of other rows events also will be
displayed if the last rows event is discarded by slave I/O
thread. And MYSQLBINLOG will print a warning for the missed
rows event.
@ client/mysqlbinlog.cc
Add code to print a warning if the body cache is nonempty
after a binlog has been processed.
@ mysql-test/suite/rpl/r/rpl_packet.result
Test result for Bug #55790
@ mysql-test/suite/rpl/r/rpl_row_ignorable_event.result
Updated for the patch of Bug #55790.
@ mysql-test/suite/rpl/t/rpl_packet.test
Added test to verify if the the Table_map_log_event will
be displayed by MYSQLBINLOG so long as it was written to
the relay log, even if its rows events are discarded. And
MYSQLBINLOG will print a warning for the missed rows event.
@ sql/log_event.cc
Added code to sync the Table_map_log_event and the header
of every rows event to file from catch directly instead of
waiting for all rows events of one statement together.
modified:
client/mysqlbinlog.cc
mysql-test/suite/rpl/r/rpl_packet.result
mysql-test/suite/rpl/r/rpl_row_ignorable_event.result
mysql-test/suite/rpl/t/rpl_packet.test
sql/log_event.cc
=== modified file 'client/mysqlbinlog.cc'
--- a/client/mysqlbinlog.cc 2010-09-01 02:51:08 +0000
+++ b/client/mysqlbinlog.cc 2010-10-19 08:06:26 +0000
@@ -1469,6 +1469,9 @@ static Exit_status dump_log_entries(cons
rc= (remote_opt ? dump_remote_log_entries(&print_event_info, logname) :
dump_local_log_entries(&print_event_info, logname));
+ if (my_b_tell(&print_event_info.body_cache))
+ fprintf(result_file, "Warning: There are rows events missed here. \n");
+
/* Set delimiter back to semicolon */
if (!raw_mode)
{
=== modified file 'mysql-test/suite/rpl/r/rpl_packet.result'
--- a/mysql-test/suite/rpl/r/rpl_packet.result 2010-07-20 15:27:13 +0000
+++ b/mysql-test/suite/rpl/r/rpl_packet.result 2010-10-19 08:06:26 +0000
@@ -57,6 +57,34 @@ SHOW BINLOG EVENTS;
SET @max_allowed_packet_1= @@session.max_allowed_packet;
SHOW BINLOG EVENTS;
SET @max_allowed_packet_2= @@session.max_allowed_packet;
+START SLAVE;
+DROP TABLE t1;
+select @@global.max_allowed_packet;
+@@global.max_allowed_packet
+4096
+select @@global.net_buffer_length;
+@@global.net_buffer_length
+4096
+select @@global.max_allowed_packet;
+@@global.max_allowed_packet
+1024
+select @@global.net_buffer_length;
+@@global.net_buffer_length
+1024
+CREATE TABLE t1 (a TEXT) ENGINE=MyISAM;
+INSERT INTO t1 VALUES (REPEAT('a', 2048));
+# 1153 = ER_NET_PACKET_TOO_LARGE
+Last_IO_Error = Got a packet bigger than 'max_allowed_packet' bytes
+# Now Read_Master_Log_Pos is as following:
+Read_Master_Log_Pos 424
+# Test the Table_map_log_event is dispalyed at Read_Master_Log_Pos by MYSQLBINLOG
+Last event in relay log:
+#server id # end_log_pos 424 Table_map: `test`.`t1` mapped to number #
+Warning: There are rows events missed here.
+DELIMITER ;
+# End of log file
+ROLLBACK /* added by mysqlbinlog */;
+/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
==== clean up ====
DROP TABLE t1;
SET @@global.max_allowed_packet= 1024;
=== modified file 'mysql-test/suite/rpl/r/rpl_row_ignorable_event.result'
--- a/mysql-test/suite/rpl/r/rpl_row_ignorable_event.result 2010-09-01 02:51:08 +0000
+++ b/mysql-test/suite/rpl/r/rpl_row_ignorable_event.result 2010-10-19 08:06:26 +0000
@@ -173,8 +173,8 @@ BEGIN
#server id # end_log_pos # Rows_query
# insert into t1(a,b) values(1,1),(2,1)
# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t1` mapped to number #
+# at #
#server id # end_log_pos # Write_rows: table id # flags: STMT_END_F
### INSERT INTO test.t1
### SET
@@ -198,8 +198,8 @@ BEGIN
#server id # end_log_pos # Rows_query
# update t1 set a = a + 5 where b = 1 LIMIT 1
# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t1` mapped to number #
+# at #
#server id # end_log_pos # Update_rows: table id # flags: STMT_END_F
### UPDATE test.t1
### WHERE
@@ -222,8 +222,8 @@ BEGIN
#server id # end_log_pos # Rows_query
# delete from t1 where a = 6
# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t1` mapped to number #
+# at #
#server id # end_log_pos # Delete_rows: table id # flags: STMT_END_F
### DELETE FROM test.t1
### WHERE
@@ -248,8 +248,8 @@ BEGIN
#server id # end_log_pos # Rows_query
# insert into t2(a,b) values(2,1),(3,1)
# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t2` mapped to number #
+# at #
#server id # end_log_pos # Write_rows: table id # flags: STMT_END_F
### INSERT INTO test.t2
### SET
@@ -263,8 +263,8 @@ BEGIN
#server id # end_log_pos # Rows_query
# update t2 set a = a + 5 where b = 1
# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t2` mapped to number #
+# at #
#server id # end_log_pos # Update_rows: table id # flags: STMT_END_F
### UPDATE test.t2
### WHERE
@@ -284,8 +284,8 @@ BEGIN
#server id # end_log_pos # Rows_query
# delete from t2 where a = 7
# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t2` mapped to number #
+# at #
#server id # end_log_pos # Delete_rows: table id # flags: STMT_END_F
### DELETE FROM test.t2
### WHERE
@@ -303,8 +303,8 @@ BEGIN
#server id # end_log_pos # Rows_query
# insert into t1(a,b) values(1,5)
# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t1` mapped to number #
+# at #
#server id # end_log_pos # Write_rows: table id # flags: STMT_END_F
### INSERT INTO test.t1
### SET
@@ -324,8 +324,8 @@ BEGIN
#server id # end_log_pos # Rows_query
# insert into t1(a,b) values(1,7)
# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t1` mapped to number #
+# at #
#server id # end_log_pos # Write_rows: table id # flags: STMT_END_F
### INSERT INTO test.t1
### SET
@@ -345,8 +345,8 @@ BEGIN
#server id # end_log_pos # Rows_query
# insert into t2(a,b) values(2,5)
# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t2` mapped to number #
+# at #
#server id # end_log_pos # Write_rows: table id # flags: STMT_END_F
### INSERT INTO test.t2
### SET
@@ -356,8 +356,8 @@ BEGIN
#server id # end_log_pos # Rows_query
# insert into t2(a,b) values(2,6)
# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t2` mapped to number #
+# at #
#server id # end_log_pos # Write_rows: table id # flags: STMT_END_F
### INSERT INTO test.t2
### SET
@@ -395,8 +395,8 @@ BEGIN
#server id # end_log_pos # Rows_query
# insert into t3(a, b) values(1,1)
# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t3` mapped to number #
+# at #
#server id # end_log_pos # Write_rows: table id # flags: STMT_END_F
### INSERT INTO test.t3
### SET
@@ -416,8 +416,8 @@ BEGIN
#server id # end_log_pos # Rows_query
# insert into t4(a, b) values(2,1)
# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t4` mapped to number #
+# at #
#server id # end_log_pos # Write_rows: table id # flags: STMT_END_F
### INSERT INTO test.t4
### SET
@@ -437,12 +437,12 @@ BEGIN
#server id # end_log_pos # Rows_query
# update t3,t4 set t3.a=3, t4.a=4 where t3.b=t4.b
# at #
-# at #
-# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t3` mapped to number #
+# at #
#server id # end_log_pos # Table_map: `test`.`t4` mapped to number #
+# at #
#server id # end_log_pos # Update_rows: table id #
+# at #
#server id # end_log_pos # Update_rows: table id # flags: STMT_END_F
### UPDATE test.t3
### WHERE
@@ -472,8 +472,8 @@ BEGIN
#server id # end_log_pos # Rows_query
# insert into t5(a, b) values(3,1)
# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t5` mapped to number #
+# at #
#server id # end_log_pos # Write_rows: table id # flags: STMT_END_F
### INSERT INTO test.t5
### SET
@@ -493,10 +493,10 @@ BEGIN
#server id # end_log_pos # Rows_query
# update t4,t5 set t4.a=4, t5.a=5 where t4.b=t5.b
# at #
-# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t4` mapped to number #
+# at #
#server id # end_log_pos # Table_map: `test`.`t5` mapped to number #
+# at #
#server id # end_log_pos # Update_rows: table id # flags: STMT_END_F
### UPDATE test.t5
### WHERE
@@ -519,8 +519,8 @@ BEGIN
#server id # end_log_pos # Rows_query
# insert delayed into t3(a,b) values(1,5),(1,6),(1,7)
# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t3` mapped to number #
+# at #
#server id # end_log_pos # Write_rows: table id # flags: STMT_END_F
### INSERT INTO test.t3
### SET
@@ -553,10 +553,10 @@ BEGIN
#server id # end_log_pos # Rows_query
# load data infile '../../std_data/words.dat' into table t6
# at #
-# at #
-# at #
#server id # end_log_pos # Table_map: `test`.`t6` mapped to number #
+# at #
#server id # end_log_pos # Write_rows: table id #
+# at #
#server id # end_log_pos # Write_rows: table id # flags: STMT_END_F
### INSERT INTO test.t6
### SET
=== modified file 'mysql-test/suite/rpl/t/rpl_packet.test'
--- a/mysql-test/suite/rpl/t/rpl_packet.test 2010-08-06 08:54:01 +0000
+++ b/mysql-test/suite/rpl/t/rpl_packet.test 2010-10-19 08:06:26 +0000
@@ -152,6 +152,51 @@ if (`SELECT NOT(@max_allowed_packet_0 =
--die @max_allowed_packet changed after executing SHOW BINLOG EVENTS
}
+#
+# BUG#55790
+# This test verifies if the the Table_map_log_event will
+# be displayed by MYSQLBINLOG so long as it was written
+# to the relay log, even if its rows events are discarded.
+#
+
+connection slave;
+START SLAVE;
+--source include/wait_for_slave_to_start.inc
+
+connection master;
+DROP TABLE t1;
+select @@global.max_allowed_packet;
+select @@global.net_buffer_length;
+sync_slave_with_master;
+select @@global.max_allowed_packet;
+select @@global.net_buffer_length;
+
+--connection master
+CREATE TABLE t1 (a TEXT) ENGINE=MyISAM;
+--sync_slave_with_master
+
+# Create big row event.
+--connection master
+INSERT INTO t1 VALUES (REPEAT('a', 2048));
+
+# Slave IO thread should stop with error when trying to read the big event.
+--connection slave
+--echo # 1153 = ER_NET_PACKET_TOO_LARGE
+--let $slave_io_errno= 1153
+--let $show_slave_io_error= 1
+--source include/wait_for_slave_io_error.inc
+
+--echo # Now Read_Master_Log_Pos is as following:
+--let $status_items= Read_Master_Log_Pos
+--source include/show_slave_status.inc
+
+--echo # Test the Table_map_log_event is dispalyed at Read_Master_Log_Pos by MYSQLBINLOG
+--let $MYSQLD_DATADIR= `SELECT @@datadir`
+--echo Last event in relay log:
+--let $binlog_file= query_get_value(SHOW SLAVE STATUS, Relay_Log_File, 1)
+--replace_regex /#[0-9]*[ ]*[0-9]*:[0-9]*:[0-9]* server id [0-9]*/#server id #/ /mapped to number [0-9]*/mapped to number #/
+exec $MYSQL_BINLOG $MYSQLD_DATADIR/$binlog_file
+ | tail -n 6;
--echo ==== clean up ====
connection master;
=== modified file 'sql/log_event.cc'
--- a/sql/log_event.cc 2010-09-24 15:24:54 +0000
+++ b/sql/log_event.cc 2010-10-19 08:06:26 +0000
@@ -8076,14 +8076,12 @@ void Rows_log_event::print_helper(FILE *
my_b_printf(head, "\t%s: table id %lu%s\n",
name, m_table_id,
last_stmt_event ? " flags: STMT_END_F" : "");
+ copy_event_cache_to_file_and_reinit(head, file);
print_base64(body, print_event_info, !last_stmt_event);
}
if (get_flags(STMT_END_F))
- {
- copy_event_cache_to_file_and_reinit(head, file);
copy_event_cache_to_file_and_reinit(body, file);
- }
}
#endif
@@ -8552,6 +8550,7 @@ void Table_map_log_event::print(FILE *fi
"\tTable_map: `%s`.`%s` mapped to number %lu\n",
m_dbnam, m_tblnam, m_table_id);
print_base64(&print_event_info->body_cache, print_event_info, TRUE);
+ copy_event_cache_to_file_and_reinit(&print_event_info->head_cache, file);
}
}
#endif
Attachment: [text/bzr-bundle] bzr/dao-gang.qu@sun.com-20101019080626-3y1zi5j4m6woepkk.bundle
