List:Commits« Previous MessageNext Message »
From:Sujatha Sivakumar Date:July 10 2012 9:42am
Subject:bzr push into mysql-5.1 branch (sujatha.sivakumar:3768 to 3769) Bug#11762670
View as plain text  
 3769 Sujatha Sivakumar	2012-07-10
      BUG#11762670:MY_B_WRITE RETURN VALUE IGNORED
      
      Problem:
      =======
      The return value from my_b_write is ignored by: `my_b_write_quoted',
      `my_b_write_bit',`Query_log_event::print_query_header'
      
      Most callers of `my_b_printf' ignore the return value. `log_event.cc' 
      has many calls to it. 
      
      Analysis:
      ========
      `my_b_write' is used to write data into a file. If the write fails it
      sets appropriate error number and error message through my_error()
      function call and sets the IO_CACHE::error == -1.
      `my_b_printf' function is also used to write data into a file, it
      internally invokes my_b_write to do the write operation. Upon
      success it returns number of characters written to file and on error
      it returns -1 and sets the error through my_error() and also sets
      IO_CACHE::error == -1.  Most of the event specific print functions
      for example `Create_file_log_event::print', `Execute_load_log_event::print'
      etc are the ones which make several calls to the above two functions and
      they do not check for the return value after the 'print' call. All the above 
      mentioned abuse cases deal with the client side.
      
      Fix:
      ===
      As part of bug fix a check for IO_CACHE::error == -1 has been added at 
      a very high level after the call to the 'print' function.  There are 
      few more places where the return value of "my_b_write" is ignored
      those are mentioned below.
      
      +++ mysys/mf_iocache2.c    2012-06-04 07:03:15 +0000
      @@ -430,7 +430,8 @@
                 memset(buffz, '0', minimum_width - length2);
               else
                 memset(buffz, ' ', minimum_width - length2);
      -        my_b_write(info, buffz, minimum_width - length2);
      
      +++ sql/log.cc	2012-06-08 09:04:46 +0000
      @@ -2388,7 +2388,12 @@
           {
             end= strxmov(buff, "# administrator command: ", NullS);
             buff_len= (ulong) (end - buff);
      -      my_b_write(&log_file, (uchar*) buff, buff_len);
      
      At these places appropriate return value handlers have been added.
     @ client/mysqlbinlog.cc
        check for IO_CACHE::error == -1 has been added after the call to
        the event specific print functions
     @ internal/mysql-test/suite/i_binlog/r/binlog_mysqlbinlog_file_write.result
        Result file has been updated with test results for BUG#11762670
     @ internal/mysql-test/suite/i_binlog/t/binlog_mysqlbinlog_file_write.test
        Added test cases for testing the fix for BUG11762670.
     @ internal/mysql-test/suite/i_main/r/slow_log_write_errchk.result
        Result file for test `slow_log_write_errchk.test'.
     @ internal/mysql-test/suite/i_main/t/slow_log_write_errchk-master.opt
        Option file includes two options, one to enable 'admin commands' to be logged
        in slow log file. The other option specifies the name for slow log file.
     @ internal/mysql-test/suite/i_main/t/slow_log_write_errchk.test
        Test script to test error handling when a write operation to the slow log file
        fails.
     @ mysys/mf_iocache2.c
        Added handler to check the written value of `my_b_write'
     @ sql/log.cc
        Added handler to check the written value of `my_b_write'
     @ sql/log_event.cc
        Added error simulation statements in `Create_file_log_event::print`
        and `Execute_load_query_log_event::print'
     @ sql/rpl_utility.h
        Removed the extra ';'

    added:
      internal/mysql-test/suite/i_main/r/slow_log_write_errchk.result
      internal/mysql-test/suite/i_main/t/slow_log_write_errchk-master.opt
      internal/mysql-test/suite/i_main/t/slow_log_write_errchk.test
    modified:
      client/mysqlbinlog.cc
      internal/mysql-test/suite/i_binlog/r/binlog_mysqlbinlog_file_write.result
      internal/mysql-test/suite/i_binlog/t/binlog_mysqlbinlog_file_write.test
      mysys/mf_iocache2.c
      sql/log.cc
      sql/log_event.cc
      sql/rpl_utility.h
 3768 Bjorn Munch	2012-07-10
      mysql_client_test did not build within limbysqld/examples

    modified:
      libmysqld/examples/CMakeLists.txt
      libmysqld/examples/Makefile.am
=== modified file 'client/mysqlbinlog.cc'
--- a/client/mysqlbinlog.cc	2012-06-29 11:25:57 +0000
+++ b/client/mysqlbinlog.cc	2012-07-10 08:53:17 +0000
@@ -784,8 +784,11 @@ Exit_status process_event(PRINT_EVENT_IN
           goto end;
       }
       else
+      {
         ce->print(result_file, print_event_info, TRUE);
-
+        if (head->error == -1)
+          goto err;
+      }
       // If this binlog is not 3.23 ; why this test??
       if (glob_description_event->binlog_version >= 3)
       {
@@ -836,6 +839,8 @@ Exit_status process_event(PRINT_EVENT_IN
 	ce->print(result_file, print_event_info, TRUE);
 	my_free((char*)ce->fname,MYF(MY_WME));
 	delete ce;
+        if (head->error == -1)
+          goto err;
       }
       else
         warning("Ignoring Execute_load_log_event as there is no "
@@ -890,6 +895,12 @@ Exit_status process_event(PRINT_EVENT_IN
         {
           convert_path_to_forward_slashes(fname);
           exlq->print(result_file, print_event_info, fname);
+          if (head->error == -1)
+          {
+            if (fname)
+              my_free(fname, MYF(MY_WME));
+            goto err;
+          }
         }
         else
           warning("Ignoring Execute_load_query since there is no "

=== modified file 'internal/mysql-test/suite/i_binlog/r/binlog_mysqlbinlog_file_write.result'
--- a/internal/mysql-test/suite/i_binlog/r/binlog_mysqlbinlog_file_write.result	2012-05-31 09:02:29 +0000
+++ b/internal/mysql-test/suite/i_binlog/r/binlog_mysqlbinlog_file_write.result	2012-07-10 08:53:17 +0000
@@ -5,3 +5,18 @@ No error
 MYSQL_BINLOG: Error writing file <file_name> (Errcode: ##)
 MYSQL_BINLOG: Error writing file <file_name> (Errcode: ##)
 ### end of test ###
+
+### Create_file_log_event::print-Without error conditions ###
+No error
+
+### Create_file_log_event::print-With error conditions ###
+MYSQL_BINLOG: Error writing file <file_name> (Errcode: ##)
+MYSQL_BINLOG: Error writing file <file_name> (Errcode: ##)
+
+### Execute_load_query_log_event::print-Without error conditions ###
+No error
+
+### Execute_load_query_log_event::print-With error conditions ###
+MYSQL_BINLOG: Error writing file <file_name> (Errcode: ##)
+MYSQL_BINLOG: Error writing file <file_name> (Errcode: ##)
+### end of test ###

=== modified file 'internal/mysql-test/suite/i_binlog/t/binlog_mysqlbinlog_file_write.test'
--- a/internal/mysql-test/suite/i_binlog/t/binlog_mysqlbinlog_file_write.test	2012-07-03 12:30:21 +0000
+++ b/internal/mysql-test/suite/i_binlog/t/binlog_mysqlbinlog_file_write.test	2012-07-10 08:53:17 +0000
@@ -38,3 +38,44 @@ exec $MYSQL_BINLOG -#d,simulate_file_wri
 --remove_file $temp_out_file
 
 --echo ### end of test ###
+#-------------------------------------------------------------------------------
+# Bug#11762670: my_b_write return value ignored
+#-------------------------------------------------------------------------------
+#mysqlbinlog utility has event specific print functions like 
+#`Create_file_log_event::print', `Delete_rows_log_event::print' etc which are
+#used to print the event queries into a file.  These print functions internally
+#make several calls to "my_b_write" and "my_b_printf" functions, whose return 
+#values are not handled by the callers. 
+
+#As part of BUG11762670 fix error handlers are added to catch the 'write errors' 
+#that might occur during the above mentioned event specific print calls. 
+#Following test script simulates errors and checks if they are being caught by 
+#the error handler. The test also checks all the calls without error simulation.
+
+--echo
+--echo ### Create_file_log_event::print-Without error conditions ###
+exec $MYSQL_BINLOG suite/binlog/std_data/binlog_old_version_4_1.000001 -r$temp_out_file 2>&1;
+--echo No error
+--echo
+--remove_file $temp_out_file
+
+--echo ### Create_file_log_event::print-With error conditions ###
+--replace_regex /.* Error writing file \'.*\' \(Errcode: [0-9]*)/MYSQL_BINLOG: Error writing file <file_name> (Errcode: ##)/
+--error 1
+exec $MYSQL_BINLOG -#d,simulate_create_event_write_error suite/binlog/std_data/binlog_old_version_4_1.000001 -r$temp_out_file 2>&1;
+--echo
+--remove_file $temp_out_file
+
+--echo ### Execute_load_query_log_event::print-Without error conditions ###
+exec $MYSQL_BINLOG --local-load=$MYSQLTEST_VARDIR/tmp/ suite/binlog/std_data/ver_5_1_23.001 -r$temp_out_file 2>&1;
+--echo No error
+--echo
+--remove_file $temp_out_file
+
+--echo ### Execute_load_query_log_event::print-With error conditions ###
+--replace_regex /.* Error writing file \'.*\' \(Errcode: [0-9]*)/MYSQL_BINLOG: Error writing file <file_name> (Errcode: ##)/
+--error 1
+--exec $MYSQL_BINLOG -#d,simulate_execute_event_write_error --local-load=$MYSQLTEST_VARDIR/tmp/ suite/binlog/std_data/ver_5_1_23.001 -r$temp_out_file 2>&1;
+--remove_file $temp_out_file
+
+--echo ### end of test ###

=== added file 'internal/mysql-test/suite/i_main/r/slow_log_write_errchk.result'
--- a/internal/mysql-test/suite/i_main/r/slow_log_write_errchk.result	1970-01-01 00:00:00 +0000
+++ b/internal/mysql-test/suite/i_main/r/slow_log_write_errchk.result	2012-07-10 08:53:17 +0000
@@ -0,0 +1,8 @@
+SET SESSION long_query_time = 0;
+SET GLOBAL slow_query_log = 1;
+SET GLOBAL debug='+d,simulate_slow_log_write_error';
+call mtr.add_suppression("Error writing file*");
+create table t1 (f int);
+alter table t1 add column seq BIGINT UNSIGNED NOT NULL AUTO_INCREMENT PRIMARY KEY;
+drop table t1;
+set @@GLOBAL.DEBUG = $debug_saved;

=== added file 'internal/mysql-test/suite/i_main/t/slow_log_write_errchk-master.opt'
--- a/internal/mysql-test/suite/i_main/t/slow_log_write_errchk-master.opt	1970-01-01 00:00:00 +0000
+++ b/internal/mysql-test/suite/i_main/t/slow_log_write_errchk-master.opt	2012-07-10 08:53:17 +0000
@@ -0,0 +1,2 @@
+--log-slow-admin-statements=1
+--log-slow-queries=slow.log

=== added file 'internal/mysql-test/suite/i_main/t/slow_log_write_errchk.test'
--- a/internal/mysql-test/suite/i_main/t/slow_log_write_errchk.test	1970-01-01 00:00:00 +0000
+++ b/internal/mysql-test/suite/i_main/t/slow_log_write_errchk.test	2012-07-10 08:53:17 +0000
@@ -0,0 +1,26 @@
+#------------------------------------------------------------------------------
+# Bug#11762670: my_b_write return value ignored
+#------------------------------------------------------------------------------
+#When an administrative command like 'OPTIMIZE TABLE, ANALYZE TABLE, and ALTER
+#TABLE' needs to be logged into slow log file, "my_b_write" function is invoked
+#to do the file write operation. The current implementation ignores the return 
+#value of "my_b_write" function. As part of BUG#11762670 fix error handler is 
+#added to capture the errors.
+
+#The following test script simulates a write error during a write to slow log 
+#file and checks if the error is being handled by the server
+
+--source include/have_debug.inc
+let $debug_saved= `select @@global.debug`;
+
+SET SESSION long_query_time = 0;
+SET GLOBAL slow_query_log = 1;
+SET GLOBAL debug='+d,simulate_slow_log_write_error';
+call mtr.add_suppression("Error writing file*");
+create table t1 (f int);
+alter table t1 add column seq BIGINT UNSIGNED NOT NULL AUTO_INCREMENT PRIMARY KEY;
+drop table t1;
+
+--source include/restart_mysqld.inc
+
+set @@GLOBAL.DEBUG = $debug_saved;

=== modified file 'mysys/mf_iocache2.c'
--- a/mysys/mf_iocache2.c	2011-06-30 15:37:13 +0000
+++ b/mysys/mf_iocache2.c	2012-07-10 08:53:17 +0000
@@ -430,7 +430,11 @@ process_flags:
           memset(buffz, '0', minimum_width - length2);
         else
           memset(buffz, ' ', minimum_width - length2);
-        my_b_write(info, buffz, minimum_width - length2);
+        if (my_b_write(info, buffz, minimum_width - length2))
+        {
+          my_afree(buffz);
+          goto err;
+        }
         my_afree(buffz);
       }
 

=== modified file 'sql/log.cc'
--- a/sql/log.cc	2012-03-12 12:28:27 +0000
+++ b/sql/log.cc	2012-07-10 08:53:17 +0000
@@ -2388,7 +2388,10 @@ bool MYSQL_QUERY_LOG::write(THD *thd, ti
     {
       end= strxmov(buff, "# administrator command: ", NullS);
       buff_len= (ulong) (end - buff);
-      my_b_write(&log_file, (uchar*) buff, buff_len);
+      DBUG_EXECUTE_IF("simulate_slow_log_write_error",
+                      {DBUG_SET("+d,simulate_file_write_error");});
+      if(my_b_write(&log_file, (uchar*) buff, buff_len))
+        tmp_errno= errno;
     }
     if (my_b_write(&log_file, (uchar*) sql_text, sql_text_len) ||
         my_b_write(&log_file, (uchar*) ";\n",2) ||

=== modified file 'sql/log_event.cc'
--- a/sql/log_event.cc	2012-06-12 07:29:13 +0000
+++ b/sql/log_event.cc	2012-07-10 08:53:17 +0000
@@ -6312,11 +6312,18 @@ void Create_file_log_event::print(FILE*
   {
     Load_log_event::print(file, print_event_info,
 			  !check_fname_outside_temp_buf());
-    /* 
-       That one is for "file_id: etc" below: in mysqlbinlog we want the #, in
-       SHOW BINLOG EVENTS we don't.
-    */
-    my_b_printf(&cache, "#"); 
+    /**
+      reduce the size of io cache so that the write function is called
+      for every call to my_b_printf().
+     */
+    DBUG_EXECUTE_IF ("simulate_create_event_write_error",
+                     {(&cache)->write_pos= (&cache)->write_end;
+                     DBUG_SET("+d,simulate_file_write_error");});
+    /*
+      That one is for "file_id: etc" below: in mysqlbinlog we want the #, in
+      SHOW BINLOG EVENTS we don't.
+     */
+    my_b_printf(&cache, "#");
   }
 
   my_b_printf(&cache, " file_id: %d  block_len: %d\n", file_id, block_len);
@@ -6992,6 +6999,13 @@ void Execute_load_query_log_event::print
   Write_on_release_cache cache(&print_event_info->head_cache, file);
 
   print_query_header(&cache, print_event_info);
+  /**
+    reduce the size of io cache so that the write function is called
+    for every call to my_b_printf().
+   */
+  DBUG_EXECUTE_IF ("simulate_execute_event_write_error",
+                   {(&cache)->write_pos= (&cache)->write_end;
+                   DBUG_SET("+d,simulate_file_write_error");});
 
   if (local_fname)
   {

=== modified file 'sql/rpl_utility.h'
--- a/sql/rpl_utility.h	2012-04-20 16:41:20 +0000
+++ b/sql/rpl_utility.h	2012-07-10 08:53:17 +0000
@@ -300,7 +300,7 @@ private:
 public:
   Deferred_log_events(Relay_log_info *rli);
   ~Deferred_log_events();
-  /* queue for exection at Query-log-event time prior the Query */;
+  /* queue for exection at Query-log-event time prior the Query */
   int add(Log_event *ev);
   bool is_empty();
   bool execute(Relay_log_info *rli);

No bundle (reason: useless for push emails).
Thread
bzr push into mysql-5.1 branch (sujatha.sivakumar:3768 to 3769) Bug#11762670Sujatha Sivakumar10 Jul