Bug #19402 SQL close to the size of the max_allowed_packet fails on the slave
Submitted: 27 Apr 2006 15:51 Modified: 28 Nov 2006 20:22
Reporter: David Newcomb (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S2 (Serious)
Version:4.1.all, 5.0.21 OS:Windows (Win2000)
Assigned to: Andrei Elkin CPU Architecture:Any

[27 Apr 2006 15:51] David Newcomb
Description:
max_allowed_packet is unset in both master and slave. It defaults to 1MB on master and slave. Applying an SQL statement of around 1MB-15bytes runs happliy on the master but then kills the slave with:

060424 13:42:49 [Note] Slave I/O thread: connected to master 'qrepl@black:3306',  replication started in log 'black-bin.000002' at position 117043635
060424 13:43:31 [ERROR] Error reading packet from server: log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master (server_errno=1236)
060424 13:43:31 [ERROR] Got fatal error 1236: 'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master' from master when reading data from binary log
060424 13:43:31 [ERROR] Slave I/O thread exiting, read up to log 'black-bin.000002', position 117045238
060424 13:44:25 [Note] Slave I/O thread: connected to master 'qrepl@black:3306',  replication started in log 'black-bin.000002' at position 117045238
060424 13:44:26 [ERROR] Error reading packet from server: log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master (server_errno=1236)
060424 13:44:26 [ERROR] Got fatal error 1236: 'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master' from master when reading data from binary log
060424 13:44:26 [ERROR] Slave I/O thread exiting, read up to log 'black-bin.000002', position 117045238
060424 13:45:10 [Note] Slave I/O thread: connected to master 'qrepl@black:3306',  replication started in log 'black-bin.000002' at position 117045238
060424 13:45:10 [ERROR] Error reading packet from server: log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master (server_errno=1236)
060424 13:45:10 [ERROR] Got fatal error 1236: 'log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master' from master when reading data from binary log
060424 13:45:10 [ERROR] Slave I/O thread exiting, read up to log 'black-bin.000002', position 117045238
060424 21:45:14 [Warning] Aborted connection 32 to db: 'quentin_v3' user: 'root' host: `localhost' (Got timeout reading communication packets)

I have decoded the binlog and can confirm that the SQL at that log position is 15 bytes less than 1MB.

How to repeat:
See attached java file

Suggested fix:
Find out what is using the extra space and get rid of it!
[27 Apr 2006 15:55] David Newcomb
rushTimecode.java

Attachment: rushTimecode.zip (application/zip, text), 16.92 KiB.

[27 Apr 2006 16:02] David Newcomb
Compile the file with: javac rushTimecode.java
and run with: java <dbhost> nofix

The nofix was my first attempt to fix it by setting "allow batch=no" in the connect string but it did not work :(

I am using Connector/J 3.1.11 but I'm pretty sure that it does not make a difference.

Run it against 4.1.10, 4.1.12, 4.1.18 and they all failed.

The create table SQL is:

CREATE TABLE `rushtimecodes` (
  `rushID` char(32) character set utf8 collate utf8_bin NOT NULL default '',
  `start` int(11) NOT NULL default '0',
  `finish` int(11) NOT NULL default '0',
  `portTimecode` int(11) NOT NULL default '0',
  `userBits` int(11) NOT NULL default '0',
  `refTimecode` int(11) NOT NULL default '0',
  KEY `rushID` (`rushID`,`start`),
  KEY `rushID_2` (`rushID`,`finish`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8;

Happy hunting!
[9 May 2006 17:11] MySQL Verification Team
Thank you for the bug report. Could you please provide the master and
slave my.ini files and the exactly release version of both servers.

Thanks in advance.
[10 May 2006 9:24] David Newcomb
my.ini from master & slave

Attachment: 19402_my.ini (application/octet-stream, text), 7.65 KiB.

[10 May 2006 9:25] David Newcomb
My.ini attached to bug report.
The exact versions were: 4.1.10, 4.1.12 and 4.1.18. During the test the same version of database was master and slave.
[15 May 2006 17:32] MySQL Verification Team
Repeated the problem using customer's testcase.

Startup master and slave with max_allowed_packet=1048576.
The master accepts the INSERT without problem.
However, it cannot send it to the slave, because the log event is larger.

T@10   : | | >read_log_event
T@10   : | | | error: data_len: 1048593
T@10   : | | <read_log_event
[16 May 2006 10:28] MySQL Verification Team
I think this is somewhat a security issue. No matter what max_allowed_packet is set on master, I see no workaround to save replication from failing if a client sends a slightly shorter length length query than max_allowed_packet.
[17 May 2006 23:55] Lars Thalmann
See also BUG#15937
[23 May 2006 12:56] MySQL Verification Team
testcase which broke my 5.0.21 replication:

#start master like: ./bin/mysqld_safe --skip-grant-tables --log-bin --server-id=2 --max_allowed_packet=1024 &
#start slave like:  ./bin/mysqld_safe --skip-grant-tables  --relay-log=aserver-relay-bin --server-id=9 --max_allowed_packet=1048576
#on master:
SHOW GLOBAL VARIABLES LIKE 'max_allowed_packet';
SHOW SESSION VARIABLES LIKE 'max_allowed_packet';
SET GLOBAL max_allowed_packet=1024;
exit
#relaunch mysql client and connect to master
#now, stop the slave, and start the slave to get new max_allowed_packet settings take affect
SHOW GLOBAL VARIABLES LIKE 'max_allowed_packet';
SHOW SESSION VARIABLES LIKE 'max_allowed_packet';
DROP DATABASE IF EXISTS `bug19402`;
CREATE DATABASE IF NOT EXISTS `bug19402`;
USE `bug19402`;
DROP TABLE IF EXISTS `figjej`;
CREATE TABLE `figjej`(`id` BIGINT UNSIGNED NOT NULL AUTO_INCREMENT PRIMARY KEY, `str` LONGTEXT)ENGINE=MyISAM;
INSERT INTO `figjej`(`str`) VALUES ('aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa');
[7 Jun 2006 12:12] David Newcomb
Please can we have an update on this. It is flagged as serious but has not been updated for 3 weeks.
[7 Jun 2006 22:03] Lars Thalmann
The solution for this has been discussed, but we have not had
time to complete the fix yet.  The idea is that the header of the 
event needs to be calculated too, and that is not done in all cases.
[8 Jun 2006 14:35] Andrei Elkin
Dressed to kill it.
[20 Jun 2006 12:27] Lars Thalmann
The manual says:

  A.2.9. Packet too large

  A communication packet is a single SQL statement sent to the MySQL
  server or a single row that is sent to the client.

  The largest possible packet that can be transmitted to or from a
  MySQL 5.0 server or client is 1GB.

This is only half of the story.  A communication packet can also be
a binlog event sent from the master to the slave.

The main problem with this bug is that the clients max_allow_packet
may allow for a query of some size very close to max_allowed_packet.
The query is later put into the binlog with extra common header and
internal query header.

When the master dump thread is later reading the binlog event, it
notices that the binlog event is greater than max_allowed_header, and
it complains about this.

There are three different alternative solutions for this bug:

1. Make each client "aware" of the size of binlog headers, thus
   limiting query size to max_allowed_packet - common header size
   - query header size.

2. Let the master-slave connection be different and allow packets of
   size max_allowed_packet + common header size + internal event header
   size.

3. Differentiate between client-master and master-slave and have two
   different variables for the packet sizes, where the master-slave
   packet size must be common header size + internal header size bigger
   than the client-master packet size.

Alternative 3 seems confusing for the user.  Alternative 2 has the
drawback that the communication buffers will actually be slightly
bigger than max_allowed_packet.  Alternative 1 forces us to add server
size information to the mysql client program.

It seems that alternative 2 is the best solution.

Steps to solve bug:
1. CHANGE
   if (data_len < LOG_EVENT_MINIMAL_HEADER_LEN ||
       data_len > current_thd->variables.max_allowed_packet)
   TO
   if (data_len < LOG_EVENT_MINIMAL_HEADER_LEN ||
       data_len > current_thd->variables.max_allowed_packet +
                 LOG_EVENT_MINIMAL_HEADER_LEN + 
                 max(QUERY_HEADER_MINIMAL_LEN,
                     QUERY_HEADER_LEN,
                     LOAD_HEADER_LEN,
                     START_V3_HEADER_LEN,
                     ROTATE_HEADER_LEN,
                     CREATE_FILE_HEADER_LEN,
                     APPEND_BLOCK_HEADER_LEN,
                     EXEC_LOAD_HEADER_LEN,
                     DELETE_FILE_HEADER_LEN,
                     FORMAT_DESCRIPTION_HEADER_LEN,
                     EXECUTE_LOAD_QUERY_EXTRA_HEADER_LEN,
                     EXECUTE_LOAD_QUERY_HEADER_LEN)
   in log_event.cc:log_event::read_log_event().

2. Make slave able of connecting with packet size max_allowed_packet +
   common header size + max internal header size.

This solution assumes that no type of event can be created on master
with size greater than max_allowed_packet - common header size -
internal header size.  This seems to hold, but should be verified.
[21 Jun 2006 8:47] David Newcomb
In my Java application I have an SQL bucket which I generate sql into then apply to the database. The default size is 1MB which is the same as default max_allowed_packet. By setting the max_allowd packet to 1.5MB there is plenty of (wasted) space in the bucket for the header. It means however that it becomes difficult to alter our internal buffer without changing the SQL configuration. Nobody around here know what LOG_EVENT_MINIMAL_HEADER_LEN, ... are set to so it is a bit accademic. It would certainly make things easier if that calculation was done on your side and max_allowd_packet actually meant max allowed packet!
[21 Jun 2006 9:50] Lars Thalmann
Hi David, I agree we should fix it so that the calculations are done on the 
inside.  Andrei is looking into this.  Best wishes, Lars
[7 Aug 2006 9:47] David Newcomb
Please can I have an update.
[28 Aug 2006 7:53] Andrei Elkin
I have to alternate the order of bugs in my queue to favor LOAD DATA from master, the case emerged rather recently. 
For that ETA is moving further.
[4 Sep 2006 12:19] Andrei Elkin
Changing ETA again since dealing with showstopping review WL3259 assigned to me the last scrum.
[8 Sep 2006 19:35] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/11637

ChangeSet@1.2481, 2006-09-08 22:35:29+03:00, aelkin@dsl-hkigw8-fe00f800-98.dhcp.inet.fi +3 -0
  BUG#19402 SQL close to the size of the max_allowed_packet fails on the slave
  
  A communication packet can also be a binlog event sent from the master to the slave.
  To be sent by master dump and accepted by slave io thread both have to have
  the value of max_allowed_packet bigger than one that client connection had.
  
  In the patch there is the MAX possible replicatio header size estimation for events
  in binlog that embedded user query. Only these events of query_log_event type, i.e
  just plain queries, require attention.
[8 Sep 2006 19:41] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/11638

ChangeSet@1.2481, 2006-09-08 22:41:22+03:00, aelkin@dsl-hkigw8-fe00f800-98.dhcp.inet.fi +6 -0
  BUG#19402 SQL close to the size of the max_allowed_packet fails on the slave
  
  A communication packet can also be a binlog event sent from the master to the slave.
  To be sent by master dump and accepted by slave io thread both have to have
  the value of max_allowed_packet bigger than one that client connection had.
  
  In the patch there is the MAX possible replicatio header size estimation for events
  in binlog that embedded user query. Only these events of query_log_event type, i.e
  just plain queries, require attention.
[11 Sep 2006 20:21] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/11719

ChangeSet@1.2481, 2006-09-11 23:21:44+03:00, aelkin@dsl-hkigw8-fe00f800-98.dhcp.inet.fi +7 -0
  BUG#19402 SQL close to the size of the max_allowed_packet fails on the slave
  
  A communication packet can also be a binlog event sent from the master to the slave.
  To be sent by master dump and accepted by slave io thread both have to have
  the value of max_allowed_packet bigger than one that client connection had.
  
  In the patch there is the MAX possible replicatio header size estimation for events
  in binlog that embedded user query. Only these events of query_log_event type, i.e
  just plain queries, require attention.
[11 Sep 2006 21:19] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/11723

ChangeSet@1.2481, 2006-09-12 00:19:05+03:00, aelkin@dsl-hkigw8-fe00f800-98.dhcp.inet.fi +7 -0
  BUG#19402 SQL close to the size of the max_allowed_packet fails on the slave
  
  A communication packet can also be a binlog event sent from the master to the slave.
  To be sent by master dump and accepted by slave io thread both have to have
  the value of max_allowed_packet bigger than one that client connection had.
  
  In the patch there is the MAX possible replicatio header size estimation for events
  in binlog that embedded user query. Only these events of query_log_event type, i.e
  just plain queries, require attention.
[16 Oct 2006 16:40] David Newcomb
I need to update my users (for different reasons) and I would like to put this fix in. Please can I have an update on which release it will be in.
[7 Nov 2006 18:24] Chuck Bell
Looks good to go.
[8 Nov 2006 14:19] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/15021

ChangeSet@1.2546, 2006-11-08 17:17:28+02:00, aelkin@dsl-hkibras-fe30f900-107.dhcp.inet.fi +2 -0
  bug#19402 SQL close to the size of the max_allowed_packet fails on slave
  fixing a flow of the test
[12 Nov 2006 17:03] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/15196

ChangeSet@1.2549, 2006-11-12 20:01:58+02:00, aelkin@dsl-hkibras-fe30f900-107.dhcp.inet.fi +3 -0
  bug#19402 SQL close to the size of the max_allowed_packet fails on the slave
  comments are fixed as was suggested in reviews.
[14 Nov 2006 9:50] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/15291

ChangeSet@1.2304, 2006-11-14 12:48:17+02:00, aelkin@dsl-hkibras-fe30f900-107.dhcp.inet.fi +2 -0
  bug#19402 SQL close to the size of the max_allowed_packet fails on the slave
  
  ver 5.0 and 5.1 refinement.
  adding to the MAX_SIZE_LOG_EVENT_STATUS estimation status vars and 
  EXECUTE_LOAD_QUERY_EXTRA_HEADER_LEN
[15 Nov 2006 9:55] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/15336

ChangeSet@1.2551, 2006-11-15 12:53:07+02:00, aelkin@dsl-hkibras-fe30f900-107.dhcp.inet.fi +2 -0
  bug#19402 SQL close to the size of the max_allowed_packet fails on the slave
  
  mending windows test.
[20 Nov 2006 14:57] Lars Thalmann
Pushed into 4.1.23, 5.0.32, 5.1.14.
[28 Nov 2006 20:22] Paul DuBois
Noted in 4.1.23, 5.0.32, 5.1.14 changelogs.

SQL statements close to the size of max_allowed_packet could produce 
binary log events larger than max_allowed_packet that could not be 
read by slave servers.