MySQL Bugs: #74734: mysqlbinlog can't decode events

Bug #74734	mysqlbinlog can't decode events > ~1.6GB
Submitted:	7 Nov 2014 13:32	Modified:	24 Apr 2015 17:06
Reporter:	Hartmut Holzgraefe	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	mysql-5.6.20, 5.6.24	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
Since bug #49932 got fixed mysqlbinlog can handle log events >1GB,
it now fails when log events get larger than about 1.6GB though

Problem is that mysqlbinlog tries to allocate a buffer large enough
to store a base64 encoded version of the event data (in sql/log_event.cc). 
Data length is taken from a four byte field in the event header, so it is 
limited to 4GB, which isn't the problem here yet. This value is then passed
to base64_needed_encoded_length() from mysys/base64.c, and here disaster 
strikes as this function is declared as 

  int base64_needed_encoded_length(int length_of_data)

while log_event.c passes in an unsigend uint32 value and stores the result
in a size_t variable which is then used to allocate memory for the base64
output buffer.

As base64 needs about 4 3rds as much space of the raw data an integer overflow happens for the return value as soon as length_of_data exceeds 3/4th of 2^31 or about 1.6GB ...

How to repeat:
with log_bin active and binlog_format=ROW:

  CREATE TABLE t1(b1 LONGBLOB, b2 LONGBLOB) ENGINE=MyISAM;
  FLUSH LOGS;
  INSERT INTO t1 VALUES(REPEAT('a', 700000000), REPEAT('b', 70000000));
  FLUSH LOGS;
  INSERT INTO t1 VALUES(REPEAT('a', 800000000), REPEAT('b', 80000000));
  FLUSH LOGS;

you'll now have two large binlog files >1GB, the one for the first INSERT can be processed by mysqlbinlog just fine. Processing the log file containing the event for the 2nd INSERT will result in
  
  [...]
  # at 192
  #141107 13:08:28 server id 23  end_log_pos 241 CRC32 0x6381e285 	  
  Table_map: `test`.`t1` mapped to number 70
  bin/mysqlbinlog: Out of memory (Needed 2161403577 bytes)

  Error: Out of memory. Could not print correct binlog event.

While the error messages shows the requested size as unsigned; which at ~2GB on a machine with ~9GB free and no ulimits set should have been allocated by malloc() just fine, strace shows: 

