Bug #47142 "slave start until" stops 1 event too late in 4.1 to 5.0 replication

When replicating from 4.1 master to 5.0 slave START SLAVE UNTIL can stop too late.
The necessary in calculating of the beginning of an event the event's length
did not correspond to the master's genuine information at the event's execution time.
That piece of info was changed at the event's relay-logging due to binlog_version<4 event
conversion by IO thread.

Fixed with storing the master genuine Query_log_event size into a new status
variable at relay-logging of the event. The stored info is extacted at the event
execution and participate further to caclulate the correct start position of the event
in the until-pos stopping routine.
The new status variable's algorithm will be only active when the event comes
from the master of version < 5.0 (binlog_version < 4).


mysql-test/r/rpl_until.result:
  results changed.
mysql-test/std_data/bug47142_master-bin.000001:
  a binlog from 4.1 master to replace one of the running 5.x master is added as 
  part of Bug #47142 regression test.
mysql-test/t/rpl_until.test:
  Regression test for Bug #47142 is added.
sql/log_event.cc:
  Storing and extracting the master's genuine size of the event from the status
  var of the event packet header.
  The binlog_version<4 query-log-event is 
  a. converted into the modern binlog_version==4 to store the original size of the event
     into a new status var; the converted representation goes into the relay log.
  b. the converted event is read out and the stored size is engaged in the start pos calculation.
  
  The new status is active only for events that IO thread instantiates for the sake of the conversion.
sql/log_event.h:
  Incrementing the max szie of MAX_SIZE_LOG_EVENT_STATUS because of the new status var;
  Defining the new status variable to hold the master's genuine event size;
  Augmenting the Query_log_event with a new member to hold a value to store/extact from the status
  var of the event packet header.

5 files changed, 102 insertions, 4 deletions

diff --git a/mysql-test/r/rpl_until.result b/mysql-test/r/rpl_until.result
index 60b956785ba..476e56878db 100644
--- a/mysql-test/r/rpl_until.result
+++ b/mysql-test/r/rpl_until.result
@@ -194,3 +194,21 @@ start slave sql_thread;
 start slave until master_log_file='master-bin.000001', master_log_pos=776;
 Warnings:
 Note	1254	Slave is already running
+stop slave;
+drop table if exists t1;
+Warnings:
+Note	1051	Unknown table 't1'
+flush logs;
+show binary logs;
+Log_name	File_size
+master-bin.000001	#
+master-bin.000002	#
+reset slave;
+start slave until master_log_file='master-bin.000001', master_log_pos=294 /* to stop right before DROP */;
+show tables /* t1 must exist */;
+Tables_in_test
+t1
+drop table t1;
+stop slave;
+reset slave;
+reset master;
diff --git a/mysql-test/std_data/bug47142_master-bin.000001 b/mysql-test/std_data/bug47142_master-bin.000001
new file mode 100644
index 00000000000..d1a089a784a
--- /dev/null
+++ b/mysql-test/std_data/bug47142_master-bin.000001
diff --git a/mysql-test/t/rpl_until.test b/mysql-test/t/rpl_until.test
index c404ea7e58b..b533c2192b0 100644
--- a/mysql-test/t/rpl_until.test
+++ b/mysql-test/t/rpl_until.test
@@ -84,4 +84,40 @@ start slave until relay_log_file='slave-relay-bin.000002', master_log_pos=561;
 start slave sql_thread;
 start slave until master_log_file='master-bin.000001', master_log_pos=776;
 
+#
+# Bug #47142  	"slave start until" stops 1 event too late in 4.1 to 5.0 replication
+#
+# testing fixes that refine the start position of prior-5.0 master's event
+# and by that provide correct execution of 
+# START SLAVE UNTIL ... master_log_pos= x;
+# Keep the test at the end of the file because it manipulates with binlog files 
+# to substitute the genuine one with a prepared on 4.1 server.
+#
+
+connection slave;
+stop slave;
+
+connection master;
+drop table if exists t1;
+flush logs;
+--source include/show_binary_logs.inc
+--remove_file $MYSQLTEST_VARDIR/log/master-bin.000001
+--copy_file $MYSQL_TEST_DIR/std_data/bug47142_master-bin.000001 $MYSQLTEST_VARDIR/log/master-bin.000001
+
+connection slave;
+reset slave;
+start slave until master_log_file='master-bin.000001', master_log_pos=294 /* to stop right before DROP */;
+--source include/wait_for_slave_sql_to_stop.inc
+
+show tables /* t1 must exist */;
+
+# clean-up of Bug #47142 testing
+
+drop table t1; # drop on slave only, master does not have t1. 
+stop slave;
+reset slave;
+
+connection master;
+reset master;
+
 # End of 4.1 tests
diff --git a/sql/log_event.cc b/sql/log_event.cc
index 40e29e58ab6..f32fcb0056c 100644
--- a/sql/log_event.cc
+++ b/sql/log_event.cc
@@ -1271,10 +1271,22 @@ bool Query_log_event::write(IO_CACHE* file)
     int8store(start, table_map_for_update);
     start+= 8;
   }
