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

@@ -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;

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

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\

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