BUG#32407: Impossible to do point-in-time recovery from older binlog

Problem: it is unsafe to read base64-printed events without first
reading the Format_description_log_event (FD).  Currently, mysqlbinlog
cannot print the FD.

As a side effect, another bug has also been fixed: When mysqlbinlog
--start-position=X was specified, no ROLLBACK was printed. I changed
this, so that ROLLBACK is always printed.

This patch does several things:

 - Format_description_log_event (FD) now print themselves in base64
   format.

 - mysqlbinlog is now able to print FD events.  It has three modes:
    --base64-output=auto    Print row events in base64 output, and print
                            FD event.  The FD event is printed even if
                            it is outside the range specified with
                            --start-position, because it would not be
                            safe to read row events otherwise. This is
                            the default.

    --base64-output=always  Like --base64-output=auto, but also print
                            base64 output for query events.  This is
                            like the old --base64-output flag, which
                            is also a shorthand for
                            --base64-output=always

    --base64-output=never   Never print base64 output, generate error if
                            row events occur in binlog.  This is
                            useful to suppress the FD event in binlogs
                            known not to contain row events (e.g.,
                            because BINLOG statement is unsafe,
                            requires root privileges, is not SQL, etc)

 - the BINLOG statement now handles FD events correctly, by setting
   the thread's rli's relay log's description_event_for_exec to the
   loaded event.

   In fact, executing a BINLOG statement is almost the same as reading
   an event from a relay log.  Before my patch, the code for this was
   separated (exec_relay_log_event in slave.cc executes events from
   the relay log, mysql_client_binlog_statement in sql_binlog.cc
   executes BINLOG statements).  I needed to augment
   mysql_client_binlog_statement to do parts of what
   exec_relay_log_event does.  Hence, I did a small refactoring and
   moved parts of exec_relay_log_event to a new function, which I
   named apply_event_and_update_pos.  apply_event_and_update_pos is
   called both from exec_relay_log_event and from
   mysql_client_binlog_statement.

 - When a non-FD event is executed in a BINLOG statement, without
   previously executing a FD event in a BINLOG statement, it generates
   an error, because that's unsafe.  I took a new error code for that:
   ER_NO_FORMAT_DESCRIPTION_EVENT_BEFORE_BINLOG_STATEMENTS.

   In order to get a decent error message containing the name of the
   event, I added the class method char*
   Log_event::get_type_str(Log_event_type type), which returns a
   string name for the given Log_event_type.  This is just like the
   existing char* Log_event::get_type_str(), except it is a class
   method that takes the log event type as parameter.

   I also added PRE_GA_*_ROWS_LOG_EVENT to Log_event::get_type_str(),
   so that names of old rows event are properly printed.

 - When reading an event, I added a check that the event type is known
   by the current Format_description_log_event. Without this, it may
   crash on bad input (and I was struck by this several times).

 - I patched the following test cases, which all contain BINLOG
   statements for row events which must be preceded by BINLOG
   statements for FD events:
    - rpl_bug31076

While I was here, I fixed some small things in log_event.cc:

 - replaced hard-coded 4 by EVENT_TYPE_OFFSET in 3 places

 - replaced return by DBUG_VOID_RETURN in one place

 - The name of the logfile can be '-' to indicate stdin.  Before my
   patch, the code just checked if the first character is '-'; now it
   does a full strcmp().  Probably, all arguments that begin with a -
   are already handled somewhere else as flags, but I still think it
   is better that the code reflects what it is supposed to do, with as
   little dependencies as possible on other parts of the code.  If we
   one day implement that all command line arguments after -- are
   files (as most unix tools do), then we need this.

I also fixed the following in slave.cc:

 - next_event() was declared twice, and queue_event was not static but
   should be static (not used outside the file).


client/client_priv.h:
  Declared the new option for base64 output.
client/mysqlbinlog.cc:
   - Change from using the two-state command line option
    "default/--base64-output" to the three-state
    "--base64-output=[never|auto|always]"
   - Print the FD event even if it is outside the --start-position range.
   - Stop if a row event is about to be printed without a preceding FD
     event.
   - Minor fixes:
      * changed 4 to EVENT_TYPE_OFFSET in some places
      * Added comments
      * before, "mysqlbinlog -xyz" read from stdin; now it does not
        (only "mysqlbinlog -" reads stdin).
