MySQL Bugs: #60926: binary log events larger than max_allowed

Bug #60926	binary log events larger than max_allowed_packet
Submitted:	19 Apr 2011 17:37	Modified:	12 Jun 2012 13:35
Reporter:	Devon Weller	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S1 (Critical)
Version:	5.5.8, 5.6.3, 5.1	OS:	Linux
Assigned to:		CPU Architecture:	Any
Tags:	binlog, max_allowed_packet

Description:
SQL statements close to the size of max_allowed_packet produce binary log events larger than max_allowed_packet.

As a result, this breaks replication as slaves report the following 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'

How to repeat:

1) Make sure the max_allowed_packet variable is set to 16777216 in MySQL.

2) Make sure binary logging is enabled

3) Send an UPDATE query that is slightly less than 16777216 bytes long. This update query has a large amount of text including many tab characters (\x0a).

4) MySQL writes a binlog event that is 16784830 bytes long.

Suggested fix:
Ensure that a binlog events is never written if it is longer than max_allowed_packet.

Thank you for the report.

Verified as described. Can be considered feature request though.

Test case for MTR:

--source include/have_log_bin.inc

set binlog_format='row';

drop table if exists t1;
create table t1(f1 longtext);
insert into t1 values(repeat('a', 1024*1022));

flush logs;

drop table t1;

set sql_log_bin=0;

show master status;
--let $MYSQLD_DATADIR=`select @@datadir`
--exec $MYSQL_BINLOG $MYSQLD_DATADIR/master-bin.000001 | $MYSQL test

select count(*) from t1;

I would respectfully argue that if the MySQL server writes an event to the binlog that will break replication that this is a bug and not a feature request.

I think this is a serious bug, not a feature request. While debugging a local occurrence of the problem, I don't think there is code on the master to prevent creation of a binlog event that exceeds max_allowed_packet. I suspect this is a consequence of MyISAM -- as it is too late to fail when a binlog event has been created because MyISAM doesn't do undo. 

When I use cscope to show all references to max_allowed_packet, I find:
* checks in slave code (log_event.cc, sql_repl.cc, slave.cc)
* a few checks that might be used by the master in limited cases (item_strfunc.cc, item_geofunc.cc)
* checks in client code (client.cc)

So please tell me where the code is in the master that enforces this.

Note that my clients are not friendly, but an unfriendly client could ignore max_allowed_packet and create even more problems.

  File                Function                   Line
