Bug #64035 Several errors in COM_BINLOG_DUMP/mysql_binlog_send crash the server in 5.5.18+
Submitted: 15 Jan 2012 6:07 Modified: 19 Jan 2012 11:31
Reporter: Jeremy Cole (Basic Quality Contributor) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S1 (Critical)
Version:5.5.18+ OS:Any
Assigned to:
Tags: binlog dump crash, COM_BINLOG_DUMP, null pointer, qc, regression, replication
Triage: Needs Triage: D1 (Critical)

[15 Jan 2012 6:07] Jeremy Cole
Description:
The server crashes when receiving a COM_BINLOG_DUMP command with a position of 0 or larger than the file size. This is supposed to be protected by the following block of code, which checks if pos is less than BIN_LOG_HEADER_SIZE (4) [all line numbers relative to 5.5.20]:

 537   if (pos < BIN_LOG_HEADER_SIZE || pos > my_b_filelength(&log))
 538   {
 539     errmsg= "Client requested master to start replication from \
 540 impossible position";
 541     my_errno= ER_MASTER_FATAL_ERROR_READING_BINLOG;
 542     goto err;
 543   }

In addition there are a couple of other places where ER_MASTER_FATAL_ERROR_READING_BINLOG is used which should also crash the server if reached.

At the "err" label, the following code is called:

1033 err:
1034   thd_proc_info(thd, "Waiting to finalize termination");
1035   if (my_errno == ER_MASTER_FATAL_ERROR_READING_BINLOG && my_b_inited(&log))
1036   {
1037     /*
1038        detailing the fatal error message with coordinates
1039        of the last position read.
1040     */
1041     my_snprintf(error_text, sizeof(error_text), fmt, errmsg,
1042                 coord->file_name, (llstr(coord->pos, llbuff1), llbuff1),
1043                 log_file_name, (llstr(my_b_tell(&log), llbuff2), llbuff2));
1044   }
1045   else
1046     strcpy(error_text, errmsg);

At this point coord has not been initialized, and this crashes the server by de-referencing it for coord->file_name and coord->pos.

The only place that coord is initialized is under a heartbeat-related test:

 474   if (heartbeat_period != LL(0))
 475   {
 476     heartbeat_ts= &heartbeat_buf;
 477     set_timespec_nsec(*heartbeat_ts, 0);
 478     coord= &coord_buf;
 479     coord->file_name= log_file_name; // initialization basing on what slave remembers
 480     coord->pos= pos;
 481   }

GDB session:

120114 20:39:22 [Note] Start binlog_dump to slave_server(0), pos(tw-mbp15-jeremycole-bin.000003, 0)

Program received signal EXC_BAD_ACCESS, Could not access memory.
Reason: KERN_INVALID_ADDRESS at address: 0x0000000000000008
[Switching to process 64287 thread 0x2607]
0x00000001002fe6ea in mysql_binlog_send (thd=0x1018dbc00, log_ident=0x10d806c10 "tw-mbp15-jeremycole-bin.000003", pos=0, flags=0) at sql_repl.cc:1043
1043	                log_file_name, (llstr(my_b_tell(&log), llbuff2), llbuff2));
(gdb) bt
#0  0x00000001002fe6ea in mysql_binlog_send (thd=0x1018dbc00, log_ident=0x10d806c10 "tw-mbp15-jeremycole-bin.000003", pos=0, flags=0) at sql_repl.cc:1043
#1  0x00000001002c139b in dispatch_command (command=COM_BINLOG_DUMP, thd=0x1018dbc00, packet=0x1018df201 "", packet_length=40) at sql_parse.cc:1237
#2  0x00000001002c24a1 in do_command (thd=0x1018dbc00) at sql_parse.cc:773
#3  0x0000000100401483 in do_handle_one_connection (thd_arg=0x1018dbc00) at sql_connect.cc:789
#4  0x0000000100401583 in handle_one_connection (arg=0x1018dbc00) at sql_connect.cc:708
#5  0x00007fff818328bf in _pthread_start ()
#6  0x00007fff81835b75 in thread_start ()
(gdb) p coord
$1 = (event_coordinates *) 0x0

How to repeat:
mysqlbinlog --read-from-remote-server -h 127.0.0.1 -P 3307 valid-log-name -j pos-larger-than-file

or

memset(buf, 0, 10);
memcpy(buf+10, name, strlen(name));  
cli_advanced_command(mysql, COM_BINLOG_DUMP, 0, 0, buf, 10 + strlen(name), 1, NULL);

Suggested fix:
Move the initialization of coord outside of the "if (heartbeat_period != LL(0))" test, or fix the error message construction to not rely on it.
[15 Jan 2012 6:10] Jeremy Cole
I forgot to add, that this code was introduced in 5.5.18 in the fix for Bug 32228:

http://bugs.mysql.com/bug.php?id=32228
[15 Jan 2012 9:23] Valerii Kravchuk
Thank you for the bug report. Verified on Mac OS X:

macbook-pro:5.5 openxs$ bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.5.20-debug-log Source distribution

Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> create table tt2(c1 int);
Query OK, 0 rows affected (0.07 sec)

mysql> insert into tt2 values(1), (2);
Query OK, 2 rows affected (0.00 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> show master status\G
*************************** 1. row ***************************
            File: macbook-pro-bin.000004
        Position: 382
    Binlog_Do_DB: 
Binlog_Ignore_DB: 
1 row in set (0.00 sec)

mysql> exit
Bye
macbook-pro:5.5 openxs$ bin/mysqlbinlog -uroot --read-from-remote-server -h 127.0.0.1 -P 3306 macbook-pro-bin.000004 -j 500
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
ERROR: Got error reading packet from server: Lost connection to MySQL server during query
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
macbook-pro:5.5 openxs$ 120115 11:20:27 mysqld_safe mysqld restarted
[15 Jan 2012 16:08] Mark Callaghan
This ia a great place for an error injection test.
[15 Jan 2012 16:09] Mark Callaghan
This is a great place for an error injection test
[19 Jan 2012 11:31] Jon Stephens
Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.

If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at

    http://dev.mysql.com/doc/en/installing-source.html
[19 Jan 2012 11:32] Jon Stephens
Documented fix in the 5.5.21 and 5.6.5 changelogs as follows:

        Executing mysqlbinlog with the --start-position=N option, where
        N was equal either to 0 or to a value greater than the length of
        the dump file, caused it to crash.

        This issue was introduced in MySQL 5.5.18 by the fix for Bug
        #32228 and Bug #11747416.

Closed.