BUG#33658850 - Binlog recovery not reporting all error states

Problem
-------
The binary log recovery process doesn't report errors for all failure cases
that may happen. More specifically, in `MYSQL_BIN_LOG::open_binlog`:

1. If ev==nullptr return error. Start ha_recover(). It's possible
that the server crashed after creating the file and before writing anything
to it.
2. If type_code!=FORMAT_DESCRIPTION_LOG_EVENT it returns error. It reports
 that the binlog is corrupted and return error. Start ha_recover();
3. If LOG_EVENT_BINLOG_IN_USE_F is cleared, it does the right thing, return
an error. Start ha_recover().
4. If is_binlog_malformed() report error and don't truncate the binlog nor
clear the LOG_EVENT_IN_USE_F.
5. If storage engine recovery fails truncate the binlog to a
valid position but not clear LOG_EVENT_IN_USE_F.
6. If valid_pos==0, it skips truncating the binary log and clearing
LOG_EVENT_IN_USE_F. That situation happens when binlog begins with a
half-transaction but is handled in case 1. and 2.

Analysis / Root-cause analysis
------------------------------
Suggested Fix:
Suggest code flow like:

ev = ...
if (!ev) {
  LogErr(...)
  return -1;
}

if (ev is not a FD event) {
  LogErr(...)
  return -1;
}

if (LOG_EVENT_IN_USE_F is not set) {
  LogErr(...)
  return 0;
}

Do the recovery.

if (is_binlog_malformed) return -1;

if (has_engine_recovery_failed) {
  Do the truncation.
  return -1;
}

if (valid_pos > 0) {
  Do the truncation.
}

Clear LOG_EVENT_IN_USE_F.

return 0;

Solution
--------
Change binlog.cc int MYSQL_BIN_LOG::open_binlog(const char *opt_name) implementation.

Change-Id: Iea89e083cef8d8fdc62273888911d91c6e07f0ad

Author: Slawomir Maludzinski

mysql-test/extra/binlog_tests/copy_file_segment.inc

@@ -0,0 +1,70 @@
+#
+# copy file segment
+#
+# $in_filename - name of the source binary log
+# $out_filename - name of the output binary log
+# $file_start_pos - file position start
+# $file_stop_pos - file position stop
+
+if (!$in_filename) {
+  --die Please assign a file name to $in_filename!!
+}
+
+if (!$out_filename) {
+  --die Please assign a file name to $out_filename!!
+}
+
+if ($file_start_pos == '') {
+  --die Please assign position of segment start offset to $file_start_pos!!
+}
+
+if ($file_stop_pos == '') {
+  --die Please assign position of segment stop offset to $file_stop_pos!!
+}
+
+--let IN_FILENAME_ENV = $in_filename
+--let OUT_FILENAME_ENV = $out_filename
+--let FILE_START_POS_ENV = $file_start_pos
+--let FILE_STOP_POS_ENV = $file_stop_pos
+
+--perl
+  my $in_filename = $ENV{'IN_FILENAME_ENV'};
+  my $out_filename = $ENV{'OUT_FILENAME_ENV'};
+  my $file_start_pos = $ENV{'FILE_START_POS_ENV'};
+  my $file_stop_pos = $ENV{'FILE_STOP_POS_ENV'};
+
+  open(IN, '<:raw', $in_filename) || die("Could not open <$in_filename: $!");
+  open(OUT, '>>:raw', $out_filename) || die("Could not open >>$out_filename: $!");
+
+  my ($len_in, $len_out, $data);
+
+  # skip $file_start_pos bytes
+  sysseek(IN, $file_start_pos, SEEK_SET);
+
+  # length to be read
+  my $length = $file_stop_pos - $file_start_pos;
+
+  # copy binary segment
+  while ($length > 0) {
+    $len_in = sysread(IN, my $data, $length);
+    if (!defined($len_in)) {
+      die("Could not sysread data: $!");
+    }
+    if ($len_in == 0) {
+      die("Read zero bytes");
+    }
+
+    $length = $length - $len_in;
+
+    my $offset = 0;
+    while ($len_in > 0) {
+
+      $len_out = syswrite(OUT, $data, $len_in, $offset);
+      if (!defined($len_out)) {
+        die("Could not syswrite data: $!");
+      }
+      $offset += $len_out;
+      $len_in -= $len_out;
+    }
+  }
+EOF

mysql-test/suite/binlog/r/binlog_open_errors.result