mysql-test/r/mysqlbinlog2.result:
  Updated result file: mysqlbinlog now prints ROLLBACK always.
mysql-test/suite/binlog/t/disabled.def:
  The test must be disabled since it reveals another bug: see BUG#33247.
mysql-test/suite/rpl/r/rpl_bug31076.result:
  Updated result file
mysql-test/suite/rpl/r/rpl_row_mysqlbinlog.result:
  Updated result file
mysql-test/suite/rpl/t/rpl_bug31076.test:
  Had to add explicit Format_description_log_event before other BINLOG
  statements
mysql-test/t/mysqlbinlog2.test:
  we must suppress base64 output in result file because it contains a
  timestamp
sql/log_event.cc:
   - Made FD events able to print themselves
   - Added check that the current FD event knows about the event type, when
     an event is about to be read. (Hint to reviewers: I had to re-indent
     a big block because of this; use diff -b)
      * To get a decent error message, I also added a class method
        const char* Log_event::get_type_str(Log_event_type)
        which converts number to event type string without having a
        Log_event object.
      * Made Log_event::get_type_str aware of PRE_GA_*_ROWS_LOG_EVENT.
   - Minor fixes:
      * Changed return to DBUG_VOID_RETURN
sql/log_event.h:
   - Declared enum to describe the three base64_output modes
   - Use the enum instead of a flag
   - Declare the new class method get_type_str (see log_event.cc)
sql/share/errmsg.txt:
  Added error msg.
sql/slave.cc:
   - Factored out part of exec_relay_log_event to the new function
     apply_event_and_update_pos, because that code is needed when executing
     BINLOG statements. (this is be functionally equivalent to the
     previous code, except: (1) skipping events is now optional, controlled
     by a parameter to the new function (2) the return value of
     exec_relay_log_event has changed; see next item).
   - Changed returned error value to always be 1. Before, it would return
     the error value from apply_log_event, which was unnecessary. This
     change is safe because the exact return value of exec_relay_log_event
     is never examined; it is only tested to be ==0 or !=0.
   - Added comments describing exec_relay_log_event and
     apply_event_and_update_pos.
   - Minor fixes:
      * Removed duplicate declaration of next_event, made queue_event
        static.
      * Added doxygen code to include this file.
sql/slave.h:
  Declared the new apply_event_and_update_pos
sql/sql_binlog.cc:
   - Made mysql_binlog_statement set the current FD event when the given
     event is an FD event. This entails using the new function
     apply_event_and_update_pos from slave.cc instead of just calling the
     ev->apply method.
   - Made mysql_binlog_statement fail if the first BINLOG statement is not
     an FD event.
mysql-test/suite/binlog/r/binlog_base64_flag.result:
  New test file needs new result file
mysql-test/suite/binlog/t/binlog_base64_flag.test:
  Added test case to verify that:
   - my patch fixes the bug
   - the new --base64-output flag works as expected
   - base64 events not preceded by an FD event give an error
   - an event of a type not known by the current FD event fails cleanly.
mysql-test/suite/binlog/std_data/binlog-bug32407.000001:
  BitKeeper file /home/sven/bk/b32407-5.1-new-rpl-mysqlbinlog_base64/mysql-test/suite/binlog/std_data/binlog-bug32407.000001

1 files changed, 198 insertions, 108 deletions

diff --git a/sql/slave.cc b/sql/slave.cc
index b6611d44723..14fa1c45c36 100644
--- a/sql/slave.cc
+++ b/sql/slave.cc
@@ -13,6 +13,17 @@
    along with this program; if not, write to the Free Software
    Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA */
 
+
+/**
+  @addtogroup Replication
+  @{
+
+  @file
+
+  @brief Code to run the io thread and the sql thread on the
+  replication slave.
+*/
+
 #include "mysql_priv.h"
 
 #include <mysql.h>
@@ -33,10 +44,6 @@
 
 #include "rpl_tblmap.h"
 
-int queue_event(Master_info* mi,const char* buf,ulong event_len);
-static Log_event* next_event(Relay_log_info* rli);
-
-
 #define FLAGSTR(V,F) ((V)&(F)?#F" ":"")
 
 #define MAX_SLAVE_RETRY_PAUSE 5
