Bug#17642 mysqlbinlog: Restore from row-based binlog fails

Problem: mysqlbinlog_base64 failed sporadically.

Reason: Missing "flush logs" before running $MYSQL_BINLOG,
which could start dumping the log file before server
has finished writting into it.
Fix:
- implementing --force-if-open option to "mysqlbinlog"
- adding --disable-force-if-open to make $MYSQL_BINLOG
  fail on non-closed log files, to garantee that nobody
  will forget "flush logs" in the future.
- adding "flush logs" into all affected tests.

client/mysqlbinlog.cc

@@ -67,6 +67,7 @@ static bool opt_hexdump= 0;
 static bool opt_base64_output= 0;
 static const char* database= 0;
 static my_bool force_opt= 0, short_form= 0, remote_opt= 0, info_flag;
+static my_bool force_if_open_opt= 1;
 static ulonglong offset = 0;
 static const char* host = 0;
 static int port= 0;
@@ -86,6 +87,7 @@ static short binlog_flags = 0;
 static MYSQL* mysql = NULL;
 static const char* dirname_for_local_load= 0;
 static bool stop_passed= 0;
+static my_bool file_not_closed_error= 0;
 
 /*
   check_header() will set the pointer below.
@@ -648,6 +650,12 @@ Create_file event for file_id: %u\n",exv->file_id);
         later.
       */
       ev= 0;
+      if (!force_if_open_opt &&
+          (description_event->flags & LOG_EVENT_BINLOG_IN_USE_F))
+      {
+        file_not_closed_error= 1;
+        DBUG_RETURN(1); 
+      }
       break;
     case BEGIN_LOAD_QUERY_EVENT:
       ev->print(result_file, print_event_info);
@@ -727,6 +735,9 @@ static struct my_option my_long_options[] =
     "already have. NOTE: you will need a SUPER privilege to use this option.",
    (gptr*) &disable_log_bin, (gptr*) &disable_log_bin, 0, GET_BOOL,
    NO_ARG, 0, 0, 0, 0, 0, 0},
+  {"force-if-open", 'F', "Force if binlog was not closed properly.",
+   (gptr*) &force_if_open_opt, (gptr*) &force_if_open_opt, 0, GET_BOOL, NO_ARG,
+   1, 0, 0, 0, 0, 0},
   {"force-read", 'f', "Force reading unknown binlog events.",
    (gptr*) &force_opt, (gptr*) &force_opt, 0, GET_BOOL, NO_ARG, 0, 0, 0, 0,
    0, 0},
@@ -1564,6 +1575,16 @@ int main(int argc, char** argv)
   my_free_open_file_info();
   /* We cannot free DBUG, it is used in global destructors after exit(). */
   my_end((info_flag ? MY_CHECK_ERROR : 0) | MY_DONT_FREE_DBUG);
+
+  if (file_not_closed_error)
+  {
+    fprintf(stderr,
+"\nError: attempting to dump binlog '%s' which was not closed properly.\n"
+"Most probably mysqld is still writting it, or crashed.\n"
+"Your current options specify --disable-force-if-open\n"
+"which means to abort on this problem.\n"
+"You can rerun using --force-if-open to ignore this problem.\n\n", argv[-1]);
+  }
   exit(exit_value);
   DBUG_RETURN(exit_value);			// Keep compilers happy
 }

mysql-test/mysql-test-run.pl

