BUG#13593869 - 64035: SEVERAL ERRORS IN COM_BINLOG_DUMP/MYSQL_BINLOG_SEND CRASH THE SERVER

The server crashes when receiving a COM_BINLOG_DUMP command with a position of 0 or
larger than the file size.
The execution proceeds to an error block having the last read replication coordinates 
pointer be NULL and its dereferencing crashed the server.

Fixed with making "public" previously used only for heartbeat coordinates.


mysql-test/extra/rpl_tests/rpl_start_stop_slave.test:
  regression test for bug#3593869-64035 is added.
mysql-test/suite/rpl/r/rpl_cant_read_event_incident.result:
  results updated (error mess format is changed).
mysql-test/suite/rpl/r/rpl_log_pos.result:
  results updated (error mess format is changed).
mysql-test/suite/rpl/r/rpl_manual_change_index_file.result:
  results updated (error mess format is changed).
mysql-test/suite/rpl/r/rpl_packet.result:
  results updated (error mess format is changed).
mysql-test/suite/rpl/r/rpl_stm_start_stop_slave.result:
  results updated (error mess format is changed).
mysql-test/suite/rpl/t/rpl_stm_start_stop_slave.test:
  Slave is stopped by bug#3593869-64035 tests so 
  -let $rpl_only_running_threads= 1 is set prior to rpl_end.
sql/share/errmsg-utf8.txt:
  Increasing the max length of explanatory message to 512.