@@ -132,6 +139,7 @@ static int create_table_from_dump(THD* thd, MYSQL *mysql, const char* db,
                                   const char* table_name, bool overwrite);
 static int get_master_version_and_clock(MYSQL* mysql, Master_info* mi);
 static Log_event* next_event(Relay_log_info* rli);
+static int queue_event(Master_info* mi,const char* buf,ulong event_len);
 static int terminate_slave_thread(THD *thd,
                                   pthread_mutex_t* term_lock,
                                   pthread_cond_t* term_cond,
@@ -1757,6 +1765,175 @@ static int has_temporary_error(THD *thd)
   DBUG_RETURN(0);
 }
 
+
+/**
+  Applies the given event and advances the relay log position.
+
+  In essence, this function does:
+
+  @code
+    ev->apply_event(rli);
+    ev->update_pos(rli);
+  @endcode
+
+  But it also does some maintainance, such as skipping events if
+  needed and reporting errors.
+
+  If the @c skip flag is set, then it is tested whether the event
+  should be skipped, by looking at the slave_skip_counter and the
+  server id.  The skip flag should be set when calling this from a
+  replication thread but not set when executing an explicit BINLOG
+  statement.
+
+  @retval 0 OK.
+
+  @retval 1 Error calling ev->apply_event().
+
+  @retval 2 No error calling ev->apply_event(), but error calling
+  ev->update_pos().
+*/
+int apply_event_and_update_pos(Log_event* ev, THD* thd, Relay_log_info* rli,
+                               bool skip)
+{
+  int exec_res= 0;
+
+  DBUG_ENTER("apply_event_and_update_pos");
+
+  DBUG_PRINT("exec_event",("%s(type_code: %d; server_id: %d)",
+                           ev->get_type_str(), ev->get_type_code(),
+                           ev->server_id));
+  DBUG_PRINT("info", ("thd->options: %s%s; rli->last_event_start_time: %lu",
+                      FLAGSTR(thd->options, OPTION_NOT_AUTOCOMMIT),
+                      FLAGSTR(thd->options, OPTION_BEGIN),
+                      rli->last_event_start_time));
+
+  /*
+    Execute the event to change the database and update the binary
+    log coordinates, but first we set some data that is needed for
+    the thread.
+
+    The event will be executed unless it is supposed to be skipped.
+
+    Queries originating from this server must be skipped.  Low-level
+    events (Format_description_log_event, Rotate_log_event,
+    Stop_log_event) from this server must also be skipped. But for
+    those we don't want to modify 'group_master_log_pos', because
+    these events did not exist on the master.
+    Format_description_log_event is not completely skipped.
+
+    Skip queries specified by the user in 'slave_skip_counter'.  We
+    can't however skip events that has something to do with the log
+    files themselves.
+
+    Filtering on own server id is extremely important, to ignore
+    execution of events created by the creation/rotation of the relay
+    log (remember that now the relay log starts with its Format_desc,
+    has a Rotate etc).
+  */
+
+  thd->server_id = ev->server_id; // use the original server id for logging
+  thd->set_time();                            // time the query
+  thd->lex->current_select= 0;
+  if (!ev->when)
+    ev->when= my_time(0);
+  ev->thd = thd; // because up to this point, ev->thd == 0
+
+  if (skip)
+  {
+    int reason= ev->shall_skip(rli);
+    if (reason == Log_event::EVENT_SKIP_COUNT)
+      --rli->slave_skip_counter;
+    pthread_mutex_unlock(&rli->data_lock);
+    if (reason == Log_event::EVENT_SKIP_NOT)
+      exec_res= ev->apply_event(rli);
+#ifndef DBUG_OFF
+    /*
+      This only prints information to the debug trace.
+
+      TODO: Print an informational message to the error log?
+    */
+    static const char *const explain[] = {
+      // EVENT_SKIP_NOT,
+      "not skipped",
+      // EVENT_SKIP_IGNORE,
+      "skipped because event should be ignored",
+      // EVENT_SKIP_COUNT
+      "skipped because event skip counter was non-zero"
+    };
+    DBUG_PRINT("info", ("OPTION_BEGIN: %d; IN_STMT: %d",
+                        thd->options & OPTION_BEGIN ? 1 : 0,
+                        rli->get_flag(Relay_log_info::IN_STMT)));
+    DBUG_PRINT("skip_event", ("%s event was %s",
+                              ev->get_type_str(), explain[reason]));
+#endif
+  }
+  else
+    exec_res= ev->apply_event(rli);
+
+  DBUG_PRINT("info", ("apply_event error = %d", exec_res));
+  if (exec_res == 0)
+  {
+    int error= ev->update_pos(rli);
+    char buf[22];
+    DBUG_PRINT("info", ("update_pos error = %d", error));
+    DBUG_PRINT("info", ("group %s %s",
+                        llstr(rli->group_relay_log_pos, buf),
+                        rli->group_relay_log_name));
+    DBUG_PRINT("info", ("event %s %s",
+                        llstr(rli->event_relay_log_pos, buf),
+                        rli->event_relay_log_name));
+    /*
+      The update should not fail, so print an error message and
+      return an error code.
+
+      TODO: Replace this with a decent error message when merged
+      with BUG#24954 (which adds several new error message).
+    */
+    if (error)
+    {
+      rli->report(ERROR_LEVEL, ER_UNKNOWN_ERROR,
+                  "It was not possible to update the positions"
+                  " of the relay log information: the slave may"
+                  " be in an inconsistent state."
+                  " Stopped in %s position %s",
+                  rli->group_relay_log_name,
+                  llstr(rli->group_relay_log_pos, buf));
+      DBUG_RETURN(2);
+    }
+  }
+
+  DBUG_RETURN(exec_res ? 1 : 0);
+}
+
+
+/**
+  Top-level function for executing the next event from the relay log.
+
+  This function reads the event from the relay log, executes it, and
+  advances the relay log position.  It also handles errors, etc.
+
+  This function may fail to apply the event for the following reasons:
+
+   - The position specfied by the UNTIL condition of the START SLAVE
+     command is reached.
+
+   - It was not possible to read the event from the log.
+
+   - The slave is killed.
+
+   - An error occurred when applying the event, and the event has been
+     tried slave_trans_retries times.  If the event has been retried
+     fewer times, 0 is returned.
+
+   - init_master_info or init_relay_log_pos failed. (These are called
+     if a failure occurs when applying the event.)</li>
+
+   - An error occurred when updating the binlog position.
+
+  @retval 0 The event was applied.
+
+  @retval 1 The event was not applied.
+*/
 static int exec_relay_log_event(THD* thd, Relay_log_info* rli)
 {
   DBUG_ENTER("exec_relay_log_event");
@@ -1802,117 +1979,26 @@ static int exec_relay_log_event(THD* thd, Relay_log_info* rli)
   }
   if (ev)
   {
-    int const type_code= ev->get_type_code();
-    int exec_res= 0;
-
-    DBUG_PRINT("exec_event",("%s(type_code: %d; server_id: %d)",
-                       ev->get_type_str(), type_code, ev->server_id));
-    DBUG_PRINT("info", ("thd->options: %s%s; rli->last_event_start_time: %lu",
-                        FLAGSTR(thd->options, OPTION_NOT_AUTOCOMMIT),
-                        FLAGSTR(thd->options, OPTION_BEGIN),
-                        rli->last_event_start_time));
-
+    int exec_res= apply_event_and_update_pos(ev, thd, rli, TRUE);
 
     /*
-      Execute the event to change the database and update the binary
-      log coordinates, but first we set some data that is needed for
-      the thread.
-
-      The event will be executed unless it is supposed to be skipped.
-
-      Queries originating from this server must be skipped.  Low-level
-      events (Format_description_log_event, Rotate_log_event,
-      Stop_log_event) from this server must also be skipped. But for
-      those we don't want to modify 'group_master_log_pos', because
-      these events did not exist on the master.
-      Format_description_log_event is not completely skipped.
-
-      Skip queries specified by the user in 'slave_skip_counter'.  We
-      can't however skip events that has something to do with the log
-      files themselves.
-
-      Filtering on own server id is extremely important, to ignore
-      execution of events created by the creation/rotation of the relay
-      log (remember that now the relay log starts with its Format_desc,
-      has a Rotate etc).
+      Format_description_log_event should not be deleted because it will be
+      used to read info about the relay log's format; it will be deleted when
+      the SQL thread does not need it, i.e. when this thread terminates.
     */
-
-    thd->server_id = ev->server_id; // use the original server id for logging
-    thd->set_time();                            // time the query
-    thd->lex->current_select= 0;
-    if (!ev->when)
-      ev->when= my_time(0);
-    ev->thd = thd; // because up to this point, ev->thd == 0
-
-    int reason= ev->shall_skip(rli);
-    if (reason == Log_event::EVENT_SKIP_COUNT)
-      --rli->slave_skip_counter;
-    pthread_mutex_unlock(&rli->data_lock);
-    if (reason == Log_event::EVENT_SKIP_NOT)
-      exec_res= ev->apply_event(rli);
-#ifndef DBUG_OFF
-    /*
-      This only prints information to the debug trace.
-
-      TODO: Print an informational message to the error log?
-    */
-    static const char *const explain[] = {
-      // EVENT_SKIP_NOT,
-      "not skipped",
-      // EVENT_SKIP_IGNORE,
-      "skipped because event should be ignored",
-      // EVENT_SKIP_COUNT
-      "skipped because event skip counter was non-zero"
-    };
-    DBUG_PRINT("info", ("OPTION_BEGIN: %d; IN_STMT: %d",
-                        thd->options & OPTION_BEGIN ? 1 : 0,
-                        rli->get_flag(Relay_log_info::IN_STMT)));
-    DBUG_PRINT("skip_event", ("%s event was %s",
-                              ev->get_type_str(), explain[reason]));
-#endif
-
-    DBUG_PRINT("info", ("apply_event error = %d", exec_res));
-    if (exec_res == 0)
+    if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT)
     {
-      int error= ev->update_pos(rli);
-      char buf[22];
-      DBUG_PRINT("info", ("update_pos error = %d", error));
-      DBUG_PRINT("info", ("group %s %s",
-                          llstr(rli->group_relay_log_pos, buf),
-                          rli->group_relay_log_name));
-      DBUG_PRINT("info", ("event %s %s",
-                          llstr(rli->event_relay_log_pos, buf),
-                          rli->event_relay_log_name));
-      /*
-        The update should not fail, so print an error message and
-        return an error code.
-
-        TODO: Replace this with a decent error message when merged
-        with BUG#24954 (which adds several new error message).
-      */
-      if (error)
-      {
-        rli->report(ERROR_LEVEL, ER_UNKNOWN_ERROR,
-                    "It was not possible to update the positions"
-                    " of the relay log information: the slave may"
-                    " be in an inconsistent state."
-                    " Stopped in %s position %s",
-                    rli->group_relay_log_name,
-                    llstr(rli->group_relay_log_pos, buf));
-        DBUG_RETURN(1);
-      }
+      DBUG_PRINT("info", ("Deleting the event after it has been executed"));
+      delete ev;
     }
 
     /*
-       Format_description_log_event should not be deleted because it will be
-       used to read info about the relay log's format; it will be deleted when
-       the SQL thread does not need it, i.e. when this thread terminates.
+      update_log_pos failed: this should not happen, so we don't
+      retry.
     */
-    if (type_code != FORMAT_DESCRIPTION_EVENT)
-    {
-      DBUG_PRINT("info", ("Deleting the event after it has been executed"));
-      delete ev;
-    }
+    if (exec_res == 2)
+      DBUG_RETURN(1);
+
     if (slave_trans_retries)
     {
       int temp_err;
@@ -3051,7 +3137,7 @@ static int queue_old_event(Master_info *mi, const char *buf,
   any >=5.0.0 format.
 */
 
-int queue_event(Master_info* mi,const char* buf, ulong event_len)
+static int queue_event(Master_info* mi,const char* buf, ulong event_len)
 {
   int error= 0;
   ulong inc_pos;
@@ -3937,4 +4023,8 @@ template class I_List_iterator<i_string>;
 template class I_List_iterator<i_string_pair>;
 #endif
 
+/**
+  @} (end of group Replication)
+*/
+
 #endif /* HAVE_REPLICATION */