List:Commits« Previous MessageNext Message »
From:Andrei Elkin Date:September 29 2011 11:55am
Subject:bzr push into mysql-5.5 branch (andrei.elkin:3554 to 3555) Bug#11747416
View as plain text  
 3555 Andrei Elkin	2011-09-29
      Bug#11747416 : 32228 A disk full makes binary log corrupt
      
      Binary log of master can get a partially logged event if the server
      runs out of disk space and, while waiting for some space to be freed,
      is shut down (or crashes). If the server is not stopped, it will just
      wait endlessly for space to be freed, thus no partial event anomaly
      occurs.  The restarted master server has had a dubious policy to send
      the incomplete event to slave which it apparently can't handle.
      Although an error was printed out the fact of sending with unclear
      error message is a source of confusion.
      Actually the problem of presence an incomplete event in the binary log
      was already fixed by WL 5493 (which was merged to our current trunk
      branch, major version 5.6). The fix makes the server truncate the
      binary log on server restart and recovery.
      
      However 5.5 master can't do that. So the current issue is a problem of
      sending incomplete events to the slave by 5.5 master.
      
      It is fixed in this patch by changing the policy so that only complete
      events are pushed by the dump thread to the IO thread. In addition,
      the error text that master sends to the slave when an incomplete event
      is found, now states that incomplete event may have been caused by an
      out-of-disk space situation and provides coordinates of
      the first and the last event bytes read.
     @ mysql-test/std_data/bug11747416_32228_binlog.000001
        a binlog is added with the last event written partly.
     @ mysql-test/suite/rpl/r/rpl_cant_read_event_incident.result
        new result file is added.
     @ mysql-test/suite/rpl/r/rpl_log_pos.result
        results updated.
     @ mysql-test/suite/rpl/r/rpl_manual_change_index_file.result
        results updated.
     @ mysql-test/suite/rpl/r/rpl_packet.result
        results updated.
     @ mysql-test/suite/rpl/t/rpl_cant_read_event_incident.test
        regression test for bug#11747416 : 32228 A disk full makes binary log corrupt
        is added.
     @ sql/share/errmsg-utf8.txt
        Increasing the explanatory part of ER_MASTER_FATAL_ERROR_READING_BINLOG error message twice
        in order to fit to the updated version which carries some more info.
     @ sql/sql_repl.cc
        Error text indicating a failure of reading from binlog that master delivers to the slave 
        is made more clear;
        A policy to regard a partial event to send it out to the slave anyway is removed.

    added:
      mysql-test/std_data/bug11747416_32228_binlog.000001
      mysql-test/suite/rpl/r/rpl_cant_read_event_incident.result
      mysql-test/suite/rpl/t/rpl_cant_read_event_incident.test
    modified:
      mysql-test/suite/rpl/r/rpl_log_pos.result
      mysql-test/suite/rpl/r/rpl_manual_change_index_file.result
      mysql-test/suite/rpl/r/rpl_packet.result
      sql/share/errmsg-utf8.txt
      sql/sql_repl.cc
 3554 Rohit Kalhans	2011-09-29
      BUG#11758262 - 50439: MARK INSERT...SEL...ON DUP KEY UPD,REPLACE...SEL,CREATE...[IGN|REPL] SEL 
      Problem: The following statements can cause the slave to go out of sync 
      if logged in statement format: 
      INSERT IGNORE...SELECT 
      INSERT ... SELECT ... ON DUPLICATE KEY UPDATE 
      REPLACE ... SELECT 
      UPDATE IGNORE :
      CREATE ... IGNORE SELECT 
      CREATE ... REPLACE SELECT  
                 
      Background: Since the order of the rows returned by the SELECT 
      statement or otherwise may differ on master and slave, therefore
      the above statements may cuase the salve to go out of sync with
      the master. 
            
      Fix:
      Issue a warning when statements like the above are exectued and 
      the bin-logging format is statement. If the logging format is mixed,
      use row based logging. Marking a statement as unsafe has been 
      done in the sql/sql_parse.cc instead of sql/sql_yacc.cc, because while
      parsing for a token has been done we cannot be sure if the parsing
      of the other tokens has been done as well.
            
      Six new warning  messages has been added for each unsafe statement. 
            
      binlog.binlog_unsafe.test has been updated to incoporate these additional unsafe statments.
      
      
      ******
      BUG#11758262 - 50439: MARK INSERT...SEL...ON DUP KEY UPD,REPLACE...SEL,CREATE...[IGN|REPL] SEL 
      Problem: The following statements can cause the slave to go out of sync 
      if logged in statement format: 
      INSERT IGNORE...SELECT 
      INSERT ... SELECT ... ON DUPLICATE KEY UPDATE 
      REPLACE ... SELECT 
      UPDATE IGNORE :
      CREATE ... IGNORE SELECT 
      CREATE ... REPLACE SELECT  
                 
      Background: Since the order of the rows returned by the SELECT 
      statement or otherwise may differ on master and slave, therefore
      the above statements may cuase the salve to go out of sync with
      the master. 
            
      Fix:
      Issue a warning when statements like the above are exectued and 
      the bin-logging format is statement. If the logging format is mixed,
      use row based logging. Marking a statement as unsafe has been 
      done in the sql/sql_parse.cc instead of sql/sql_yacc.cc, because while
      parsing for a token has been done we cannot be sure if the parsing
      of the other tokens has been done as well.
            
      Six new warning  messages has been added for each unsafe statement. 
            
      binlog.binlog_unsafe.test has been updated to incoporate these additional unsafe statments.
     @ mysql-test/extra/rpl_tests/rpl_insert_duplicate.test
        Test removed: Added the test to rpl.rpl_insert_ignore.test
        
        
        
        ******
        Test removed: the test is redundant as the same is being tested in rpl.rpl_insert_ignore.
     @ mysql-test/extra/rpl_tests/rpl_insert_id.test
        Warnings disabled for the unsafe statements.
     @ mysql-test/extra/rpl_tests/rpl_insert_ignore.test
        1. Disabled warnings while  for unsafe statements
        2. As INSERT...IGNORE is an unsafe statement, an insert ignore not changing any rows, 
        will not be logged in the binary log, in the ROW and MIXED modes. It will however be logged
        in STATEMENT mode.
     @ mysql-test/r/commit_1innodb.result
        updated result file
        
        
        
        ******
        updated result file
     @ mysql-test/suite/binlog/r/binlog_stm_blackhole.result
        Updated result file.
     @ mysql-test/suite/binlog/r/binlog_unsafe.result
        updated result file
     @ mysql-test/suite/binlog/t/binlog_unsafe.test
         added tests for the statements marked as unsafe.
     @ mysql-test/suite/rpl/r/rpl_insert_duplicate.result
        File Removed :Result file of rpl_insert_duplicate, which has been removed.
     @ mysql-test/suite/rpl/r/rpl_insert_ignore.result
        Added the content of rpl.rpl_insert_duplicate here.
     @ mysql-test/suite/rpl/r/rpl_insert_select.result
        Result file removed as the corresponding test has beenn removed.
     @ mysql-test/suite/rpl/r/rpl_known_bugs_detection.result
        Updated result file.
     @ mysql-test/suite/rpl/t/rpl_insert_duplicate.test
        File Removed: this was a wrapper for rpl.rpl_insert_duplicate.test, which has been removed.
     @ mysql-test/suite/rpl/t/rpl_insert_select.test
        File Removed: This test became redundant after this fix, This test showed how INSERT IGNORE...SELECT break replication, which has been handled in this fix.
     @ mysql-test/suite/rpl/t/rpl_known_bugs_detection.test
        Since all the tests are statement based bugs are being tested, having mixed format
        forces the event to be written in row format. When the statement and causes the
        test to fail as certain known bugs do not occur when the even is logged in row format.
     @ sql/share/errmsg-utf8.txt
        added 6 new Warning messages.
        
        
        
        ******
        added 6 new Warning messages.
     @ sql/sql_lex.cc
        Added 6 new error Identifier [ER_BINLOG_STMT_UNSAFEE_*]
     @ sql/sql_lex.h
        Added 6 new BINLOG_STMT_UNSAFE_* enums to identify the type of unsafe statement dealt with in this bug.
        
        
        ******
        Added 6 new BINLOG_STMT_UNSAFE_* enums to identify the type of unsafe statement dealt with in this bug.
     @ sql/sql_parse.cc
        added check for specific queries and marked them as unsafe.
        
        
        ******
        added check for specific queries and marked them as unsafe.

    removed:
      mysql-test/extra/rpl_tests/rpl_insert_duplicate.test
      mysql-test/suite/rpl/r/rpl_insert_duplicate.result
      mysql-test/suite/rpl/r/rpl_insert_select.result
      mysql-test/suite/rpl/t/rpl_insert_duplicate.test
      mysql-test/suite/rpl/t/rpl_insert_select.test
    modified:
      mysql-test/extra/rpl_tests/rpl_insert_id.test
      mysql-test/extra/rpl_tests/rpl_insert_ignore.test
      mysql-test/r/commit_1innodb.result
      mysql-test/suite/binlog/r/binlog_stm_blackhole.result
      mysql-test/suite/binlog/r/binlog_unsafe.result
      mysql-test/suite/binlog/t/binlog_unsafe.test
      mysql-test/suite/rpl/r/rpl_insert_ignore.result
      mysql-test/suite/rpl/r/rpl_known_bugs_detection.result
      mysql-test/suite/rpl/t/rpl_known_bugs_detection.test
      sql/share/errmsg-utf8.txt
      sql/sql_lex.cc
      sql/sql_lex.h
      sql/sql_parse.cc