@@ -0,0 +1,36 @@
+RESET MASTER;
+include/save_error_log_position.inc
+Prepare binary log with header only
+Prepare binary log without Format_desc event
+Prepare binary log without Format_desc event
+Backup binlog file
+
+# 1. Test Error in Log_event::read_log_event() #
+################################################
+# restart
+RESET MASTER;
+include/assert_error_log.inc [server: 1, pattern: Error in Log_event::read_log_event().*]
+
+# 2. Truncated binary log
+##############################################################################
+# restart
+RESET MASTER;
+include/assert_error_log.inc [server: 1, pattern: Error in Log_event::read_log_event().*
+Error reading GTIDs from binary log.*
+]
+
+# 3. Test Found invalid event sequence while recovering from binary log file #
+##############################################################################
+# restart
+RESET MASTER;
+include/assert_error_log.inc [server: 1, pattern: Found invalid event sequence while recovering from binary log file.*]
+# restart
+
+# 4. Test check !(ev->common_header->flags & LOG_EVENT_BINLOG_IN_USE_F) #
+#########################################################################
+# Adding debug point 'binlog_crash_between_close_and_open' to @@GLOBAL.debug
+FLUSH BINARY LOGS;
+ERROR HY000: Lost connection to MySQL server during query
+# restart
+# Check for the "Failed to open the crashed binlog file when source server is recovering it\."
+Pattern "\[Note\] \[[^]]*\] \[[^]]*\] Failed to open the crashed binlog file when source server is recovering it\." found

mysql-test/suite/binlog/t/binlog_open_errors.test