sql/sql_repl.cc:
  Making `coord' to carry the last read from binlog event coordinates
  regardless of heartbeat.
  Renaming, small cleanup and simplifying the code after if (coord) becomes unnecessary.
  Adding yet another 3rd pair of coordinates - the starting replication - 
  into error text.

11 files changed, 77 insertions, 34 deletions

diff --git a/mysql-test/extra/rpl_tests/rpl_start_stop_slave.test b/mysql-test/extra/rpl_tests/rpl_start_stop_slave.test
index 42250764b54..301f4d84c58 100644
--- a/mysql-test/extra/rpl_tests/rpl_start_stop_slave.test
+++ b/mysql-test/extra/rpl_tests/rpl_start_stop_slave.test
@@ -177,3 +177,36 @@ UNLOCK TABLES;
 --connection master
 DROP TABLE t1;
 sync_slave_with_master;
+
+#
+# bug#3593869-64035 uninitialized event_coordinates instance crashes server
+# Testing how out of valid range position value is handled with an error.
+#
+
+--connection master
+RESET MASTER;
+let $master_pos= query_get_value(SHOW MASTER STATUS, Position, 1);
+let $master_pos= `SELECT $master_pos + 1`;
+
+--connection slave
+--source include/stop_slave.inc
+--replace_regex /[0-9]+/MASTER_POS/
+eval CHANGE MASTER TO master_log_pos=$master_pos;
+
+START SLAVE;
+# ER_MASTER_FATAL_ERROR_READING_BINLOG 1236
+--let $slave_param=Last_IO_Errno
+--let $slave_param_value=1236
+--source include/wait_for_slave_param.inc
+
+--let $slave_io_error_replace= / at [0-9]*/ at XXX/ /\.\/*master-bin/master-bin/
+--let $status_items= Last_IO_Errno, Last_IO_Error
+--source include/show_slave_status.inc
+
+--source include/stop_slave.inc
+RESET SLAVE;
+
+--connection master
+RESET MASTER;
+
+# Slave is stopped by bug#3593869-64035 tests.
diff --git a/mysql-test/suite/rpl/r/rpl_cant_read_event_incident.result b/mysql-test/suite/rpl/r/rpl_cant_read_event_incident.result
index c1b2c6e3195..a719f865090 100644
--- a/mysql-test/suite/rpl/r/rpl_cant_read_event_incident.result
+++ b/mysql-test/suite/rpl/r/rpl_cant_read_event_incident.result
@@ -11,7 +11,7 @@ reset slave;
 start slave;
 include/wait_for_slave_param.inc [Last_IO_Errno]
 Last_IO_Errno = '1236'
-Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'binlog truncated in the middle of event; consider out of disk space on master; the last event was read from './master-bin.000001' at 316, the last byte read was read from './master-bin.000001' at 335.''
+Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'binlog truncated in the middle of event; consider out of disk space on master; the start event position from '' at XXX, the last event was read from 'master-bin.000001' at XXX, the last byte read was read from 'master-bin.000001' at XXX.''
 reset master;
 stop slave;
 reset slave;
diff --git a/mysql-test/suite/rpl/r/rpl_log_pos.result b/mysql-test/suite/rpl/r/rpl_log_pos.result
index 72e7c3e2d7f..afd91a29f9e 100644
--- a/mysql-test/suite/rpl/r/rpl_log_pos.result
+++ b/mysql-test/suite/rpl/r/rpl_log_pos.result
@@ -9,7 +9,7 @@ change master to master_log_pos=MASTER_LOG_POS;
 Read_Master_Log_Pos = '75'
 start slave;
 include/wait_for_slave_io_error.inc [errno=1236]
-Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master; the last event was read from 'master-bin.000001' at XXX, the last byte read was read from 'master-bin.000001' at XXX.''
+Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master; the start event position from 'master-bin.000001' at XXX, the last event was read from 'master-bin.000001' at XXX, the last byte read was read from 'master-bin.000001' at XXX.''
 include/stop_slave_sql.inc
 show master status;
 File	Position	Binlog_Do_DB	Binlog_Ignore_DB
diff --git a/mysql-test/suite/rpl/r/rpl_manual_change_index_file.result b/mysql-test/suite/rpl/r/rpl_manual_change_index_file.result
index e41886ddf6b..efe9bf076f0 100644
--- a/mysql-test/suite/rpl/r/rpl_manual_change_index_file.result
+++ b/mysql-test/suite/rpl/r/rpl_manual_change_index_file.result
@@ -5,7 +5,7 @@ CREATE TABLE t1(c1 INT);
 FLUSH LOGS;
 call mtr.add_suppression('Got fatal error 1236 from master when reading data from binary log: .*could not find next log');
 include/wait_for_slave_io_error.inc [errno=1236]
-Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'could not find next log; the last event was read from 'master-bin.000002' at XXX, the last byte read was read from 'master-bin.000002' at XXX.''
+Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'could not find next log; the start event position from 'master-bin.000001' at XXX, the last event was read from 'master-bin.000002' at XXX, the last byte read was read from 'master-bin.000002' at XXX.''
 CREATE TABLE t2(c1 INT);
 FLUSH LOGS;
 CREATE TABLE t3(c1 INT);
diff --git a/mysql-test/suite/rpl/r/rpl_packet.result b/mysql-test/suite/rpl/r/rpl_packet.result
index 864e246312d..b2da820755e 100644
--- a/mysql-test/suite/rpl/r/rpl_packet.result
+++ b/mysql-test/suite/rpl/r/rpl_packet.result
@@ -37,7 +37,7 @@ DROP TABLE t1;
 CREATE TABLE t1 (f1 int PRIMARY KEY, f2 LONGTEXT, f3 LONGTEXT) ENGINE=MyISAM;
 INSERT INTO t1(f1, f2, f3) VALUES(1, REPEAT('a', @@global.max_allowed_packet), REPEAT('b', @@global.max_allowed_packet));
 include/wait_for_slave_io_error.inc [errno=1236]
-Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master; the last event was read from 'master-bin.000001' at XXX, the last byte read was read from 'master-bin.000001' at XXX.''
+Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master; the start event position from '' at XXX, the last event was read from 'master-bin.000001' at XXX, the last byte read was read from 'master-bin.000001' at XXX.''
 STOP SLAVE;
 RESET SLAVE;
 RESET MASTER;
diff --git a/mysql-test/suite/rpl/r/rpl_stm_start_stop_slave.result b/mysql-test/suite/rpl/r/rpl_stm_start_stop_slave.result
index 57206873e2f..8bf903b0713 100644
--- a/mysql-test/suite/rpl/r/rpl_stm_start_stop_slave.result
+++ b/mysql-test/suite/rpl/r/rpl_stm_start_stop_slave.result
@@ -69,6 +69,16 @@ include/wait_for_slave_to_stop.inc
 include/start_slave.inc
 # Clean up
 DROP TABLE t1;
+RESET MASTER;
+include/stop_slave.inc
+CHANGE MASTER TO master_log_pos=MASTER_POS;
+START SLAVE;
+include/wait_for_slave_param.inc [Last_IO_Errno]
+Last_IO_Errno = '1236'
+Last_IO_Error = 'Got fatal error 1236 from master when reading data from binary log: 'Client requested master to start replication from impossible position; the start event position from 'master-bin.000001' at XXX, the last event was read from 'master-bin.000001' at XXX, the last byte read was read from 'master-bin.000001' at XXX.''
+include/stop_slave.inc
+RESET SLAVE;
+RESET MASTER;
 SET @@global.innodb_flush_log_at_trx_commit= @old_innodb_flush_log_at_trx_commit;
 call mtr.add_suppression("Slave SQL.*Request to stop slave SQL Thread received while applying a group that has non-transactional changes; waiting for completion of the group");
 SET @@global.innodb_flush_log_at_trx_commit= @old_innodb_flush_log_at_trx_commit;
diff --git a/mysql-test/suite/rpl/t/rpl_cant_read_event_incident.test b/mysql-test/suite/rpl/t/rpl_cant_read_event_incident.test
index 5e88b163d99..490ddf5d167 100644
--- a/mysql-test/suite/rpl/t/rpl_cant_read_event_incident.test
+++ b/mysql-test/suite/rpl/t/rpl_cant_read_event_incident.test
@@ -51,6 +51,7 @@ start slave;
 --let $slave_param_value=1236
 --source include/wait_for_slave_param.inc
 
+--let $slave_io_error_replace= / at [0-9]*/ at XXX/ /\.\/*master-bin/master-bin/
 --let $status_items= Last_IO_Errno, Last_IO_Error
 --source include/show_slave_status.inc
 
diff --git a/mysql-test/suite/rpl/t/rpl_stm_start_stop_slave.test b/mysql-test/suite/rpl/t/rpl_stm_start_stop_slave.test
index ada080e9071..dfe2e49bb90 100644
--- a/mysql-test/suite/rpl/t/rpl_stm_start_stop_slave.test
+++ b/mysql-test/suite/rpl/t/rpl_stm_start_stop_slave.test
@@ -22,5 +22,5 @@ SET @@global.innodb_flush_log_at_trx_commit= @old_innodb_flush_log_at_trx_commit
 call mtr.add_suppression("Slave SQL.*Request to stop slave SQL Thread received while applying a group that has non-transactional changes; waiting for completion of the group");
 --connection master
 SET @@global.innodb_flush_log_at_trx_commit= @old_innodb_flush_log_at_trx_commit;
-
+--let $rpl_only_running_threads= 1
 --source include/rpl_end.inc
diff --git a/sql/log_event.h b/sql/log_event.h
index d65f2d2c85d..6782f237a36 100644
--- a/sql/log_event.h
+++ b/sql/log_event.h
@@ -717,11 +717,11 @@ typedef struct st_print_event_info
   Such identifier is not yet unique generally as the event originating master
   is resetable. Also the crashed master can be replaced with some other.
 */
-struct event_coordinates
+typedef struct event_coordinates
 {
   char * file_name; // binlog file name (directories stripped)
   my_off_t  pos;       // event's position in the binlog file
-};
+} LOG_POS_COORD;
 
 /**
   @class Log_event
diff --git a/sql/share/errmsg-utf8.txt b/sql/share/errmsg-utf8.txt
index 5507b633f8f..04951f33fc4 100644
--- a/sql/share/errmsg-utf8.txt
+++ b/sql/share/errmsg-utf8.txt
@@ -4701,14 +4701,14 @@ ER_NOT_SUPPORTED_YET 42000
         spa "Esta versión de MySQL no soporta todavia '%s'"
         swe "Denna version av MySQL kan ännu inte utföra '%s'"
 ER_MASTER_FATAL_ERROR_READING_BINLOG  
-        nla "Kreeg fatale fout %d: '%-.256s' van master tijdens lezen van data uit binaire log"
-        eng "Got fatal error %d from master when reading data from binary log: '%-.256s'"
-        ger "Schwerer Fehler %d: '%-.256s vom Master beim Lesen des binären Logs"
-        ita "Errore fatale %d: '%-.256s' dal master leggendo i dati dal log binario"
-        por "Obteve fatal erro %d: '%-.256s' do master quando lendo dados do binary log"
-        rus "Получена неисправимая ошибка %d: '%-.256s' от головного сервера в процессе выборки данных из двоичного журнала"
-        spa "Recibió fatal error %d: '%-.256s' del master cuando leyendo datos del binary log"
-        swe "Fick fatalt fel %d: '%-.256s' från master vid läsning av binärloggen"
+        nla "Kreeg fatale fout %d: '%-.512s' van master tijdens lezen van data uit binaire log"
+        eng "Got fatal error %d from master when reading data from binary log: '%-.512s'"
+        ger "Schwerer Fehler %d: '%-.512s vom Master beim Lesen des binären Logs"
+        ita "Errore fatale %d: '%-.512s' dal master leggendo i dati dal log binario"
+        por "Obteve fatal erro %d: '%-.512s' do master quando lendo dados do binary log"
+        rus "Получена неисправимая ошибка %d: '%-.512s' от головного сервера в процессе выборки данных из двоичного журнала"
+        spa "Recibió fatal error %d: '%-.512s' del master cuando leyendo datos del binary log"
+        swe "Fick fatalt fel %d: '%-.512s' från master vid läsning av binärloggen"
 ER_SLAVE_IGNORED_TABLE  
         eng "Slave SQL thread ignored the query because of replicate-*-table rules"
         ger "Slave-SQL-Thread hat die Abfrage aufgrund von replicate-*-table-Regeln ignoriert"
diff --git a/sql/sql_repl.cc b/sql/sql_repl.cc
index 5300a327029..605acc1f393 100644
--- a/sql/sql_repl.cc
+++ b/sql/sql_repl.cc
@@ -447,8 +447,7 @@ void mysql_binlog_send(THD* thd, char* log_ident, my_off_t pos,
   String* packet = &thd->packet;
   int error;
   const char *errmsg = "Unknown error";
-  const char *fmt= "%s; the last event was read from '%s' at %s, the last byte read was read from '%s' at %s.";
-  char llbuff1[22], llbuff2[22];
+  char llbuff0[22], llbuff1[22], llbuff2[22];
   char error_text[MAX_SLAVE_ERRMSG]; // to be send to slave via my_message()
   NET* net = &thd->net;
   mysql_mutex_t *log_lock;
@@ -468,16 +467,15 @@ void mysql_binlog_send(THD* thd, char* log_ident, my_off_t pos,
   */
   ulonglong heartbeat_period= get_heartbeat_period(thd);
   struct timespec heartbeat_buf;
-  struct event_coordinates coord_buf;
   struct timespec *heartbeat_ts= NULL;
-  struct event_coordinates *coord= NULL;
+  const LOG_POS_COORD start_coord= { log_ident, pos },
+    *p_start_coord= &start_coord;
+  LOG_POS_COORD coord_buf= { log_file_name, BIN_LOG_HEADER_SIZE },
+    *p_coord= &coord_buf;
   if (heartbeat_period != LL(0))
   {
     heartbeat_ts= &heartbeat_buf;
     set_timespec_nsec(*heartbeat_ts, 0);
-    coord= &coord_buf;
-    coord->file_name= log_file_name; // initialization basing on what slave remembers
-    coord->pos= pos;
   }
   sql_print_information("Start binlog_dump to slave_server(%d), pos(%s, %lu)",
                         thd->server_id, log_ident, (ulong)pos);
@@ -597,6 +595,7 @@ impossible position";
     mysql_bin_log, and it's already inited, and it will be destroyed
     only at shutdown).
   */
+  p_coord->pos= pos; // the first hb matches the slave's last seen value
   log_lock= mysql_bin_log.get_log_lock();
   log_cond= mysql_bin_log.get_log_cond();
   if (pos > BIN_LOG_HEADER_SIZE)
@@ -694,8 +693,7 @@ impossible position";
       /*
         log's filename does not change while it's active
       */
-      if (coord)
-        coord->pos= uint4korr(packet->ptr() + ev_offset + LOG_POS_OFFSET);
+      p_coord->pos= uint4korr(packet->ptr() + ev_offset + LOG_POS_OFFSET);
 
       event_type= (Log_event_type)((*packet)[LOG_EVENT_OFFSET+ev_offset]);
       DBUG_EXECUTE_IF("dump_thread_wait_before_send_xid",
@@ -851,8 +849,7 @@ impossible position";
 	  /* we read successfully, so we'll need to send it to the slave */
           mysql_mutex_unlock(log_lock);
 	  read_packet = 1;
-          if (coord)
-            coord->pos= uint4korr(packet->ptr() + ev_offset + LOG_POS_OFFSET);
+          p_coord->pos= uint4korr(packet->ptr() + ev_offset + LOG_POS_OFFSET);
           event_type= (Log_event_type)((*packet)[LOG_EVENT_OFFSET+ev_offset]);
 	  break;
 
@@ -874,16 +871,16 @@ impossible position";
           signal_cnt= mysql_bin_log.signal_cnt;
           do 
           {
-            if (coord)
+            if (heartbeat_period != 0)
             {
-              DBUG_ASSERT(heartbeat_ts && heartbeat_period != 0);
+              DBUG_ASSERT(heartbeat_ts);
               set_timespec_nsec(*heartbeat_ts, heartbeat_period);
             }
             thd->enter_cond(log_cond, log_lock,
                             "Master has sent all binlog to slave; "
                             "waiting for binlog to be updated");
             ret= mysql_bin_log.wait_for_update_bin_log(thd, heartbeat_ts);
-            DBUG_ASSERT(ret == 0 || (heartbeat_period != 0 && coord != NULL));
+            DBUG_ASSERT(ret == 0 || (heartbeat_period != 0));
             if (ret == ETIMEDOUT || ret == ETIME)
             {
 #ifndef DBUG_OFF
@@ -901,7 +898,7 @@ impossible position";
                 thd->exit_cond(old_msg);
                 goto err;
               }
-              if (send_heartbeat_event(net, packet, coord))
+              if (send_heartbeat_event(net, packet, p_coord))
               {
                 errmsg = "Failed on my_net_write()";
                 my_errno= ER_UNKNOWN_ERROR;
@@ -1012,8 +1009,7 @@ impossible position";
 	goto err;
       }
 
-      if (coord)
-        coord->file_name= log_file_name; // reset to the next
+      p_coord->file_name= log_file_name; // reset to the next
     }
   }
 
@@ -1038,9 +1034,12 @@ err:
        detailing the fatal error message with coordinates 
        of the last position read.
     */
+    const char *fmt= "%s; the start event position from '%s' at %s, the last event was read from '%s' at %s, the last byte read was read from '%s' at %s.";
     my_snprintf(error_text, sizeof(error_text), fmt, errmsg,
-                coord->file_name, (llstr(coord->pos, llbuff1), llbuff1),
-                log_file_name, (llstr(my_b_tell(&log), llbuff2), llbuff2));
+                p_start_coord->file_name,
+                (llstr(p_start_coord->pos, llbuff0), llbuff0),
+                p_coord->file_name, (llstr(p_coord->pos, llbuff1), llbuff1),
+                log_file_name,    (llstr(my_b_tell(&log), llbuff2), llbuff2));
   }
   else
     strcpy(error_text, errmsg);