=== added file 'mysql-test/std_data/bug11747416_32228_binlog.000001'
Binary files a/mysql-test/std_data/bug11747416_32228_binlog.000001	1970-01-01 00:00:00 +0000 and b/mysql-test/std_data/bug11747416_32228_binlog.000001	2011-09-29 11:14:43 +0000 differ

=== added file 'mysql-test/suite/rpl/r/rpl_cant_read_event_incident.result'
--- a/mysql-test/suite/rpl/r/rpl_cant_read_event_incident.result	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/r/rpl_cant_read_event_incident.result	2011-09-29 11:14:43 +0000
@@ -0,0 +1,19 @@
+include/master-slave.inc
+[connection master]
+call mtr.add_suppression("Error in Log_event::read_log_event()");
+include/rpl_stop_server.inc [server_number=1]
+include/rpl_start_server.inc [server_number=1]
+show binlog events;
+ERROR HY000: Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error
+call mtr.add_suppression("Slave I/O: Got fatal error 1236 from master when reading data from binary log");
+stop slave;
+reset slave;
+start slave;
+include/wait_for_slave_param.inc [Last_IO_Errno]
+Last_IO_Errno = '1236'
+Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'binlog truncated in the middle of event; consider out of disk space on master; the last event was read from ./master-bin.000001 at 316, the last byte read was read from ./master-bin.000001 at 335.''
+reset master;
+stop slave;
+reset slave;
+drop table t;
+End of the tests