0 mysql.h             <global>                    188 unsigned long max_allowed_packet;
1 mysql.h             <global>                    374 #define max_allowed_packet (*mysql_get_parameters()->p_max_allowed_packet)
2 libmysql.c          <global>                     66 #undef max_allowed_packet
3 libmysql.c          <global>                     69 ulong max_allowed_packet= 1024L*1024L*1024L;
4 libmysql.c          <global>                    229 {&max_allowed_packet, &net_buffer_length, 0};
5 priv.cc             <global>                     34 unsigned long max_allowed_packet= 16384;
6 priv.h              <global>                     69 extern unsigned long max_allowed_packet;
7 client.c            <global>                     42 #undef max_allowed_packet
8 mysqld.cc           <global>                   7282 &global_system_variables.max_allowed_packet,
9 mysqld.cc           <global>                   7283 &max_system_variables.max_allowed_packet, 0, GET_ULONG,
a set_var.cc          <global>                    384 &SV::max_allowed_packet);
b sql_class.h         <global>                    402 ulong max_allowed_packet;
c sql_client.cc       <global>                     38 global_system_variables.max_allowed_packet);
d libmysql.c          my_net_local_init          1576 net->max_packet_size= max(net_buffer_length, max_allowed_packet);
e mysql_connection.cc my_net_local_init            68 net->max_packet_size= max_allowed_packet;
f client.c            mysql_read_default_options 1195 options->max_allowed_packet= atoi(opt_arg);
g client.c            CLI_MYSQL_REAL_CONNECT     2148 if (mysql->options.max_allowed_packet)
h client.c            CLI_MYSQL_REAL_CONNECT     2149 net->max_packet_size= mysql->options.max_allowed_packet;
i item_geofunc.cc     val_str                     489 if (str->length() > current_thd->variables.max_allowed_packet)
j item_geofunc.cc     val_str                     494 func_name(), current_thd->variables.max_allowed_packet);
k item_strfunc.cc     val_str                     313 current_thd->variables.max_allowed_packet)
l item_strfunc.cc     val_str                     318 current_thd->variables.max_allowed_packet);
m item_strfunc.cc     val_str                     663 current_thd->variables.max_allowed_packet)
n item_strfunc.cc     val_str                     668 current_thd->variables.max_allowed_packet);
o item_strfunc.cc     val_str                     920 current_thd->variables.max_allowed_packet)
p item_strfunc.cc     val_str                     926 current_thd->variables.max_allowed_packet);
q item_strfunc.cc     val_str                     949 current_thd->variables.max_allowed_packet)
r item_strfunc.cc     val_str                     954 current_thd->variables.max_allowed_packet);
s item_strfunc.cc     val_str                    1027 (ulonglong) current_thd->variables.max_allowed_packet)
t item_strfunc.cc     val_str                    1032 func_name(), current_thd->variables.max_allowed_packet);
u item_strfunc.cc     val_str                    2435 if (length > current_thd->variables.max_allowed_packet / (uint) count)
v item_strfunc.cc     val_str                    2440 func_name(), current_thd->variables.max_allowed_packet);
w item_strfunc.cc     val_str                    2525 if ((ulonglong) byte_count > current_thd->variables.max_allowed_packet)
x item_strfunc.cc     val_str                    2530 func_name(), current_thd->variables.max_allowed_packet);
y item_strfunc.cc     val_str                    2630 if ((ulonglong) byte_count > current_thd->variables.max_allowed_packet)
z item_strfunc.cc     val_str                    2635 func_name(), current_thd->variables.max_allowed_packet);
A item_strfunc.cc     val_str                    2973 if (stat_info.st_size > (long ) current_thd->variables.max_allowed_packet)
B item_strfunc.cc     val_str                    2978 func_name(), current_thd->variables.max_allowed_packet);
C item_strfunc.cc     val_str                    3362 if (new_size > current_thd->variables.max_allowed_packet)
D item_strfunc.cc     val_str                    3367 current_thd->variables.max_allowed_packet);
E log_event.cc        read_log_event              997 data_len > current_thd->variables.max_allowed_packet)
F log_event.cc        read_log_event             1098 #ifndef max_allowed_packet
G log_event.cc        read_log_event             1100 uint max_allowed_packet= thd ? thd->variables.max_allowed_packet : ~(ulong)0;
H log_event.cc        read_log_event             1108 if (data_len > max_allowed_packet)
I mysqld.cc           get_options                9485 max_allowed_packet= global_system_variables.max_allowed_packet;
J slave.cc            init_slave_thread          1903 thd->variables.max_allowed_packet= global_system_variables.max_allowed_packet
K slave.cc            handle_slave_io            2841 thd->variables.max_allowed_packet);
L sql_repl.cc         mysql_binlog_send           414 int old_max_allowed_packet= thd->variables.max_allowed_packet;
M sql_repl.cc         mysql_binlog_send           530 thd->variables.max_allowed_packet+= MAX_LOG_EVENT_HEADER;
N sql_repl.cc         mysql_binlog_send           882 thd->variables.max_allowed_packet= old_max_allowed_packet;
O sql_repl.cc         mysql_binlog_send           904 thd->variables.max_allowed_packet= old_max_allowed_packet;
P sql_repl.cc         mysql_show_binlog_events   1569 int old_max_allowed_packet= thd->variables.max_allowed_packet;
Q sql_repl.cc         mysql_show_binlog_events   1627 thd->variables.max_allowed_packet += MAX_LOG_EVENT_HEADER;
R sql_repl.cc         mysql_show_binlog_events   1708 thd->variables.max_allowed_packet= old_max_allowed_packet;
S sql_repl.cc         log_loaded_block           1881 uint max_event_size= current_thd->variables.max_allowed_packet;
T sql_show.cc         mysqld_list_processes	 1801 ulong max_query_length= (verbose ? thd->variables.max_allowed_packet :

I fully agree with Mark that this should be considered a bug. 

If some 'safe margin' is required when executing large statements to a master in order not to break replication. such 'safe margin' should be handled by the server by the way it uses 'max_allowed_packet.

I alos have to ask for a reply (as soon as possible) to *how big* such safe margin should be (a constant, a formula .. whatever).  This explains a nasty issue we had with one of our applications.

And to send a 1MB binlog event from master to slave, the value for max_allowed_packet on both the master and the slave must be >= 1MB. So there isn't an easy workaround for this. The easy workaround would have been to use a larger value on the slave.

does it mean fix for bug #19402 was not good enough?

The fix for bug#19402 already causes the master and slave to ignore max_allowed_packet by increasing their session setting based on the maximum known possible replication overhead.

So how does the overhead become greater than the maximum we think is possible?

Is it some custom version of replication that adds more overhead without also adjusting the calculation that allows for it?

If not, what statements are being used that are causing the calculation to fail?

Documented fix as follows in the 5.1.64, 5.5.26, and 5.6.6 changelogs:

        An event whose length exceeded the size of the master dump
        thread's max_allowed_packet caused replication to fail. This
        could occur when updating many large rows and using row-based
        replication.

        As part of the fix for this issue, a new server option
        --slave-max-allowed-packet is added, which permits
        max_allowed_packet to be exceeded by the slave SQL and I/O
        threads. Now the size of a packet transmitted from the master to
        the slave is checked only against this value (available as the
        value of the slave_max_allowed_packet server system variable),
        and not against the value of max_allowed_packet.

Closed.

@jon ..

It should be added here as well http://dev.mysql.com/doc/refman/5.5/en/server-options.html if it is not already.  Documenting in "Change History" is not enough.

Since you don't reply I had to add a new bug:
http://bugs.mysql.com/bug.php?id=65626

Bug #44690 was marked as a duplicate