Bug #82212 mysqlbinlog can produce events larger than max_allowed_packet for mysql
Submitted: 13 Jul 2016 7:26 Modified: 13 Jul 2016 9:37
Reporter: Valeriy Kravchuk Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.6.29, any, 5.6.31 OS:Any
Assigned to: CPU Architecture:Any
Tags: max_allowed_packet, missing manual, MySQL, mysqlbinlog

[13 Jul 2016 7:26] Valeriy Kravchuk
Description:
The "fix" for the Bug #60926 just introduced a new variable, slave_max_allowed_packet, that (when master size max_allowed_packet was not 1G already) allows slave to read somewhat bigger row-based events. But this fix does not help to do point in time or partial recovery based on mysqlbinlog ... | mysql ... typical approach. 

See a primitive test case below to show this, actually based on the MTR one from Sveta in Bug #60926.

How to repeat:
Make sure you have binary logging enabled, binlog_format set to ROW and some small max_allowed_packet size (16K in my case) set on server. Then:

C:\Program Files\MySQL\MySQL Server 5.6\bin>mysql -uroot -proot -P3314 test
Warning: Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 30
Server version: 5.6.29-log MySQL Community Server (GPL)

Copyright (c) 2000, 2016, 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> select @@binlog_format;
+-----------------+
| @@binlog_format |
+-----------------+
| ROW             |
+-----------------+
1 row in set (0.00 sec)

mysql> select @@max_allowed_packet;
+----------------------+
| @@max_allowed_packet |
+----------------------+
|                16384 |
+----------------------+
1 row in set (0.00 sec)

mysql> flush logs;
Query OK, 0 rows affected (0.29 sec)

mysql> drop table if exists t1;
Query OK, 0 rows affected (0.36 sec)

mysql> create table t1(f1q longtext);
Query OK, 0 rows affected (0.48 sec)

mysql> insert into t1 values(repeat('a', 1024*15));
Query OK, 1 row affected (0.24 sec)

mysql> show master status;
+------------------+----------+--------------+------------------+---------------
----+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_
Set |
+------------------+----------+--------------+------------------+---------------
----+
| pc-PC-bin.000006 |    15897 |              |                  |
    |
+------------------+----------+--------------+------------------+---------------
----+
1 row in set (0.00 sec)

mysql> exit
Bye

So, thew binary log itself is smaller than max-allowed_packet, it's OK. Now let's try to restore data based on this binary log's content:

C:\Program Files\MySQL\MySQL Server 5.6\bin>mysqlbinlog -uroot -proot "C:\Progra
mData\MySQL\MySQL Server 5.6\data\pc-PC-bin.000006" | mysql --max_allowed_packet
=16384 -uroot -proot -P3314 test
Warning: Using a password on the command line interface can be insecure.
Warning: Using a password on the command line interface can be insecure.
ERROR 1153 (08S01) at line 42: Got a packet bigger than 'max_allowed_packet' byt
es

C:\Program Files\MySQL\MySQL Server 5.6\bin>mysqlbinlog -uroot -proot "C:\Progra
mData\MySQL\MySQL Server 5.6\data\pc-PC-bin.000006" > "h:\tmp\binlog.sql"
Warning: Using a password on the command line interface can be insecure.

C:\Program Files\MySQL\MySQL Server 5.6\bin>dir h:\tmp\*.sql
 Том в устройстве H имеет метку BOOTABLE
 Серийный номер тома: CA15-AD93

 Содержимое папки h:\tmp

07/13/2016  10:06 AM            23,763 binlog.sql
               1 файлов         23,763 байт
               0 папок   2,707,075,072 байт свободно

You can see that the result of mysqlbinlog applied to the binary log is already notably larger than max_allowed_packet. In the resulting file, binlog.sql, we see this huge event:

# at 466
#160713 10:03:52 server id 1  end_log_pos 15866 CRC32 0x9777fab5 	Write_rows: table id 122 flags: STMT_END_F

BINLOG '
2OeFVxMBAAAALgAAANIBAAAAAHoAAAAAAAEABHRlc3QAAnQxAAH8AQQB58W0+w==
2OeFVx4BAAAAKDwAAPo9AAAAAHoAAAAAAAEAAgAB//4APAAAYWFhYWFhYWFhYWFhYWFhYWFhYWFh
YWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFh
...
YWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFh
YWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFhYWFh
YWFhYWFhtfp3lw==
'/*!*/;
# at 15866
#160713 10:03:52 server id 1  end_log_pos 15897 CRC32 0xcb57e2d1 	Xid = 279
COMMIT/*!*/;
# at 15897
...

that, while corresponding to row-based event smaller than max_allowed_packet, is larger than the same max_allowed_packet because of encoding applied.

In my case I surely can increase max_allowed_packet and restore the data if needed, but what if the value was 1G already and the event was big enough to end up >1G in size after applying mysqlbinlog? I'll tell you, you get this (edited output from the real life case):

prompt> mysqlbinlog log-bin.028109 | mysql --max_allowed_packet=1073741824
ERROR 2006 (HY000) at line 4728603: MySQL server has gone away

and no easy way to restore the data.

Suggested fix:
Take encoding overhead of mysqlbinlog into account somehow while deciding on maximum possible row-based even size for the given max_allowed_packet.

In the meantime, please, describe "safe" setting of max_allowed_packet in case of row-based replication in the manual clearly, as well as any workarounds for the case when max_allowed_packet was 1G on the server that produced binary long with huge row based event that one needs to restore now.
[13 Jul 2016 7:29] Valeriy Kravchuk
The content of binlog.sql created by mysqlbinlog for the case presented

Attachment: binlog.sql (application/octet-stream, text), 23.21 KiB.

[13 Jul 2016 9:37] Umesh Shastry
Hello Valerii,

Thank you for the report and test case.
Verified as described with 5.6.31 build.

Thanks,
Umesh