=== modified file 'mysql-test/suite/rpl/r/rpl_log_pos.result'
--- a/mysql-test/suite/rpl/r/rpl_log_pos.result	2011-01-31 13:11:05 +0000
+++ b/mysql-test/suite/rpl/r/rpl_log_pos.result	2011-09-29 11:14:43 +0000
@@ -9,7 +9,7 @@ change master to master_log_pos=MASTER_L
 Read_Master_Log_Pos = '75'
 start slave;
 include/wait_for_slave_io_error.inc [errno=1236]
-Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master''
+Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master; the last event was read from ./master-bin.000001 at 75, the last byte read was read from ./master-bin.000001 at 94.''
 include/stop_slave_sql.inc
 show master status;
 File	Position	Binlog_Do_DB	Binlog_Ignore_DB

=== modified file 'mysql-test/suite/rpl/r/rpl_manual_change_index_file.result'
--- a/mysql-test/suite/rpl/r/rpl_manual_change_index_file.result	2010-12-19 17:07:28 +0000
+++ b/mysql-test/suite/rpl/r/rpl_manual_change_index_file.result	2011-09-29 11:14:43 +0000
@@ -5,7 +5,7 @@ CREATE TABLE t1(c1 INT);
 FLUSH LOGS;
 call mtr.add_suppression('Got fatal error 1236 from master when reading data from binary log: .*could not find next log');
 include/wait_for_slave_io_error.inc [errno=1236]
-Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'could not find next log''
+Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'could not find next log; the last event was read from ./master-bin.000002 at 237, the last byte read was read from ./master-bin.000002 at 237.''
 CREATE TABLE t2(c1 INT);
 FLUSH LOGS;
 CREATE TABLE t3(c1 INT);