+  if (master_data_written != 0)
+  {
+    /*
+      Q_MASTER_DATA_WRITTEN_CODE only exists in relay logs where the master
+      has binlog_version<4 and the slave has binlog_version=4. See comment
+      for master_data_written in log_event.h for details.
+    */
+    *start++= Q_MASTER_DATA_WRITTEN_CODE;
+    int4store(start, master_data_written);
+    start+= 4;
+  }
+
   /*
     NOTE: When adding new status vars, please don't forget to update
-    the MAX_SIZE_LOG_EVENT_STATUS in log_event.h and update function
-    code_name in this file.
+    the MAX_SIZE_LOG_EVENT_STATUS in log_event.h and update the function
+    code_name() in this file.
    
     Here there could be code like
     if (command-line-option-which-says-"log_this_variable" && inited)
@@ -1354,6 +1366,7 @@ Query_log_event::Query_log_event(THD* thd_arg, const char* query_arg,
    auto_increment_offset(thd_arg->variables.auto_increment_offset),
    lc_time_names_number(thd_arg->variables.lc_time_names->number),
    charset_database_number(0),
+   master_data_written(0),
    table_map_for_update((ulonglong)thd_arg->table_map_for_update)
 {
   time_t end_time;
@@ -1481,6 +1494,7 @@ code_name(int code)
   case Q_LC_TIME_NAMES_CODE: return "Q_LC_TIME_NAMES_CODE";
   case Q_CHARSET_DATABASE_CODE: return "Q_CHARSET_DATABASE_CODE";
   case Q_TABLE_MAP_FOR_UPDATE_CODE: return "Q_TABLE_MAP_FOR_UPDATE_CODE";
+  case Q_MASTER_DATA_WRITTEN_CODE: return "Q_MASTER_DATA_WRITTEN_CODE";
   }
   sprintf(buf, "CODE#%d", code);
   return buf;
@@ -1518,7 +1532,7 @@ Query_log_event::Query_log_event(const char* buf, uint event_len,
    flags2_inited(0), sql_mode_inited(0), charset_inited(0),
    auto_increment_increment(1), auto_increment_offset(1),
    time_zone_len(0), lc_time_names_number(0), charset_database_number(0),
-   table_map_for_update(0)
+   table_map_for_update(0), master_data_written(0)
 {
   ulong data_len;
   uint32 tmp;
@@ -1574,6 +1588,18 @@ Query_log_event::Query_log_event(const char* buf, uint event_len,
     DBUG_PRINT("info", ("Query_log_event has status_vars_len: %u",
                         (uint) status_vars_len));
     tmp-= 2;
+  } 
+  else
+  {
+    /*
+      server version < 5.0 / binlog_version < 4 master's event is 
+      relay-logged with storing the original size of the event in
+      Q_MASTER_DATA_WRITTEN_CODE status variable.
+      The size is to be restored at reading Q_MASTER_DATA_WRITTEN_CODE-marked
+      event from the relay log.
+    */
+    DBUG_ASSERT(description_event->binlog_version < 4);
+    master_data_written= data_written;
   }
   /*
     We have parsed everything we know in the post header for QUERY_EVENT,
@@ -1665,6 +1691,11 @@ Query_log_event::Query_log_event(const char* buf, uint event_len,
       table_map_for_update= uint8korr(pos);
       pos+= 8;
       break;
+    case Q_MASTER_DATA_WRITTEN_CODE:
+      CHECK_SPACE(pos, end, 4);
+      data_written= master_data_written= uint4korr(pos);
+      pos+= 4;
+      break;
     default:
       /* That's why you must write status vars in growing order of code */
       DBUG_PRINT("info",("Query_log_event has unknown status vars (first has\
diff --git a/sql/log_event.h b/sql/log_event.h
index 45e3d11b48c..10b374199de 100644
--- a/sql/log_event.h
+++ b/sql/log_event.h
@@ -212,7 +212,8 @@ struct sql_ex_info
                                    1 + 1 + 255    /* type, length, time_zone */ + \
                                    1 + 2          /* type, lc_time_names_number */ + \
                                    1 + 2          /* type, charset_database_number */ + \
-                                   1 + 8          /* type, table_map_for_update */)
+                                   1 + 8          /* type, table_map_for_update */ + \
+                                   1 + 4          /* type, master_data_written */)
 #define MAX_LOG_EVENT_HEADER   ( /* in order of Query_log_event::write */ \
   LOG_EVENT_HEADER_LEN + /* write_header */ \
   QUERY_HEADER_LEN     + /* write_data */   \
@@ -278,6 +279,9 @@ struct sql_ex_info
 #define Q_CHARSET_DATABASE_CODE 8
 
 #define Q_TABLE_MAP_FOR_UPDATE_CODE 9
+
+#define Q_MASTER_DATA_WRITTEN_CODE 10
+
 /* Intvar event post-header */
 
 #define I_TYPE_OFFSET        0
@@ -810,6 +814,15 @@ public:
     statement, for other query statements, this will be zero.
   */
   ulonglong table_map_for_update;
+  /*
+    Holds the original length of a Query_log_event that comes from a
+    master of version < 5.0 (i.e., binlog_version < 4). When the IO
+    thread writes the relay log, it augments the Query_log_event with a
+    Q_MASTER_DATA_WRITTEN_CODE status_var that holds the original event
+    length. This field is initialized to non-zero in the SQL thread when
+    it reads this augmented event.
+  */
+  uint32 master_data_written;
 
 #ifndef MYSQL_CLIENT