Selecting wrong pos with SHOW BINLOG EVENTS causes a potentially misleading message in the server error log

Bug #1409652 reported by Nilnandan Joshi
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
MySQL Server
Unknown
Unknown
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
Medium
Sergei Glushchenko
5.1
Won't Fix
Undecided
Unassigned
5.5
Fix Released
Medium
Sergei Glushchenko
5.6
Fix Released
Medium
Sergei Glushchenko

Bug Description

While selecting wrong pos with SHOW BINLOG EVENTS, it fails and does give error to client and log to error log

mysql> show global variables like 'binlog_format%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| binlog_format | ROW |
+---------------+-------+
1 row in set (0.00 sec)

mysql> show global variables like 'max_allowed_packet';
+--------------------+------------+
| Variable_name | Value |
+--------------------+------------+
| max_allowed_packet | 1073741824 |
+--------------------+------------+
1 row in set (0.00 sec)

mysql> create table nil (id int, name varchar(10), city varchar(10), phone int);
Query OK, 0 rows affected (0.01 sec)

mysql> insert into nil values (1, 'nilnandan','ahmedabad',2348762347);
Query OK, 1 row affected, 1 warning (0.01 sec)
mysql> select * from nil;
+------+-----------+-----------+------------+
| id | name | city | phone |
+------+-----------+-----------+------------+
| 1 | nilnandan | ahmedabad | 2147483647 |
+------+-----------+-----------+------------+
1 row in set (0.00 sec)

mysql> insert into nil select * from nil;
Query OK, 1 row affected (0.01 sec)
Records: 1 Duplicates: 0 Warnings: 0

mysql> insert into nil select * from nil;
Query OK, 2 rows affected (0.00 sec)
Records: 2 Duplicates: 0 Warnings: 0
..
.

mysql> insert into nil select * from nil;
Query OK, 8388608 rows affected (37.83 sec)
Records: 8388608 Duplicates: 0 Warnings: 0

mysql> insert into nil select * from nil limit 2000000;
Query OK, 2000000 rows affected, 1 warning (8.36 sec)
Records: 2000000 Duplicates: 0 Warnings: 1

mysql> insert into nil select * from nil limit 2000000;
Query OK, 2000000 rows affected, 1 warning (7.66 sec)
Records: 2000000 Duplicates: 0 Warnings: 1

mysql> insert into nil select * from nil limit 3000000;
Query OK, 3000000 rows affected, 1 warning (11.86 sec)
Records: 3000000 Duplicates: 0 Warnings: 1

mysql> quit
Bye
nilnandan@desktop:~$

nilnandan@desktop:~/sandboxes/rsandbox_Percona-Server-5_6_21/master/data/test$ ll -h
total 1.4G
drwx------ 2 nilnandan nilnandan 4.0K Jan 12 13:58 ./
drwx------ 5 nilnandan nilnandan 4.0K Jan 12 13:54 ../
-rw-rw---- 1 nilnandan nilnandan 8.5K Jan 12 13:58 nil.frm
-rw-rw---- 1 nilnandan nilnandan 1.4G Jan 12 14:28 nil.ibd
nilnandan@desktop:~/sandboxes/rsandbox_Percona-Server-5_6_21/master/data/test$

-- Create outfile to load the data

mysql> SELECT * INTO OUTFILE '/tmp/nil_table.txt'
    -> FIELDS TERMINATED BY ',' OPTIONALLY ENCLOSED BY '"'
    -> LINES TERMINATED BY '\n'
    -> FROM nil;
Query OK, 23777216 rows affected (20.00 sec)

nilnandan@desktop:/tmp$ ll -h nil_table.txt
-rw-rw-rw- 1 nilnandan nilnandan 840M Jan 12 14:36 nil_table.txt
nilnandan@desktop:/tmp$

-- Create new table and load the data

mysql> create table nil_new (id int, name varchar(10), city varchar(10), phone int);
Query OK, 0 rows affected (0.01 sec)

mysql> LOAD DATA INFILE '/tmp/nil_table.txt'
    -> INTO TABLE nil_new
    -> FIELDS TERMINATED BY ',' OPTIONALLY ENCLOSED BY '"'
    -> LINES TERMINATED BY '\n';
Query OK, 23777216 rows affected (1 min 34.75 sec)
Records: 23777216 Deleted: 0 Skipped: 0 Warnings: 0

mysql> show master status \G
*************************** 1. row ***************************
             File: mysql-bin.000004
         Position: 692490956
     Binlog_Do_DB:
 Binlog_Ignore_DB:
Executed_Gtid_Set: 2c827228-90cf-11e4-b877-00224db1c503:1-34
1 row in set (0.00 sec)

mysql> SHOW BINLOG EVENTS IN 'mysql-bin.000004' FROM 692490800;
ERROR 1220 (HY000): Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error
mysql>

nilnandan@desktop:~/sandboxes/rsandbox_Percona-Server-5_6_21/master/data$ tail -f msandbox.err
2015-01-12 14:38:17 11087 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.21-rel70.1 started; log sequence number 2084708105
2015-01-12 14:38:17 11087 [Note] RSA private key file not found: /home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_21/master/data//private_key.pem. Some authentication plugins will not work.
2015-01-12 14:38:17 11087 [Note] RSA public key file not found: /home/nilnandan/sandboxes/rsandbox_Percona-Server-5_6_21/master/data//public_key.pem. Some authentication plugins will not work.
2015-01-12 14:38:17 11087 [Note] Server hostname (bind-address): '127.0.0.1'; port: 20886
2015-01-12 14:38:17 11087 [Note] - '127.0.0.1' resolves to '127.0.0.1';
2015-01-12 14:38:17 11087 [Note] Server socket created on IP: '127.0.0.1'.
2015-01-12 14:38:17 11087 [Note] Event Scheduler: Loaded 0 events
2015-01-12 14:38:17 11087 [Note] /home/nilnandan/Downloads/Softwares/5.6.21/bin/mysqld: ready for connections.
Version: '5.6.21-70.1-log' socket: '/tmp/mysql_sandbox20886.sock' port: 20886 Percona Server (GPL), Release 70.1, Revision 698
2015-01-12 14:45:49 11087 [ERROR] Error in Log_event::read_log_event(): 'Event too big', data_len: 1768818944, event_type: 127

summary: - SHOW BINLOG EVENTS fails if binlog has event size of close or more than
+ SHOW BINLOG EVENTS fails if binlog has event size of more than
max_allowed_packet
tags: added: i49776
tags: added: upstream
Revision history for this message
Valerii Kravchuk (valerii-kravchuk) wrote : Re: SHOW BINLOG EVENTS fails if binlog has event size of more than max_allowed_packet

Yet another simple way to reproduce these scary messages (with nonsense even type) in the error log is like this:

[openxs@centos bzr2]$ mysql -uroot -P3314 test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 4
Server version: 5.6.22-71.0-log Percona Server (GPL), Release 71.0, Revision 726

Copyright (c) 2009-2014 Percona LLC and/or its affiliates
Copyright (c) 2000, 2014, 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> show master status;
+-------------------+----------+--------------+------------------+-------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+-------------------+----------+--------------+------------------+-------------------+
| centos-bin.000022 | 4271 | | | |
+-------------------+----------+--------------+------------------+-------------------+
1 row in set (0.00 sec)

mysql> show binlog events in 'centos-bin.000022' from 117;
ERROR 1220 (HY000): Error when executing command SHOW BINLOG EVENTS: Wrong offset or I/O error
mysql> exit
Bye
[openxs@centos bzr2]$ su
Password:
[root@centos bzr2]# tail /var/log/mysqld.log
...

2015-01-13 12:47:52 2721 [ERROR] Error in Log_event::read_log_event(): 'Event too big', data_len: 1744830464, event_type: -36

So, whenever one uses some "wrong" offset this statement writes to the error log, while the error is just in one statement and replication continues to work.

tags: added: i49874
Revision history for this message
Peiran Song (peiran-song) wrote :
Download full text (5.0 KiB)

Nil:

I wonder if the test you did just verified reading a "wrong" offset would result in such an error as Valerii also noted.

mysql> show master status \G
*************************** 1. row ***************************
             File: mysql-bin.000004
         Position: 692490956

mysql> SHOW BINLOG EVENTS IN 'mysql-bin.000004' FROM 692490800;

This 692490800 looks like an invalid offset.

I can't reproduce the bug on PS 5.6 nor PS 5.5. However, with both versions, invalid offset did result in this error.

I used a file over 5K to test:

node1> load data infile '/home/peiran/sandboxes/rsandbox_Percona-Server-5_5_28/master/5k.txt' into table bin_test fields terminated by '|' optionally
Query OK, 1 row affected, 1 warning (0.01 sec)
Records: 1 Deleted: 0 Skipped: 0 Warnings: 1