=== modified file 'mysql-test/suite/rpl/r/rpl_packet.result'
--- a/mysql-test/suite/rpl/r/rpl_packet.result	2011-03-25 12:55:22 +0000
+++ b/mysql-test/suite/rpl/r/rpl_packet.result	2011-09-29 11:14:43 +0000
@@ -37,7 +37,7 @@ DROP TABLE t1;
 CREATE TABLE t1 (f1 int PRIMARY KEY, f2 LONGTEXT, f3 LONGTEXT) ENGINE=MyISAM;
 INSERT INTO t1(f1, f2, f3) VALUES(1, REPEAT('a', @@global.max_allowed_packet), REPEAT('b', @@global.max_allowed_packet));
 include/wait_for_slave_io_error.inc [errno=1236]
-Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master''
+Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master; the last event was read from ./master-bin.000001 at 463, the last byte read was read from ./master-bin.000001 at 482.''
 STOP SLAVE;
 RESET SLAVE;
 RESET MASTER;

=== added file 'mysql-test/suite/rpl/t/rpl_cant_read_event_incident.test'
--- a/mysql-test/suite/rpl/t/rpl_cant_read_event_incident.test	1970-01-01 00:00:00 +0000
+++ b/mysql-test/suite/rpl/t/rpl_cant_read_event_incident.test	2011-09-29 11:14:43 +0000
@@ -0,0 +1,64 @@
+#
+# Bug#11747416 : 32228 	A disk full makes binary log corrupt.
+#
+# 
+# The test demonstrates reading from binlog error propagation to slave 
+# and reporting there.
+# Conditions for the bug include a crash at time of the last event to
+# the binlog was written partly. With the fixes the event is not sent out 
+# any longer, but rather the dump thread sends out a sound error message.
+# 
+# Crash is not simulated. A binlog with partly written event in its end is installed
+# and replication is started from it.
+#
+
+--source include/master-slave.inc
+--source include/have_binlog_format_mixed.inc
+
+call mtr.add_suppression("Error in Log_event::read_log_event()");
+
+--connection master
+--let $datadir= `SELECT @@datadir`
+
+--let $rpl_server_number= 1
+--source include/rpl_stop_server.inc
+
+--remove_file $datadir/master-bin.000001
+--copy_file $MYSQL_TEST_DIR/std_data/bug11747416_32228_binlog.000001 $datadir/master-bin.000001
+
+--let $rpl_server_number= 1
+--source include/rpl_start_server.inc
+
+--source include/wait_until_connected_again.inc
+
+# evidence of the partial binlog
+--error ER_ERROR_WHEN_EXECUTING_COMMAND
+show binlog events;
+
+--connection slave
+call mtr.add_suppression("Slave I/O: Got fatal error 1236 from master when reading data from binary log");
+stop slave;
+reset slave;
+start slave;
+
+# ER_MASTER_FATAL_ERROR_READING_BINLOG 1236
+--let $slave_param=Last_IO_Errno
+--let $slave_param_value=1236
+--source include/wait_for_slave_param.inc
+
+--let $status_items= Last_IO_Errno, Last_IO_Error
+--source include/show_slave_status.inc
+
+#
+# Cleanup
+#
+
+--connection master
+reset master;
+
+--connection slave
+stop slave;
+reset slave;
+drop table t; # table was created from binlog. it does not exist on master.
+
+--echo End of the tests

=== modified file 'sql/share/errmsg-utf8.txt'
--- a/sql/share/errmsg-utf8.txt	2011-09-29 09:17:27 +0000
+++ b/sql/share/errmsg-utf8.txt	2011-09-29 11:14:43 +0000
@@ -4701,14 +4701,14 @@ ER_NOT_SUPPORTED_YET 42000 
         spa "Esta versión de MySQL no soporta todavia '%s'"
         swe "Denna version av MySQL kan ännu inte utföra '%s'"
 ER_MASTER_FATAL_ERROR_READING_BINLOG  