@@ -1849,7 +1849,7 @@ sub environment_setup () {
   # ----------------------------------------------------
   my $cmdline_mysqlbinlog=
     "$exe_mysqlbinlog" .
-      " --no-defaults --debug-info --local-load=$opt_tmpdir";
+      " --no-defaults --disable-force-if-open --debug-info --local-load=$opt_tmpdir";
   if ( $mysql_version_id >= 50000 )
   {
     $cmdline_mysqlbinlog .=" --character-sets-dir=$path_charsetsdir";

mysql-test/r/binlog_row_mix_innodb_myisam.result

@@ -400,6 +400,7 @@ insert into t2 select * from t1;
 select get_lock("a",10);
 get_lock("a",10)
 1
+flush logs;
 select
 (@a:=load_file("MYSQLTEST_VARDIR/tmp/mix_innodb_myisam_binlog.output"))
 is not null;

mysql-test/r/binlog_stm_mix_innodb_myisam.result

@@ -367,6 +367,7 @@ insert into t2 select * from t1;
 select get_lock("a",10);
 get_lock("a",10)
 1
+flush logs;
 select
 (@a:=load_file("MYSQLTEST_VARDIR/tmp/mix_innodb_myisam_binlog.output"))
 is not null;

mysql-test/r/mysqlbinlog.result

@@ -210,6 +210,7 @@ select HEX(f) from t4;
 HEX(f)
 835C
 flush logs;
+flush logs;
 select * from t5  /* must be (1),(1) */;
 a
 1
@@ -250,3 +251,4 @@ call p1();
 1
 drop procedure p1;
 drop table t1, t2, t03, t04, t3, t4, t5;
+flush logs;

mysql-test/r/mysqlbinlog2.result

@@ -170,6 +170,7 @@ ROLLBACK /* added by mysqlbinlog */;
 /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
 
 --- Local with 2 binlogs on command line --
+flush logs;
 /*!40019 SET @@session.max_insert_delayed_threads=0*/;
 /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
 DELIMITER /*!*/;

mysql-test/r/mysqlbinlog_base64.result

@@ -6,6 +6,7 @@ update t1 set a=a+2 where a=2;
 update t1 set a=a+2 where a=3;
 create table t2 (word varchar(20));
 load data infile '../std_data_ln/words.dat' into table t2;
+flush logs;
 drop table t1;
 drop table t2;
 select * from t1;

mysql-test/r/user_var-binlog.result

@@ -13,6 +13,7 @@ master-bin.000001	#	Query	1	#	use `test`; INSERT INTO t1 VALUES(@`a b`)
 master-bin.000001	#	User var	1	#	@`var1`=_latin1 0x273B616161 COLLATE latin1_swedish_ci
 master-bin.000001	#	User var	1	#	@`var2`=_binary 0x61 COLLATE binary
 master-bin.000001	#	Query	1	#	use `test`; insert into t1 values (@var1),(@var2)
+flush logs;
 /*!40019 SET @@session.max_insert_delayed_threads=0*/;
 /*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
 DELIMITER /*!*/;

mysql-test/t/binlog_row_mix_innodb_myisam.test

@@ -19,6 +19,7 @@
 # we check that the error code of the "ROLLBACK" event is 0 and not
 # ER_SERVER_SHUTDOWN (i.e. disconnection just rolls back transaction
 # and does not make slave to stop)
+flush logs;
 --exec $MYSQL_BINLOG --start-position=516 $MYSQLTEST_VARDIR/log/master-bin.000001 > $MYSQLTEST_VARDIR/tmp/mix_innodb_myisam_binlog.output
 --replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
 eval select

mysql-test/t/binlog_stm_mix_innodb_myisam.test

@@ -11,6 +11,7 @@
 # we check that the error code of the "ROLLBACK" event is 0 and not
 # ER_SERVER_SHUTDOWN (i.e. disconnection just rolls back transaction
 # and does not make slave to stop)
+flush logs;
 --exec $MYSQL_BINLOG --start-position=551 $MYSQLTEST_VARDIR/log/master-bin.000001 > $MYSQLTEST_VARDIR/tmp/mix_innodb_myisam_binlog.output
 --replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR
 eval select

mysql-test/t/mysqlbinlog.test

@@ -133,6 +133,7 @@ flush logs;
 # resulted binlog, parly consisting of multi-byte utf8 chars, 
 # must be digestable for both client and server. In 4.1 the client 
 # should use default-character-set same as the server.
+flush logs;
 --exec $MYSQL_BINLOG --short-form $MYSQLTEST_VARDIR/log/master-bin.000006 | $MYSQL
 select * from t5  /* must be (1),(1) */;
 
@@ -155,8 +156,8 @@ call p1();
 drop procedure p1;
 --error 1305
 call p1();
---exec $MYSQL_BINLOG --short-form $MYSQLTEST_VARDIR/log/master-bin.000007
---exec $MYSQL_BINLOG --short-form $MYSQLTEST_VARDIR/log/master-bin.000007 | $MYSQL
+--exec $MYSQL_BINLOG --short-form $MYSQLTEST_VARDIR/log/master-bin.000008
+--exec $MYSQL_BINLOG --short-form $MYSQLTEST_VARDIR/log/master-bin.000008 | $MYSQL
 call p1();
 drop procedure p1;
 
@@ -164,3 +165,13 @@ drop procedure p1;
 drop table t1, t2, t03, t04, t3, t4, t5; 
 
 # End of 5.0 tests
+
+#
+# Test --disable-force-if-open and --force-if-open
+#
+flush logs;
+--error 1
+--exec $MYSQL_BINLOG $MYSQLTEST_VARDIR/log/master-bin.000010 >/dev/null 2>/dev/null
+--exec $MYSQL_BINLOG --force-if-open $MYSQLTEST_VARDIR/log/master-bin.000010 >/dev/null 2>/dev/null
+
+# End of 5.1 tests

mysql-test/t/mysqlbinlog2.test

@@ -72,6 +72,7 @@ select "--- Local with 2 binlogs on command line --" as "";
 
 # This is to verify that some options apply only to first, or last binlog
 
+flush logs;
 --exec $MYSQL_BINLOG --short-form $MYSQLTEST_VARDIR/log/master-bin.000001 $MYSQLTEST_VARDIR/log/master-bin.000002
 
 --disable_query_log

mysql-test/t/mysqlbinlog_base64.test

@@ -15,6 +15,7 @@ load data infile '../std_data_ln/words.dat' into table t2;
 #
 #  Save binlog
 #
+flush logs;
 --exec $MYSQL_BINLOG --hexdump $MYSQLTEST_VARDIR/log/master-bin.000001 > $MYSQLTEST_VARDIR/tmp/mysqlbinlog_base64.sql
 
 #

mysql-test/t/user_var-binlog.test

@@ -20,6 +20,7 @@ show binlog events from 102;
 # absolutely need variables names to be quoted and strings to be
 # escaped).
 --replace_result $MYSQL_TEST_DIR MYSQL_TEST_DIR
+flush logs;
 --exec $MYSQL_BINLOG --short-form $MYSQLTEST_VARDIR/log/master-bin.000001 
 drop table t1;