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.

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.

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;

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

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

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;

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;

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
 

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

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

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"

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 @@ impossible position";
        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);