-        nla "Kreeg fatale fout %d: '%-.128s' van master tijdens lezen van data uit binaire log"
-        eng "Got fatal error %d from master when reading data from binary log: '%-.128s'"
-        ger "Schwerer Fehler %d: '%-.128s vom Master beim Lesen des binären Logs"
-        ita "Errore fatale %d: '%-.128s' dal master leggendo i dati dal log binario"
-        por "Obteve fatal erro %d: '%-.128s' do master quando lendo dados do binary log"
-        rus "Получена неиспр    spa "Recibió fatal error %d: '%-.128s' del master cuando leyendo datos del binary log"
-        swe "Fick fatalt fel %d: '%-.128s' från master vid läsning av binärloggen"
+        nla "Kreeg fatale fout %d: '%-.256s' van master tijdens lezen van data uit binaire log"
+        eng "Got fatal error %d from master when reading data from binary log: '%-.256s'"
+        ger "Schwerer Fehler %d: '%-.256s vom Master beim Lesen des binären Logs"
+        ita "Errore fatale %d: '%-.256s' dal master leggendo i dati dal log binario"
+        por "Obteve fatal erro %d: '%-.256s' do master quando lendo dados do binary log"
+        rus "Получена неисправимая bió fatal error %d: '%-.256s' del master cuando leyendo datos del binary log"
+        swe "Fick fatalt fel %d: '%-.256s' från master vid läsning av binärloggen"
 ER_SLAVE_IGNORED_TABLE  
         eng "Slave SQL thread ignored the query because of replicate-*-table rules"
         ger "Slave-SQL-Thread hat die Abfrage aufgrund von replicate-*-table-Regeln ignoriert"

=== modified file 'sql/sql_repl.cc'
--- a/sql/sql_repl.cc	2011-07-18 17:18:03 +0000
+++ b/sql/sql_repl.cc	2011-09-29 11:14:43 +0000
@@ -352,7 +352,7 @@ Increase max_allowed_packet on master";
     *errmsg = "memory allocation failed reading log event";
     break;
   case LOG_READ_TRUNC:
-    *errmsg = "binlog truncated in the middle of event";
+    *errmsg = "binlog truncated in the middle of event; consider out of disk space on master";
     break;
   default:
     *errmsg = "unknown error reading log event on the master";
@@ -447,6 +447,9 @@ void mysql_binlog_send(THD* thd, char* l
   String* packet = &thd->packet;
   int error;
   const char *errmsg = "Unknown error";
+  const char *fmt= "%s; the last event was read from %s at %s, the last byte read was read from %s at %s.";
+  char llbuff1[22], llbuff2[22];
+  char error_text[MAX_SLAVE_ERRMSG]; // to be send to slave via my_message()
   NET* net = &thd->net;
   mysql_mutex_t *log_lock;
   mysql_cond_t *log_cond;
@@ -677,10 +680,8 @@ impossible position";
     if (reset_transmit_packet(thd, flags, &ev_offset, &errmsg))
       goto err;
 
-    my_off_t prev_pos= pos;
-    while (!(error = Log_event::read_log_event(&log, packet, log_lock)))
+    while (!(error= Log_event::read_log_event(&log, packet, log_lock)))
     {
-      prev_pos= my_b_tell(&log);
 #ifndef DBUG_OFF
       if (max_binlog_dump_events && !left_events--)
       {
@@ -767,17 +768,6 @@ impossible position";
     }
 
     /*
-      here we were reading binlog that was not closed properly (as a result
-      of a crash ?). treat any corruption as EOF
-    */
-    if (binlog_can_be_corrupted &&
-        error != LOG_READ_MEM && error != LOG_READ_EOF)
-    {
-      my_b_seek(&log, prev_pos);
-      error=LOG_READ_EOF;
-    }
-
-    /*
       TODO: now that we are logging the offset, check to make sure
       the recorded offset and the actual match.
       Guilhem 2003-06: this is not true if this master is a slave
@@ -1021,6 +1011,16 @@ end:
 
 err:
   thd_proc_info(thd, "Waiting to finalize termination");
+  if (my_errno == ER_MASTER_FATAL_ERROR_READING_BINLOG && my_b_inited(&log))
+    /* 
+       detailing the fatal error message with coordinates 
+       of the last position read.
+    */
+    my_snprintf(error_text, sizeof(error_text), fmt, errmsg,
+                coord->file_name, (llstr(coord->pos, llbuff1), llbuff1),
+                log_file_name, (llstr(my_b_tell(&log), llbuff2), llbuff2));
+  else
+    strcpy(error_text, errmsg);
   end_io_cache(&log);
   RUN_HOOK(binlog_transmit, transmit_stop, (thd, flags));
   /*
@@ -1037,7 +1037,7 @@ err:
     mysql_file_close(file, MYF(MY_WME));
   thd->variables.max_allowed_packet= old_max_allowed_packet;
 
-  my_message(my_errno, errmsg, MYF(0));
+  my_message(my_errno, error_text, MYF(0));
   DBUG_VOID_RETURN;
 }
 

No bundle (reason: useless for push emails).
Thread
bzr push into mysql-5.5 branch (andrei.elkin:3554 to 3555) Bug#11747416Andrei Elkin2 Oct