Bug #77818 mysqlbinlog cannot read events with numbers, larger than 4G
Submitted: 23 Jul 2015 20:02 Modified: 24 Jul 2015 9:02
Reporter: Sveta Smirnova (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Row Based Replication ( RBR ) Severity:S3 (Non-critical)
Version:5.6.25. 5.7.7, 5.6.27, 5.7.9 OS:Any
Assigned to: CPU Architecture:Any

[23 Jul 2015 20:02] Sveta Smirnova
Description:
Even after fix for bug #74734 mysqlbinlog cannot read events with numbers, larger than 4G

How to repeat:
Create event, larger than 4G:

set binlog_format='row';
create table t1(f1 longtext);
insert into t1 values(repeat('a', 1073741824/2));
create table t2 like t1;
flush logs;
insert into t2 select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1;

Process binary log with mysqlbinlog using no options, it will succeed:

mysqlbinlog var/mysqld.1/data/master-bin.000002 >tmp.sql

Now find all valied positions:

cat tmp.sql | grep -i at > tmp.sql.cr 
cat tmp.sql.cr 
# at 4
#150723 22:33:08 server id 1  end_log_pos 120 CRC32 0x62430c0b  Start: binlog v 4, server v 5.6.25-73.1-debug-log created 150723 22:33:08
# at 120
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
# at 192
# at 238
# at 536871190
# at 1073742142
# at 1610613094
# at 2147484046
# at 2684354998
# at 3221225950
# at 3758096902
# at 4294967854
# at 4294967927
#150723 22:33:11 server id 1  end_log_pos 679 CRC32 0xd83ecaea  Rotate to master-bin.000003  pos: 4

Try to read binary log, starting from position 4294967854:

mysqlbinlog var/mysqld.1/data/master-bin.000002 --start-position=4294967854 >tmp.sql
mysqlbinlog: [Warning] option 'start-position': unsigned value 4294967854 adjusted to 4294967295
ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 1633771873, event_type: 97
ERROR: Could not read entry at offset 4294967295: Error in log format or read error.
[24 Jul 2015 9:02] Umesh Shastry
Hello Sveta,

Thank you for the report.
Observed this with 5.6.27 and 5.7.9 builds.

Thanks,
Umesh
[24 Jul 2015 9:03] Umesh Shastry
// 5.6.27 

scripts/mysql_install_db --basedir=/export/umesh/server/binaries/mysql-advanced-5.6.27 --datadir=/export/umesh/server/binaries/mysql-advanced-5.6.27/77818
bin/mysqld --no-defaults --innodb_log_file_size=10G --max_allowed_packet=4G --log-bin=master-bin --server-id=1 --basedir=/export/umesh/server/binaries/mysql-advanced-5.6.27 --datadir=/export/umesh/server/binaries/mysql-advanced-5.6.27/77818 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/server/binaries/mysql-advanced-5.6.27/77818/log.err 2>&1 &

--- build used

[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.6.27: cat docs/INFO_SRC
commit: 13d05b5e381b81c49011b1646dc512a332f39465
date: 2015-07-23 10:59:54 +0530
build-date: 2015-07-23 08:13:17 +0200
short: 13d05b5
branch: mysql-5.6

MySQL source 5.6.27

[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.6.27: bin/mysql -uroot -S /tmp/mysql_ushastry.sock test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.6.27-enterprise-commercial-advanced-log MySQL Enterprise Server - Advanced Edition (Commercial)

Copyright (c) 2000, 2015, 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> set binlog_format='row';
Query OK, 0 rows affected (0.00 sec)

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

mysql> insert into t1 values(repeat('a', 1073741824/2));
create table t2 like t1;
flush logs;
insert into t2 select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1;
Query OK, 1 row affected (18.46 sec)

mysql> create table t2 like t1;
Query OK, 0 rows affected (0.46 sec)

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

mysql> insert into t2 select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1;
Query OK, 8 rows affected (2 min 14.75 sec)
Records: 8  Duplicates: 0  Warnings: 0

mysql> show master logs;
+-------------------+------------+
| Log_name          | File_size  |
+-------------------+------------+
| master-bin.000001 |  536871461 |
| master-bin.000002 | 4294967933 |
| master-bin.000003 |        120 |
+-------------------+------------+
3 rows in set (0.01 sec)

mysql> \q
Bye
[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.6.27: bin/mysqlbinlog 77818/master-bin.000002  >tmp.sql
[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.6.27: cat tmp.sql | grep -i at > tmp.sql.cr
[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.6.27:
[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.6.27: cat tmp.sql.cr
# at 4
#150724 10:31:38 server id 1  end_log_pos 120 CRC32 0x730f19e7  Start: binlog v 4, server v 5.6.27-enterprise-commercial-advanced-log created 150724 10:31:38
# at 120
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
# at 192
# at 238
# at 536871190
# at 1073742142
# at 1610613094
# at 2147484046
# at 2684354998
# at 3221225950
# at 3758096902
# at 4294967854
# at 4294967885
#150724 10:31:38 server id 1  end_log_pos 637 CRC32 0x78de0ba4  Rotate to master-bin.000003  pos: 4
[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.6.27:
[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.6.27:  bin/mysqlbinlog 77818/master-bin.000002 --start-position=4294967854 > tmp.sql
Warning: option 'start-position': unsigned value 4294967854 adjusted to 4294967295
ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 1633771873, event_type: 97
ERROR: Could not read entry at offset 4294967295: Error in log format or read error.
[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.6.27:
[24 Jul 2015 9:03] Umesh Shastry
// 5.7.9

bin/mysql_install_db --insecure --basedir=/export/umesh/server/binaries/mysql-advanced-5.7.9 --datadir=/export/umesh/server/binaries/mysql-advanced-5.7.9/77818 -v
bin/mysqld --no-defaults  --innodb_log_file_size=10G --max_allowed_packet=4G --log-bin=master-bin --server-id=1 --basedir=/export/umesh/server/binaries/mysql-advanced-5.7.9 --datadir=/export/umesh/server/binaries/mysql-advanced-5.7.9/77818 --core-file --socket=/tmp/mysql_ushastry.sock  --port=15000 --log-error=/export/umesh/server/binaries/mysql-advanced-5.7.9/77818/log.err 2>&1 &

--build used

[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.7.9: cat docs/INFO_SRC
commit: a43c30d8a6bdbad63ec2d7cbc3af25034270f6c2
date: 2015-07-24 10:16:19 +0530
build-date: 2015-07-24 07:21:33 +0200
short: a43c30d
branch: mysql-5.7

MySQL source 5.7.9

[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.7.9: bin/mysql -uroot -S /tmp/mysql_ushastry.sock
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 3
Server version: 5.7.9-enterprise-commercial-advanced-log MySQL Enterprise Server - Advanced Edition (Commercial)

Copyright (c) 2000, 2015, 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 database test;
Query OK, 1 row affected (0.00 sec)

mysql> use test
Database changed
mysql> set binlog_format='row';
Query OK, 0 rows affected (0.00 sec)

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

mysql> insert into t1 values(repeat('a', 1073741824/2));
create table t2 like t1;
flush logs;
insert into t2 select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1;
Query OK, 1 row affected (19.79 sec)

mysql> create table t2 like t1;
Query OK, 0 rows affected (0.00 sec)

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

mysql> insert into t2 select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1 union all select f1 from t1;
Query OK, 8 rows affected (2 min 15.97 sec)
Records: 8  Duplicates: 0  Warnings: 0

mysql> show master logs;
+-------------------+------------+
| Log_name          | File_size  |
+-------------------+------------+
| master-bin.000001 |  536871849 |
| master-bin.000002 | 4294968032 |
| master-bin.000003 |        154 |
+-------------------+------------+
3 rows in set (0.00 sec)
mysql> \q
Bye
[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.7.9:  bin/mysqlbinlog 77818/master-bin.000002  >tmp.sql
[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.7.9:  cat tmp.sql | grep -i at > tmp.sql.cr
[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.7.9:  cat tmp.sql.cr
# at 4
#150724 10:48:08 server id 1  end_log_pos 123 CRC32 0xea0f9ab9  Start: binlog v 4, server v 5.7.9-enterprise-commercial-advanced-log created 150724 10:48:08
# at 123
# at 154
# at 219
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
# at 291
# at 337
# at 536871289
# at 1073742241
# at 1610613193
# at 2147484145
# at 2684355097
# at 3221226049
# at 3758097001
# at 4294967953
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
# at 4294967984
#150724 10:48:08 server id 1  end_log_pos 736 CRC32 0x49e5f5d8  Rotate to master-bin.000003  pos: 4
[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.7.9:  bin/mysqlbinlog 77818/master-bin.000002 --start-position=4294967953 > tmp.sql
mysqlbinlog: [Warning] option 'start-position': unsigned value 4294967953 adjusted to 4294967295
ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 1633771873, event_type: 97
ERROR: Could not read entry at offset 4294967295: Error in log format or read error.
[umshastr@hod03]/export/umesh/server/binaries/mysql-advanced-5.7.9:
[16 Aug 2018 8:12] liusl liu
Observed this with 5.7.17 and 5.7.22 builds