[...]
25309 write(1, "# at 192\n#141107 13:08:28 server"..., 117) = 117
25309 mmap(NULL, 1600004096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f312fcea000
25309 read(3, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"..., 1599934464) = 1599934464
25309 read(3, "bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb"..., 418) = 418
25309 mmap(NULL, 1600004096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f30d0708000
25309 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2309, ...}) = 0
25309 mmap(NULL, 18446744071575990272, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = -1 ENOMEM (Cannot allocate memory)
[...]

So instead of 2161403577 bytes (~2GB) malloc/mmap received a request for  
18446744071575990272 (~18 ExaBytes) was issued due to the uint32->int->size_t conversion mess ...

Suggested fix:
convert 

  int base64_needed_encoded_length(int length_of_data)

to 

  size_t base64_needed_encoded_length(size_t length_of_data)

so that sizes are calculated properly

Hello Hartmut Holzgraefe,

Thank you for the report.
Observed this behavior on my test box after >5 attempts.

Thanks,
Umesh

// Build used

ushastry@ushastry:~/Downloads/mysql-5.6.24$ more docs/INFO_SRC 
commit: c7c5dcc9a4fc1669b5578d8d5122305272c837c4
date: 2015-01-12 14:10:32 +0530
build-date: 2015-01-12 18:00:53 +0100
short: c7c5dcc
branch: mysql-5.6

MySQL source 5.6.24

// Start up

scripts/mysql_install_db --no-defaults --basedir=/home/ushastry/Downloads/mysql-5.6.24 --datadir=/home/ushastry/Downloads/mysql-5.6.24/74734
bin/mysqld --no-defaults --basedir=/home/ushastry/Downloads/mysql-5.6.24 --datadir=/home/ushastry/Downloads/mysql-5.6.24/74734 --log_bin=master-bin --binlog_format=ROW --server_id=1 --max_allowed_packet=1G --socket=/tmp/mysql.sock  --port=3306 --log-error=/home/ushastry/Downloads/mysql-5.6.24/74734/log.err 2>&1 &

// try to increase/decrease repeatr count in order to make events > ~1.6GB

  CREATE TABLE t1(b1 LONGBLOB, b2 LONGBLOB) ENGINE=MyISAM;
  INSERT INTO t1 VALUES(REPEAT('a', 950000000), REPEAT('b', 75000000));
  INSERT INTO t1 VALUES(REPEAT('a', 950000000), REPEAT('b', 95000000));
  FLUSH LOGS;

ushastry@ushastry:~/Downloads/mysql-5.6.24$ bin/mysqlbinlog --base64-output=decode-rows 74734/master-bin.000024 
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#150113 15:40:42 server id 1  end_log_pos 120 CRC32 0xa15cfa38 	Start: binlog v 4, server v 5.6.24-enterprise-commercial-advanced-log created 150113 15:40:42
# at 120
#150113 15:45:20 server id 1  end_log_pos 192 CRC32 0xc0efe028 	Query	thread_id=1	exec_time=41	error_code=0
SET TIMESTAMP=1421144120/*!*/;
SET @@session.pseudo_thread_id=1/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1073741824/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 192
#150113 15:45:20 server id 1  end_log_pos 240 CRC32 0x665d5013 	Table_map: `test`.`t1` mapped to number 70
bin/mysqlbinlog: Out of memory (Needed 1391403569 bytes)

Error: Out of memory. Could not print correct binlog event.

ushastry@ushastry:~/Downloads/mysql-5.6.24$ ls -lh 74734/master-bin.000024 
-rw-rw---- 1 ushastry ushastry 2.0G Jan 13 15:50 74734/master-bin.000024

ushastry@ushastry:~/Downloads/mysql-5.6.24$ free -m -t
             total       used       free     shared    buffers     cached
Mem:          3013        262       2750          0          0         41
-/+ buffers/cache:        220       2792
Swap:         2020        480       1540
Total:        5034        743       4291

Thanks for your input. This has been fixed in upcoming versions and the following was added to the changelog:

Using mysqlbinlog to process log events greater than 1.6GB failed with an out of memory error. This was caused by an internal error converting the length variable. The fix upgrades the length variable to avoid overflow in both encoding and decoding functions.

commit ba082ab5c077d74e50b364a432296e99b5b3a57f
Author: Sujatha Sivakumar <sujatha.sivakumar@oracle.com>
Date:   Thu Apr 16 10:55:47 2015 +0530

    Bug#20350989: MYSQLBINLOG CAN'T DECODE EVENTS > ~1.6GB
    
    Problem:
    ========
    While converting row_data into base64 encoded format the
    row_data size conversion happens in the following manner.
    The initial row data is stored in an uint32 variable. The
    base64 encoded value needs about 4/3rds as much space of the
    raw data. Int variable is used to store the base64 bit
    encoded length. Because of this when a large event is
    received the conversion from uint32->int results in
    overflow.
    
    So instead of 2161403577 bytes (~2GB), malloc/mmap received
    a request for 18446744071575990272 (~18 ExaBytes) was issued
    due to the uint32->int->size_t conversion mess ...
    
    Analysis:
    ========
    Problem is that mysqlbinlog tries to allocate a buffer large
    enough to store a base64 encoded version of the event data
    (in sql/log_event.cc). Data length is taken from a four byte
    field in the event header, so it is limited to 4GB, which
    isn't the problem here yet. This value is then passed to
    base64_needed_encoded_length() from mysys/base64.c, and here
    disaster strikes as this function is declared as
    
    int base64_needed_encoded_length(int length_of_data)
    
    log_event.cc stores the extracted event length in uint32
    variable. This length is intern passed to the above function
    base64_needed_encoded_length which converts the size to int.
    When the event size is large and required base64 data length
    exceeds int limits this results in an overflow and results
    in out of memory error.
    
    Fix:
    ===
    Upgraded the length variable to avoid overflow in both
    encoding and decoding functions.
    
    Note: The mentioned server changes will cause following
    warnings in cluster code.
    
    storage/ndb/src/mgmapi/mgmapi.cpp:3407: warning: field width
    specifier ‘*’ expects argument of type ‘int’, but argument 3
    has type ‘size_t {aka long unsigned int}’ [-Wformat=]
    
    storage/ndb/src/mgmsrv/Config.cpp:247: warning:...
    
    The above code changes are used in cluster code to exchange
    configuration data between cluster nodes and management
    server. This code is used for both packing and unpacking the
    base64 encoded data. This data can be of max length as shown
    below which is well within int limits.
    
    if(len64 ==0 || len64 > (1024*1024)) {
      result.assfmt("Illegal config length size %d", len64);
      goto done;
    }
    
    Hence to fix these warnings for cluster code the base64
    encoded length is still typecasted to int.