@@ -0,0 +1,229 @@
+# === Purpose ===
+#
+# Check errors returned by MYSQL_BIN_LOG::open_binlog
+#
+# ==== Requirements ====
+#
+# R1. When the binary log file is opened during recovery,
+# the following error conditions and boundary conditions should be handled:
+#  * If the file is truncated just after the magic header,
+#    it should report an error and start ha_recover().
+#  * If the file is missing a format_description_log_event,
+#    recovery should report an error and start ha_recover().
+#  * If the Format_description_log_event exists but
+#    does not have LOG_EVENT_BINLOG_IN_USE_F set,
+#    it should report a warning and start ha_recover().
+#
+# === Implementation ====
+#
+# 1. Start server so that binary log is created
+# 2. Prepare binary log with header only
+# 3. Check error ER_READ_LOG_EVENT_FAILED is reported 
+#      "Error in Log_event::read_log_event()"
+# 4. Perpare binary log without Format_desc event
+# 5. Check error ER_BINLOG_CRASH_RECOVERY_MALFORMED_LOG is reported 
+#      "Found invalid event sequence while recovering from binary log file."
+# 6. Set debug points binlog_crash_between_close_and_open so that server is crashed
+#    after binary log LOG_EVENT_BINLOG_IN_USE_F is set to false
+# 7. Check error ER_BINLOG_CANT_OPEN_CRASHED_BINLOG is reported 
+#      "Failed to open the crashed binlog file when source server is recovering it."
+#
+# === References ===
+# 
+# BUG #33658850 Binlog recovery not reporting all error states
+#
+--source include/have_debug.inc
+--source include/have_binlog_format_mixed.inc
+
+RESET MASTER;
+
+--let $MYSQLD_DATADIR = `SELECT @@DATADIR`
+--let $binlog = query_get_value(SHOW MASTER STATUS, File, 1)
+--let $event_following_format_desc_start = query_get_value(SHOW BINLOG EVENTS IN '$binlog', Pos, 2)
+--let $event_following_format_desc_stop = query_get_value(SHOW BINLOG EVENTS IN '$binlog', End_log_pos, 2)
+
+--file_exists $MYSQLD_DATADIR/$binlog
+
+#
+# Use save_error_log_position.inc before the first call to assert_error_log.inc.
+# The error log may contain errors from earlier test runs.
+#
+--source include/save_error_log_position.inc
+
+#
+# Shutdown server
+#
+--source include/shutdown_mysqld.inc
+
+#
+# Prepare binary log with header only
+#
+--echo Prepare binary log with header only
+
+--let $in_filename = $MYSQLD_DATADIR/$binlog
+--let $out_filename = $MYSQLD_DATADIR/$binlog.header
+--let $file_start_pos = 0
+--let $file_stop_pos = 4
+--source extra/binlog_tests/copy_file_segment.inc
+
+#
+# Prepare binary log with truncated Format_desc event
+#
+--echo Prepare binary log without Format_desc event
+
+--let $in_filename = $MYSQLD_DATADIR/$binlog
+--let $out_filename = $MYSQLD_DATADIR/$binlog.truncformat
+--let $file_start_pos = 0
+--let $file_stop_pos = $event_following_format_desc_start
+--dec $file_stop_pos
+--source extra/binlog_tests/copy_file_segment.inc
+
+#
+# Prepare binary log without Format_desc event
+#
+--echo Prepare binary log without Format_desc event
+
+--let $in_filename = $MYSQLD_DATADIR/$binlog
+--let $out_filename = $MYSQLD_DATADIR/$binlog.formatless
+--let $file_start_pos = 0
+--let $file_stop_pos = 4
+--source extra/binlog_tests/copy_file_segment.inc
+--let $file_start_pos = $event_following_format_desc_start
+--let $file_stop_pos = $event_following_format_desc_stop
+--source extra/binlog_tests/copy_file_segment.inc
+
+#
+# Backup binlog file
+#
+--echo Backup binlog file
+
+--copy_file $MYSQLD_DATADIR/$binlog $MYSQLD_DATADIR/$binlog.backup
+
+--echo
+--echo # 1. Test Error in Log_event::read_log_event() #
+--echo ################################################
+
+#
+# Swap header only event
+#
+--remove_file $MYSQLD_DATADIR/$binlog
+--copy_file $MYSQLD_DATADIR/$binlog.header $MYSQLD_DATADIR/$binlog
+
+#
+# Start server
+#
+--source include/start_mysqld.inc
+
+RESET MASTER;
+
+#
+# Search for error message : 'arrived the end of the file'
+#
+--let $error_pattern = Error in Log_event::read_log_event().*
+--source include/assert_error_log.inc
+
+#
+# Shutdown server
+#
+--source include/shutdown_mysqld.inc
+
+--echo
+--echo # 2. Truncated binary log
+--echo ##############################################################################
+
+#
+# Swap header only event
+#
+--remove_file $MYSQLD_DATADIR/$binlog
+--copy_file $MYSQLD_DATADIR/$binlog.truncformat $MYSQLD_DATADIR/$binlog
+
+#
+# Start server
+#
+--source include/start_mysqld.inc
+
+RESET MASTER;
+
+#
+# Search for error message : 'binlog truncated in the middle of event; consider out of disk space'
+#
+let $error_pattern = Error in Log_event::read_log_event().*
+  Error reading GTIDs from binary log.*
+;
+--source include/assert_error_log.inc
+
+#
+# Shutdown server
+#
+--source include/shutdown_mysqld.inc
+
+--echo
+--echo # 3. Test Found invalid event sequence while recovering from binary log file #
+--echo ##############################################################################
+
+#
+# Swap format less binary log
+#
+--remove_file $MYSQLD_DATADIR/$binlog
+--copy_file $MYSQLD_DATADIR/$binlog.formatless $MYSQLD_DATADIR/$binlog
+
+#
+# Start server
+#
+--source include/start_mysqld.inc
+
+RESET MASTER;
+
+#
+# Search for error message
+#
+--let $error_pattern = Found invalid event sequence while recovering from binary log file.*
+--source include/assert_error_log.inc
+
+#
+# Shutdown server
+#
+--source include/shutdown_mysqld.inc
+
+#
+# Restore binary log file
+#
+--remove_file $MYSQLD_DATADIR/$binlog
+--copy_file $MYSQLD_DATADIR/$binlog.backup $MYSQLD_DATADIR/$binlog
+
+#
+# Now the server should start
+#
+--source include/start_mysqld.inc
+
+--echo
+--echo # 4. Test check !(ev->common_header->flags & LOG_EVENT_BINLOG_IN_USE_F) #
+--echo #########################################################################
+
+--let $debug_point = binlog_crash_between_close_and_open
+--source include/add_debug_point.inc
+
+--error CR_SERVER_LOST
+FLUSH BINARY LOGS;
+
+#
+# Start server
+#
+--remove_file $MYSQLTEST_VARDIR/log/mysqld.1.err
+--source include/start_mysqld.inc
+
+#
+# Search for note message
+#
+--let SEARCH_FILE = $MYSQLTEST_VARDIR/log/mysqld.1.err
+--let SEARCH_PATTERN = \[Note\] \[[^]]*\] \[[^]]*\] Failed to open the crashed binlog file when source server is recovering it\.
+--echo # Check for the "Failed to open the crashed binlog file when source server is recovering it\."
+--source include/search_pattern.inc
+
+#
+# Cleanup
+#
+--remove_file $MYSQLD_DATADIR/$binlog.backup
+--remove_file $MYSQLD_DATADIR/$binlog.header
+--remove_file $MYSQLD_DATADIR/$binlog.truncformat
+--remove_file $MYSQLD_DATADIR/$binlog.formatless