node1> show binlog events in "mysql-bin.000007";
+------------------+------+-------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+------------------+------+-------------+-----------+-------------+---------------------------------------------------------------------------------------------------------------------+
| mysql-bin.000007 | 4 | Format_desc | 101 | 120 | Server ver: 5.6.19-67.0-log, Binlog ver: 4 |
| mysql-bin.000007 | 120 | Query | 101 | 297 | use `test`; CREATE TABLE `bin_test` (
  `a` int(11) DEFAULT NULL,
  `b` text
) ENGINE=InnoDB DEFAULT CHARSET=latin1 |
| mysql-bin.000007 | 297 | Query | 101 | 369 | BEGIN |
| mysql-bin.000007 | 369 | Table_map | 101 | 422 | table_id: 72 (test.bin_test) |
| mysql-bin.000007 | 422 | Write_rows | 101 | 466 | table_id: 72 flags: STMT_END_F |
| mysql-bin.000007 | 466 | Xid | 101 | 497 | COMMIT /* xid=19 */ |
| mysql-bin.000007 | 497 | Query | 101 | 569 | BEGIN |
| mysql-bin.000007 | 569 | Table_map | 101 | 622 | table_id: 72 (test.bin_test) |
| mysql-bin.000007 | 622 | Write_rows | 101 | 9074 | table_id: 72 flags: STMT_END_F |
| mysql-bin.000007 | 9074 | Xid | 101 | 9105 | COMMIT /* xid=21 */ ...

Read more...

Revision history for this message
Peiran Song (peiran-song) wrote :

Additional information on the message being printed in error log:

When reading from wrong position, the message in error log also takes the following forms when binlog event size didn't exceed max_allowed_packet:

150116 17:14:03 [ERROR] Error in Log_event::read_log_event(): 'Event too small', data_len: 2, event_type: 0
150116 17:14:45 [ERROR] Error in Log_event::read_log_event(): 'read error', data_len: 134217729, event_type: 68

Here is a quick example (binlog event size didn't exceed max_allowed_packet):

master[5.5.28-rel29.1-log] > show binlog events in "mysql-bin.000009";
+------------------+------+-------------+-----------+-------------+-----------------------------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+------------------+------+-------------+-----------+-------------+-----------------------------------------------------------+
| mysql-bin.000009 | 4 | Format_desc | 1 | 107 | Server ver: 5.5.28-rel29.1-log, Binlog ver: 4 |
| mysql-bin.000009 | 107 | Query | 1 | 215 | use `test`; alter table t_a change a a int auto_increment |
| mysql-bin.000009 | 215 | Query | 1 | 283 | BEGIN |
| mysql-bin.000009 | 283 | Intvar | 1 | 311 | INSERT_ID=15 |
| mysql-bin.000009 | 311 | Query | 1 | 411 | use `test`; insert into t_a (b) select b from t_a |
| mysql-bin.000009 | 411 | Xid | 1 | 438 | COMMIT /* xid=22 */
...

> show binlog events in "mysql-bin.000009" from 117;

Error log: 150116 17:14:03 [ERROR] Error in Log_event::read_log_event(): 'Event too small', data_len: 2, event_type: 0

> show binlog events in "mysql-bin.000009" from 220;
Error log: 150116 17:14:45 [ERROR] Error in Log_event::read_log_event(): 'read error', data_len: 134217729, event_type: 68

Note that, in the second case, though the data_len reported is bigger than max_allowed_packet, it reported it as 'read error'.

 > show variables like 'max_allowed%';
+--------------------+---------+
| Variable_name | Value |
+--------------------+---------+
| max_allowed_packet | 1048576 |
+--------------------+---------+

summary: - SHOW BINLOG EVENTS fails if binlog has event size of more than
- max_allowed_packet
+ While selecting wrong pos with SHOW BINLOG EVENTS, it fails and does
+ give error to client and log to error log:
summary: While selecting wrong pos with SHOW BINLOG EVENTS, it fails and does
- give error to client and log to error log:
+ give error to client and log to error log
Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote : Re: While selecting wrong pos with SHOW BINLOG EVENTS, it fails and does give error to client and log to error log

Changing bug subject as It doesn't related to max_allowed_packet.

description: updated
Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :
summary: - While selecting wrong pos with SHOW BINLOG EVENTS, it fails and does
- give error to client and log to error log
+ Selecting wrong pos with SHOW BINLOG EVENTS causes a potentially
+ misleading message in the error log
summary: Selecting wrong pos with SHOW BINLOG EVENTS causes a potentially
- misleading message in the error log
+ misleading message in the server error log
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1600

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.