List:Commits« Previous MessageNext Message »
From:Dao-Gang.Qu Date:October 19 2010 8:06am
Subject:bzr commit into mysql-next-mr-bugfixing branch (Dao-Gang.Qu:3324) Bug#55790
View as plain text  
#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
Thread
bzr commit into mysql-next-mr-bugfixing branch (Dao-Gang.Qu:3324) Bug#55790Dao-Gang.Qu19 Oct
  • Re: bzr commit into mysql-next-mr-bugfixing branch (Dao-Gang.Qu:3324)Bug#55790Sven Sandberg19 Oct
    • Re: bzr commit into mysql-next-mr-bugfixing branch (Dao-Gang.Qu:3324)Bug#55790Libing Song20 Oct
      • Re: bzr commit into mysql-next-mr-bugfixing branch (Dao-Gang.Qu:3324)Bug#55790Daogang Qu20 Oct
    • Re: bzr commit into mysql-next-mr-bugfixing branch (Dao-Gang.Qu:3324)Bug#55790Daogang Qu20 Oct
  • Re: bzr commit into mysql-next-mr-bugfixing branch (Dao-Gang.Qu:3324)Bug#55790Libing Song21 Oct
    • Re: bzr commit into mysql-next-mr-bugfixing branch (Dao-Gang.Qu:3324)Bug#55790Daogang Qu22 Oct